diff --git a/includes/bootstrap.inc b/includes/bootstrap.inc index c06055e..545b8db 100644 --- a/includes/bootstrap.inc +++ b/includes/bootstrap.inc @@ -41,6 +41,64 @@ define('ERROR_REPORTING_DISPLAY_SOME', 1); define('ERROR_REPORTING_DISPLAY_ALL', 2); /** + * Error reporting type of debug information: Add backtrace information to logs. + * Do not start at zero! + */ +define('ERROR_REPORTING_DISPLAY_LOGS', 1); + +/** + * Error reporting type of debug information: Add backtrace information to + * messages on page. + */ +define('ERROR_REPORTING_DISPLAY_MESSAGES', 2); + +/** + * Error reporting type of debug information: Include scalar variables. + */ +define('ERROR_REPORTING_DISPLAY_SCALAR', 3); + +/** + * Error reporting type of debug information: Include non-scalar variables. + */ +define('ERROR_REPORTING_DISPLAY_NON_SCALAR', 4); + +/** + * Error reporting type of debug information: How may calls deep from the error + * line to show scalar variables. + */ +define('ERROR_REPORTING_DISPLAY_SCALAR_CALL_START', 1); + +/** + * Error reporting type of debug information: How may calls deep from the error + * line to show scalar variables. + */ +define('ERROR_REPORTING_DISPLAY_SCALAR_CALL_DEPTH', 0); + +/** + * Error reporting type of debug information: How may calls deep from the error + * line to show non-scalar variables. + */ +define('ERROR_REPORTING_DISPLAY_NON_SCALAR_CALL_START', 1); + +/** + * Error reporting type of debug information: How may calls deep from the error + * line to show non-scalar variables + */ +define('ERROR_REPORTING_DISPLAY_NON_SCALAR_CALL_DEPTH', 0); + +/** + * Error reporting type of debug information: How Non-scalar values can become + * too long to practically display. Limit the output size with this setting. + */ +define('ERROR_REPORTING_DISPLAY_SCALAR_MAX_LENGTH', 1024); + +/** + * Error reporting type of debug information: How Non-scalar values can become + * too long to practically display. Limit the output size with this setting. + */ +define('ERROR_REPORTING_DISPLAY_NON_SCALAR_MAX_LENGTH', 1024); + +/** * Indicates that the item should never be removed unless explicitly selected. * * The item may be removed using cache_clear_all() with a cache ID. @@ -2572,6 +2630,30 @@ function drupal_get_hash_salt() { } /** + * 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; +} + +/** * Provides custom PHP error handling. * * @param $error_level diff --git a/includes/errors.inc b/includes/errors.inc index 3548d1f..2113108 100644 --- a/includes/errors.inc +++ b/includes/errors.inc @@ -199,6 +199,9 @@ function _drupal_log_error($error, $fatal = FALSE) { $number++; } + $error['!backtrace'] = format_backtrace(); + $st_opts = variable_get('error_backtrace_display', array(2 => 0, 1 => 0)); + // Log the error immediately, unless this is a non-fatal error which has been // triggered via drupal_trigger_error_with_delayed_logging(); in that case // trigger it in a shutdown function. Fatal errors are always triggered @@ -207,7 +210,20 @@ function _drupal_log_error($error, $fatal = FALSE) { drupal_register_shutdown_function('watchdog', 'php', '%type: !message in %function (line %line of %file).', $error, $error['severity_level']); } else { - watchdog('php', '%type: !message in %function (line %line of %file).', $error, $error['severity_level']); + if ($st_opts[ERROR_REPORTING_DISPLAY_LOGS]) { + $message_line = '%type: 
!message

LINE: %line
FUNCTION: %function
FILE: %file'; + if ($st_opts[ERROR_REPORTING_DISPLAY_LOGS]) { + $message_line .= ' !backtrace'; + } + } + else { + $message_line = '%type: !message in %function (line %line of %file).'; + } + + // If it was a DB error don't write to the DB. + if (!array_has_PDOException($error)) { + watchdog('php', $message_line, $error, $error['severity_level']); + } } if ($fatal) { @@ -244,13 +260,29 @@ function _drupal_log_error($error, $fatal = FALSE) { $class = 'status'; } - drupal_set_message(t('%type: !message in %function (line %line of %file).', $error), $class); + // Attempt to reduce verbosity by removing DRUPAL_ROOT from the file path + // in the message. + $root_length = strlen(DRUPAL_ROOT); + if (substr($error['%file'], 0, $root_length) == DRUPAL_ROOT) { + $error['%file'] = substr($error['%file'], $root_length + 1); + } + $message = t('%type: !message in %function (line %line of %file).', $error); + + // Check if verbose error reporting is on. + $error_level = variable_get('error_level', ERROR_REPORTING_DISPLAY_ALL); + + if ($error_level != ERROR_REPORTING_HIDE) { + if ($st_opts[ERROR_REPORTING_DISPLAY_MESSAGES]) { + $message .= $error['!backtrace']; + } + } + drupal_set_message($message, $class); } if ($fatal) { drupal_set_title(t('Error')); - // We fallback to a maintenance page at this point, because the page generation - // itself can generate errors. + // We fallback to a maintenance page at this point, because the page + // generation itself can generate errors. print theme('maintenance_page', array('content' => t('The website encountered an unexpected error. Please try again later.'))); exit; } @@ -293,3 +325,210 @@ function _drupal_get_last_caller($backtrace) { } return $call; } + +/** + * Formats a backtrace into an HTML table. + * + * @param int $skip_level + * How many levels to remove from the end of the backtrace. 1 is the default + * which is enough to remove this function. + * + * @return string + * An HTML string. + */ +function format_backtrace($skip_level = 0) { + if (array_sum(variable_get('error_backtrace_display', array(2 => 0, 1 => 0))) === 0) { + return ''; + } + + $show_vars = (variable_get('error_backtrace_display_scalar', ERROR_REPORTING_DISPLAY_SCALAR) || + variable_get('error_backtrace_display_non_scalar', ERROR_REPORTING_DISPLAY_NON_SCALAR)); + + $backtrace = debug_backtrace(TRUE); + $backtrace = array_slice($backtrace, ($skip_level + 1), NULL); + $callstack = array_reverse($backtrace, TRUE); + add_backtrace_styling(); + $cs1 = $show_vars ? 'Passed variables' : ''; + $cs = << + + + + + + + + $cs1 + + + +EOT; + + $row_bunching = 3; + $data_to_show = array('function' => 0, 'line' => 0, 'file' => 0); + if ($show_vars) { + $data_to_show += array('args' => 0); + } + foreach ($callstack as $call_depth => &$v) { + $row_bunching++; + if ($row_bunching >= 3) { + $row_class = 'class="row-bunch"'; + $row_bunching = 0; + } + else { + $row_class = ''; + } + $cs .= ""; + + /* + * Let's set this locally since they'll be called many times in the loop + * and this function could be called many times. + */ + static $static_set = FALSE; + static $show_scalar; + static $max_len_scalar; + static $start_vars_scalar; + static $stop_vars_scalar; + static $show_non_scalar; + static $max_len_non_scalar; + static $start_vars_non_scalar; + static $stop_vars_non_scalar; + static $output_buffering; + + if (!$static_set) { + $show_scalar = variable_get('error_backtrace_display_scalar', ERROR_REPORTING_DISPLAY_SCALAR); + $max_len_scalar = variable_get('error_backtrace_display_scalar_max_length', ERROR_REPORTING_DISPLAY_SCALAR_MAX_LENGTH); + $start_vars_scalar = variable_get('error_backtrace_display_scalar_call_start', ERROR_REPORTING_DISPLAY_SCALAR_CALL_START); + $stop_vars_scalar = variable_get('error_backtrace_display_scalar_call_start', ERROR_REPORTING_DISPLAY_SCALAR_CALL_START) + + variable_get('error_backtrace_display_scalar_call_depth', ERROR_REPORTING_DISPLAY_SCALAR_CALL_DEPTH); + + $show_non_scalar = variable_get('error_backtrace_display_non_scalar', ERROR_REPORTING_DISPLAY_NON_SCALAR); + $max_len_non_scalar = variable_get('error_backtrace_display_non_scalar_max_length', ERROR_REPORTING_DISPLAY_NON_SCALAR_MAX_LENGTH); + $start_vars_non_scalar = variable_get('error_backtrace_display_non_scalar_call_start', ERROR_REPORTING_DISPLAY_NON_SCALAR_CALL_START); + $stop_vars_non_scalar = variable_get('error_backtrace_display_non_scalar_call_start', ERROR_REPORTING_DISPLAY_NON_SCALAR_CALL_START) + + variable_get('error_backtrace_display_non_scalar_call_depth', ERROR_REPORTING_DISPLAY_NON_SCALAR_CALL_DEPTH); + + $output_buffering = ini_get('output_buffering'); + + $static_set = TRUE; + } + + foreach ($data_to_show as $k2 => $v2) { + if (isset($v[$k2])) { + switch ($k2) { + case 'args': + $data = ''; + foreach ($v[$k2] as $index => $arg) { + if (is_scalar($arg)) { + if ($show_scalar && $call_depth >= $start_vars_scalar && $call_depth <= $stop_vars_scalar) { + $data .= _format_backtrace_fmt_var($arg, $max_len_scalar, gettype($arg)); + } + } + else { + if ($show_non_scalar && $call_depth >= $start_vars_non_scalar && $call_depth <= $stop_vars_non_scalar) { + if (!empty($output_buffering)) { + ob_start(); + // Handles recursion so do it this way if possible. + var_dump($arg); + $var = ob_get_clean(); + } + else { + // '@' = Suppress the "does not handle recursion" warnings. + $var = @var_export($arg, TRUE); + } + $data .= _format_backtrace_fmt_var($var, $max_len_non_scalar); + } + } + } + // Remove
off end of last var. + $data = strlen($data) ? substr($data, 0, -4) : ' '; + $cs .= ""; + break; + + default: + $data = str_replace(DRUPAL_ROOT . '/', '', $v[$k2]); + $data = htmlentities($data); + $cs .= ""; + break; + } + } + else { + $cs .= ""; + } + } + $cs .= ''; + } + $cs .=<< +
IndexFunction calledCaller lineCaller file
$call_depth$data$data
+ +EOT + ; + return '

BACKTRACE:' . $cs; +} + +/** + * Formats variables for better presentation. + * + * Formatting includes: + * Puts the type of variable in front of the value, e.g. + * "string: The quick brown..." + * Limits the length of string being returned. + * Optionally shows the number of characters truncated. + * Makes HTML safe. + * + * @param string $arg + * The variable to format as a string. + * @param int $max_len + * A limit on the length of string being returned. + * @param string $type + * The type of variable the string represents. + * + * @return string + * The variable formatted. + */ +function _format_backtrace_fmt_var($arg, $max_len, $type = FALSE) { + $var = str_replace(DRUPAL_ROOT . '/', '', $arg); + $diff = (strlen($var) - $max_len); + if ($diff > 0) { + $var = substr($var, 0, $max_len); + } + if ($type !== FALSE) { + $var = $type . ': ' . $var; + } + $var = htmlentities($var) . '
'; + if ($diff > 0) { + $var .= '...(' . number_format($diff) . ' chars truncated)
'; + } + return $var; +} + +/** + * Adds some styling to make the display of the backtrace far clearer to + * analyze. + * + * @staticvar boolean $needs_styling + */ +function add_backtrace_styling() { + static $needs_styling = TRUE; + + if ($needs_styling) { + $css = << 'inline', 'preprocess' => FALSE)); + $needs_styling = FALSE; + } +} diff --git a/modules/dblog/dblog.admin.inc b/modules/dblog/dblog.admin.inc index f8a00c2..e82fcb7 100644 --- a/modules/dblog/dblog.admin.inc +++ b/modules/dblog/dblog.admin.inc @@ -153,6 +153,7 @@ function dblog_event($id) { $severity = watchdog_severity_levels(); $result = db_query('SELECT w.*, u.name, u.uid FROM {watchdog} w INNER JOIN {users} u ON w.uid = u.uid WHERE w.wid = :id', array(':id' => $id))->fetchObject(); if ($dblog = $result) { + add_backtrace_styling(); $rows = array( array( array('data' => t('Type'), 'header' => TRUE), diff --git a/modules/dblog/dblog.module b/modules/dblog/dblog.module index df305a2..d050583 100644 --- a/modules/dblog/dblog.module +++ b/modules/dblog/dblog.module @@ -148,20 +148,43 @@ function dblog_watchdog(array $log_entry) { require_once DRUPAL_ROOT . '/includes/unicode.inc'; } try { - Database::getConnection('default', 'default')->insert('watchdog') - ->fields(array( - 'uid' => $log_entry['uid'], - 'type' => drupal_substr($log_entry['type'], 0, 64), - 'message' => $log_entry['message'], - 'variables' => serialize($log_entry['variables']), - 'severity' => $log_entry['severity'], - 'link' => drupal_substr($log_entry['link'], 0, 255), - 'location' => $log_entry['request_uri'], - 'referer' => $log_entry['referer'], - 'hostname' => drupal_substr($log_entry['ip'], 0, 128), - 'timestamp' => $log_entry['timestamp'], - )) - ->execute(); + // If it was a DB error don't write to the DB. + if (!array_has_PDOException($log_entry)) { + Database::getConnection('default', 'default')->insert('watchdog') + ->fields(array( + 'uid' => $log_entry['uid'], + 'type' => drupal_substr($log_entry['type'], 0, 64), + 'message' => $log_entry['message'], + 'variables' => serialize($log_entry['variables']), + 'severity' => $log_entry['severity'], + 'link' => drupal_substr($log_entry['link'], 0, 255), + 'location' => $log_entry['request_uri'], + 'referer' => $log_entry['referer'], + 'hostname' => drupal_substr($log_entry['ip'], 0, 128), + 'timestamp' => $log_entry['timestamp'], + )) + ->execute(); + } + else { + // The following if statement is because the test "basic upgrade path" + // throws the following error: + // 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 ) + // however the existing Drupal error logging just let's it go without + // telling simpletests there's a problem (because a calling function uses + // a simple semaphore to stop errors being triggered inside the error + // handler). Since we go out of our way to catch these errors as well we + // won't pass the automatic tester while this error exists. + // + // To solve this we add the following if statement to more accurrately + // simulate Drupal's current behavior. Once the SQL error in the test is + // fixed we should remove this if statement. + if (!drupal_valid_test_ua()) { + _drupal_log_error($log_entry['variables'], TRUE); + } + } } catch (Exception $e) { // Exception is ignored so that watchdog does not break pages during the diff --git a/modules/system/system.admin.inc b/modules/system/system.admin.inc index cdcc78f..ec8546b 100644 --- a/modules/system/system.admin.inc +++ b/modules/system/system.admin.inc @@ -1676,6 +1676,105 @@ function system_logging_settings() { '#description' => t('It is recommended that sites running on production environments do not display any errors.'), ); + $form['backtrace_options'] = array( + '#type' => 'fieldset', + '#collapsible' => TRUE, + '#collapsed' => TRUE, + '#title' => t('Backtrace Options'), + '#description' => t('These options should only be used in developer environments.'), + ); + + $form['backtrace_options']['error_backtrace_display'] = array( + '#type' => 'checkboxes', + '#title' => t('Choose how to monitor backtrace information.'), + '#default_value' => variable_get('error_backtrace_display', array(2 => 0, 1 => 0)), + '#options' => array( + ERROR_REPORTING_DISPLAY_MESSAGES => t('Show on page'), + ERROR_REPORTING_DISPLAY_LOGS => t('Add to log'), + ), + '#description' => t('On production environments do not use "Show on page".'), + ); + + $form['backtrace_options']['scalar'] = array( + '#type' => 'fieldset', + '#collapsible' => TRUE, + '#collapsed' => TRUE, + '#title' => t('Scalar Variables Options'), + ); + + $form['backtrace_options']['scalar']['error_backtrace_display_scalar'] = array( + '#type' => 'checkbox', + '#title' => t('Include passed values'), + '#default_value' => variable_get('error_backtrace_display_scalar', ERROR_REPORTING_DISPLAY_SCALAR), + ); + + $form['backtrace_options']['scalar']['error_backtrace_display_scalar_call_start'] = array( + '#type' => 'textfield', + '#title' => t('Backtrace start'), + '#default_value' => variable_get('error_backtrace_display_scalar_call_start', ERROR_REPORTING_DISPLAY_SCALAR_CALL_START), + '#size' => 4, + '#maxlength' => 4, + '#description' => t('From what depth to start showing scalar variables. 1 = the place the error occured.'), + ); + + $form['backtrace_options']['scalar']['error_backtrace_display_scalar_call_depth'] = array( + '#type' => 'textfield', + '#title' => t('Backtrace depth'), + '#default_value' => variable_get('error_backtrace_display_scalar_call_depth', ERROR_REPORTING_DISPLAY_SCALAR_CALL_DEPTH), + '#size' => 4, + '#maxlength' => 4, + '#description' => t('How may calls deep from the starting point to show scalar variables.'), + ); + + $form['backtrace_options']['scalar']['error_backtrace_display_scalar_max_length'] = array( + '#type' => 'textfield', + '#title' => t('Max length'), + '#default_value' => variable_get('error_backtrace_display_scalar_max_length', ERROR_REPORTING_DISPLAY_SCALAR_MAX_LENGTH), + '#size' => 10, + '#maxlength' => 10, + '#description' => t('Limit the output size in characters of scalar values.'), + ); + + $form['backtrace_options']['non_scalar'] = array( + '#type' => 'fieldset', + '#collapsible' => TRUE, + '#collapsed' => TRUE, + '#title' => t('Non-scalar Variables Options'), + ); + + $form['backtrace_options']['non_scalar']['error_backtrace_display_non_scalar'] = array( + '#type' => 'checkbox', + '#title' => t('Include passed values'), + '#default_value' => variable_get('error_backtrace_display_non_scalar', ERROR_REPORTING_DISPLAY_NON_SCALAR), + ); + + $form['backtrace_options']['non_scalar']['error_backtrace_display_non_scalar_call_start'] = array( + '#type' => 'textfield', + '#title' => t('Backtrace start'), + '#default_value' => variable_get('error_backtrace_display_non_scalar_call_start', ERROR_REPORTING_DISPLAY_NON_SCALAR_CALL_START), + '#size' => 4, + '#maxlength' => 4, + '#description' => t('From what depth to start showing non-scalar variables. 1 = the place the error occured.'), + ); + + $form['backtrace_options']['non_scalar']['error_backtrace_display_non_scalar_call_depth'] = array( + '#type' => 'textfield', + '#title' => t('Backtrace depth'), + '#default_value' => variable_get('error_backtrace_display_non_scalar_call_depth', ERROR_REPORTING_DISPLAY_NON_SCALAR_CALL_DEPTH), + '#size' => 4, + '#maxlength' => 4, + '#description' => t('How may calls deep from the starting point to show non-scalar variables.'), + ); + + $form['backtrace_options']['non_scalar']['error_backtrace_display_non_scalar_max_length'] = array( + '#type' => 'textfield', + '#title' => t('Max length'), + '#default_value' => variable_get('error_backtrace_display_non_scalar_max_length', ERROR_REPORTING_DISPLAY_NON_SCALAR_MAX_LENGTH), + '#size' => 10, + '#maxlength' => 10, + '#description' => t('Limit the output size in characters of non-scalar values.'), + ); + return system_settings_form($form); } diff --git a/modules/system/system.test b/modules/system/system.test index 9eaf562..31a37b4 100644 --- a/modules/system/system.test +++ b/modules/system/system.test @@ -114,11 +114,11 @@ class ModuleTestCase extends DrupalWebTestCase { */ function assertLogMessage($type, $message, $variables = array(), $severity = WATCHDOG_NOTICE, $link = '') { $count = db_select('watchdog', 'w') - ->condition('type', $type) + ->condition('type', drupal_substr($type, 0, 64)) ->condition('message', $message) ->condition('variables', serialize($variables)) ->condition('severity', $severity) - ->condition('link', $link) + ->condition('link', drupal_substr($link, 0, 255)) ->countQuery() ->execute() ->fetchField();