Hace unos meses vimos como hacer debug de procesos en Solaris con el comando truss y dije además que este comando era la alternativa a strace en GNU/Linux. Vamos a ver entonces las posibilidades que nos ofrece el comando strace. Nos permite visualizar en la salida estándar los errores, llamadas al sistema y señales que recibe el proceso. Esto implica ver todo el proceso de ejecución de un proceso desde que comienza hasta que termina a bajo nivel.
Hay dos formas muy sencillas de ejecutarlo, una es strace <COMANDO> y la otra strace -p <PID>. Vamos a ver por ejemplo las llamadas al sistema y señales que recibimos al ejecutar un simple comando date:
~$ strace date
execve("/bin/date", ["date"], [/* 42 vars */]) = 0
brk(0) = 0x858f000
access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
mmap2(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb774e000
access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
fstat64(3, {st_mode=S_IFREG|0644, st_size=69920, ...}) = 0
mmap2(NULL, 69920, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb773c000
close(3) = 0
access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
open("/lib/i386-linux-gnu/librt.so.1", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\320\30\0\0004\0\0\0"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0644, st_size=30684, ...}) = 0
mmap2(NULL, 33360, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xbee000
mmap2(0xbf5000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x6) = 0xbf5000
close(3) = 0
access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
open("/lib/i386-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0000\226\1\0004\0\0\0"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=1713640, ...}) = 0
mmap2(NULL, 1723100, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xce0000
mmap2(0xe7f000, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x19f) = 0xe7f000
mmap2(0xe82000, 10972, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xe82000
close(3) = 0
access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
open("/lib/i386-linux-gnu/libpthread.so.0", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0p[\0\0004\0\0\0"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=124663, ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb773b000
mmap2(NULL, 107008, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xa6e000
mmap2(0xa85000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x16) = 0xa85000
mmap2(0xa87000, 4608, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xa87000
close(3) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb773a000
set_thread_area({entry_number:-1 -> 6, base_addr:0xb773a6c0, limit:1048575, seg_32bit:1, contents:0, read_exec_only:0, limit_in_pages:1, seg_not_present:0, useable:1}) = 0
mprotect(0xe7f000, 8192, PROT_READ) = 0
mprotect(0xa85000, 4096, PROT_READ) = 0
mprotect(0xbf5000, 4096, PROT_READ) = 0
mprotect(0x8055000, 4096, PROT_READ) = 0
mprotect(0xf67000, 4096, PROT_READ) = 0
munmap(0xb773c000, 69920) = 0
set_tid_address(0xb773a728) = 4028
set_robust_list(0xb773a730, 0xc) = 0
futex(0xbf808d94, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 1, NULL, b773a6c0) = -1 EAGAIN (Resource temporarily unavailable)
rt_sigaction(SIGRTMIN, {0xa73570, [], SA_SIGINFO}, NULL, 8) = 0
rt_sigaction(SIGRT_1, {0xa735f0, [], SA_RESTART|SA_SIGINFO}, 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
uname({sys="Linux", node="Xubuntu", ...}) = 0
brk(0) = 0x858f000
brk(0x85b0000) = 0x85b0000
open("/usr/lib/locale/locale-archive", O_RDONLY|O_LARGEFILE|O_CLOEXEC) = 3
fstat64(3, {st_mode=S_IFREG|0644, st_size=7245312, ...}) = 0
mmap2(NULL, 2097152, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb753a000
mmap2(NULL, 4096, PROT_READ, MAP_PRIVATE, 3, 0x46c) = 0xb774d000
close(3) = 0
clock_gettime(CLOCK_REALTIME, {1351934071, 598373225}) = 0
open("/etc/localtime", O_RDONLY|O_CLOEXEC) = 3
fstat64(3, {st_mode=S_IFREG|0644, st_size=2593, ...}) = 0
fstat64(3, {st_mode=S_IFREG|0644, st_size=2593, ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb774c000
read(3, "TZif2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\10\0\0\0\10\0\0\0\0"..., 4096) = 2593
_llseek(3, -28, [2565], SEEK_CUR) = 0
read(3, "\nCET-1CEST,M3.5.0,M10.5.0/3\n", 4096) = 28
close(3) = 0
munmap(0xb774c000, 4096) = 0
fstat64(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 2), ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb774c000
write(1, "Sat Nov 3 10:14:31 CET 2012\n", 29Sat Nov 3 10:14:31 CET 2012
) = 29
close(1) = 0
munmap(0xb774c000, 4096) = 0
close(2) = 0
exit_group(0) = ?
Como podéis observar, podemos ver todo el proceso de ejecución del comando, las llamadas a las librerías del sistema, ficheros que se han utilizado para la ejecución del comando, funciones, señales que recibimos de cada parte del proceso, etc.
A primera vista parece que vaya a resultar muy complicado hacer debug de un proceso con esta información, pero no es necesario conocer ni entender todo, puedes detectar cuando por ejemplo se llama a un fichero que no existe o cuando los permisos del mismo no dejan al comando ejecutar una determinada tarea dentro del marco de ejecución del proceso.
La otra forma de ejecutarlo que más se suele utilizar es pasandole un PID, esto es útil cuando el proceso que queremos revisar está ya en ejecución. Sería similar a un «tail -f» que haríamos a un fichero de log:
En este caso lo ejecutamos como root seguido del PID:
# strace -p 1967
Process 1697 attached - interrupt to quit
ppoll([{fd=5, events=POLLIN}, {fd=20, events=POLLIN}, {fd=4, events=POLLIN}, {fd=32, events=POLLIN}, {fd=33, events=POLLIN}, {fd=35, events=POLLIN}, {fd=9, events=POLLIN}, {fd=29, events=POLLIN}, {fd=31, events=POLLIN|POLLERR|POLLHUP}, {fd=31, events=0}, {fd=30, events=POLLIN}, {fd=23, events=POLLIN}, {fd=26, events=POLLIN}, {fd=16, events=POLLIN}, {fd=19, events=POLLIN}, {fd=15, events=POLLIN|POLLERR|POLLHUP}, {fd=15, events=0}, {fd=14, events=POLLIN}, {fd=13, events=POLLIN}, {fd=7, events=POLLIN}], 20, NULL, NULL, 8) = 1 ([{fd=19, revents=POLLIN}])
read(19, "\1\0\0\0\0\0\0\0", 8) = 8
send(20, "\0\0\0\24\377\377\377\377\0\0\0\0\0\0\0\0\0\0\0\0", 20, MSG_NOSIGNAL) = 20
ppoll([{fd=5, events=POLLIN}, {fd=20, events=POLLIN|POLLOUT}, {fd=4, events=POLLIN}, {fd=32, events=POLLIN}, {fd=33, events=POLLIN}, {fd=35, events=POLLIN}, {fd=9, events=POLLIN}, {fd=29, events=POLLIN}, {fd=31, events=POLLIN|POLLERR|POLLHUP}, {fd=31, events=0}, {fd=30, events=POLLIN}, {fd=23, events=POLLIN}, {fd=26, events=POLLIN}, {fd=16, events=POLLIN}, {fd=19, events=POLLIN}, {fd=15, events=POLLIN|POLLERR|POLLHUP}, {fd=15, events=0}, {fd=14, events=POLLIN}, {fd=13, events=POLLIN}, {fd=7, events=POLLIN}], 20, NULL, NULL, 8) = 1 ([{fd=20, revents=POLLOUT}])
send(20, "L\0\0\0=L\377\377\377\377L\0\0\0\2L\0\0\275 ", 20, MSG_NOSIGNAL) = 20
ppoll([{fd=5, events=POLLIN}, {fd=20, events=POLLIN|POLLOUT}, {fd=4, events=POLLIN}, {fd=32, events=POLLIN}, {fd=33, events=POLLIN}, {fd=35, events=POLLIN}, {fd=9, events=POLLIN}, {fd=29, events=POLLIN}, {fd=31, events=POLLIN|POLLERR|POLLHUP}, {fd=31, events=0}, {fd=30, events=POLLIN}, {fd=23, events=POLLIN}, {fd=26, events=POLLIN}, {fd=16, events=POLLIN}, {fd=19, events=POLLIN}, {fd=15, events=POLLIN|POLLERR|POLLHUP}, {fd=15, events=0}, {fd=14, events=POLLIN}, {fd=13, events=POLLIN}, {fd=7, events=POLLIN}], 20, NULL, NULL, 8) = 1 ([{fd=20, revents=POLLIN|POLLOUT}])
recvmsg(20, {msg_name(0)=NULL, msg_iov(1)=[{"\0\0\0\
...
...
También podríamos evitar ver toda la salida directa por pantalla y mostrar con el parámetro «-c» un resumen de las llamadas y errores durante la ejecución:
# strace -c date Sat Nov 3 10:22:31 CET 2012 % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- -nan 0.000000 0 5 read -nan 0.000000 0 1 write -nan 0.000000 0 6 open -nan 0.000000 0 8 close -nan 0.000000 0 1 execve -nan 0.000000 0 5 5 access -nan 0.000000 0 3 brk -nan 0.000000 0 3 munmap -nan 0.000000 0 1 uname -nan 0.000000 0 5 mprotect -nan 0.000000 0 1 _llseek -nan 0.000000 0 2 rt_sigaction -nan 0.000000 0 1 rt_sigprocmask -nan 0.000000 0 1 getrlimit -nan 0.000000 0 16 mmap2 -nan 0.000000 0 8 fstat64 -nan 0.000000 0 1 1 futex -nan 0.000000 0 1 set_thread_area -nan 0.000000 0 1 set_tid_address -nan 0.000000 0 1 clock_gettime -nan 0.000000 0 1 set_robust_list ------ ----------- ----------- --------- --------- ---------------- 100.00 0.000000 72 6 total
Para un uso más avanzado del comando y entender su salida como siempre os recomiendo su página man:
$ man strace