Lo que Vanya probó
Vanya sabía que iba a probar el paquete "nginx + service".
Aquí haré un comentario de inmediato: se eligió un paquete de este tipo para este artículo simplemente porque puede demostrar de manera más clara el uso de varias utilidades al depurar un problema y porque es muy simple de configurar y generar. En la vida real, puede ser solo un servicio o una cadena de servicios que se solicitan entre sí.
El servidor HTTP predeterminado Python SimpleHTTPServer actúa como un servicio que, en respuesta a una solicitud sin parámetros, muestra el contenido del directorio actual:
[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/) ...
Nginx se configura de la siguiente manera:
upstream test {
server 127.0.0.1:8000;
}
server {
listen 80;
location / {
proxy_pass http://test;
}
}
Vanya necesitaba probar un solo caso de prueba: para verificar que la solicitud de / funciona. Comprobó y todo funcionó:
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>
Pero luego, en un momento del banco de pruebas, los desarrolladores actualizaron algo y Vanya recibió un error:
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>
Decidió no arrojar este error incomprensible a los desarrolladores, sino obtener acceso ssh al servidor y averiguar qué estaba pasando allí. Tenía poco conocimiento en el campo de este tipo de depuración de problemas, pero tenía muchas ganas de aprender, por lo que se armó con motores de búsqueda, lógica y fue a localizar el error.
El primer pensamiento de Vanya: troncos
De hecho, si ocurre un error, solo necesita encontrarlo en el archivo de registro. Pero primero debe encontrar el archivo de registro. Vanya fue a Google y descubrió que a menudo los registros se encuentran en el directorio / var / log . De hecho, el directorio nginx se encontró allí:
[root@ivan ~]# ls /var/log/nginx/
access.log access.log-20200831 error.log error.log-20200831
Ivan miró las últimas líneas del registro de errores y entendió qué estaba mal: los desarrolladores cometieron un error en la configuración de nginx, un error tipográfico se deslizó en el puerto de subida.
[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"
? — . - , , . nginx , , , ?
En ese momento, Vanya pensó: “¿Qué pasaría si los registros de nginx estuvieran en un directorio diferente? ¿Cómo los encontraría? " En un par de años, Vanya tendrá más experiencia con los servicios en Linux y sabrá que la ruta al archivo de registro a menudo se pasa al servicio como un argumento de línea de comando, o está contenida en un archivo de configuración, cuya ruta también se pasa a menudo al servicio como un argumento de línea de comando. Bueno, idealmente, la ruta al archivo de registro debería estar escrita en la documentación del servicio.
Por cierto, a través del archivo de configuración puede encontrar la ruta al archivo de registro en 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;
¿Y si no hay nada en los registros?
En su tiempo libre, Vanya decidió pensar en cómo habría hecho frente a la tarea si nginx no hubiera escrito nada en el registro. Vanya sabía que el servicio estaba escuchando en el puerto 8000, por lo que decidió observar el tráfico en este puerto en el servidor. La utilidad tcpdump lo ayudó con esto . Con la configuración correcta, vio una solicitud y una respuesta:
Volcado de tráfico en el puerto 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
Con una configuración incorrecta (con el puerto 8009 en el nginx upstream), no había tráfico en el puerto 8000. Vanya estaba encantada: ahora, incluso si los desarrolladores se olvidaron de escribir en el registro en caso de errores de red, al menos puede averiguar si el tráfico se dirige al host o puerto deseado.
¿Qué conclusión se puede sacar de esta historia? Incluso si no hay registros, Linux tiene utilidades que pueden ayudar a localizar problemas.
¿Y si no es una red?
Todo funcionó bien, pero un día Vanya volvió a recibir un error, esta 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 volvió al servidor, pero esta vez el problema no estaba relacionado con la red. El registro de servicio también decía Archivo no encontrado , y Vanya decidió averiguar por qué apareció de repente tal error. Sabe que hay un proceso python3 -m http.server , pero no sabe el contenido de qué directorio muestra este servicio (o, en otras palabras, cuál es el directorio de trabajo actual de este proceso). Se entera con el 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
También se puede hacer usando el comando pwdx o usando el directorio 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
Este directorio realmente existe en el servidor y contiene un archivo llamado test_file . ¿Qué pasa? Ivan buscó en Google y encontró la utilidad strace , con la que puede ver qué llamadas del sistema realiza un proceso (por cierto, hay un buen artículo sobre strace en Habré, y ni siquiera uno ). Puede iniciar un nuevo proceso a través de strace o conectarse con esta utilidad a un proceso que ya se esté ejecutando. La segunda opción le convenía a Vanya:
Salida de 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 ...>
Por lo general, la salida de strace es bastante voluminosa (y tal vez muy grande), por lo que es más conveniente redirigirla inmediatamente a un archivo y luego buscar las llamadas al sistema necesarias en él. En este caso, puede encontrar inmediatamente que el servicio está intentando abrir el directorio / root / test_dir_srv / - alguien le cambió el nombre y no reinició el servicio después de eso, por lo que devuelve 404.
Si entiende inmediatamente qué llamadas del sistema necesita mirar, puede usar la opción -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 no se detuvo allí y descubrió que existe un depurador de proyectos GNU: GDB . Con su ayuda, puede " entrar" en el proceso e incluso modificarlo ligeramente. Y Vanya decidió intentar encontrar el último error utilizando GDB . Sugirió que, dado que el servicio muestra el contenido del directorio, puede intentar poner un punto de interrupción en la función open () y ver qué sucede:
Salida de la utilidad 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]
Después del comando c ( continuar ) , Vanya lanzó curl en otra consola , alcanzó un punto de interrupción en el depurador y comenzó a ejecutar este programa (es decir, el servicio) paso a paso. Tan pronto como encontró abierto en algún nombre de ruta , imprimió el valor de esta variable y vio " / root / test_dir_srv / ".
GDB es una herramienta poderosa y este es el caso de uso más simple. A veces puede ayudar a reproducir cualquier caso complejo (por ejemplo, puede pausar el proceso en el momento adecuado y reproducir la condición de carrera), también ayuda a leer archivos de volcado del núcleo.
¿Y si Docker?
En un momento dado, DevOps decidió que el servicio ahora se implementaría con un contenedor Docker y era necesario volver a probar todos los casos que encontró Vanya. Vanya buscó en Google fácilmente lo siguiente:
- Puede usar tcpdump , strace y gdb dentro de un contenedor, pero debe tener en cuenta las capacidades de Linux (hay un artículo que explica por qué strace no funcionó en un contenedor sin --cap-add = SYS_PTRACE ).
- Se puede usar la opción --pid .
Pero se preguntó si era posible ver todo el tráfico yendo al contenedor (o desde el contenedor) directamente desde el anfitrión. En tcpdump tenemos la posibilidad de mostrar cualquier interfaz de tráfico (opción -i ), cada contenedor corresponde a una interfaz virtual Veth (esto se puede ver, por ejemplo, a través del ifconfig o la ip a ), pero ¿cómo sabes a qué contenedor le corresponde la interfaz? Si el contenedor no utiliza redes de host , dentro de él habrá una interfaz de red eth0 a través de la cual puede comunicarse a través de la red con otros contenedores y el host. Todo lo que queda es encontrar el ifindex de qué interfaz en el host coincide con la interfaz iflinketh0 del contenedor (puede leer lo que esto significa aquí ).
[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
Ahora puede ejecutar tcpdump en la interfaz veth6c18dba :
tcpdump -i veth6c18dba
Pero hay una manera más fácil: puede encontrar la dirección IP del contenedor en su red y escuchar el tráfico en él:
[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
Conclusión: depurar en un contenedor Docker no es un gran problema. Las utilidades funcionan en él y puede usar los registros de la ventana acoplable para leer los registros .
conclusiones
Como ingeniero responsable, Vanya decidió resumir brevemente la nueva información para sí mismo en la base de conocimientos interna. Esto es lo que escribió:
- Los troncos son el mejor amigo del hombre. Si se encuentra un comportamiento inesperado del servicio y al mismo tiempo no escribe nada en el registro, esta es una razón para pedir a los desarrolladores que agreguen registros.
- , , . , Linux , .
- tcpdump. , .
- «» strace, ltrace gdb.
- , Docker-.
- /proc/PID. , /proc/PID/fd .
- Las utilidades ps , ls , stat , lsof , ss , du , top , free , ip , ldconfig , ldd y otras también pueden ayudar a obtener información diversa sobre el sistema, archivos o procesos .
Espero que esta historia te haya sido útil y, al menos una vez, te ayude a comprender qué ocurre cuando depuras algo en Linux. Si Vanya se perdió algo, ¡compártelo en los comentarios!