diff --git a/flake.nix b/flake.nix index 7fa3a20e..5d723bb1 100644 --- a/flake.nix +++ b/flake.nix @@ -81,7 +81,6 @@ update-php-packages = pkgs.writeShellScriptBin "generate-composer-to-nix.sh" '' set -euxo pipefail TMPDIR="$(${pkgs.coreutils}/bin/mktemp -d)" - trap 'rm -rf -- "$TMPDIR"' EXIT mkdir "$TMPDIR/src" mkdir "$TMPDIR/composer2nix" ${pkgs.coreutils}/bin/cp "${./composer.json}" "$TMPDIR/src/" @@ -117,7 +116,6 @@ publish-to-github-pages = pkgs.writeShellScriptBin "publish-blog.sh" '' set -euxo pipefail TMPDIR="$(${pkgs.coreutils}/bin/mktemp -d)" - trap 'rm -rf -- "$TMPDIR"' EXIT cd "$TMPDIR" ${pkgs.git}/bin/git clone git@github.com:Ocramius/ocramius.github.com.git . git checkout master diff --git a/php-packages.nix b/php-packages.nix index a0b77716..71981ef5 100644 --- a/php-packages.nix +++ b/php-packages.nix @@ -858,7 +858,7 @@ let in composerEnv.buildPackage { inherit packages devPackages noDev; - name = "ocramius.github.com"; + name = "ocramius.github.io"; src = composerEnv.filterSrc ./.; executable = false; symlinkDependencies = false; diff --git a/source/_posts/2026-07-28-php-logging-with-psr-3.md b/source/_posts/2026-07-28-php-logging-with-psr-3.md new file mode 100644 index 00000000..697f5372 --- /dev/null +++ b/source/_posts/2026-07-28-php-logging-with-psr-3.md @@ -0,0 +1,550 @@ +--- +layout: post +title: Proper logging in PHP with PSR-3 +category: Blog +tags: [ "logging", "php", "software design", "psr-3" ] +year: 2026 +month: 07 +day: 28 +published: true +summary: "Logging with PSR-3 in PHP - the proper way" +description: Common logging usage in PHP, how to do it well, and what to avoid +--- + +
+ This post is for people that do day-by-day busywork coding, and for team leads that want to direct their + peers towards better logging practices. +
+ ++ Note that this article comes from my regular need to present these exact points to different people, multiple + times a year, in multiple teams, in multiple companies. +
+ ++ Also, we will not talk about how to configure a PSR-3 logger, + but rather how to use one. +
+ ++ Error/exception handling is the main use-case for logging. +
+ +
+ When logging exceptions, please pass the Throwable instance to the 'exception' context key.
+
+ Avoid cluttering the logger call with data deriving from the exception: it's not the logger call-site's job, + and you are just repeating work. +
+ ++ I often see unnecessary code like: +
+ +~~~php +try { + // logic here +} catch (SomeException $failed) { + $this->logger->error('Something went wrong', [ + // first mistake: we forgot 'exception' + 'previous' => $failed->getPrevious(), // let the logger do this! + 'line' => $failed->getLine(), // already part of the stack trace + 'error' => $failed->getMessage(), // also always rendered + 'error_type' => $failed::class, // done by the logger, usually + ]); +} +~~~ + ++ The logger itself must instead be configured (and usually already is configured) to render: +
+ +::class
+ + Your responsibility is to instead pass context information that the logger can't infer on its own. +
+ +
+ For business-specific failures that deserve a type, we can upcast them to a Throwable anyway:
+
+ Having clear exception types, even if used just with the logger, will allow you to easily + detect multiple code locations affected by the same kind of failure later on. +
+ ++ Beware: raising exceptions and logging both come with substantial CPU, memory and IO overhead, + so you should always decide carefully when logging and exceptions can be raised in a tight loop. +
+ +
+ Remember also that a Throwable always collects the entire stack trace it was raised from,
+ which may affect garbage collection, if the logger keeps messages in memory.
+
+ Loggers are perfectly capable of determining the stack trace of a raised log message: the 'exception'
+ key is not necessary for that feature to work, so creating a new Throwable is your decision.
+
+ I'm personally not a fan of cluttering code with log and debug statements, but it is undeniable that logging will + help you keep a general understanding of how your software is behaving in production, both when healthy or unhealthy. +
+ ++ A system that produces no output may be functioning perfectly, or be completely broken: having some insight + into whether it is "still ticking" is a good idea. +
+ ++ Not sure if everything OK, or monitoring is broken. ++ +
+ I recommend having $logger->info('Heartbeat'); or similar calls in code that runs in long-running
+ operations, polling loops, or that are sitting idly, waiting for input:
+
+ You can either configure the logger or the call-site to only log a percentage of the calls, + where the system would otherwise become too chatty. +
+ ++ Periodically logging is not a replacement for + + an external health-check probe + . +
+ ++ Note that you may want to also use metrics instead + (more on this below). +
+ ++ Please use dependency injection when requesting a logger: +
+ +~~~php +final readonly class MyService implements SomeService +{ + public function __construct(private LoggerInterface $logger) {} + + function someLogic() { + $this->logger->debug('Look ma, I got the logger via DI!'); + } +} +~~~ + ++ Besides avoiding the pitfalls of service location and global state, you get: +
+ ++ Here's how one could customize the logger in a service definition: +
+ +~~~php +$serviceDefinitions->add( + SomeService::class, + function (MainLogger $rootLogger) { + return new MyService( + $rootLogger + ->forWiredService(SomeService::class) + ->withEnvironment($someEnvironment) + ); + } +); +~~~ + ++ Here's how one could work with log messages in a test: +
+ +~~~php +#[Test] +function my_service_does_a_bunch_of_things_in_a_very_specific_order(): void +{ + $testSpyLogger = new RecordingLogger(); + + $systemUnderTest = new MyService($testSpyLogger); + + $systemUnderTest->doSomeWork(); + + Assert::equals( + [ + 'Extracted data', + 'processed row A', + 'processed row B', + 'failed to process row C', + 'finished', + ], + $testSpyLogger->messages + ); +} +~~~ + +
+ I often see teams using loggers to record metric information, then grepping through the result,
+ to produce graphs or further analytics data:
+
+ While you can most certainly do that, the logger is the wrong abstraction for metrics. +
+ ++ The correct tool for metrics is + OTEL metrics, + (although any "metrics-alike" tooling works too): +
+ +~~~php +final readonly class LoggedCart implements CartService { + public function __construct( + // ... + MeterProvider $metrics, + ) { + $this->checkoutAmounts = $metrics->createHistogram('cart.checkout.total_amount'); + } + + public function cartCheckout( + // ... + ): void { + // ... + + $this->checkoutAmounts->record($cart->totalAmount()); + } +} +~~~ + +
+ See also the MeterProviderInterface.
+
+ With this setup, your metrics can be collected more efficiently (in batches), and can be sent to dedicated + backends, such as time series databases, ready to be viewed. +
+ ++ Note that you are still free to wire the metrics reader so that it forwards recorded metrics to your logger! +
+ ++ You will often see developers logging the elapsed time for an operation: +
+ +~~~php +final readonly class CreditCardCheckout implements Checkout { + public function __construct( + // ... + private LoggerInterface $logger, + ) {} + + public function cartCheckout( + // ... + ): void { + $start = $this->clock->now(); + $this->logger->debug('checkout.start', ['time' => $start]) + // ... + + $end = $this->clock->now(); + $this->logger->log( + 'checkout.end', + [ + 'time' => $end, + 'duration' => $end->diff($start) + ] + ); + } +} +~~~ + ++ Similarly to metrics, a logger is not the correct abstraction: instead, look at + OTEL Tracing +
+ ++ Traces allows for a cleaner implementation: +
+ +~~~php +final readonly class CreditCardCheckout implements Checkout { + public function __construct( + // ... + private Tracer $tracer, + ) {} + + public function cartCheckout( + // ... + ): void { + $span = $this->tracer->spanBuilder('checkout') + ->startSpan(); + + // ... + + $span->end(); + } +} +~~~ + +
+ The API can be further improved with your own Tracer additions, and you can still
+ send span start/end to your logger.
+
+ By using the correct abstraction, dedicated trace collector software (such as + Jaeger, Zipkin, AWS X-Ray, etc.) + can give you full insight into how operations are nested, run concurrently, etc: +
+ +
+
+
+ Please don't do this: +
+ +~~~php +$this->logger->info('user ' . $user->username() . ' logged in'); +~~~ + +
+ PSR-3 specifies a {bracket_based} message interpolation convention, which you can rely upon:
+
+ With the above, you gain: +
+ ++ Remember that this behaviour needs to be + enabled. +
+ ++ The log level mostly has an effect on: +
+ ++ It is important to not raise the log level unnecessarily, + or you may run into a full disk, capped out monitoring system, full email inbox, or annoyed + on-call coworker. +
+ ++ Logs should capture our attention only when relevant: attention is a valuable currency ++ +
+ When reviewing new code, always ask yourself whether you can "push the log level down". +
+ +
+ For tight loops, debug could suffice. You also don't want to see these messages in production: they
+ should be turned off by default.
+
+ Successful operations should probably receive an info level: you also want to know if a system
+ is working correctly.
+
+ For acceptable blips in your data, a notice could work.
+
+ Data processing that failed, but recovered with a fallback, should probably receive a warning.
+
+ Anything from exception up should be discussed within your team and business domain, when introduced.
+
+ Logging is a delicate matter: avoid making it more delicate, as it is your last resort in trying to + understand a failing system. +
+ ++ Following code is problematic: +
+ +~~~php +$this->logger->error( + 'user {username} failed to log in', + [ + 'exception' => $exception, + 'username' => $this->users->get($userId)->username() + ] +); +~~~ + ++ At this stage, you do not know if the system is in an irrecoverable state, and this entire expression may fail. +
+ +
+ Additionally, your logging operation is potentially slowing down the system: perhaps logging $userId
+ sufficed?
+
+ As a good rule of thumb, the logger call-site should not perform expressions that can @throw,
+ or which interact with global state (a @phpstan-pure or @psalm-pure declaration can help).
+
+ This article hopefully contains things that you can point at when discussing logger usages with your colleagues: + I sure needed this compendium of patterns for my future self ☺️ +
\ No newline at end of file diff --git a/source/img/posts/2026-07-28-php-logging-with-psr-3/distributed-trace-jaeger.png b/source/img/posts/2026-07-28-php-logging-with-psr-3/distributed-trace-jaeger.png new file mode 100644 index 00000000..48a28dc3 Binary files /dev/null and b/source/img/posts/2026-07-28-php-logging-with-psr-3/distributed-trace-jaeger.png differ