jDempster

Using strace to debug PHP

The Problem

Recently I stumbled into an issue with the PHP FTP functions. After successfully connecting to a server and authenticating, fetching a file list using ftp_nlist would return NULL. This isn’t even a return type listed in the manual.

Example

$ftp_server = 'ftp.example.com';

// set up basic connection
$conn_id = ftp_connect($ftp_server) or die("Couldn't connect to $ftp_server\n");

$ftp_user_name = 'user';
$ftp_user_pass = 'pass';

// login with username and password
$login_result = ftp_login($conn_id, $ftp_user_name, $ftp_user_pass) or die("Login failed");

// get contents of the current directory
$contents = ftp_nlist($conn_id, ".");

// output $contents
var_dump($contents);

Why was it failing? It was connecting fine, there where no problems with authenticating.

As a developer getting into this situation is very frustrating. Where do we turn to?

The Solution (strace)

What is strace

One solution is strace (presumably short for “system trace”), a system debugging tool for linux. There are other Unix variants like dtruss and dtrace. In this article we’ll concentrate on strace.

The tool traces system calls and signals made by the process you tell it to trace. The name of each system call, its arguments and its return value are printed on standard error, which isn’t pretty. I find it helpful to output the results to a file (-o filename argument to strace can help), alternatively you can redirect standard error to standard out and pipe the results though grep.

How to use strace

There are two ways you can tell it to trace a process, which depends on if the process is already running or not.

Trace an already running process

Attach to the process with the process ID pid and begin tracing. The trace can be terminated at any time by a keyboard interrupt signal (ctrl-c). strace will detach itself from the process leaving it to continue running. This can be handy to look at what a long running script is currently doing. This includes things like Apache.

// -p pid
$ strace -p 123

Trace a specified command

The other way we can trace something is by telling it the command we want executed and traced. Anything which is not one of its own arguments is the command it will execute, anything after that are arguments to the executing command.

// -e is an argument of strace with the value of open
// -v is an argument of php with no value
$ strace -e open php -v 2>&1 | grep php.ini
// outputs the location of the php.ini file which was loaded

Understanding the output

Running the command:

strace -e open php -v 2>&1 | grep php.ini

Outputs:

open("/usr/bin/php.ini", O_RDONLY|O_LARGEFILE) = -1 ENOENT (No such file or directory)
open("/etc/php5/cli/php.ini", O_RDONLY|O_LARGEFILE) = 3

Here we see that PHP attempted to open two files. One in directory where the binary is, and one in /etc/php5/cli/ this is where PHP has been compiled to look. The first system call failed with No such file or directory.

You can learn more about system calls and their return values from the linux documentation. http://linux-documentation.com/en/man/man2/open.html

Strace & PHP Continued…

Find php.ini

Example Command:

// -e open, trace only the open system call
// -v ask php to show it's version
// 2>&1 redirect stderr to stdout
// | grep php.ini filter the output for the string php.ini
$ strace -e open php -v 2>&1 | grep php.ini
// outputs the location of the php.ini file which was loaded :)

Example Output:

open("/usr/bin/php.ini", O_RDONLY|O_LARGEFILE) = -1 ENOENT (No such file or directory)
open("/etc/php5/cli/php.ini", O_RDONLY|O_LARGEFILE) = 3

php.ini is being loaded from /etc/php5/cli/php.ini

File not loading