8.3 Tracing Program Execution and System Calls
The tools we’ve seen so far examine active processes. However, if you have no idea why a program dies almost immediately after starting up, lsof won’t help you. In fact, you’d have a difficult time even running lsof concurrently with a failed command.
The strace (system call trace) and ltrace (library trace) commands can help you discover what a program attempts to do. Those tools produce extraordinarily large amounts of output, but once you know what to look for, you’ll have more information at your disposal for tracking down problems.
8.3.1 strace
Recall that a system call is a privileged operation that a user-space process asks the kernel to perform, such as opening and reading data from a file. The strace utility prints all the system calls that a process makes. To see it in action, run this command:
$ strace cat /dev/null
By default, strace sends its output to the standard error. If you want to save the output in a file, use the -o save_file option. You can also redirect by appending 2> save_file to your command line, but you’ll also capture any standard error from the command you’re examining.
In Chapter 1, you learned that when one process wants to start another process, it invokes the fork() system call to spawn a copy of itself, and then the copy uses a member of the exec() family of system calls to start running a new program. The strace command begins working on the new process (the copy of the original process) just after the fork() call. Therefore, the first lines of the output from this command should show execve() in action, followed by a memory initialization call, brk(), as follows:
execve("/bin/cat", ["cat", "/dev/null"], 0x7ffef0be0248 /* 59 vars */) = 0
brk(NULL) = 0x561e83127000
The next part of the output deals primarily with loading shared libraries. You can ignore this unless you really want to dig deep into the shared library system:
access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or
directory)
openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=119531, ...}) = 0
mmap(NULL, 119531, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7fa9db241000
close(3) = 0
--snip--
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\260\34\2\0\0\0\0\0"..
., 832) = 832
In addition, skip past the mmap output until you get to the lines near the end of the output that look like this:
fstat(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(0x88, 1), ...}) = 0
openat(AT_FDCWD, "/dev/null", O_RDONLY) = 3
fstat(3, {st_mode=S_IFCHR|0666, st_rdev=makedev(0x1, 3), ...}) = 0
fadvise64(3, 0, 0, POSIX_FADV_SEQUENTIAL) = 0
mmap(NULL, 139264, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) =
0x7fa9db21b000
read(3, "", 131072) = 0
munmap(0x7fa9db21b000, 139264) = 0
close(3) = 0
close(1) = 0
close(2) = 0
exit_group(0) = ?
+++ exited with 0 +++
This part of the output shows the command at work. First, look at the openat() call (a slight variant of open()), which opens a file. The 3 is a result that means success (3 is the file descriptor that the kernel returns after opening p. 204 the file). Below that, you can see where cat reads from /dev/null (the read() call, which also has 3 as the file descriptor). Then there’s nothing more to read, so the program closes the file descriptor and exits with exit_group().
What happens when the command encounters an error? Try strace cat not_a_file instead and examine the open() call in the resulting output:
openat(AT_FDCWD, "not_a_file", O_RDONLY) = -1 ENOENT (No such file or
directory)
Because open() couldn’t open the file, it returned -1 to signal an error. You can see that strace reports the exact error and gives you a short description of the error.
Missing files are the most common problem with Unix programs, so if the system log and other log information aren’t very helpful and you have nowhere else to turn when you’re trying to track down a missing file, strace can be of great use. You can even use it on daemons that fork or detach themselves. For example, to track down the system calls of a fictitious daemon called crummyd, enter:
$ strace -o crummyd_strace -ff crummyd
In this example, the -o option to strace logs the action of any child process that crummyd spawns into crummyd_strace.pid, where pid is the process ID of the child process.
8.3.2 ltrace
The ltrace command tracks shared library calls. The output is similar to that of strace, which is why it’s being mentioned here, but it doesn’t track anything at the kernel level. Be warned that there are many more shared library calls than system calls. You’ll definitely need to filter the output, and ltrace itself has many built-in options to assist you.
See Section 15.1.3 for more on shared libraries. The ltrace command doesn’t work on statically linked binaries.