From ee37632695c0fac1960149d0d4263f93285611a7 Mon Sep 17 00:00:00 2001 From: Philipp Holzer Date: Fri, 22 Feb 2019 20:10:27 +0100 Subject: [PATCH 1/6] 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); + } +} From cec6f4902394f74653c3b11bf04221d59470aeb1 Mon Sep 17 00:00:00 2001 From: Philipp Holzer Date: Fri, 22 Feb 2019 20:24:10 +0100 Subject: [PATCH 2/6] Removed unused code --- src/App.php | 3 --- src/Core/System.php | 15 --------------- 2 files changed, 18 deletions(-) diff --git a/src/App.php b/src/App.php index 3df285cb38..5a8d9831d6 100644 --- a/src/App.php +++ b/src/App.php @@ -197,7 +197,6 @@ class App $this->footerScripts[] = trim($url, '/'); } - public $process_id; public $queue; private $scheme; private $hostname; @@ -367,8 +366,6 @@ class App $this->loadDefaultTimezone(); Core\L10n::init(); - - $this->process_id = Core\System::processID('log'); } /** diff --git a/src/Core/System.php b/src/Core/System.php index f0ed083573..69d15a1764 100644 --- a/src/Core/System.php +++ b/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 * From 9c12f3f226cefa64456c559fd060e067389d9886 Mon Sep 17 00:00:00 2001 From: Philipp Holzer Date: Fri, 22 Feb 2019 20:41:13 +0100 Subject: [PATCH 3/6] Formatting logger to new style --- src/Core/Worker.php | 19 +++++++++---------- 1 file changed, 9 insertions(+), 10 deletions(-) diff --git a/src/Core/Worker.php b/src/Core/Worker.php index bfe70c39c8..29d825050f 100644 --- a/src/Core/Worker.php +++ b/src/Core/Worker.php @@ -356,14 +356,12 @@ class Worker { $a = \get_app(); - $mypid = getmypid(); - $argc = count($argv); $logger = $a->getLogger(); $workerLogger = new WorkerLogger($logger, $funcname); - $workerLogger ->info("Process start.", ['process' => $mypid, 'priority' => $queue["priority"], 'id' => $queue["id"]]); + $workerLogger ->info("Process start.", ['priority' => $queue["priority"], 'id' => $queue["id"]]); $stamp = (float)microtime(true); @@ -376,6 +374,7 @@ class Worker // 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); @@ -401,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]); + $workerLogger->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; @@ -411,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); + $workerLogger->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); + $workerLogger->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); + $workerLogger->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); + $workerLogger->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."); + $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"); + $workerLogger->info('Cooldown.', ['priority' => $queue["priority"], 'id' => $queue["id"], 'cooldown' => $cooldown]); sleep($cooldown); } } From a613523dd7cd69bf5c7f1e08a5bb7a113e7f7f4e Mon Sep 17 00:00:00 2001 From: Philipp Holzer Date: Fri, 22 Feb 2019 20:45:13 +0100 Subject: [PATCH 4/6] skip WorkerLogger for Logging --- src/Factory/LoggerFactory.php | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/src/Factory/LoggerFactory.php b/src/Factory/LoggerFactory.php index 77a09637c4..97b513bd34 100644 --- a/src/Factory/LoggerFactory.php +++ b/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'); From 16863c5d825caf41978920cd579426864f48f65c Mon Sep 17 00:00:00 2001 From: Philipp Holzer Date: Fri, 22 Feb 2019 23:53:20 +0100 Subject: [PATCH 5/6] switched back to logger --- src/Core/Worker.php | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/Core/Worker.php b/src/Core/Worker.php index 29d825050f..cb8511a0e8 100644 --- a/src/Core/Worker.php +++ b/src/Core/Worker.php @@ -400,7 +400,7 @@ class Worker $rest = number_format(max(0, $up_duration - (self::$db_duration + self::$lock_duration)), 4); $exec = number_format($duration, 4); - $workerLogger->info('Performance log.', ['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; From 8760d89eb8ea30b37a8dbbbc0f440a4d7e38f444 Mon Sep 17 00:00:00 2001 From: Philipp Holzer Date: Sat, 23 Feb 2019 10:24:22 +0100 Subject: [PATCH 6/6] reverting back workerLogger to Logger --- src/Core/Worker.php | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/src/Core/Worker.php b/src/Core/Worker.php index cb8511a0e8..efaa7cd493 100644 --- a/src/Core/Worker.php +++ b/src/Core/Worker.php @@ -410,13 +410,13 @@ class Worker self::$lock_duration = 0; if ($duration > 3600) { - $workerLogger->info('Longer than 1 hour.', ['priority' => $queue["priority"], 'id' => $queue["id"], 'duration' => round($duration/60, 3)]); + $logger->info('Longer than 1 hour.', ['priority' => $queue["priority"], 'id' => $queue["id"], 'duration' => round($duration/60, 3)]); } elseif ($duration > 600) { - $workerLogger->info('Longer than 10 minutes.', ['priority' => $queue["priority"], 'id' => $queue["id"], 'duration' => round($duration/60, 3)]); + $logger->info('Longer than 10 minutes.', ['priority' => $queue["priority"], 'id' => $queue["id"], 'duration' => round($duration/60, 3)]); } elseif ($duration > 300) { - $workerLogger->info('Longer than 5 minutes.', ['priority' => $queue["priority"], 'id' => $queue["id"], 'duration' => round($duration/60, 3)]); + $logger->info('Longer than 5 minutes.', ['priority' => $queue["priority"], 'id' => $queue["id"], 'duration' => round($duration/60, 3)]); } elseif ($duration > 120) { - $workerLogger->info('Longer than 2 minutes.', ['priority' => $queue["priority"], 'id' => $queue["id"], 'duration' => round($duration/60, 3)]); + $logger->info('Longer than 2 minutes.', ['priority' => $queue["priority"], 'id' => $queue["id"], 'duration' => round($duration/60, 3)]); } $workerLogger->info('Process done. ', ['priority' => $queue["priority"], 'id' => $queue["id"], 'duration' => number_format($duration, 4)]); @@ -426,7 +426,7 @@ class Worker $cooldown = Config::get("system", "worker_cooldown", 0); if ($cooldown > 0) { - $workerLogger->info('Cooldown.', ['priority' => $queue["priority"], 'id' => $queue["id"], 'cooldown' => $cooldown]); + $logger->info('Cooldown.', ['priority' => $queue["priority"], 'id' => $queue["id"], 'cooldown' => $cooldown]); sleep($cooldown); } }