Upgrade Your Drupal Skills
We trained 1,000+ Drupal Developers over the last decade.
See Advanced Courses NAH, I know EnoughDebug 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.
About Drupal Sun
Drupal Sun is an Evolving Web project. It allows you to:
- Do full-text search on all the articles in Drupal Planet (thanks to Apache Solr)
- Facet based on tags, author, or feed
- Flip through articles quickly (with j/k or arrow keys) to find what you're interested in
- View the entire article text inline, or in the context of the site where it was created
See the blog post at Evolving Web