Right now, if db_query fails, it prints an error to the following effect:

user warning: Column count doesn't match value count at row 1 query: INSERT INTO blocks (visibility, pages, custom, title, module, theme, status, weight, delta, cache) VALUES(0, '', 0, 'dfsdf', 'block', 'garland', 0, 0, 14) in /Users/webchick/Sites/head/includes/database.mysql.inc on line 157.

The (normally) really useful part of this error is the filename and the line number. Unfortunately, the file/line number is ALWAYS includes/database.mysql.inc and line 157, for every single db_query call. :( Your only recourse is to start grepping through files to find a query kind of like the one being executed, or else hack core to stick debug_backtrace() in strategic places.

This patch adds an exception in drupal_error_handler for db_query, and instead turns that error into the following:

user warning: Column count doesn't match value count at row 1 query: INSERT INTO blocks (visibility, pages, custom, title, module, theme, status, weight, delta, cache) VALUES(0, '', 0, 'dfsdf', 'block', 'garland', 0, 0, 13) in /Users/webchick/Sites/head/modules/block/block.admin.inc on line 265.

This is especially important now that modules are being split up into 3+ files all over the place. It would've taken me a long time to track down where this buggy query was otherwise.

The downside? The code is pretty crufty. :P If someone can think of a better way to do this, I'm all ears.

Support from Acquia helps fund testing for Drupal Acquia logo

Comments

webchick’s picture

kbahey’s picture

This is REALLY needed. Let us get it in.

My only comment would be to not repeat 3 as a constant, make it a variable (e.g. $index) or a define('something', 3);, in case we introduce a different call sequence, then it is just one place to change.

webchick’s picture

Status: Needs review » Needs work

pwolanin thought of a *much* better solution here: instead of hacking the main error handling function, have _db_query temporarily register its own error handler, and restore it at the end.

pwolanin’s picture

maybe _db_query() could call set_error_handler() then restore_error_handler()?

Wim Leers’s picture

This would indeed be a very helpful change! Why didn't I think of that? :) Thanks, webchick!

webchick’s picture

Status: Needs work » Needs review
FileSize
6.21 KB

Ok, here's a version with pwolanin's idea.

Pros:
- No longer are performing a debug_backtrace() for *all* errors; only database errors specifically. Should be much better performance-wise.
- Still works! ;)

Cons:
- Lots of duplicated code... I basically had to copy/paste the drupal_error_handler() function as db_error_handler, and then just add my custom $line and $filename variables at the top. I also have to duplicate the set_error_handler stuff in each of the database.*.inc files. I don't think there's a way around that though.

If only there was a way to cut in and affect the $line and $filename variables before they get to drupal_error_handler(), this could be much simpler. But I don't think that's the case.

webchick’s picture

Oh. Also, since this new patch adds an extra function, I guess it qualifies as an API change. However, the fact that the line number/filename for db_query-related errors are all bogus might also be considered a bug. ;) Hopefully a core committer can weigh in on whether this should be postponed or if it has a chance for 6.x.

webchick’s picture

Actually, here's a new, non-API-breaking (mostly ;)), non-code-duplicating approach.

I read up on http://php.net/set_error_handler, and found that it also passes this nice $context variable in, which is an array of all variables currently in scope.

So if we pass that into drupal_error_handler, and check for the existence of $context['query'], we can then do our logic to change the line/file name before the output message is created.

And speaking of logic, I happened upon pager_query, which has a different stack trace, and actually ends up as #4, and not #3. So I now have an array of "query-ish" functions, and check to see which one called it, and call that one's index accordingly. This should be a bit more robust.

pwolanin’s picture

well, that certainly looks nicer! Your list of query functions needs db_query_range also, I think.

Is 'query' really a robust thing to look for in the context? How about something like:

${md5('query')} = TRUE;

and then in the patch check for

if (isset($context['md5(query)'])) {

Or better yet, use define() so it's not re-calculated all the time.

in database.inc:

define (QUERY_FUNCTION, md5('query'));

in each DB-specific .inc:

function _db_query($query, $debug = 0) {
  global $active_db, $queries;
  ${QUERY_FUNCTION} = TRUE;

and then in the patch check for

if (isset($context[QUERY_FUNCTION])) {
webchick’s picture

Great suggestion! Implemented. :D I also added db_query_temporary and update_sql to that list.

Now, the one remaining problem (so far) is that because both pager_query AND db_query_range are in the array, pager_query's file/line no will get set to pager.inc, rather than the place where the query originated. :( Since pager_query calls db_query_range, it'll be ahead of it in the backtrace.

To test, edit node.module, node_page_default, the first select query there to just put in some random crap that will cause an SQL error. The error will be:

user warning: Unknown column 'no.nid' in 'field list' query: SELECT no.nid, n.sticky, n.created FROM node n WHERE n.promote = 1 AND n.status = 1 ORDER BY n.sticky DESC, n.created DESC LIMIT 0, 10 in /Users/webchick/Sites/head/includes/pager.inc on line 75.

where it should be:

user warning: Unknown column 'no.nid' in 'field list' query: SELECT no.nid, n.sticky, n.created FROM node n WHERE n.promote = 1 AND n.status = 1 ORDER BY n.sticky DESC, n.created DESC LIMIT 0, 10 in /Users/webchick/Sites/head/modules/node/node.module on line 1558.

But we're getting there. :)

webchick’s picture

All right! Thanks to quicksketch (and later echoed by dmitrig01)'s marvelous idea -- storing the backtrace index with the query functions -- I think this sucker hits all the edge cases and is ready for prime-time testing now.

Steven’s picture

It seems to me this patch makes an assumption about what happens inside _db_query() (i.e. db-backend specific), and hardcodes that assumption in the fixed index values in the db-agnostic error handler.

e.g. Take one of the trigger_error() statements from the patch, and move the line of code out into another function, which is called from the original trigger_error() location. The backtrace for these errors will now contain an additional step between the start and whatever function we are looking for, and the lookup will fail.

As more advanced back-ends are being worked on, it seems very bad to assume anything about the call dispatching inside the database abstraction layer. One possible solution would be to change the global variable from a boolean to an integer, containing the number of backtrace steps needed to step out from the database-backend-specific code from each particular point.

Steven’s picture

It seems to me this patch makes an assumption about what happens inside _db_query() (i.e. db-backend specific), and hardcodes that assumption in the fixed index values in the db-agnostic error handler.

e.g. Take one of the trigger_error() statements from the patch, and move the line of code out into another function, which is called from the original trigger_error() location. The backtrace for these errors will now contain an additional step between the start and whatever function we are looking for, and the lookup will fail.

As more advanced back-ends are being worked on, it seems very bad to assume anything about the call dispatching inside the database abstraction layer. One possible solution would be to change the global variable from a boolean to an integer, containing the number of backtrace steps needed to step out from the database-backend-specific code from each particular point.

Dries’s picture

Why don't we just print the entire stack trace? It's what all other programming languages do, and it makes it a lot easier to understand what is going on.

kbahey’s picture

As an option with some settings, I would support what Dries says. Otherwise, it is too verbose, and too revealing as well (if displayed in a browser).

However, in this case, we know that there is specifically some database error (SQL, ...etc.) so we focus on that specific, and give the file/line of the offending code.

pwolanin’s picture

actually, better might just be to hardcode the md5 value - no need to ever run it!
MD5 ("DB_ERROR") = a515ac9c2796ca0e23adbe92c68fc9fc

// Use the string md5('DB_ERROR') as a flag.
define('DB_ERROR', 'a515ac9c2796ca0e23adbe92c68fc9fc');

Also - pager query calls db_query_range(). So, which order does the backtrace array contain? If you're trying to backtrace a pager query you'll hit db_query_range first. Perhaps you need to use array_reverse() on the keys or some such?

foreach (array_reverse(array_keys($backtrace)) as $index) {
  if (in_array($backtrace[$index]['function'], $query_functions)) {

pwolanin’s picture

I didn't read Dries before posting (I hit the follow-up link in my e-mail) - my suggestion above could also be modified (at least if some debug flag is on) to show the part of the stack trace we care about - that is everything from from the menu system down to the function making the query - in most cases I don't think one wants or needs to know about the variety of system functions actually doing the query.

webchick’s picture

Status: Needs review » Needs work

@Steven: Good points; there are a lot of assumptions in the code. :\ But I'm not sure how to do:

One possible solution would be to change the global variable from a boolean to an integer, containing the number of backtrace steps needed to step out from the database-backend-specific code from each particular point.

It seems like I'd need to do the backtrace in two places..? Once in _db_query and again in drupal_error_handler? Or am I just misunderstanding (totally likely/possible :P).

@pwolanin: Yes, the functions intentionally listed in a very specific order, so that update_sql will be found before db_query, etc.

@Dries: Ideally I would like to do that; however, I've actually crashed my browser a few times using my quick and dirty debugging technique when you, for example, get to a page that has 30 table rows and each one of those generates a notice that gets dsm()ed. Eek.

But actually, what about THIS! When logging the error via watchdog, we include the full backtrace. The dsm() prints:

user warning: Column count doesn't match value count at row 1 query: INSERT INTO blocks (visibility, pages, custom, title, module, theme, status, weight, delta, cache) VALUES(0, '', 0, 'dfsdf', 'block', 'garland', 0, 0, 14) in /Users/webchick/Sites/head/includes/database.mysql.inc on line 157. Please view the [link-to-watchdog-log-entry]event logs[/link] for more information.

Of course, the last is only printed if dblog is found.

This way it would help debug not only database errors, but all other errors, AND wouldn't crash the browser by printing too much information to the screen.

webchick’s picture

Title: Add useful error reporting for db_query() » Add backtraces to watchdog

I had misunderstood pwolanin earlier; he was advocating going through the backtrace in the opposite order, so that it would find the correct function and we wouldn't need any of this index business. I think that would work fine.

However, in debugging MORE stuff today and yesterday, I noticed there are several other things that give stupid error messages, like node_loads that fail for non-SQL-related reasons and stuff like that. Therefore, I plan to implement Dries's suggestion @ #14. Patch forthcoming...

webchick’s picture

Status: Needs work » Needs review
FileSize
961 bytes

Here we go. This will append a backtrace to any errors of type 'php', which includes SQL errors.

This looks a bit scary, but it's only because var_dump doesn't return a value, so I have to use output buffering. We could make this a 3-liner with a simple:

if ($type == 'php') {
  $message .= '<pre>'. print_r(debug_backtrace(), 1) .'</pre>';
}

However, particularly when debugging FAPI, it's sometimes very helpful to know whether that "nothing" is FALSE, NULL, or an empty string.

webchick’s picture

FileSize
51.82 KB

Here's a screenshot of what it looks like.

moshe weitzman’s picture

devel.module alreacdy has different error handlers. it seems to me that this is where the functionality belongs. also xdebug already does this in a far prettier way. i don't care much though. my .02.

webchick’s picture

Devel module is something I don't trust on production sites. It feels like too many people have commit access to that project, and it does A LOT of stuff besides simply printing backtraces.

But if the answer is won't fix -- use devel, I can live with that. I'll still use the first patch here for debugging locally, just thought it might be helpful to include in core.

kbahey’s picture

I find the var_dump makes my eyes bleed.

Here is a better version:

Index: includes/bootstrap.inc
===================================================================
RCS file: /cvs/drupal/drupal/includes/bootstrap.inc,v
retrieving revision 1.181
diff -u -F^f -r1.181 bootstrap.inc
--- includes/bootstrap.inc      7 Aug 2007 08:41:24 -0000       1.181
+++ includes/bootstrap.inc      25 Aug 2007 21:32:17 -0000
@@ -707,6 +707,18 @@ function request_uri() {
 function watchdog($type, $message, $variables = array(), $severity = WATCHDOG_NOTICE, $link = NULL) {
   global $user, $base_root;

+  // If this is a PHP error, append a backtrace to the message for easier
+  // debugging. Because var_dump() does not return a value, need to use
+  // output buffering.
+  if ($type == 'php') {
+    $message .= '<pre>';
+    $dump = debug_backtrace();
+    foreach($dump as $key => $value) {
+      $message .= $value['file']. ':' .$value['function']. ':' .$value['line'] . "\n";
+    }
+    $message .= '</pre>';
+  }
+
   // Prepare the fields to be logged
   $log_message = array(
     'type'        => $type,

The output looks like so:

You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use near &#039;.nid, n.sticky, n.created FROM node n WHERE n.promote = 1 AND n.status = 1 ORDER&#039; at line 1 query: SELECT bah n.nid, n.sticky, n.created FROM node n WHERE n.promote = 1 AND n.status = 1 ORDER BY n.sticky DESC, n.created DESC LIMIT 0, 10 in /blah/drupal/includes/database.mysqli.inc on line 154.

/blah/drupal/includes/common.inc:watchdog:549
:drupal_error_handler:
/blah/drupal/includes/database.mysqli.inc:trigger_error:154
/blah/drupal/includes/database.mysqli.inc:_db_query:270
/blah/drupal/includes/pager.inc:db_query_range:75
/blah/drupal/modules/node/node.module:pager_query:1558
:node_page_default:
/blah/drupal/includes/menu.inc:call_user_func_array:314
/blah/drupal/index.php:menu_execute_active_handler:15

Note the filepath:function:line

Some backtrace points have no filepath/line number, but that would be the same in the array.

Anyone likes this better?

Re: devel, I use it on live sites, but a) should not be mandatory for error tracing, and b) many themes do not like it (e.g. CSS based ones can have the output of devel shift up and become too disruptive).

pwolanin’s picture

I think the original goal of the patch - print accurate error messages for SQL errors - is still pretty critical for core. It would make a lot of bug reports in the queue more informative.

pwolanin’s picture

FileSize
4.56 KB

here's a patch that goes essentially back to the patch in #10 to fulfill the simple goal of seeing the actual relevant line# for SQL errors.

One key difference: $backtrace = array_reverse(debug_backtrace()); Thus it naturally gives us the correct result for pager_query.

for example, if I break the query in node_page_default():

user warning: You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use near '.nid, n.sticky, n.created FROM node n WHERE n.promote = 1 AND n.status = 1 ORDER' at line 1 query: SELECT xxx n.nid, n.sticky, n.created FROM node n WHERE n.promote = 1 AND n.status = 1 ORDER BY n.sticky DESC, n.created DESC LIMIT 0, 10 in /www/drupal6/modules/node/node.module on line 1576.
pwolanin’s picture

Title: Add backtraces to watchdog » Add useful error reporting for db_query() (or add backtraces to watchdog)
dvessel’s picture

Status: Needs review » Reviewed & tested by the community

I tried breaking a couple of queries and it always works. The node_search() tricked me since it points to the search module but it's pointing a lot closer to any errors.

Very nice!

moshe weitzman’s picture

sorry, i have not inspected this closely. i just want to remind that the $queries global already has backtrace info in it, and we should make sure that it stays available and accurate. after all the devel.module query log has already provided this backtrace info since the beginning of time.

pwolanin’s picture

I don't see any reason why this patch would affect devel. I assume devel uses the code such as here:

http://api.drupal.org/api/function/_db_query/6

which turns the backtrace on if the 'dev_query' variable is TRUE. In fact, since I think devel supplants the drupal error handler with its own, the code in this patch would never execute with devel on except for setting the ${DB_QUERY} variable.

moshe weitzman’s picture

yes, seems like we are fine.

devel has the option to replace the error handler but thats no longer the default. one of the existing options is a backtrace but it doesn't work too well IMO.

Gábor Hojtsy’s picture

Status: Reviewed & tested by the community » Fixed

I agree that the original goals: including the right line number and file name in the error were best completed in core. A full stack trace for all errors is a no-go if you have lots of errors on a page, as noted by webchick. So reviewed this last patch and as I found no outstanding problems with it, I got it committed. Thanks!

pwolanin’s picture

Status: Fixed » Patch (to be ported)

Can this simple version be considered for 5.x backport?

bdragon’s picture

Version: 6.x-dev » 5.x-dev
dww’s picture

Version: 5.x-dev » 6.x-dev
Status: Patch (to be ported) » Fixed

As if we didn't already have enough reasons to love webchick and pwolanin. ;) I just noticed this issue while reading CVS logs (it's been a while since I updated my D6 test site) and y'all rock. Thanks!

That said, I don't think I'd support this as a backport to D5. While it's incredibly useful, it really is more of a new feature and it could potentially break something in the stable series. Let's just make this yet another reason to upgrade to D6. ;)

Anonymous’s picture

Status: Fixed » Closed (fixed)