Starting with Drupal 7, the system has become extremely modular. Generic functions are re-used in many places, so it's a horrible job to figure out where exactly an error originates from.

Issues like #1067750: Let Field API fail in a tale-telling way on invalid $entity only underline the problem space.

There are several problems with introducing a backtrace and the current patch attempts to address them. Some issues are:

We need better reporting for developers

A clear formatting has been setup and can easily be customized with a little CSS.

There is no one reporting format that will be universally useful

Various options to set the level of detail returned are available.

We don't want to make things complicated for the average user

These extra options are hidden in a collapsed fieldset and described as "being for developers."

We need to avoid possibly crashing from processing large variables that may even have recursion

Defaults to limit the length of variables that can be returned yet is adjustable if a developer needs more information.

Keeping it simple

The added options are added to the familiar: admin/config/development/logging configuration page.

Note: This patch may look large at first glance but once you mitigate the constant definitions at the top, the functions added to the bottom of errors.inc which only provide some nice formatting and the additions to the UI at admin/config/development/logging, it's quite modest.

CommentFileSizeAuthor
#301 improved-exception-log-interdiff.txt915 bytesklausi
#301 add_backtrace_to_all_errors-1158322-301-D7.patch4.56 KBklausi
#294 add_backtrace_to_all_errors-1158322-293-D7.patch4.1 KBdalin
#292 add_backtrace_to_all_errors-1158322-292-D7.patch3.41 KBdalin
#291 add_backtrace_to_all_errors-1158322-291-D7.patch3.21 KBdalin
#279 interdiff-276-279.txt3.16 KBReg
#279 add_backtrace_to_all_errors-1158322-279-D7.patch21.74 KBReg
#276 add_backtrace_to_all_errors-1158322-276-D7.patch21.55 KBReg
#275 add_backtrace_to_all_errors-1158322-275-D7.patch21.55 KBReg
#274 drupal-1158322-274-backtrace-d7-errors.patch20.75 KBAlan D.
#272 add_backtrace_to_all_errors-1158322-270-D7.patch20.79 KBReg
#268 add_backtrace_to_all_errors-1158322-268-D7.patch24.1 KBReg
#267 Screenshot-watchdog-test.png56.59 KBAlan D.
#260 interdiff-232-256.txt14.51 KBReg
#256 add_backtrace_to_all_errors-1158322-256-D7.patch24.09 KBReg
#251 add_backtrace_to_all_errors-1158322-251-D7.patch23.68 KBReg
#232 add_backtrace_to_all_errors-1158322-232-D7.patch21.92 KBReg
#222 interdiff.txt731 bytesReg
#221 interdiff.txt1.92 KBReg
#221 add_backtrace_to_all_errors-1158322-221-D7.patch21.92 KBReg
#220 interdiff.txt1.92 KBReg
#220 add_backtrace_to_all_errors-1158322-220-D7.patch22.57 KBReg
#218 interdiff.txt1.92 KBReg
#218 add_backtrace_to_all_errors-1158322-216-D7.patch21.05 KBReg
#215 interdiff.txt1.84 KBReg
#215 add_backtrace_to_all_errors-1158322-214-D7.patch20.52 KBReg
#213 interdiff.txt1.44 KBReg
#213 add_backtrace_to_all_errors-1158322-213-D7.patch20.4 KBReg
#209 add_backtrace_to_all_errors-1158322-209-D7.patch20.36 KBReg
#203 Update_Calculate-errorBacktrace_23FEB2015.jpg40.31 KBKebz
#199 drupal-1158322-199-backtrace-errors-D7.patch14.92 KBmikeytown2
#198 test-issue-1158322-198-2.png118.75 KBcesarmiquel
#198 test-issue-1158322-198.png94.37 KBcesarmiquel
#194 drupal-1158322-194-backtrace-errors-D7.patch14.34 KBmikeytown2
#192 drupal-1158322-192-backtrace-errors-D7.patch14.18 KBmikeytown2
#191 drupal-1158322-191-backtrace-errors-D7.patch14.15 KBmikeytown2
#188 drupal-1158322-188-backtrace-errors-D7.patch13.98 KBmikeytown2
#186 drupal-1158322-186-backtrace-errors-D7.patch13.97 KBmikeytown2
#179 drupal-1158322-179-backtrace-errors-D7.patch13.72 KBmikeytown2
#165 1158322-error_backtrace-161.patch28.44 KBReg
#161 1158322-error_backtrace-161.patch0 bytesReg
#158 1158322-error_backtrace-158.patch28.16 KBReg
#152 1158322-error_backtrace-151.patch29.06 KBReg
#147 1158322-error_backtrace-147-D8.patch21.67 KBReg
#141 1158322-error_backtrace-141-D8.patch13.27 KBReg
#138 1158322-error_backtrace-138-D7.patch10.62 KBReg
#137 1158322-error_backtrace-137-D7.patch9.87 KBReg
#129 1158322-error_backtrace-129-D7.patch9.8 KBReg
#127 1158322-error_backtrace-127-with_test-D7-do-not-test.patch7.33 KBmrfelton
#126 1158322-error_backtrace-126-with_test.patch6.92 KBdas-peter
#126 1158322-patch-diff-112-126.txt1.97 KBdas-peter
#122 fix-errors-1158322-122.patch2.2 KBAnonymous (not verified)
#114 1158322_114-do-not-test.patch1.69 KBchx
#112 1158322-error_backtrace-112-with_test.patch7.99 KBdas-peter
#111 1158322-error_backtrace-109-test_only.patch3.51 KBolli
#111 1158322-error_backtrace-109-with_test.patch6.92 KBolli
#109 drupal8.error-backtrace.109.patch3.41 KBsun
#100 1158322-error_backtrace-100.patch375 bytesolli
#96 testbot-fail.png72.35 KBmikeytown2
#92 drupal8.error-backtrace.92.patch1.19 KBsun
#82 drupal-1158322-82-add-backtrace-to-errors-D7.patch7.05 KBmikeytown2
#77 drupal8.error-backtrace.77.patch7.09 KBsun
#77 interdiff.txt1.08 KBsun
#72 drupal7.error-backtrace.1158322.72.D7-do-not-test.patch7.08 KBmrfelton
#71 drupal8.error-backtrace.1158322.71.patch7.11 KBsalvis
#68 drupal8.error-backtrace.68.patch6.14 KBsun
#59 drupal-1158322-59.patch5.91 KBamateescu
#56 drupal-1158322-56.patch5.91 KBtim.plunkett
#53 patch-1158322-53.patch5.87 KBartfulrobot
#50 exception.png92.41 KBwapnik
#43 Screen shot 2011-09-08 at 20.24.40.png102.02 KBsteinmb
#42 1158322-42-error-backtrace.patch5.91 KBjhedstrom
#34 Screen shot 2011-06-07 at 17.01.13.png128.52 KBsteinmb
#19 drupal.error-backtrace.19.patch4.4 KBsun
#19 error-backtrace.19.png13.84 KBsun
#1 error-backtrace.1.png13.76 KBsun
drupal.error-backtrace.0.patch4.07 KBsun
Support from Acquia helps fund testing for Drupal Acquia logo

Comments

sun’s picture

FileSize
13.76 KB

error-backtrace.1.png

pounard’s picture

You forgot probably the most important, exception stack trace. While PHP fatal errors will make you unable to get to this, and while common warnings can be catched and probably need this exact backtrace, most of the work should focus on loosy exception catching that core does and should probably push a "production mode" concept into core for development and testing sites.

Status: Needs review » Needs work

The last submitted patch, drupal.error-backtrace.0.patch, failed testing.

Lars Toomre’s picture

@pounard - Could elaborate on what you meant by 'loosy exception catching' and a 'production mode concept'?

Are you suggesting that core should respond if a different way to a variable indicating whether a site is development/staging/production (best practices BTW)?

pounard’s picture

@#4, For the later, yes totally what you said: most frameworks and piece of software allows to configure, at least, a production and a devel mode. ZF allows user to set as many "modes" as they can via configuration override (through the Zend_Config API). Each "mode" is (for the most, outside the site configuration) a set of variables such as error display, error logging, etc..

Drupal has the error level variable, but it's pretty much all that you can have, having finer granularity over "development" mode could be better to somehow force modules to use that in order to do their own different processing depending on the runtime mode (and development mode could mean different things among different sites, so it's basically a pure set of variables). For the most, the core isn't design to have a devel mode, and the error display handler is totally unable to display back trace. I'm actually fed off switching 10 variables to // comments each time I need to this while a single named parameter in the settings.php file (or even as environment variable inside the HTTPd configuration) would be more than enough to trigger a packaged set of variable overrides).

For the first part, about exception, there is something that is actually really anoying with D7, is that when you raise some exceptions, the sites goes to fallback maintenance theme (which is a good fallback mode actually) but doesn't display the exceptions stack trace (which imposes the developer to go to watchdog screen). While some errors can sometime prevent any page to be displayed (including watchdog screen, known as recent log entries), the devel mode should always trigger the full trace to be displayed by the error handler whatever happens.

I did this exact patch on a development site once, I should have kept it (trashed it actually). The actual functions in error.inc file are absolutely not designed to do this (they only keep the error message, that should actually not get to the end user when in production mode btw) so the patch was kinda tricky. I should be able to restore it somehow.

sun’s picture

Status: Needs work » Needs review

@pounard: Any discussion pertaining to a "production mode concept" belongs into a separate issue, not this one. Thanks.

And yes, the current patch only focuses on errors, not exceptions. For exceptions, we'd have to introduce a DrupalException class, which overrides PHP's default ->getMessage() method to append a similar backtrace, leveraging the ->getTrace() provided by PHP.

Additionally, built-in + bootstrap-safe handling for t() messages and arguments would be highly beneficial to have.

Also, just now I recognize that the function in the actual error message does not contain argument values like the functions in the backtrace.

jbrown’s picture

This is cool, but I would prefer a table.

dsm(debug_backtrace()); provides a lot more information.

sun’s picture

@jbrown: A table for what? And why?

Also, to make one thing crystal clear:

The next time someone proposes a full backtrace output, this issue will immediately won't fix.

pounard’s picture

@#6

And yes, the current patch only focuses on errors, not exceptions. For exceptions, we'd have to introduce a DrupalException class, which overrides PHP's default ->getMessage() method to append a similar backtrace, leveraging the ->getTrace() provided by PHP.

FOUTAISES! (French word for "bullshits"). Creating a specific exception specialization for Drupal is certainly a good idea, for finer error handling, while doing it for display purposes doesn't make any sense (current display is good enough, and if you want a custom one, please just build using the raw stack trace you can get as an array).
EDIT: Let me explain a bit more: Each time you override code by creating a layer over an existing one only because the API doesn't fit you what you like, you create what we call code indirection. Code indirection often leads to spagetti code and pretty much fucks up any framework. OOP inheritance is a good thing, when you use it for business reasons, exception's business is to have a granular error handling mecanism, and changing exception display IS NOT exception's business, please, NEVER ever override exception only for this kind of display purpose, you will create code indirection that may impact performances even when not running in devel mode.

Further more, this patch is useless without talking before of a framework-wide error handling strategy. All it will provide in the long term is a lot code indirection (other use case of code indirection here, split up code, then attempt to glue back pieces, only provides headaches and useless glue code) and will make everybody's life harder when it will come to unify already existing code for implementing a common solution in the end.
EDIT: Pretty much rewrote the full paragraph, better english and typo.

Damien Tournoud’s picture

Status: Needs review » Closed (duplicate)

This is a duplicate of #1157850: Provide detailed backtrace in the log for Drupal fatal errors, please keep this discussion in one place, please.

pounard’s picture

Thanks Damien.

Damien Tournoud’s picture

Status: Closed (duplicate) » Needs review

Actually, this patch seems superior. Marked the other issue as duplicate.

Damien Tournoud’s picture

Status: Needs review » Needs work

This patch looks good to me. There is only one thing to do: extend it to exceptions by passing the 'backtrace' key into _drupal_decode_exception(); there is no reason not to output a simplified backtrace for exceptions too (and the current patch introduced a notice in the exception handling code path).

pounard’s picture

#13 Damien+1 It would be a good thing to do.

rfay’s picture

Status: Needs work » Needs review

Wow, great stuff. Thanks for your work on this, @sun. I guess great minds think alike... or are annoyed by the same old thing over and over again. In commerce, we're seeing fatals show up in the issue queue and we have absolutely no way to get context on them.

I do like showing more information, and would appreciate you saying *why* that would make this a won't fix. Also would like to make sure we display information from exceptions, as an uncaught exception is just another kind of error.

Key differences in #1157850: Provide detailed backtrace in the log for Drupal fatal errors:
* There only fatals get a backtrace. Some sites exist with so many ongoing non-fatals that it may not be worth providing the backtrace for those. But I'm certainly open on this.
* There, exceptions get a backtrace and it seems to work just fine.
* There's a complete backtrace rather than a simplified one
* It only goes into the log. I don't really like taking an already scary fatal page and adding a stack trace to it and presenting that to the user.

Damien Tournoud’s picture

I'm fine with the current amount of information. Displaying more gets things tricky fast (do we want the full path of the files, or just the basename? something in between? do we want to display objects? how to handle that? etc.).

Damien Tournoud’s picture

Also, I'm fine displaying the backtrace by default when the error is displayed. We might consider making the display of the backtrace optional, but I don't really see the point (error display is already optional).

moshe weitzman’s picture

Looks good to me.

sun’s picture

No progress on exceptions yet, but

- removed removal of error source in the backtrace (so function arguments are visible for that, too)
- added safe attempt to not expose DRUPAL_ROOT

error-backtrace.19.png

Status: Needs review » Needs work

The last submitted patch, drupal.error-backtrace.19.patch, failed testing.

rfay’s picture

Status: Needs work » Needs review

Since we're working on this class of things, shameless plug for #1159422: Death to WSOD: Output information about what caused a fatal error

rfay’s picture

#19: drupal.error-backtrace.19.patch queued for re-testing.

moshe weitzman’s picture

I think we should restrict this to just www requests and not CLI.

Status: Needs review » Needs work

The last submitted patch, drupal.error-backtrace.19.patch, failed testing.

rfay’s picture

If you're testing: I created an error-creating fatal module for testing.

naught101’s picture

This would be absolutely awesome to something like this in the simpletest module as well, especially because you can't get a debug manually when running simpletest (ie. using something like dpm(debug_backtrace())).

Dunno if that should be part of this bug, or a separate issue?

aspilicious’s picture

+++ b/modules/field/modules/text/text.moduleundefined
@@ -9,6 +9,7 @@
+  $foo = $bar;

I don't think anything is wrong with this patch, it is this line (testing line) that is breaking the testbot.

Powered by Dreditor.

sun’s picture

Let's also move that algorithm generating a simplified/prettified backtrace output into a separate function. Would be useful for Devel and custom/other code. A full backtrace is often too heavy, especially for on-issue communication (just ran into this in another issue).

moonray’s picture

Including line numbers might be helpful as well. Sometimes functions are called several times in a function, and you might not know which on is at fault.

rfay’s picture

I agree; I copied this code to commerce_devel and was immediately forced to add file and line number. I used just basename($trace['file']) and $trace['line']

Anonymous’s picture

big plus one from me! may even be able to retire some of the debug code i've been using for longer than i can remember.

also, i really like #30, because i often want to look at cleaned up backtraces while developing, and it has nothing to do with errors.

steinmb’s picture

+1 from me too!
Running my dev. sandbox with patch #19

naught101’s picture

Would it be possible to put those errors in a collapsed fieldset? it's not uncommon that if you get one, you get a lot, and the messages could end up being quite long.

chx’s picture

Very useful and well done -- but I am hesitant a little. Do we want this on screen or watchdog only? We could amend the watchdog hook so that the modules logging can provide a link if they want (dblog and mongodb will, syslog won't) . One problem here is that sometimes errors come by the dozens or even the hundreds. Not to mention that I do not want to consider all the possible security implications. Should you leave error display on? No. But, should we make that mistake so much worse?

Also, since know the file path can we link the core functions (if it does not start with profiles or sites it's core) to api.drupal.org for convinience?

Finally, the part where we ucfirst(gettype()) -- if it's not scalar, then it's a resource, an object or an array. For arrays we could display a count like Array (20), for objects we could show the class like Object (NegativeDentry) and finally for resources: ob_start(); var_dump($x); ob_get_clean(). Because this shows the type of resource and even the internal identifier which can be used to discern between two resources of the same type.

chx’s picture

We have agreed to scrap the watchdog idea but instead create a new ERROR_REPORTING_VERBOSE level.

slefevre1’s picture

What would be handy is just to backtrace to the first (last?) non-core function in the call stack. It doesn't help me to know that there was a problem in form_execute_handlers(), but if it at least goes back to whatever last non-core function is in the call stack, that'd be a big help. Any PHP error that drupal reports to me is way too generic. You might as well get rid of them for what they're presently worth.

Q: are most/all errors going to originate in non-core functions? In other words, would this work/be useful in most cases? I don't know.

jhedstrom’s picture

Status: Needs work » Needs review

Here's the patch from 19 without the $foo = $bar line, so the tests should pass. I also added the ERROR_REPORTING_DISPLAY_VERBOSE constant, the change to the error form, and the logic of whether to display the backtrace or not.

Owen Barton’s picture

Subscribe - I think this will at least give some people better clues about where to look for and/or report bugs.

@jhedstrom - #39 is missing the patch you mention

moonray’s picture

One thing to watch for is large strings... drupal_render_page() for instance can be passed a VERY large string value.

The following will need to include some kind of trimming.

<?php
$call['args'][] = is_string($arg) ? "'$arg'" : $arg;
?>
jhedstrom’s picture

Oops. Here's the patch I forgot to actually upload in #39.

steinmb’s picture

Attached screenshot with running with #42

bryancasler’s picture

subscribe

naught101’s picture

Is there really much point having a backtrace with no line numbers or filenames?

pingers’s picture

Tend to agree, line and file helps a lot. Problems don't always stem from the last call in the stack (obviously). Objects can have overridden methods, so determining which class contains the actual called code is problematic without filename. Line number is useful when a function is called more than once from the originating function.

mrfelton’s picture

I too think we need filenames and line numbers for each function call in the stack.

pounard’s picture

Do this patch also add a backtrace field to watchdog database table and hook signature documentation so that those trace will always be present when logged?

rfay’s picture

Status: Needs review » Needs work

Will need reroll after the /core patch went in.

wapnik’s picture

FileSize
92.41 KB

What about displaying more information, like for example symfony does too. Few lines of code around the error, request info, ... What you think about adding Symfony\Component\HttpKernel\Debug\ErrorHandler and Symfony\Component\HttpKernel\Debug\ExceptionHandler to Drupal?

pounard’s picture

I like #50 suggestion, and because those two components are parts of the HttpKernel Synfony component, it's tied to what WSCCI is doing and will probably be included as a part of HttpKernel. I would definitely cleanup core error handling code.

Speaking of design, we could easily extend those two and raise events (using Synfony's EventDispatcher package) on errors so modules could act on those (we can keep a hook for registering module listeners though at first).

I definitely +1 wapnik suggestion.

EDIT: The event listener doesn't seems like a good pattern here, my opinion is that it should never exist more than one error listener; But, in order to reproduce the actual core hook_watchdog() behavior, we can do as I described upper easily.

Alan D.’s picture

(Off topic) Could we get permissions added while this is being refactored? The function / method signatures could be used to see what modules and versions are enabled, allowing easy discovery of possible security vulnerabilities. Maybe a new permission "view on-screen errors and warnings" or something?

artfulrobot’s picture

FileSize
5.87 KB

Patch from #42 did not apply cleanly on 7.14 for me. Here's one that did.

rfay’s picture

Status: Needs work » Needs review

Status: Needs review » Needs work

The last submitted patch, patch-1158322-53.patch, failed testing.

tim.plunkett’s picture

Issue tags: +Needs backport to D7
FileSize
5.91 KB

Rerolling #53 for D8.

tim.plunkett’s picture

Status: Needs work » Needs review
chx’s picture

Status: Needs review » Reviewed & tested by the community

The purpose of this patch is to provide a short backtrace to give some clue. Those needing more are welcome to install devel. I for myself like this.

amateescu’s picture

FileSize
5.91 KB
+++ b/core/includes/errors.inc
@@ -21,6 +21,11 @@ const ERROR_REPORTING_DISPLAY_SOME = 1;
 const ERROR_REPORTING_DISPLAY_ALL = 2;
 
 /**
+ * Error reporting level: display all messages, plus backtrace information.
+ */
+define('ERROR_REPORTING_DISPLAY_VERBOSE', 3);

Fixed in the attached patch. This is only a minor change so leaving at RTBC.

Alan D.’s picture

Trying not to sound like a broken record, can we slip in a permission check here for the screen errors?

I've used this code on a custom D7 module that is happy spitting out backtraces all over the place (Fields and Panels are generate so many warnings), but our clients is blissfully unaware and we are resolving these bugs much faster because of the code replicated from here and the fact that we get an instant backtrace.

+  global $user;
+  $detail_access = (!empty($user) && $user->uid == 1) || (function_exists('user_access') ? user_access('view screen errors') : 0);

And then in all of the corresponding locations:

  if (drupal_is_cli()) {
    if ($fatal) {
      // When called from CLI, simply output a plain text message.
-      print html_entity_decode(strip_tags(t('%type: !message in %function (line %line of %file).', $error))). "\n";
+      if ($detail_access) {
+        $message = t('%type: !message in %function (line %line of %file).', $error);
+      }
+      else {
+        $message = t('The website encountered an unexpected error. Please try again later.');
+      }
+      print html_entity_decode(strip_tags($message)) . "\n";
      exit;
    }
  }

  if (isset($_SERVER['HTTP_X_REQUESTED_WITH']) && $_SERVER['HTTP_X_REQUESTED_WITH'] == 'XMLHttpRequest') {
    if ($fatal) {
      // When called from JavaScript, simply output the error message.
-      print t('%type: !message in %function (line %line of %file).', $error);
+      if ($detail_access) {
+        print t('%type: !message in %function (line %line of %file).', $error);
+      }
+      else {
+        print t('The website encountered an unexpected error. Please try again later.');
+      }
      exit;
    }

-    if (error_displayable($error)) {
+    if ($detail_access && error_displayable($error)) {
tstoeckler’s picture

Can we do #60 in a follow-up / separate issue?!
Seems like that needs some more discussion and this has been lingering for so long already.

amateescu’s picture

Agreed with #61. I'm tired of installing commerce_devel just to get this important piece of DX.

Alan D.’s picture

salvis’s picture

I'm tired of installing commerce_devel just to get this important piece of DX.

I was on the brink of adding the commerce_devel code to devel, but it requires duplicating an awful lot of core code to get it right, because core is so uncooperative.

Let me look into this to see what it would take to provide a reasonable integration point.

chx’s picture

because core is so uncooperative.

. Hrm. What is missing? Please file an issue for any missing hooks, alters etc

salvis’s picture

Yes, I'll open a new issue. We'll need a new hook.

devel_commerce duplicates the entire 76-line _drupal_log_error() function just to customize two lines.


+++ b/core/includes/errors.inc
@@ -241,13 +253,55 @@ function _drupal_log_error($error, $fatal = FALSE) {
+      // Do not expose DRUPAL_ROOT, if possible.
+      $root_length = strlen(DRUPAL_ROOT);
+      if (substr($error['%file'], 0, $root_length) == DRUPAL_ROOT) {
+        $error['%file'] = substr($error['%file'], $root_length + 1);
+      }

We could and maybe should do more here. I have found that if Drupal is symlinked into the webroot directory (for easy sharing among multiple sites), then DRUPAL_ROOT will contain the path in the webroot, but PHP delivers the resolved paths in the file system. This means there is no match and the file system path is exposed.

catch’s picture

Status: Reviewed & tested by the community » Needs work

I'm not sure we should add the DRUPAL_ROOT check at all here, see http://groups.drupal.org/node/230373 for example.

If we add it, but it doesn't work all the time, we'll get more 'full path disclosure vulnerability!?!!!!" crap.

If we don't do it at all, then we might still get that but we can just say we don't care at all.

I can maybe see an argument for shortening the filenames just to reduce verbosity, but then is that the right place?

sun’s picture

Status: Needs work » Needs review
FileSize
6.14 KB

The paths are shortened to reduce verbosity only. At no point in time I considered "security" to be a reason for the shortening.

To account for that, for now, I'd recommend to implant the verbosity reason into code comments, because - yes, the code does not explain why this is done, so anyone reading it might mistakenly believe that this is a (poor) security "feature".

I'd suggest to enhance both the constant definition as well as the inline comment above the code block that performs the stripping:

+++ b/core/includes/errors.inc
@@ -21,6 +21,11 @@ const ERROR_REPORTING_DISPLAY_SOME = 1;
 /**
+ * Error reporting level: display all messages, plus backtrace information.
+ */
+const ERROR_REPORTING_DISPLAY_VERBOSE = 3;

@@ -241,13 +253,55 @@ function _drupal_log_error($error, $fatal = FALSE) {
+      // Do not expose DRUPAL_ROOT, if possible.

Done so.

I'd prefer a separate follow-up issue for #66 to improve the symlink case. We might be able to use realpath(DRUPAL_ROOT), but as usual, I guess that needs a lot of dedicated testing on its own.

salvis’s picture

Status: Needs review » Needs work

EDIT: Ignore this comment!

+++ b/core/includes/errors.inc
@@ -193,6 +201,10 @@ function _drupal_log_error($error, $fatal = FALSE) {
+  // Backtrace array is not a valid replacement value for t().
+  $backtrace = $error['backtrace'];
+  unset($error['backtrace']);
+

'backtrace' is not '!backtrace', and thus no replacement candidate value; 'severity_level' is not intended for t() either.

Once this patch has landed, I'd like to propose a new hook_log_error($error) that passes $error for any module that wants to display/log/whatever the message in an alternative way. It would be nice to pass the backtrace, too. This could be an additional parameter, but why not just leave it in $error and pass $error unchanged?

salvis’s picture

(didn't mean to change the status)

salvis’s picture

Status: Needs work » Needs review
FileSize
7.11 KB
+++ b/core/includes/errors.inc
@@ -21,6 +21,14 @@ const ERROR_REPORTING_DISPLAY_SOME = 1;
+ * Error reporting level: display all messages, plus backtrace information.
+ *
+ * DRUPAL_ROOT is attempted to be stripped from file paths in the backtrace to
+ * reduce verbosity only, not for (false) security reasons.

Actually, the stripping is not related to the "backtrace information" -- it's about the path in the error message. Drop the second paragraph.

+++ b/core/includes/errors.inc
@@ -193,6 +204,10 @@ function _drupal_log_error($error, $fatal = FALSE) {
+  // Backtrace array is not a valid replacement value for t().
+  $backtrace = $error['backtrace'];
+  unset($error['backtrace']);
+

t() does not like having additional stuff in its $variables argument, especially non-scalars. So this is needed — ignore my comment in #69.

+++ b/core/includes/errors.inc
@@ -241,13 +256,56 @@ function _drupal_log_error($error, $fatal = FALSE) {
+      // Attempt to reduce verbosity by removing DRUPAL_ROOT from file paths in
+      // the backtrace. This does not happen for (false) security.

Fix the comment to not mislead.

In addition to the items above, I've made the following changes:

Fixed the docblock of _drupal_log_error() to document the new 'backtrace' key.

Moved the formatting of the backtrace to a separate _drupal_format_backtrace() function. This improves the code structure, and the function can be useful for contribs.

Added passing string arguments through filter_xss().

mrfelton’s picture

Nice. Here it is for those that want in their D7 make files.

chx’s picture

Thanks for working on the Drupal 7 backport. However, it's premature -- we only backport once the patch is committed.

I must say I hate with a fiery passion when people post patches for drush make! It typically makes the queue harder to follow and flies straight against http://drupal.org/best-practices/do-not-hack-core .

chx’s picture

Status: Needs review » Reviewed & tested by the community

#67 is addressed so back to green. Perhaps we could salvage #72 as well as if this goes in.

mrfelton’s picture

Sorry chx, but it's a very useful patch wether for Drupal 8 or Drupal 7. I tested #71 on D8, it did the job, it passed all the tests, so I backported it. This issue was tagged as "needs backport to Drupal 7" back in comment #56. I marked the patch clearly as a D7 patch, and one that the testbot should ignore. I don't know how you can possibly call that hacking core.

chx’s picture

I thought #73 was quite clear on what my problem was -- and sorry for lashing out at you. In this case it's not that bad -- but often we see these drush make patches in very long, convoluted issues and even on those that have zero chance of getting in. I expressed my hopes in fact that your patch can be used, after all.

sun’s picture

Moved the formatting of the backtrace to a separate _drupal_format_backtrace() function. This improves the code structure, and the function can be useful for contribs.

_ denotes a private function though, which shouldn't be used by anything else. I agree with the intention and general usefulness, so here's a quick fix for that.

salvis’s picture

_ denotes a private function though, which shouldn't be used by anything else.

Agreed, but no scope prefix, i.e. format_backtrace()? There are certainly other ways to format a backtrace.

I modeled the docblock after the one for _drupal_get_last_caller(), but I agree with sun's improvements in #71. Should we improve the _drupal_get_last_caller($backtrace) docblock accordingly (and add the type hint)? Can/should we remove that underline, too?

sun’s picture

I only adjusted the phpDoc of the newly added function. Fixing phpDoc of existing functions is left for dedicated general code clean-up issues.

webchick’s picture

Category: task » feature

This seems like a nice useful feature, but it's a feature, not a task. I'll get back to this again when I'm through the rest of the major/critical tasks/bugs.

catch’s picture

Version: 8.x-dev » 7.x-dev
Status: Reviewed & tested by the community » Patch (to be ported)

Committed/pushed to 8.x, moving to 7.x for backport.

mikeytown2’s picture

Status: Patch (to be ported) » Needs review
FileSize
7.05 KB

Pretty much a straight port from #77 to D7.

chx’s picture

Status: Needs review » Reviewed & tested by the community

I think this is good to go , I do not see any string changes only a single addition t('All messages, with backtrace information')

steinmb’s picture

Looking good, RTBC.

Wim Leers’s picture

OMG YES. This will make it a zillion times easier for contrib modules to debug things (because many non-technical users don't know the kind of information we need). Thanks to all of you who made this happen!

sun’s picture

Alan D.’s picture

And just in case this is forgotten about: #1608034: Add permissions for displaying errors

Live sites have errors too and errors shouldn't show to non-admins / developers!

geek-merlin’s picture

So this has 8.x and 7.x RTBC patches.
Will this get attention as 7.x issue?

Alan D.’s picture

#82 appears to have the go ahead to commit into 7.x - it is already in 8.x

#86 is to allow developers to alter the settings in the settings.php file without resorting to meaningless numbers like 32767 or 30719 for E_ALL (PHP version dependent)

#87 is to allow site builders to run this on live sites without exposing the internals to the entire world

David_Rothstein’s picture

Sorry, the combination of string addition, UI change, and form structure change makes me not want to commit this right before the Drupal 7.15 release. Let's hold off and discuss again after that.

I think as long as we provide some advanced notice (and commit this towards the beginning of a release cycle) it's OK, though.

But..... why does this patch not have tests (for either Drupal 7 or Drupal 8)? There's a DrupalErrorHandlerTestCase in the codebase that attempts to test each of the 'error_level' options, but now it doesn't have any tests for the new option being added.

sun’s picture

Version: 7.x-dev » 8.x-dev
Status: Reviewed & tested by the community » Needs work

Sorry to do this, but there is a flaw somewhere in the code, so it's probably not that bad that we didn't commit the backport yet.

For certain errors/exceptions, an additional error/exception is thrown. I wasn't able to identify yet what exact kind of errors/exceptions are triggering the additional one.

Manually dumping a debug_backtrace() yields this:

  [1]=>
  array(4) {
    ["file"]=>
    string(54) "core\includes\errors.inc"
    ["line"]=>
    int(253)
    ["function"]=>
    string(17) "error_displayable"
    ["args"]=>
    array(1) {
      [0]=>
      &array(6) {
        ["%type"]=>
        string(6) "Notice"
        ["!message"]=>
        string(26) "Undefined index: backtrace"
        ["%function"]=>
        string(19) "_drupal_log_error()"
        ["%file"]=>
        string(54) "core\includes\errors.inc"
        ["%line"]=>
        int(208)
        ["severity_level"]=>
        int(5)
      }
    }

So it looks like some errors/exceptions do not have a backtrace, and/or _drupal_log_error() might be called from another place, which didn't pass the error/exception through _drupal_error_handler_real().

sun’s picture

Status: Needs work » Needs review
FileSize
1.19 KB

This would be the obvious "quick fix", but I don't think that's the proper thing to do.

scito’s picture

Currently, backtraces are not added to watchdog loggings. Is there a reason not add them to watchdog loggings?

Backtraces in watchdog entries would be useful on production sites, especially since UI logging is normally disabled on production sites.

rooby’s picture

@scito:

I'm guessing you haven't read any of this issue.

mikeytown2’s picture

Got testbot to throw "Undefined index: backtrace Notice".
http://qa.drupal.org/pifr/test/329463

mikeytown2’s picture

FileSize
72.35 KB

Looks like that went away, so here is a screenshot of it. More info on what failed... http://drupal.org/node/818818#comment-6417664

sun’s picture

Assigned: sun » Unassigned

Thanks @mikeytown2, that seems to be exactly the same nested exception I'm frequently encountering, too. I won't have time to look further into this, so I hope someone else can take over.

Cameron Tod’s picture

I am currently having an error which triggers the "Undefined index: backtrace" notice, related to #1798732: Convert install_task, install_time and install_current_batch to use the state system.

I'm not sure if this of any use, but I thought I would at least make a note of it here - hopefully it helps to narrow things down.

Starting Drupal installation. This takes a few seconds ...                                                                          [ok]
Undefined index: backtrace errors.inc:188                                                                                              [notice]
WD php: Symfony\Component\DependencyInjection\Exception\InvalidArgumentException: The service definition "keyvalue" does not exist. [error]
in Symfony\Component\DependencyInjection\ContainerBuilder->getDefinition() (line 690 of
/Users/cam8001/Sites/drupal/core/vendor/symfony/dependency-injection/Symfony/Component/DependencyInjection/ContainerBuilder.php).
Symfony\Component\DependencyInjection\Exception\InvalidArgumentException: The service definition "keyvalue" does not exist. in Symfony\Component\DependencyInjection\ContainerBuilder->getDefinition() (line 690 of /Users/cam8001/Sites/drupal/core/vendor/symfony/dependency-injection/Symfony/Component/DependencyInjection/ContainerBuilder.php).

$error is

array (
  '%type' => 'Symfony\\Component\\DependencyInjection\\Exception\\InvalidArgumentException',
  '!message' => 'The service definition &quot;keyvalue&quot; does not exist.',
  '%function' => 'Symfony\\Component\\DependencyInjection\\ContainerBuilder->getDefinition()',
  '%file' => '/Users/cam8001/Sites/drupal/core/vendor/symfony/dependency-injection/Symfony/Component/DependencyInjection/ContainerBuilder.php',
  '%line' => 690,
  'severity_level' => 3,
)

Heres a gist with a backtrace. https://gist.github.com/3956062

sun’s picture

It is possible that #1536868: No trace when database is down fixed the PHP notice about the missing 'backtrace'. I did not verify this, only saw that commit in the log.

olli’s picture

Here is one missing line.

sun’s picture

Status: Needs review » Reviewed & tested by the community

Well, that totally looks more like it. Thanks! :)

Wim Leers’s picture

Heh, what a lovely patch :)

webchick’s picture

Version: 8.x-dev » 7.x-dev
Status: Reviewed & tested by the community » Patch (to be ported)

Great catch! :)

Committed and pushed to 8.x. Back to 7.x for porting as per the tags, though I'm not sure if David's into that idea or not.

Berdir’s picture

Getting the following now when an exception is thrown, I think that is caused by this patch:

htmlspecialchars() expects parameter 1 to be string, array given
htmlspecialchars(Array, 3, 'UTF-8')
check_plain(Array)
drupal_placeholder(Array)
format_string('%type: !message in %function (line %line of %file). !backtrace', Array)
Drupal\simpletest\TestBase->exceptionHandler(Object)
Drupal\simpletest\TestBase->run()
_simpletest_batch_operation(Array, '208', Array)
call_user_func_array('_simpletest_batch_operation', Array)
_batch_process()
_batch_do()
_batch_page()
system_batch_page()
call_user_func_array('system_batch_page', Array)
Drupal\Core\EventSubscriber\LegacyControllerSubscriber->Drupal\Core\EventSubscriber\{closure}()
call_user_func_array(Object, Array)
Symfony\Component\HttpKernel\HttpKernel->handleRaw(Object, 1)
Symfony\Component\HttpKernel\HttpKernel->handle(Object, 1, 1)
Drupal\Core\HttpKernel->handle(Object, 1, 1)
Symfony\Component\HttpKernel\Kernel->handle(Object)

Which is because of:

    // The exception message is run through check_plain() by _drupal_decode_exception().
    $message = format_string('%type: !message in %function (line %line of %file). <pre class="backtrace">!backtrace</pre>', _drupal_decode_exception($exception) + array(
      '!backtrace' => format_backtrace($verbose_backtrace),

So the backtrace array is passed to format_string(), which tries to check_plain() it.

webchick’s picture

Version: 7.x-dev » 8.x-dev
Status: Patch (to be ported) » Needs work

Here we go again...

sun’s picture

Additionally, the entire code of errors.inc has been duplicated into ExceptionController...

None of the code that has been added by this issue exists in there.

I don't know in which situations the functions in errors.inc are triggered in HEAD — they're still registered early in the bootstrap, and I've seen verbose error messages including backtrace in HEAD up until very recently, but we completely changed the bootstrap to boot DrupalKernel instead (as of yesterday) and the Symfony Kernel is known to overload the environment.

I was under the assumption that we disabled that by overriding Kernel::init() in DrupalKernel, but in trying to debug an exception to debug some other functionality, I factually don't see any function in errors.inc getting invoked (except error_displayable(), which is weird on its own...) — instead, the entire thing runs through Drupal\Core\ExceptionController::on500Html(), which still calls into various procedural functions, but I'm not able to make sense of it.

sun’s picture

Category: feature » task
Status: Needs work » Active

This essentially means that the entire patch in #77 needs to be redone. (plus the follow-up fix from #100)

catch’s picture

Category: task » bug
sun’s picture

Status: Active » Needs review
FileSize
3.41 KB

Attached patch re-implements #77 and #100 in ExceptionController.

I'm getting a formatted backtrace with this again.

Status: Needs review » Needs work

The last submitted patch, drupal8.error-backtrace.109.patch, failed testing.

olli’s picture

Status: Needs work » Needs review
FileSize
6.92 KB
3.51 KB

Attached a simple test.

das-peter’s picture

Updated patch, fixes the mentioned issue in #104 from berdir.

Status: Needs review » Needs work

The last submitted patch, 1158322-error_backtrace-112-with_test.patch, failed testing.

chx’s picture

Here's some patch from the other end of the problem. It nukes the backtrace before format_stringing it from update or testbase. Not sure how helpful it is, but it's written and maybe it helps.

Berdir’s picture

Status: Needs work » Needs review
Berdir’s picture

+++ b/core/modules/system/lib/Drupal/system/Tests/System/ErrorHandlerTest.phpundefined
@@ -121,6 +123,24 @@ function testExceptionHandler() {
+    // We cannot use assertErrorMessage() since the extact error reported
+    // varies from database to database. Check that the SQL string is displayed.

extact => exact.

Status: Needs review » Needs work
Issue tags: -DX (Developer Experience), -Needs backport to D7

The last submitted patch, 1158322-error_backtrace-112-with_test.patch, failed testing.

Berdir’s picture

Status: Needs work » Needs review
Issue tags: +DX (Developer Experience), +Needs backport to D7
Anonymous’s picture

37ea2e09c90fd4ee6deb22040d0eae9bc06b5ef8 breaks callers of _drupal_decode_exception(). i just wasted a bunch of time trying to figure out a heisenbug over in #1331486: Move module_invoke_*() and friends to an Extensions class because of this.

please can we rollback?

Anonymous’s picture

if we're not going to rollback, can we commit something along the lines of #114 to stop the bleeding?

webchick’s picture

Can you review it and mark it RTBC if it fixes your problem? :)

Anonymous’s picture

attaching #114 so the bot runs it. i think it's RTBC, looked at usage of _drupal_decode_exception() and this covers the cases that were broken by the 'backtrace' array in it's output.

i've added on doc fix to #114 - we had a reference to drupal_decode_exception instead of _drupal_decode_exception.

so if this comes back green, i'm going to RTBC - no commit credit, the patch is chx's work.

Anonymous’s picture

Status: Needs review » Reviewed & tested by the community

yay.

webchick’s picture

Version: 8.x-dev » 7.x-dev
Category: bug » feature
Status: Reviewed & tested by the community » Patch (to be ported)

Have we finally seen the end of this perma-major? Tune in tomorrow! ;)

Committed and pushed to 8.x.

Oh-so-tentatively marking down to 7.x for backport, but I recommend waiting awhile to see how the dust settles first.

Berdir’s picture

Version: 7.x-dev » 8.x-dev
Status: Patch (to be ported) » Needs work

I think not.

I'm not sure why #114 was committed and not #112, which I think contained a fix for the problem as well + other improvements and test coverage.

What #112 did not contain is the update.inc change, so let's not roll back (I'm glad at least the ugly exception in case of test exceptions was fixed) but #112 will need a re-roll now.

das-peter’s picture

Status: Needs work » Needs review
FileSize
1.97 KB
6.92 KB

I hope this is re-rolled properly.

mrfelton’s picture

Really need something that works for Drupal 7 too. Attached is a backport of the patch in #126.

Berdir’s picture

Also, can we update watchdog_exception() to include the backtrace as well while we're at it? Because that's the one where it would be *really* useful.

Reg’s picture

Status: Needs work » Needs review
FileSize
9.8 KB

This patch is against drupal 7.18. Since this is an issue for Drupal 8 this will probably fail testing.

Also, I added a couple of features, namely:

  • You can choose whether the output goes to the page and/or the log
  • You can choose to display either with scalar variables as before and/or a stack trace. I find the stack trace option more useful in most cases since if I need to start looking at variables being passed I'll probably be using a real IDE/debugger for the job. A simple stack trace on the otherhand has helped me countless times determining where an error is originating without resorting to a debugger.

In any case, the prime goal here is to add flexibility. If anyone else has other outputs they find useful it would be very easy to copy the methodology I used to add another format. I mention this because I noticed earlier in the issue much debate over what should be displayed. There's never going to be one best display of information so some choices should help.

Status: Needs review » Needs work

The last submitted patch, 1158322-error_backtrace-129-D7.patch, failed testing.

salvis’s picture

Status: Needs review » Needs work

Thank you, but we need to get the D8 version committed first.

Reg’s picture

Well, it's there for anyone using D7 that wants it.

I wouldn't mind doing it for D8 but my time is limited and I checked the error that was generated "Detect a non-applicable patch". I really don't know what that means or how I would go about finding exactly what it's complaining about. I'm a little shy of jumping in trying pass all the tests for a version I've never used when I can't really figure out the line(s) the tester is complaining about.

Perhaps you could give me some insight on where the detail of what created that message is? I looked around and couldn't find anything to give any extra detail.

David_Rothstein’s picture

@Reg, I think you already answered your own question above :)

This patch is against drupal 7.18. Since this is an issue for Drupal 8 this will probably fail testing.

So yeah, that's all that's happening really; the testbot is trying to apply the patch to Drupal 8 and it doesn't apply there since it was written for Drupal 7.

Most likely there are several reasons why the patch won't apply, but the main one is that in Drupal 8 all the modules and such have been moved into the top-level core/ directory...

Reg’s picture

Ok, I appreciate that however what I still want to know is how do I "see" that in the test results.

This is one thing: "Detect a non-applicable patch". What I would expect to see is: "File referenced in patch .../xyz not found." ...anything that's not a cryptic response.

What's concerning me is if I tackle creating a patch for a version I don't yet know that passes testing am I going to be spending all my time trying to decode what the tester is saying because that's only one error but I when I looked at the results saw dozens of checks, perhaps close to a 100... that's a lot to go wrong and spend time scratching your head over what it's telling you.

mikeytown2’s picture

Version: 8.x-dev » 7.x-dev
Status: Needs work » Needs review

Going to retest #129 under D7

mikeytown2’s picture

#129: 1158322-error_backtrace-129-D7.patch queued for re-testing.

Once this test is done, we can switch the issue back to 8.x

Reg’s picture

Very cool and thank you so much. If I wasn't so tapped out for time I would tackle the D8 version but I just can't right now so I really appreciate this!

I've been using this over the last couple of days and made a couple of tweaks (changed a label and removed a couple of "notices" that came up under certain circumstances). I've attached the update here.

One thing that I know should be changed is there is a very tiny bit of styling added for a table that is generated in the PHP. I'm sure someone who knows the drupal system CSS well could remove that (it's only a couple of lines) and just hard code in some existing CSS classes. I added a TODO in there to that effect.

Reg’s picture

This has one change only. Occasionally a PDOException will get through and if you have it set to send to watchdog the PDO will reject the exception since you can't send errors from using the PDO back though the PDO. This is a restriction by PHP, and it makes perfect sense so no complaints here.

This addition checks for such an error and if you have it set to go to watchdog it simply won't thus preventing a cascade of errors. The danger here is that the error could get "thrown away" if you don't have it set to display errors as well.

I'm in two minds about this, it would easy enough to force the error to the display if we don't allow to go to watchdog however there are user settings to control that and I don't necessarily want to ignore the user settings.

I could make an argument to force to show the error or equally well to leave it up to the user. If anyone wants to chime in, please do.

sun’s picture

Version: 7.x-dev » 8.x-dev
Category: feature » task
Status: Needs review » Needs work
Issue tags: -Needs backport to D7

Friends, this issue is getting completely out of hands again. This is still not working correctly in HEAD, since we magically skipped over an essential follow-up patch. I'm removing the backport tags and everything else. This needs to be fixed in HEAD first.

The D8 patch that is still required is #109/#126.

Also noteworthy: The committed follow-up patch from #122 added manual unset($variables['backtrace']) calls to various places, but that is not sufficient; hook_watchdog() implementations still get a backtrace that may contain data that cannot be serialized: #1934738: Exception: Serialization of 'Closure' is not allowed in serialize() (line 154 of dblog.module)

Reg’s picture

@sun:#139 The error you are referring to I just came across and fixed. I believe it is the very last bug in the code (although you never know for sure).

Anyway, the code is here: http://drupal.org/node/1937832.

If you look for the function "array_has_PDOException" and the two calls to it and incorporate it into your D8 code you will have removed that error. Sorry I couldn't do this directly on D8 yet but at least there is a fix you can adopt easily enough for whomever is working in this problem.

Reg’s picture

I don't have a running copy of D8 however the code is so similar to D7 (for the parts that relate to this) it wasn't hard to manually splice the D7 code into the D8 code.

Of course there is more than a decent chance I made a mistake along the way so I would very much appreciate anyone who's actively running D8 to test this and let me know of anything that comes up. I'll fix it quickly so we can finally get better error reporting officially integrated into Drupal.

This is meant to be identical to the latest patch for D7 I did that's seems to be working perfectly (at http://drupal.org/node/1937832#comment-7154472 so you can use that as well for a reference if you want to do a little debugging yourself).

One thing I avoided is adding 2 tests. I think you really want a running copy for that however I did add a TODO where they should go.

Berdir’s picture

Thanks for working on this, here is a quick review. Don't try to do too much in here.

+++ b/core/includes/bootstrap.incundefined
@@ -57,10 +57,15 @@
+ * Error reporting type of debug information: Add stacktrace or backtrace information to logs.
...
+ * Error reporting type of debug information: Add stacktrace or backtrace information to messages on page.

Comment shouldn't be longer than 80 characters.

+++ b/core/includes/bootstrap.incundefined
@@ -57,10 +57,15 @@
+const ERROR_REPORTING_DISPLAY_LOGS = 1;  // Do not start at zero.

Comments shouldn't be appended to code but always be on their own line. Also, why is this not using a stringe like the other constants?

+++ b/core/includes/errors.incundefined
@@ -186,8 +185,11 @@
+    $backtrace = debug_backtrace(TRUE);

As of PHP 5.3.6, which we now require, the arguments to that function have changed, see http://php.net/debug_backtrace

+++ b/core/includes/errors.incundefined
@@ -209,7 +211,29 @@
+  $st_opts=variable_get('error_stacktrace_display', array());
...
+  $bt_opts=variable_get('error_backtrace_display', array());

Needs spaces around the =. And it shouldn't use variable_get() but config()

+++ b/core/includes/errors.incundefined
@@ -209,7 +211,29 @@
+  if (!array_has_PDOException($error)) { // If it was a DB error don't write to the DB.
+    watchdog('php', $message_line, $error, $error['severity_level']);

That should a) be handled by dblog.module, for which there is a specific issue and b) we actually should never pass a backtrace array through to watchdog, only the generated string. Then this wouldn't be a problem.

+++ b/core/includes/errors.incundefined
@@ -357,5 +408,64 @@
     $return .= $call['function'] . '(' . implode(', ', $call['args']) . ")\n";
...
-  return $return;
+  return '<br/><br/>BACKTRACE:<br/>' . $return;

I don't think this should be changed. As you can see in the line above, this function currently doesn't assume that it returns HTML and is returned in a HTML response.

Reg’s picture

On all but the last two points: First, it's less than I thought it would be given a manual splicing of code and having never run D8 so I'm not feeling too bad about it but it is going to be difficult to get it right since none of my work involves working on D8. Is there any chance you could tweak those few and give it whirl? That would be big help!

On the last two points:

That should a) be handled by dblog.module, for which there is a specific issue and b) we actually should never pass a backtrace array through to watchdog, only the generated string. Then this wouldn't be a problem.

a) Agreed, I hadn't got around to moving it but it was in the plan.

b) Agreed, and I already thought this one through a bit and the reasoning goes a little beyond what "should be". The reality is that you just don't know what people are going to do with contributed modules (or for that matter even a core bug could cause the same problem) and this PDOException getting through to watchdog is such a showstopper that's it's worth throwing in extra protection like this. You will also see a similar check right in watchdog for the same reason (they both need to be in place to work). If you don't then what can happen is you "lose" the error that caused the problem and the only problem you see is that "cannot pass PDOExecption to..." (I've experienced this first hand it's not fun to deal with) which then defeats what we are trying to achieve which is easier debugging. So, in this case, being overly careful and protective is not a bad thing at all so from already having experienced the problems that can otherwise happen, it's a good thing to keep it as is.

return '<br/><br/>BACKTRACE:<br/>' . $return;
I don't think this should be changed.

It's changed for a very good reason. You should test it before setting yourself on this conclusion. It is complimentary to:
return '...STACKTRACE:..'
I've been using these two quite a bit in D7 and they report well together the way I have done them. It also sets up a precedence for if/when someone may add other reporting styles, i.e., we've given each type a header to distinguish them.

Crell’s picture

Coming here from #1872690: Exception: Serialization of 'Closure' is not allowed in serialize.

Why exactly do we need to serialize a backtrace that in many cases is not serializable, because this is PHP and not everything is serializable?

And if we need to log exceptions, have a look at Symfony's FlattenException that is intended to address the same issue.

steinmb’s picture

Reg’s picture

I'm not sure where backtrace is getting serialized. It's certainly not in any of the code that I created to have the backtrace so I could only assume it's built into a function that gets called along the way I've not fully looked at, if at all. The full backtrace isn't used anyway, for the purpose of readability it's stripped down and summarized in two different forms, each of which you can choose to use or not. (patch at #141 above).

Regarding using symphony, right now we simply pass the error to the screen and don't let it go to the DB (most recent code #141). Given that the error was in the database that seems like a very sensible course of action to me so I'm not sure if there's any benefit in doing extra work just to see if you can send it back into the DB.

Reg’s picture

Finally had some time to do this some justice.

This is a fairly significant rework so I'll probably have to iterate a couple of times but I have D8 running now which of course makes all the difference.

This will probably speed up development so it would be nice to get it into D8 ASAP.

Reg’s picture

It says status ignore on the patch. How do you make it run or not run tests on a patch?

tim.plunkett’s picture

Status: Needs work » Needs review
Reg’s picture

Is that what causes a patch to be tested, setting the status to needs review? - Never mind, found: https://drupal.org/node/332678

Status: Needs review » Needs work

The last submitted patch, 1158322-error_backtrace-147-D8.patch, failed testing.

Reg’s picture

Status: Needs work » Needs review
FileSize
29.06 KB

The only errors that patch produced was from the simpletest. I had a look and it was something that was there and I hadn't really worked on. Looking through it I only got so far and then came to an impasse and could use some advice from people who work in that area more.

Here's what I have found and where I am up to. I've reworked the test so that all combinations of conditions can be tested. However, I do not know how to effect an error in the context of a webtest that will inject the results of that triggered error into the HTML that's tested when you use the "assert" functions.

What won't work is you can't use set_error_handler() and then trigger_error() as the results won't go into the HTML that we want it to. I tried adding a hook so that I could create an error in the hook (using page_alter) so that I could create an error condition there but couldn't get the hook to take. I don't know if that's because the test modules won't get picked up by hooks or if I need to do something to make D8 realize the hook is there.

Another tact I was looking at was that CronRunTest:testCronExceptions() seems to create an exception so I figured there must be a way to trigger an error to do what I want but I don't really know enough to figure it out. Also I've never seen this syntax (from CronRunTest):

    \Drupal::state()->set('system.cron_last', $cron_last);

Does anyone know what that prepended slash does?

For now I just bypass the tests with a return at the top of the function until someone can give me enough info to know how to go about finishing it off.

Thanks.

Crell’s picture

Copying from the related #2063303: A Drupal 8 AjaxResponse that must return a 403, returns a 403 and prints "A fatal error occurred: "

I know Symfony and Silex have very good debug output in case of uncaught exceptions. Symfony also has a nice debug toolbar. We should perhaps look into both of them and see if there's code we can borrow, or at least concepts.

mtift’s picture

@Reg: the Drupal class exists to support legacy code that cannot be dependency injected. When you use it in a class you need to use the fully-qualified namespace, which is \Drupal (rather than Drupal). When it is used in procedural code (such as a hook), it can just be called like Drupal::state.

Reg’s picture

I'm working on a solution. In the meantime does anyone know why this function:

function _drupal_error_handler_real($error_level, $message, $filename, $line, $context) {

has this passed $context variable even though it's not used in the function?

Crell’s picture

I'm not sure, but frankly all exception handling in errors.inc needs to be removed in favor of the existing handling in the kernel, which will catch it anyway.

Reg’s picture

Drupal is not an OS, what do you do call a kernel in drupal?

Reg’s picture

This has testing of all the admin options and select error types however it's just looking for errors to be thrown so unit testing rather than functional testing.

Error trapping is a bit of a special case and I don't know if it makes sense to do functional testing with error trapping. However, if someone knows a trick to make the error trapping work with functional tests, terrific. I would like to see how it's done.

Also, could someone have a look at the error output and admin. options. I would like to know what people think of it over the previous way.

Crell’s picture

The HttpKernel class, provided by Symfony in the HttpKernel component. I strongly recommend reading through that and understanding it before working on error handling, because what you're doing here appears to be Drupal 7-era architecture. You're adding a bunch of new functions and global constants to support error handling code that is *almost* never called, and when it is it probably shouldn't be. There's an entirely different error handling model provided by HttpKernel that we should be moving more toward, not continuing to develop the legacy, ugly one that still assumes PHP 4 is a viable language. :-)

Reg’s picture

Good point.

I looked at the error handling as is and right now this is the error trapping in Drupal so when an error happens this will *always* be called so this at the moment is anything but code that is almost never called. That is, no other error trap is set (unless running tests).

Symphony does have a set_error_handler() statement but at least through normal page loads without add-in modules I don't see it ever being run.

I'm happy to change this code over to Symphony integration, if in fact after study that is the way to go, however like almost everyone else I'm a volunteer so time is needed. The best steps forward I suggest are for now to use what I have written as it makes troubleshooting far better than anything previously so it should speed up development.

I'll dig into Symphony when I can next block out a chunk of time to study it and refactor this code accordingly.

Reg’s picture

A small improvement.

Status: Needs review » Needs work

The last submitted patch, 1158322-error_backtrace-161.patch, failed testing.

das-peter’s picture

Well, that's impressive, a patch without changes has failed tests :D

rooby’s picture

Probably has something to do with it being 0 bytes :)

Reg’s picture

LOL, that is bizarre. I was about to make some excuses about working until daylight and such but it's a full patch on my system so I have no idea what happened. Maybe a slight update delay on my LAN with my NFS share ...who knows.

Reg’s picture

Status: Needs work » Needs review

Status: Needs review » Needs work

The last submitted patch, 1158322-error_backtrace-161.patch, failed testing.

Reg’s picture

There's been an update to the git repo. which is why the last patch failed. I updated my local repo to build a new patch but even though I have the patch I can't test it before uploading because this update is throwing an exception (nothing to do with my code as far as I can see).

What's the coarse of action here? Just wait a while until whoever is working on that area fixes it?

The interesting thing here is it is a Symfony error so that's an opportunity for me to look at that part of the error handling although sooner than I really have time for.

 Symfony\Component\DependencyInjection\Exception\ServiceNotFoundException:  You have requested a non-existent service "csrf_token". in .../core/vendor/symfony/dependency-injection/Symfony/Component/DependencyInjection/Container.php on line 289
 Stack trace:
   1. {main}() .../index.php:0
   2. drupal_handle_request() .../index.php:13
   3. Drupal\Core\DrupalKernel->handle() .../core/includes/bootstrap.inc:1902
   4. Drupal\Core\HttpKernel->handle() .../core/lib/Drupal/Core/DrupalKernel.php:296
   5. Symfony\Component\HttpKernel\HttpKernel->handle() .../core/lib/Drupal/Core/HttpKernel.php:52
   6. Symfony\Component\HttpKernel\HttpKernel->handleRaw() .../core/vendor/symfony/http-kernel/Symfony/Component/HttpKernel/HttpKernel.php:61
   7. call_user_func_array() .../core/vendor/symfony/http-kernel/Symfony/Component/HttpKernel/HttpKernel.php:117
   8. Drupal\views\Routing\ViewPageController->handle() .../core/vendor/symfony/http-kernel/Symfony/Component/HttpKernel/HttpKernel.php:117
   9. Drupal\views\ViewExecutable->executeDisplay() .../core/modules/views/lib/Drupal/views/Routing/ViewPageController.php:82
  10. Drupal\views\Plugin\views\display\Page->execute() .../core/modules/views/lib/Drupal/views/ViewExecutable.php:1397
  11. drupal_render_page() .../core/modules/views/lib/Drupal/views/Plugin/views/display/Page.php:97
  12. block_page_build() .../core/includes/common.inc:3660
  13. block_get_blocks_by_region() .../core/modules/block/block.module:224
  14. _block_get_renderable_region() .../core/modules/block/block.module:272
  15. entity_view() .../core/modules/block/block.module:303
  16. Drupal\block\BlockRenderController->view() .../core/includes/entity.inc:632
  17. Drupal\block\BlockRenderController->viewMultiple() .../core/modules/block/lib/Drupal/block/BlockRenderController.php:29
  18. Drupal\search\Plugin\Block\SearchBlock->build() .../core/modules/block/lib/Drupal/block/BlockRenderController.php:42
  19. drupal_get_form() .../core/modules/search/lib/Drupal/search/Plugin/Block/SearchBlock.php:57
  20. drupal_build_form() .../core/includes/form.inc:175
  21. drupal_prepare_form() .../core/includes/form.inc:385
  22. drupal_get_token() .../core/includes/form.inc:1085
  23. Drupal::csrfToken() .../core/includes/common.inc:3063
  24. Symfony\Component\DependencyInjection\Container->get() .../core/lib/Drupal.php:401
das-peter’s picture

What's the coarse of action here? Just wait a while until whoever is working on that area fixes it?

Did you re-install Drupal to test it? This sounds like an artefact in the configuration files. Ensure the config files are deleted before you reinstall the system.
I use this script to automate that whole thing:
rm sites/default/files/* -Rf && drush si standard --sites-subdir=default --account-pass=admin -y && drush dis overlay -y && drush en devel simpletest devel_generate -y && drush uli -l http://d8.localhost

Reg’s picture

Interesting thanks! I will definitely do that later however I'm actually going to leave it as is for now because I don't want the Symfony error to go away.

The reason being I read a little on the error handling in Symfony and they say that the error handling there is limited and that the best error handling can be done by using a custom error handler. I figure this is an opportunity to figure out how to take it over through their configuration files and use ours so I'm looking at this is an "opportunity in disguise".

Of course part of that might mean moving the code over to classes as Symfony is very (if not entirely, I haven't looked that far yet) class oriented. If that's the case I'll probably do the transition in two steps, first take it over and then later do class conversion as my time is way over on what I allocated already but it would be very nice to get at least an initial Symfony integration going with the error handling.

sun’s picture

Issue summary: View changes
Status: Needs work » Fixed

I'm not sure what happened here. The latest patches contain completely different changes. The original change was still not completed for D8 (see #109 ... #139)

In order to get this back under control, I've created #2188523: ExceptionController does not respect configured system.logging:error_level (verbose backtrace) for the necessary follow-up fixes in D8 now.

We could consider to backport the original change here as a minor feature addition to D7, but doing so will require a very careful and cautious backport and review, since multiple patches were committed (to fix regressions of the original patch). For now, I'm tentatively marking this fixed.

mikeytown2’s picture

I'm still using #138 in D7 so getting this backported to D7 would be ideal.

Status: Fixed » Closed (fixed)

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

mikeytown2’s picture

Version: 8.x-dev » 7.x-dev
Status: Closed (fixed) » Active
Issue tags: +Needs backport to 7.x

Reopening this for 7.x. Close it if this is the wrong place and I will create a new issue.

Anybody’s picture

Issue tags: -

It's a good idea to backport this to Drupal 7 because especially Exceptions are extremely hard to backtrace in Drupal 7. An error page appears without any deeper information (just the Exception message) and also the Watchdog entries show no backtrace!

geek-merlin’s picture

+1 for this.
We might look into commerce_devel that already does exactly that.

david_garcia’s picture

I just installed D8 and to my surprise the "revamped" error logging with detail is just useless. I am using patch from #138 in my sites for D7 and the output is much more useful.

I mean.... this is useful stuff (D7, patch from #138, includes line numbers, files, etc...):

PDOException:
SQLSTATE[22018]: [Microsoft][SQL Server Native Client 11.0][SQL Server]Conversion failed when converting the nvarchar value 'en' to data type int.: SELECT base.[uid] AS [uid], base.[name] AS [name], base.[pass] AS [pass], base.[mail] AS [mail], base.[theme] AS [theme], base.[signature] AS [signature], base.[signature_format] AS [signature_format], base.[created] AS [created], base.[access] AS [access], base.[login] AS [login], base.[status] AS [status], base.[timezone] AS [timezone], base.[language] AS [language], base.[picture] AS [picture], base.[init] AS [init], base.[data] AS [data]
FROM
{users} base
WHERE ( ([base].[uid] IN (:db_condition_placeholder_0)) ); Array
(
[:db_condition_placeholder_0] => en
)

LINE: 100
FUNCTION: EntityCacheControllerHelper::entityCacheLoad()
FILE: D:\_Webs\mysite.com\sites\all\modules\entitycache\entitycache.module

STACKTRACE:

INDEX FUNCTION CALLED CALLER LINE CALLER FILE
12 drupal_bootstrap 20 D:\_Webs\mysite.com\index.php
11 _drupal_bootstrap_full 2274 D:\_Webs\mysite.com\includes\bootstrap.inc
10 menu_set_custom_theme 5156 D:\_Webs\mysite.com\includes\common.inc
9 menu_get_custom_theme 1807 D:\_Webs\mysite.com\includes\menu.inc
8 menu_get_item 1792 D:\_Webs\mysite.com\includes\menu.inc
7 _menu_translate 485 D:\_Webs\mysite.com\includes\menu.inc
6 _menu_load_objects 778 D:\_Webs\mysite.com\includes\menu.inc
5 user_load 606 D:\_Webs\mysite.com\includes\menu.inc
4 user_load_multiple 366 D:\_Webs\mysite.com\modules\user\user.module
3 entity_load 291 D:\_Webs\mysite.com\modules\user\user.module
2 load 7804 D:\_Webs\mysite.com\includes\common.inc
1 entityCacheLoad 229 D:\_Webs\mysite.com\sites\all\modules\entitycache\entitycache.module
0 execute 100 D:\_Webs\mysite.com\sites\all\modules\entitycache\entitycache.module

BACKTRACE:
SelectQuery->execute() EntityCacheControllerHelper::entityCacheLoad(Object, Array, Array) EntityCacheUserController->load(Array, Array) entity_load('user', Array, Array, ) user_load_multiple(Array, Array, ) user_load('en') _menu_load_objects(Array, Array) _menu_translate(Array, Array) menu_get_item() menu_get_custom_theme(1) menu_set_custom_theme() _drupal_bootstrap_full() drupal_bootstrap(7)

And this is useless stuff (D8):

Drupal\Core\Database\DatabaseExceptionWrapper: SQLSTATE[42000]: [Microsoft][SQL Server Native Client 11.0][SQL Server]Incorrect syntax near '='.: SELECT revision.[vid] AS [vid], revision.[langcode] AS [langcode], revision.[revision_timestamp] AS [revision_timestamp], revision.[revision_uid] AS [revision_uid], revision.[revision_log] AS [revision_log], base.[nid] AS [nid], base.[type] AS [type], base.[uuid] AS [uuid], base.vid = revision.vid AS isDefaultRevision FROM {node} base INNER JOIN {node_revision} revision ON revision.vid = base.vid WHERE ( ([base].[nid] IN (:db_condition_placeholder_0)) ); Array ( [:db_condition_placeholder_0] => 1 ) in Drupal\Core\Entity\Sql\SqlContentEntityStorage->getFromStorage() (line 431 of core\lib\Drupal\Core\Entity\Sql\SqlContentEntityStorage.php).
PDOStatement->execute([Array])
Drupal\Core\Database\Statement->execute([Array])
Drupal\Core\Database\Driver\sqlsrv\Statement->execute([Array], [Array])
Drupal\Core\Database\Connection->query(SELECT revision.[vid] AS [vid], revision.[langcode] AS [langcode], revision.[revision_timestamp] AS [revision_timestamp], revision.[revision_uid] AS [revision_uid], revision.[revision_log] AS [revision_log], base.[nid] AS [nid], base.[type] AS [type], base.[uuid] AS [uuid], base.vid = revision.vid AS isDefaultRevision
FROM
{node} base
INNER JOIN {node_revision} revision ON revision.vid = base.vid
WHERE ( ([base].[nid] IN (:db_condition_placeholder_0)) ), [Array], [Array])
Drupal\Core\Database\Query\Select->execute()
Drupal\Core\Entity\Sql\SqlContentEntityStorage->getFromStorage([Array])
Drupal\Core\Entity\Sql\SqlContentEntityStorage->doLoadMultiple([Array])
Drupal\Core\Entity\EntityStorageBase->loadMultiple([Array])
Drupal\Core\Entity\EntityStorageBase->load(1)
Drupal\Core\ParamConverter\EntityConverter->convert(1, [Array], node, [Array])
Drupal\Core\ParamConverter\ParamConverterManager->convert([Array])
Drupal\Core\Routing\Enhancer\ParamConversionEnhancer->enhance([Array], Symfony\Component\HttpFoundation\Request)
Symfony\Cmf\Component\Routing\DynamicRouter->applyRouteEnhancers([Array], Symfony\Component\HttpFoundation\Request)
Symfony\Cmf\Component\Routing\DynamicRouter->matchRequest(Symfony\Component\HttpFoundation\Request)
Symfony\Cmf\Component\Routing\ChainRouter->doMatch(/node/1, Symfony\Component\HttpFoundation\Request)
Symfony\Cmf\Component\Routing\ChainRouter->matchRequest(Symfony\Component\HttpFoundation\Request)
Drupal\Core\Routing\AccessAwareRouter->matchRequest(Symfony\Component\HttpFoundation\Request)
Symfony\Component\HttpKernel\EventListener\RouterListener->onKernelRequest(Symfony\Component\HttpKernel\Event\GetResponseEvent, kernel.request, Symfony\Component\EventDispatcher\ContainerAwareEventDispatcher)
call_user_func([Array], Symfony\Component\HttpKernel\Event\GetResponseEvent, kernel.request, Symfony\Component\EventDispatcher\ContainerAwareEventDispatcher)
Symfony\Component\EventDispatcher\EventDispatcher->doDispatch([Array], kernel.request, Symfony\Component\HttpKernel\Event\GetResponseEvent)
Symfony\Component\EventDispatcher\EventDispatcher->dispatch(kernel.request, Symfony\Component\HttpKernel\Event\GetResponseEvent)
Symfony\Component\EventDispatcher\ContainerAwareEventDispatcher->dispatch(kernel.request, Symfony\Component\HttpKernel\Event\GetResponseEvent)
Symfony\Component\HttpKernel\HttpKernel->handleRaw(Symfony\Component\HttpFoundation\Request, 1)
Symfony\Component\HttpKernel\HttpKernel->handle(Symfony\Component\HttpFoundation\Request, 1, TRUE)
Drupal\Core\StackMiddleware\KernelPreHandle->handle(Symfony\Component\HttpFoundation\Request, 1, TRUE)
Drupal\Core\StackMiddleware\PageCache->handle(Symfony\Component\HttpFoundation\Request, 1, TRUE)
Drupal\Core\StackMiddleware\ReverseProxyMiddleware->handle(Symfony\Component\HttpFoundation\Request, 1, TRUE)
Stack\StackedHttpKernel->handle(Symfony\Component\HttpFoundation\Request, 1, TRUE)
Drupal\Core\DrupalKernel->handle(Symfony\Component\HttpFoundation\Request)

Am I missing something?

1) Why is stacktrace and backtrace not logged into watchdog?
2) Where is the stacktrace? (I can backtrace wich is not the same thing).

Maybe there is something not working in my D8 installation, or is that the expected output of the new error logging system.

I can tell you, the output and functionality provided by patch #138 is a huge timesaver, 90% of small bugs can be solved straight, even without replication, by just taking a look at a complete and detailed error dump.

Reg’s picture

For D7 I have a backport for that however to keep it separate from D8 I created a separate issue here https://www.drupal.org/node/1937832 .

It's a little dated and I can't remember if I fixed the seemingly random SQL error at the time of the latest patch there. However, I have it fixed and I'll upload a new patch to issue 1937832 within a couple of days for anyone who wants a D7 backtrace error patch that works on the latest 7.x Drupal.

For D8 I got stuck for time because Symphony is a whole thing in itself and I haven't been able to find the time to dedicate to learning it and then tapping into it. However, if someone wants to post a code snippet that shows how to take over it's error handling properly within the Drupal context then I'll be happy to take it from there and create a patch for D8 as well as I have everything except the Symphony part done.

mikeytown2’s picture

Status: Active » Needs review
FileSize
13.72 KB

Pulling in latest D7 patch from #1937832-1: Add backtrace to all errors for D7. It's 2 days newer than #138.

Fixed a php notice I got with that patch as well (line 222 inside of errors.inc)
Changed this
if ($st_opts[ERROR_REPORTING_DISPLAY_LOGS] || $bt_opts[ERROR_REPORTING_DISPLAY_LOGS]) {
to this

  if (!empty($st_opts[ERROR_REPORTING_DISPLAY_LOGS]) || !empty($bt_opts[ERROR_REPORTING_DISPLAY_LOGS])) {
david_garcia’s picture

Status: Needs review » Needs work

A comment from: #1937832: Add backtrace to all errors for D7

@reg said: PHP won't let you write PDO exceptions to the DB, and rightly so.

I have been using that patch (modified to allow PDO dumping on database) on all our production sites and writting PDO exceptions to database does work (why sould it not?). I mean, I just cannot understand what "PHP won't let you write PDO exceptions to the DB". Exceptions are not written to the database themselves....

This needs some clarification....

mikeytown2’s picture

I think the idea is if PDO is throwing exceptions due to the database being gone then trying to write more data to it is not a good idea.

The last submitted patch, 179: drupal-1158322-179-backtrace-errors-D7.patch, failed testing.

david_garcia’s picture

PDO exception does not necesarily mean that database is gone.

But it is worth considering that situation, and prevent infinite loops.

I cannot think of a consistent way of analyzing an exception and determining if the database is down based on it, but asuming that PDO Exception means database is down is also a mistake.

mikeytown2’s picture

Pinging the database would be a good way to detect. I know there is mysqli_ping(), trying to find an equivalent for PDO like this http://terenceyim.wordpress.com/2009/01/09/adding-ping-function-to-pdo/

david_garcia’s picture

What about something like this:

function array_get_PDOExceptionCode(array $log) {
  if $log has a PDO Exception return Code, otherwise return FALSE;
}

if ($current_code = array_get_PDOExceptionCode($log_entry)) {
    try {
       Get connection and insert into database.
    } 
    catch(Error $e) {
      if($code = array_get_PDOExceptionCode($e)) {
       // Same PDO Code twice, database is not working properly.
        _drupal_log_error($log_entry, TRUE);
      } 
      else {
        // This is a different exception, rethrow it.
        throw;
      }
    }
}

This prevents database down infinite loop, without adding overhead. If the same PDO Code is thrown twice, we can assume it is not worth counting on database logging.

Just an idea....

mikeytown2’s picture

Status: Needs work » Needs review
FileSize
13.97 KB

I modified the array_has_PDO_connection_exception() function by renaming it and seeing if the PDOException message as the text gone away in it.

Status: Needs review » Needs work

The last submitted patch, 186: drupal-1158322-186-backtrace-errors-D7.patch, failed testing.

mikeytown2’s picture

Status: Needs work » Needs review
FileSize
13.98 KB

Fixed the function name in dblog.module

david_garcia’s picture

I think it is not reliable to count on a "gone away" string for database down detection, this can be different on different database engines. Also, database down can manifest itself as different messages on different situations (ex. when database is shutting down it will send different message compared to when it is not available, but in both cases it is not available).

I'd rather control exception code repetition, so if when logging to database we get the same PDO error that we were going to log, that means a more than potential inifinite loop.

Status: Needs review » Needs work

The last submitted patch, 188: drupal-1158322-188-backtrace-errors-D7.patch, failed testing.

mikeytown2’s picture

Status: Needs work » Needs review
FileSize
14.15 KB

Trying to get the current way working; once this passes tests I'll look into a better way of preventing errors that cause errors due to database issues.

mikeytown2’s picture

Fixed a couple of notices I was getting

Crell’s picture

Status: Needs review » Active
Issue tags: +Needs issue summary update
  1. +++ b/includes/errors.inc
    @@ -199,7 +210,30 @@ function _drupal_log_error($error, $fatal = FALSE) {
    +  $st_opts=variable_get('error_stacktrace_display', array());
    

    Needs spaces around the =, here and in a few other places. Also, $st_opts is a meaningless variable name.

  2. +++ b/includes/errors.inc
    @@ -199,7 +210,30 @@ function _drupal_log_error($error, $fatal = FALSE) {
    +    watchdog('php', $message_line, $error, $error['severity_level']);
    

    The watchdog() function is deprecated, I believe. Don't keep usages of it around.

But that aside, I will repeat my statement from over a year ago: 98% of all exceptions will get caught by our kernel exception listeners, NOT by the legacy procedural code floating about in errors.inc and friends. Those files need to get refactored out and removed, not added to. If you want to add optional backtrace output, do that in the new exception handling framework in an OOP fashion. Trying to pile more functions into the nearly-unused legacy system is going in the entirely wrong direction.

mikeytown2’s picture

Thanks for pointing out the coder fixes :)

In D7 the watchdog() function seems to be alive and well according to the docs. The comment from #156 is in the context of D8 from my understanding; #139 up to #174 is talking about D8. I could be mistaken but I do not believe D7 has kernel exception listeners. If this patch doesn't belong in this issue I will re-open this issue then #1937832: Add backtrace to all errors for D7

mikeytown2’s picture

Status: Active » Needs review
Crell’s picture

... I completely missed that this issue had been refiled for D7. My brain was in D8 space. Sorry.

Given the length I would prefer to see a new issue for D7 to avoid such confusion.

Anybody’s picture

#194 works great for me. Can we get some more responses? :)
It would be great and very very helpful to see this in core soon, I think.

Thanks a lot!

cesarmiquel’s picture

Great work guys! I tested #194 on an exception I have but the formatting code seems to have issues. This is how it looks:

I added a print_r() to the format_stacktrace() function in includes/errors.inc and noticed that the $backtrace array seems to not have all keys. The problem seems to be this code:

    foreach (array('function'=>0, 'line'=>0, 'file'=>0) as $k2 => $v2) {
      if (isset($v[$k2])) {
        $data = str_replace(DRUPAL_ROOT . '/', '', $v[$k2]);
        $data = htmlentities($data);
        $cs .= "<td>$data</td>";
      }   
    }   
    $cs .= '</tr>';

which doesn't add a blank <td></td> when the key is not set. I suggest replacing with:

    $cs .= "<tr $row_class><td>$k</td>";
    foreach (array('function'=>0, 'line'=>0, 'file'=>0) as $k2 => $v2) {
      $data = '';
      if (isset($v[$k2])) {
        $data = str_replace(DRUPAL_ROOT . '/', '', $v[$k2]);
        $data = htmlentities($data);
      }
      $cs .= "<td>$data</td>";
    }   
    $cs .= '</tr>';

With this code the following stacktrace is displayed:

Unfortunately I can't provide a patch because I don't have the latest code. Hope this helps though.

mikeytown2’s picture

New patch based off of #194 with the fix from #198 included. Also did some UTF-8 encoding tricks with htmlentities()

cgmonroe’s picture

Status: Needs review » Needs work

I LOVE this series of patches.. Unfortunately, I keep getting a PhP out of memory with both #199 and #194 with a nasty EntityMalformedException problem, even after increasing the limit up to 2000M (from 512M).

I didn't have time to try all the patches, so I stopped after these two and applied #138 which I never seem to have problems with. This generated the stacktraces I needed.

Sorry, this still needs some work.

david_garcia’s picture

Just for the record, this needs even more work. I'm getting this sometimes.

Fatal error: Call to undefined function array_has_PDOException() \modules\dblog\dblog.module on line 155

This basically means that dblog has been called before errors.inc has been included, we should review the bootstraping process and see under which conditions can this happen.

The message that is trying to get looged is by the system_test module, with the message 'hook_boot'.

/**
* Implements hook_boot().
*/
function system_test_boot() {
watchdog('system_test', 'hook_boot');
}

Kebz’s picture

Where does "backtrace" originate? Is it in core or a specific module turns it on?

I'm just curious because when notices, errors, etc. pops up on my screen, it usually just shows the error and nothing more. For the last few days, it is now showing up with "Backtrace" right below the notices and with more info that I'm use to seeing.

For example (image attached as well)

Notice: Undefined index: version_major in update_calculate_project_update_status() (line 629 of .../modules/update/update.compare.inc).

Backtrace:
update_calculate_project_update_status('userpoints', Array, Array) update.compare.inc:347
update_calculate_project_data(Array) update.install:33
update_requirements('runtime') update.module:136
update_init()
call_user_func_array('update_init', Array) module.inc:895
module_invoke_all('init') common.inc:5193
_drupal_bootstrap_full() bootstrap.inc:2278
drupal_bootstrap(7) index.php:20

Also, just wondering if this link https://api.drupal.org/api/devel/devel.module/function/ddebug_backtrace/7 is the same as the topic of discussion.

Kebz’s picture

Kebz’s picture

Update: I just found my answer... lol
I downloaded the module "Commerce Devel" and didn't realize it is the source of the "Backtrace" feature that I was seeing on notices, warnings, errors. And due to the information that "Backtrace" provides, it helped resolved a problem (https://www.drupal.org/node/2142133)

Backtrace should definitely be part of core ... a useful tool for developers at any level.

Commerce Devel https://www.drupal.org/project/commerce_devel
A great introduction can be found here https://fr.commerceguys.com/node/69

mikeytown2’s picture

@cgmonroe
In terms of memory usage I think if I where to use some of the new parameters added to debug_backtrace() in 5.3.6 & 5.4.0 that should help in those situation. Outside of this there is not much that can be done for older versions of PHP; debug_backtrace() can eat up a lot of ram.

david_garcia’s picture

@mikeytown2 It is too weird that he's getting out-of-memory even with 2000MB, maybe he's stuck in an infinite loop when handling the error (quite possible with the current implementation).

izaaksom’s picture

Just a comment. When using AJAX and logging shown on pages; I got some warnings printed in the request body, and because of that some modals windows broke. So I had to turn off error logging on pages to access that configuration forms.

¿Just wondering if something it's implemented in topic?

Keep up with the good work!

rooby’s picture

In relation to #205 I think that returning just function calls would be good enough in a lot of cases and reduces risk relating to system configuration of memory limits and such.

Maybe it should be disabled for old versions of PHP or else there could be a setting page where it could be enabled/disabled with a warning about enabling it for old PHP versions.

Such a settings page could also potentially contain an option for newer PHP versions to switch between function calls and full data.

Alternatively those settings could just be variables you set in the settings.php file.
That's probably a better solution that a UI in this case.

Reg’s picture

@Crell #196: Agreed that for D7 there should be a separate issue and in fact I started on at #178 but people kept on-going with this thread. At this point, unless there is someone who can control how this thread behaves it might be more expedient to start a similar thread for D8 and leave this one for D7 since there is so much history here around D7.

Having said that, I noticed there have been a few patches against my original with some updates. Unfortunately my original at the time was a compromise between a previous implementation and something I used myself over the years. Hence the separate "backtrace" and "stacktrace" options.

Since I am revisiting the code I decided to just finish it up with the my own implementation but incorporating the features from the previous code I never bothered with. I think everyone will find this much nicer all around since it's not a "half way" measure anymore.

The basic new features are for both scalar and non-scalar variables which are handled separately which are:

  • Show/hide - Turn off non-scalar can help avoid out of memory issues
  • Start showing from a call depth, default 1 - the call on which the error occurred
  • Stop showing after n calls deep, default 0 meaning just show on one call - the call the error occurred
  • Limit to n characters for each variable - default 1024 (adjust to avoid out of memory issues)

If either scalar or non-scalar variables are selected then an additional column is added for the variable output.

The issue with "td" not being created for the HTML table at certain times has been fixed.

This patch is against D7.35 which is a little old and if it causes issues with passing tests then I'll create a clean install of the latest D7 and redo the patch.

Reg’s picture

Status: Needs work » Needs review

Status: Needs review » Needs work

The last submitted patch, 209: add_backtrace_to_all_errors-1158322-209-D7.patch, failed testing.

cesarmiquel’s picture

I'm at Drupalcon Barcelona with time on my hands to help and wanting to see this committed to core. Ping me so I can help with this issue.

Reg’s picture

Status: Needs work » Needs review
FileSize
20.4 KB
1.44 KB

Trying again with a minor bug fix.

Status: Needs review » Needs work

The last submitted patch, 213: add_backtrace_to_all_errors-1158322-213-D7.patch, failed testing.

Reg’s picture

Sorry if I end up trying a few times before I get it right. The tests are only approximate on my local machine because I run PHP 5.6 and the drupal.org testbot runs in PHP 5.4 so I'm figuring out as much as I can locally but there's still some trial and error here that I can't get around.

On this one I simply moved a function that sometimes was being "undefined". For anyone who likes a mystery just by using "function_exists" just above where the problem was happening would cause the function to exist and the error would be avoided. E.g., this would cause a function undefined error (the function "array_has_PDOException" was the culprit not being defined):

  if (!array_has_PDOException($log_entry)) { // If it was a DB error don't write to the DB.
    do stuff...
  } else {
    _drupal_log_error($log_entry, TRUE);
  }

...but this would cause the function to be found and work so neither an error would happen nor would I get a backtrace!:

  static $traced = FALSE;
  if (!function_exists('array_has_PDOException') && !$traced) {
    $traced = TRUE;
    $fh = fopen('trace.txt', 'w');
    fwrite($fh, var_export(debug_backtrace(DEBUG_BACKTRACE_IGNORE_ARGS), true));
    fclose($fh);
  }

  if (!array_has_PDOException($log_entry)) { // If it was a DB error don't write to the DB.
    do stuff...
  } else {
    _drupal_log_error($log_entry, TRUE);
  }
Reg’s picture

Status: Needs work » Needs review

Status: Needs review » Needs work

The last submitted patch, 215: add_backtrace_to_all_errors-1158322-214-D7.patch, failed testing.

Reg’s picture

Status: Needs work » Needs review
FileSize
21.05 KB
1.92 KB

From about 1200 problems to 6 last time so getting close.

Status: Needs review » Needs work

The last submitted patch, 218: add_backtrace_to_all_errors-1158322-216-D7.patch, failed testing.

Reg’s picture

Status: Needs work » Needs review
FileSize
22.57 KB
1.92 KB

This should finally do it.

Reg’s picture

Same as before with debugging code removed.

Reg’s picture

FileSize
731 bytes

The interdiff.txt to match previous patch - ignore the one with it.

Reg’s picture

This is a discovered issue that resulted from these enhancements :
https://www.drupal.org/node/2606742

Reg’s picture

It would be nice to get this in the core but with D8 about to be launched I'm wondering if it's possible at this stage to get anything new in the D7 core. It's certainly long over due and sorely needed.

vrwired’s picture

I tested this on a vanilla copy. Tested it out fine there using intentional errors.

Then patched another site which already had a warning I'd been meaning to debug today - Undefined index: page_manager in workbench_moderation_form_alter().

On both sites, I was able to get backtrace info on screen and in logs.

This will be a very useful patch to d7 core indeed.

David_Rothstein’s picture

This is a bit of a confusing issue since it had a lot of commits for Drupal 8 already, but still not clear if it's fully fixed for Drupal 8 yet...

I think at this point it makes sense to leave this issue on Drupal 7 for the backport - any remaining problems with Drupal 8 can be filed as separate bug reports. However, we do have to make sure that what we're doing here for Drupal 7 is actually a backport of what already went into Drupal 8 (from a functional perspective, that is - even if the code is different). If there are new features or capabilities being proposed for Drupal 7, they need to go into Drupal 8 first.

I am not sure (since I'm not too familiar with this issue), but it looks like Drupal 8 only had one constant that was added here (ERROR_REPORTING_DISPLAY_VERBOSE, with a corresponding option in the UI) but the latest Drupal 7 patch in #221 has way more constants and way more options. Why are all those extra options being added (and why only for Drupal 7 and not Drupal 8)? Do we really need anything more than the single option that was added to Drupal 8?

(OK, looking a little closer I do kind of see the point of having it be a separate option in the UI, e.g. a checkbox that enables backtraces regardless of whether error messages are displayed on the screen or not - rather than the extra radio button that Drupal 8 has which only ever allows displaying the backtrace on the screen. Because there'd definitely be value in showing the backtrace in the logs for production sites that don't want error messages displayed to the screen at all. But (a) that kind of change would need to go into Drupal 8 first, and (b) it still seems like it would be a lot simpler and require a lot fewer options than are in the latest Drupal 7 patch here.)

In any case, thanks for working on this. It looks like a very useful feature!

Reg’s picture

@David_Rothstein:
I'll work on getting these features in D8 so it can be backported and try to make that my weekend project this week. Is there a different issue for D8 with the changes you mentioned or is it all here on this issue?

Part of the reason for the extra features which I agree might seem like a overkill compared to what it was is potential "out of memory" errors and and giving a way to just reduce what you see to what you need so you don't suffer from information overload. You will see a note next to each option on the page that's there to protect you from out of memory errors.

The additional options that are not to help with out of memory are there to fine tune what you see. You need to be able to tweak detail so you get that balance of detail you need without going overboard and there really isn't a "one size fits all" solution so you need to give people the ability to tweak for their particular troubleshooting needs at the time.

Could I entice you to apply this patch on a project of yours and play with it a little? I think you will really like what you see and I would certainly appreciate the feedback (I've been tweaking the parameters over years for myself so finally being able to sharing them is really nice to be able to do).

David_Rothstein’s picture

It looks like #77, #100, and #122 above were the patches committed to Drupal 8 (not sure if I missed any). There may also have been changes in other issues of course. It's probably best to use the above commits as a guide and then just look in the current Drupal 8 codebase and see exactly what the corresponding code looks like now.

I did a brief test of the Drupal 7 patch now. It looked pretty neat. But doesn't the Drupal 8 patch handle those issues without any configuration, just by trying to make some smart choices for exactly what amount of information to show in the backtrace? (See Error::formatBacktrace() for the current Drupal 8 formatting code.)

Reg’s picture

Thanks for checking it out and so quickly!

...But doesn't the Drupal 8 patch handle those issues without any configuration...

I honestly don't know as I have only checked D8 out now and then and never had a chance to delve into it but I guess I'll be doing that this weekend (or sooner if I can) so I'll get back to as soon I get to delve into the details.

pounard’s picture

There's something bothering me with the actual patch, maybe it's a detail:

 /**
+ * We don't want to call watchdog if anywhere in the array there is a
+ * PDOException since PHP won't let us log a PDOException back to the DB. The
+ * function will check for the exception recursively through the array and
+ * return TRUE if it finds it.
+ *
+ * @param type $array
+ *   The array to check, will likely be $error from calling function
+ *
+ * @return boolean
+ *   TRUE if found.
+ */
+function array_has_PDOException($array) {
+  if (array_key_exists('%type', $array) && stripos($array['%type'], 'PDOException') !== FALSE) {
+    return TRUE;
+  }
+  foreach ($array as $value) {
+    if (is_array($value) && array_has_PDOException($value)) {
+      return TRUE;
+    }
+  }
+  return FALSE;
+}
+

Are you really storing exceptions into the database ? It's not supposed to get in there, exceptions are tight bound to the current run stack, only reporting should be stored ?

Anyway, seeing this code (in latest D7 patch) :
watchdog('php', $message_line, $error, $error['severity_level']);

It violates the watchdog() function signature, I am wrong ?

Reg’s picture

The patch doesn't try to store anything into the DB that Drupal doesn't already try to store into the DB. All as the patch does is give backtrace detail in a nice format when you choose to turn backtracing on. Of course that doesn't mean that what you are saying is wrong but we should probably raise a separate issue for that.

That bit of code is there because I came across cases where Drupal was trying to write PDOExceptions to the DB. See the discovered issue I found while doing this: https://www.drupal.org/node/2606742 as a case in point.

Reg’s picture

Status: Needs review » Needs work

The last submitted patch, 232: add_backtrace_to_all_errors-1158322-232-D7.patch, failed testing.

klausi’s picture

Hm, this patch is a bit too large for my taste so I developed a smaller one with print_r($backtrace) for watchdog() in #2654406: Log backtrace of PHP errors and exceptions. It only logs a lightweight backtrace and does not show it because during development I use the devel module anyway.

  • catch committed fd352bf on 8.3.x
    Issue #1158322 by sun, jhedstrom, et al : Added backtrace to all errors.
    
  • webchick committed 37ea2e0 on 8.3.x
    Issue #1158322 follow-up by olli: Added missing backtrace to exception...
  • webchick committed 99fa84c on 8.3.x
    Issue #1158322 follow-up by chx: Fixed htmlspecialchars() expects...

  • catch committed fd352bf on 8.3.x
    Issue #1158322 by sun, jhedstrom, et al : Added backtrace to all errors.
    
  • webchick committed 37ea2e0 on 8.3.x
    Issue #1158322 follow-up by olli: Added missing backtrace to exception...
  • webchick committed 99fa84c on 8.3.x
    Issue #1158322 follow-up by chx: Fixed htmlspecialchars() expects...
geek-merlin’s picture

Great work to get this into core!
In the meantime the abandoned code from commerce_devel lives here:
https://www.drupal.org/project/pbt

Just for inspiration.

Anybody’s picture

@axel.rutz thank you very much for this great module. Hopefully we'll see this in D7 core soon. Thank you all!

Reg’s picture

I'm glad people are still supporting this! I kind of dropped the patch I was creating here because I didn't think anyone was interested. I'll update it so it passes the bot again in the next couple of days.

Chris Charlton’s picture

I see commits for 8.x, any additional patches needed for 7.x?

Reg’s picture

All my patches are for 7.x and you will see that this issue is set for version 7. I'm not sure why the version 8 commit(s) are here.

Maybe just someone didn't look carefully at the version of the issue before adding a commit here?

Perhaps a new issue linked to here for version 8 would be appropriate and then a back ported version from 8 can be done here if it's needed to be done that way to keep with policy?

jimmyko’s picture

It is so weird that it is committed to Drupal 8 on a issue tagged with Drupal 7. And the committers just ignoring the questions raised here and even not leaving any message here for what they have done and reasons...

Alan D.’s picture

#235 & #336 are just auto-generated comments the old commits going to the new branch I believe from way back in 2012 :)

http://cgit.drupalcode.org/drupal/commit/?id=fd352bf

jimmyko’s picture

@AlanD Thanks for the explanation. So this feature is still absent from both D7 and D8...

sinasalek’s picture

There are several issues similar to this. this one is for D8 #2638140: Error logging should log a backtrace consistently.
And there is another one for D7 #2777955: [D7] Enable error logging to log a backtrace string which is simpler
I did a bit of comparison and the patch here is much more customizable

  • catch committed fd352bf on 8.4.x
    Issue #1158322 by sun, jhedstrom, et al : Added backtrace to all errors.
    
  • webchick committed 37ea2e0 on 8.4.x
    Issue #1158322 follow-up by olli: Added missing backtrace to exception...
  • webchick committed 99fa84c on 8.4.x
    Issue #1158322 follow-up by chx: Fixed htmlspecialchars() expects...

  • catch committed fd352bf on 8.4.x
    Issue #1158322 by sun, jhedstrom, et al : Added backtrace to all errors.
    
  • webchick committed 37ea2e0 on 8.4.x
    Issue #1158322 follow-up by olli: Added missing backtrace to exception...
  • webchick committed 99fa84c on 8.4.x
    Issue #1158322 follow-up by chx: Fixed htmlspecialchars() expects...
deanflory’s picture

add_backtrace_to_all_errors-1158322-221-D7.patch applied to D7.54:

patching file includes/errors.inc
Hunk #6 FAILED at 210.

patching file modules/dblog/dblog.module
Hunk #1 FAILED at 144.

geek-merlin’s picture

Chris Charlton’s picture

Why did the D7 patch reviews get stalled?

Reg’s picture

It's been quite a long time since this patch was updated so I've updated it to get it compatible with the latest D7. I'll do an interdiff after it passes and I'm sure there's all sorts of new checks since last time I did this so that I'll have to probably try a few times before it passes.

Reg’s picture

Status: Needs work » Needs review

The last submitted patch, 114: 1158322_114-do-not-test.patch, failed testing. View results

Status: Needs review » Needs work

The last submitted patch, 251: add_backtrace_to_all_errors-1158322-251-D7.patch, failed testing. View results
- codesniffer_fixes.patch Interdiff of automated coding standards fixes only.

Reg’s picture

Status: Needs work » Needs review
FileSize
24.09 KB
Reg’s picture

Issue summary: View changes
Reg’s picture

Issue summary: View changes
Reg’s picture

Issue summary: View changes
Reg’s picture

Issue tags: -Needs issue summary update
FileSize
14.51 KB

That passed so I added the interdiff. The problem was actually a core fault and I created an issue for it here: https://www.drupal.org/project/drupal/issues/2934298.

There was also a tag suggesting the issue summary needed to be updated so I have updated it and removed the tag.

Reg’s picture

Issue summary: View changes
Reg’s picture

Issue summary: View changes
Reg’s picture

Issue summary: View changes
Reg’s picture

Issue summary: View changes
Alan D.’s picture

Status: Needs review » Needs work

Shouldn't all the string trims simply use drupal_substr() here? The mb_* functions are not a requirement

function drupal_substr($text, $start, $length = NULL) {
  // Determined from _unicode_check()
  global $multibyte; 
  if ($multibyte == UNICODE_MULTIBYTE) {
    return $length === NULL ? mb_substr($text, $start) : mb_substr($text, $start, $length);
  }
  else {
...

  }
}
Reg’s picture

@alan-d I would love it to be that easy but I tested many combinations, here is the test code (please forgive how long "$link = ..." is here, the editor did this):

$link = urldecode('/content/xo%E9%85%B1%E5%87%89%E6%8B%8C%E7%B4%A0%E9%B8%A1%E7%85%A7%E7%83%A7%E9%B8%A1%E9%BB%84%E7%8E%AB%E7%91%B0-%E7%A7%91%E5%B7%9E%E7%9A%84%E5%B0%8F%E4%B9%9D%E5%AF%A8%E6%B2%9F%E7%BB%9D%E7%BE%8E%E9%AB%98%E5%B1%B1%E6%B9%96%E6%B3%8A%E9%85%B1%E5%87%89%E6%8B%8C%E7%B4%A0%E9%B8%A1%E7%85%A7%E7%83%A7%E9%B8%A1%E9%BB%84%E7%8E%AB%E7%91%B0-%E7%A7%91%E5%B7%9E%E7%9A%84%E5%B0%8F%E4%B9%9D%E5%AF%A8%E6%B2%9F%E7%BB%9D%E7%BE%8E%E9%AB%98%E5%B1%B1%E6%B9%96%E6%B3%8A%E9%85%B1%E5%87%89%E6%8B%8C%E7%B4%A0%E9%B8%A1%E7%85%A7%E7%83%A7%E9%B8%A1%E9%BB%84%E7%8E%AB%E7%91%B0-%E7%A7%91%E5%B7%9E%E7%9A%84%E5%B0%8F%E4%B9%9D%E5%AF%A8%E6%B2%9F%E7%BB%9D%E7%BE%8E%E9%AB%98%E5%B1%B1%E6%B9%96%E6%B3%8A%E9%85%B1%E5%87%89%E6%8B%8C%E7%B4%A0%E9%B8%A1%E7%85%A7%E7%83%A7%E9%B8%A1%E9%BB%84%E7%8E%AB%E7%91%B0-%E7%A7%91%E5%B7%9E%E7%9A%84%E5%B0%8F%E4%B9%9D%E5%AF%A8%E6%B2%9F%E7%BB%9D%E7%BE%8E%E9%AB%98%E5%B1%B1%E6%B9%96%E6%B3%8A%E9%85%B1%E5%87%89%E6%8B%8C%E7%B4%A0%E9%B8%A1%E7%85%A7%E7%83%A7%E9%B8%A1%E9%BB%84%E7%8E%AB%E7%91%B0-%E7%A7%91%E5%B7%9E%E7%9A%84%E5%B0%8F%E4%B9%9D%E5%AF%A8%E6%B2%9F%E7%BB%9D%E7%BE%8E%E9%AB%98%E5%B1%B1%E6%B9%96%E6%B3%8A%E9%85%B1%E5%87%89%E6%8B%8C%E7%B4%A0%E9%B8%A1%E7%85%A7%E7%83%A7%E9%B8%A1%E9%BB%84%E7%8E%AB%E7%91%B0-%E7%A7%91%E5%B7%9E%E7%9A%84%E5%B0%8F%E4%B9%9D%E5%AF%A8%E6%B2%9F%E7%BB%9D%E7%BE%8E%E9%AB%98%E5%B1%B1%E6%B9%96%E6%B3%8A%E9%85%B1%E5%87%89%E6%8B%8C%E7%B4%A0%E9%B8%A1%E7%85%A7%E7%83%A7%E9%B8%A1%E9%BB%84%E7%8E%AB%E7%91%B0-%E7%A7%91%E5%B7%9E%E7%9A%84%E5%B0%8F%E4%B9%9D%E5%AF%A8%E6%B2%9F%E7%BB%9D%E7%BE%8E%E9%AB%98%E5%B1%B1%E6%B9%96%E6%B3%8A%E9%85%B1%E5%87%89%E6%8B%8C%E7%B4%A0%E9%B8%A1%E7%85%A7%E7%83%A7%E9%B8%A1%E9%BB%84%E7%8E%AB%E7%91%B0-%E7%A7%91%E5%B7%9E%E7%9A%84%E5%B0%8F%E4%B9%9D%E5%AF%A8%E6%B2%9F%E7%BB%9D%E7%BE%8E%E9%AB%98%E5%B1%B1%E6%B9%96%E6%B3%8A%E9%85%B1%E5%87%89%E6%8B%8C%E7%B4%A0%E9%B8%A1%E7%85%A7%E7%83%A7%E9%B8%A1%E9%BB%84%E7%8E%AB%E7%91%B0-%E7%A7%91%E5%B7%9E%E7%9A%84%E5%B0%8F%E4%B9%9D%E5%AF%A8%E6%B2%9F%E7%BB%9D%E7%BE%8E%E9%AB%98%E5%B1%B1%E6%B9%96%E6%B3%8A%E9%85%B1%E5%87%89%E6%8B%8C%E7%B4%A0%E9%B8%A1%E7%85%A7%E7%83%A7%E9%B8%A1%E9%BB%84%E7%8E%AB%E7%91%B0-%E7%A7%91%E5%B7%9E%E7%9A%84%E5%B0%8F%E4%B9%9D%E5%AF%A8%E6%B2%9F%E7%BB%9D%E7%BE%8E%E9%AB%98%E5%B1%B1%E6%B9%96%E6%B3%8A%E9%85%B1%E5%87%89%E6%8B%8C%E7%B4%A0%E9%B8%A1%E7%85%A7%E7%83%A7%E9%B8%A1%E9%BB%84%E7%8E%AB%E7%91%B0-%E7%A7%91%E5%B7%9E%E7%9A%84%E5%B0%8F%E4%B9%9D%E5%AF%A8%E6%B2%9F%E7%BB%9D%E7%BE%8E%E9%AB%98%E5%B1%B1%E6%B9%96%E6%B3%8A%E9%85%B1%E5%87%89%E6%8B%8C%E7%B4%A0%E9%B8%A1%E7%85%A7%E7%83%A7%E9%B8%A1%E9%BB%84%E7%8E%AB%E7%91%B0-%E7%A7%91%E5%B7%9E%E7%9A%84%E5%B0%8F%E4%B9%9D%E5%AF%A8%E6%B2%9F%E7%BB%9D%E7%BE%8E%E9%AB%98%E5%B1%B1%E6%B9%96%E6%B3%8A%E9%85%B1%E5%87%89%E6%8B%8C%E7%B4%A0%E9%B8%A1%E7%85%A7%E7%83%A7%E9%B8%A1%E9%BB%84%E7%8E%AB%E7%91%B0-%E7%A7%91%E5%B7%9E%E7%9A%84%E5%B0%8F%E4%B9%9D%E5%AF%A8%E6%B2%9F%E7%BB%9D%E7%BE%8E%E9%AB%98%E5%B1%B1%E6%B9%96%E6%B3%8A-lake-isabelle');
file_put_contents('./link.txt', $link);
file_put_contents('./substred.txt',  substr($link, 0, 255, 'UTF-8'));
file_put_contents('./mb_substred.txt', mb_substr($link, 0, 255, 'UTF-8'));
file_put_contents('./qsubstred.txt',  "'" . mb_substr($link, 0, 255, 'UTF-8') . "'");
file_put_contents('./qmb_substred.txt', "'" . mb_substr($link, 0, 255, 'UTF-8') . "'");
file_put_contents('./mbstrimwidth.txt',  mb_strimwidth($link, 0, 255, 'UTF-8'));

and THE ONLY ONE that gave a result that made sense and that the DB & tests passed was the results from:
file_put_contents('./mbstrimwidth.txt', mb_strimwidth($link, 0, 255, 'UTF-8'));.

Many times I have deferred to the wisdom of what has already been done (there are many smarter people than me working on this) but in this case there is empirical evidence to the contrary. drupal_substr() will not solve this problem and perhaps given enough stress testing it will be modified to incorporate mb_strimwidth() however these functions perform different tasks and I suspect that drupal_substr() will remain as is and that mb_strimwidth() will we used where appropriate, like here.

On another note, this part of drupal_substr():

 global $multibyte; 
  if ($multibyte == UNICODE_MULTIBYTE) {

predisposes there is some global recognition of multibyte being present (that that ONLY checking for UNICODE is sufficient) as a factor. I don't think that's an appropriate flag in this case. It's better to assume the worst case and always get it right regardless of any flags.

Alan D.’s picture

FileSize
56.59 KB

The main issue is that mbstring is a non-default extension with PHP that is not required to run Drupal, so this will cause a fatal error on many systems where that extension is not installed.

As an aside.

My local tests had no issue using mb_substr() via drupal_strlen() nor mb_strimwidth() writing to the watchdog table using your example above. My table charset was utf8,

drupal_set_message($link);
$a = substr($link, 0, 255);
drupal_set_message($a . '<br>strlen()' . strlen($a) . ':: drupal_strlen()' . drupal_strlen($a) . ' :: mb_strlen() ' . mb_strlen($a));
  $rec = array('link' => $a, 'type' => 'testing', 'message' => 'Testing ' . $a, 'variables' => serialize(array()), 'location' => 'http://localhost/', 'referer' => 'http://localhost/');
//drupal_write_record('watchdog', $rec);

$a = mb_substr($link, 0, 255);
drupal_set_message($a . '<br>strlen()' . strlen($a) . ':: drupal_strlen()' . drupal_strlen($a) . ' :: mb_strlen() ' . mb_strlen($a));
  $rec = array('link' => $a, 'type' => 'testing', 'message' => 'Testing ' . $a, 'variables' => serialize(array()), 'location' => 'http://localhost/', 'referer' => 'http://localhost/');
drupal_write_record('watchdog', $rec);

$a = mb_strimwidth($link, 0, 255);
drupal_set_message($a . '<br>strlen()' . strlen($a) . ':: drupal_strlen()' . drupal_strlen($a) . ' :: mb_strlen() ' . mb_strlen($a));
  $rec = array('link' => $a, 'type' => 'testing', 'message' => 'Testing ' . $a, 'variables' => serialize(array()), 'location' => 'http://localhost/', 'referer' => 'http://localhost/');
drupal_write_record('watchdog', $rec);

Tests done on a running Drupal install with mbstring enabled

substr() failed both when it wrote the message to the screen (last char was invalid) and the database. (an exception)

#251 changed drupal_strlen() with substr(), the failing test doesn't suprise me
#256 changed drupal_strlen() with substr() & mb_strimwidth(), so this removes the additional charset protection on type & hostname

When $multibyte == UNICODE_MULTIBYTE comes into play is with _unicode_check() that will only happen after mbstring is set up via

  mb_internal_encoding('utf-8');
  mb_language('uni');

Personally, is a link doesn't fit 255 chars, it's becomes meaningless once trimed, but that's another story lol

Reg’s picture

LOL, I was thinking the same thing about the link when I was looking at it getting truncated. Anyway, if some systems not having multibyte functions installed is the only issue, I think we have simple solution... looking through the Drupal unicode.inc file I found drupal_truncate_bytes() which seems to do the trick. That said, I couldn't imagine any system not having multibyte functions these days.

New patch using drupal_truncate_bytes() attached.

Reg’s picture

Status: Needs work » Needs review

Status: Needs review » Needs work

The last submitted patch, 268: add_backtrace_to_all_errors-1158322-268-D7.patch, failed testing. View results

Reg’s picture

Issue summary: View changes
Status: Needs work » Needs review

Status: Needs review » Needs work

The last submitted patch, 272: add_backtrace_to_all_errors-1158322-270-D7.patch, failed testing. View results
- codesniffer_fixes.patch Interdiff of automated coding standards fixes only.

Alan D.’s picture

Status: Needs work » Needs review
FileSize
20.75 KB

These were the 3 bits I was looking at. This happily executes watchdog('test', 'A test', array(), WATCHDOG_DEBUG, $link); using your link example above.

-        'type' => drupal_substr($log_entry['type'], 0, 64),
-        'link' => drupal_substr($log_entry['link'], 0, 255),
-        'hostname' => drupal_substr($log_entry['ip'], 0, 128),

From

+          'type'      => substr($log_entry['type'], 0, 64),
+          'link'      => drupal_truncate_bytes($log_entry['link'], 255),
+          'hostname'  => substr($log_entry['ip'], 0, 128),

To

+          'type'      => drupal_substr($log_entry['type'], 0, 64),
+          'link'      => drupal_substr($log_entry['link'], 0, 255),
+          'hostname'  => drupal_substr($log_entry['ip'], 0, 128),

Re-rolled to run the automated testing. Note, I have not reviewed the rest of the code other than getting rid of the "No newline at end of file" part of the patch in #272

Reg’s picture

I went through and cleaned up as much of the formatting notices as I could and did a couple of other improvements as well.

It's interesting that drupal_substr() on the link doesn't cause a DB error because it creates a total length of 723 bytes so the 255 DB limit is clearly multibyte friendly.

Reg’s picture

Alan D.’s picture

Nice work on the tidy up. It will help speed things up :)

Note: I tried with and without the mbstring extension enabled without issue, but the db was default the MySQL CHARSET=utf8 from the install I was testing on (old Drupal 7 one from back in 2104).

I'd assume that if drupal_substr() failed here it would potpourri of unrelated issues, which was why I found it unusual the need for the change :)

Checking core, it seems to be handled via drupal_strlen() normally, as most things indirectly set the limit via forms:

i.e. Node form title #maxlength = 255 & the length gets validated via drupal_strlen()

But a couple of places do use truncate_utf8(). I guess these handle data from sources outside of Drupal that could contain characters that need special processing? But these to be the exception rather than the norm.

comment_submit()
$comment->subject = truncate_utf8(trim(decode_entities(strip_tags($comment_text))), 29, TRUE);
aggregator_aggregator_process()
$item['title'] = truncate_utf8($item['title'], 255, TRUE, TRUE)
Reg’s picture

Reg’s picture

Just some more code formatting improvements.

Reg’s picture

Guys,

This issue was started in 2011 and I got involved in 2013, that's 7 & 5 years ago! respectively. There's a lot of interest and a definite need for it and we finally got an old patch up to date with the latest Drupal (7).

It would be great if someone from the core Drupal team would pick this up and run with it before this patch again gets so dated that it needs a serious revamp.

Any takers?

Chris Charlton’s picture

+1 to #280.

:)

SKAUGHT’s picture

Alan D.’s picture

Quick followup code std review to help speed things up even more ;)

https://www.drupal.org/pift-ci-job/853993
798 coding standards messages - 36 more than branch result

There seems to be trailing whitespace in a few places.

Search for "Whitespace found at end of line" in https://www.drupal.org/pift-ci-job/853993 or enable trim on save options in your IDE :)

+ * Error reporting type of debug information: How may calls deep from the errorSPACE

Doc comment short description must end with a full stop

+ * Error reporting type of debug information: How may calls deep from the error 
+ * line to show non-scalar variables

The first word after the colon should be in lowercase unless it is a proper noun.

Automatic testing complains about multiline comments a bit.

+ * Error reporting type of debug information: Add backtrace information to
+ * messages on page.

Most of the "Error reporting type of debug information" parts appear redundant?

Indicates that backtrace information is added to the messages on the page.
Indicates that backtrace information is added to the logs.
Display character limit of debug backtrace scalar arguments.
etc

Required? See alternative below for format_backtrace() that would make this redundant.

Do not start at zero! 

includes/bootstrap.inc
function array_has_PDOException($array) {
2636 Doc comment short description must be on a single line, further text should be a separate paragraph
2638 Expected "mixed" but found "type" for parameter type
2639 Parameter comment must end with a full stop
2641 Expected "bool" but found "boolean" for function return type
2644 Invalid function name, expected array_has_p_do_exception but found array_has_PDOException

Func name lowercase: array_has_pdoexception()

Short and sweet description should be enough?

Parses an array containing a debug backtrace for a PDOException class.

The type indicator type should be array if you use that, maybe $debug_info instead of $array so it reads nicer?

+ * @param type $array
+ * @param array $debug_info

includes/errors.inc
399 Equals sign not aligned with surrounding assignments; expected 7 spaces but found 11 spaces
400 Equals sign not aligned with surrounding assignments; expected 4 spaces but found 8 spaces
401 Equals sign not aligned with surrounding assignments; expected 1 space but found 5 spaces
402 Equals sign not aligned with surrounding assignments; expected 2 spaces but found 6 spaces

Not sure on the std here, though this is easier to read :P

includes/errors.inc
466 Space found before semicolon; expected "EOT;" but found "EOT ;"

function add_backtrace_styling()

+ * Adds some styling to make the display of the backtrace far clearer to 
+ * analyze.
+ * Adds inline CSS for styling a debug backtrace message.

modules/dblog/dblog.module
171 Comment indentation error, expected only 1 spaces

Maybe the @code tags?

+      // The following if statement is because the test "basic upgrade path"
+      // throws the following error:
+      // @code
+      //   SQLSTATE[42S02]: Base table or view not found: 1146
+      //   Table 'drupal_7_dev.simpletest107742access' doesn't exist: SELECT
+      //   mask FROM {access} WHERE status = :status AND type = :type;
+      //   Array ( [:status] => 0 [:type] => host )
+      // @endcode
+      // However the existing Drupal error logging just let's it go without

Personal preference, it's nice to see what random integers mean when they are used:

  $st_opts = variable_get('error_backtrace_display', array(2 => 0, 1 => 0));
  $st_opts = variable_get('error_backtrace_display', array(
    ERROR_REPORTING_DISPLAY_MESSAGES => 0,
    ERROR_REPORTING_DISPLAY_LOGS => 0,
  ));

And readability within format_backtrace() easier with this?

  if (array_sum(variable_get('error_backtrace_display', array(2 => 0, 1 => 0))) === 0) {
    return '';
  }

  $backtrace_display = array_filter(variable_get('error_backtrace_display', array()));
  if (!$backtrace_display) {
    return '';
  }
Chris Charlton’s picture

Can't wait to share this with our meetup group when it gets in!

SKAUGHT’s picture

Status: Needs review » Needs work
Reg’s picture

I'll do a clean up on these coding conventions this weekend.

David_Rothstein’s picture

I appreciate the work that has gone into this, but I'm not sure what framework-level review is needed here right now besides the one I already provided in #226 and #228 a long time ago. Because of those issues, which are substantial, I don't see how the patch could be committed to Drupal 7 in its current form.

SKAUGHT’s picture

Thanks Dave. i knew the tag was a little overzealous in that way. Which comes from it's own issue of process.. many of us do not know which tags to add to escalate issue reviews (past the group of people already watching it).

mikeytown2’s picture

What is needed is a straight backport from 8.x. Any new feature needs to land in 8.x and then 7.x. That is the issue with this patch, it does too much in comparison to what's in 8.x currently.

I like where this is headed but this needs to be a backport from 8.x first.

Reg’s picture

I don't know what you expect by a backport from Drupal 8. I would get the importance if the error trapping in D8 had some semblance to D7 but the error trapping part that matches D7 at all is a very small part of the error trapping in D8. Last I looked most of the error trapping is in symfony (although that was a few years ago so it could have changed quite a bit since then).

By the time you wrote code that gave a similar output in D8 that we are doing here there wouldn't be anything significant to backport - perhaps only the formatting function. It would instead just be a rewrite, not really a backport, which presumably would result in something like what we have now. So, if it's going to be code that almost doesn't relate at all, what do you hope to gain by requiring to do it that way?

dalin’s picture

Priority: Major » Normal
Status: Needs work » Needs review
FileSize
3.21 KB

The most recent patch was attempting to do a lot more than just add basic backtrace info to error logs/messages. It also had some problematic (mis)use of Drupal APIs, and confusing nomenclature.

Here's a much stripped down version that is fairly similar to D8. Hopefully this is a whole lot more core-worthy. Admittedly I haven't read all 290 comments on this issue, so I'm not sure if someone has already tried this simple approach.

dalin’s picture

Fixed a bug and plugged a vulnerability.

dalin’s picture

dalin’s picture

Now with support for exceptions.

nerdstein’s picture

I tested the patch in #294 and it works great.

To deploy, I ran the following Drush command:

drush ev "variable_set('error_backtrace', array(2 => 1, 1 => 1));"
Gnanasampandan Velmurgan’s picture

Patch #294 Its looks good to me. Its works. Thanks!

jhedstrom’s picture

+++ b/includes/bootstrap.inc
@@ -40,6 +40,16 @@
+define('ERROR_REPORTING_BACKTRACE_TO_LOGS', 1);
...
+define('ERROR_REPORTING_BACKTRACE_TO_SCREEN', 2);

Given #2908079: Move some of the bootstrap.inc PHP-related constants to \Drupal and deprecate the old versions, we should probably avoid adding new constants to bootstrap.inc I think...

  • catch committed fd352bf on 9.1.x
    Issue #1158322 by sun, jhedstrom, et al : Added backtrace to all errors.
    
  • webchick committed 37ea2e0 on 9.1.x
    Issue #1158322 follow-up by olli: Added missing backtrace to exception...
  • webchick committed 99fa84c on 9.1.x
    Issue #1158322 follow-up by chx: Fixed htmlspecialchars() expects...
anrikun’s picture

+1 for #294

anrikun’s picture

Status: Needs review » Reviewed & tested by the community
klausi’s picture

Unfortunately the patch from #294 does not handle exceptions that are thrown somewhere in code. Then the backtrace is useless, example:

Exception: bam in redirect_init() (line 303 of /var/www/html/profiles/recruiter/modules/redirect/redirect.module).

#0 /var/www/html/includes/bootstrap.inc(2587): _drupal_log_error(Array, true)
#1 [internal function]: _drupal_exception_handler(Object(Exception))
#2 {main}

When we have an exception then we need to log the backtrace of the exception, not the backtrace to the exception handler.

Attached is a small update to the patch that handles that.

aurelianzaha’s picture

aurelianzaha’s picture

Status: Needs review » Reviewed & tested by the community
eliosh’s picture

+1 for the #301 patch.
Is there a plan for a D8+ patch also ?

dalin’s picture

@eliosh, while this comment thread is super long, this was first committed to D8 about 10yrs ago. All that's left is D7. The latest D7 patch is significantly better than what we have in D9, but any improvements for that should be in new issues.

poker10’s picture

Patch #301 looks good, we are also using it, thanks!

It should help a lot in a cases like EntityMalformedException, where you currently need to print the backtrace manually to find the root of the problem.

However this last version of the patch is still a little bit "improved" over the D8 patch commited earlier. Actually, the patch #301 seems to be a combination of this issue backport and another issue backport: #2777955: [D7] Enable error logging to log a backtrace string

I am not sure if maintainers would allow this to get in or if it would needs to be in two separate backports.

solideogloria’s picture

The commits that were added in #298 might not be using error_reporting() correctly as of PHP 8.

See #3322606: Does the Drupal error_reporting() check still work?

It'd be good if someone else could see if a fix is needed.

Edit: The call to error_reporting() actually existed before these commits, but the issue is still related, as the code might not be working as intended.

Anybody’s picture

@eliosh, while this comment thread is super long, this was first committed to D8 about 10yrs ago. All that's left is D7. The latest D7 patch is significantly better than what we have in D9, but any improvements for that should be in new issues.

++!

Please create follow-ups for further improvements and let's get this finally committed, before we're on page 2 here ... -.-

anrikun’s picture

+1 for #301 too
Please commit!

Stoob’s picture

+1 and thank you for the wonderful #301 patch. Don't forget to turn backtrace in settings at admin/config/development/logging after patch applied