Adding worker id & functionname to worker logs

diff --git a/src/Core/Worker.php b/src/Core/Worker.php
index 3f55aede33d9dd0734f37887d819c3813e427139..bfe70c39c8db69d3c3a9b8ced3c15b3ae4678169 100644 (file)
--- 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 (file)
index 0000000..a929583
--- /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 (file)
index 0000000..4a84c40
--- /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);
+       }
+}