Pag-debug ng software deployment na may strace

Pag-debug ng software deployment na may strace

Ang aking pang-araw-araw na trabaho ay halos pag-deploy ng software, na nangangahulugang gumugugol ako ng maraming oras sa pagsubok na sagutin ang mga tanong tulad ng:

  • Gumagana ang software na ito para sa developer, ngunit hindi para sa akin. Bakit?
  • Kahapon ang software na ito ay gumana para sa akin, ngunit ngayon ay hindi. Bakit?

Ito ay isang uri ng pag-debug na bahagyang naiiba sa regular na pag-debug ng software. Ang regular na pag-debug ay tungkol sa lohika ng code, ngunit ang deployment debugging ay tungkol sa pakikipag-ugnayan sa pagitan ng code at ng kapaligiran. Kahit na ang ugat ng problema ay isang lohikal na error, ang katotohanan na ang lahat ay gumagana sa isang makina at hindi sa isa pa ay nangangahulugan na ang problema ay sa paanuman sa kapaligiran.

Kaya sa halip na ang karaniwang mga tool sa pag-debug tulad ng gdb Mayroon akong ibang hanay ng mga tool para sa pag-debug ng deployment. At ang paborito kong tool para sa pagharap sa problema tulad ng "Bakit hindi gumagana ang software na ito para sa akin?" tinawag bakas.

Ano ang strace?

bakas ay isang tool para sa “system call tracing”. Ito ay orihinal na nilikha para sa Linux, ngunit ang parehong mga debugging trick ay maaaring gawin sa mga tool para sa iba pang mga system (DTrace o ktrace).

Ang pangunahing aplikasyon ay napaka-simple. Kailangan mo lang magpatakbo ng strace gamit ang anumang utos at itatapon nito ang lahat ng mga tawag sa system (bagaman kailangan mo munang i-install ito mismo bakas):

$ strace echo Hello
...Snip lots of stuff...
write(1, "Hellon", 6)                  = 6
close(1)                                = 0
close(2)                                = 0
exit_group(0)                           = ?
+++ exited with 0 +++

Ano ang mga tawag sa sistemang ito? Ito ay tulad ng isang API para sa kernel ng operating system. Noong unang panahon, ang software ay may direktang access sa hardware na pinapatakbo nito. Kung, halimbawa, kailangan nitong magpakita ng isang bagay sa screen, nilalaro nito ang mga port o memory-mapped na rehistro para sa mga video device. Nang naging tanyag ang multitasking computer system, naghari ang kaguluhan habang pinaglalabanan ng iba't ibang application ang hardware. Maaaring ibagsak ng mga error sa isang application ang iba, kung hindi ang buong system. Pagkatapos ay lumabas ang mga privilege mode (o “ring protection”) sa CPU. Ang kernel ang naging pinaka-pribilehiyo: nakatanggap ito ng ganap na pag-access sa hardware, na nagdulot ng hindi gaanong pribilehiyong mga application na kailangan nang humiling ng access mula sa kernel upang makipag-ugnayan sa hardware sa pamamagitan ng mga system call.

Sa binary level, ang isang system call ay bahagyang naiiba sa isang simpleng function call, ngunit karamihan sa mga program ay gumagamit ng isang wrapper sa karaniwang library. Yung. ang POSIX C standard library ay naglalaman ng function call sumulat (), na naglalaman ng lahat ng code na tukoy sa arkitektura para sa system call magsulat.

Pag-debug ng software deployment na may strace

Sa madaling salita, ang anumang pakikipag-ugnayan sa pagitan ng isang application at kapaligiran nito (mga sistema ng computer) ay isinasagawa sa pamamagitan ng mga tawag sa system. Samakatuwid, kapag gumagana ang software sa isang makina ngunit hindi sa isa pa, makabubuting tingnan ang mga resulta ng pagsubaybay sa tawag ng system. Higit na partikular, narito ang isang listahan ng mga tipikal na sandali na maaaring masuri gamit ang isang trace ng system call:

  • Console I/O
  • Network I/O
  • Pag-access sa file system at file I/O
  • Pamamahala sa buhay ng isang proseso ng thread
  • Mababang antas ng pamamahala ng memorya
  • Access sa mga partikular na driver ng device

Kailan gagamitin ang strace?

Sa teorya, bakas ginagamit sa anumang programa sa espasyo ng gumagamit, dahil ang anumang programa sa espasyo ng gumagamit ay dapat gumawa ng mga tawag sa system. Gumagana ito nang mas mahusay sa mga pinagsama-sama, mababang antas na mga programa, ngunit gumagana rin ito sa mga mataas na antas ng mga wika tulad ng Python kung maaari mong maputol ang karagdagang ingay mula sa runtime at interpreter.

Sa lahat ng karangyaan nito bakas nagpapakita ng sarili sa panahon ng pag-debug ng software na gumagana nang maayos sa isang makina, ngunit biglang huminto sa pagtatrabaho sa isa pa, na gumagawa ng mga hindi malinaw na mensahe tungkol sa mga file, pahintulot, o hindi matagumpay na mga pagtatangka na magsagawa ng ilang mga utos o iba pa... Sayang, ngunit hindi mahusay na pinagsama sa mga problemang may mataas na antas tulad ng mga error sa pag-verify ng certificate. Kadalasan ito ay nangangailangan ng kumbinasyon bakasminsan bakas at mas mataas na antas ng mga tool (tulad ng command line tool openssl upang i-debug ang sertipiko).

Gagamit kami ng standalone na server bilang isang halimbawa, ngunit ang pagsubaybay sa system call ay kadalasang maaaring gawin sa mas kumplikadong mga deployment platform. Kailangan mo lamang piliin ang mga tamang tool.

Simpleng halimbawa ng pag-debug

Sabihin nating gusto mong patakbuhin ang kamangha-manghang application ng server na foo, at ito ang hahantong sa iyo:

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

Tila hindi nito mahanap ang configuration file na iyong isinulat. Nangyayari ito dahil minsan kapag nag-compile ang mga manager ng package ng isang application, na-override nila ang mga inaasahang lokasyon ng file. At kung susundin mo ang gabay sa pag-install para sa isang pamamahagi, sa isa pa makikita mo ang mga file na ganap na naiiba mula sa kung saan mo inaasahan. Maaaring malutas ang problema sa loob ng ilang segundo kung sinabi ng mensahe ng error kung saan hahanapin ang configuration file, ngunit hindi. Kaya saan titingin?

Kung mayroon kang access sa source code, maaari mong basahin ito at alamin ang lahat. Isang magandang backup na plano, ngunit hindi ang pinakamabilis na solusyon. Maaari kang gumamit ng step-by-step na debugger tulad ng gdb at tingnan kung ano ang ginagawa ng programa, ngunit mas epektibong gumamit ng tool na partikular na idinisenyo upang ipakita ang pakikipag-ugnayan sa kapaligiran: bakas.

Pagbubuhos bakas maaaring mukhang kalabisan, ngunit ang mabuting balita ay ang karamihan sa mga ito ay maaaring ligtas na hindi papansinin. Madalas na kapaki-pakinabang na gamitin ang -o operator upang i-save ang mga resulta ng bakas sa isang hiwalay na file:

$ 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 +++

Tinatayang ang buong unang pahina ng output bakas - Ito ay karaniwang mababang antas ng paghahanda para sa paglulunsad. (Maraming tawag mmap, mprotekta, brk para sa mga bagay tulad ng pag-detect ng mababang antas ng memorya at pagpapakita ng mga dynamic na aklatan.) Sa totoo lang, habang nagde-debug ang output bakas Mas magandang basahin mula sa pinakadulo. Magkakaroon ng hamon sa ibaba magsulat, na nagpapakita ng mensahe ng error. Tumingin kami sa itaas at nakita ang unang maling tawag sa system - ang tawag openat, na nagtatapon ng error ENOENT (“file o directory not found”) sinusubukang buksan /etc/foo/config.json. Dito dapat naroroon ang configuration file.

Ito ay isang halimbawa lamang, ngunit sasabihin ko 90% ng oras na ginagamit ko bakas, wala nang mas mahirap gawin kaysa dito. Nasa ibaba ang isang kumpletong step-by-step na gabay sa pag-debug:

  • Magalit dahil sa isang hindi malinaw na mensahe tungkol sa isang system-y error mula sa isang program
  • I-restart ang program gamit ang bakas
  • Hanapin ang mensahe ng error sa mga resulta ng bakas
  • Pumunta nang mas mataas hanggang sa maabot mo ang unang nabigong tawag sa system

Malamang na ang system call sa hakbang 4 ay magbubunyag kung ano ang naging mali.

Mga tip

Bago magpakita sa iyo ng isang halimbawa ng mas kumplikadong pag-debug, magpapakita ako sa iyo ng ilang mga trick para sa epektibong paggamit bakas:

kaibigan mo ang lalaki

Sa maraming *nix system, ang kumpletong listahan ng mga system call sa kernel ay maaaring makuha sa pamamagitan ng pagpapatakbo lalaki syscalls. Makakakita ka ng mga bagay tulad ng brk(2), na nangangahulugang mas maraming impormasyon ang maaaring makuha sa pamamagitan ng pagpapatakbo tao 2 brk.

Maliit na rake: lalaki 2 tinidor ipinapakita sa akin ang pahina para sa shell tinidor () в GNU libc, na, lumalabas, ay ipinatupad sa pamamagitan ng pagtawag clone(). Tumawag ng semantics tinidor ay nananatiling pareho kung sumulat ka ng isang programa gamit tinidor (), at magpatakbo ng isang bakas - hindi ako makakahanap ng anumang mga tawag tinidor, sa halip na sila ay magkakaroon clone(). Ang ganitong mga rake ay nalilito lamang sa iyo kung sinimulan mong ihambing ang pinagmulan sa output bakas.

Gamitin ang -o upang i-save ang output sa isang file

bakas maaaring makabuo ng malawak na output, kaya kadalasan ay kapaki-pakinabang ang pag-imbak ng mga resulta ng bakas sa magkakahiwalay na mga file (tulad ng sa halimbawa sa itaas). Nakakatulong din ito upang maiwasan ang nakakalito na output ng programa sa output bakas sa console.

Gamitin ang -s upang tingnan ang higit pang data ng argumento

Maaaring napansin mo na ang ikalawang kalahati ng mensahe ng error ay hindi ipinapakita sa halimbawang bakas sa itaas. Ito ay dahil bakas Ang default ay nagpapakita lamang ng unang 32 byte ng string argument. Kung gusto mong makakita ng higit pa, magdagdag ng katulad ng -s 128 sa tawag bakas.

-y ginagawang mas madaling subaybayan ang mga file, socket, atbp.

Ang ibig sabihin ng "Lahat ay file" na ang *nix system ay gumagawa ng lahat ng I/O gamit ang mga descriptor ng file, nalalapat man iyon sa isang file o isang network o mga interprocess na pipe. Maginhawa ito para sa programming, ngunit ginagawang mahirap na subaybayan kung ano talaga ang nangyayari kapag nakikita mong karaniwan basahin и magsulat sa mga resulta ng trace ng system call.

Sa pamamagitan ng pagdaragdag ng operator oo, pipilitin mo bakas i-annotate ang bawat file descriptor sa output na may tala kung ano ang itinuturo nito.

Mag-attach sa isang tumatakbo nang proseso na may -p**

Tulad ng makikita mo mula sa halimbawa sa ibaba, minsan kailangan mong subaybayan ang isang programa na tumatakbo na. Kung ito ay kilala na ito ay tumatakbo bilang proseso 1337 (sabihin, mula sa output ps), pagkatapos ay masusubaybayan mo ito tulad nito:

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

Maaaring kailanganin mo ang mga karapatan sa ugat.

Gamitin ang -f para subaybayan ang mga proseso ng bata

bakas Bilang default, isang proseso lang ang sinusubaybayan nito. Kung ang prosesong ito ay nagbubunga ng mga proseso ng bata, makikita ang system call upang i-spawn ang proseso ng bata, ngunit ang mga tawag sa system ng proseso ng bata ay hindi ipapakita.

Kung sa tingin mo ay nasa proseso ng bata ang error, gamitin ang pahayag -f, papaganahin nito ang pagsubaybay nito. Ang downside dito ay mas malito ka pa ng output. Kailan bakas sumusubaybay sa isang proseso o isang thread, nagpapakita ito ng isang stream ng mga kaganapan sa tawag. Kapag sumubaybay ito ng maraming proseso nang sabay-sabay, maaari mong makita ang pagsisimula ng isang tawag na naantala ng isang mensahe , pagkatapos - isang grupo ng mga tawag para sa iba pang mga sangay ng pagpapatupad, at pagkatapos lamang - ang dulo ng una <…foocall ipinagpatuloy>. O hatiin ang lahat ng mga resulta ng bakas sa iba't ibang mga file, gamit din ang operator -ff (mga detalye sa gabay sa bakas).

I-filter ang mga bakas gamit ang -e

Tulad ng nakikita mo, ang resulta ng bakas ay isang tunay na tumpok ng lahat ng posibleng tawag sa system. Bandila -e Maaari mong i-filter ang bakas (tingnan pamumuno sa bakas). Ang pangunahing bentahe ay mas mabilis na magpatakbo ng isang na-filter na bakas kaysa gumawa ng isang buong bakas at pagkatapos grep`sa. Upang maging matapat, halos palaging wala akong pakialam.

Hindi lahat ng pagkakamali ay masama

Ang isang simple at karaniwang halimbawa ay isang program na naghahanap ng isang file sa ilang mga lugar nang sabay-sabay, tulad ng isang shell na naghahanap ng isang direktoryo na naglalaman ng isang executable file:

$ 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
...

Ang heuristics tulad ng "huling nabigong kahilingan bago mag-ulat ng error" ay mahusay sa paghahanap ng mga nauugnay na error. Magkagayunman, lohikal na magsimula sa pinakadulo.

Makakatulong sa iyo ang mga tutorial sa C programming na maunawaan ang mga tawag sa system.

Ang mga karaniwang tawag sa C library ay hindi mga system call, ngunit isang manipis na layer lamang sa ibabaw. Kaya, kung naiintindihan mo kahit kaunti kung paano at kung ano ang gagawin sa C, mas madali para sa iyo na maunawaan ang mga resulta ng trace ng system call. Halimbawa, nagkakaproblema ka sa pag-debug ng mga tawag sa mga network system, tingnan ang parehong classic Gabay ni Bija sa Network Programming.

Isang mas kumplikadong halimbawa ng pag-debug

Sinabi ko na na ang halimbawa ng simpleng pag-debug ay isang halimbawa ng kung ano ang kadalasang kailangan kong harapin kapag nagtatrabaho bakas. Gayunpaman, kung minsan ang isang tunay na pagsisiyasat ay kinakailangan, kaya narito ang isang totoong buhay na halimbawa ng mas advanced na pag-debug.

bcron - task processing scheduler, isa pang pagpapatupad ng *nix daemon cron. Naka-install ito sa server, ngunit kapag may sumubok na i-edit ang iskedyul, ito ang mangyayari:

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

Okay, ibig sabihin bcron sinubukang magsulat ng isang partikular na file, ngunit hindi ito gumana, at hindi niya aaminin kung bakit. Pagbubunyag bakas:

# 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 +++

Mayroong isang mensahe ng error malapit sa pinakadulo magsulat, ngunit sa pagkakataong ito ay may kakaiba. Una, walang nauugnay na error sa system call, na kadalasang nangyayari bago ito. Pangalawa, malinaw na sa isang lugar ay may nakabasa na ng mensahe ng error. Mukhang nasa ibang lugar ang totoong problema, at bcontab pinapatugtog lang ang mensahe.

Kung titingnan mo binasa ng lalaki 2, makikita mo na ang unang argumento (3) ay isang file descriptor, na ginagamit ni *nix para sa lahat ng pagproseso ng I/O. Paano ko malalaman kung ano ang kinakatawan ng file descriptor 3? Sa partikular na kaso na ito, maaari kang tumakbo bakas may operator oo (tingnan sa itaas) at awtomatiko nitong sasabihin sa iyo, ngunit para malaman ang mga bagay na tulad nito, kapaki-pakinabang na malaman kung paano basahin at i-parse ang mga resulta ng bakas.

Ang pinagmulan ng isang file descriptor ay maaaring isa sa maraming mga tawag sa system (lahat ito ay depende sa kung para saan ang descriptor - isang console, isang network socket, ang file mismo, o iba pa), ngunit kahit na ano ito, hinahanap namin mga tawag sa pamamagitan ng pagbabalik ng 3 (i.e. .e. hinahanap namin ang “= 3” sa mga resulta ng pagsubaybay). Sa resultang ito mayroong 2 sa kanila: openat sa pinakatuktok at socket Nasa gitna. openat binubuksan ang file ngunit malapit(3) ay magpapakita na ito ay muling nagsasara. (Rake: maaaring magamit muli ang mga deskriptor ng file kapag binuksan at isinara ang mga ito). Tumawag socket () angkop dahil ito ang huli bago basahin (), at lumalabas na gumagana ang bcontab sa isang bagay sa pamamagitan ng isang socket. Ang susunod na linya ay nagpapakita na ang file descriptor ay nauugnay sa unix domain socket sa daan /var/run/bcron-spool.

Kaya, kailangan nating hanapin ang prosesong nauugnay sa saksakan ng unix sa kabila. Mayroong ilang mga maayos na trick para sa layuning ito, na parehong kapaki-pakinabang para sa pag-debug ng mga deployment ng server. Ang una ay ang paggamit netstat o mas bago ss (katayuan ng socket). Ang parehong mga utos ay nagpapakita ng mga aktibong koneksyon sa network ng system at kinuha ang pahayag -l upang ilarawan ang mga socket sa pakikinig, gayundin ang operator -p upang ipakita ang mga program na konektado sa socket bilang isang kliyente. (Maraming mas kapaki-pakinabang na mga opsyon, ngunit ang dalawang ito ay sapat na para sa gawaing ito.)

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

Ito ay nagpapahiwatig na ang nakikinig ay ang utos inixserver, tumatakbo gamit ang process ID 20629. (At, nagkataon, gumagamit ito ng file descriptor 3 bilang socket.)

Ang pangalawang talagang kapaki-pakinabang na tool para sa paghahanap ng parehong impormasyon ay tinatawag lsof. Inililista nito ang lahat ng bukas na file (o mga deskriptor ng file) sa system. O maaari kang makakuha ng impormasyon tungkol sa isang partikular na file:

# 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

Ang Process 20629 ay isang mahabang buhay na server, kaya maaari mo itong ilakip bakas gamit ang isang bagay tulad ng strace -o /tmp/trace -p 20629. Kung mag-e-edit ka ng cron job sa ibang terminal, makakatanggap ka ng trace output na may error. At narito ang resulta:

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

(Huling tanggapin () ay hindi makukumpleto kapag sinusubaybayan.) Muli, sa kasamaang-palad, ang resultang ito ay hindi naglalaman ng error na hinahanap namin. Wala kaming nakikitang anumang mensahe na ipinapadala o natatanggap ng bcontag mula sa socket. Sa halip, kumpletuhin ang kontrol sa proseso (clone, maghintay4, SIGCHLD atbp.) Ang prosesong ito ay nagbubunga ng proseso ng bata, na, gaya ng maaari mong hulaan, ay talagang gumagana. At kung kailangan mong abutin ang kanyang landas, idagdag sa tawag guhit -f. Ito ang makikita natin kapag hinanap natin ang mensahe ng error sa bagong resulta na may 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 +++

Ngayon, iyan ay isang bagay. Nakatanggap ang Proseso 21470 ng error na "tinanggihan ang access" kapag sinusubukang gumawa ng file sa path tmp/spool.21470.1573692319.854640 (na may kaugnayan sa kasalukuyang gumaganang direktoryo). Kung alam lang natin ang kasalukuyang gumaganang direktoryo, malalaman din natin ang buong landas at malalaman natin kung bakit hindi makagawa ang proseso ng pansamantalang file nito. Sa kasamaang palad, ang proseso ay lumabas na, kaya hindi mo magagamit lsof -p 21470 upang mahanap ang kasalukuyang direktoryo, ngunit maaari kang magtrabaho sa kabaligtaran na direksyon - hanapin ang PID 21470 system na mga tawag na nagbabago sa direktoryo. (Kung wala, ang PID 21470 ay dapat na namana ang mga ito mula sa magulang nito, at ito ay sa pamamagitan na ng lsof -p hindi malaman.) This system call is chdir (na madaling malaman sa tulong ng mga modernong online na search engine). At narito ang resulta ng mga baligtad na paghahanap batay sa mga resulta ng bakas, hanggang sa server 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 +++

(Kung nawala ka, baka gusto mong basahin ang aking nakaraang post tungkol sa *nix process management at shell.) Kaya, ang server na PID 20629 ay hindi nakatanggap ng pahintulot na lumikha ng isang file sa path /var/spool/cron/tmp/spool.21470.1573692319.854640. Malamang, ang dahilan nito ay ang mga klasikong setting ng pahintulot ng file system. Suriin natin:

# 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

Doon nakalibing ang aso! Ang server ay tumatakbo bilang isang user cron, ngunit ang root lamang ang may pahintulot na sumulat sa direktoryo /var/spool/cron/tmp/. Simpleng utos chown cron /var/spool/cron/tmp/ pipilitin bcron gumana ng tama. (Kung hindi iyon ang problema, kung gayon ang susunod na malamang na pinaghihinalaan ay isang module ng seguridad ng kernel tulad ng SELinux o AppArmor, kaya susuriin ko ang log ng mensahe ng kernel gamit ang dmesg.)

Sa kabuuan

Ang mga bakas ng tawag sa system ay maaaring maging napakalaki para sa isang baguhan, ngunit umaasa akong naipakita ko na ang mga ito ay isang mabilis na paraan upang i-debug ang isang buong klase ng mga karaniwang problema sa pag-deploy. Isipin na sinusubukang i-debug ang isang multiprocess bcrongamit ang isang step-by-step na debugger.

Ang pag-parse ng mga resulta ng trace pabalik sa kadena ng tawag sa system ay nangangailangan ng kasanayan, ngunit tulad ng sinabi ko, halos palaging, gamit bakas, Nakukuha ko lang ang resulta ng bakas at naghahanap ng mga error simula sa dulo. Anyway, bakas tumutulong sa akin na makatipid ng maraming oras sa pag-debug. Umaasa ako na magiging kapaki-pakinabang din ito sa iyo.

Pinagmulan: www.habr.com

Magdagdag ng komento