Как Иван ошибку в бэкенде локализовывал
В комментариях к одной из моих статей про базовые команды Linux shell для тестировщиков справедливо заметили, что в ней не было указано применение команд в процессе тестирования. Я подумал, что лучше поздно, чем никогда, поэтому решил рассказать историю Backend QA-инженера Вани, который столкнулся с неожиданным поведением сервиса и попытался разобраться, где именно случилась ошибка.
Ваня знал, что ему предстоит тестировать связку «nginx + сервис».
Здесь я сразу сделаю ремарку: такая связка была выбрана для этой статьи просто потому, что она нагляднее всего может продемонстрировать применение различных утилит при дебаге проблемы и потому, что её очень просто сконфигурировать и поднять. В реальных условиях это может быть либо просто сервис, либо цепочка сервисов, которые делают запросы друг другу.
В качестве сервиса выступает дефолтный HTTP сервер Python SimpleHTTPServer, который в ответ на запрос без параметров выводит содержимое текущей директории:
[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 же сконфигурирован следующим образом:
upstream test {
server 127.0.0.1:8000;
}
server {
listen 80;
location / {
proxy_pass http://test;
}
}
Ване нужно было протестировать один-единственный тест-кейс: проверить, что запрос на / работает. Он проверил, и всё работало:
MacBook-Pro-Ivan:~ ivantester$ curl http://12.34.56.78
Directory listing for /
Directory listing for /
Но затем в один момент на тестовом стенде разработчики что-то обновили, и Ваня получил ошибку:
MacBook-Pro-Ivan:~ ivantester$ curl http://12.34.56.78
502 Bad Gateway
502 Bad Gateway
nginx/1.14.2
Он решил не скидывать эту непонятную ошибку разработчикам, а получить доступ по ssh на сервер и разобраться, в чём там дело. Знаний в области такого рода дебага проблем у него было мало, но он очень хотел научиться, поэтому вооружился поисковиками, логикой и пошёл локализовывать баг.
Действительно, если случилась ошибка, то нужно просто найти её в лог-файле. Но сначала нужно найти сам лог-файл. Ваня полез в Google и узнал, что часто логи лежат в директории /var/log. Действительно, там нашлась директория nginx:
[root@ivan ~]# ls /var/log/nginx/
access.log access.log-20200831 error.log error.log-20200831
Иван посмотрел последние строчки error лога и понял, в чём дело: разработчики ошиблись в конфигурации nginx, в порт 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"
Какой можно сделать из этого вывод? Логи — лучший друг тестировщиков и разработчиков при локализации ошибок. Если есть какое-то неожиданное поведение сервиса, а в логах при этом ничего нет, то это повод вернуть задачу в разработку с просьбой добавить логов. Ведь если б nginx не писал в лог о неудачной попытке достучаться до апстрима, то, согласитесь, искать проблему было бы сложнее?
В тот момент Ваня задумался: «А что, если бы в nginx логи лежали в другой директории? Как бы я их нашёл?» Через пару лет у Вани будет больше опыта работы с сервисами в Linux, и он будет знать, что путь к лог-файлу часто передают сервису аргументом командной строки, либо он содержится в файле конфигурации, путь к которому также часто передают сервису аргументом командной строки. Ну и в идеале путь к лог-файлу должен быть прописан в документации сервиса.
Кстати, через файл конфигурации можно найти путь к лог-файлу и в 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;
В свободное время Ваня решил подумать, а как бы он справился с задачей, если бы nginx не писал ничего в лог. Ваня знал, что сервис слушает порт 8000, поэтому решил посмотреть трафик на этом порту на сервере. С этим ему помогла утилита tcpdump. При правильной конфигурации он видел запрос и ответ:
[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.
Directory listing for /
Directory listing for /
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
При неправильной конфигурации (с портом 8009 в апстриме nginx) на порту 8000 никакого трафика не было. Ваня обрадовался: теперь даже если разработчики забыли реализовать запись в лог при сетевых ошибках, всё равно можно хотя бы узнать, идёт ли трафик на нужный хост или порт.
Какой вывод можно сделать из этой истории? Даже если логов нет, в Linux есть утилиты, которые могут помочь с локализацией проблем.
Всё хорошо работало, но однажды Ваня снова получил ошибку, на этот раз другую:
MacBook-Pro-Ivan:~ ivantester$ curl http://12.34.56.78
Error response
Error response
Error code: 404
Message: File not found.
Error code explanation: HTTPStatus.NOT_FOUND - Nothing matches the given URI.
Ваня снова зашёл на сервер, но в этот раз проблема не была связана с сетью. В логе сервиса тоже было написано File not found, и Ваня решил разобраться, почему внезапно появилась такая ошибка. Он знает, что есть процесс python3 -m http.server, но не знает, содержимое какой директории выводит этот сервис (или, другими словами, какая у этого процесса current working directory). Он узнаёт это с помощью команды 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
Также это можно сделать с помощью команды pwdx или с помощью директории 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
Такая директория действительно есть на сервере, и в ней лежит файл с именем test_file. В чём же дело? Иван погуглил и нашёл утилиту strace, с помощью которой можно смотреть, какие системные вызовы выполняет процесс (про strace, кстати, есть хорошая статья на Хабре, и даже не одна). Можно либо запускать новый процесс через 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
[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
[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
[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
[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, " ) = 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
Обычно вывод strace довольно объёмный (а может быть и очень большим), поэтому удобнее сразу перенаправлять его в файл и потом уже искать в нём нужные системные вызовы. В данном же случае можно сразу обнаружить, что сервис пытается открыть директорию /root/test_dir_srv/ — кто-то переименовал её и не перезапустил после этого сервис, поэтому он возвращает 404.
Если сразу понятно, какие именно системные вызовы нужно посмотреть, можно использовать опцию -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.
Ваня на этом не остановился и узнал, что есть GNU Project Debugger — GDB. С его помощью можно »залезть» в процесс и даже немного модифицировать его. И Ваня решил попробовать обнаружить последнюю ошибку с помощью GDB. Он предположил, что раз сервис выводит содержимое директории, то можно попробовать поставить breakpoint на функции open () и посмотреть, что будет:
[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
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:
, closefd=, mode=, 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]
После команды c (continue) Ваня в другой консоли запустил curl, попал в дебаггере в точку останова и стал выполнять эту программу (то есть сервис) по шагам. Как только он нашёл в коде open по какому-то пути name, он вывел значение этой переменной и увидел »/root/test_dir_srv/».
GDB — это мощный инструмент, и здесь описан простейший вариант его использования. Иногда он может помочь в воспроизведении каких-либо сложных кейсов (например, можно приостановить процесс в нужный момент и воспроизвести состояние гонки), также он помогает с чтением core dump файлов.
В один момент DevOps решили, что сервис теперь будет деплоиться Docker-контейнером, и нужно было провести ретест всех кейсов, которые нашёл Ваня. Ваня без проблем нагуглил следующее:
- Использовать tcpdump, strace и gdb можно и внутри контейнера, но нужно иметь ввиду Linux capabilities (есть статья, которая объясняет, почему strace не работал в контейнере без --cap-add=SYS_PTRACE).
- Можно использовать опцию --pid.
Но ему стало интересно, можно ли посмотреть весь трафик, идущий в контейнер (или из контейнера), прям с хоста. У tcpdump есть возможность выводить трафик какого-либо интерфейса (опция -i), каждому контейнеру соответствует один виртуальный интерфейс veth (это можно увидеть, например, через ifconfig или ip a), но как понять, какому контейнеру какой интерфейс соответствует? Если контейнер не использует host networking, то внутри него будет сетевой интерфейс eth0, через который он может общаться по сети с другими контейнерами и хостом. Остаётся лишь найти, ifindex какого интерфейса на хосте совпадает с iflink интерфейса eth0 контейнера (что это означает можно почитать здесь).
[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
Теперь можно запускать tcpdump для интерфейса veth6c18dba:
tcpdump -i veth6c18dba
Но есть способ проще: можно найти IP-адрес контейнера в его сети и слушать трафик на нём:
[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
Вывод: дебаг в Docker-контейнере — это не страшно. Утилиты в нём работают, а для чтения логов можно использовать docker logs.
Как ответственный инженер, Ваня решил кратко законспектировать новую для себя информацию во внутренней базе знаний. Вот что он написал:
- Логи — лучший друг человека. Если встречается неожиданное поведение сервиса и при этом он не пишет ничего в лог — это повод попросить разработчиков добавить логов.
- Иногда бывает, что локализовать ошибку надо, даже если в логах ничего нет. К счастью, в Linux есть много утилит, которые помогают с этим.
- С дебагом любых сетевых коммуникаций помогает tcpdump. Он помогает видеть, какой трафик откуда и куда идёт на сервере.
- Заглянуть »внутрь» процесса помогают утилиты strace, ltrace и gdb.
- Всё это можно использовать, если сервис работает в Docker-контейнере.
- Много информации о процессе есть в директориях /proc/PID. Например, в /proc/PID/fd находятся симлинки на все открытые процессом файлы.
- Также помочь получить различную информацию о системе, файлах или процессах могут утилиты ps, ls, stat, lsof, ss, du, top, free, ip, ldconfig, ldd и прочие.
Надеюсь, вам была полезна эта история, и хотя бы однажды она поможет вам понять, в чём дело, когда вы будете что-то дебажить в Linux. Если Ваня что-то упустил, делитесь этим в комментариях!
