Tuesday, June 22, 2010

strace - Debugging a live misbehaving process.

Often when a server is live you dont have the luxury of installing a debug-able version and stepping through its code when the problem appears. Other times you need to get a hold on whatever is killing a program that you never even wrote.

Enter "strace" this tool watches the system calls of a process and dumps it to your console for analysis. strace is not for the faint at heart. You need to know about how shells operate, how dynamic linked libraries are loaded and based and how kernel system calls pass in and out of system. On the flip side if you have never seen it before its a real eye opener. The average programmer most likely just doesn't realize how involved the kernel is with your little program.

To execute it on a program from scratch
strace -v <filename>
Note the "-v" gives you information about the environment variables that are passed from the shell to the new process.

To attach to a live process (you'll need to match the processes privilege level or better)
strace -p <process_id>

Here are some more resources on it:
http://www.redhat.com/magazine/010aug05/features/strace/
http://linux.die.net/man/1/strace

ok and here is an strace of ls in an empty directory so you can clearly see that simple isnt really that simple! (PS I seem to have a problem with my locales is polluting the result)
~/tmp> strace ls ./

execve("/bin/ls", ["ls", "./"], [/* 42 vars */]) = 0
brk(0)                                  = 0x61a000
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f7da0f51000
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) = 0x7f7da0f4f000
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
open("/home/ashley/obj-mail-release-NDEBUG/dist/bin/tls/x86_64/librt.so.1", O_RDONLY) = -1 ENOENT (No such file or directory)
stat("/home/ashley/obj-mail-release-NDEBUG/dist/bin/tls/x86_64", 0x7fff25ef42d0) = -1 ENOENT (No such file or directory)
open("/home/ashley/obj-mail-release-NDEBUG/dist/bin/tls/librt.so.1", O_RDONLY) = -1 ENOENT (No such file or directory)
stat("/home/ashley/obj-mail-release-NDEBUG/dist/bin/tls", 0x7fff25ef42d0) = -1 ENOENT (No such file or directory)
open("/home/ashley/obj-mail-release-NDEBUG/dist/bin/x86_64/librt.so.1", O_RDONLY) = -1 ENOENT (No such file or directory)
stat("/home/ashley/obj-mail-release-NDEBUG/dist/bin/x86_64", 0x7fff25ef42d0) = -1 ENOENT (No such file or directory)
open("/home/ashley/obj-mail-release-NDEBUG/dist/bin/librt.so.1", O_RDONLY) = -1 ENOENT (No such file or directory)
stat("/home/ashley/obj-mail-release-NDEBUG/dist/bin", 0x7fff25ef42d0) = -1 ENOENT (No such file or directory)
open("/home/ashley/obj-mail-debug/dist/lib/tls/x86_64/librt.so.1", O_RDONLY) = -1 ENOENT (No such file or directory)
stat("/home/ashley/obj-mail-debug/dist/lib/tls/x86_64", 0x7fff25ef42d0) = -1 ENOENT (No such file or directory)
open("/home/ashley/obj-mail-debug/dist/lib/tls/librt.so.1", O_RDONLY) = -1 ENOENT (No such file or directory)
stat("/home/ashley/obj-mail-debug/dist/lib/tls", 0x7fff25ef42d0) = -1 ENOENT (No such file or directory)
open("/home/ashley/obj-mail-debug/dist/lib/x86_64/librt.so.1", O_RDONLY) = -1 ENOENT (No such file or directory)
stat("/home/ashley/obj-mail-debug/dist/lib/x86_64", 0x7fff25ef42d0) = -1 ENOENT (No such file or directory)
open("/home/ashley/obj-mail-debug/dist/lib/librt.so.1", O_RDONLY) = -1 ENOENT (No such file or directory)
stat("/home/ashley/obj-mail-debug/dist/lib", 0x7fff25ef42d0) = -1 ENOENT (No such file or directory)
open("/etc/ld.so.cache", O_RDONLY)      = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=102124, ...}) = 0
mmap(NULL, 102124, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f7da0f36000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/lib/librt.so.1", O_RDONLY)       = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\240#\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0644, st_size=35784, ...}) = 0
mmap(NULL, 2132968, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f7da0b2c000
mprotect(0x7f7da0b34000, 2093056, PROT_NONE) = 0
mmap(0x7f7da0d33000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x7000) = 0x7f7da0d33000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/lib/libselinux.so.1", O_RDONLY)  = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\240Q\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0644, st_size=109368, ...}) = 0
mmap(NULL, 2209176, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f7da0910000
mprotect(0x7f7da0929000, 2097152, PROT_NONE) = 0
mmap(0x7f7da0b29000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x19000) = 0x7f7da0b29000
mmap(0x7f7da0b2b000, 1432, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f7da0b2b000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/lib/libacl.so.1", O_RDONLY)      = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\220\33\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0644, st_size=27600, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f7da0f35000
mmap(NULL, 2122744, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f7da0709000
mprotect(0x7f7da070f000, 2097152, PROT_NONE) = 0
mmap(0x7f7da090f000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x6000) = 0x7f7da090f000
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, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\340\342"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=1436976, ...}) = 0
mmap(NULL, 3543672, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f7da03a7000
mprotect(0x7f7da04ff000, 2097152, PROT_NONE) = 0
mmap(0x7f7da06ff000, 20480, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x158000) = 0x7f7da06ff000
mmap(0x7f7da0704000, 17016, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f7da0704000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/lib/libpthread.so.0", O_RDONLY)  = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\260W\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=130224, ...}) = 0
mmap(NULL, 2208624, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f7da018b000
mprotect(0x7f7da01a1000, 2097152, PROT_NONE) = 0
mmap(0x7f7da03a1000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x16000) = 0x7f7da03a1000
mmap(0x7f7da03a3000, 13168, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f7da03a3000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/lib/libdl.so.2", O_RDONLY)       = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0 \16\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0644, st_size=14624, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f7da0f34000
mmap(NULL, 2109728, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f7d9ff87000
mprotect(0x7f7d9ff89000, 2097152, PROT_NONE) = 0
mmap(0x7f7da0189000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x2000) = 0x7f7da0189000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/lib/libattr.so.1", O_RDONLY)     = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0000\21\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0644, st_size=16128, ...}) = 0
mmap(NULL, 2111240, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f7d9fd83000
mprotect(0x7f7d9fd87000, 2093056, PROT_NONE) = 0
mmap(0x7f7d9ff86000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x3000) = 0x7f7d9ff86000
close(3)                                = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f7da0f33000
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f7da0f32000
arch_prctl(ARCH_SET_FS, 0x7f7da0f32780) = 0
mprotect(0x7f7da06ff000, 12288, PROT_READ) = 0
munmap(0x7f7da0f36000, 102124)          = 0
set_tid_address(0x7f7da0f32810)         = 15691
set_robust_list(0x7f7da0f32820, 0x18)   = 0
futex(0x7fff25ef4e0c, 0x81 /* FUTEX_??? */, 1) = 0
rt_sigaction(SIGRTMIN, {0x7f7da01902d0, [], SA_RESTORER|SA_SIGINFO, 0x7f7da01997d0}, NULL, 8) = 0
rt_sigaction(SIGRT_1, {0x7f7da0190350, [], SA_RESTORER|SA_RESTART|SA_SIGINFO, 0x7f7da01997d0}, NULL, 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [RTMIN RT_1], NULL, 8) = 0
getrlimit(RLIMIT_STACK, {rlim_cur=8192*1024, rlim_max=RLIM_INFINITY}) = 0
brk(0)                                  = 0x61a000
brk(0x63b000)                           = 0x63b000
open("/etc/selinux/config", O_RDONLY)   = -1 ENOENT (No such file or directory)
statfs("/selinux", 0x7fff25ef3d30)      = -1 ENOENT (No such file or directory)
open("/proc/mounts", O_RDONLY)          = 3
fstat(3, {st_mode=S_IFREG|0444, st_size=0, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f7da0f4e000
read(3, "rootfs / rootfs rw 0 0\nnone /sys"..., 1024) = 1024
read(3, "server1/public /home/ashley/file"..., 1024) = 537
read(3, "", 1024)                       = 0
close(3)                                = 0
munmap(0x7f7da0f4e000, 4096)            = 0
open("/usr/lib/locale/locale-archive", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/usr/share/locale/locale.alias", O_RDONLY) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=2586, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f7da0f4e000
read(3, "# Locale name alias data base.\n#"..., 4096) = 2586
read(3, "", 4096)                       = 0
close(3)                                = 0
munmap(0x7f7da0f4e000, 4096)            = 0
open("/usr/lib/locale/en_US.UTF-8/LC_IDENTIFICATION", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/usr/lib/locale/en_US.utf8/LC_IDENTIFICATION", O_RDONLY) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=373, ...}) = 0
mmap(NULL, 373, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f7da0f4e000
close(3)                                = 0
open("/usr/lib/gconv/gconv-modules.cache", O_RDONLY) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=25700, ...}) = 0
mmap(NULL, 25700, PROT_READ, MAP_SHARED, 3, 0) = 0x7f7da0f47000
close(3)                                = 0
futex(0x7f7da0703f40, 0x81 /* FUTEX_??? */, 2147483647) = 0
open("/usr/lib/locale/en_US.UTF-8/LC_MEASUREMENT", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/usr/lib/locale/en_US.utf8/LC_MEASUREMENT", O_RDONLY) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=23, ...}) = 0
mmap(NULL, 23, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f7da0f46000
close(3)                                = 0
open("/usr/lib/locale/en_US.UTF-8/LC_TELEPHONE", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/usr/lib/locale/en_US.utf8/LC_TELEPHONE", O_RDONLY) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=59, ...}) = 0
mmap(NULL, 59, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f7da0f45000
close(3)                                = 0
open("/usr/lib/locale/en_US.UTF-8/LC_ADDRESS", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/usr/lib/locale/en_US.utf8/LC_ADDRESS", O_RDONLY) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=155, ...}) = 0
mmap(NULL, 155, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f7da0f44000
close(3)                                = 0
open("/usr/lib/locale/en_US.UTF-8/LC_NAME", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/usr/lib/locale/en_US.utf8/LC_NAME", O_RDONLY) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=77, ...}) = 0
mmap(NULL, 77, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f7da0f43000
close(3)                                = 0
open("/usr/lib/locale/en_US.UTF-8/LC_PAPER", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/usr/lib/locale/en_US.utf8/LC_PAPER", O_RDONLY) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=34, ...}) = 0
mmap(NULL, 34, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f7da0f42000
close(3)                                = 0
open("/usr/lib/locale/en_US.UTF-8/LC_MESSAGES", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/usr/lib/locale/en_US.utf8/LC_MESSAGES", O_RDONLY) = 3
fstat(3, {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
close(3)                                = 0
open("/usr/lib/locale/en_US.utf8/LC_MESSAGES/SYS_LC_MESSAGES", O_RDONLY) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=52, ...}) = 0
mmap(NULL, 52, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f7da0f41000
close(3)                                = 0
open("/usr/lib/locale/en_US.UTF-8/LC_MONETARY", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/usr/lib/locale/en_US.utf8/LC_MONETARY", O_RDONLY) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=286, ...}) = 0
mmap(NULL, 286, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f7da0f40000
close(3)                                = 0
open("/usr/lib/locale/en_US.UTF-8/LC_COLLATE", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/usr/lib/locale/en_US.utf8/LC_COLLATE", O_RDONLY) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=921214, ...}) = 0
mmap(NULL, 921214, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f7da0e51000
close(3)                                = 0
open("/usr/lib/locale/en_US.UTF-8/LC_TIME", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/usr/lib/locale/en_US.utf8/LC_TIME", O_RDONLY) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=2451, ...}) = 0
mmap(NULL, 2451, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f7da0f3f000
close(3)                                = 0
open("/usr/lib/locale/en_US.UTF-8/LC_NUMERIC", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/usr/lib/locale/en_US.utf8/LC_NUMERIC", O_RDONLY) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=54, ...}) = 0
mmap(NULL, 54, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f7da0f3e000
close(3)                                = 0
open("/usr/lib/locale/en_US.UTF-8/LC_CTYPE", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/usr/lib/locale/en_US.utf8/LC_CTYPE", O_RDONLY) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=254076, ...}) = 0
mmap(NULL, 254076, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f7da0e12000
close(3)                                = 0
ioctl(1, SNDCTL_TMR_TIMEBASE or TCGETS, {B38400 opost isig icanon echo ...}) = 0
ioctl(1, TIOCGWINSZ, {ws_row=46, ws_col=156, ws_xpixel=0, ws_ypixel=0}) = 0
stat("./", {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
open("./", O_RDONLY|O_NONBLOCK|O_DIRECTORY|0x80000) = 3
fstat(3, {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
fcntl(3, F_GETFD)                       = 0x1 (flags FD_CLOEXEC)
getdents(3, /* 2 entries */, 4096)      = 48
getdents(3, /* 0 entries */, 4096)      = 0
close(3)                                = 0
close(1)                                = 0
close(2)                                = 0
exit_group(0)                           = ?
Process 15691 detached

No comments:

Post a Comment