Debugowanie wdrażania oprogramowania za pomocą strace

Debugowanie wdrażania oprogramowania za pomocą strace

Na co dzień zajmuję się głównie wdrażaniem oprogramowania, co oznacza, że ​​dużo czasu poświęcam na odpowiadanie na pytania takie jak:

  • To oprogramowanie działa dla programisty, ale nie dla mnie. Dlaczego?
  • Wczoraj to oprogramowanie działało dla mnie, ale dzisiaj nie. Dlaczego?

Jest to rodzaj debugowania, który różni się nieco od zwykłego debugowania oprogramowania. Regularne debugowanie dotyczy logiki kodu, ale debugowanie wdrażania dotyczy interakcji między kodem a środowiskiem. Nawet jeśli przyczyną problemu jest błąd logiczny, fakt, że na jednym komputerze wszystko działa, a na innym nie, oznacza, że ​​problem tkwi w jakiś sposób w środowisku.

Zamiast zwykłych narzędzi do debugowania, takich jak gdb Mam inny zestaw narzędzi do debugowania wdrażania. I moje ulubione narzędzie do radzenia sobie z problemem, takie jak „Dlaczego to oprogramowanie nie działa w moim przypadku?” zwany strace.

Co to jest strace?

strace to narzędzie do „śledzenia wywołań systemowych”. Pierwotnie został stworzony dla systemu Linux, ale te same sztuczki debugowania można wykonać za pomocą narzędzi dla innych systemów (DTrace lub ktrace).

Podstawowa aplikacja jest bardzo prosta. Wystarczy uruchomić strace z dowolnym poleceniem, a wszystkie wywołania systemowe zostaną zrzucone (chociaż najpierw prawdopodobnie będziesz musiał zainstalować to samodzielnie 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 +++

Jakie są te wywołania systemowe? To coś w rodzaju API dla jądra systemu operacyjnego. Dawno, dawno temu oprogramowanie miało bezpośredni dostęp do sprzętu, na którym działało. Jeśli np. potrzebował wyświetlić coś na ekranie, bawił się portami lub rejestrami mapowanymi w pamięci urządzeń wideo. Kiedy popularne stały się wielozadaniowe systemy komputerowe, zapanował chaos, gdy różne aplikacje walczyły o sprzęt. Błędy w jednej aplikacji mogą spowodować awarię innych, jeśli nie całego systemu. Następnie w procesorze pojawiły się tryby przywilejów (lub „ochrona pierścieniowa”). Jądro stało się najbardziej uprzywilejowane: otrzymało pełny dostęp do sprzętu, dając początek mniej uprzywilejowanym aplikacjom, które już musiały prosić o dostęp z jądra, aby wchodzić w interakcję ze sprzętem poprzez wywołania systemowe.

Na poziomie binarnym wywołanie systemowe różni się nieco od prostego wywołania funkcji, ale większość programów korzysta z opakowania w bibliotece standardowej. Te. standardowa biblioteka POSIX C zawiera wywołanie funkcji pisać(), który zawiera cały kod specyficzny dla architektury dla wywołania systemowego napisać.

Debugowanie wdrażania oprogramowania za pomocą strace

Krótko mówiąc, wszelka interakcja aplikacji z jej otoczeniem (systemami komputerowymi) odbywa się poprzez wywołania systemowe. Dlatego też, gdy oprogramowanie działa na jednym komputerze, a nie na innym, dobrze byłoby przyjrzeć się wynikom śledzenia wywołań systemowych. Dokładniej, oto lista typowych punktów, które można analizować za pomocą śledzenia wywołań systemowych:

  • We/wy konsoli
  • We/wy sieciowe
  • Dostęp do systemu plików i operacje we/wy plików
  • Zarządzanie czasem życia wątku procesu
  • Zarządzanie pamięcią na niskim poziomie
  • Dostęp do konkretnych sterowników urządzeń

Kiedy używać strace?

W teorii, strace używany z dowolnym programem w przestrzeni użytkownika, ponieważ każdy program w przestrzeni użytkownika musi wykonywać wywołania systemowe. Działa wydajniej ze skompilowanymi programami niskiego poziomu, ale działa również z językami wysokiego poziomu, takimi jak Python, jeśli potrafisz odciąć się od dodatkowego szumu ze środowiska wykonawczego i interpretera.

W całej okazałości strace objawia się podczas debugowania oprogramowania, które działa dobrze na jednym komputerze, ale nagle przestaje działać na innym, generując niejasne komunikaty o plikach, uprawnieniach lub nieudanych próbach wykonania jakichś poleceń lub czegoś innego... Szkoda, ale tak nie jest dobrze komponują się z problemami wysokiego poziomu, takimi jak błędy weryfikacji certyfikatu. Zwykle wymaga to kombinacji strace, Czasami ślad i narzędzia wyższego poziomu (takie jak narzędzie wiersza poleceń openssl do debugowania certyfikatu).

Jako przykład wykorzystamy serwer autonomiczny, ale śledzenie wywołań systemowych często można przeprowadzić na bardziej złożonych platformach wdrożeniowych. Trzeba tylko wybrać odpowiednie narzędzia.

Prosty przykład debugowania

Powiedzmy, że chcesz uruchomić niesamowitą aplikację serwerową foo i oto co otrzymujesz:

$ foo
Error opening configuration file: No such file or directory

Najwyraźniej nie mógł znaleźć pliku konfiguracyjnego, który napisałeś. Dzieje się tak, ponieważ czasami, gdy menedżerowie pakietów kompilują aplikację, zastępują oczekiwane lokalizacje plików. A jeśli postępujesz zgodnie z instrukcją instalacji dla jednej dystrybucji, w innej znajdziesz pliki zupełnie inne niż się spodziewałeś. Problem można rozwiązać w ciągu kilku sekund, jeśli komunikat o błędzie będzie wskazywał, gdzie szukać pliku konfiguracyjnego, ale tak nie jest. Gdzie więc szukać?

Jeśli masz dostęp do kodu źródłowego, możesz go przeczytać i dowiedzieć się wszystkiego. Dobry plan tworzenia kopii zapasowych, ale nie najszybsze rozwiązanie. Możesz skorzystać z debugera krok po kroku, np gdb i zobacz, co program robi, ale o wiele skuteczniejsze jest użycie narzędzia, które jest specjalnie zaprojektowane do pokazywania interakcji z otoczeniem: strace.

Wniosek strace może wydawać się zbędne, ale dobra wiadomość jest taka, że ​​większość z nich można bezpiecznie zignorować. Często przydatne jest użycie operatora -o w celu zapisania wyników śledzenia w oddzielnym pliku:

$ strace -o /tmp/trace foo
Error opening configuration file: No such file or directory
$ cat /tmp/trace
execve("foo", ["foo"], 0x7ffce98dc010 /* 16 vars */) = 0
brk(NULL)                               = 0x56363b3fb000
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
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 (No such file or directory)
dup(2)                                  = 3
fcntl(3, F_GETFL)                       = 0x2 (flags O_RDWR)
brk(NULL)                               = 0x56363b3fb000
brk(0x56363b41c000)                     = 0x56363b41c000
fstat(3, {st_mode=S_IFCHR|0620, st_rdev=makedev(0x88, 0x8), ...}) = 0
write(3, "Error opening configuration file"..., 60) = 60
close(3)                                = 0
exit_group(1)                           = ?
+++ exited with 1 +++

Mniej więcej cała pierwsza strona wydruku strace - Zwykle jest to przygotowanie na niskim poziomie do startu. (Wiele rozmów mmap, ochrona, brk do rzeczy takich jak wykrywanie pamięci niskiego poziomu i wyświetlanie bibliotek dynamicznych.) Właściwie podczas debugowania danych wyjściowych strace Lepiej czytać od końca. Poniżej będzie wyzwanie napisać, który wyświetla komunikat o błędzie. Patrzymy powyżej i widzimy pierwsze błędne wywołanie systemowe - wywołanie otwórz, co powoduje błąd ENOENT („nie znaleziono pliku lub katalogu”) podczas próby otwarcia /etc/foo/config.json. Tutaj powinien znajdować się plik konfiguracyjny.

To był tylko przykład, ale powiedziałbym, że 90% czasu, którego używam strace, nie ma nic trudniejszego do zrobienia niż to. Poniżej znajduje się kompletny przewodnik debugowania krok po kroku:

  • Zdenerwuj się niejasnym komunikatem o błędzie systemowym z programu
  • Uruchom ponownie program za pomocą strace
  • Znajdź komunikat o błędzie w wynikach śledzenia
  • Idź wyżej, aż trafisz na pierwsze nieudane wywołanie systemowe

Jest bardzo prawdopodobne, że wywołanie systemowe w kroku 4 ujawni, co poszło nie tak.

Wskazówki

Zanim pokażę Ci przykład bardziej złożonego debugowania, pokażę Ci kilka trików pozwalających na efektywne wykorzystanie strace:

mężczyzna jest twoim przyjacielem

W wielu systemach *nix pełną listę wywołań systemowych do jądra można uzyskać uruchamiając człowiek wywołuje syscall. Zobaczysz takie rzeczy jak brk(2), co oznacza, że ​​więcej informacji można uzyskać biegnąc mężczyzna 2 br.

Małe grabie: widelec człowieka 2 pokazuje mi stronę powłoki widelec() в Biblioteka GNU, który, jak się okazuje, jest realizowany poprzez wywołanie klon(). Zadzwoń do semantyki widelec pozostaje taki sam, jeśli napiszesz program za pomocą widelec()i uruchom śledzenie — nie znajdę żadnych połączeń widelec, zamiast nich będzie klon(). Takie grabie tylko Cię dezorientują, jeśli zaczniesz porównywać źródło z wyjściem strace.

Użyj opcji -o, aby zapisać dane wyjściowe do pliku

strace może generować obszerne dane wyjściowe, dlatego często przydatne jest przechowywanie wyników śledzenia w oddzielnych plikach (jak w powyższym przykładzie). Pomaga to również uniknąć mylenia wyników programu z wynikami strace w konsoli.

Użyj opcji -s, aby wyświetlić więcej danych argumentów

Być może zauważyłeś, że druga połowa komunikatu o błędzie nie jest pokazana w powyższym przykładzie śledzenia. To dlatego, że strace domyślnie pokazuje tylko pierwsze 32 bajty argumentu ciągu. Jeśli chcesz zobaczyć więcej, dodaj coś takiego -s 128 na połączenie strace.

-y ułatwia śledzenie plików, gniazd itp.

„Wszystko jest plikiem” oznacza, że ​​systemy *nix wykonują wszystkie operacje we/wy przy użyciu deskryptorów plików, niezależnie od tego, czy dotyczy to pliku, sieci czy potoków międzyprocesowych. Jest to wygodne w programowaniu, ale utrudnia śledzenie tego, co naprawdę się dzieje, gdy widzisz coś wspólnego czytać и napisać w wynikach śledzenia wywołań systemowych.

Dodając operator tak, zmusisz strace dodaj adnotację do każdego deskryptora pliku w wynikach, zapisując, na co wskazuje.

Dołącz do już działającego procesu za pomocą -p**

Jak zobaczysz na poniższym przykładzie, czasami trzeba prześledzić program, który już działa. Jeśli wiadomo, że działa jako proces 1337 (powiedzmy, z pliku wyjściowego ps), możesz to prześledzić w ten sposób:

$ strace -p 1337
...system call trace output...

Możesz potrzebować praw root.

Użyj -f, aby monitorować procesy potomne

strace Domyślnie śledzi tylko jeden proces. Jeśli ten proces tworzy procesy potomne, wówczas wywołanie systemowe uruchamiające proces potomny będzie widoczne, ale wywołania systemowe procesu potomnego nie będą wyświetlane.

Jeśli uważasz, że błąd występuje w procesie potomnym, użyj instrukcji -f, umożliwi to jego śledzenie. Wadą tego jest to, że wynik będzie jeszcze bardziej dezorientujący. Gdy strace śledzi jeden proces lub jeden wątek, pokazuje pojedynczy strumień zdarzeń wywołania. Gdy śledzi wiele procesów jednocześnie, rozpoczęcie połączenia może zostać przerwane przez komunikat , następnie - seria wywołań innych gałęzi wykonawczych i dopiero wtedy - koniec pierwszej <…foocall wznowiony>. Lub podziel wszystkie wyniki śledzenia na różne pliki, również używając operatora -ff (szczegóły w przewodnik nadotycząca strace).

Filtruj ślady za pomocą -e

Jak widać, wynikiem śledzenia jest prawdziwy stos wszystkich możliwych wywołań systemowych. Flaga -e Możesz filtrować ślad (patrz руководство nadotycząca strace). Główną zaletą jest to, że szybciej jest uruchomić filtrowane śledzenie niż wykonać pełne śledzenie grepo godz. Szczerze mówiąc, prawie zawsze jest mi to obojętne.

Nie wszystkie błędy są złe

Prostym i powszechnym przykładem jest program wyszukujący plik w kilku miejscach jednocześnie, podobnie jak powłoka szukająca katalogu zawierającego plik wykonywalny:

$ strace sh -c uname
...
stat("/home/user/bin/uname", 0x7ffceb817820) = -1 ENOENT (No such file or directory)
stat("/usr/local/bin/uname", 0x7ffceb817820) = -1 ENOENT (No such file or directory)
stat("/usr/bin/uname", {st_mode=S_IFREG|0755, st_size=39584, ...}) = 0
...

Heurystyki takie jak „ostatnie nieudane żądanie przed zgłoszeniem błędu” są dobre w znajdowaniu odpowiednich błędów. Tak czy inaczej, logiczne jest zacząć od samego końca.

Samouczki dotyczące programowania w języku C mogą pomóc w zrozumieniu wywołań systemowych.

Standardowe wywołania bibliotek C nie są wywołaniami systemowymi, a jedynie cienką warstwą powierzchniową. Jeśli więc choć trochę zrozumiesz, jak i co robić w C, łatwiej będzie ci zrozumieć wyniki śledzenia wywołań systemowych. Na przykład masz problemy z debugowaniem wywołań do systemów sieciowych, spójrz na ten sam klasyk Przewodnik Bija po programowaniu sieciowym.

Bardziej złożony przykład debugowania

Mówiłem już, że przykład prostego debugowania jest przykładem tego, z czym najczęściej mam do czynienia podczas pracy strace. Czasami jednak wymagane jest prawdziwe dochodzenie, dlatego oto rzeczywisty przykład bardziej zaawansowanego debugowania.

bcron - harmonogram przetwarzania zadań, kolejna implementacja demona *nix cron. Jest zainstalowany na serwerze, ale gdy ktoś próbuje edytować harmonogram, dzieje się tak:

# crontab -e -u logs
bcrontab: Fatal: Could not create temporary file

OK, to znaczy bcron próbował napisać określony plik, ale nie wyszło, a on nie chce przyznać dlaczego. Odkrywanie 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 pojawia się komunikat o błędzie napisać, ale tym razem coś jest innego. Po pierwsze, nie ma istotnego błędu wywołania systemowego, który zwykle pojawia się wcześniej. Po drugie jasne jest, że gdzieś ktoś już przeczytał komunikat o błędzie. Wygląda na to, że prawdziwy problem leży gdzie indziej i bcrontab po prostu odtwarza wiadomość.

Jeśli spojrzysz na mężczyzna 2 przeczytaj, możesz zobaczyć, że pierwszy argument (3) jest deskryptorem pliku, którego *nix używa do całego przetwarzania we/wy. Jak mogę się dowiedzieć, co reprezentuje deskryptor pliku 3? W tym konkretnym przypadku możesz biegać strace z оператором tak (patrz wyżej) i automatycznie ci to powie, ale aby dowiedzieć się takich rzeczy, warto 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 służy deskryptor - konsoli, gniazda sieciowego, samego pliku czy czegoś innego), ale tak czy inaczej, szukamy wywołuje, zwracając 3 (tj. w wynikach śledzenia szukamy „= 3”). W tym wyniku są 2 z nich: otwórz na samej górze i gniazdo Pośrodku. otwórz otwiera plik ale zamknięte(3) pokaże następnie, że zamyka się ponownie. (Rake: deskryptory plików można ponownie wykorzystać podczas ich otwierania i zamykania). Dzwonić gniazdo elektryczne() nadaje się, bo to ostatni raz czytać()i okazuje się, że bcrontab współpracuje z czymś poprzez gniazdo. Następna linia pokazuje, z którym powiązany jest deskryptor pliku gniazdo domeny unix po drodze /var/run/bcron-szpula.

Musimy więc znaleźć proces z którym jest powiązany gniazdo unixowe z drugiej strony. W tym celu istnieje kilka sprytnych sztuczek, obie przydatne do debugowania wdrożeń serwerów. Pierwszym z nich jest użycie netstat lub nowsze ss (stan gniazda). Obydwa polecenia pokazują aktywne połączenia sieciowe systemu i pobierają instrukcję -l opisać gniazda podsłuchowe, a także operatora -p aby wyświetlić programy podłączone do gniazda jako klient. (Istnieje wiele innych przydatnych opcji, ale te dwie wystarczą do tego zadania.)

# ss -pl | grep /var/run/bcron-spool
u_str LISTEN 0   128   /var/run/bcron-spool 1466637   * 0   users:(("unixserver",pid=20629,fd=3))

Sugeruje to, że słuchacz jest rozkazem serwer inix, działający z identyfikatorem procesu 20629. (I przypadkowo używa deskryptora pliku 3 jako gniazda).

Drugie naprawdę przydatne narzędzie do wyszukiwania tych samych informacji nazywa się lsof. Zawiera listę wszystkich otwartych plików (lub deskryptorów plików) w systemie. Możesz 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=STREAM

Proces 20629 jest serwerem długowiecznym, więc można go do niego podłączyć strace używając czegoś takiego strace -o /tmp/trace -p 20629. Jeśli edytujesz zadanie cron w innym terminalu, otrzymasz wynik śledzenia z 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 (To be restarted if SA_RESTART is set)
--- 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 (No child processes)
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 (To be restarted if SA_RESTART is set)
--- 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 (No child processes)
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 zaakceptować() nie zostanie ukończony podczas śledzenia.) Niestety, ten wynik nie zawiera szukanego przez nas błędu. Nie widzimy żadnych komunikatów wysyłanych przez bcrontag do gniazda lub odbieranych z niego. Zamiast tego pełna kontrola procesu (klonować, czekać4, SIGCHLD itp.) Ten proces tworzy proces potomny, który, jak można się domyślić, wykonuje prawdziwą pracę. A jeśli chcesz złapać jej trop, dołącz do rozmowy strace -f. To właśnie 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 (Permission denied) 
21470 write(1, "32:ZCould not create temporary f"..., 36) = 36
21470 write(2, "bcron-spool[21470]: Fatal: logs:"..., 84) = 84
21470 unlink("tmp/spool.21470.1573692319.854640") = -1 ENOENT (No such file or directory)
21470 exit_group(111)                   = ?
21470 +++ exited with 111 +++

To już coś. Proces 21470 otrzymuje błąd „odmowa dostępu” podczas próby utworzenia pliku w ścieżce tmp/szpula.21470.1573692319.854640 (odnoszący się do bieżącego katalogu roboczego). Gdybyśmy tylko znali bieżący katalog roboczy, znalibyśmy również pełną ścieżkę i moglibyśmy dowiedzieć się, dlaczego proces nie może utworzyć w nim pliku tymczasowego. Niestety proces już się zakończył, więc nie możesz po prostu użyć lsof -p 21470 aby znaleźć bieżący katalog, ale możesz popracować w odwrotnym kierunku - poszukaj wywołań systemowych PID 21470 zmieniających katalog. (Jeśli ich nie ma, PID 21470 musiał odziedziczyć je od swojego rodzica, a to już minęło lsof -str nie można znaleźć.) To wywołanie systemowe to chdir (co łatwo sprawdzić za pomocą nowoczesnych wyszukiwarek internetowych). A oto wynik odwrotnego wyszukiwania na podstawie wyników śledzenia, aż do 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 (Permission denied) 
21470 write(1, "32:ZCould not create temporary f"..., 36) = 36
21470 write(2, "bcron-spool[21470]: Fatal: logs:"..., 84) = 84
21470 unlink("tmp/spool.21470.1573692319.854640") = -1 ENOENT (No such file or directory)
21470 exit_group(111)                   = ?
21470 +++ exited with 111 +++

(Jeśli się zgubiłeś, możesz przeczytać mój poprzedni post o zarządzaniu procesami *nix i powłokach.) Zatem serwer PID 20629 nie otrzymał pozwolenia na utworzenie pliku w ścieżce /var/spool/cron/tmp/spool.21470.1573692319.854640. Najprawdopodobniej przyczyną tego są klasyczne ustawienia uprawnień systemu 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-spool

To tam pochowany jest pies! Serwer działa jako cron użytkownika, ale tylko root ma uprawnienia do zapisu w katalogu /var/szpula/cron/tmp/. Proste polecenie chown cron /var/spool/cron/tmp/ zmusi bcron działać poprawnie. (Jeśli to nie był problem, następnym najprawdopodobniejszym podejrzanym jest moduł bezpieczeństwa jądra, taki jak SELinux lub AppArmor, więc sprawdziłbym dziennik komunikatów jądra za pomocą dmesg.)

Razem

Śledzenie wywołań systemowych może być przytłaczające dla początkującego, ale mam nadzieję, że pokazałem, że są szybkim sposobem na debugowanie całej klasy typowych problemów z wdrażaniem. Wyobraź sobie próbę debugowania procesu wieloprocesowego bcronza pomocą debugera krok po kroku.

Analizowanie wyników śledzenia wstecz w łańcuchu wywołań systemowych wymaga umiejętności, ale jak powiedziałem, prawie zawsze używania strace, po prostu otrzymuję wynik śledzenia i szukam błędów, zaczynając od końca. W każdym razie, strace pomaga mi zaoszczędzić dużo czasu na debugowaniu. Mam nadzieję, że będzie przydatny również dla Ciebie.

Źródło: www.habr.com

Dodaj komentarz