[9.x] Improve exception logging #35723
Conversation
No semantic changes in this commit, it's just a style change to make the next commit's diff easier to read, and make the final code more consistent.
- [`Illuminate\Foundation\Exceptions\Handler::report()`](https://github.com/laravel/framework/blob/08303c7cbaa0b3271060ce315160d0722b2a78f0/src/Illuminate/Foundation/Exceptions/Handler.php#L233-L240) already does this when logging caught exceptions - This is well-defined behavior as per [PSR-3](https://www.php-fig.org/psr/psr-3/#13-context) Previously, logged exceptions would be passed down to `Illuminate\Monolog\Logger` which forcibly casts them to strings, resulting in the `__toString()` method being called on them - which is inherited from [Exception](https://www.php.net/manual/en/exception.tostring.php), which prints a stack trace. This stack trace ends up being used as the log message itself. This change makes it so that when an exception is logged, the log message becomes a shorter and usually more readable string, which is the return value of the `getMessage()` method on the exception object, and passes the exception object itself as the `exception` key of the log message context, but only if that key wasn't already manually set by the user when logging the exception. Monolog's [`LineFormatter`](https://github.com/Seldaek/monolog/blob/78bd7bd33313c3a7ad1f2b0fc0c11a203d4e3826/src/Monolog/Formatter/LineFormatter.php#L168-L195) will already process exceptions found in the context to include a nice stack trace, if the `includeStacktraces` option is turned on (which it is by default in Laravel). This means that no information should be lost, unless someone is explicitly relying on the current behavior and/or making uncommon logging configuration changes. Furthermore, this enables userland code to attach additional processors to the wrapped Monolog instance and include additional custom processing on the logged exception objects if desired. Ref laravel/ideas#2449 (comment)
|
Before and after examples from what gets logged into $e1 = new InvalidArgumentException('A bad argument was supplied.');
$e2 = new RuntimeException('An error has occurred.', 0, $e1);
Log::error($e2);BeforeAfterCommentAs you can see, the full stack trace is still available in the log, it's just part of the context now, instead of the main log message - because by default, the context is also part of the formatting applied in LineFormatter. This makes no significant difference to the readability of the messages in |
|
P.S. One difference in how chained exceptions are logged by PHP's default
Monolog's approach is actually far more useful, as the first thing you see in its output is the actual exception which was logged, and is probably the place you want to look into first if you're debugging an issue. |
|
I'm worried that the very first line is not an improvement at all, making it actually harder to quickly see what the culprit is. What is see:
In fact, the "After" contains pretty much 0 usable information at the most important part 🤷♀️ |
|
I mean it does look useless based on my contrived example, but in practice, it's as useful as the log message itself is. In case it might not be obvious from my before/after examples, the Examples randomly found in Laravel by searching for
These are just the first few, and the usability of this format definitely depends on the exception message itself. However my opinion is that an automatically generated stack trace is just not a good log message, which is meant to be short and to the point. Furthermore, from personal (ie. subjective) experience, stack traces as log messages make it harder to use external logging systems (e.g. Sentry), whereas it makes more sense for them to be part of the context. Finally, as mentioned at the very start, this exact logging logic is what happens by default in My PR just makes it so that the same logic is automatically applied when logging an exception object. |
|
I don't see a big reason to change this to be honest. |
|
@taylorotwell The goal was to make logging exceptions explicitly (ie. Without this, users need to manually always do |
|
I think the old way is better. The way you are suggesting violates the logging contract. Implementations are not supposed to do anything with an object other than call its |
|
@GrahamCampbell That's not quite true, and I've linked to the relevant PSR-3 passage:
(Emphasis mine). However, I feel I may have just overdocumented this PR in the comments, to the point where it isn't obviously clear why this would be the more useful behavior (while still being okay with PSR-3). |
|
Hmm, well their phpdoc contradicts that comment. Saying only strings should be passed. |
|
@GrahamCampbell I agree that's confusing, but I assume the phpdoc would've been Anyway, I appreciate your thoughts, and understand now that others simply don't see this as a useful improvement. I just felt that the PR was misunderstood, because the comment by @mfn mentioned that the new output looks confusing, even though Laravel already logs exceptions precisely like this, when caught by the exception handler - this PR just adds to the consistency of the logging infrastructure. |
Preface
As the explanation seems a bit long, I'd just like to highlight the important fact that Laravel already does this exact thing when logging exceptions in
Illuminate\Foundation\Exceptions\Handler::report()which was introduced via #19698 - this just makes logging exceptions via e.g.Log::error($exception)be consistent, which results in other benefits described further below.Supersedes #35722
Here's the commit message from the second commit (the first is just an aesthetic change to make the second commit more readable - feel free to squash if needed):
Add special handling when logging exceptions
Illuminate\Foundation\Exceptions\Handler::report()already does this when logging caught exceptionsPreviously, logged exceptions would be passed down to
Illuminate\Monolog\Loggerwhich forcibly casts them to strings, resulting in the__toString()method being called on them - which is inherited from Exception, which prints a stack trace. This stack trace ends up being used as the log message itself.This change makes it so that when an exception is logged, the log message becomes a shorter and usually more readable string, which is the return value of the
getMessage()method on the exception object, and passes the exception object itself as theexceptionkey of the log message context, but only if that key wasn't already manually set by the user when logging the exception.Monolog's
LineFormatterwill already process exceptions found in the context to include a nice stack trace, if theincludeStacktracesoption is turned on (which it is by default in Laravel).This means that no information should be lost, unless someone is explicitly relying on the current behavior and/or making uncommon logging configuration changes.
Furthermore, this enables userland code to attach additional processors to the wrapped Monolog instance and include additional custom processing on the logged exception objects if desired.
Ref laravel/ideas#2449 (comment)
P.S. I'll attach a before and after in a comment below.