
O que Vanya testou
Vanya sabia que iria testar o pacote "nginx + service".
Aqui, farei imediatamente uma observação: esse pacote foi escolhido para este artigo simplesmente porque pode demonstrar mais claramente o uso de vários utilitários ao depurar um problema e porque é muito fácil de configurar e aumentar. Em termos reais, pode ser apenas um serviço ou uma cadeia de serviços que fazem solicitações entre si.
O servidor HTTP padrão Python SimpleHTTPServer atua como um serviço que, em resposta a uma solicitação sem parâmetros, exibe o conteúdo do diretório atual:
[root@ivan test_dir_srv]# ls -l
total 0
-rw-r--r-- 1 root root 0 Aug 25 11:23 test_file
[root@ivan test_dir_srv]# python3 -m http.server --bind 127.0.0.1 8000
Serving HTTP on 127.0.0.1 port 8000 (http://127.0.0.1:8000/) ...
O Nginx é configurado da seguinte maneira:
upstream test {
server 127.0.0.1:8000;
}
server {
listen 80;
location / {
proxy_pass http://test;
}
}
Vanya precisava testar um único caso de teste: para verificar se a solicitação para / funciona. Ele verificou e tudo funcionou:
MacBook-Pro-Ivan:~ ivantester$ curl http://12.34.56.78
<!DOCTYPE HTML PUBLIC "-//W3C//DTD HTML 4.01//EN" "http://www.w3.org/TR/html4/strict.dtd">
<html>
<head>
<meta http-equiv="Content-Type" content="text/html; charset=utf-8">
<title>Directory listing for /</title>
</head>
<body>
<h1>Directory listing for /</h1>
<hr>
<ul>
<li><a href="test_file">test_file</a></li>
</ul>
<hr>
</body>
</html>
Mas então, em um ponto na bancada de teste, os desenvolvedores atualizaram algo e Vanya recebeu um erro:
MacBook-Pro-Ivan:~ ivantester$ curl http://12.34.56.78
<html>
<head><title>502 Bad Gateway</title></head>
<body bgcolor="white">
<center><h1>502 Bad Gateway</h1></center>
<hr><center>nginx/1.14.2</center>
</body>
</html>
Ele decidiu não jogar esse erro incompreensível para os desenvolvedores, mas obter acesso ssh ao servidor e descobrir o que estava acontecendo lá. Ele tinha pouco conhecimento na área desse tipo de depuração de problemas, mas ele realmente queria aprender, então se armou de mecanismos de busca, lógica e foi localizar o bug.
O primeiro pensamento de Vanya: toras
Na verdade, se ocorreu um erro, você só precisa localizá-lo no arquivo de log. Mas primeiro você precisa encontrar o próprio arquivo de log. Vanya foi ao Google e descobriu que frequentemente os logs estão no diretório / var / log . Na verdade, o diretório nginx foi encontrado lá:
[root@ivan ~]# ls /var/log/nginx/
access.log access.log-20200831 error.log error.log-20200831
Ivan olhou para as últimas linhas do log de erros e percebeu o que estava errado: os desenvolvedores cometeram um erro na configuração do nginx, um erro de digitação na porta upstream.
[root@ivan ~]# tail /var/log/nginx/error.log
2020/08/31 04:36:21 [error] 15050#15050: *90452 connect() failed (111: Connection refused) while connecting to upstream, client: 31.170.95.221, server: , request: "GET / HTTP/1.0", upstream: "http://127.0.0.1:8009/", host: "12.34.56.78"
Que conclusão pode ser tirada disso? Logs são os melhores amigos de testadores e desenvolvedores ao localizar bugs. Se houver algum comportamento inesperado do serviço, mas não houver nada nos logs, esse é um motivo para retornar a tarefa ao desenvolvimento com uma solicitação para adicionar logs. Afinal, se o nginx não tivesse escrito no log sobre uma tentativa malsucedida de alcançar o upstream, então, você vê, teria sido mais difícil procurar um problema?
Naquele momento, Vanya pensou: “E se os logs do nginx estivessem em um diretório diferente? Como eu os encontraria? " Em alguns anos, Vanya terá mais experiência com serviços no Linux e saberá que o caminho para o arquivo de log é frequentemente passado para o serviço como um argumento de linha de comando ou está contido em um arquivo de configuração, cujo caminho também é frequentemente passado para o serviço como um argumento de linha de comando. Bem, idealmente, o caminho para o arquivo de log deve ser escrito na documentação do serviço.
A propósito, por meio do arquivo de configuração, você pode encontrar o caminho para o arquivo de log no nginx:
[root@ivan ~]# ps ax | grep nginx | grep master
root 19899 0.0 0.0 57392 2872 ? Ss 2019 0:00 nginx: master process /usr/sbin/nginx -c /etc/nginx/nginx.conf
[root@ivan ~]# grep "log" /etc/nginx/nginx.conf
error_log /var/log/nginx/error.log warn;
log_format main '$remote_addr - $remote_user [$time_local] "$request" '
access_log /var/log/nginx/access.log main;
E se não houver nada nos registros?
Em seu tempo livre, Vanya decidiu pensar em como ele teria lidado com a tarefa se o nginx não tivesse escrito nada no log. Vanya sabia que o serviço estava escutando na porta 8000, então decidiu examinar o tráfego dessa porta no servidor. O utilitário tcpdump o ajudou com isso . Com a configuração correta, ele viu uma solicitação e uma resposta:
Despejar o tráfego na porta 8000
[root@ivan ~]# tcpdump -nn -i lo -A port 8000
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on lo, link-type EN10MB (Ethernet), capture size 262144 bytes
09:10:42.114284 IP 127.0.0.1.33296 > 127.0.0.1.8000: Flags [S], seq 3390176024, win 43690, options [mss 65495,sackOK,TS val 830366494 ecr 0,nop,wscale 8], length 0
E..<..@.@..............@.............0.........
1~c.........
09:10:42.114293 IP 127.0.0.1.8000 > 127.0.0.1.33296: Flags [S.], seq 4147196208, ack 3390176025, win 43690, options [mss 65495,sackOK,TS val 830366494 ecr 830366494,nop,wscale 8], length 0
E..<..@.@.<..........@...110.........0.........
1~c.1~c.....
09:10:42.114302 IP 127.0.0.1.33296 > 127.0.0.1.8000: Flags [.], ack 1, win 171, options [nop,nop,TS val 830366494 ecr 830366494], length 0
E..4..@.@..............@.....111.....(.....
1~c.1~c.
09:10:42.114329 IP 127.0.0.1.33296 > 127.0.0.1.8000: Flags [P.], seq 1:88, ack 1, win 171, options [nop,nop,TS val 830366494 ecr 830366494], length 87
E.....@.@..b...........@.....111...........
1~c.1~c.GET / HTTP/1.0
Host: test
Connection: close
User-Agent: curl/7.64.1
Accept: */*
09:10:42.114333 IP 127.0.0.1.8000 > 127.0.0.1.33296: Flags [.], ack 88, win 171, options [nop,nop,TS val 830366494 ecr 830366494], length 0
E..4R/@.@............@...111...p.....(.....
1~c.1~c.
09:10:42.115062 IP 127.0.0.1.8000 > 127.0.0.1.33296: Flags [P.], seq 1:155, ack 88, win 171, options [nop,nop,TS val 830366494 ecr 830366494], length 154
E...R0@.@............@...111...p...........
1~c.1~c.HTTP/1.0 200 OK
Server: SimpleHTTP/0.6 Python/3.7.2
Date: Mon, 07 Sep 2020 13:10:42 GMT
Content-type: text/html; charset=utf-8
Content-Length: 340
09:10:42.115072 IP 127.0.0.1.33296 > 127.0.0.1.8000: Flags [.], ack 155, win 175, options [nop,nop,TS val 830366494 ecr 830366494], length 0
E..4.@.@..............@...p.11......(.....
1~c.1~c.
09:10:42.115094 IP 127.0.0.1.8000 > 127.0.0.1.33296: Flags [P.], seq 155:495, ack 88, win 171, options [nop,nop,TS val 830366494 ecr 830366494], length 340
E...R1@.@..<.........@...11....p.....|.....
1~c.1~c.<!DOCTYPE HTML PUBLIC "-//W3C//DTD HTML 4.01//EN" "http://www.w3.org/TR/html4/strict.dtd">
<html>
<head>
<meta http-equiv="Content-Type" content="text/html; charset=utf-8">
<title>Directory listing for /</title>
</head>
<body>
<h1>Directory listing for /</h1>
<hr>
<ul>
<li><a href="test_file">test_file</a></li>
</ul>
<hr>
</body>
</html>
09:10:42.115098 IP 127.0.0.1.33296 > 127.0.0.1.8000: Flags [.], ack 495, win 180, options [nop,nop,TS val 830366494 ecr 830366494], length 0
E..4.
@.@..............@...p.13......(.....
1~c.1~c.
09:10:42.115128 IP 127.0.0.1.8000 > 127.0.0.1.33296: Flags [F.], seq 495, ack 88, win 171, options [nop,nop,TS val 830366494 ecr 830366494], length 0
E..4R2@.@............@...13....p.....(.....
1~c.1~c.
09:10:42.115264 IP 127.0.0.1.33296 > 127.0.0.1.8000: Flags [F.], seq 88, ack 496, win 180, options [nop,nop,TS val 830366495 ecr 830366494], length 0
E..4..@.@..............@...p.13 .....(.....
1~c.1~c.
09:10:42.115271 IP 127.0.0.1.8000 > 127.0.0.1.33296: Flags [.], ack 89, win 171, options [nop,nop,TS val 830366495 ecr 830366495], length 0
E..4R3@.@............@...13 ...q.....(.....
1~c.1~c.
^C
12 packets captured
24 packets received by filter
0 packets dropped by kernel
Com uma configuração incorreta (com a porta 8009 no upstream do nginx), não havia tráfego na porta 8000. Vanya ficou maravilhada: agora, mesmo que os desenvolvedores tenham esquecido de gravar no log em caso de erros de rede, você ainda pode pelo menos descobrir se o tráfego está indo para o host ou porta desejado.
Que conclusão pode ser tirada dessa história? Mesmo se não houver registros, o Linux tem utilitários que podem ajudar na localização de problemas.
E se não for uma rede?
Tudo funcionou bem, mas um dia Vanya voltou a receber um erro, desta vez diferente:
MacBook-Pro-Ivan:~ ivantester$ curl http://12.34.56.78
<!DOCTYPE HTML PUBLIC "-//W3C//DTD HTML 4.01//EN"
"http://www.w3.org/TR/html4/strict.dtd">
<html>
<head>
<meta http-equiv="Content-Type" content="text/html;charset=utf-8">
<title>Error response</title>
</head>
<body>
<h1>Error response</h1>
<p>Error code: 404</p>
<p>Message: File not found.</p>
<p>Error code explanation: HTTPStatus.NOT_FOUND - Nothing matches the given URI.</p>
</body>
</html>
Vanya foi ao servidor novamente, mas desta vez o problema não estava relacionado à rede. O registro do serviço também dizia Arquivo não encontrado , e Vanya decidiu descobrir por que esse erro apareceu de repente. Ele sabe que existe um processo python3 -m http.server , mas não sabe o conteúdo de qual diretório este serviço exibe (ou, em outras palavras, qual é o diretório de trabalho atual desse processo). Ele descobre com o comando lsof :
[root@ivan ~]# ps aux | grep python | grep "http.server"
root 20638 0.0 0.3 270144 13552 pts/2 S+ 08:29 0:00 python3 -m http.server
[root@ivan ~]# lsof -p 20638 | grep cwd
python3 20638 root cwd DIR 253,1 4096 1843551 /root/test_dir_srv2
Também pode ser feito usando o comando pwdx ou usando o diretório proc :
[root@ivan ~]# pwdx 20638 20638: /root/test_dir_srv2 [root@ivan ~]# ls -l /proc/20638/cwd lrwxrwxrwx 1 root root 0 Aug 31 08:37 /proc/20638/cwd -> /root/test_dir_srv2
Esse diretório realmente existe no servidor e contém um arquivo chamado test_file . Qual é o problema? Ivan pesquisou no Google e encontrou o utilitário strace , com o qual você pode ver quais chamadas de sistema o processo executa ( aliás, existe um bom artigo do Habré sobre strace , e nenhum ). Você pode iniciar um novo processo por meio do strace ou conectar-se com este utilitário a um processo já em execução. A segunda opção convinha a Vanya:
Saída Strace
[root@ivan ~]# strace -ff -p 20638
strace: Process 20638 attached
restart_syscall(<... resuming interrupted poll ...>) = 0
poll([{fd=4, events=POLLIN}], 1, 500) = 0 (Timeout)
poll([{fd=4, events=POLLIN}], 1, 500) = 0 (Timeout)
poll([{fd=4, events=POLLIN}], 1, 500) = 0 (Timeout)
poll([{fd=4, events=POLLIN}], 1, 500) = 0 (Timeout)
poll([{fd=4, events=POLLIN}], 1, 500) = 0 (Timeout)
poll([{fd=4, events=POLLIN}], 1, 500) = 1 ([{fd=4, revents=POLLIN}])
accept4(4, {sa_family=AF_INET, sin_port=htons(57530), sin_addr=inet_addr("127.0.0.1")}, [16], SOCK_CLOEXEC) = 5
clone(child_stack=0x7f2beeb28fb0, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, parent_tidptr=0x7f2beeb299d0, tls=0x7f2beeb29700, child_tidptr=0x7f2beeb299d0) = 21062
futex(0x11204d0, FUTEX_WAIT_PRIVATE, 0, NULLstrace: Process 21062 attached
<unfinished ...>
[pid 21062] set_robust_list(0x7f2beeb299e0, 24) = 0
[pid 21062] futex(0x11204d0, FUTEX_WAKE_PRIVATE, 1) = 1
[pid 20638] <... futex resumed> ) = 0
[pid 20638] futex(0x921c9c, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 27, {1598879772, 978949000}, ffffffff <unfinished ...>
[pid 21062] futex(0x921c9c, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x921c98, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
[pid 20638] <... futex resumed> ) = 0
[pid 20638] futex(0x921cc8, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...>
[pid 21062] futex(0x921cc8, FUTEX_WAKE_PRIVATE, 1) = 1
[pid 20638] <... futex resumed> ) = 0
[pid 20638] futex(0x921cc8, FUTEX_WAKE_PRIVATE, 1) = 0
[pid 20638] poll([{fd=4, events=POLLIN}], 1, 500 <unfinished ...>
[pid 21062] recvfrom(5, "GET / HTTP/1.1\r\nConnection: upgr"..., 8192, 0, NULL, NULL) = 153
[pid 21062] stat("/root/test_dir_srv/", 0x7f2beeb27350) = -1 ENOENT (No such file or directory)
[pid 21062] open("/root/test_dir_srv/", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
[pid 21062] write(2, "127.0.0.1 - - [31/Aug/2020 09:16"..., 70) = 70
[pid 21062] write(2, "127.0.0.1 - - [31/Aug/2020 09:16"..., 60) = 60
[pid 21062] sendto(5, "HTTP/1.0 404 File not found\r\nSer"..., 184, 0, NULL, 0) = 184
[pid 21062] sendto(5, "<!DOCTYPE HTML PUBLIC \"-//W3C//D"..., 469, 0, NULL, 0) = 469
[pid 21062] shutdown(5, SHUT_WR) = 0
[pid 21062] close(5) = 0
[pid 21062] madvise(0x7f2bee329000, 8368128, MADV_DONTNEED) = 0
[pid 21062] exit(0) = ?
[pid 21062] +++ exited with 0 +++
<... poll resumed> ) = 0 (Timeout)
poll([{fd=4, events=POLLIN}], 1, 500) = 0 (Timeout)
poll([{fd=4, events=POLLIN}], 1, 500) = 0 (Timeout)
poll([{fd=4, events=POLLIN}], 1, 500^Cstrace: Process 20638 detached
<detached ...>
Normalmente, a saída do strace é bastante volumosa (e talvez muito grande), por isso é mais conveniente redirecioná-la imediatamente para um arquivo e, em seguida, procurar as chamadas de sistema necessárias nele. Nesse caso, você pode descobrir imediatamente que o serviço está tentando abrir o diretório / root / test_dir_srv / - alguém o renomeou e não reiniciou o serviço depois disso, então ele retorna 404.
Se você entender imediatamente quais chamadas do sistema você precisa examinar, você pode usar a opção -e :
[root@ivan ~]# strace -ff -e trace=open,stat -p 20638
strace: Process 20638 attached
strace: Process 21396 attached
[pid 21396] stat("/root/test_dir_srv/", 0x7f2beeb27350) = -1 ENOENT (No such file or directory)
[pid 21396] open("/root/test_dir_srv/", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
[pid 21396] +++ exited with 0 +++
^Cstrace: Process 20638 detached
: « » , strace. , , (, / ), . ltrace.
- ?
Vanya não parou por aí e descobriu que existe um GNU Project Debugger - GDB . Com sua ajuda, você pode " entrar" no processo e até mesmo modificá-lo ligeiramente. E Vanya decidiu tentar encontrar o último erro usando GDB . Ele sugeriu que, como o serviço exibe o conteúdo do diretório, você pode tentar colocar um ponto de interrupção na função open () e ver o que acontece:
Saída do utilitário Gdb
[root@ivan ~]# gdb -p 23998
GNU gdb (GDB) Red Hat Enterprise Linux 7.6.1-119.el7
Copyright (C) 2013 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law. Type "show copying"
and "show warranty" for details.
This GDB was configured as "x86_64-redhat-linux-gnu".
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Attaching to process 23998
…
… < debugging symbols...>
...
0x00007f2284c0b20d in poll () at ../sysdeps/unix/syscall-template.S:81
81 T_PSEUDO (SYSCALL_SYMBOL, SYSCALL_NAME, SYSCALL_NARGS)
Missing separate debuginfos, use: debuginfo-install keyutils-libs-1.5.8-3.el7.x86_64 krb5-libs-1.15.1-34.el7.x86_64 libcom_err-1.42.9-13.el7.x86_64 libgcc-4.8.5-36.el7.x86_64 libselinux-2.5-14.1.el7.x86_64 openssl-libs-1.0.2k-16.el7.x86_64 pcre-8.32-17.el7.x86_64 zlib-1.2.7-18.el7.x86_64
(gdb) set follow-fork-mode child
(gdb) b open
Breakpoint 1 at 0x7f2284c06d20: open. (2 locations)
(gdb) c
Continuing.
[New Thread 0x7f227a165700 (LWP 24030)]
[Switching to Thread 0x7f227a165700 (LWP 24030)]
Breakpoint 1, open64 () at ../sysdeps/unix/syscall-template.S:81
81 T_PSEUDO (SYSCALL_SYMBOL, SYSCALL_NAME, SYSCALL_NARGS)
(gdb) n
83 T_PSEUDO_END (SYSCALL_SYMBOL)
(gdb) n
_io_FileIO___init___impl (opener=<optimized out>, closefd=<optimized out>, mode=<optimized out>, nameobj=0x7f227a68f6f0, self=0x7f227a68f6c0) at ./Modules/_io/fileio.c:381
381 Py_END_ALLOW_THREADS
(gdb) n
379 self->fd = open(name, flags, 0666);
(gdb) n
381 Py_END_ALLOW_THREADS
(gdb) print name
$1 = 0x7f227a687c90 "/root/test_dir_srv/"
(gdb) q
A debugging session is active.
Inferior 1 [process 23998] will be detached.
Quit anyway? (y or n) y
Detaching from program: /usr/local/bin/python3.7, process 23998
[Inferior 1 (process 23998) detached]
Após o comando c ( continuar ) , Vanya lançou o curl em outro console , atingiu um ponto de interrupção no depurador e começou a executar este programa (ou seja, o serviço) passo a passo. Assim que encontrou aberto em algum nome de caminho , ele imprimiu o valor desta variável e viu " / root / test_dir_srv / ".
GDB é uma ferramenta poderosa e aqui está o caso de uso mais simples. Às vezes, pode ajudar na reprodução de quaisquer casos complexos (por exemplo, você pode pausar o processo no momento certo e reproduzir a condição de corrida), também ajuda na leitura de arquivos de despejo de núcleo.
E se Docker?
Em um ponto, o DevOps decidiu que o serviço agora seria implantado com um contêiner Docker e foi necessário testar novamente todos os casos que Vanya encontrou. Vanya pesquisou facilmente o seguinte:
- Você pode usar tcpdump , strace e gdb dentro de um contêiner, mas você precisa ter em mente os recursos do Linux (há um artigo que explica por que o strace não funcionava em um contêiner sem --cap-add = SYS_PTRACE ).
- A opção --pid pode ser usada .
Mas ele se perguntou se era possível ver todo o tráfego indo para o contêiner (ou do contêiner) diretamente do host. No tcpdump temos a possibilidade de exibir qualquer interface de tráfego (opção -i ), cada container corresponde a uma interface virtual Veth (isso pode ser visto, por exemplo, através do ifconfig ou do ip a ), mas como saber a qual container a qual interface corresponde? Se o contêiner não usar rede de host , dentro dele haverá uma interface de rede eth0 , por meio da qual ele pode se comunicar pela rede com outros contêineres e o host. Tudo o que resta é encontrar o ifindex de qual interface no host corresponde à interface iflinketh0 do contêiner (você pode ler o que isso significa aqui ).
[root@ivan ~]# for f in `ls /sys/class/net/veth*/ifindex`; do echo $f; cat $f; done | grep -B 1 `docker exec test_service_container cat /sys/class/net/eth0/iflink` | head -1
/sys/class/net/veth6c18dba/ifindex
Agora você pode executar tcpdump na interface veth6c18dba :
tcpdump -i veth6c18dba
Mas há uma maneira mais fácil: você pode encontrar o endereço IP do contêiner em sua rede e ouvir o tráfego nele:
[root@ivan ~]# docker inspect -f '{{range .NetworkSettings.Networks}}{{.IPAddress}}{{end}}' test_service_container
172.17.0.10
[root@ivan ~]# tcpdump -i any host 172.17.0.10
Conclusão: a depuração em um contêiner do Docker não é grande coisa. Os utilitários funcionam nele e você pode usar os logs do docker para ler os logs .
conclusões
Como engenheiro responsável, Vanya decidiu delinear brevemente novas informações para si mesmo na base de conhecimento interna. Aqui está o que ele escreveu:
- Os troncos são os melhores amigos do homem. Se um comportamento inesperado do serviço for encontrado e, ao mesmo tempo, ele não gravar nada no log, esse é um motivo para pedir aos desenvolvedores que adicionem logs.
- , , . , Linux , .
- tcpdump. , .
- «» strace, ltrace gdb.
- , Docker-.
- /proc/PID. , /proc/PID/fd .
- Utilitários ps , ls , stat , lsof , ss , du , top , free , ip , ldconfig , ldd e outros também podem ajudar a obter várias informações sobre o sistema, arquivos ou processos .
Espero que esta história tenha sido útil para você, e pelo menos uma vez ela irá ajudá-lo a entender o que acontece quando você depura algo no Linux. Se Vanya perdeu algo, compartilhe nos comentários!