Fun to Program – Debug: level 2

TOC

This was originally written and created around 2013 and may require to be updated. (2021)

Debug: level 2

Tracing program execution to understand the general behavior of the program is the major part of debugging.

There are several ways to trace programs non-interactively without any modifications to the source.

strace

This is very effective tools to investigate what a program does without reading its full source at the system calll level.

Let’s investigate how the hello-gdb ELF binary (see ELF: Compile hello-gdb) is executed.

The trace of the system call is obtained with strace.

$ strace ./hello-gdb
execve("./hello-gdb", ["./hello-gdb"], [/* 58 vars */]) = 0
brk(0)                                  = 0xbed000
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2aa
aaaacc000
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=176595, ...}) = 0
mmap(NULL, 176595, PROT_READ, MAP_PRIVATE, 3, 0) = 0x2aaaaaace000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\240\32\2\0\0\0\0\0"..., 
832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=1742520, ...}) = 0
mmap(NULL, 3849280, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x2a
aaaaccf000
mprotect(0x2aaaaae71000, 2097152, PROT_NONE) = 0
mmap(0x2aaaab071000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENY
WRITE, 3, 0x1a2000) = 0x2aaaab071000
mmap(0x2aaaab077000, 15424, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANON
YMOUS, -1, 0) = 0x2aaaab077000
close(3)                                = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2aa
aaaafa000
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2aa
aaaafb000
arch_prctl(ARCH_SET_FS, 0x2aaaaaafab40) = 0
mprotect(0x2aaaab071000, 16384, PROT_READ) = 0
mprotect(0x2aaaaaccc000, 4096, PROT_READ) = 0
munmap(0x2aaaaaace000, 176595)          = 0
fstat(1, {st_mode=S_IFIFO|0600, st_size=0, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x2aa
aaaace000
write(1, "Hello, world!\n", 14Hello, world!
)         = 14
exit_group(0)                           = ?

This can get too big to read.

The statistics of the system call is obtained with strace -c to get the big picture.

$ strace -c ./hello-gdb
Hello, world!
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
  -nan    0.000000           0         1           read
  -nan    0.000000           0         1           write
  -nan    0.000000           0         2           open
  -nan    0.000000           0         2           close
  -nan    0.000000           0         3           fstat
  -nan    0.000000           0         8           mmap
  -nan    0.000000           0         3           mprotect
  -nan    0.000000           0         1           munmap
  -nan    0.000000           0         1           brk
  -nan    0.000000           0         3         3 access
  -nan    0.000000           0         1           execve
  -nan    0.000000           0         1           arch_prctl
------ ----------- ----------- --------- --------- ----------------
100.00    0.000000                    27         3 total

Now you know which system calls to trace, use strace -e trace=.... For example what files are accessed can be done just tracing open.

$ strace -e trace=open ./hello-gdb
open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
open("/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
Hello, world!

ltrace

This is very effective tools to investigate what a program does without reading its full source at the library call level.

Let’s investigate how the hello-gdb ELF binary (see ELF: Compile hello-gdb) is executed from a different angle.

The trace of the library call is obtained with ltrace.

$ ltrace ./hello-gdb
__libc_start_main(0x4004fd, 1, 0x7fff4e14a7b8, 0x400520, 0x4005b0 <unfinished ..
.>
puts("Hello, world!")                            = 14
Hello, world!
+++ exited (status 0) +++

The statistics of the library call is obtained with ltrace -c.

$ ltrace -c ./hello-gdb
Hello, world!
% time     seconds  usecs/call     calls      function
------ ----------- ----------- --------- --------------------
100.00    0.000129         129         1 puts
------ ----------- ----------- --------- --------------------
100.00    0.000129                     1 total

But the use of ltrace slows down program execution significantly for some case. Use it carefully.

Here are some similar tracing programs.

• xtrace package: trace communication between X client and server
• latrace package: traces library calls in dynamically linked programs with LD_AUDIT feature