Math-Linux.com

Knowledge base dedicated to Linux and applied mathematics.

Home > Linux > Tutorials > Strace tool - Linux debugging - troubleshooting

Strace tool - Linux debugging - troubleshooting

All the versions of this article: [English] [français]

strace is a utility that can trace system calls.
System calls are the fundamental interfaces between an applications and the kernel.
They are generally not invoked directly, but rather via wrapper functions in glibc (or perhaps some other library).
For examples: fstat, mmap, open, close

open("/usr/lib/locale/fr_FR.utf8/LC_MONETARY", O_RDONLY) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=290, ...}) = 0
mmap(NULL, 290, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f841bde9000
close(3)

By using strace, we can intercept these system calls for a given process or a given command.
strace is a powerful troubleshooting tool for all unix/linux admins and users.

Strace basic usage

strace command

root@kali:~# strace ifconfig eth0
execve("/sbin/ifconfig", ["ifconfig", "eth0"], [/* 34 vars */]) = 0
brk(0) = 0x1b0f000
...
write(1, " inet adr:192.168.1.14 "..., 75
inet adr:192.168.1.14 Bcast:192.168.1.255 Masque:255.255.255.0
) = 75
open("/proc/net/if_inet6", O_RDONLY) = 6
...
close(5) = 0
exit_group(0)

System calls in file

I you want to store strace output in a file, use
strace -o filename command

For example:

root@kali:~# strace -o strace.txt ifconfig eth0
eth0
Link encap:Ethernet  HWaddr 00:0c:29:b9:0e:c0  
inet adr:192.168.1.14  Bcast:192.168.1.255  Masque:255.255.255.0
adr inet6: 2a01:e35:2f20:ed90:20c:29ff:feb9:ec0/64 Scope:Global
adr inet6: fe80::20c:29ff:feb9:ec0/64 Scope:Lien
UP BROADCAST RUNNING MULTICAST  MTU:1500  Metric:1
RX packets:17876 errors:0 dropped:0 overruns:0 frame:0
TX packets:10953 errors:0 dropped:0 overruns:0 carrier:0
collisions:0 lg file transmission:1000
RX bytes:18635399 (17.7 MiB)  TX bytes:980986 (957.9 KiB)

root@kali:~# head -n 2 strace.txt
execve("/sbin/ifconfig", ["ifconfig", "eth0"], [/* 34 vars */]) = 0
brk(0)                                  = 0x1437000

System call report/summary

strace -c command allows to make a report of system calls. For example:

root@kali:~# strace -c ifconfig eth0
eth0      Link encap:Ethernet  HWaddr 00:0c:29:b9:0e:c0  
         inet adr:192.168.1.14  Bcast:192.168.1.255  Masque:255.255.255.0
         adr inet6: 2a01:e35:2f20:ed90:20c:29ff:feb9:ec0/64 Scope:Global
         adr inet6: fe80::20c:29ff:feb9:ec0/64 Scope:Lien
         UP BROADCAST RUNNING MULTICAST  MTU:1500  Metric:1
         RX packets:17294 errors:0 dropped:0 overruns:0 frame:0
         TX packets:10524 errors:0 dropped:0 overruns:0 carrier:0
         collisions:0 lg file transmission:1000
         RX bytes:18290334 (17.4 MiB)  TX bytes:924666 (902.9 KiB)

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
100.00    0.040000        2857        14        11 access
 0.00    0.000000           0         8           read
 0.00    0.000000           0        10           write
 0.00    0.000000           0        35        14 open
 0.00    0.000000           0        22           close
 0.00    0.000000           0        22           fstat
 0.00    0.000000           0        28           mmap
 0.00    0.000000           0         6           mprotect
 0.00    0.000000           0         4           munmap
 0.00    0.000000           0         3           brk
 0.00    0.000000           0        11           ioctl
 0.00    0.000000           0         3           socket
 0.00    0.000000           0         1           execve
 0.00    0.000000           0         1           uname
 0.00    0.000000           0         1           arch_prctl
------ ----------- ----------- --------- --------- ----------------
100.00    0.040000                   169        25 total

Here, syscall open generates 14 erros. How to trace these specific calls ?

Trace specific system call

We can use -e option of strace:

root@kali:~# strace -e open ifconfig eth0
open("/etc/ld.so.cache", O_RDONLY)      = 3
open("/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY) = 3
open("/usr/lib/locale/locale-archive", O_RDONLY) = -1 ENOENT (No such file or directory)

...

open("/usr/lib/x86_64-linux-gnu/gconv/ISO8859-1.so", O_RDONLY) = 6
eth0      Link encap:Ethernet  HWaddr 00:0c:29:b9:0e:c0  
         inet adr:192.168.1.14  Bcast:192.168.1.255  Masque:255.255.255.0
open("/proc/net/if_inet6", O_RDONLY)    = 6
         adr inet6: 2a01:e35:2f20:ed90:20c:29ff:feb9:ec0/64 Scope:Global
         adr inet6: fe80::20c:29ff:feb9:ec0/64 Scope:Lien
         UP BROADCAST RUNNING MULTICAST  MTU:1500  Metric:1
         RX packets:17783 errors:0 dropped:0 overruns:0 frame:0
         TX packets:10915 errors:0 dropped:0 overruns:0 carrier:0
         collisions:0 lg file transmission:1000
         RX bytes:18626514 (17.7 MiB)  TX bytes:978630 (955.6 KiB)

We can see clearly that ifconfig try to open missing files. How many ?

root@kali:~# strace -e open ifconfig eth0 2>&1 | grep "No such file or directory" | wc -l
14

Exactly 14 !!! Like in the summary system call report.

Trace multipe system calls

We can use the -e trace=function1,function2, ... option
For example to trace mprotect or brk system calls:

root@kali:~# strace -e trace=mprotect,brk ifconfig eth0
brk(0)                                  = 0x1c1f000
mprotect(0x7f400429c000, 2097152, PROT_NONE) = 0
mprotect(0x7f400449c000, 16384, PROT_READ) = 0
mprotect(0x60f000, 4096, PROT_READ)     = 0
mprotect(0x7f40046c5000, 4096, PROT_READ) = 0
brk(0)                                  = 0x1c1f000
brk(0x1c40000)                          = 0x1c40000
mprotect(0x7f4003f1b000, 2093056, PROT_NONE) = 0
mprotect(0x7f400411a000, 4096, PROT_READ) = 0
eth0      Link encap:Ethernet  HWaddr 00:0c:29:b9:0e:c0  
         inet adr:192.168.1.14  Bcast:192.168.1.255  Masque:255.255.255.0
         adr inet6: 2a01:e35:2f20:ed90:20c:29ff:feb9:ec0/64 Scope:Global
         adr inet6: fe80::20c:29ff:feb9:ec0/64 Scope:Lien
         UP BROADCAST RUNNING MULTICAST  MTU:1500  Metric:1
         RX packets:17822 errors:0 dropped:0 overruns:0 frame:0
         TX packets:10932 errors:0 dropped:0 overruns:0 carrier:0
         collisions:0 lg file transmission:1000
         RX bytes:18630337 (17.7 MiB)  TX bytes:979684 (956.7 KiB)

Trace specific category of system calls

-e trace=file
You can think of this as an abbreviation for -e trace=open,stat,chmod,unlink,... which is useful to seeing what files the process is referencing.
Furthermore, using the abbreviation will ensure that you don’t accidentally forget to include a call like lstat in the list

-e trace=process
Trace all system calls which involve process management. This is useful for watching the fork, wait,and exec steps of a process.

-e trace=network
Trace all the network related system calls.

-e trace=signal
Trace all signal related system calls.

-e trace=ipc
Trace all IPC related system calls.

-e trace=desc
Trace all file descriptor related system calls.

For example to trace specific category network:

root@kali:~# strace -e trace=network ifconfig eth0
socket(PF_FILE, SOCK_DGRAM, 0)          = 3
socket(PF_INET, SOCK_DGRAM, IPPROTO_IP) = 4
socket(PF_INET6, SOCK_DGRAM, IPPROTO_IP) = 5
eth0      Link encap:Ethernet  HWaddr 00:0c:29:b9:0e:c0  
         inet adr:192.168.1.14  Bcast:192.168.1.255  Masque:255.255.255.0
         adr inet6: 2a01:e35:2f20:ed90:20c:29ff:feb9:ec0/64 Scope:Global
         adr inet6: fe80::20c:29ff:feb9:ec0/64 Scope:Lien
         UP BROADCAST RUNNING MULTICAST  MTU:1500  Metric:1
         RX packets:17836 errors:0 dropped:0 overruns:0 frame:0
         TX packets:10940 errors:0 dropped:0 overruns:0 carrier:0
         collisions:0 lg file transmission:1000
         RX bytes:18631824 (17.7 MiB)  TX bytes:980182 (957.2 KiB)

Get timestamps operation and time calls

It could be useful to get time entry of a system call or timestamps system calls:

strace -r Relative timestamp upon entry to each system call.
strace -t Prefix each line of the trace with the time of day.
strace -tt Time printed will include the microseconds.
strace -ttt Time printed will include the microseconds and the leading portion will be printed as the number of seconds since the epoch.

root@kali:~# strace -r -o strace_r.txt ifconfig eth0 > /dev/null
root@kali:~# strace -t -o strace_t.txt ifconfig eth0 > /dev/null
root@kali:~# strace -tt -o strace_tt.txt ifconfig eth0 > /dev/null
root@kali:~# strace -ttt -o strace_ttt.txt ifconfig eth0 > /dev/null
root@kali:~# ls -rt strace_*
strace_r.txt  strace_t.txt  strace_tt.txt  strace_ttt.txt
root@kali:~# head -n 2 strace_*
==> strace_r.txt <==
    0.000000 execve("/sbin/ifconfig", ["ifconfig", "eth0"], [/* 34 vars */]) = 0
    0.000192 brk(0)                    = 0x75a000

==> strace_ttt.txt <==
1399201553.405215 execve("/sbin/ifconfig", ["ifconfig", "eth0"], [/* 34 vars */]) = 0
1399201553.405410 brk(0)                = 0x159d000

==> strace_tt.txt <==
07:05:50.173343 execve("/sbin/ifconfig", ["ifconfig", "eth0"], [/* 34 vars */]) = 0
07:05:50.173648 brk(0)                  = 0x1398000

==> strace_t.txt <==
07:05:41 execve("/sbin/ifconfig", ["ifconfig", "eth0"], [/* 34 vars */]) = 0
07:05:41 brk(0)

What happens if a process fork ?

You can follow system calls if a process fork, -f option follows child process

root@kali:~# strace -f -o strace_acroread.txt acroread > /dev/null

Attach to an existing process

To attach strace to an existing process:

strace -p PID

For example:

root@kali:~# pidof sshd
6177
root@kali:~# strace -p 6177
Process 6177 attached - interrupt to quit
select(7, [3 4], NULL, NULL, NULL

Try to connect to the server kali (IP:192.168.1.14):

root@station:~# ssh kali

Now you have something like:

root@kali:~# strace -p 6177
Process 6177 attached - interrupt to quit
select(7, [3 4], NULL, NULL, NULL)      = 1 (in [3])
accept(3, {sa_family=AF_INET, sin_port=htons(45468), sin_addr=inet_addr("192.168.1.23")}, [16]) = 5
fcntl(5, F_GETFL)                       = 0x2 (flags O_RDWR)
pipe([6, 7])                            = 0
socketpair(PF_FILE, SOCK_STREAM, 0, [8, 9]) = 0
clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7f22b8b91a90) = 12420
close(7)                                = 0
write(8, "\0\0\2\263\0", 5)             = 5
write(8, "\0\0\2\252\n\n\n\nPort 22\n\n\n\nProtocol 2\n\nH"..., 690) = 690
close(8)                                = 0
close(9)                                = 0
close(5)                                = 0
select(7, [3 4 6], NULL, NULL, NULL)    = 1 (in [6])
close(6)                                = 0
select(7, [3 4], NULL, NULL, NULL

A pair of connected sockets is created: socketpair(...) with the foreign address—>192.168.1.23:45468

Moreover, we can see that a connection is established:

root@kali:~# netstat -at | grep -F '192.168.1.23'
tcp        0      0 192.168.1.14:ssh        192.168.1.23:45468      ESTABLISHED

I hope I could help you !!! Strace is a very powerful tool, do not forget man strace !!!

Any message or comments?

comments powered by Disqus