Basics

Debugging of Drupal was never easy, until you know the right tools and how to use them.

There are plenty of alternative debugging methods using some popular PHP libraries XDebug, XHProf, NuSphere PhpED, etc. and also most of the IDE have already built-in step-by-step debugger.

Disadvantages of debugging using PHP libraries and IDE

What are the disadvantages of using PHP libraries or IDE? Basically performance and time consuming configuration. But if the problem is happening on production or staging server (of course you don't have access to your favourite IDE),  you need to react very fast (before clients will find out:) and by installing PHP debuggers on your production environments it could cause even more problems than good (it could affect different live sites, performance, downtime). Alternatively you can download the database and reproduce it on your local environment, but if the database is too big it could take ages. If you're debugging on your local, usually you don't want to spend hours of configuring different extensions (it's easier when using already configured LAMP). Other thing is to mention that some problems are caused only on specific environments and would be not to able to reproduce it on your local machine.

Strace

Strace is a debugging utility for Linux and some other Unix-like systems to monitor the system calls used by a program and all the signals it receives. On Unix you can use truss, on Mac you can use dtruss.

You can install strace by: sudo apt-get install strace or any other package manager which you have.

On Windows Xp and earlier you can use StraceNT (System Call Tracer) which Windows equivalent of strace. See this stackoverflow article for newer tracing and event monitoring tools for Windows Vista and 7.

On OS X you can use dtrace/dtruss.

Tcpdump

Tcpdump is a popular network packet analyzer that runs under the command line. It's included in most of the *nix like distributions.

To use it on Windows you can install Cygwin environment.

 

Debugging

Let's start by some examples.

Debugging Apache process

Using strace to debug Apache requests

You can use strace to attach to any running process or even processes (up to 32) and follow all the threads. Usually Apache has different instances and each request is redirected to child process, so to attach our debugger to Apache process, we need to know all PIDs which it's using. The following command should returns all used Apache PIDs:

$ ps wuax | grep apache | grep -v grep | awk '{print $2}' | xargs
1699 2217 2249 2645 6215 7165 9548 9641 14703 14712 18611

So now we can start tracing our web requests by executing the following command:

On OS X you can simply run: sudo dtruss -fn httpd

sudo strace `ps wuax | grep apache | grep -v grep | awk '{print "-p" $2}' | xargs`

It will attach and trace all Apache processes and dump everything what's actually happening on the fly. Pressing Control-C it will stop the strace.

Each line is the system call which are called by a process and the  signals  which are received by a process. More information you can find in strace manual (command: man strace).

So how do we know which request is which? We don't know.

But filtering our results we can guess.

Filtering strace results

By filtering our strace results, we can see more specific details. For filtering you can use different tools like grep, sed or cut.

The following command will filter all requests to Drupal module files:

sudo strace -e trace=file -o/dev/stdout -f `ps wuax | grep apache | grep -v grep | awk '{print "-p" $2}' | xargs` | grep -w module

If you execute this command, it will listen for all Apache requests, so go to your local website and open any request to see any strace output.

If you want to include PHP files, you can extend it by:

sudo strace -e trace=file -o/dev/stdout -f `ps wuax | grep apache | grep -v grep | awk '{print "-p" $2}' | xargs` | grep -we module -e inc -e php

You can customize the last extensions to include images, css, javascript or whatever files you need.

After execution we should see some output like:

14712 access("modules/system/page-home.tpl.php", F_OK) = -1 ENOENT (No such file or directory)
14712 access("sites/all/modules/modalframe/page-home.tpl.php", F_OK) = -1 ENOENT (No such file or directory)
14712 stat("./sites/all/themes/fusion/page.tpl.php", {st_mode=S_IFREG|0664, st_size=4831, ...}) = 0

It will give us the idea of all PHP files which are accessed by Apache.

How does it help?

Using strace results to find file which caused problem (WSOD, redirect, Page not found, etc.)

By analysing all the requests to our files (using above commands), we can easily find our last accessed file, so in case if we are diagnosing the problem of some kind of WSOD, you should know at least in which file or module it happened.

Using tcpdump to debug Apache requests

Using tcpdump, you can analyse the results of actual network communication. It's useful when you trying to find out more information about cookies sent, headers, content of the page, Apache solr requests or other external requests. More information about the usage you can find in tcpdump manual (command: man tcpdump).

Here is example of dumping everything which is sent or received on port 80 (www):

sudo tcpdump -i lo -nl -s0 -w- port www | strings -n8

But these results needs to be filtered. In example, here you have example of dumping all Apache requests in real time:

sudo tcpdump -i lo -nl -s0 -w- port www | strings -n8 | grep -C1 -e ^GET -e ^POST

Where lo is you local network interface (you can use: -i any to listen on all network interfaces).

Example output:

Keep-Alive: timeout=5, max=83
GET /sites/all/themes/fusion/css/new/img/logo.png?d=0 HTTP/1.1
Host: localhost 
-- 
Cache-Control: max-age=0 
GET /sites/all/themes/fusion/css/new/img/sprites.png 
HTTP/1.1 Host: localhost

To dump all the headers (including Cookies and posted data), you can change the filter by:

sudo tcpdump -i lo -nl -s0 -w- port www | strings -n8 | grep -C1 ':'

Which filtering by ":", which is the character used in most of the headers.

Or you could filter requests by specific file types like:

sudo tcpdump -i lo -nl -s0 -w- port www | strings -n8 | grep -E "(GET|POST).*(js|css|misc|ico|png|jpg|gif)"

Debugging database queries (MySQL, etc.)

Using strace to debug database queries (MySQL, PostgreSQL, etc.)

You can use strace also to debug database queries, so instead of file tracing, you can use write operations filtering by common query keywords, like:

sudo strace -s1000 -e trace=write -o/dev/stdout -f `ps wuax | grep apache | grep -v grep | awk '{print "-p" $2}' | xargs` | grep -E "(SELECT|INSERT|UPDATE|DELETE)"

Using tcpdump to debug MySQL queries

You can analyse database queries being sent to MySQL server by the following command:

sudo tcpdump -i lo -s0 -nl -w- dst port mysql | strings -n8

Example output:

/* admin : user_load */ SELECT * FROM users u WHERE uid = 1 
/* admin : user_load */ SELECT r.rid, r.name FROM role r INNER JOIN users_roles ur ON ur.rid = r.rid WHERE ur.uid = 1 

You can use with different type of databases, just check in /etc/services which port or name it's using.

Using tcpdump to debug PostgreSQL queries

As above:

sudo tcpdump -i lo -s0 -nl -w- dst port postgres | strings -n8

Debugging drush

Debugging drush have more benefits, because you don't need sudo access to trace it (in case when you don't have root access) and also you don't have to trace all the apache processes or network adapters, just the plain command line.

When using drush, there is no really one command to simulate specific page request, but you can use PHP code to achieve that.

Here is some simple example:

strace -s1000 drush eval "menu_execute_active_handler('node');"

Where node is the page which you're trying to open. Or you can use any function you want which you want to debug it.

Debugging Simpletests

Analysing and fixing simpletests was always tricky based on some limitations and further more on internal browser.

The easiest way is to do some stop points with printing the information to the file like:
file_put_contents('files/simpletest.log', __FUNCTION__ . '(): Path: '. $this->getUrl() . ';\n", FILE_APPEND);

But how do we know where to put the debug points, if we're looking something that breaks, but we don't know where to look for and what's actually happening.
You can of course use the same methods described above using apache tracing, but lets choose the command line of course.

To run simpletest in drush, you have to run as Apache user to have write access to our file system.
How do I know which username is my Apache user?
It's easy!
stat -c %U `drush eval "echo DRUPAL_ROOT"`/`drush vget file_directory_path | cut -d\\" -f2`

So the full command to debug our Simpletest is:

sudo -u www-data strace -e trace=open,write -s100 -f drush -y -l http://default test-run --all --dirty

Where www-data is your Apache user and http://default is your address of your website. To not remove simpletest tables after the test, we use --dirty parameter. To follow child processes we use -f parameter.

You can customize the output and formatting by reading the next section.

Hints and tricks using strace

Filtering the results

Filtering the results using '-e trace'

You can use -e parameter to choose in which kind of data are you interested or you can mix them together (with comma).

Here are some hints:

-e trace=write - tracing all data written to file descriptors (mostly used for database queries (MySQL),

-e trace=open - trace all system calls which opening the files (mostly used for checking file includes)

-e trace=file - trace all system calls which take a file name as an argument (mostly used for checking file operations)

-e trace=network - trace all the network related system calls (mostly used to debug network issues)

-e trace=read - tracing all data read from file descriptors (mostly used to trace incoming data from files, database, etc.),

See: man strace for more options

Showing the full length

You can use -s parameter to specify the maximum string size to print. If you have long queries or code dumps, use e.g. 10000, to not miss anything:)

Filtering the results using grep

By default strace dumping the results to standard error output, to change it you have to use -o parameter to redirect it to the standard output (or you can use 2>&1 redirect after the command). Also you can use -C to include number of lines of output context (to see what was before that line).

In the following example we're looking all kind of errors and watchdog stuff on our front page:

strace -s1000 -o /dev/stdout drush eval "menu_execute_active_handler('node');" | grep -C2 -e error -e watchdog

Or:

strace -s1000 drush eval "menu_execute_active_handler('node');" 2>&1 | grep -C2 -e error -e watchdog

Formating the output

Sometimes if you want to have clean output or if you're annoyed with nulls or function displayed on every query, you can add the sed and cut filter at the end of the query, example:

strace -f -o /dev/stdout -e write -s1000 drush eval "print menu_execute_active_handler('node');" | sed 's@\\[0-9]*@@g' | cut -d' ' -f2-

 

Extras

Simpletest testing script

Here is the script which you can use to run or debug SimpleTests tests:

#!/bin/sh
# @file: run_tests.sh

# Variables
DEBUG="strace -fe write -s100 "
FILTER="sed 's@\\\\[0-9]*@@g' | cut -d' ' -f2-"

# Sudo requirement
echo Checking the environment...
sudo uname -a

# Check the arguments
if [ "$1" = "debug" ]; then
  PREFIX="$DEBUG"
  which strace || sudo apt-get install strace
else
  echo "Hint: you can use: '$0 debug' command to debug tests using strace."
fi
if [ -n "$2" ]; then
  TESTS=$2
else
  echo "Hint: you can use: '$0 run testMyTest' command to run a specific test."
  TESTS="--all"
fi

# Detect Drupal root
DRUPAL_ROOT="`drush status "Drupal root" | awk '{print $NF}' | head -n1`"
FILES_DIR="files"

# Change it to your proper apache user
APACHE_USER="`stat -c %U $DRUPAL_ROOT/$FILES_DIR`"

# Trying to detect last used vhost based on the latest watchdog entry
VHOST="`drush sqlq "SELECT location FROM {watchdog} ORDER BY wid DESC LIMIT 1" | tail -n1 | cut -d/ -f1-3`"

# drush command
DRUSH="drush -y -l $VHOST"

echo "Drupal root:  " $DRUPAL_ROOT
echo "Files dir:    " $FILES_DIR
echo "Apache user:  " $APACHE_USER
echo "Virtual host: " $VHOST
echo "Drush cmd:    " $DRUSH
echo "PHP:          " $(php -v)

echo Running tests...
set -o xtrace
drush -y en simpletest simpletest_clone
chdir "$DRUPAL_ROOT"
sudo -u $APACHE_USER $PREFIX $DRUSH test-run $TESTS --dirty
set -o xtrace -

echo "Cleaning temporary tables and files..."
sudo -u $APACHE_USER $PREFIX $DRUSH test-clean
echo "$0 done."

Usage:

./run_tests.sh - run all tests

./run_tests.sh debug - debug all tests using strace

./run_tests.sh run Block - run tests within specified group

./run_tests.sh debug Block - debug tests within specified group using strace

Support

If you've still some problems with Drupal, you may consider asking at Drupal Answers.

Comments

kurtfoster’s picture

Under the heading Using strace to debug Apache requests, you need a new line after xargs, at the moment it look like it's one command rather than the 1699 2217 ... etc being the output from the command.

ps wuax | grep apache | grep -v grep | awk '{print $2}' | xargs 1699 2217 2249 2645 6215 7165 9548 9641 14703 14712 18611  

Should be

$ sudo strace `ps wuax | grep apache | grep -v grep | awk '{print $2}' | xargs | sed 's/\([0-9]*\)/\-p \1/g' `

1699 2217 2249 2645 6215 7165 9548 9641 14703 14712 18611

kenorb’s picture

@kafmil Thanks for suggestion, I've updated it.