Follow-up to #2638140: Error logging should log a backtrace consistently

Problem/Motivation

Software has bugs, so errors are there and will be logged.
Sadly by default Drupal just puts the line of the broken code, which is already helpful, but on the other hand often now really helpful, because you need a full backtrace to figure something out.

Proposed resolution

Log a backtrace on top of the actual error message.
This will just make the backtrace available in the variables section, but won't be displayed as part of the watchdog site.

D7: Make the new setting opt-in and provide a way to get the value.

Remaining tasks

User interface changes

API changes

Data model changes

CommentFileSizeAuthor
#18 2777955-18.patch4.92 KBamontero
#14 interdiff-2777955-12-14.txt3.26 KBaerozeppelin
#14 2777955-14.patch4.51 KBaerozeppelin
#12 interdiff-2777955-8-12.txt1.98 KBaerozeppelin
#12 2777955-12.patch2.42 KBaerozeppelin
#8 interdiff-2777955-2-8.txt902 bytesrachel_norfolk
#8 2777955-8.patch2.38 KBrachel_norfolk
#2 2777955-2.patch2.33 KBaerozeppelin
Support from Acquia helps fund testing for Drupal Acquia logo

Comments

Fabianx created an issue. See original summary.

aerozeppelin’s picture

aerozeppelin CreditAttribution: aerozeppelin commented
Status: Patch (to be ported) » Needs review
FileSize
2777955-2.patch2.33 KB

An initial attempt to port the patch to D7. Not sure if I am heading in the right direction. Any inputs would be helpful.

Status: Needs review » Needs work

The last submitted patch, 2: 2777955-2.patch, failed testing.

The last submitted patch, 2: 2777955-2.patch, failed testing.

The last submitted patch, 2: 2777955-2.patch, failed testing.

rachel_norfolk’s picture

rachel_norfolk
Primary language English
Location UK
CreditAttribution: rachel_norfolk at Open Development Ltd for Horizons Unlimited commented 
+++ b/includes/errors.inc
@@ -72,7 +71,14 @@ function _drupal_error_handler_real($error_level, $message, $filename, $line, $c
+    if (variable_get('enable_backtrace', TRUE)) {
+      $error_details['@backtrace_string'] = (new \Exception())->getTraceAsString();
...
   }

@@ -121,6 +127,12 @@ function _drupal_decode_exception($exception) {
+    $error_details['@backtrace_string'] = (new \Exception())->getTraceAsString();

It seems the method here of creating the exception is not liked by php53.

Maybe need to be a little more long-handed about it?

Fabianx’s picture

Fabianx CreditAttribution: Fabianx as a volunteer and at Tag1 Consulting commented

Yes, a variable "$e = new Exception();" is fine to use here.

rachel_norfolk’s picture

rachel_norfolk
Primary language English
Location UK
CreditAttribution: rachel_norfolk at Open Development Ltd for Horizons Unlimited commented
Status: Needs work » Needs review
FileSize
2777955-8.patch2.38 KB
interdiff-2777955-2-8.txt902 bytes

So, we should end up with something like the attached for php53 friendliness...

Fabianx’s picture

Fabianx CreditAttribution: Fabianx as a volunteer and at Tag1 Consulting commented 
  1. +++ b/includes/errors.inc
@@ -72,7 +71,15 @@ function _drupal_error_handler_real($error_level, $message, $filename, $line, $c
+    if (variable_get('enable_backtrace', TRUE)) {

@@ -121,6 +128,13 @@ function _drupal_decode_exception($exception) {
+  if (variable_get('enable_backtrace', TRUE)) {

    We need to document this variable and maybe rename it a little ore verbose:

    drupal_error_log_backtrace

    maybe? 

  2. +++ b/includes/errors.inc
@@ -211,6 +225,13 @@ function _drupal_log_error($error, $fatal = FALSE) {
+    if (array_key_exists('@backtrace_string', $error)) {
+      error_log(sprintf('%s: %s in %s on line %d %s', $error['%type'], $error['!message'], $error['%file'], $error['%line'], $error['@backtrace_string']));
+    }
+    else {
+      error_log(sprintf('%s: %s in %s on line %d', $error['%type'], $error['!message'], $error['%file'], $error['%line']));
+    }

    Are we sure we only want that for fatal errors?

rachel_norfolk’s picture

rachel_norfolk
Primary language English
Location UK
CreditAttribution: rachel_norfolk at Open Development Ltd for Horizons Unlimited commented
Issue tags: +Drupalaton
rachel_norfolk’s picture

rachel_norfolk
Primary language English
Location UK
CreditAttribution: rachel_norfolk at Open Development Ltd for Horizons Unlimited commented
Status: Needs review » Needs work
aerozeppelin’s picture

aerozeppelin CreditAttribution: aerozeppelin commented
Status: Needs work » Needs review
FileSize
2777955-12.patch2.42 KB
interdiff-2777955-8-12.txt1.98 KB

Changes as per #9.

Fabianx’s picture

Fabianx CreditAttribution: Fabianx as a volunteer and at Tag1 Consulting commented
Status: Needs review » Needs work

Thank you for your work on this!

Some more things:

  1. +++ b/includes/errors.inc
@@ -72,7 +71,16 @@ function _drupal_error_handler_real($error_level, $message, $filename, $line, $c
+    if (variable_get('drupal_error_log_backtrace', TRUE)) {

@@ -121,6 +129,13 @@ function _drupal_decode_exception($exception) {
+  if (variable_get('drupal_error_log_backtrace', TRUE)) {

    For BC reasons, the default needs to be FALSE.

    And we need to document the new value in settings.php. 

  2. +++ b/includes/errors.inc
@@ -255,6 +270,13 @@ function _drupal_log_error($error, $fatal = FALSE) {
+  if (array_key_exists('@backtrace_string', $error)) {
+    error_log(sprintf('%s: %s in %s on line %d %s', $error['%type'], $error['!message'], $error['%file'], $error['%line'], $error['@backtrace_string']));
+  }
+  else {
+    error_log(sprintf('%s: %s in %s on line %d', $error['%type'], $error['!message'], $error['%file'], $error['%line']));
+  }

    Oh - I think I misread, that, yes we likely want to do this whole block only for fatal errors, but for both if and else.

aerozeppelin’s picture

aerozeppelin CreditAttribution: aerozeppelin commented
Status: Needs work » Needs review
FileSize
2777955-14.patch4.51 KB
interdiff-2777955-12-14.txt3.26 KB

You're welcome. Thank you for reviewing my patch. I've updated my patch with the changes. Let's see what the test bot thinks.

Status: Needs review » Needs work

The last submitted patch, 14: 2777955-14.patch, failed testing.

David_Rothstein’s picture

David_Rothstein CreditAttribution: David_Rothstein as a volunteer commented
Status: Needs work » Needs review
Fabianx’s picture

Fabianx CreditAttribution: Fabianx as a volunteer and at Tag1 Consulting commented

Looks pretty good to me, still unsure about the helper function.

amontero’s picture

amontero
Location Barcelona
CreditAttribution: amontero commented
FileSize
2777955-18.patch4.92 KB

Need this and wanting to work on it.
Stale patch, reroll, feed the testbot.

Status: Needs review » Needs work

The last submitted patch, 18: 2777955-18.patch, failed testing. View results

Fabianx’s picture

Fabianx CreditAttribution: Fabianx as a volunteer and at Tag1 Consulting commented
Issue tags: +Drupal 7.60 target

Moving into 7.60 sprint

joseph.olstad’s picture

joseph.olstad
Primary language French
CreditAttribution: joseph.olstad commented

Please do not be alarmed by "composer Command Failed" - this is not an indication of a problem with the patch.
It occurs since approximately may 4th, there is a known testrunner issue. @mixologic (responsible for the testrunner) is on vacation
#2970950: D7 test runner not working since may 4th 2018 'Composer command failed'
Hopefully @mixologic gets back from his vacation soon.

joseph.olstad’s picture

joseph.olstad
Primary language French
CreditAttribution: joseph.olstad commented
Status: Needs work » Needs review

re-trigger testbot

Status: Needs review » Needs work

The last submitted patch, 18: 2777955-18.patch, failed testing. View results

joseph.olstad’s picture

joseph.olstad
Primary language French
CreditAttribution: joseph.olstad commented
Status: Needs work » Needs review
joseph.olstad’s picture

joseph.olstad
Primary language French
CreditAttribution: joseph.olstad commented
Issue tags: -Drupal 7.60 target +Drupal 7.70 target

Bumping to 7.70. This didn't make it into 7.60

rcodina’s picture

rcodina CreditAttribution: rcodina commented

I've been testing patch on #18 and it works for me.

joseph.olstad’s picture

joseph.olstad
Primary language French
CreditAttribution: joseph.olstad commented
Issue tags: -Drupal 7.70 target +Drupal 7.74 target

I like!