diff --git a/src/Core/Worker.php b/src/Core/Worker.php
index 3f55aede33..bfe70c39c8 100644
--- a/src/Core/Worker.php
+++ b/src/Core/Worker.php
@@ -8,6 +8,7 @@ use Friendica\BaseObject;
use Friendica\Database\DBA;
use Friendica\Model\Process;
use Friendica\Util\DateTimeFormat;
+use Friendica\Util\Logger\WorkerLogger;
use Friendica\Util\Network;
/**
@@ -359,11 +360,10 @@ class Worker
$argc = count($argv);
- // Currently deactivated, since the new logger doesn't support this
- //$new_process_id = System::processID("wrk");
- $new_process_id = '';
+ $logger = $a->getLogger();
+ $workerLogger = new WorkerLogger($logger, $funcname);
- Logger::log("Process ".$mypid." - Prio ".$queue["priority"]." - ID ".$queue["id"].": ".$funcname." ".$queue["parameter"]." - Process PID: ".$new_process_id);
+ $workerLogger ->info("Process start.", ['process' => $mypid, 'priority' => $queue["priority"], 'id' => $queue["id"]]);
$stamp = (float)microtime(true);
@@ -371,24 +371,19 @@ class Worker
// For this reason the variables have to be initialized.
$a->getProfiler()->reset();
- // For better logging create a new process id for every worker call
- // But preserve the old one for the worker
- $old_process_id = $a->process_id;
- $a->process_id = $new_process_id;
- $a->queue = $queue;
-
$up_duration = microtime(true) - self::$up_start;
// Reset global data to avoid interferences
unset($_SESSION);
+ Logger::init($workerLogger);
if ($method_call) {
call_user_func_array(sprintf('Friendica\Worker\%s::execute', $funcname), $argv);
} else {
$funcname($argv, $argc);
}
+ Logger::init($logger);
- $a->process_id = $old_process_id;
unset($a->queue);
$duration = (microtime(true) - $stamp);
@@ -425,7 +420,7 @@ class Worker
Logger::log("Prio ".$queue["priority"].": ".$queue["parameter"]." - longer than 2 minutes (".round($duration/60, 3).")", Logger::DEBUG);
}
- Logger::log("Process ".$mypid." - Prio ".$queue["priority"]." - ID ".$queue["id"].": ".$funcname." - done in ".number_format($duration, 4)." seconds. Process PID: ".$new_process_id);
+ Logger::log("Process ".$mypid." - Prio ".$queue["priority"]." - ID ".$queue["id"].": ".$funcname." - done in ".number_format($duration, 4)." seconds.");
$a->getProfiler()->saveLog($a->getLogger(), "ID " . $queue["id"] . ": " . $funcname);
diff --git a/src/Util/Logger/WorkerLogger.php b/src/Util/Logger/WorkerLogger.php
new file mode 100644
index 0000000000..a9295834d9
--- /dev/null
+++ b/src/Util/Logger/WorkerLogger.php
@@ -0,0 +1,220 @@
+<?php
+
+namespace Friendica\Util\Logger;
+
+use Psr\Log\LoggerInterface;
+
+/**
+ * A Logger for specific worker tasks, which adds an additional woker-id to it.
+ * Uses the decorator pattern (https://en.wikipedia.org/wiki/Decorator_pattern)
+ */
+class WorkerLogger implements LoggerInterface
+{
+ /**
+ * @var LoggerInterface The original Logger instance
+ */
+ private $logger;
+
+ /**
+ * @var string the current worker ID
+ */
+ private $workerId;
+
+ /**
+ * @var string The called function name
+ */
+ private $functionName;
+
+ /**
+ * @param LoggerInterface $logger The logger for worker entries
+ * @param string $functionName The current function name of the worker
+ * @param int $idLength The length of the generated worker ID
+ */
+ public function __construct(LoggerInterface $logger, $functionName, $idLength = 7)
+ {
+ $this->logger = $logger;
+ $this->functionName = $functionName;
+ $this->workerId = $this->generateWorkerId($idLength);
+ }
+
+ /**
+ * Generates an ID
+ *
+ * @param int $length
+ *
+ * @return string
+ */
+ private function generateWorkerId($length)
+ {
+ if ($length <= 0) {
+ $this->logger->alert('id length must be greater than 0.');
+ return '';
+ }
+
+ try {
+ return substr(bin2hex(random_bytes(ceil($length / 2))), 0, $length);
+ } catch (\Exception $exception) {
+ $this->logger->alert('random_bytes threw an error', ['exception' => $exception]);
+ return '';
+ }
+ }
+
+ /**
+ * Adds the worker context for each log entry
+ *
+ * @param array $context
+ */
+ private function addContext(array &$context)
+ {
+ $context['worker_id'] = $this->workerId;
+ $context['worker_cmd'] = $this->functionName;
+ }
+
+ /**
+ * Returns the worker ID
+ *
+ * @return string
+ */
+ public function getWorkerId()
+ {
+ return $this->workerId;
+ }
+
+ /**
+ * System is unusable.
+ *
+ * @param string $message
+ * @param array $context
+ *
+ * @return void
+ */
+ public function emergency($message, array $context = [])
+ {
+ $this->addContext($context);
+ $this->logger->emergency($message, $context);
+ }
+
+ /**
+ * Action must be taken immediately.
+ *
+ * Example: Entire website down, database unavailable, etc. This should
+ * trigger the SMS alerts and wake you up.
+ *
+ * @param string $message
+ * @param array $context
+ *
+ * @return void
+ */
+ public function alert($message, array $context = [])
+ {
+ $this->addContext($context);
+ $this->logger->alert($message, $context);
+ }
+
+ /**
+ * Critical conditions.
+ *
+ * Example: Application component unavailable, unexpected exception.
+ *
+ * @param string $message
+ * @param array $context
+ *
+ * @return void
+ */
+ public function critical($message, array $context = [])
+ {
+ $this->addContext($context);
+ $this->logger->critical($message, $context);
+ }
+
+ /**
+ * Runtime errors that do not require immediate action but should typically
+ * be logged and monitored.
+ *
+ * @param string $message
+ * @param array $context
+ *
+ * @return void
+ */
+ public function error($message, array $context = [])
+ {
+ $this->addContext($context);
+ $this->logger->error($message, $context);
+ }
+
+ /**
+ * Exceptional occurrences that are not errors.
+ *
+ * Example: Use of deprecated APIs, poor use of an API, undesirable things
+ * that are not necessarily wrong.
+ *
+ * @param string $message
+ * @param array $context
+ *
+ * @return void
+ */
+ public function warning($message, array $context = [])
+ {
+ $this->addContext($context);
+ $this->logger->warning($message, $context);
+ }
+
+ /**
+ * Normal but significant events.
+ *
+ * @param string $message
+ * @param array $context
+ *
+ * @return void
+ */
+ public function notice($message, array $context = [])
+ {
+ $this->addContext($context);
+ $this->logger->notice($message, $context);
+ }
+
+ /**
+ * Interesting events.
+ *
+ * Example: User logs in, SQL logs.
+ *
+ * @param string $message
+ * @param array $context
+ *
+ * @return void
+ */
+ public function info($message, array $context = [])
+ {
+ $this->addContext($context);
+ $this->logger->info($message, $context);
+ }
+
+ /**
+ * Detailed debug information.
+ *
+ * @param string $message
+ * @param array $context
+ *
+ * @return void
+ */
+ public function debug($message, array $context = [])
+ {
+ $this->addContext($context);
+ $this->logger->debug($message, $context);
+ }
+
+ /**
+ * Logs with an arbitrary level.
+ *
+ * @param mixed $level
+ * @param string $message
+ * @param array $context
+ *
+ * @return void
+ */
+ public function log($level, $message, array $context = [])
+ {
+ $this->addContext($context);
+ $this->logger->log($level, $message, $context);
+ }
+}
diff --git a/tests/src/Util/Logger/WorkerLoggerTest.php b/tests/src/Util/Logger/WorkerLoggerTest.php
new file mode 100644
index 0000000000..4a84c40bb5
--- /dev/null
+++ b/tests/src/Util/Logger/WorkerLoggerTest.php
@@ -0,0 +1,119 @@
+<?php
+
+namespace src\Util\Logger;
+
+use Friendica\Test\MockedTest;
+use Friendica\Util\Logger\WorkerLogger;
+
+class WorkerLoggerTest extends MockedTest
+{
+ private function assertUid($uid, $length = 7)
+ {
+ $this->assertRegExp('/^[a-zA-Z0-9]{' . $length . '}+$/', $uid);
+ }
+
+ /**
+ * Test the a id with length zero
+ * @expectedException
+ */
+ public function testGetWorkerIdZero()
+ {
+ $logger = \Mockery::mock('Psr\Log\LoggerInterface');
+ $logger
+ ->shouldReceive('alert')
+ ->with('id length must be greater than 0.')
+ ->once();
+ new WorkerLogger($logger, 'test', 0);
+ }
+
+ /**
+ * Test the generated Uid
+ */
+ public function testGetWorkerId()
+ {
+ $logger = \Mockery::mock('Psr\Log\LoggerInterface');
+ for ($i = 1; $i < 14; $i++) {
+ $workLogger = new WorkerLogger($logger, 'test', $i);
+ $uid = $workLogger->getWorkerId();
+ $this->assertUid($uid, $i);
+ }
+ }
+
+ public function dataTest()
+ {
+ return [
+ 'info' => [
+ 'func' => 'info',
+ 'msg' => 'the alert',
+ 'context' => [],
+ ],
+ 'alert' => [
+ 'func' => 'alert',
+ 'msg' => 'another alert',
+ 'context' => ['test' => 'it'],
+ ],
+ 'critical' => [
+ 'func' => 'critical',
+ 'msg' => 'Critical msg used',
+ 'context' => ['test' => 'it', 'more' => 0.24545],
+ ],
+ 'error' => [
+ 'func' => 'error',
+ 'msg' => 21345623,
+ 'context' => ['test' => 'it', 'yet' => true],
+ ],
+ 'warning' => [
+ 'func' => 'warning',
+ 'msg' => 'another alert' . 123523 . 324.54534 . 'test',
+ 'context' => ['test' => 'it', 2 => 'nope'],
+ ],
+ 'notice' => [
+ 'func' => 'notice',
+ 'msg' => 'Notice' . ' alert' . true . 'with' . '\'strange\'' . 1.24. 'behavior',
+ 'context' => ['test' => 'it'],
+ ],
+ 'debug' => [
+ 'func' => 'debug',
+ 'msg' => 'at last a debug',
+ 'context' => ['test' => 'it'],
+ ],
+ ];
+ }
+
+ /**
+ * Test the WorkerLogger with different log calls
+ * @dataProvider dataTest
+ */
+ public function testEmergency($func, $msg, $context = [])
+ {
+ $logger = \Mockery::mock('Psr\Log\LoggerInterface');
+ $workLogger = new WorkerLogger($logger, 'test');
+ $testContext = $context;
+ $testContext['worker_id'] = $workLogger->getWorkerId();
+ $testContext['worker_cmd'] = 'test';
+ $this->assertUid($testContext['worker_id']);
+ $logger
+ ->shouldReceive($func)
+ ->with($msg, $testContext)
+ ->once();
+ $workLogger->$func($msg, $context);
+ }
+
+ /**
+ * Test the WorkerLogger with
+ */
+ public function testLog()
+ {
+ $logger = \Mockery::mock('Psr\Log\LoggerInterface');
+ $workLogger = new WorkerLogger($logger, 'test');
+ $context = $testContext = ['test' => 'it'];
+ $testContext['worker_id'] = $workLogger->getWorkerId();
+ $testContext['worker_cmd'] = 'test';
+ $this->assertUid($testContext['worker_id']);
+ $logger
+ ->shouldReceive('log')
+ ->with('debug', 'a test', $testContext)
+ ->once();
+ $workLogger->log('debug', 'a test', $context);
+ }
+}