Сегодня более интересный кейс с отладкой php-fpm который непонятным образом, рандомно зависал. Будем использовать любимый strace, как ты любишь.
Проблема: На сервере крутится php-fpm, в любой момент времени процесс начинает зависать, то есть перестаёт обрабатывать любые запросы.
В какой-то момент может очухаться, а может и нет. В любом случае проблема решается перезапуском systemctl restart php-fpm. Ну и в логах ничего криминального нет, даже в дебаг режиме. По факту имеем 502 Bad Gateway.
Ребята придумали костыль, какой-то башник, который в кроне проверяет зависание и затем автоматически ребутит. Да, как временное решение подходит. Но сам знаешь, что временное всегда становится постоянным.
До этого были перепробованы все возможные варианты с конфигом, накручивание буферов, гугление, даже грешили на nginx, но ничего не помогало.
Так и жили пока дядя Рома не соизволил разобраться в ситуации, ну и разобрался.
Расчехляем strace
Для начала ты должен знать, что php использует модель master/slave. Главный процесс использует воркеры (workers) для обработки входящих запросов. Запрос может выполниться на любом из воркеров, поэтому нужно сказать strace чтобы мониторил все воркеры. Для этого будем использовать связку с командой pidof ну и приправим это sed’ом.
strace -f $(pidof php-fpm | sed 's/\([0-9]*\)/\-p \1/g') -epoll
Sed обрезает лишнее и оставляет только pid в голом виде, ну и затем эти пиды закидываем в strace.
А после запуска команды и зависания php, я увидел такое:
[pid 1234] poll([{fd=10 ...]) = 0 (Timeout)
[pid 1234] poll([{fd=10 ...]) = 0 (Timeout)
[pid 1234] poll([{fd=10 ...]) = 0 (Timeout)
[pid 1234] poll([{fd=10 ...]) = 0 (Timeout)
Ага, уже есть с чем работать. Какой-то таймаут. И файловый дескриптор fd=10. Хм. Теперь надо понять, что это за таймаут и дескриптор fd=10. Для этого сделаем так:
lsof -p 1234
Эта команда выдаст список всех файлов, которые открыты процессом, включая сокеты.
php 0u IPv4 13193 0t0 TCP :8000 (LISTEN)
php 1u CHR 1,4 0t0 4728 /dev/null
php 2u CHR 1,4 0t0 4728 /dev/null
php 3ur REG /tmp/.RedPem.Hte (deleted)
php 4u IPv4 TCP :8000->:5042 (ESTABLISHED)
php 5uW REG sessions/sess_tmh0dls75
php 6u 0000 0,9 0 4842 anon_inode
php 7u unix 0t0 25714 socket
php 8u unix 0t0 25714 socket
php 9u TCP l->l:11210 (ESTABLISHED)
php 10u TCP host->10.0.0.100:9200 (SYN_SENT)
Смотрим самую последнюю строку как раз с fd=10. Видим что у нас проблема с подключением к 10.0.0.100:9200. Очень интересно. Что это вообще за айпишник такой.
Не останавливаемся и копаем дальше.
В большинстве случае порт 9200 принадлежит ElasticSearch. Роем в эту сторону и обнаруживаем, что в php проекте используется библиотека ElasticSearch PHP.
Как оказалось, при разработке проекта, прекрасные девы подключили ElasticSearch, чтобы чото там отлавливать. А на айпишнике 10.0.0.100 как раз располагалась серверная часть ElasticSearch. Разработку прекратили, сервер с эластиком убили, но из конфигов проекта забыли выкосить.
Вот оно и продолжало ломиться туда, где ничего нет. В этом и заключался баг. PHP постоянно опрашивал ElasticSearch сервер для получения ответа, но в ответ ничего. Рабочий процесс зависал в цикле и не мог ответить ни на один другой запрос.
Такие дела. Я прям уверен — если пройтись с помощью strace по всяким популярным php движкам, там столько интересного вылезет. Кстати с помощью strace можно вполне удачно разгонять проекты, банально фиксишь то, что вызывает таймауты.
Порой наталкивался на ситуацию когда проект тормозил из-за корявого резолва доменов, или были проблемы с таймзоной, аналогично всё это дебажилось через strace.
В общем изучай и бери на вооружение, опыт полезный. Увидимся!