Привет, далеко ходить не будем, сегодня более интересный кейс с отладкой 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.



В общем изучай и бери на вооружение, опыт полезный. Увидимся!



tags: #linux #debug #рабочиебудни



💩 @bashdays