strace jest doskonałym narzędziem służącym do śledzenia procesów, zarówno tych już uruchomionych (możliwość podpięcia się pod działający już proces, np. daemon,) jak i uruchamianych na bieżąco. Wspominałem już o nim w artykule 10 narzędzi które powinien znać administrator, a teraz chciałbym rozszerzyć ten artykuł konkretnie o przykłady i analizy.
strace nie należy do najprostszych narzędzi, może nie tyle chodzi o samą obsługę, ale o zrozumienie wyników. Na pewno należy znać podstawy budowy systemu Linuks, ale zdecydowanie większym atutem będzie znajomość podstaw programowania w ANSI C. Kernel Linuksa jak i większość narzędzi dostępnych w systemie jest właśnie napisana w tym języku, oznacza to, że funkcje wykonywane przez programy (również programy napisane w językach wyższego poziomu), muszą być tłumaczone na funkcje języka C, a strace'owanie, polega właśnie na podglądaniu wywoływanych funkcji systemowych przez konkretny program.
Przykład 1
#include <stdio.h>
#include <stdlib.h>int main(void) {
printf("Hello worldn");
exit(0);
}
Program po skompilowaniu (make example1) i uruchomieniu wyświetla jedynie napis Hello world, spójrzmy co zwróci nam strace ./example1
jamzed@yoursite:~/Lab$ strace ./example1
execve("./example1", ["./example1"], [/* 22 vars */]) = 0
brk(0) = 0x901e000
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) = 0xb78eb000
access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
open("/etc/ld.so.cache", O_RDONLY) = 3
fstat64(3, {st_mode=S_IFREG|0644, st_size=18028, ...}) = 0
mmap2(NULL, 18028, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb78e6000
close(3) = 0
access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
open("/lib/tls/i686/cmov/libc.so.6", O_RDONLY) = 3
read(3, "177ELF111���������3�3�1���260l1�004���"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=1319364, ...}) = 0
mmap2(NULL, 1329512, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x77e000
mprotect(0x8bc000, 4096, PROT_NONE) = 0
mmap2(0x8bd000, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x13e) = 0x8bd000
mmap2(0x8c0000, 10600, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x8c0000
close(3) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb78e5000
set_thread_area({entry_number:-1 -> 6, base_addr:0xb78e56c0, limit:1048575, seg_32bit:1, contents:0, read_exec_only:0, limit_in_pages:1, seg_not_present:0, useable:1}) = 0
mprotect(0x8bd000, 8192, PROT_READ) = 0
mprotect(0x8049000, 4096, PROT_READ) = 0
mprotect(0xfd8000, 4096, PROT_READ) = 0
munmap(0xb78e6000, 18028) = 0
fstat64(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 8), ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb78ea000
write(1, "Hello worldn", 12Hello world
) = 12
exit_group(0) = ?
Na samym początku widać funkcję execve, która powoduje uruchomienie binarki example1, kolejne linie to ładowanie bibliotek niezbędnych do uruchamiania programów, pogrubione linie to coś dla nas interesującego, pierwsza i druga to otwarcie i czytanie pliku (/lib/tls/i686/cmov/libc.so.6), read(3...), pierwsza funkcja open() zwróciła numer deskryptora pliku (3) a druga read() przeczytała z tego deskryptora 512 bajtów, kolejna linia na którą warto zwrócić uwagę do fstat64(1...), funkcja fstat64 pobiera status pliku, w tym przypadku deksryptora 1 (STDOUT), następnie wywoływana jest funkcja write(1...), która powoduje zapisanie danych do konkretnego deskryptora (1). Czyli tłumacząc teraz na język ludzki, nasza aplikacja wykonała wypisanie "Hello world" do 1 deskryptora (STDOUT), czyli na nasz ekran.
Przytoczyłem powyższy przykład, żeby pokazać jak wygląda standardowy output ze strace'a, tak naprawdę to każda czynność wykonywana przez jakąś aplikację to wywoływanie konkretnych funkcji, otwarcie pliku open(), zamknięcie pliku/deskryptora close(), pisanie write(), czytanie read()... itd... jeśli nie wiemy jak działa któraś z funkcji, możemy skorzystać z doskonałej pomocy jaką są manuale, np. man 2 write.
ssize_t write(int fd, const void *buf, size_t count);
man mówi nam, że funkcja write zwraca wynik jako ssize_t (czyli ilość przeczytanych bajtów), a jako argumenty przyjmuje (int deskryptor, wskaźnik do bufora z danymi, rozmiar bufora z danymi), na naszym przykładzie, deskryptor to STDOUT, wskaźnik do bufora jest zastąpiony konkretnymi danymi "Hello worldn", rozmiar to 12 bajtów, wszystko się zgadza.
W kolejnym przykładzie pokażę, jak wygląda klasyczne połączenie TCP do zdalnego hosta, przygotowałem krótki program wykonujący połączenie TCP na adres localhost (127.0.0.1), na port 5000 i wysyłający informację.
Przykład 2
#include <sys/socket.h>
#include <sys/types.h>
#include <netinet/in.h>
#include <netdb.h>
#include <stdio.h>
#include <string.h>
#include <stdlib.h>
#include <unistd.h>
#include <errno.h>int main(void) {
int sock;
char *send_data = "DANE DANE DANEn";
struct hostent *host;
struct sockaddr_in server_addr;host = gethostbyname("localhost");
sock = socket(AF_INET, SOCK_STREAM, 0);server_addr.sin_family = AF_INET;
server_addr.sin_port = htons(5000);
server_addr.sin_addr = *((struct in_addr *)host->h_addr);
bzero(&(server_addr.sin_zero),8);connect(sock, (struct sockaddr *)&server_addr, sizeof(struct sockaddr));
printf("SEND DATAn");
send(sock,send_data,strlen(send_data), 0);
close(sock);return 0;
}
Dla lepszego zobrazowania, uruchamiamy w drugim terminalu netcata (nc -l -p 5000), co pozwoli nam obserwować czy, nasz klient TCP wykonał rzeczywiście połączenie i przesłał dane.
jamzed@yoursite:~/Lab$ strace ./example2
open("/etc/resolv.conf", O_RDONLY) = 3
fstat64(3, {st_mode=S_IFREG|0644, st_size=35, ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7834000
read(3, "search plnnameserver 194.204.159"..., 4096) = 35
read(3, "", 4096) = 0
close(3) = 0
munmap(0xb7834000, 4096) = 0
stat64("/etc/resolv.conf", {st_mode=S_IFREG|0644, st_size=35, ...}) = 0
open("/etc/resolv.conf", O_RDONLY) = 3
fstat64(3, {st_mode=S_IFREG|0644, st_size=35, ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7834000
read(3, "search plnnameserver 194.204.159"..., 4096) = 35
read(3, "", 4096) = 0
close(3) = 0
munmap(0xb7834000, 4096) = 0
socket(PF_FILE, 0x80801 /* SOCK_??? */, 0) = 3
connect(3, {sa_family=AF_FILE, path="/var/run/nscd/socket"}, 110) = -1 ENOENT (No such file or directory)
close(3) = 0
socket(PF_FILE, 0x80801 /* SOCK_??? */, 0) = 3
connect(3, {sa_family=AF_FILE, path="/var/run/nscd/socket"}, 110) = -1 ENOENT (No such file or directory)
close(3) = 0
open("/etc/nsswitch.conf", O_RDONLY) = 3
fstat64(3, {st_mode=S_IFREG|0644, st_size=475, ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7834000
read(3, "# /etc/nsswitch.confn#n# Example"..., 4096) = 475
read(3, "", 4096) = 0
close(3) = 0
munmap(0xb7834000, 4096) = 0
open("/etc/ld.so.cache", O_RDONLY) = 3
fstat64(3, {st_mode=S_IFREG|0644, st_size=18028, ...}) = 0
mmap2(NULL, 18028, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb7830000
close(3) = 0
access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
open("/lib/tls/i686/cmov/libnss_files.so.2", O_RDONLY) = 3
read(3, "177ELF111���������3�3�1��� 32��004���"..., 512) = 512
fstat64(3, {st_mode=S_IFREG|0644, st_size=42572, ...}) = 0
mmap2(NULL, 45772, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x8c3000
mmap2(0x8cd000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x9) = 0x8cd000
close(3) = 0
mprotect(0x8cd000, 4096, PROT_READ) = 0
munmap(0xb7830000, 18028) = 0
open("/etc/host.conf", O_RDONLY) = 3
fstat64(3, {st_mode=S_IFREG|0644, st_size=92, ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7834000
read(3, "# The "order" line is only used "..., 4096) = 92
read(3, "", 4096) = 0
close(3) = 0
munmap(0xb7834000, 4096) = 0
open("/etc/hosts", O_RDONLY|O_CLOEXEC) = 3
fcntl64(3, F_GETFD) = 0x1 (flags FD_CLOEXEC)
fstat64(3, {st_mode=S_IFREG|0644, st_size=272, ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7834000
read(3, "127.0.0.1tlocalhostn195.205.203."..., 4096) = 272
read(3, "", 4096) = 0
close(3) = 0
munmap(0xb7834000, 4096) = 0
socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 3
connect(3, {sa_family=AF_INET, sin_port=htons(5000), sin_addr=inet_addr("127.0.0.1")}, 16) = 0
fstat64(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 8), ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7834000
write(1, "SEND DATAn", 10SEND DATA
) = 10
send(3, "DANE DANE DANEn", 15, 0) = 15
close(3) = 0
exit_group(0) = ?
Pominąłem pierwsze linie inicjalizujące nasz program, wkleiłem od momentu kiedy zaczyna się coś dziać. Podczas wykonywania połączenia TCP musi nastąpić kilka czynności, przede wszystkim musi nastąpić zamiana hosta na adres IP, musi zostać utworzony socket, po tym dopiero connect() do konkretnego hosta i portu, i następnie można już poprawnie wykonać send(), czyli wysłać dane. Pogrubione linie właśnie pokazują jak system czyta plik /etc/resolv.conf, następnie próbuje zresolwować host localhost poprzez połączenie po sockecie do nscd (name service cache daemon), keszującego daemona, ten nie odpowiada więc następuje czytanie pliku /etc/host.conf, który określa kolejność w jakiej należy resolwować hosty:
jamzed@yoursite:~/Lab$ cat /etc/host.conf
# The "order" line is only used by old versions of the C library.
order hosts,bind
najpierw /etc/hosts a dopiero później korzystając z serwera DNS, co właśnie robi nasza aplikacja, szuka localhost w /etc/hosts i znajduje (127.0.0.1). Po tym jak znane jest IP następuje utworzenie socketu socket(PF_INET, SOCK_STREAM, IPPROTO_IP), SOCK_STREAM mówi o tym, że będzie to połączenie TCP/IP, mając utworzony socket następuje wywołanie funkcji connect(3, {sa...), jako pierwszy argument funkcja przyjmuje deskryptor naszego socketa (3), następuje więc połączenie z naszym serwerem 127.0.0.1:5000, kolejny krok to wypisanie na STDOUT stringu "SEND DATAn" i dopiero po tym jest send(3, "DANE...), czyli właściwie wysłanie danych do serwera, później pozostaje posprzątać po sobie close(3), i zakończyć poprawnie program exit(0).
Jeśli uruchomiony nasz program w momencie kiedy serwer nie będzie działał poprawnie zobaczymy w wyniku strace co dokładnie jest przyczyną problemów:
socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 3
connect(3, {sa_family=AF_INET, sin_port=htons(5000), sin_addr=inet_addr("127.0.0.1")}, 16) = -1 ECONNREFUSED (Connection refused)
fstat64(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 8), ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7871000
write(1, "SEND DATAn", 10SEND DATA
) = 10
send(3, "DANE DANE DANEn", 15, 0) = -1 EPIPE (Broken pipe)
--- SIGPIPE (Broken pipe) @ 0 (0) ---
+++ killed by SIGPIPE +++
Widzimy, że funkcja connect() zwróciła -1 czyli Connection refused co świadczy o tym, że połączenie z serwerem nie udało się, nasza aplikacja nie obsługuje błędów więc próbuje pisać do deskryptora którego nie ma, stąd drugi komunikat Broken pipe. Analogiczna sytuacja może wystąpić w każdej innej aplikacji, w przeglądarce, w kliencie GG, jeśli wykonany na nim strace, a serwer nie będzie działał poprawnie, również zobaczymy podobny wynik.
Na początku cały ten output może wydawać się bardzo nieczytelny i trudny w analizie, ale z czasem przeglądając wyniki strace'a różnych aplikacji dojdziemy do wprawy i diagnozowanie nawet złożonych aplikacji/problemów nie będzie sprawiała nam dużych trudności. Jest to pierwszy artykuł poświęcony strace'owi, mam nadzieję, że nie ostatni i z czasem na przykładzie rozwiązywania konkretnych problemów strace będzie pojawiał się coraz częściej, zapraszam więc do zapoznania się z tym narzędziem (man strace).
Kod przykładów do pobrania:
A co Wy ostatnio strace'owaliście? ;-)