Moja główna praca polega głównie na wdrażaniu systemów oprogramowania, co oznacza, że spędzam dużo czasu, starając się odpowiedzieć na takie pytania:
- U developera to oprogramowanie działa, a u mnie nie. Dlaczego?
- Wczoraj to oprogramowanie działało u mnie, a dzisiaj już nie. Dlaczego?
To rodzaj debugowania, które nieco różni się od tradycyjnego debugowania oprogramowania. Tradycyjne debugowanie dotyczy logiki kodu, podczas gdy debugowanie wdrożenia dotyczy interakcji kodu ze środowiskiem. Nawet jeśli źródło problemu to błąd logiczny, fakt, że na jednej maszynie wszystko działa, a na innej nie, oznacza, że coś jest nie tak ze środowiskiem.
Dlatego zamiast tradycyjnych narzędzi do debugowania, takich jak gdb , mam inny zestaw narzędzi do debugowania wdrożenia. A moim ulubionym narzędziem do walki z problemem typu „Dlaczego to oprogramowanie u mnie nie działa?” jest strace.
Czym właściwie jest strace?
— to narzędzie do „śledzenia wywołań systemowych”. Zostało pierwotnie stworzone dla systemu Linux, ale te same techniki debugowania można zastosować także z narzędziami dla innych systemów ( lub ).
Główne zastosowanie jest bardzo proste. Wystarczy uruchomić strace z dowolną komendą, a on wyśle do zrzutu wszystkie wywołania systemowe (choć najpierw trzeba może zainstalować samo strace):
$ strace echo Hello
...Snip lots of stuff...
write(1, "Hellon", 6) = 6
close(1) = 0
close(2) = 0
exit_group(0) = ?
+++ exited with 0 +++Czym są te wywołania systemowe? To coś w rodzaju API dla jądra systemu operacyjnego. Dawno temu oprogramowanie miało bezpośredni dostęp do „sprzętu”, na którym działało. Na przykład, gdy trzeba było coś wyświetlić na ekranie, manipulowało portami lub rejestrami wyświetlania w pamięci dla urządzeń wideo. Kiedy popularne stały się wielozadaniowe systemy komputerowe, zapanował chaos, ponieważ różne aplikacje walczyły o dostęp do „sprzętu”. Błędy w jednej aplikacji mogły zburzyć działanie innych, a nawet całego systemu. Wtedy w CPU wprowadzono tryby uprzywilejowania (lub „ochronę pierścieniową”). Najbardziej uprzywilejowane stało się jądro: miało pełny dostęp do „sprzętu”, tworząc aplikacje o mniejszych uprawnieniach, które musiały prosić jądro o dostęp do „sprzętu” — poprzez wywołania systemowe.
Na poziomie binarnym, wywołanie systemowe nieco różni się od prostego wywołania funkcji, jednak większość programów korzysta z opakowania w standardowej bibliotece. Tzn. standardowa biblioteka POSIX C zawiera wywołanie funkcji write(), która zawiera cały kod zależny od architektury dla wywołania systemowego write.
Krótko mówiąc, wszelkie interakcje aplikacji z jej otoczeniem (systemami komputerowymi) odbywają się za pomocą wywołań systemowych. Dlatego, gdy oprogramowanie działa na jednej maszynie, a na drugiej nie, warto zajrzeć w wyniki śledzenia wywołań systemowych. A konkretniej, oto lista typowych kwestii, które można przeanalizować przy pomocy śledzenia wywołań systemowych:
- Konsolowy input-output
- Sieciowy input-output
- Dostęp do systemu plików i input-output plików
- Zarządzanie cyklem życia wątków procesów
- Niskopoziomowe zarządzanie pamięcią
- Dostęp do sterowników specjalnych urządzeń
Kiedy używać strace?
Teoretycznie, strace jest używany z wszelkimi programami w przestrzeni użytkownika, ponieważ każdy program w przestrzeni użytkownika musi wykonywać wywołania systemowe. Działa skuteczniej z kompilowanymi, niskopoziomowymi programami, ale działa również z językami wysokiego poziomu, takimi jak Python, jeśli uda się przebić przez dodatkowy hałas ze środowiska wykonawczego i interpretera.
W całej okazałości strace ukazuje się podczas debugowania oprogramowania, które działa dobrze na jednej maszynie, a na drugiej nagle przestaje działać, dając niejasne komunikaty o plikach, uprawnieniach lub nieudanych próbach wykonania poleceń czy innych… Szkoda, ale nie sprawdza się zbyt dobrze w przypadku problemów wysokiego poziomu, takich jak błąd weryfikacji certyfikatu. Zwykle wymaga to kombinacji strace, czasami i narzędzi o wyższym poziomie (jak narzędzie wiersza poleceń openssl do debugowania certyfikatu).
Na przykład, bierzemy pracę na izolowanym serwerze, ale śledzenie wywołań systemowych często można przeprowadzić także na bardziej złożonych platformach wdrożeniowych. Trzeba tylko dobrać odpowiednie narzędzie.
Przykład prostego debugowania
Załóżmy, że chcesz uruchomić niesamowitą aplikację serwerową foo i wygląda to tak:
$ foo
Błąd otwierania pliku konfiguracyjnego: Nie ma takiego pliku ani kataloguOczywiście, nie udało mu się znaleźć napisanego przez Ciebie pliku konfiguracyjnego. Dzieje się tak, ponieważ czasami menedżery pakietów, kompilując aplikację, nadpisują oczekiwane lokalizacje plików. I jeśli podążać za instrukcją instalacji dla jednej dystrybucji, w innej możesz znaleźć pliki zupełnie nie tam, gdzie się ich spodziewałeś. Problem można by rozwiązać w kilka sekund, gdyby komunikat o błędzie wskazywał, gdzie szukać pliku konfiguracyjnego, ale on tego nie robi. Więc gdzie szukać?
Jeśli masz dostęp do kodu źródłowego, możesz go przeczytać i wszystko wyjaśnić. Dobry plan awaryjny, ale nie najszybsze rozwiązanie. Możesz użyć debuggera krokowego, takiego jak gdb , i zobaczyć, co robi program, ale znacznie efektywniej jest użyć narzędzia, które zostało specjalnie zaprojektowane do pokazywania interakcji ze środowiskiem: strace.
Wnioski strace może wydawać się nadmiarowe, ale dobrą wiadomością jest to, że dużą część z tego można śmiało zignorować. Często przydatne jest użycie operatora -o, aby zapisywać wyniki śledzenia w osobnym pliku:
$ strace -o /tmp/trace foo
Błąd podczas otwierania pliku konfiguracyjnego: Brak takiego pliku lub katalogu
$ cat /tmp/trace
execve("foo", ["foo"], 0x7ffce98dc010 /* 16 vars */) = 0
brk(NULL) = 0x56363b3fb000
access("/etc/ld.so.preload", R_OK) = -1 ENOENT (Brak takiego pliku lub katalogu)
openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=25186, ...}) = 0
mmap(NULL, 25186, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f2f12cf1000
close(3) = 0
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
read(3, "177ELF2113 3 > 1 260A2 "..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=1824496, ...}) = 0
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f2f12cef000
mmap(NULL, 1837056, PROT_READ, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f2f12b2e000
mprotect(0x7f2f12b50000, 1658880, PROT_NONE) = 0
mmap(0x7f2f12b50000, 1343488, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x22000) = 0x7f2f12b50000
mmap(0x7f2f12c98000, 311296, PROT_READ, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x16a000) = 0x7f2f12c98000
mmap(0x7f2f12ce5000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1b6000) = 0x7f2f12ce5000
mmap(0x7f2f12ceb000, 14336, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f2f12ceb000
close(3) = 0
arch_prctl(ARCH_SET_FS, 0x7f2f12cf0500) = 0
mprotect(0x7f2f12ce5000, 16384, PROT_READ) = 0
mprotect(0x56363b08b000, 4096, PROT_READ) = 0
mprotect(0x7f2f12d1f000, 4096, PROT_READ) = 0
munmap(0x7f2f12cf1000, 25186) = 0
openat(AT_FDCWD, "/etc/foo/config.json", O_RDONLY) = -1 ENOENT (Brak takiego pliku lub katalogu)
dup(2) = 3
fcntl(3, F_GETFL) = 0x2 (flagi O_RDWR)
brk(NULL) = 0x56363b3fb000
brk(0x56363b41c000) = 0x56363b41c000
fstat(3, {st_mode=S_IFCHR|0620, st_rdev=makedev(0x88, 0x8), ...}) = 0
write(3, "Błąd podczas otwierania pliku konfiguracyjnego"..., 60) = 60
close(3) = 0
exit_group(1) = ?
+++ zakończono z 1 +++Przykładowo cała pierwsza strona wyjścia strace — to zwykle niski poziom przygotowania do uruchomienia. (Wiele wywołań mmap, mprotect, brk do rzeczy typu wykrywania niskopoziomowej pamięci i mapowania dynamicznych bibliotek.) Z reguły wyniki podczas debugowania strace najlepiej czytać od samego końca. Na dole będzie wywołanie write, które wyświetla komunikat o błędzie. Patrzymy wyżej i widzimy pierwsze nieudane wywołanie systemowe — wywołanie openat, generujące błąd ENOENT („plik lub katalog nie znaleziony”), próbujący otworzyć /etc/foo/config.json. Oto tutaj powinien znajdować się plik konfiguracyjny.
To był tylko przykład, ale powiedziałbym, że 90% czasu, kiedy korzystam z strace, nie robię nic bardziej skomplikowanego. Poniżej znajduje się pełny przewodnik krok po kroku do debugowania:
- Nie denerwuj się z powodu niewyraźnego komunikatu o błędzie systemu z programu
- Uruchom ponownie program z strace
- Znajdź w wynikach śledzenia komunikat o błędzie
- Idź w górę, aż natrafisz na pierwsze nieudane wywołanie systemowe
Bardzo prawdopodobne, że wywołanie systemowe w 4. kroku wskaże, co poszło nie tak.
Wskazówki
Zanim pokażę przykład bardziej zaawansowanego debugowania, przedstawię kilka wskazówek dotyczących efektywnego korzystania z. strace:
man — twój przyjaciel
W wielu systemach *nix pełną listę wywołań systemowych do jądra można uzyskać, uruchamiając man syscalls. Zobaczysz rzeczy takie jak brk(2), co oznacza, że więcej informacji można uzyskać, uruchamiając man 2 brk.
Małe pułapki: man 2 fork pokazuje mi stronę dla powłoki fork() do GNU libc, która, jak się okazuje, jest realizowana przy użyciu wywołania clone(). Semantyka wywołania fork pozostaje ta sama, jeśli napiszesz program korzystający z fork(), a śledzenie — nie znajdę wywołań fork, zamiast nich będą clone(). Takie pułapki wprowadzają w błąd, jeśli zaczynasz porównywać źródło z wyjściem. strace.
Użyj -o, aby zapisać wyjście do pliku
strace może generować obszerną zawartość, więc często przydatne jest przechowywanie wyników śledzenia w oddzielnych plikach (jak w powyższym przykładzie). To również pomaga uniknąć pomyłek między wyjściem programu a wyjściem strace w konsoli.
Użyj -s, aby zobaczyć więcej danych argumentu
Z pewnością zauważyłeś, że druga część komunikatu o błędzie nie została pokazana w powyższym przykładzie śledzenia. To dlatego, że strace domyślnie pokazuje tylko pierwsze 32 bajty argumentu ciągu. Jeśli chcesz widzieć więcej, dodaj coś takiego jak -s 128 do wywołania strace.
-u ułatwia śledzenie plików, gniazd i innych.
"Wszystko jest plikiem" oznacza, że systemy *nix realizują wszystkie operacje I/O, korzystając z deskryptorów plików, niezależnie od tego, czy dotyczy to pliku, sieci czy kanałów międzyprocesowych. Jest to wygodne dla programowania, ale utrudnia śledzenie rzeczywistych działań, gdy widzisz ogólne read i write w wynikach śledzenia wywołań systemowych.
Dodając opcję -u, zmusisz strace do oznaczenia każdego deskryptora pliku w wyjściu z adnotacją, na co wskazuje.
Przyłącz się do już uruchomionego procesu z -p**
Jak widać w poniższym przykładzie, czasami trzeba śledzić program, który już działa. Jeśli wiadomo, że jest uruchamiany jako proces 1337 (powiedzmy, z wyjść ps), można go śledzić w ten sposób:
$ strace -p 1337
...wynik śledzenia wywołań systemowych...Możesz potrzebować praw root.
Użyj -f, aby śledzić procesy podrzędne.
strace Domyślnie śledzi tylko jeden proces. Jeśli ten proces generuje procesy potomne, można zobaczyć wywołanie systemowe do utworzenia procesu potomnego, ale wywołania systemowe procesu potomnego nie będą wyświetlane.
Jeśli uważasz, że problem tkwi w procesie potomnym, użyj operatora -f, to włączy jego śledzenie. Minusem tego jest to, że wyniki będą jeszcze bardziej mylące. Kiedy strace śledzi jeden proces lub jedną gałąź, pokazuje jedną sekwencję zdarzeń wywołań. Kiedy śledzi wiele procesów, możesz zobaczyć początek wywołania, przerwany komunikatem <unfinished …>, następnie grupę wywołań dla innych gałęzi wykonania, a dopiero potem zakończenie pierwszego z <… foocall resumed>. Albo podziel wszystkie wyniki śledzenia na różne pliki, używając również operatora -ff (szczegóły — w w strace).
Filtruj śledzenie za pomocą -e
Jak widać, wynik śledzenia to rzeczywista masa wszystkich możliwych wywołań systemowych. Flaga -e może filtrować śledzenie (patrz w strace). Główną zaletą jest to, że uruchomienie śledzenia z filtrowaniem jest szybsze niż robienie pełnego śledzenia, a potem grep`anie. Szczerze mówiąc, rzadko mnie to obchodzi.
Nie wszystkie błędy są złe
Prosty i powszechny przykład to program, który szuka pliku w kilku miejscach, jak powłoka, która szuka, w którym koszu znajduje się plik wykonywalny:
$ strace sh -c uname
...
stat("/home/user/bin/uname", 0x7ffceb817820) = -1 ENOENT (Brak takiego pliku lub katalogu)
stat("/usr/local/bin/uname", 0x7ffceb817820) = -1 ENOENT (Brak takiego pliku lub katalogu)
stat("/usr/bin/uname", {st_mode=S_IFREG|0755, st_size=39584, ...}) = 0
...Heurystyka typu „ostatnie nieudane zapytanie przed komunikatem o błędzie” jest dobra w poszukiwaniu istotnych błędów. W każdym razie logiczne jest, aby zacząć od samego końca.
Zrozumienie wywołań systemowych dobrze wspierają przewodniki po programowaniu w języku C.
Standardowe wywołania do bibliotek C nie są wywołaniami systemowymi, lecz jedynie cienką warstwą powierzchniową. Dlatego jeśli masz choć trochę pojęcia o tym, jak i co zrobić w C, będzie łatwiej zrozumieć wyniki śledzenia wywołań systemowych. Na przykład, jeśli masz problemy z debugowaniem wywołań do systemów sieciowych, sprawdź klasyczne .
Przykład debugowania bardziej skomplikowany.
Już mówiłem, że przykład prostego debugowania to coś, z czym najczęściej muszę się zmagać w pracy z strace. Jednak czasami wymaga to prawdziwego dochodzenia, więc oto rzeczywisty przykład bardziej skomplikowanego debugowania.
— to harmonogram zadań, kolejna implementacja demona *nix cron. Jest zainstalowany na serwerze, ale kiedy ktoś próbuje edytować harmonogram, dzieje się coś takiego:
# crontab -e -u logs
bcrontab: Fatal: Could not create temporary fileDobrze, więc bcron próbował napisać jakiś plik, ale mu się nie udało i nie przyznaje się dlaczego. Rozpoczynamy strace:
# strace -o /tmp/trace crontab -e -u logs
bcrontab: Fatal: Could not create temporary file
# cat /tmp/trace
...
openat(AT_FDCWD, "bcrontab.14779.1573691864.847933", O_RDONLY) = 3
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f82049b4000
read(3, "#Ansible: logsaggn20 14 * * * lo"..., 8192) = 150
read(3, "", 8192) = 0
munmap(0x7f82049b4000, 8192) = 0
close(3) = 0
socket(AF_UNIX, SOCK_STREAM, 0) = 3
connect(3, {sa_family=AF_UNIX, sun_path="/var/run/bcron-spool"}, 110) = 0
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f82049b4000
write(3, "156:Slogs #Ansible: logsaggn20 1"..., 161) = 161
read(3, "32:ZCould not create temporary f"..., 8192) = 36
munmap(0x7f82049b4000, 8192) = 0
close(3) = 0
write(2, "bcrontab: Fatal: Could not creat"..., 49) = 49
unlink("bcrontab.14779.1573691864.847933") = 0
exit_group(111) = ?
+++ exited with 111 +++Na samym końcu jest komunikat o błędzie write, ale tym razem coś się różni. Po pierwsze, brakuje odpowiedniego błędu wywołania systemowego, który zazwyczaj występuje przed tym. Po drugie, widać, że gdzieś ktoś już przeczytał komunikat o błędzie. Wygląda na to, że prawdziwy problem jest gdzie indziej, a bcrontab po prostu reprodukuje komunikat.
Jeśli spojrzymy na man 2 read, to możemy zobaczyć, że pierwszy argument (3) to deskryptor pliku, który *nix używa do wszelkiej obsługi wejścia-wyjścia. Jak dowiedzieć się, co reprezentuje deskryptor pliku 3? W tym konkretnym przypadku można uruchomić strace z operatorem -u (patrz wyżej), a on automatycznie to zobrazuje, jednak aby obliczać podobne rzeczy, dobrze wiedzieć, jak czytać i analizować wyniki śledzenia.
Źródłem deskryptora pliku może być jedno z wielu wywołań systemowych (wszystko zależy od tego, do czego deskryptor jest używany — do konsoli, gniazda sieciowego, rzeczywistego pliku lub czegoś innego), ale tak czy inaczej, wywołania szukamy, zwracając 3 (tzn. szukając „= 3” w wynikach śledzenia). W tym wyniku są 2: openat na samej górze i socket w środku. openat otwiera plik, ale zamknąć(3) po tym pokaże, że znowu się zamyka. (Pułapka: deskryptory plików mogą być na nowo używane, gdy są otwierane i zamykane). Wywołanie socket() pasuje, ponieważ jest ostatnie przed read(), i okazuje się, że bcrontab działa z czymś przez gniazdo. Następna linia pokazuje, że deskryptor pliku jest związany z unix domain socket po ścieżce /var/run/bcron-spool.
Więc trzeba znaleźć proces, powiązany z unix socket z drugiej strony. W tym celu jest kilka eleganckich sztuczek, które będą przydatne do debugowania wdrożeń serwerowych. Pierwsza — użyć netstat lub nowszego ss (status gniazda). Obie komendy pokazują aktywne połączenia sieciowe systemu i przyjmują operator -l do opisu gniazd nasłuchujących, a także operator -p do wyświetlania programów podłączonych do gniazda jako klient. (Jest wiele bardziej użytecznych opcji, ale na tę chwilę wystarczą te dwie.)
# ss -pl | grep /var/run/bcron-spool
u_str LISTEN 0 128 /var/run/bcron-spool 1466637 * 0 users:(("unixserver",pid=20629,fd=3))To oznacza, że nasłuchująca to komenda inixserver, działająca z identyfikatorem procesu 20629. (A tak się składa, że używa deskryptora pliku 3 jako gniazda.)
Drugi naprawdę przydatny narzędzie do uzyskania tych samych informacji nazywa się lsof. Wypisuje wszystkie otwarte pliki (lub deskryptory plików) w systemie. Można też uzyskać informacje o jednym konkretnym pliku:
# lsof /var/run/bcron-spool
COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME
unixserve 20629 cron 3u unix 0x000000005ac4bd83 0t0 1466637 /var/run/bcron-spool type=STREAMProces 20629 to długo żyjący serwer, więc można go podłączyć strace przy pomocy czegoś takiego jak strace -o /tmp/trace -p 20629. Jeśli edytujesz zadanie cron w innym terminalu — otrzymasz wyniki śledzenia z występującym błędem. A oto wynik:
accept(3, NULL, NULL) = 4
clone(child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7faa47c44810) = 21181
close(4) = 0
accept(3, NULL, NULL) = ? ERESTARTSYS (Do ponownego uruchomienia, jeśli SA_RESTART jest ustawiony)
--- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=21181, si_uid=998, si_status=0, si_utime=0, si_stime=0} ---
wait4(0, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], WNOHANG|WSTOPPED, NULL) = 21181
wait4(0, 0x7ffe6bc36764, WNOHANG|WSTOPPED, NULL) = -1 ECHILD (Brak procesów podrzędnych)
rt_sigaction(SIGCHLD, {sa_handler=0x55d244bdb690, sa_mask=[CHLD], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7faa47ab9840}, {sa_handler=0x55d244bdb690, sa_mask=[CHLD], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7faa47ab9840}, 8) = 0
rt_sigreturn({mask=[]}) = 43
accept(3, NULL, NULL) = 4
clone(child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7faa47c44810) = 21200
close(4) = 0
accept(3, NULL, NULL) = ? ERESTARTSYS (Do ponownego uruchomienia, jeśli SA_RESTART jest ustawiony)
--- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=21200, si_uid=998, si_status=111, si_utime=0, si_stime=0} ---
wait4(0, [{WIFEXITED(s) && WEXITSTATUS(s) == 111}], WNOHANG|WSTOPPED, NULL) = 21200
wait4(0, 0x7ffe6bc36764, WNOHANG|WSTOPPED, NULL) = -1 ECHILD (Brak procesów podrzędnych)
rt_sigaction(SIGCHLD, {sa_handler=0x55d244bdb690, sa_mask=[CHLD], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7faa47ab9840}, {sa_handler=0x55d244bdb690, sa_mask=[CHLD], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7faa47ab9840}, 8) = 0
rt_sigreturn({mask=[]}) = 43
accept(3, NULL, NULL)(Ostatni accept() nie zostanie zakończony podczas śledzenia.) I znowu, jak bardzo bym tego nie żałował, ale ten wynik nie zawiera błędu, którego szukamy. Nie widzimy żadnych wiadomości, które bcrontag wysyłał do gniazda lub otrzymywał od niego. Zamiast tego cała kontrola procesu (clone, wait4, SIGCHLD i inne). Ten proces generuje proces potomny, który, jak można się domyślić, wykonuje prawdziwą pracę. A jeśli trzeba uchwycić jego ślad, dodaj do wywołania strace -f. Oto co znajdziemy, szukając komunikatu o błędzie w nowym wyniku za pomocą strace -f -o /tmp/trace -p 20629:
21470 openat(AT_FDCWD, "tmp/spool.21470.1573692319.854640", O_RDWR|O_CREAT|O_EXCL, 0600) = -1 EACCES (Odmowa dostępu)
21470 write(1, "32:ZNie można utworzyć tymczasowego pliku f"..., 36) = 36
21470 write(2, "bcron-spool[21470]: Fatal: logs:"..., 84) = 84
21470 unlink("tmp/spool.21470.1573692319.854640") = -1 ENOENT (Brak takiego pliku lub katalogu)
21470 exit_group(111) = ?
21470 +++ zakończono z kodem 111 +++Oto, to już coś. Proces 21470 otrzymuje błąd „odmowa dostępu” podczas próby utworzenia pliku w ścieżce tmp/spool.21470.1573692319.854640 (odnoszącym się do bieżącego katalogu roboczego). Gdybyśmy tylko wiedzieli, jaki jest bieżący katalog roboczy, wiedzielibyśmy także pełną ścieżkę i moglibyśmy ustalić, dlaczego proces nie może w nim utworzyć swojego tymczasowego pliku. Niestety, proces już zakończono, więc nie można po prostu użyć lsof -p 21470 żeby znaleźć bieżący katalog, ale można działać w odwrotną stronę - poszukać wywołań systemowych PID 21470, które zmieniają katalog. (Jeśli takich nie ma, PID 21470 musiał dziedziczyć je od rodzica, a to już przez lsof -p nie da się ustalić.) Tym wywołaniem systemowym jest chdir (co można łatwo ustalić za pomocą nowoczesnych wyszukiwarek internetowych). Oto wyniki naszych odwrotnych poszukiwań, aż do samego serwera PID 20629:
20629 clone(child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7faa47c44810) = 21470
...
21470 execve("/usr/sbin/bcron-spool", ["bcron-spool"], 0x55d2460807e0 /* 27 vars */) = 0
...
21470 chdir("/var/spool/cron") = 0
...
21470 openat(AT_FDCWD, "tmp/spool.21470.1573692319.854640", O_RDWR|O_CREAT|O_EXCL, 0600) = -1 EACCES (Odmowa dostępu)
21470 write(1, "32:ZNie można utworzyć tymczasowego f"..., 36) = 36
21470 write(2, "bcron-spool[21470]: Fatal: logs:"..., 84) = 84
21470 unlink("tmp/spool.21470.1573692319.854640") = -1 ENOENT (Brak takiego pliku lub katalogu)
21470 exit_group(111) = ?
21470 +++ zakończono z kodem 111 +++(Jeśli się gubisz, być może powinieneś przeczytać mój poprzedni post .) A więc, serwer PID 20629 nie uzyskał uprawnień do stworzenia pliku pod tą ścieżką /var/spool/cron/tmp/spool.21470.1573692319.854640. Najprawdopodobniej przyczyną są klasyczne ustawienia uprawnień w systemie plików. Sprawdźmy:
# ls -ld /var/spool/cron/tmp/
drwxr-xr-x 2 root root 4096 Nov 6 05:33 /var/spool/cron/tmp/
# ps u -p 20629
USER PID %CPU %MEM VSZ RSS TTY STAT START TIME COMMAND
cron 20629 0.0 0.0 2276 752 ? Ss Nov14 0:00 unixserver -U /var/run/bcron-spool -- bcron-spoolOto gdzie tkwi problem! Serwer działa jako użytkownik cron, ale tylko root ma uprawnienia do zapisywania w katalogu /var/spool/cron/tmp/. Prosta komenda chown cron /var/spool/cron/tmp/ rozwiąże to bcron działać poprawnie. (Jeśli problem nie leżał w tym, to następny najbardziej prawdopodobny podejrzany to moduł bezpieczeństwa jądra typu SELinux lub AppArmor, więc sprawdziłbym dziennik zdarzeń jądra za pomocą dmesg.)
Podsumowując
Zarówno dla początkujących, jak i w wynikach śledzenia wywołań systemowych można się pogubić, ale mam nadzieję, że pokazałem, że są one szybkim sposobem na debugowanie całej klasy powszechnych problemów z wdrożeniem. Wyobraź sobie, jak próbujesz debugować aplikację wieloprocesową bcron, używając debuggera krokowego.
Analizowanie wyników śledzenia wstecz wzdłuż łańcucha wywołań systemowych wymaga umiejętności, ale jak już wspomniałem, prawie zawsze, korzystając z strace, po prostu uzyskuję wyniki śledzenia i szukam błędów, zaczynając od końca. W każdym razie, strace ułatwia mi to zaoszczędzenie mnóstwa czasu na debugowaniu. Mam nadzieję, że będzie to również pomocne dla Ciebie.
Źródło: habr.com
