Debug live errors more easily with debug_backtrace() output in error messages

Tailing my error log, I kept coming across annoying errors like this:


[Mon Nov 13 21:14:49 2006] [error] [client xx.xxx.xxx.xxx] PHP Warning: mysql_real_escape_string() expects parameter 1 to be string, array given in /path/to/drupal/includes/database.mysql.inc on line 350, referer: http://www.example.com/node/1234/edit

No matter how hard I tried, I couldn’t reproduce the errors locally, but somehow real users could create them on the live server. I tried to track down the bug but could only go so far – yes, it was happening when a node was edited, and it was in a database query, but which query? There were too many to look at, so I needed more information.

Because I couldn’t reproduce the bug locally, no amount of dprint_r() and such had any effect. Following some advice in #drupal I explored debug_backtrace() and added its output to a custom error log like this:


function mymodule_error($errno, $errstr, $errfile, $errline, $errcontext) {

if (in_array($errno, array(ERR_LOW, E_NOTICE, E_STRICT))) {
$level = false;
}
elseif (in_array($errno, array(ERR_MED, E_WARNING))) {
$level = ‘WARNING’;
}
elseif (in_array($errno, array(ERR_HI, E_ERROR))) {
$level = ‘FATAL’;
}
else $level = ‘UNKNOWN’;

if ($level) {
// don’t log unimportant errors

$functions = array();
foreach (debug_backtrace() AS $errors) {
$functions[] = $errors[‘function’] . ‘:’ . $errors[‘line’];
}
$trace = join(‘ < = ', $functions);

error_log($level . ' ' . $errfile . ':' . $errline . '. ' . $errstr . '. (' . $trace . ')');
}
}
set_error_handler('mymodule_error');

I put the code in a module file, and it didn’t work… an hour of hair pulling later I found the culprit to be devel.module:

function devel_init() {
restore_error_handler();
}

… this was undoing my error handling setting, so I had to comment out the restore_error_handler() line and my error handler took centre stage.

With the new code live, I just waited a few hours until the bug showed up again – this time, with extra backtrace information to help me debug:


[Tue Nov 14 18:13:14 2006] [error] [client xx.xxx.xxx.xxx] WARNING /path/to/drupal/includes/database.mysql.inc:350. mysql_real_escape_string() expects parameter 1 to be string, array given. (mymodule_error: < = mysql_real_escape_string:350 <= db_escape_string:152 <= _db_query_callback: <= preg_replace_callback:196 <= db_query:1040 <= my_custom_function:659 <= my_nodetype_update:297 <= node_invoke:494 <= node_save:1876 <= node_form_submit: <= call_user_func_array:206 <= drupal_submit_form:132 <= drupal_get_form:1620 <= node_form:2093 <= node_page: <= call_user_func_array:418 <= menu_execute_active_handler:15), referer: http://www.example.com/node/1234/edit

So now I knew exactly where the bug was coming from. ‘db_query’ was called on line ‘1040’ of my file, and of the several ways to get into the function in which line 1040 resides, I knew it had come form my_custom_function on line 659.

Armed with this extra information, tracking down the bug was a breeze. Stupidly, I’d forgotten to do a regular expression I was supposed to do on a variable before doing a db_query, meaning arrays which were supposed to be left alone were wandering into the query pretending to be strings.

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s