From ee37632695c0fac1960149d0d4263f93285611a7 Mon Sep 17 00:00:00 2001 From: Philipp Holzer Date: Fri, 22 Feb 2019 20:10:27 +0100 Subject: [PATCH] Adding worker id & functionname to worker logs --- src/Core/Worker.php | 19 +- src/Util/Logger/WorkerLogger.php | 220 +++++++++++++++++++++ tests/src/Util/Logger/WorkerLoggerTest.php | 119 +++++++++++ 3 files changed, 346 insertions(+), 12 deletions(-) create mode 100644 src/Util/Logger/WorkerLogger.php create mode 100644 tests/src/Util/Logger/WorkerLoggerTest.php 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 @@ +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 @@ +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); + } +}