Third & GroveThird & Grove
Apr 30, 2015 - Justin Emond

Five best practices to debug Drupal

The Drupal watchdog() function is the primary method of debugging your application.

1. Actually understand the watchdog() function

Seriously, go read the API documentation on the function. I'll wait.

OK, do you see it? The watchdog() function doesn't actually log anything at all. It may seem bonkers, but it's actually very well designed. The whole point of the watchdog() function is to provide a single function that every Drupal module can call as needed, regardless of where logs are being stored, how logs are being processed, or if logging is actually happening at all.

The watchdog() functions only purpose is to add some information to the log entry (like time and IP address) and pass that along to any module that invokes hook_watchdog(). These are the modules that actually do something with the log information. In most Drupal sites the dblog module is enabled. This module invoked hook_watchdog() and writes the log data to the database.

Other contrib modules invoke hook_watchdog() and write the log data to lower-level server log files or custom backend logging facilities.

2. Include debugging logic in your custom code from day 1

A best practice for Drupal custom module development in general is to log debugging information even when you aren't sure if you will need it (you will, trust me). If you don't include this from the start, you will be without the tools you need to debug the site when your code is in production.

When should you call watchdog? A good rule of thumb is anytime you interact with a third-party system via an API (think cURL calls), log the request and response.

3. Namespace your watchdog() calls

Drupal's modular architecture is how Drupal remains powerful yet flexible content management framework. However, given that a Drupal site is potentially a collection of modules you have no way to predict, namespacing is very important in module names, variables, database table names, View names, Panel names, and even watchdog() calls.

Luckily the watchdog() function's first parameter is for this purpose:

 

$message = 'Gateway was used by user @name with data: <pre>@data</pre>';
$variables = array('@name' => $account->name, '@data' => print_r($package, TRUE));
watchdog('mymodule', $message, $variables, WATCHDOG_NOTICE);

 

Namespacing your log entries will make it easy for developers to know what module this log message relates and allow log streams to be live filtered.

4. Concerned about verbosity? Drupal variables to the rescue!

If you are concerned that you might be logging too much information (think massive response payloads on chatty APIs) wrap the watchdog call in a variable_get() call, like:

 

if (variable_get('my_module_api_debug', FALSE)) {
  watchdog('mymodule_api', $message, $variables, WATCHDOG_NOTICE);
}

 

The second parameter of variable_get() is the default value to return if the variable doesn't exist. The best part about this code is you don't need to define this variable when you push your module. When you encounter a production issue and you need the logs simply use the magic of Drush aliases to set this variable to enable logging. No code push needed! When it's time to turn off the logging simple use Drush to disable the variable.

5. Don't use t() with watchdog()

It's tempting to use t() for the $message parameter of watchdog since you are writing text that needs to be translated. Resist the urge! The watchdog() function is one of the few places in Drupal where you think you should use t() but you shouldn't (hi hook_menu()!).

Why shouldn't you cal t()? Because translation occurs at the output of log files, not input, so later translation is possible. Translation occurs in the theme function the powers the recent log screen of Drupal: theme_dblog_message().