Skip to content

Logger v2 #11

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
mnapoli merged 4 commits into from
Jun 14, 2025
Merged

Logger v2 #11

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
4e80b7a
Improve the format to log data as structured JSON
mnapoli Jun 13, 2025
d830ef1
Change the default log level to INFO
mnapoli Jun 13, 2025
98197a1
Update the documentation
mnapoli Jun 13, 2025
e93431c
Fix CS
mnapoli Jun 13, 2025
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
17 changes: 7 additions & 10 deletions README.md
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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:

Expand All @@ -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

Expand All @@ -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
Expand All @@ -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
Expand Down
134 changes: 114 additions & 20 deletions src/StderrLogger.php
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -4,6 +4,7 @@

use Psr\Log\AbstractLogger;
use Psr\Log\LogLevel;
use Throwable;

/**
* PSR-3 logger that logs into stderr.
Expand Down Expand Up @@ -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;

Expand All @@ -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
Expand Down Expand Up @@ -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);
}
}
88 changes: 48 additions & 40 deletions tests/StderrLoggerTest.php
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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');
Expand All @@ -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');
Expand All @@ -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
);
Expand All @@ -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(<<<LOGS
[INFO] $expectedMessage

LOGS
);
$logs = $this->getLogs();
$this->assertStringStartsWith('INFO ' . $expectedMessage . ' ', $logs);
}

public static function provideInterpolationExamples(): array
Expand All @@ -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(<<<LOGS
[INFO] Exception
InvalidArgumentException: This is an exception message in $currentFile:%d
Stack trace:
#0 $currentFile(%d): Bref\Logger\Test\StderrLoggerTest->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
Expand All @@ -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);
}
}
}