Merge pull request #6723 from nupplaphil/issue/6658-worker_id

Adding worker ID to log

src/App.php

@@ -197,7 +197,6 @@ class App
 		$this->footerScripts[] = trim($url, '/');
 	}
 
-	public $process_id;
 	public $queue;
 	private $scheme;
 	private $hostname;
@@ -374,8 +373,6 @@ class App
 		$this->loadDefaultTimezone();
 
 		Core\L10n::init();
-
-		$this->process_id = Core\System::processID('log');
 	}
 
 	/**

src/Core/System.php

@@ -234,21 +234,6 @@ class System extends BaseObject
 		}
 	}
 
-	/**
-	 * Generates a process identifier for the logging
-	 *
-	 * @param string $prefix A given prefix
-	 *
-	 * @return string a generated process identifier
-	 */
-	public static function processID($prefix)
-	{
-		// We aren't calling any other function here.
-		// Doing so could easily create an endless loop
-		$trailer = $prefix . ':' . getmypid() . ':';
-		return substr($trailer . uniqid('') . mt_rand(), 0, 26);
-	}
-
 	/**
 	 * Returns the current Load of the System
 	 *

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;
 
 /**
@@ -355,15 +356,12 @@ class Worker
 	{
 		$a = \get_app();
 
-		$mypid = getmypid();
-
 		$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.", ['priority' => $queue["priority"], 'id' => $queue["id"]]);
 
 		$stamp = (float)microtime(true);
 
@@ -371,24 +369,20 @@ 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);
 
+		// Set the workerLogger as new default logger
+		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);
@@ -406,7 +400,7 @@ class Worker
 		$rest    = number_format(max(0, $up_duration - (self::$db_duration + self::$lock_duration)), 4);
 		$exec    = number_format($duration, 4);
 
-		Logger::info('Performance:', ['total' => $dbtotal, 'count' => $dbcount, 'stat' => $dbstat, 'write' => $dbwrite, 'block' => $dblock, 'rest' => $rest, 'exec' => $exec]);
+		$logger->info('Performance log.', ['total' => $dbtotal, 'count' => $dbcount, 'stat' => $dbstat, 'write' => $dbwrite, 'block' => $dblock, 'rest' => $rest, 'exec' => $exec]);
 
 		self::$up_start = microtime(true);
 		self::$db_duration = 0;
@@ -416,23 +410,23 @@ class Worker
 		self::$lock_duration = 0;
 
 		if ($duration > 3600) {
-			Logger::log("Prio ".$queue["priority"].": ".$queue["parameter"]." - longer than 1 hour (".round($duration/60, 3).")", Logger::DEBUG);
+			$logger->info('Longer than 1 hour.', ['priority' => $queue["priority"], 'id' => $queue["id"], 'duration' =>   round($duration/60, 3)]);
 		} elseif ($duration > 600) {
-			Logger::log("Prio ".$queue["priority"].": ".$queue["parameter"]." - longer than 10 minutes (".round($duration/60, 3).")", Logger::DEBUG);
+			$logger->info('Longer than 10 minutes.', ['priority' => $queue["priority"], 'id' => $queue["id"], 'duration' =>   round($duration/60, 3)]);
 		} elseif ($duration > 300) {
-			Logger::log("Prio ".$queue["priority"].": ".$queue["parameter"]." - longer than 5 minutes (".round($duration/60, 3).")", Logger::DEBUG);
+			$logger->info('Longer than 5 minutes.', ['priority' => $queue["priority"], 'id' => $queue["id"], 'duration' =>   round($duration/60, 3)]);
 		} elseif ($duration > 120) {
-			Logger::log("Prio ".$queue["priority"].": ".$queue["parameter"]." - longer than 2 minutes (".round($duration/60, 3).")", Logger::DEBUG);
+			$logger->info('Longer than 2 minutes.', ['priority' => $queue["priority"], 'id' => $queue["id"], 'duration' =>   round($duration/60, 3)]);
 		}
 
-		Logger::log("Process ".$mypid." - Prio ".$queue["priority"]." - ID ".$queue["id"].": ".$funcname." - done in ".number_format($duration, 4)." seconds. Process PID: ".$new_process_id);
+		$workerLogger->info('Process done. ', ['priority' => $queue["priority"], 'id' => $queue["id"], 'duration' =>   number_format($duration, 4)]);
 
 		$a->getProfiler()->saveLog($a->getLogger(), "ID " . $queue["id"] . ": " . $funcname);
 
 		$cooldown = Config::get("system", "worker_cooldown", 0);
 
 		if ($cooldown > 0) {
-			Logger::log("Process ".$mypid." - Prio ".$queue["priority"]." - ID ".$queue["id"].": ".$funcname." - in cooldown for ".$cooldown." seconds");
+			$logger->info('Cooldown.', ['priority' => $queue["priority"], 'id' => $queue["id"], 'cooldown' => $cooldown]);
 			sleep($cooldown);
 		}
 	}

src/Factory/LoggerFactory.php

@@ -7,6 +7,7 @@ use Friendica\Core\Logger;
 use Friendica\Network\HTTPException\InternalServerErrorException;
 use Friendica\Util\Logger\FriendicaDevelopHandler;
 use Friendica\Util\Logger\FriendicaIntrospectionProcessor;
+use Friendica\Util\Logger\WorkerLogger;
 use Friendica\Util\Profiler;
 use Monolog;
 use Psr\Log\LoggerInterface;
@@ -33,7 +34,7 @@ class LoggerFactory
 		$logger->pushProcessor(new Monolog\Processor\PsrLogMessageProcessor());
 		$logger->pushProcessor(new Monolog\Processor\ProcessIdProcessor());
 		$logger->pushProcessor(new Monolog\Processor\UidProcessor());
-		$logger->pushProcessor(new FriendicaIntrospectionProcessor(LogLevel::DEBUG, [Logger::class, Profiler::class]));
+		$logger->pushProcessor(new FriendicaIntrospectionProcessor(LogLevel::DEBUG, [Logger::class, Profiler::class, WorkerLogger::class]));
 
 		$debugging = $config->get('system', 'debugging');
 		$stream    = $config->get('system', 'logfile');

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