Using Strace

== Using strace ===

A guide to reading, interpreting and understanding strace output.

What is strace?

Strace is a program which traces the system calls that a running program makes. It is an extremely useful debugging tool on Linux systems. A system call is a function that asks the kernel to do something (for example to request that a file is opened). By understanding which system calls a program makes, we begin to understand what it is doing; more often we use it to understand why the program fails.

A simple example

It is easiest to explain how to use strace by starting with a simple example. We’ll use the command cat /etc/passwd as an example, since it should behave in a similar way on most Linux installations; namely it should succeed in displaying the contents of the password file. We will enter the command strace cat /etc/passwd >/dev/null, which starts strace and tells it to trace system calls made when cat /etc/shadow is run. The reason for redirecting the standard output to /dev/null is to make sure that the output from cat itself does not get mixed up in the output from strace.

Here’s the output from the command strace cat /etc/passwd >/dev/null on my system:

execve("/bin/cat", [["cat",|"/etc/passwd"]], [[/*|20 vars */]]) = 0 uname({sys="Linux", node="tyler", ...}) = 0 brk(0)                                  = 0x804cd6c old_mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x40017000 access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory) open("/etc/ld.so.preload", O_RDONLY)    = -1 ENOENT (No such file or directory) open("/etc/ld.so.cache", O_RDONLY)      = 3 fstat64(3, {st_mode=S_IFREG|0644, st_size=42247, ...}) = 0 old_mmap(NULL, 42247, PROT_READ, MAP_PRIVATE, 3, 0) = 0x40018000 close(3)                                = 0 access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory) open("/lib/libc.so.6", O_RDONLY)        = 3 read(3, "177ELF111331360^1"..., 512) = 512 fstat64(3, {st_mode=S_IFREG|0755, st_size=1244688, ...}) = 0 old_mmap(NULL, 1254852, PROT_READ|PROT_EXEC, MAP_PRIVATE, 3, 0) = 0x40023000 old_mmap(0x4014b000, 32768, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED, 3, 0x127000) = 0x4014b000 old_mmap(0x40153000, 9668, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x40153000 close(3)                                = 0 munmap(0x40018000, 42247)               = 0 brk(0)                                  = 0x804cd6c brk(0x806dd6c)                          = 0x806dd6c brk(0)                                  = 0x806dd6c brk(0x806e000)                          = 0x806e000 open("/usr/lib/locale/locale-archive", O_RDONLY|O_LARGEFILE) = 3 fstat64(3, {st_mode=S_IFREG|0644, st_size=1837728, ...}) = 0 mmap2(NULL, 1837728, PROT_READ, MAP_PRIVATE, 3, 0) = 0x40156000 close(3)                                = 0 fstat64(1, {st_mode=S_IFCHR|0666, st_rdev=makedev(1, 3), ...}) = 0 open("/etc/passwd", O_RDONLY|O_LARGEFILE) = 3 fstat64(3, {st_mode=S_IFREG|0644, st_size=1460, ...}) = 0 read(3, "root:x:0:0:root:/root:/bin/bash "..., 4096) = 1460 write(1, "root:x:0:0:root:/root:/bin/bash "..., 1460) = 1460 read(3, "", 4096)                       = 0 close(3)                                = 0 close(1)                                = 0 exit_group(0)                           = ?

As you can see, strace produces many lines of output, many of them completely irrelevant. Do not be alarmed; after a little practice it becomes reasonably easy to filter out the lines that are not useful to you. Let’s start by taking a look at the first line and learning a little about what everything means:

execve("/bin/cat", [["cat",|"/etc/passwd"]], [[/*|20 vars */]]) = 0

strace tells us here that the system call execve was executed, the arguments “/bin/cat”, [[“cat”,|”/etc/passwd”]], [[/*|20 vars */]] were passed to it and it returned a value of 0.

This is pretty meaningless unless we know what execve does. In order to find out, we type man 2 execve to read its man page. We should always use man 2 <syscall> because syscalls are documented in section 2 of the manual. If you do not specify section 2, man may find a different page which has the same name, which can be very confusing.

The man page tells us that execve executes a program. If you look at the SYNOPSIS section, you can see that the first parameter is called filename and in the DESCRIPTION section it tells us that the program pointed at by filename will be executed. In the interests of brevity we will ignore what the rest of the parameters do and look instead at what appears at the end of the line from strace.

After the equals sign we see what value the syscall returned. In the case of this line it returned zero. What the return value actually means depends on the syscall. Let’s ignore it for the time being and skip forward 4 lines to the next line of interesting output.

access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)

This is a good example of the kind of noise (non-useful output) that you’ll get using strace. By reading the access(2) man page you can tell that the program is checking the permissions on /etc/ld.so.nohwcap, is getting -1 back, which means an error is encountered. At the end of the line from strace there is a code for the error (ENOENT), followed by some text describing what it means. In fact, by scrolling down to the ERRORS section of the access(2) man page we can see that it means that the file did not exist.

So, does this error mean that we have discovered a problem with cat? No. Looking to see if a file exists (and getting an error because it doesn’t) are perfectly normal things for a program to do. There are many error codes which occur during normal behaviour and ENOENT is a good example.

If you try using strace on almost any other program it will try to access the same file. What is happening here is that the dynamic linker is checking for configuration files. You don’t need to know precisely what that means, but you do need to be aware that it happens and ignore these lines (unless you are trying to diagnose a problem with the dynamic linker).

The line following is very similar, but then we get to:

open("/etc/ld.so.cache", O_RDONLY)      = 3 fstat64(3, {st_mode=S_IFREG|0644, st_size=42247, ...}) = 0 old_mmap(NULL, 42247, PROT_READ, MAP_PRIVATE, 3, 0) = 0x40018000 close(3)      

In these 4 lines, the program:

• Opens the file /etc/ld.so.cache and returns number 3, indicating that file descriptor 3 should be used to do things to that file.

• Gets file status information (see fstat(2)) on file descriptor 3 – the file it just opened.

• Maps the file into memory.
• Closes the file.

You may be wondering why the program doesn’t seem to do anything with the file status or contents – it just opens it, gets some info, maps it and closes it. It almost certainly does perform some action based on the file contents but we do not see this because these actions are not system calls. strace only traces system calls – it cannot tell us everything that a program does. This file in particular is the list of all dynamically linked libraries on the system and it is checked by the dynamic linker when any program runs. So again, it is just noise, as it does not tell us much about how cat works.

In fact, many of the remaining lines can be described as noise of this type, until we get to:

open("/etc/passwd", O_RDONLY|O_LARGEFILE) = 3 fstat64(3, {st_mode=S_IFREG|0644, st_size=1460, ...}) = 0 read(3, "root:x:0:0:root:/root:/bin/bash "..., 4096) = 1460 write(1, "root:x:0:0:root:/root:/bin/bash "..., 1460) = 1460 read(3, "", 4096)                       = 0 close(3)                                = 0

In these lines we can see that /etc/passwd is opened, some data is obtained, then it writes some output to file descriptor 1. We know that some data has been written to standard output, which is always file descriptor 1, for any program. Also observe that strace doesn’t show all the data, but displays … to indicate that there was more data, but it couldn’t fit it all on a line.

So now you’ve come to the end of a simple, but exhaustive example, you should have a basic understanding of how to use strace