Debugging using debug_backtrace

    See more
    • Created

    Issue

    How do I debug PHP issues in my Drupal site?

    Resolution

    Debugging PHP issues in a Drupal website can be anything from quick and easy to seriously problematic. PHP includes a debugging function called debug_backtrace , which will print out the chain of code that leads up to the point where the backtrace function is called.

    Imagine the following scenario: when you load a page, you may see an error message that looks like this:

    warning: Invalid argument supplied for foreach() in /modules/field/field.module on line 966.

    However. it is really next to impossible to know what is wrong with just the above error message. One way to determine the cause of this error, could be to add debugging code to the problem file within Drupal:

     

    1. In your docroot, open the file in question. In the preceding example, it is the file /modules/field.module.
    2. Navigate to the line number in the error message.
    3. Add the following code at the top of the function: 
      var_dump(debug_backtrace()); die();

    This will display all of the PHP functions and their arguments that called the function you are in. Usually, the technical output in the backtrace will give you a good indication of which module or function is causing the error.

    Another option: using a debug_backtrace wrapper

    The following code is a wrapper for debug_backtrace() that generates a more human-readable version than the method described above. It also logs the output to a file, along with a timestamp and other useful information.

    This code needs to be available to Drupal, so you should either add it to your settings.php file, or place it into a custom module. Whenever you call this function from your code, it appends output to a debug.log file in the /mnt/tmp/[sitename]/ directory, where [sitename] is the name of your docroot. The output traces each call with a timestamp. This enables you to see how long each step takes to complete. From there, you should be able to step backwards through the calls to figure out where the problem is.

    Download this file

    <?php
/**
 * Acquia Debug function. This logs a backtrace and an optional message into a logfile
 * which will be helpful for debugging.
 * INSTALLATION: 
 *   Place this at the end of your settings.php file. 
 *   You can alter the ACQUIA_DEBUG_LOG constant to your preferred path.
 * USAGE: 
 *    You can call acquia_debug() with an optional message.
 *    Example:
 *       acquia_debug("Debug message 1");
 *       acquia_debug("Contents of $this:" . var_export($this, true));
 *    The output is as follows:
 *      [{process_id} - {internal_counter} - {timestamp}] {URL-if-http-request} : [backtrace...]
 *      {optional message}
 * SAMPLE OUTPUT:
 *   mysite@ded-1234:/var/www/html/mysite.dev/docroot$ drush ev 'acquia_debug("Hello World!");'
 *   mysite@ded-1234:/var/www/html/mysite.dev/docroot$ tail -3 /mnt//tmp/[sitename]/acquia_debug.log 
 *   [22872 - 1 - 1414074029.736] : [drush.php 16] drush_main()  -->  [drush.php 61] _drush_bootstrap_and_dispatch()  -->  [drush.php 92] drush_dispatch()  -->  [command.inc 182] call_user_func_array()  -->  drush_command()  -->  [command.inc 214] _drush_invoke_hooks()  -->  [command.inc 362] call_user_func_array()  -->  drush_core_php_eval()  -->  [core.drush.inc 1100] eval()
 *    Hello World!
 */
define('ACQUIA_DEBUG_LOG', '/mnt/tmp/' . $_ENV['AH_SITE_NAME'] . '/acquia_debug.log');
function acquia_debug($message = '') {
  static $count = 0;
  $count++;
  $time = round(microtime(TRUE), 3);
  $request_string = '[' . getmypid() . " - $count - $time] ";
  $request_string .= php_sapi_name() != 'cli' ? "{$_SERVER['REQUEST_METHOD']} {$_SERVER['REQUEST_URI']}" : '';

  $things = func_get_args();
  $backtrace = debug_backtrace();
  $first = array_shift($backtrace);
  $file_info = isset($first['file']) ? '[' . basename($first['file']) . ' ' . $first['line'] . '] ' : '';
  $temp_backtrace[] = $file_info . (isset($first['class']) ? $first['class'] . $first['type'] : '') . $first['function'] . '()';
  foreach ($backtrace as $trace) {
    $file_info = isset($trace['file']) ? '[' . basename($trace['file']) . ' ' . $trace['line'] . '] ' : '';
    $temp_backtrace[] = $file_info . (isset($trace['class']) ? $trace['class'] . $trace['type'] : '') . $trace['function'] . '()';
  }
  array_shift($temp_backtrace);
  $message = implode("  -->  ", array_reverse($temp_backtrace)) . "\n";

  foreach ($things as $thing) {
    switch (gettype($thing)) {
      case 'object':
      case 'array':
        $message .= print_r($thing, TRUE);
        break;
      case 'resource':
        break;
      default:
        $message .= $thing . "\n";
    }
  }
  file_put_contents(ACQUIA_DEBUG_LOG, "$request_string: $message\n", FILE_APPEND);
}

    Example: logging calls to variable_set() in Drupal 7

    variable_set can sometimes be bad for general website performance (see The innocuous variable_set .) One use case for the acquia_debug() function is to find out what is calling it. In the following code snippet, a call to acquia_debug() has been added inside the variable_set() function:

    The following code is an example of the problematic use of variable_set, and can have a major impact on cache and database performance. Adding the acquia_debug() call to it results in a log in your /mnt/tmp/[sitename]/acquia_debug.log file.

    
function variable_set($name, $value)   { 
     global $conf;
     db_merge('variable')->key(array('name' => $name))->fields(array('value'=>serialize($value)))->execute(); 
     acquia_debug("MESSAGE: variable_set($name, ...) called."); 
     cache_clear_all('variables', 'cache_bootstrap'); 
     
     $conf[$name] = $value;
   }

    After this code is added and a problem page is loaded, the log file should contain some useful information, which should look similar to this:

    
[ pid=4413 | count=1 | time=1425487626.026 ] GET /admin/config/administration/admin_menu [index.php 21] menu_execute_active_handler() --> [menu.inc 532] drupal_deliver_page() -->[common.inc 2557] drupal_deliver_html_page() --> [common.inc 2669] drupal_render_page() --> [common.inc 5757] drupal_render() --> [common.inc 5910] theme() --> [theme.inc 1122] template_process_html() --> [theme.inc 2631] drupal_get_js() --> [common.inc 4267] drupal_alter() -->[module.inc 1101] locale_js_alter() --> [locale.module 929] _locale_invalidate_js() --> [locale.inc 1993] variable_set() variable_set(javascript_parsed, ...) called.

    where

    • pid is your PHP process ID
    • count is the amount of calls to acquia_debug() so far in the current request.
    • time is the UNIX timestamp (including milliseconds)
    • GET [...] is the actual request URL that generated this log line.

    Closing notes

    An alternative to modifying core and adding code is to use Xdebug. We document two methods of using Xdebug here:

    Generally, you can assume that Drupal core will not cause PHP errors like this. These errors most likely originate from a contributed module, website-specific code in a theme template, or a custom module. We hope the above options we've discussed here can help you get started in troubleshooting tough problems.

    Topics

    Related articles