diff --git a/src/App.php b/src/App.php index 9fef11e92f..6945dc459d 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; @@ -374,8 +373,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 * diff --git a/src/Core/Worker.php b/src/Core/Worker.php index 3f55aede33..efaa7cd493 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; /** @@ -355,15 +356,12 @@ class Worker { $a = \get_app(); - $mypid = getmypid(); - $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.", ['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); } } 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'); 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); + } +}