Pass the raw exception to logger implementations

+++ b/core/includes/update.inc
@@ -186,7 +186,7 @@ function update_do_one($module, $number, $dependency_map, &$context) {
       $variables = Error::decodeException($e);
-      unset($variables['backtrace']);
+      unset($variables['backtrace'], $variables['exception']);
       $ret['#abort'] = ['success' => FALSE, 'query' => t('%type: @message in %function (line %line of %file).', $variables)];

Oh I see, so we remove it in every place where we pass it to t(), but not when we actually do logging. This makes 100% sense.

I went through all the calls to Error::decodeException() and I was not able to find a case where we unset in the case I did not to see unsetting and the other way round.

Yeah let's do that :)

Thank you @mfb!

1. +++ b/core/includes/errors.inc
   @@ -142,9 +143,10 @@ function error_displayable($error = NULL) {
    function _drupal_log_error($error, $fatal = FALSE) {
   

   The docs for the $error param need updating.

2. +++ b/core/includes/errors.inc
   @@ -160,7 +162,7 @@ function _drupal_log_error($error, $fatal = FALSE) {
          // Provide the PHP backtrace to logger implementations.
   

   This comment looks like it needs updating.

3. +++ b/core/includes/errors.inc
   @@ -160,7 +162,7 @@ function _drupal_log_error($error, $fatal = FALSE) {
   -      \Drupal::logger('php')->log($error['severity_level'], '%type: @message in %function (line %line of %file) @backtrace_string.', $error + ['backtrace' => $backtrace]);
   +      \Drupal::logger('php')->log($error['severity_level'], '%type: @message in %function (line %line of %file) @backtrace_string.', $error + ['backtrace' => $backtrace, 'exception' => $exception]);
   

   Could do with some test coverage of this change.

#2954126: The return value of Error::decodeException should never be passed to LoggerInterface::log. is related.

I believe the fix I proposed in #2954126: The return value of Error::decodeException should never be passed to LoggerInterface::log. was the exact opposite of this issue, provide less context to loggers :)

What I found was a PSR3 logger implementation like monolog completely blows up when huge amounts of data is sent via context. Adding extra information to the context would essentially mean less log messages are stored. The equivalent issue in the monolog queue is here: #2954130: Mitigate huge values for $context due to core adding backtrace information to logs..

I'm not sure what the solution is: some logging implementations can make use of this info, others break when it's provided.

I think it's a bit of a smell that we start adding extra information to the context in core, then immediately unset it in dblog. Who is to say other logging implementations don't need to apply the same treatment and unset these variables too? Why should dblog even have to unset this in the first place?

My current feeling on this is that passing all this extra data isn't in line with the spirit of the interface and we should provide some kind of adapter to the interface which provides a more structured approach to accessing additional metadata like exception objects and backtraces.

Spitballing a possible approach to #20, perhaps an ErrorAwareLoggerInterface with a signature like:

    /**
     * Logs with an arbitrary level and additional error context.
     *
     * @param mixed  $level
     * @param string $message
     * @param array  $context
     * @param array  $backtrace
     * @param mixed $exception
     *
     * @return void
     */
    public function log($level, $message, array $context = array(), $backtrace = [], $exception = NULL);

Given there is PSR-3 I'm wondering how others handle that? Monolog allows you to set is up, but it is not enabled: https://github.com/Seldaek/monolog/blob/7405bb5d673df9ee05698876843e85b0...

Given that: Could we add something like a container parameter to enable that?

In core we're expecting monolog to normalize the full output of \Exception::getTrace, that's what we're calling in Error::decodeException.

The code linked above is slightly different because when it encounters an exception, it'll normalize it with \Exception::getTraceAsString which is obviously way less taxing than iterating an entire callstack and attempting to normalize the variables for every frame in that stack.

It looks like, since monolog knows how to handle exceptions, but not huge megabyte arrays, maybe 'backtrace' should be removed entirely in favour of an 'exception' (which can be queried for the backtrace or backtrace as a string if that's useful).

@mfb
This would mean that logger implementations would need to distinct between the two cases, right? You as one of them, do you think that could be a problem?

I've found a similar issue in the Drush logger channel.
https://github.com/drush-ops/drush/issues/3683

DbLog works around the problem with an unset($context['backtrace'])... so it appears it's a systemic issue.

I closed #2351099: watchdog_exception() hides the exception from logger implementations as a duplicate of this issue, since this one has a more extensive patch.

Really interested in this because I just spent much longer that needed trying to track down a plugin exception in newrelic because it got the trace of the exception handler not the trace of the exception because newrelic's logger doesn't have access to it.

Opened an issue to support this in newrelic right away #3094508: Support passing exceptions to error logger

It _might_ make sense to move the backtrace and backtrace_string context down into loggers and leave the handling up to them but that's a bigger change that could be discussed in a follow up. Also deprecating an array key sounds annoying.

Just passing the exception through seems to align with the PSR and interface and be a no brainer with pretty solid wins for contrib. LGTM

+++ b/core/lib/Drupal/Core/Utility/Error.php
@@ -72,6 +72,7 @@ public static function decodeException($exception) {
+      'exception' => $exception,

I was wondering if we needed to do something to watchdog_exception to handle passing the exception through even if we're deprecating it but thinking through the patch this seems to be enough to handle it.

It could dump it into the message but it has a native trace area that's highlighted over the message. In addition to the trace, the exception type is used to group errors and to take advantage of that you need to pass \Exception|\Throwable to the extension method so this is needed to fully take advantage of its exception logging.

This issue has some great discussion and I like the idea of improving our logger this way. I think we probably want framework manager review to validate the decision, since it affects multiple subsystems.

Unfortunately, the latest patch does not apply to 9.1.x (probably because the bits related to simpletest are gone). So NW for a reroll.

Thanks!

Rerolled for 9.1.x by just removing the change related to simpletest.

I think the interdiff looks a little odd because some changes changed lines, but are otherwise the same as the previous patch.

Yeah reviewed this and the real interdiff is just the simpletest TestBase.php chunk as xjm guessed :)

not sure why i didn't move this back to rtbc. :-/

How many of the cases where we're unsetting $error['exception'] are just for cleanliness and how many are required for things not to blow up?

#2949419-20: Pass the raw exception to logger implementations still seems relevant - i.e. will other logging implementations have to make the same change as dblog?

So I think we're unseting defensively. More accurately, those changes are modifying the dblog implementation to better handle the PSR interface which _specifically_ calls out the exception key as containing exceptions with backtraces. If we didn't start including it, it would be prudent for us to make those changes anyways because implementations be calling the logger and passing that in.

There _are_ kinda competing concerns here. On the one hand, passing the exception with all its backtrace data _could_ cause problems for some loggers. Monolog probably will want to add the exception key to their filter list from that issue. On the other though is that loggers like NewRelic can't fully function without it.

Since the PSR specifically calls out this context key as containing exceptions it seems reasonable to expect loggers to handle this case so I think that addresses #20 well enough and core should move forward with this feature.

OK #48/#49 is fair enough, but this now needs another 9.1.x re-roll.

Re-rolling patch against 9.1.x.

Fixed test, Please check.

Test Fixed, Please review.

latest patch looks good to me

Committed 6e7fc11 and pushed to 9.2.x. Thanks!

Moving to 9.1.x for backport discussion.

Setting this back to fixed now that 9.1.0 is out; it's an addition-ish.