Adding worker id & functionname to worker logs

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
+		$logger = $a->getLogger();
-		//$new_process_id = System::processID("wrk");
+		$workerLogger = new WorkerLogger($logger, $funcname);
-		$new_process_id = '';
 
-		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);
 

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);
+	}
+}

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);
+	}
+}