Debugging with strace

Dig Deep

© Stephen Mcsweeny, 123RF

© Stephen Mcsweeny, 123RF

Article from Issue 105/2009
Author(s):

After "Hello World," you really need to look at system calls in more detail. In this second of two articles, we'll look at debugging in the real world.

An article in the June issue [1] explored the very useful system call tracer strace [2]. Strace helps you hunt down the source of problems with home-grown apps or buggy open source programs that won't quite work on your system. In this article, I take a closer look at how to interpret some of the system call information discovered through strace and describe some ways to make strace more useful in practical situations.

Hello Again!

In the previous article, I introduced the simple test program shown in Listing 1. To run strace on this program and send the output to a file, I typed:

strace -o outputfile.txt helloworld.c

The strace output for Listing 1 is shown in Listing 2. A close look at a couple of lines in the output will give you some insights into how Linux deals with files and memory.

Listing 1

helloworld.c

01 #include<stdio.h>
02
03 main()
04 {
05     printf("Hello World");
06 }

Listing 2

Complete strace for helloworld.c

01 execve("./helloworld", ["./helloworld"], [/* 20 vars */]) = 0
02 uname({sys="Linux", node="the.earth.li", ...}) = 0
03 brk(0)                                  = 0x501000
04 access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
05 mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2afb0be09000
06 access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
07 open("/etc/ld.so.cache", O_RDONLY)      = 3
08 fstat(3, {st_mode=S_IFREG|0644, st_size=43270, ...}) = 0
09 mmap(NULL, 43270, PROT_READ, MAP_PRIVATE, 3, 0) = 0x2afb0be0b000
10 close(3)                                = 0
11 access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
12 open("/lib/libc.so.6", O_RDONLY)        = 3
13 read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\200\305"..., 640) = 640
14 lseek(3, 624, SEEK_SET)                 = 624
15 read(3, "\4\0\0\0\20\0\0\0\1\0\0\0GNU\0\0\0\0\0\2\0\0\0\6\0\0\0"..., 32) = 32
16 fstat(3, {st_mode=S_IFREG|0755, st_size=1286104, ...}) = 0
17 mmap(NULL, 2344904, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x2afb0bf0a000
18 mprotect(0x2afb0c02b000, 1161160, PROT_NONE) = 0
19 mmap(0x2afb0c12b000, 98304, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x121000) = 0x2afb0c12b000
20 mmap(0x2afb0c143000, 14280, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x2afb0c143000
21 close(3)                                = 0
22 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2afb0c147000
23 mprotect(0x2afb0c12b000, 86016, PROT_READ) = 0
24 arch_prctl(ARCH_SET_FS, 0x2afb0c1476d0) = 0
25 munmap(0x2afb0be0b000, 43270)           = 0
26 fstat(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 51), ...}) = 0
27 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2afb0be0b000
28 write(1, "Hello World", 11)             = 11
29 munmap(0x2afb0be0b000, 4096)            = 0
30 exit_group(11)                          = ?

/etc/ld.so.nohwcap

In Listing 2, notice that the program tries to access /etc/ld.so.nohwcap without success. For instance, line 11 provides the message:

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

In this case, the problem is pretty hard to track down because /etc/ld.so.nohwcap is an under-documented file. This step reveals what sorts of libraries the linker looks for.

If /etc/ld.so.nohwcap is present, the linker loads the non-optimized version of a library (i.e., not optimized for your particular hardware). If it's not present, the linker will go looking for the hardware-optimized version.

For more information on ld.so, you can check out the man page, but basically it's responsible for loading all shared libraries, preparing a program to run, and running it. Any Linux program will need ld.so to do its thing before it can run, unless it has been linked statically.

Sandboxes and Pointers

One of the great things about Linux is how well documented the system calls are. From the man pages, you can get information on any of the functions you see in strace output with man functionname or man 2 functionname. The documentation makes it easy to learn a lot just by looking at strace output.

User programs on a modern system run in a little sandbox: They're not permitted to interact directly with the computer (so you can't just shove numbers into registers to make things happen, as you could 20 years ago). Instead, everything goes through the kernel, and strace traces these messages to the kernel. If you don't see any strace output for a bit, it doesn't necessarily mean that your program is stuck; it might be doing stuff within its own sandbox (e.g., calculations) that doesn't require it to talk to the kernel.

System calls often use pointers to data structures. A pointer is a memory reference that tells the system where to look in memory to find a particular piece of information. If you were a computer, this would be great, but it's not so good when you're a human, because digging around in memory isn't easy. When strace sees a pointer, instead of giving you the value of the pointer, it does the lookup for you and returns the contents of that pointer so that you're shown the actual data. When you're reading man pages and it talks about a pointer to a data structure or a pointer to a buffer, remember that what you see in the strace output is the contents of that data structure.

Files and Memory

As you might have noticed when first looking at the output for this program, one of the lines that comes up quite frequently is mmap. The mmap call is responsible for mapping files or devices into memory. Look at how an mmap call is structured in Listing 3, for example.

Listing 3

mmap Call

01 open("/etc/ld.so.cache", O_RDONLY)      = 3
02 fstat(3, {st_mode=S_IFREG|0644, st_size=43270, ...}) = 0
03 mmap(NULL, 43270, PROT_READ, MAP_PRIVATE, 3, 0) = 0x2afb0be0b000

Before the mmap call, the output shows that the /etc/ld.so.cache file has opened successfully with a file descriptor of 3.

Then there's a call to fstat. The first argument, 3, is the file descriptor for the file opened in the previous line.

Perhaps you've noticed that when files are opened to a number, the numbers start at 3. This occurs because the file descriptors 0-2 are already allocated: 0 to stdin, 1 to stdout, and 2 to stderr.

The fstat call returns information about a file. The first argument is the file descriptor, which, as here, will have been set up by an earlier open call. The next section in the brackets is a stat structure. Strace doesn't actually show all of it (hence the … at the end), but the stat structure contains information about the file: user and group ID of owner, device ID, time last modified, and so on. (If you want to get full information on these sorts of structures, you can use the strace option -v.)

From the stat structure, you can see the file protection and size (in bytes) of the file. You should be able to interpret both of these values: The protection uses the same coding as chmod, so here, that's owner+group read, owner write, and owner execute (0644), and the size is just a number. (The other part of the mode field is a flag identifying whether it's a regular file, directory, or something else: S_IFREG means it's a regular file.) The fstat call returns 0 for success, as here: When called, the function fills in the stat structure that is recorded here.

In the mmap call, the first argument is a memory location, intended as a hint to the system as to where the memory mapping might start. Usually, as in this case, it's zero (NULL, i.e., the system has free rein to use any location it likes). The next number, which you might recognize, is the size in bytes of the file (so here, 43270 matches the size in the stat structure in the fstat call). The PROT* section specifies the protection that this memory should have, and it can't conflict with the mode of the file. Here, I'm opening with READ only. Because I'm not running as root, I don't have write or execute access to this file.

Next, the mmap call maps data from a file into memory, and these options specify how that mapping works. Here, MAP_PRIVATE means that any changes made to the mapped region (i.e., any changes made to memory) aren't shared with any other processes and aren't written back to the original file, which obviously is a good idea in the case of a system file like ld.so.cache! The next argument is, yet again, 3, the file descriptor. The final value is the offset, which here is set to 0.

The value returned by mmap is the memory address at which the mapping starts. To see when the system cleans up after itself, look for a munmap call later on with that memory address – that will clear out the memory address.

Note that you will get this call in a C trace, but not in a Perl trace. Because C explicitly sets up its own memory, it also explicitly clears up after itself (or it can, depending on the details of the implementation of malloc). Perl, on the other hand, just leaves this to be done by the system in due course.

While I'm looking at system calls in detail, what about the exit_group call that ends both strace outputs? All this does is exit threads. Unlike exit, it clears up not only that thread, but all threads in the current group.

Static or Dynamic

Static linking means that a program brings its own libraries. Dynamic linking means that a program uses the system libraries. With dynamic linking, you only have to have one copy of all the standard system libraries, rather than a copy per program. Pretty much all Linux programs use dynamic linking now, unless they've been specifically optimized to reduce overhead.

Buy Linux Magazine

SINGLE ISSUES
 
SUBSCRIPTIONS
 
TABLET & SMARTPHONE APPS
Get it on Google Play

US / Canada

Get it on Google Play

UK / Australia

Related content

  • strace

    Get started with strace by examining a pair of "Hello World" programs. Next month, in the second part of this two-part series, I'll take a deeper look at strace output.

  • Tracing Tools

    Programs rarely reveal what they are doing in the background, but a few clever tools, of interest to both programmers and administrators, monitor this activity and log system functions.

  • Perl: Ptrace

    Linux lets users watch the kernel at work with a little help from Ptrace, a tool that both debuggers and malicious process kidnappers use. A CPAN module introduces this technology to Perl and, if this is not enough, C extensions add functionality.

  • sysdig

    Many Linux diagnostic tools require knowledge of a special syntax, which complicates handling and confuses the output. Sysdig groups several important tools into a single interface.

  • How to Write a Rootkit

    Today’s rootkits infiltrate a target system at kernel level, thus escaping unwanted attention from administrators. Read on for a practical look at how a kernel rootkit really works.

comments powered by Disqus

Direct Download

Read full article as PDF:

News

njobs Europe
What:
Where:
Country:
Njobs Netherlands Njobs Deutschland Njobs United Kingdom Njobs Italia Njobs France Njobs Espana Njobs Poland
Njobs Austria Njobs Denmark Njobs Belgium Njobs Czech Republic Njobs Mexico Njobs India Njobs Colombia