company_banner

Как Иван ошибку в бэкенде локализовывал

    В комментариях к одной из моих статей про базовые команды 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
    <!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>
    

    Но затем в один момент на тестовом стенде разработчики что-то обновили, и Ваня получил ошибку:

    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>
    

    Он решил не скидывать эту непонятную ошибку разработчикам, а получить доступ по 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. При правильной конфигурации он видел запрос и ответ:

    Дамп трафика на порту 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
    


    При неправильной конфигурации (с портом 8009 в апстриме nginx) на порту 8000 никакого трафика не было. Ваня обрадовался: теперь даже если разработчики забыли реализовать запись в лог при сетевых ошибках, всё равно можно хотя бы узнать, идёт ли трафик на нужный хост или порт.

    Какой вывод можно сделать из этой истории? Даже если логов нет, в Linux есть утилиты, которые могут помочь с локализацией проблем.

    А если не сеть?


    Всё хорошо работало, но однажды Ваня снова получил ошибку, на этот раз другую:

    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>
    

    Ваня снова зашёл на сервер, но в этот раз проблема не была связана с сетью. В логе сервиса тоже было написано 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, либо подключаться этой утилитой к уже запущенному процессу. Ване подходил второй вариант:

    Вывод утилиты 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 ...>
    


    Обычно вывод 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() и посмотреть, что будет:
    Вывод утилиты 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]
    


    После команды c (continue) Ваня в другой консоли запустил curl, попал в дебаггере в точку останова и стал выполнять эту программу (то есть сервис) по шагам. Как только он нашёл в коде open по какому-то пути name, он вывел значение этой переменной и увидел «/root/test_dir_srv/».
    GDB — это мощный инструмент, и здесь описан простейший вариант его использования. Иногда он может помочь в воспроизведении каких-либо сложных кейсов (например, можно приостановить процесс в нужный момент и воспроизвести состояние гонки), также он помогает с чтением core dump файлов.

    А что если Docker?


    В один момент DevOps решили, что сервис теперь будет деплоиться Docker-контейнером, и нужно было провести ретест всех кейсов, которые нашёл Ваня. Ваня без проблем нагуглил следующее:

    1. Использовать tcpdump, strace и gdb можно и внутри контейнера, но нужно иметь ввиду Linux capabilities (есть статья, которая объясняет, почему strace не работал в контейнере без --cap-add=SYS_PTRACE).
    2. Можно использовать опцию --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. Если Ваня что-то упустил, делитесь этим в комментариях!
    FunCorp
    Разработка развлекательных сервисов

    Comments 17

      +2
      Неплохо, спасибо.
        +1
        Довольно интетерсно написано
          +2
          Нестандартный формат подачи информации, очень приятно читать статью.
            0
            а что Ване делать, если нужно дебажить nginx с https трафиком (принимает https и отправляет дальше в https сервис)? :)
              0

              Ваня такое встречал редко. Так редко делают, потому что обычно вся связка сервисов находится в какой-то внутренней сети, в которую нет доступа снаружи, и использовать там HTTPS — это нормальный такой оверхед. Проще всего переконфигурить nginx, чтоб ходил по HTTP. Либо использовать ssldump, но Ваня не пользовался им.

                0
                Ага, совпадает с моим собственным мнением.
                У нас была проблема как раз с тем, что через HTTP ходит нормально, а вот через HTTPS — нет (были настроены два server_name, скажем a_server_name и b_server_name и если первый запрос приходит к a_server_name, то все остальные запросы и к a_server_name и к b_server_name идут все равно через a_server_name).
              0
              Полевой конспект полезный. Спасибо.

              Но хочется обратить внимание на один момент, с точки зрения процесса обеспечения качества:
              Он решил не скидывать эту непонятную ошибку разработчикам, а получить доступ по ssh на сервер и разобраться, в чём там дело. Знаний в области такого рода дебага проблем у него было мало, но он очень хотел научиться, поэтому вооружился поисковиками, логикой и пошёл локализовывать баг

              Я бы проверил с другой машины, с другой сети (и все там что надо*), и если проблема на лицо, сперва зарепортил, а потом бы только занимался самообразованием.
              * — По уму, для определенных типов ошибок должен быть протокол действий, необходимых чтобы зафиксировать сбой

              И вообще, доступность сервисов и серверов должна проверяется автоматизацией (мониторинг там всякий и пр.), и все проблемы сразу идут разрабам на почту или автоматически заводятся тикеты. Ну или хотя бы к этому стремиться. Это достойная цель для QA, сделать так, чтобы проблемы обнаруживались быстрее. С графиками которые можно потом менеджерам представить мол «вот и вот, хостинг гуано, надо переезжать в облака, тыры-пыры.»

              Не знаю, какого бы ранга ты QA не был, не нужно тратить свое время и делать работу системного инженера. Ведь пока ты там занимаешься самообразованием — об ошибке никто еще ничего не знает. Это как при автомобильной аварии, сначала звоним в скорую, а потом оказываем первую помощь*. Чаще, системные инженеры все равно круче и опытнее. То что знания надо расширять, конечно, не спорю, но не в ущерб «пациенту».
              * — И то, самый полезный совет при оказании ПП: «Не уверен — лучше не трогай.»

              P.S.
              И молодым тестировщикам на заметку, на тему «не нахожу общий язык с разработчиками» — будете заниматься не своим делом, будете пытаться «блеснуть знаниями», не подружитесь никогда.
                +3
                Спасибо за комментарий!

                Во-первых, сразу скажу, что я не имел ввиду ситуацию, когда проблема на проде. В этом случае, естественно, дебагом должны заниматься девопсы/разработчики, как люди, лучше всего знающие инфраструктуру и ПО. Речь в статье шла скорее о ситуации, когда проблема возникает при тестировании какой-то новой фичи, и ситуации, описанные в статье, сильно искуственные. Доступность сервисов определённо должна проверяться автоматизацией.

                Во-вторых, я считаю, что тестировщик всё-таки должен «блистать знаниями» в разумных пределах. Пример: отдают сервис на тестирование, тестировщик запускает тест, получает в ответ Connection reset by peer. Дальше есть 2 варианта: либо тестировщик просто пишет разрабам «тут странная ошибка, воспроизводится тестом XXX, вот вам Reopen задачи», либо он понимает, что клиент получил TCP-пакет с RST, что сервис упал, пойдёт в лог и приложит к задаче стектрейс. Или, если сервис отложил core dump-файл, заюзает gdb на этот файл, сделает там bt и приложит трейс из дампа к задаче.
                Оба варианта имеют право на жизнь, всё зависит от процесса и культуры разработки и тестирования в компании/отделе. Лично мне ближе второй :)
                0

                Если Ваня уже на сервере, можно проверить, отвечает ли сервис без nginx, например:


                curl http://127.0.0.1:8000/

                Так же, можно использовать команду nestat или ss, чтобы узнать какой порт по факту прослушивает процесс и прослушивает ли вообще:


                netstat -tunapl | grep "python\|8000"
                  0
                  Спасибо за комментарий! curl на localhost действительно может дать информации, а про ss я написал в конце без подробностей. netstat же уже устарел, хоть пользоваться им никто не запрещает :)
                    0

                    Ещё Ване может потребоваться утилита iptables в некоторых случаях. А когда Ваня совсем отчается, вспомнит про SELinux.

                      0
                      Про iptables я уже писал, поэтому тут не упоминал, да и это не совсем про дебаг.
                      Ну а чтоб дойти до SELinux, надо и правда совсем отчаяться))
                  +2
                  Где вариант посмотри настройки (не только nginx, а самого приложение), посмотри код? Для решения многих проблем — это горазда проще, чем использовать strace

                  P.S. Ну и главное не фанатеть, иногда лучше спросить
                  PSS Если для тестирования требует богатый опыт использования strace, то лучше подумать о рефакторинге такого чуда.
                    0
                    Хотелось рассмотреть именно back-box тестирование, а так да, изучение конфига и кода иногда помогает. Ну вот конкретно в моём примере как такового конфига и кода у приложения вообще не было (был, конечно, в либах питона).
                    Про рефакторинг чуда, которое только через strace раздебажишь, согласен :) Но всякое бывает)) Поэтому и написал статью, чтобы показать, что даже если ничего не понятно, можно попробовать расковырять это утилитами.
                    +1

                    Ещё бэкенд может использовать язык наподобие Rust, выдающий навязчивые хинты при игноре возвращаемого значения и, как результат, заставляющий разработчика писать код вывода ошибки пользователю как наиболее простецкий способ, в расчёте на то, что он никогда не выполнится. А по факту выполнившись внезапно один раз из ста он позволяет легче лёгкого локализовать баг.

                      0
                      Читал все это и постоянно отгонял назойливые мысли: а почему тестер имеет доступ на сервер, да еще и с правами рута (tcpdump без них не оживет)? Почему он развлекается чтением логов и просмотром трафика вместо того, чтобы отрепортить баг и перейти к следующей задаче?

                    Only users with full accounts can post comments. Log in, please.