Automatic exception context processing when logging

[levacic]

Update

A better proposal is provided in a comment further below.

The original proposal is preserved in this message for reference and background on why the feature might be useful.

---

Goal

Automatically add additional context when logging an exception.

Note about logging exceptions

While one would usually log messages, PSR-3 in fact allows for logging exceptions:

Every method accepts a string as the message, or an object with a __toString() method. Implementors MAY have special handling for the passed objects. If that is not the case, implementors MUST cast it to a string.

Source: https://www.php-fig.org/psr/psr-3/#12-message

Exceptions do have a __toString() method, as per the official documentation, so it's fine to pass them to a PSR-3 logger. As defined in the PSR, the logger is allowed to have special handling for these, and this special handling is what's being suggested as the implementation part of this proposal.

Current situation

It's possible to log additional context manually when invoking the logger:

Log::debug('Message', ['some' => 'context']);
Log::warning('Article not found.', ['slug' => 'article-that-doesnt-exist']);

try {
    throw new UserNotFoundException('user@example.com');
} catch (UserNotFoundException $e) {
    Log::error($e, ['email' => $e->getEmail()]);
}

There's no direct way to add context to messages logged by the application's exception handler. It's somewhat achievable though, by leveraging the ability to override the context() (for globally-configurable context) and notably exceptionContext() (for exception-specific context) methods in App\Exceptions\Handler, and somehow passing the context via the exception thrown in application code.

I currently do the latter with an ExceptionWithContext interface (as described in the implementation suggestion below), and various application exceptions implement this context. I then override App\Exceptions\Handler::exceptionContext() to check whether the caught exception implements this interface, and fetch its context if it does.

There's not automatic way to do the same with manually logged exceptions.

Implementation suggestion

Assume an interface such as:

interface ExceptionWithContext
{
    /**
     * Get the exception context.
     *
     * @return array
     */
    public function getContext(): array;
}

Also assume the following modification of Illuminate\Log\Logger::writeLog():

protected function writeLog($level, $message, $context)
{
    $this->logger->{$level}(
        $message = $this->formatMessage($message),
        $context = $this->formatContext($context, $message),
    );

    $this->fireLogEvent($level, $message, $context);
}

protected function formatContext($context, $message)
{
    if ($message instanceof Throwable) {
        $context['exception_chain_context'] = $this->getExceptionChainContext($message);
    }

    return $context;
}

protected function getExceptionChainContext(Throwable $e)
{
    $exceptionChainContext = [];

    do {
        $exceptionChainContext[] = [
            'exception' => get_class($e),
            'context' => ($e instanceof ExceptionWithContext) ? $e->getContext() : null,
        ];
    } while ($e = $e->getPrevious());

    return $exceptionChainContext;
}

Apart from the two new methods, the only functional change to writeLog() is that instead of passing just $context to the wrapped logger instance, we would pass formatContext($context, $message).

Finally assume that Illuminate\Foundation\Exceptions\Handler::exceptionContext() is changed to this:

protected function exceptionContext(Throwable $e)
{
    return [
        'exception_chain_context' => $this->exceptionChainContext($e),
    ];
}

protected exceptionChainContext(Throwable $e)
{
    $exceptionChainContext = [];

    do {
        $exceptionChainContext[] = [
            'exception' => get_class($e),
            'context' => ($e instanceof ExceptionWithContext) ? $e->getContext() : null,
        ];
    } while ($e = $e->getPrevious());

    return $exceptionChainContext;
}

Those are all the changes required in Laravel itself.

Usage

This enables us to do the following:

// An InvalidFooException that provides the context with which it was thrown.
class InvalidFooException extends RuntimeException implements ExceptionWithContext
{
    private $foo;

    public function __construct($foo, ?Throwable $previous, int $code)
    {
        parent::__construct('Invalid foo.', $code, $previous);

        $this->foo = $foo;
    }

    public function getContext(): array
    {
        return [
            'foo' => $this->foo,
        ];
    }
}

// Imagine a similar InvalidBarException class.
class InvalidBarException extends RuntimeException implements ExceptionWithContext
{
    // Similar to the previous one.
}

// This is some code that does foo-related processing, and throws an
// InvalidFooException in some situation.
function fooThrower()
{
    throw new InvalidFooException('foo');
}

// This is some code that relies on the previous foo-related processing code.
// If it catches the InvalidFooException, it rethrows it as InvalidBarException
// with some added context from the local scope.
function barThrower()
{
    try {
        fooThrower();
    } catch (InvalidFooException $e) {
        throw new InvalidBarException('bar', $e);
    }
}

What's useful about this is that we will get, at least, the following context when this exception gets logged (either via the app's exception handler if it bubbles up that far, or if, say, some higher-level code catches InvalidBarException, handles it gracefully, but logs it anyway via Log::warning($caughtBarException)):

{
    "context": {
        "exception_chain_context": [
            {
                "exception": "InvalidBarException",
                "context": {
                    "bar": "bar"
                }
            },
            {
                "exception": "InvalidFooException",
                "context": {
                    "foo": "foo"
                }
            }
        ]
    }
}

Additionally, if such an exception is uncaught by application code and bubbles up to the application's exception handler (and even if it exists anywhere in the chain), its context will get logged along with the actual exception message itself.

When logging via Log::error($exception, ['custom' => 'context']), any manually-added context will be preserved, as long as it doesn't use the exception_chain_context key.

Userland alternatives

The automatic handling in the app exceptions handler is already possible by simply overriding exceptionContext() within App\Exceptions\Handler.

However, there doesn't seem to be an obvious way to override the processing when directly logging an exception via Log::error($exception) due to the logging functionality being a pretty important core framework feature, with some hard-coded behavior. The LogServiceProvider gets registered early on in the app lifecycle, and the LogManager has several places where it explicitly instantiates Illuminate\Log\Logger, making it impossible to provide a custom implementation at this point.

I've considered various alternatives to this (providing a custom logger as per Laravel's documentation, manually overriding LogManager later in the app lifecycle, messing with Monolog handlers/processors/formatters, etc.), but they all have some downsides compared to a native implementation of this feature, or are downright impossible to do. I'd prefer to keep this proposal as short as possible, so I won't list them for now, but if anyone's interested in these alternative approaches, I can document them as well.

Backward Compatibility

This feature is fully backward-compatible.

Open questions

Assuming there's interest in this proposal, there are several aspects that should be figured out:

• How to namespace the new interface? My suggestions are, in order of preference, Illuminate\Foundation\Exceptions\ExceptionWithContext, Illuminate\Support\ExceptionWithContext, and Illuminate\Log\ExceptionWithContext.
• Is there a good way to avoid the duplicated exception chain processing code?
• Is there a better key name for the context than exception_chain_context? Ideally we would want something that's unlikely to conflict with any context a user might manually pass.
• A possible addition to the exception chain processing would be to also format each exception's message with its own context. This is currently possible to do for the top-level exception by using Monolog\Processor\PsrLogMessageProcessor, however chained exceptions won't be processed by this.
• Is the formatting of the exception_chain_context in this proposal sensible? An alternative version would be for the logged exception's context to be logged as the root-level context, and then recursively nest chained exceptions' contexts in previous_exception_context keys, e.g.

  {
      "context": {
          "exception": "InvalidBarException",
          "context": {
              "bar": "bar"
          },
          "previous_exception_context": {
              "exception": "InvalidFooException",
              "context": {
                  "foo": "foo"
              }
          }
      }
  }

[levacic]

Another related (but maybe separate from this one) feature that could be tackled is to also update the mentioned Illuminate\Log\Logger::writeLog() method (or the new formatContext() method suggested here) to add the exception itself as an exception key in the context - as is already done within Illuminate\Foundation\Exceptions\Handler::report().

This is also covered in PSR-3.

These to upgrades would be a huge help for awesome logging capabilities when logging exceptions either through the top-level exception handler, or by just logging something manually.

[levacic]

After some work on this, I believe I have a cleaner solution.

As mentioned previously, the Illuminate\Foundation\Exceptions\Handler::report():

• logs an exception's message, instead of logging the exception itself, which would be cast to string in Monolog\Logger::error(), resulting in the message being PHP's default stack trace formatting of an exception
• passes the exception to the log record context as the exception key, which is defined by PSR-3

Laravel updates

My suggestion would be to modify Illuminate\Log\Logger::writeLog() to do the same thing if it was passed an exception. Basically this:

 protected function writeLog($level, $message, $context)
 {
+    $context = $this->formatContext($context, $message);
+    $message = $this->formatMessage($message);
+
+    $this->logger->{$level}($message, $context);
-    $this->logger->{$level}($message = $this->formatMessage($message), $context);
 
     $this->fireLogEvent($level, $message, $context);
 }
 
 protected function formatMessage($message)
 {
     if (is_array($message)) {
         return var_export($message, true);
     } elseif ($message instanceof Jsonable) {
         return $message->toJson();
     } elseif ($message instanceof Arrayable) {
         return var_export($message->toArray(), true);
+    } elseif ($message instanceof Throwable) {
+        return $message->getMessage();
     }
 
     return $message;
 }
+
+protected function formatContext($context, $message)
+{
+    if ($message instanceof Throwable
+        && !isset($context['exception'])
+    ) {
+        $context['exception'] = $message;
+    }
+
+    return $context;
+}

What this basically achieves is that when an exception is logged (e.g. Log::error(new RuntimeException('An error has occurred.')), the log message will be just the exception's message (e.g. An error has occurred. for this example), whereas the exception itself will be part of the log record's context.

The exception object as part of the log record context will still usually be nicely formatted by Monolog by default (including a stack trace for the complete exception chain), so no information will be lost (unless somebody is using a custom LineFormatter with a custom output pattern that outputs the message but not the context - but I'm not sure how common that kind of thing is in practice).

Custom exception context processing

As the exception object is now part of the log record context, it can be further manipulated by attaching custom processors to Monolog. So the original intent of this issue, which is logging the context of each individual exception in the exception chain, can be achieved by simply pushing a processor like this into Monolog:

<?php

declare(strict_types=1);

namespace App\Log;

use App\Exceptions\ExceptionWithContext;
use Throwable;

class ExceptionContextProcessor
{
    /**
     * Process the log record.
     *
     * If there is an exception object in the `exception` key of the record's
     * context, it will add the complete exception chain into the `extra` data
     * part of the log record. For any exception that carries its own context,
     * it will also add that context along with the exception, in the relevant
     * `extra` data entry.
     *
     * The resulting `extra` data will have an `exception_chain_with_context`
     * array, with each element having an `exception` key with the name of the
     * exception in the exception chain, and a `context` key with that
     * particular exception's context (if that exception carries its own
     * context).
     *
     * @param array $record The log record.
     *
     * @return array
     */
    public function __invoke(array $record): array
    {
        // If the log record doesn't have a context, or the context doesn't have
        // an exception attached, or the exception key is not actually an
        // exception - there's nothing we can do, so we'll just return the
        // record as it was.
        if (
            !isset($record['context'])
            || !isset($record['context']['exception'])
            || !($record['context']['exception'] instanceof Throwable)
        ) {
            return $record;
        }

        // Extract the exception for readability.
        $exception = $record['context']['exception'];

        // Attach the exception chain with context to the record's "extra" data.
        $record['extra']['exception_chain_with_context'] = $this->getExceptionChainWithContext($exception);

        // If the exception itself is carrying context, we'll append it to the
        // record's existing context - but without overwriting anything already
        // there, so as to enable users to still pass custom data if needed.
        $record['context'] = $this->mergeContextWithExceptionContext($record['context'], $exception);

        return $record;
    }

    /**
     * Extract the complete exception chain with each exception's context.
     *
     * If an exception's context exists, it will be included for that exception,
     * otherwise it will be `null`.
     *
     * @param Throwable $exception The exception for which to extract the chain.
     *
     * @return array
     */
    private function getExceptionChainWithContext(Throwable $exception): array
    {
        $exceptionChainContext = [];

        do {
            $exceptionChainContext[] = [
                'exception' => get_class($exception),
                'context' => ($exception instanceof ExceptionWithContext) ? $exception->getContext() : null,
            ];

            $exception = $exception->getPrevious();
        } while ($exception);

        return $exceptionChainContext;
    }

    /**
     * Merge existing context with exception-specific context.
     *
     * If the exception is not carrying its own context, the original context
     * will just be returned as-is. Otherwise, the exception's context will
     * *NOT* overwrite the original context's keys.
     *
     * @param array     $context   The original context.
     * @param Throwable $exception The exception being logged.
     *
     * @return array
     */
    private function mergeContextWithExceptionContext(array $context, Throwable $exception): array
    {
        // If the exception is not carrying context, just return the original
        // context as-is.
        if (!($exception instanceof ExceptionWithContext)) {
            return $context;
        }

        return array_merge(
            $exception->getContext(),
            $context,
        );
    }
}

Contrary to my original suggestion, this has several benefits:

• No changes necessary to Illuminate\Foundation\Exceptions\Handler
• Therefore, no duplication of the exception chain context processing code is needed either (as it's centrally processed by this processor class)
• This particular processor implementation attaches the exception chain with context to the log record's extra data, instead of the context - which seems like a more suitable location
• This processor implementation also automatically attaches a context-carrying exception's context into the log record context (taking care not to overwrite any explicitly configured context)
• Unlike with the current Illuminate\Log\Logger::writeLog() implementation, this kind of exception context processing is now completely possible in userland code (in case the "exception with context" concept isn't deemed interesting/useful enough to be part of Laravel's core)

Backward compatibility

I'm not sure about this one - it doesn't seem like it should break anything for anyone, but it would change the log output slightly (however, with no information loss), and it might affect the log output for people who do specific (uncommon, IMHO) types of changes to the logging configuration.