diff --git a/README.md b/README.md index f964941..8419a1a 100644 --- a/README.md +++ b/README.md @@ -24,7 +24,7 @@ The logger does not require any configuration: $logger = new \Bref\Logger\StderrLogger(); ``` -By default messages **above the `warning` level** will be logged, the rest will be discarded. +By default, messages **above the `info` level** will be logged, the rest will be discarded. It is possible to log using any [PSR-3 log level](https://www.php-fig.org/psr/psr-3/#5-psrlogloglevel), the most common ones being: @@ -36,11 +36,12 @@ $logger->error('This is an error'); ``` ``` -[WARNING] This is a warning -[ERROR] This is an error +INFO This is an info {"message":"This is an info","level":"INFO"} +WARNING This is a warning {"message":"This is a warning","level":"WARNING"} +ERROR This is an error {"message":"This is an error","level":"ERROR"} ``` -Messages under `warning` are not logged. +Messages under `info` are not logged. ### Message placeholders @@ -53,7 +54,7 @@ $logger->warning('Invalid login attempt for email {email}', [ ``` ``` -[WARNING] Invalid login attempt for email johndoe@example.com +WARNING Invalid login attempt for email johndoe@example.com {"message":"Invalid login attempt for email johndoe@example.com","level":"WARNING","context":{"email":"johndoe@example.com"}} ``` ### Logging exceptions @@ -71,11 +72,7 @@ try { ``` ``` -[ERROR] Impossible to complete the action -InvalidArgumentException: Impossible to complete the action in /var/task/index.php:12 -Stack trace: -#0 /var/task/index.php(86): main() -... +ERROR Impossible to complete the action {"message":"Impossible to complete the action","level":"ERROR","exception":{"class":"InvalidArgumentException","message":"Impossible to complete the action","code":0,"file":"/var/task/index.php","line":12,"trace":[{"file":"/var/task/index.php","line":86,"function":"main"}]} ``` ### Log level diff --git a/src/StderrLogger.php b/src/StderrLogger.php index 92580c8..8fcf25a 100644 --- a/src/StderrLogger.php +++ b/src/StderrLogger.php @@ -4,6 +4,7 @@ use Psr\Log\AbstractLogger; use Psr\Log\LogLevel; +use Throwable; /** * PSR-3 logger that logs into stderr. @@ -34,7 +35,7 @@ class StderrLogger extends AbstractLogger * @param string $logLevel The log level above which messages will be logged. Messages under this log level will be ignored. * @param resource|string $stream If unsure leave the default value. */ - public function __construct(string $logLevel = LogLevel::WARNING, $stream = 'php://stderr') + public function __construct(string $logLevel = LogLevel::INFO, $stream = 'php://stderr') { $this->logLevel = $logLevel; @@ -60,19 +61,28 @@ public function log($level, $message, array $context = []): void $message = $this->interpolate($message, $context); - $message = sprintf("[%s] %s\n", strtoupper($level), $message); + // Make sure everything is kept on one line to count as one record + $displayMessage = str_replace(["\r\n", "\r", "\n"], ' ', $message); - fwrite($this->stream, $message); + // Prepare data for JSON + $data = [ + 'message' => $message, + 'level' => strtoupper($level), + ]; - /** - * If an Exception object is passed in the context data, it MUST be in the 'exception' key. - * Logging exceptions is a common pattern and this allows implementors to extract a stack trace - * from the exception when the log backend supports it. Implementors MUST still verify that - * the 'exception' key is actually an Exception before using it as such, as it MAY contain anything. - */ - if (isset($context['exception']) && $context['exception'] instanceof \Throwable) { - $this->logException($context['exception']); + // Move any exception to the root + if (isset($context['exception']) && $context['exception'] instanceof Throwable) { + $data['exception'] = $context['exception']; + unset($context['exception']); } + + if (! empty($context)) { + $data['context'] = $context; + } + + $formattedMessage = sprintf("%s\t%s\t%s\n", strtoupper($level), $displayMessage, $this->toJson($this->normalize($data))); + + fwrite($this->stream, $formattedMessage); } private function openStderr(): void @@ -113,15 +123,99 @@ private function interpolate(string $message, array $context): string return strtr($message, $replacements); } - private function logException(\Throwable $exception): void + /** + * Normalizes data for JSON serialization. + * + * @param mixed $data + * @param int $depth Current recursion depth + * @return mixed + */ + private function normalize($data, int $depth = 0) + { + $maxDepth = 9; // Similar to NormalizerFormatter's default + $maxItems = 1000; // Similar to NormalizerFormatter's default + + if ($depth > $maxDepth) { + return 'Over ' . $maxDepth . ' levels deep, aborting normalization'; + } + + if (is_array($data)) { + $normalized = []; + + $count = 1; + foreach ($data as $key => $value) { + if ($count++ > $maxItems) { + $normalized['...'] = 'Over ' . $maxItems . ' items (' . count($data) . ' total), aborting normalization'; + break; + } + + $normalized[$key] = $this->normalize($value, $depth + 1); + } + + return $normalized; + } + + if (is_object($data)) { + if ($data instanceof \DateTimeInterface) { + return $data->format(\DateTime::RFC3339); + } + + if ($data instanceof Throwable) { + return $this->normalizeException($data, $depth); + } + + if ($data instanceof \JsonSerializable) { + return $data; + } + + if (method_exists($data, '__toString')) { + return $data->__toString(); + } + + if (get_class($data) === '__PHP_Incomplete_Class') { + return new \ArrayObject($data); + } + + return $data; + } + + if (is_resource($data)) { + return '{resource}'; + } + + return $data; + } + + /** + * Normalizes an exception for JSON serialization. + */ + private function normalizeException(Throwable $e, int $depth = 0): array + { + $maxDepth = 9; + + if ($depth > $maxDepth) { + return ['class' => get_class($e), 'message' => 'Over ' . $maxDepth . ' levels deep, aborting normalization']; + } + + $data = [ + 'class' => get_class($e), + 'message' => $e->getMessage(), + 'code' => $e->getCode(), + 'file' => $e->getFile() . ':' . $e->getLine(), + ]; + + if ($e->getPrevious() instanceof Throwable) { + $data['previous'] = $this->normalizeException($e->getPrevious(), $depth + 1); + } + + return $data; + } + + /** + * @param mixed $data + */ + private function toJson($data): string { - fwrite($this->stream, sprintf( - "%s: %s in %s:%d\nStack trace:\n%s\n", - get_class($exception), - $exception->getMessage(), - $exception->getFile(), - $exception->getLine(), - $exception->getTraceAsString() - )); + return json_encode($data, JSON_UNESCAPED_SLASHES | JSON_UNESCAPED_UNICODE | JSON_PRESERVE_ZERO_FRACTION); } } diff --git a/tests/StderrLoggerTest.php b/tests/StderrLoggerTest.php index 05f7f73..7a74380 100644 --- a/tests/StderrLoggerTest.php +++ b/tests/StderrLoggerTest.php @@ -22,7 +22,7 @@ public function setUp(): void $this->logger = new StderrLogger(LogLevel::DEBUG, $this->stream); } - public function test log messages to stderr() + public function test_log_messages_format() { $this->logger->debug('Debug'); $this->logger->info('Info'); @@ -33,21 +33,21 @@ public function test log messages to stderr() $this->logger->alert('Alert'); $this->logger->emergency('Emergency'); - $this->assertLogs(<<<'LOGS' -[DEBUG] Debug -[INFO] Info -[NOTICE] Notice -[WARNING] Alert -[ERROR] Error -[CRITICAL] Critical -[ALERT] Alert -[EMERGENCY] Emergency + $this->assertLogsMatch(<<<'LOGS' +DEBUG Debug {"message":"Debug","level":"DEBUG"} +INFO Info {"message":"Info","level":"INFO"} +NOTICE Notice {"message":"Notice","level":"NOTICE"} +WARNING Alert {"message":"Alert","level":"WARNING"} +ERROR Error {"message":"Error","level":"ERROR"} +CRITICAL Critical {"message":"Critical","level":"CRITICAL"} +ALERT Alert {"message":"Alert","level":"ALERT"} +EMERGENCY Emergency {"message":"Emergency","level":"EMERGENCY"} LOGS ); } - public function test logs above the configured log level() + public function test_logs_above_the_configured_log_level() { $this->logger = new StderrLogger(LogLevel::WARNING, $this->stream); $this->logger->debug('Debug'); @@ -59,12 +59,12 @@ public function test logs above the configured log level() $this->logger->alert('Alert'); $this->logger->emergency('Emergency'); - $this->assertLogs(<<<'LOGS' -[WARNING] Alert -[ERROR] Error -[CRITICAL] Critical -[ALERT] Alert -[EMERGENCY] Emergency + $this->assertLogsMatch(<<<'LOGS' +WARNING Alert {"message":"Alert","level":"WARNING"} +ERROR Error {"message":"Error","level":"ERROR"} +CRITICAL Critical {"message":"Critical","level":"CRITICAL"} +ALERT Alert {"message":"Alert","level":"ALERT"} +EMERGENCY Emergency {"message":"Emergency","level":"EMERGENCY"} LOGS ); @@ -74,17 +74,14 @@ public function test logs above the configured log level() * @param mixed $contextValue */ #[DataProvider('provideInterpolationExamples')] - public function test log messages are interpolated($contextValue, string $expectedMessage) + public function test_log_messages_are_interpolated($contextValue, string $expectedMessage) { $this->logger->info('{foo}', [ 'foo' => $contextValue, ]); - $this->assertLogs(<<getLogs(); + $this->assertStringStartsWith('INFO ' . $expectedMessage . ' ', $logs); } public static function provideInterpolationExamples(): array @@ -106,27 +103,37 @@ public static function provideInterpolationExamples(): array ]; } - public function test exceptions are logged() + public function test_logs_with_context() { - $this->logger->info('Exception', [ - 'exception' => $this->createTestException(), - ]); + $this->logger->info('Test message', ['key' => 'value']); + + $this->assertLogsMatch(<<<'LOGS' +INFO Test message {"message":"Test message","level":"INFO","context":{"key":"value"}} - $currentFile = __FILE__; - $this->assertLogsMatch(<<createTestException() -#1 %a LOGS ); } - private function assertLogs(string $expectedLog): void + public function test_multiline_message() { - rewind($this->stream); - self::assertSame($expectedLog, fread($this->stream, fstat($this->stream)['size'])); + $this->logger->error("Test\nmessage"); + + $this->assertLogsMatch(<<<'LOGS' +ERROR Test message {"message":"Test\nmessage","level":"ERROR"} + +LOGS + ); + } + + public function test_with_exception() + { + $e = new \Exception('Test error'); + $this->logger->info('Test message', ['exception' => $e]); + + $logs = $this->getLogs(); + $this->assertStringStartsWith('INFO Test message {"message":"Test message","level":"INFO","exception":', $logs); + $this->assertStringContainsString('"class":"Exception"', $logs); + $this->assertStringContainsString('"message":"Test error"', $logs); } private function assertLogsMatch(string $expectedLog): void @@ -135,8 +142,9 @@ private function assertLogsMatch(string $expectedLog): void self::assertStringMatchesFormat($expectedLog, fread($this->stream, fstat($this->stream)['size'])); } - private function createTestException(): \InvalidArgumentException + private function getLogs(): string { - return new \InvalidArgumentException('This is an exception message'); + rewind($this->stream); + return stream_get_contents($this->stream); } -} +} \ No newline at end of file