Русский
Русский
English
Статистика
Реклама

Дебаггинг

Перевод Жизнь инженера Netflix дело о лишних 40 мс

16.01.2021 14:23:21 | Автор: admin
Приложение Netflix работает на сотнях смарт-телевизоров, потоковых пультах и приставках платного ТВ. Инженер-партнёр помогает производителям устройств запустить приложение Netflix на их устройствах. В этой статье я расскажу об одной особенно сложной проблеме, которая заблокировала запуск устройства в Европе.




Как начались странности


Ближе к концу 2017 года я участвовал в конференции-связи, где обсуждали проблему с приложением Netflix на новой ТВ-приставке. Эта приставка была новым устройством Android с воспроизведением 4K на базе Android Open Source Project (AOSP) 5.0 Lollipop. В Netflix я имел дело с несколькими устройствами, но это было моё первое устройство Android TV.

В этой конференции участвовали все четыре игрока рынка: крупная европейская компания платного телевидения (оператор), эта компания запускала устройство; подрядчик, который интегрировал прошивку ТВ-приставки (интегратор); производитель микросхем; я представлял Netflix.

Интегратор и Netflix уже закончили строгую сертификацию Netflix, но во время внутреннего испытания оператора телеканалов один из руководителей компании рассказал о серьёзной проблеме: воспроизведение Netflix на его устройстве прерывалось, то есть видео проигрывалось совсем недолго, затем останавливалось, проигрывалось и снова прерывалось. Случалось это не всегда, но, как правило, спустя несколько дней после включения устройства. На представленной видеозаписи баг выглядел ужасно.

Интегратор нашёл способ воспроизвести проблему: нужно было несколько раз запустить Netflix, начать воспроизведение, затем вернуться в пользовательский интерфейс устройства. Нам дали сценарий, чтобы повторять ситуацию автоматически. Иногда воспроизведение ситуации с помощью скрипта занимало пять минут, но баг проявлялся всегда.

Тем временем полевой инженер производителя микросхем диагностировал причину проблемы: приложение Netflix, Ninja для Android-TV, медленно подавало аудиоданные. Видео останавливалось из-за истощения буфера в конвейере аудиоустройства. Ролик замирал, пока декодер ждал данных от Ninja. Когда новые данные поступали, проигрыватель оживал.

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

Расследование


Я был настроен скептически. То же самое приложение Ninja работает на миллионах устройств Android TV, включая смарт-ТВ и другие приставки. Если ошибка в Ninja, то почему она проявляется только на Android 5.0?

С помощью скрипта от интегратора я воспроизвёл проблему сам. Связался со своим коллегой у продавца микросхем, спросил, видел ли он что-то подобное раньше (он не видел). Затем я начал читать исходный код Ninja, потому что хотел найти фрагмент, который передавал данные. Я многое разузнал, но запутался в коде воспроизведения и нуждался в помощи.

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


Рисунок 1 Упрощённый конвейер воспроизведения

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

В Ninja эта работа выполнялась с помощью Android Thread. Есть простой конечный автомат и логика для обработки разных состояний воспроизведения, но при нормальном воспроизведении поток копирует один кадр данных в API воспроизведения Android, а затем сообщает планировщику потоков, что он должен подождать 15 мс и снова вызвать обработчика. Когда вы создаёте поток Android, можно запросить, чтобы поток запускался повторно, как если бы в цикле; но это планировщик потоков Android и он вызывает обработчика, а не ваше собственное приложение.

Чтобы воспроизвести видео со скоростью 60 кадров в секунду (наивысшей чистотой кадров в Netflix), устройство должно отображать новый кадр каждые 16,66 мс, поэтому наличие нового сэмпла проверяется каждые 15 мс. Этого времени достаточно, чтобы опережать любой видеопоток Netflix.

Интегратор определил, что проблема кроется в аудиопотоке, поэтому я сосредоточился на конкретном обработчике потока, который доставлял аудиосэмплы в аудиосервис Android. Где же лишние миллисекунды?

Я предположил, что виновата какая-то вызванная обработчиком функция, поэтому прописал логирование по всему обработчику, предполагая, что код-виновник станет очевиден. Вскоре стало ясно, что в обработчике не было ничего плохого: даже когда воспроизведение прерывалось, он отрабатывал за несколько миллисекунд.

Прозрение


В конце концов я обратил внимание на три цифры: скорость передачи данных, время вызова обработчика и время, когда он передаёт управление обратно в Android. Я написал сценарий, чтобы проанализировать вывод логирования, и построил график, который ответил на мой вопрос.


Рисунок 2 Визуализация пропускной способности аудио и синхронизации обработчика потоков

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

  1. Две высокие шипованные части, где скорость передачи данных достигает 500 байт/мс. Эта фаза буферизации, перед началом воспроизведения. Обработчик копирует данные так быстро, как только может.
  2. Область посередине это нормальное воспроизведение. Аудиоданные перемещаются со скоростью около 45 байт/мс.
  3. Область заикания находится справа, где аудиоданные движутся со скоростью ближе 10 байт/мс. Это недостаточно быстро, чтобы воспроизведение продолжалось.

Неизбежный вывод оранжевая линия подтверждает то, что рассказал инженер производителя микросхем: Ninja медленно передаёт данные. Чтобы понять причину, давайте посмотрим, о чём свидетельствуют жёлтые и серые линии. Жёлтая линия показывает время, проведённое в самой подпрограмме обработчика, это время рассчитывалось по записанным вверху и внизу обработчика отметкам.
И при нормальном воспроизведении, и при воспроизведении с заиканием время в обработчике было одинаковым: около 2 мс. Пики показывают случаи, когда выполнение замедлялось из-за затрат на другие задачи устройства.

Корень проблемы


Серая линия, время между вызовами обработчика, свидетельствует о другом. Когда видео проигрывается нормально, видно, что обработчик вызывается каждые 15 мс. Когда видео прерывается (справа), обработчик вызывается примерно каждые 55 мс. Между вызовами есть лишние 40 мс, а значит, успеть за воспроизведением невозможно. Но почему?

Я рассказал о своём открытии интегратору и производителю микросхем (посмотрите, виноват планировщик потоков Android!). Но они продолжали сопротивляться: почему бы вам просто не копировать новые данные, когда вызывается обработчик? Критика была справедливой, но, если переписать код таким образом, это повлечёт за собой больше изменений, чем я был готов внести, поэтому я решил продолжить поиск первопричины.

Я погрузился в исходный код Android и узнал, что потоки Android это конструкция пользовательского пространства, а планировщик потоков, чтобы определять время, использует системный вызов epoll(). Производительность epoll() не гарантируется, поэтому я подозревал, что на эту функцию влияет что-то системное.
И здесь меня спас другой инженер поставщика микросхем, который обнаружил ошибку; эту ошибку исправили в следующей версии Android Marshmallow. Планировщик потоков Android изменяет поведение потоков в зависимости от того, работает ли приложение в фоновом режиме или на переднем плане. Потокам в фоновом режиме задается дополнительное время ожидания в 40000000 нс. Ошибка в глубине самой Android означала, что дополнительное время возникает, когда поток перемещается на передний план.

Обычно поток обработчика звука создавался, когда приложение выполнялось на переднем плане, но иногда поток создавался немного раньше. Такое случалось, когда приложение Ninja работало в фоновом режиме и тогда проигрыватель останавливался.

Извлеченные уроки


Это была не последняя исправленная на этой платформе ошибка, но именно её было труднее всего отследить. Баг скрывался за пределами Netflix, не в конвейере воспроизведения; вместе с тем все исходные данные указывали на ошибку в приложении Netflix.

Эта история показывает одну из сторон моей любимой работы: я не могу предугадать все проблемы, которые наши партнёры перебросят мне, кроме того, я знаю, что для разрешения проблем мне нужно разбираться в нескольких системах, работать с замечательными коллегами и постоянно заставлять себя узнавать что-то новое. Моя работа прямо влияет на людей, на их удовольствие от отличного продукта. Я понимаю, что, когда люди наслаждаются Netflix в своей гостиной, именно я тот человек в команде, который делает это возможным.




Подробнее..

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

09.09.2020 12:15:30 | Автор: admin
В комментариях к одной из моих статей про базовые команды Linux shell для тестировщиков справедливо заметили, что в ней не было указано применение команд в процессе тестирования. Я подумал, что лучше поздно, чем никогда, поэтому решил рассказать историю Backend QA-инженера Вани, который столкнулся с неожиданным поведением сервиса и попытался разобраться, где именно случилась ошибка.



Что тестировал Ваня


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

В качестве сервиса выступает дефолтный HTTP сервер Python SimpleHTTPServer, который в ответ на запрос без параметров выводит содержимое текущей директории:

[root@ivan test_dir_srv]# ls -ltotal 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 8000Serving HTTP on 127.0.0.1 port 8000 (http://personeltest.ru/away/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.log2020/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 masterroot   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.conferror_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 8000tcpdump: verbose output suppressed, use -v or -vv for full protocol decodelistening on lo, link-type EN10MB (Ethernet), capture size 262144 bytes09: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 0E..<..@.@..............@.............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 0E..<..@.@.<..........@...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 0E..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 87E.....@.@..b...........@.....111...........1~c.1~c.GET / HTTP/1.0Host: testConnection: closeUser-Agent: curl/7.64.1Accept: */*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 0E..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 154E...R0@.@............@...111...p...........1~c.1~c.HTTP/1.0 200 OKServer: SimpleHTTP/0.6 Python/3.7.2Date: Mon, 07 Sep 2020 13:10:42 GMTContent-type: text/html; charset=utf-8Content-Length: 34009: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 0E..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 340E...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 0E..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 0E..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 0E..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 0E..4R3@.@............@...13 ...q.....(.....1~c.1~c.^C12 packets captured24 packets received by filter0 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 cwdpython3 20638 root cwd  DIR   253,1   4096 1843551 /root/test_dir_srv2

Также это можно сделать с помощью команды pwdx или с помощью директории proc:

[root@ivan ~]# pwdx 2063820638: /root/test_dir_srv2[root@ivan ~]# ls -l /proc/20638/cwdlrwxrwxrwx 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 20638strace: Process 20638 attachedrestart_syscall(<... resuming interrupted poll ...>) = 0poll([{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) = 5clone(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) = 21062futex(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 20638strace: Process 20638 attachedstrace: 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 23998GNU gdb (GDB) Red Hat Enterprise Linux 7.6.1-119.el7Copyright (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:8181T_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 openBreakpoint 1 at 0x7f2284c06d20: open. (2 locations)(gdb) cContinuing.[New Thread 0x7f227a165700 (LWP 24030)][Switching to Thread 0x7f227a165700 (LWP 24030)]Breakpoint 1, open64 () at ../sysdeps/unix/syscall-template.S:8181T_PSEUDO (SYSCALL_SYMBOL, SYSCALL_NAME, SYSCALL_NARGS)(gdb) n83T_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:381381                Py_END_ALLOW_THREADS(gdb) n379                self->fd = open(name, flags, 0666);(gdb) n381                Py_END_ALLOW_THREADS(gdb) print name$1 = 0x7f227a687c90 "/root/test_dir_srv/"(gdb) qA debugging session is active.Inferior 1 [process 23998] will be detached.Quit anyway? (y or n) yDetaching 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_container172.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. Если Ваня что-то упустил, делитесь этим в комментариях!
Подробнее..

Категории

Последние комментарии

  • Имя: Макс
    24.08.2022 | 11:28
    Я разраб в IT компании, работаю на арбитражную команду. Мы работаем с приламы и сайтами, при работе замечаются постоянные баны и лаги. Пацаны посоветовали сервис по анализу исходного кода,https://app Подробнее..
  • Имя: 9055410337
    20.08.2022 | 17:41
    поможем пишите в телеграм Подробнее..
  • Имя: sabbat
    17.08.2022 | 20:42
    Охренеть.. это просто шикарная статья, феноменально круто. Большое спасибо за разбор! Надеюсь как-нибудь с тобой связаться для обсуждений чего-либо) Подробнее..
  • Имя: Мария
    09.08.2022 | 14:44
    Добрый день. Если обладаете такой информацией, то подскажите, пожалуйста, где можно найти много-много материала по Yggdrasil и его уязвимостях для написания диплома? Благодарю. Подробнее..
© 2006-2024, personeltest.ru