Error logging should log a backtrace consistently

+++ b/core/includes/errors.inc
@@ -129,7 +129,7 @@ function _drupal_log_error($error, $fatal = FALSE) {
+  $backtrace = $error['@backtrace'] = $error['backtrace'];

The backtrace is an array of arrays. I think it is the output of debug_backtrace() so something must be done to make it plain text.

@dawehner

I am not sure you can do that with an exception object. An alternative is a backtrace array to string formatting function.

Let's see if I can get this green while we think about ideas.

This is a useful improvement! We may need to remove the first few items off the trace, as those are internal error handling calls. Their presence in the trace is unnecessary and can be confusing.

I understood your argument from #10. The way I saw it, was that this is not necessarily about presentation, but about making the data itself less confusing for people who may not be entirely familiar with backtraces and Drupal's error handling.

_drupal_log_error() is an internal function. Though it would be somewhat difficult to determine the exact number of calls to remove from the stack, it would not be impossible.

RTBC for me - looks like a great improvement. I am using such a patch sometimes locally.

"Perfect is the enemy of good enough."

Lets fix any problems with the backtrace (too many, too less, etc.) in a follow-up.

Is there a reason not to backport this to 7?

Why don't we just use $error['@backtrace'] = Error::formatBacktrace($error['backtrace']) Then we don't have to generate the backtrace twice.

Why don't we just use $error['@backtrace'] = Error::formatBacktrace($error['backtrace'])...?

Total ignorance that Error::formatBacktrace() exists.

We may not need that follow-up if this is to everyone's liking.

So thinking about this some more I'm a bit concerned about this resulting in massive log files. It might be nice to make this optional. Not sure.

fwiw I agree with dawehner - if the log entries are big, that's less of a problem than having them in the first place and the backtrace provides more chance of fixing them.

Also at this level there really shouldn't be a massive number being logged - most would go into a proper logging handler (which we already log backtraces for) - unless the site down more or less.

Moving back to Alex for a second look.

Hmmm... actually the comment

    // Remove any backtraces since they may contain an unserializable variable.
    unset($context['backtrace']);

Hints as to why we're not doing this...

+++ b/core/includes/errors.inc
@@ -130,6 +130,7 @@ function _drupal_log_error($error, $fatal = FALSE) {
+  $error['@backtrace'] = Error::formatBacktrace($error['backtrace']);

However I think the above code protects us because of...

      if (isset($trace['args'])) {
        foreach ($trace['args'] as $arg) {
          if (is_scalar($arg)) {
            $call['args'][] = is_string($arg) ? '\'' . Xss::filter($arg) . '\'' : $arg;
          }
          else {
            $call['args'][] = ucfirst(gettype($arg));
          }
        }
      }

So we're not serializing non-scalar arguments.

We have to be certain that adding the backtrace will not cause errors that hide the real error as that would make things worse.

Also I'm not sure why the patch attached to #19 is not showing in the issue summary.

Setting back to "needs review" so that other people can confirm that my thoughts in #26 are correct.

I like adding the backtrace, however Error::formatBacktrace() might indeed do too much.

I personally prefer the backtrace I get from PHP exceptions itself:

$e = new \Exception();
$backtrace = $e->getTraceAsString();

That is:

- a) incredibly fast - as its internally created and formatted
- b) has no superfluous data and internally deals with objects, etc.
- c) is kinda directly what python, ruby, etc. output in its stage.

I now use this exclusively for creating backtraces in my own debugging and we can directly also Xss::filter() the whole string - as there is no HTML output to preserve.

Also those backtraces never get too large.

In fact I think we should even deprecate our backtrace formatting and replace with that method.

#32 I think we should get back to that. internal backtrace generation is so much faster than all the string manipulation in user code - unless Alex strongly disagrees, e.g. even if we generate it twice as its generated by PHP it is still faster.

And not every error is an Exception in PHP 5.x - IIRC.

In fact, my RTBC for #9 still stands.

I agree with #34, too.

Can we re-RTBC #9 or should we re-upload os its clearer?

We probably would need a comment explaining why we create a new Exception to get the backtrace().

Also marking for backport to D7 as we just discussed adding that to make specially the missing module errors easier to find, but for D7 it would of course be opt-in.

I use $e = new Exception(); $e->getTraceAsString() for my own debugging too, so happy with a version that does that.

The issue doesn't have a current patch, so NW for that. (@dawehner says #9 but all the files are hidden.)

Do these backtraces ever show up in watchdog? If so we should have screenshots since it will impact site admins. If not let's document that here.

Thanks! This would be valuable for developers.

#40 How would you access the backtrace then?

Back to RTBC then, you can at least do a DB query or write a contrib module.

1. +++ b/core/includes/errors.inc
   @@ -132,6 +132,9 @@ function _drupal_log_error($error, $fatal = FALSE) {
      $backtrace = $error['backtrace'];
   ...
   +  $e = new \Exception();
   +  $error['@backtrace'] = $e->getTraceAsString();
   

   One thing that is weird is that these backtraces will be different.

2. +++ b/core/includes/errors.inc
   @@ -132,6 +132,9 @@ function _drupal_log_error($error, $fatal = FALSE) {
      unset($error['backtrace']);
   

   No need to unset now

Ah I missed the @ re the unset.

What I meant by different is this... the backtrace is created in _drupal_error_handler_real() and the string version in _drupal_log_error() - I think they should be created in the same place. However interestingly the only other call to _drupal_log_error() is _drupal_log_error(Error::decodeException($exception), TRUE); in _drupal_exception_handler(). This already creates an string backtrace and we should definitely use that one.

BC layer... if we think we need one.

RTBC - New approach looks great to me!

@backstrace_string makes a lot of sense.

Might be a good idea to write a quick CR for this?

@dawehner that's what happens inside Error::decodeException($exception); - in drupal 9 we can just set the return to have a key @backtrace_string instead of backtrace_string.

    return array(
      '%type' => get_class($exception),
      // The standard PHP exception handler considers that the exception message
      // is plain-text. We mimic this behavior here.
      '@message' => $message,
      '%function' => $caller['function'],
      '%file' => $caller['file'],
      '%line' => $caller['line'],
      'severity_level' => static::ERROR,
      'backtrace' => $backtrace,
      'backtrace_string' => $exception->getTraceAsString(),
    );

This is the return from \Drupal\Core\Utility\Error::decodeException() - I don;t understand what is meant by

Nope. Its using its own scheme of encoding the exception.

+++ b/core/includes/bootstrap.inc
@@ -551,7 +551,10 @@ function _drupal_exception_handler($exception) {
+    $error['@backtrace_string'] = $error['backtrace_string'];
+    unset($error['backtrace_string']);

This causes a bit of squinting and WTF; maybe an inline comment?

Also could still use that CR. Thanks!

I think this would be an okay addition during beta; it's task-ish and BC.

+++ b/core/includes/bootstrap.inc
@@ -562,6 +562,8 @@ function _drupal_exception_handler($exception) {
+    // We use @backtrace_string, as it will end up in the logging as variable
+    // as part of _drupal_log_error().

nit - in the logging == in the logs?

--

Back to RTBC

Thanks @dawehner and @Fabianx; that helps.

It's still not entirely clear to me. I'd suggest something like:
The 'backtrace_string' key contains the raw backtrace from \Drupal\Utility\Whatever\Error::decodeException(). Store it to '@backtrace_string' for use with a string placeholder in _drupal_error_log(), and unset the old placeholder.

Or something. What's confusing to me is that we are not making this API addition to Error as well and handling the BC there.

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

I don't think we should be changing the return array of Error::decodeException() even in a minor release.

+++ b/core/includes/errors.inc
@@ -129,10 +129,6 @@ function error_displayable($error = NULL) {
-  // This was added in Drupal 8.2.0. This code can be removed in Drupal 9.0.0.
-  if (!isset($error['@backtrace_string'])) {
-    $error['@backtrace_string'] = (new \Exception())->getTraceAsString();
-  }

I don't think we should be removing this tiny bc layer either.

@xjm / #64 The reason this change is not made in Error::decodeException is our BC policy.

In my opinion we should go back to #64

Or here is a potentially cleaner way of handling this. Well at least putting all of the BC logic in one place.

Removing a (now) unnecessary change.

@dawehner I guess we could. Seems messy but I guess we could do & to not have two copies lying around.

Here it is

The test fail has nothing to do with this patch - https://www.drupal.org/pift-ci-job/396395 - it looks like l.d.o was unavailable for a second for some reason.

That is pretty neat way of solving that and keeping BC at the same time, +1 from me.

Back to RTBC

@xjm / #64 The reason this change is not made in Error::decodeException is our BC policy.

I said add a key, not change the key. Adding a key to the associative array return value is a totally acceptable API addition.

+++ b/core/lib/Drupal/Core/Utility/Error.php
@@ -61,7 +61,7 @@ public static function decodeException($exception) {
-    return array(
+    $return = array(
       '%type' => get_class($exception),
       // The standard PHP exception handler considers that the exception message
       // is plain-text. We mimic this behavior here.
@@ -71,8 +71,12 @@ public static function decodeException($exception) {

@@ -71,8 +71,12 @@ public static function decodeException($exception) {
       '%line' => $caller['line'],
       'severity_level' => static::ERROR,
       'backtrace' => $backtrace,
+      // @todo https://www.drupal.org/node/2775867 Change to @backtrace_string
+      //   in Drupal 9.
       'backtrace_string' => $exception->getTraceAsString(),
     );
+    $return['@backtrace_string'] = &$return['backtrace_string'];
+    return $return;

Well I'm not exactly wild about these changes. it makes it really weird for anything that was manipulating the 'backtrace_string' before - which one should you manipulate now? In fact it does not matter... which is quite funky...

Psy Shell v0.7.0 (PHP 7.0.7 — cli) by Justin Hileman
>>> $a = []
=> []
>>> $a['a'] = '3';
=> "3"
>>> $a['b'] = &$a['a'];
=> "3"
>>> $a;
=> [
     "a" => &1 "3",
     "b" => &1 "3",
   ]
>>> $a['a'] = '2';
=> "2"
>>> $a;
=> [
     "a" => &1 "2",
     "b" => &1 "2",
   ]
>>> $a['b'] = '3';
=> "3"
>>> $a;
=> [
     "a" => &1 "3",
     "b" => &1 "3",
   ]

A bit special :)

I actually kinda agree with @alexpott that I would avoid saving it by reference; that tends to lead to Bad Things Happen™.

Still not sure why this would be out of scope:

diff --git a/core/lib/Drupal/Core/Utility/Error.php b/core/lib/Drupal/Core/Utility/Error.php
index aca31fa..ea048be 100644
--- a/core/lib/Drupal/Core/Utility/Error.php
+++ b/core/lib/Drupal/Core/Utility/Error.php
@@ -32,7 +32,17 @@ class Error {
    *   The exception object that was thrown.
    *
    * @return array
-   *   An error in the format expected by _drupal_log_error().
+   *   All the parameters are plain text, with the exception of !message, which
+   *   needs to be a safe HTML string.
+   *   - %type
+   *   - !message
+   *   - %function
+   *   - %file
+   *   - %line
+   *   - severity_level
+   *   - @backtrace_string
+   *   - backtrace_string: (deprecated) Same as @backtrace_string, retained for
+   *     BC. Will be removed before 9.0.0. Use @backtrace_string instead.
    */
   public static function decodeException($exception) {
     $message = $exception->getMessage();
@@ -72,6 +82,7 @@ public static function decodeException($exception) {
       'severity_level' => static::ERROR,
       'backtrace' => $backtrace,
       'backtrace_string' => $exception->getTraceAsString(),
+      '@backtrace_string' => $exception->getTraceAsString(),
     );
   }
 

Then we could just use @backtrace_string everywhere in core but leave backtrace_string for BC. The only thing that seems kind of out of scope is fixing the return value documentation for Error::decodeException() (it's backwards for something in Utility to refer to a procedural function for docs; should be the other way around).

Going to set at NR until we sort this one way or the other -- sorry @dawehner. :(

@xjm the reason I made it by reference is that backtraces are not small. Especially in some deeply nested rendering situation like threaded comments. We're already in a error situation and running out of memory for BC seemed pointless.

This is yet another reason I didn't want to actually make any changes to the Error class and just handle all the BC in _drupal_log_error() which why my preference has always been for #67. In my opinion we should go back to that and be done. Having multiple places where we handle BC also feels more fragile.

Reuploading the patch from #67.

Discussed the BC at length with @xjm. Salient points:

• \Drupal\Core\Utility\Error::decodeException() is documented to return An error in the format expected by _drupal_log_error(). - public API depending on _drupal_log_error?
• The backtrace_string was only introduced in 8.0.5 by #2646786: Add a backtrace for logged exceptions

Decided that the BC layer and difficulties implementing something simple means that we should just change the key and be done. I've updated the CR to reflect this.

Updating issue credit.

Committed dd1c1ce and pushed to 8.2.x. Thanks!

This issue is tagged for D7 backport, so according to our current backport policy, a separate issue to discuss that backport should be created and then we can mark this issue fixed.

#90: If its a bug, then it could be pushed to 8.1.x (the new description makes it look like a bug), as FR => no go.

Also:

YEAH!

@dawehner I think probably we should not backport it to 8.1.x in this case, particularly given the internal API addition/internal BC break. At this point 8.1.x is in commit freeze for 8.1.8 anyway, so there is only one more bugfix release for 8.1.x that will include any changes we make from this point forward, and we are very conservative for the month before the final patch release.

D7 issue is here: https://www.drupal.org/node/2777955, Thanks all!