Debugging in Drupal

Debugging in Drupal

Gergely Lekli's picture

Debugging is an integral part of any development process, and the time it requires tends to add up to a significant part of the total development time. Therefore, it is wise to consider various debugging tools and select the one that fits your working habits and conditions best to save time.

Among the aspects of debugging, logging debug messages is the one that I believe is most relevant in Drupal development. In this post, I am reviewing three different options to log events or messages in Drupal.

Printing log messages on the web page

Let me start with the simplest and most trivial one: using drupal_set_message() to print debugging data on the page. Normally used to show messages to the user, this function is perfectly suitable for debugging. By invoking this function with the log message as its first parameter, it will print the message in the Drupal message area when the page is reloaded.

For example, you can use this to check whether a certain part of the code gets executed. If you also need to check the content of a variable, you can use this function to print the variable. One thing to keep in mind is that the function takes a string as its parameter. If you need to print a more complex variable – an object or an array -- it needs to be converted to a human readable format using print_r(), as the following excerpt illustrates. The second parameter of print_r() tells it to return the output as opposed to printing it out directly.

drupal_set_message(print_r($my_var, TRUE));

Because this function takes part in Drupal’s page rendering process, there are certain pitfalls to using it for debugging. Here are some pitfalls I have experienced:

  • It is not suitable to debug cached pages. Calling drupal_set_message() prevents the page from being served from cache or being saved to cache. This has rarely been a problem for me, but it is good to be aware of.
  • It might be cumbersome to investigate large objects and arrays. If you try to print out something as huge as a view object, for example, the page will load slowly, and the printed variable will not be easily readable due to the limitations of the page width.
  • It is too late to call drupal_set_message() in template files. If you do so, the message will only appear after one extra page reload.
  • Messages are not persistent. If the output is data that you will need in the future, be sure to copy it somewhere else.

If you use this method, you can make good use of the Devel module as well, which defines a wrapper function around drupal_set_message(). With Devel module, you can just type dpm() instead, and this function can handle objects and arrays directly – in addition to being easier to type. Furthermore, it prints objects and arrays with the Krumo debugging tool, which prints complex variables in a collapsible structured way, making it easier to handle.

An alternative to drupal_set_message() would be to print the message directly using print or echo. This way, we would not be interfering with Drupal’s page rendering process. However, these messages could be sent to the browser right in the middle of the page rendering process, whereas Drupal normally renders everything first and sends the entire output to the browser at once. As a result, the printed message will appear at unpredictable locations on the page with an unpredictable formatting.

Saving to the database

Drupal provides the watchdog() function to log debug messages to the database. Everything passed to it will be saved in the watchdog table, along with additional data regarding the page request, like the requesting user and url. Similarly to drupal_set_message(), watchdog() takes a string, so objects and arrays need to be sent through print_r().

This method does not interfere with the page rendering process, so it might be preferred in some cases. Messages can be viewed on Drupal’s admin interface at admin/reports/dblog. One downside is somewhat inconvenient to access the data. On the log page, you only see a list of entries, but not the actual message. To see the message, you need to click on the entry to load a new page with the message.

There is a module that makes this process one step easier. The Devel Debug Log module (which was authored by myself) provides a page that displays an auto-refreshing list of recent entries. It relies on Devel and uses its Krumo tool to print complex variables.

Of course, this method is not useful for troubleshooting database related bugs.

Saving to a file

I consider this the most versatile form of logging messages. It does its job independently of the Drupal ecosystem, and has no prerequisites, like saving to the database necessitates a working database connection. You only need to be certain that write permission is set on the output file.

To log messages to a file, create a simple function containing only the few lines shown in the snippet below. From then on, log_to_file($message) can be called to log a message. This, by the way, can be used on any PHP-based site, and not just Drupal.

function log_to_file($text) {
  $f = fopen('my_log.txt', 'a');
  fwrite($f, date('Ymd H:i:s - ') . $text . "\n");
  fclose($f);
}

The example function also prepends the current time to the message so that it is easier to identify various entries.

The part I like most about this method is that one can open a console window and use the tail command to view the file’s contents such that new content is continuously being displayed as anything is written to the file. The actual command to do this is as follows:

tail –f my_log.txt

The excellent Devel module implements this method also. One can use its drupal_debug() function out of the box, without having to write any functions.

Comments

Hi,
Thank you for the article.

I am curious, why you didn't mention using a standard source code debugger (E.G. something like xdebug for php and firebug/webkit inspector for javascript/css/local storage, etc.)? Regular, full featured source code debuggers have been standard programmer's tools for decades. Why not mention them?

How do you debug process with a static log message? For example, a call to the database is not returning expected results. You don't know where in the call stack the issue is occurring. With a standard debugger, you set a breakpoint in your code and trace the process till the database call is made. No guessing involved. A standard debugger allows you to follow the process. With a static log message, how do you know where in the processing sequence the issue is occurring. Isn't that why standard debuggers were invented? Why reinvent the wheel?

A standard debugger also does not require you to add unnecessary source code statements. You set a breakpoint, or, you set a watch.

Google bundles a normal source code debugger with it's Chromium web browser. Do you recommend folks use that debugger? Or do you recommend the same technique of printing data structure dumps?

Again. really curious. Why not use a normal debugger??

I look forward to your answer.
Thank you :)

Gergely Lekli's picture

Hi John,

Thank you for your valuable feedback, and for pointing this out.

I am not suggesting against using debuggers at all. Debuggers can indeed go much further than logging messages. Nevertheless, this article was intended to focus on ways to achieve this particular goal - in case this is what the reader is looking for.

I wrote a very similar module called Object Log for the same purpose -

http://drupal.org/project/object_log

The approaches are quite different, though, and I think each approach is useful in different cases. Let me know if you're interested in joining forces.

<code>fwrite($f, date('Ymd H:i:s - ') . $t . "\n");</code>

or

<code>fwrite($f, date('Ymd H:i:s - ') . $text . "\n");</code>

Cheers for the article.

Gergely Lekli's picture

Ah, yes. Evidently, the article itself has not been debugged. Thank you.

I use sometime the php function debug_backtrace. Used with dpm(), you can display the full function call stack http://php.net/manual/en/function.debug-backtrace.php usefull when you need to know which previous function is called and manipulate the data you receive

Thx for your article.

Great article! You should try the devel Drupal module. It adds a ver handy function: kpr(). You can get an idea of how it looks like here: http://zugec.com/drupal/replacement-for-printr .

Instead of drupal_set_message(print_r($my_var, TRUE)); you can just use dpm($my_var); .You need to install Devel.

Post new comment

About Urban Insight

We create elegant, mobile-friendly websites.

We solve complex problems using Drupal and open source software.

Learn More

Snippet

onScreen is a jQuery plugin to detect whether an element is currently visible on-screen. It adds the :onScreen selector which you can use like so: $("span:onScreen").
http://benpickles.github.com/onScreen/