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(‘

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:

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.