Problem/Motivation

For exceptions, Drupal core passes the raw PHP backtrace to logger implementations. It does not do so for PHP errors, warnings, notices etc. so the logger must regenerate the backtrace if it needs one (as various third-party logging libraries such as Sentry do).

Proposed resolution

Include the backtrace in the $context array for errors, just like it is for exceptions.

Remaining tasks

Review change notice: https://www.drupal.org/node/2868845

User interface changes

None

API changes

Logger implementations will receive the backtrace for errors, in addition to exceptions.

Data model changes

None

Original report by mfb

Logger implementations could make use of the raw debug_backtrace() array, rather than having to regenerate it (which I'd assume uses extra memory and wastes CPU cycles).

I'm not clear why core unsets the backtrace - it may be doing so for no good reason - so testing out this patch to see if it passes tests.

Support from Acquia helps fund testing for Drupal Acquia logo

Comments

mfb created an issue. See original summary.

mfb’s picture

Status: Active » Needs review

Status: Needs review » Needs work

The last submitted patch, backtrace-logger.patch, failed testing.

mfb’s picture

Status: Needs work » Needs review
FileSize
796 bytes

Ok now that I look at the code that couldn't possibly work.. $error is passed to various functions that expect an array of strings.

mfb’s picture

dawehner’s picture

This was just recently changed in #2638140: Error logging should log a backtrace consistently

Why do you need the full backtrace when you already have the string available? I'm also wondering why its important to care about performance in this case. Things are already super bad, when an error is triggered, isn't it?

mfb’s picture

dedicated logging systems like Sentry do a much better job displaying PHP backtraces than dblog or syslog. and they're often setup for centralized log aggregation across an organization. if it's not passed a backtrace, Sentry PHP library generates its own - including Drupal error logging functions which are not helpful.

Performance definitely matters because PHP notices and warnings are logged this way.

dawehner’s picture

Okay fair. My only worry is: When we include the backtrace some implementations might try to serialize it directly, which could cause issues, couldn't it?

mfb’s picture

context already contains $context['user'] which is the user object - so I would expect there shouldn't be any problem passing other non-strings in the logger context

mfb’s picture

dawehner’s picture

Status: Needs review » Reviewed & tested by the community

I haven't read #9 yet, that is a good point.

dagmar’s picture

Status: Reviewed & tested by the community » Needs review

There is another call to the php logger here: DefaultExceptionHtmlSubscriber::makeSubrequest

mfb’s picture

Status: Needs review » Reviewed & tested by the community

@dagmar in that method, $error array does include the raw backtrace courtesy of Error::decodeException

mfb’s picture

although, I think we should pass the raw Exception object in the logger context, as well.. but I guess that could be a separate patch..

alexpott’s picture

Status: Reviewed & tested by the community » Needs work
Issue tags: +Needs change record

I think we need a change record here. To inform loggers that _drupal_log_error will be passing the entire backtrace in.

Also I think if the message contains the word @backtrace the following code might be a bit interesting...

      // PSR3 style placeholders.
      if ($has_psr3) {
        // Keys are not prefixed with anything according to PSR3 specs.
        // If the message is "User {username} created" the variable key will be
        // just "username".
        if (strpos($message, '@' . $key) !== FALSE) {
          $key = '@' . $key;
        }
      }

I think having @backtrace atm would be a bug

mfb’s picture

Issue tags: -Needs change record

I think a change record is a bit superfluous, since loggers already receive the raw backtrace when logging exceptions, but I created a draft anyways, as I guess change records are also useful for spreading good news, not just scary breaking changes :)

mfb’s picture

Status: Needs work » Needs review
mfb’s picture

Title: pass the raw backtrace to logger implementations » pass raw backtrace to loggers for errors, not just exceptions
mfb’s picture

Issue summary: View changes
mfb’s picture

Anyone able to give this patch and change notice a review?

dawehner’s picture

Status: Needs review » Reviewed & tested by the community

I think having @backtrace atm would be a bug

I hope we don't let anyone control the actual message from outside :)

Status: Reviewed & tested by the community » Needs work

The last submitted patch, 4: backtrace-logger.patch, failed testing. View results

mfb’s picture

Status: Needs work » Reviewed & tested by the community

think that was a bogus test failure

Version: 8.4.x-dev » 8.5.x-dev

Drupal 8.4.0-alpha1 will be released the week of July 31, 2017, which means new developments and disruptive changes should now be targeted against the 8.5.x-dev branch. For more information see the Drupal 8 minor version schedule and the Allowed changes during the Drupal 8 release cycle.

  • catch committed 3d2b382 on 8.5.x
    Issue #2857437 by mfb: pass raw backtrace to loggers for errors, not...

catch credited catch.

catch’s picture

Status: Reviewed & tested by the community » Fixed

#16 and #21 are both good answers. Committed/pushed to 8.5.x, thanks!

mfb’s picture

we have a draft change record @ https://www.drupal.org/node/2868845

dawehner’s picture

@mfb
Thank you!
I just published it

Status: Fixed » Closed (fixed)

Automatically closed - issue fixed for 2 weeks with no activity.