Nginx отдаёт 502 через раз: поиск виновника по таймингам

MAATRIX

Мониторинг молчит, сайт вроде бы жив, но часть пользователей жалуется на 502 — не все и не постоянно, а с виду случайно. Самое неприятное в такой картине — она не воспроизводится по требованию: вы открываете страницу десять раз подряд и всё работает. Это разбор конкретного механизма, из-за которого так бывает: nginx как прокси рвёт соединение по своему таймауту, пока бэкенд ещё честно готовит ответ, и как это отличить от реальной поломки приложения по логам, а не по ощущениям.

Первая версия: грешим на бэкенд и перезапускаем его

Стандартный первый шаг, когда в мониторинге появляется рост 502 — идти смотреть на приложение за прокси. Логика понятна: 502 Bad Gateway формально означает, что nginx получил невалидный ответ от апстрима или не смог его дождаться, а самый очевидный подозреваемый — упавший или зависший процесс.

Дальше обычно происходит вот что: смотрят systemctl status для сервиса, видят, что процесс жив, но раз проблема есть — перезапускают. И это часто действительно помогает. На несколько минут, иногда на час-два, 502 пропадают. Вывод напрашивается сам: "приложение подтекает, надо чинить утечку" или "процесс иногда подвисает, поставим перезапуск по крону".

Проблема в том, что перезапуск помогает почти при любой причине временной деградации — он обнуляет накопленное состояние (открытые соединения, память, очереди), но не объясняет, почему деградация появилась. Если через несколько часов 502 возвращаются с той же частотой — это сигнал, что вы лечите симптом, а не причину. Здесь стоит остановиться и не хватать очередную "починку", а посмотреть на цифры: сколько именно длились запросы, которые превратились в 502, и сколько бэкенд реально тратил времени на ответ в этот момент.

Таймауты nginx против реального времени ответа бэкенда

Ключевая вещь, которую легко упустить: nginx как reverse proxy сам обрывает соединение с апстримом, если тот не ответил за отведённое время — независимо от того, жив бэкенд или нет. За это отвечают три директивы в блоке location или http:

location /api/ {
    proxy_pass http://backend;

    proxy_connect_timeout 5s;   # время на установку TCP-соединения с апстримом
    proxy_send_timeout    60s;  # время между двумя операциями записи в апстрим
    proxy_read_timeout    60s;  # время между двумя операциями чтения ответа от апстрима
}

Если явно не задать эти значения, действуют дефолты nginx — обычно 60 секунд для каждого из трёх параметров (конкретное значение зависит от версии и уже применённых в конфиге настроек, проверьте свой nginx -T, а не полагайтесь на память). Проблема начинается не тогда, когда бэкенд падает намертво, а когда он изредка отвечает дольше, чем proxy_read_timeout. В этот момент nginx считает апстрим недоступным, обрывает соединение и отдаёт клиенту 502 (иногда 504, если ваш конфиг явно различает эти случаи через proxy_next_upstream и таймауты — об этом отдельно есть статья про 504 Gateway Timeout, механизм там смежный). Формально бэкенд жив, просто чуть задержался — но с точки зрения клиента разницы никакой, он видит ошибку.

Отсюда и "случайность" картины: 502 ловят не все запросы, а только те, что попали на медленный ответ, а таких — меньшинство. Если у бэкенда медианное время ответа 80 мс, а хвост распределения раз в несколько минут доходит до 65 секунд — вы получите редкие, на вид непредсказуемые 502 именно на этих выбросах.

Как увидеть проблему в access-логе nginx

Стандартный лог-формат nginx не показывает время ответа апстрима, только сам факт запроса. Чтобы увидеть тайминги, добавьте в nginx.conf (в блок http) расширенный формат:

log_format upstream_timing
    '$remote_addr - $remote_user [$time_local] '
    '"$request" $status $body_bytes_sent '
    'rt=$request_time uct="$upstream_connect_time" '
    'urt="$upstream_response_time" '
    'ust="$upstream_status" ref="$http_referer"';

server {
    access_log /var/log/nginx/access.log upstream_timing;
}

Ключевые переменные:

• $request_time — сколько всего заняла обработка запроса на стороне nginx, от первого байта до последнего.
• $upstream_response_time — сколько ждали ответа от апстрима. Именно это поле рвётся при таймауте.
• $upstream_connect_time — сколько заняло установление соединения с апстримом (полезно отличать зависшую очередь на подключение от медленного ответа).
• $upstream_status — код, который вернул сам апстрим (если он вообще успел ответить).

После перезагрузки конфига (nginx -s reload) ищите в логе именно 502-строки и смотрите на urt:

grep ' 502 ' /var/log/nginx/access.log | grep -oP 'urt="\K[^"]+'

Если в выдаче видите значения вида urt="60.001" (то есть ровно на границе или чуть выше proxy_read_timeout) — это почти наверняка не сбой бэкенда, а обрыв по таймауту. Если бы бэкенд реально падал или не принимал соединение, upstream_status был бы пустым или сразу error, а не таким аккуратным числом рядом с настроенным таймаутом. Возьмите топ самых больших urt за сутки и посмотрите на распределение по времени — часто оно кластеризуется вокруг конкретных минут, а не размазано равномерно, и это уже подсказка для следующего шага.

Почему бэкенд иногда медленный: GC-паузы и конкуренция за пул к базе

Самый частый вопрос на этом этапе — "но почему тогда бэкенд иногда реально отвечает 60+ секунд, если обычно он быстрый?". Две причины встречаются заметно чаще остальных.

Паузы сборщика мусора (GC). В управляемых рантаймах (JVM, .NET, Node.js, Go в меньшей степени) сборщик мусора периодически останавливает выполнение потоков приложения — обычно это доли миллисекунды, но при накоплении большого количества "мусора" на куче или при конкретных паттернах аллокаций пауза может вырасти до сотен миллисекунд или секунд. Если такая пауза совпадает по времени с обработкой конкретного запроса — этот запрос и станет тем самым выбросом в urt. Смотреть нужно в GC-логи приложения (для JVM — -Xlog:gc* или старый -verbose:gc), сопоставляя метки времени пауз с временем "зависших" запросов из access-лога nginx.

Конкуренция за пул соединений к базе. Если пул соединений к БД ограничен (типичные значения — 10-20 соединений на инстанс приложения), а на пике нагрузки одновременных запросов, которым нужна база, больше, чем свободных соединений в пуле — часть запросов встаёт в очередь ожидания свободного соединения. Если очередь достаточно длинная, ожидание само по себе может превысить таймаут nginx, хотя ни один запрос к базе по отдельности не выполнялся медленно. Это классический механизм описан подробнее в статье про connection pool — тут важно, что проблема проявляется именно пачками, синхронно с пиками нагрузки, а не равномерно.

Отличить эти две причины друг от друга можно по логам приложения: GC-паузу видно в GC-логе рантайма, а ожидание пула — в метриках самого пула соединений (большинство ORM и пул-менеджеров, включая HikariCP, pgBouncer, дают метрику wait time или pending requests), либо просто по времени между "запрос пришёл" и "запрос начал выполнять SQL" в логах приложения.

Быстрый фикс: увеличить таймауты — и его цена

Самое простое временное решение — раздвинуть таймауты nginx под наблюдаемый худший случай:

location /api/ {
    proxy_pass http://backend;
    proxy_connect_timeout 5s;
    proxy_send_timeout    90s;
    proxy_read_timeout    90s;
}

Это законный приём, если вы точно знаете свой worst-case (по логам, а не наугад) и он конечен — например, у вас есть один тяжёлый отчётный эндпоинт, который иногда честно считает 40-50 секунд, и это ожидаемо. Но у этого решения есть цена, которую важно проговорить прямо:

• Клиент и его браузер тоже дольше висят в ожидании — пользовательский опыт не улучшается, просто ошибка превращается в долгую загрузку вместо быстрой (для пользователя это не всегда лучше).
• Воркер-процесс (или поток) nginx и соответствующий воркер бэкенда дольше заняты одним запросом — при повторении проблемы на пике вы упрётесь не в 502, а в исчерпание воркеров и очередь запросов целиком.
• Если корневая причина — исчерпание пула соединений к базе, увеличенный таймаут не решает проблему, а просто даёт очереди больше времени вырасти ещё сильнее, прежде чем что-то отвалится.

Увеличение таймаута — разумный шаг для конкретных, осознанно тяжёлых операций (импорт, генерация отчёта, batch-запрос), но плохое решение по умолчанию для всего API, потому что оно маскирует то, что должно быть замечено и исправлено.

Правильный фикс: убрать причину задержки, а не таймаут

Если задержки — это GC-паузы, обычно помогает не "добавить памяти и забыть", а разобраться, что именно аллоцируется в пиковые моменты: часто это один неоптимальный запрос, который вытягивает в память слишком много объектов за раз (например, SELECT * без пагинации на большую таблицу), или утечка, которая накапливает мусор до тех пор, пока сборщик не устроит "стоп-фазу" подольше. Профилировщик рантайма (heap dump + анализ, для JVM — jmap/VisualVM, для Node — --inspect и Chrome DevTools) покажет, что именно занимает память на момент паузы.

Если причина — конкуренция за пул к базе, вариантов чинить обычно два, и они не взаимоисключающие: увеличить размер пула (но не бесконечно — упрётесь в лимит соединений самой БД, max_connections в PostgreSQL) либо найти и ускорить запрос, который держит соединение дольше остальных (долгая транзакция, отсутствующий индекс, блокировка). Полезно сразу проверить, не решает ли задачу внешний пулер вроде pgBouncer, который эффективнее распределяет ограниченное число реальных соединений к БД между большим числом клиентов приложения.

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

Как сопоставлять логи nginx и приложения по времени

Это самая практическая часть разбора — без неё предыдущие пункты остаются теорией. Порядок действий:

1. Синхронизируйте часовые пояса и точность. Убедитесь, что $time_local в nginx и таймстемпы в логах приложения используют один часовой пояс (или переведите вручную) и сравнимую точность — секунды часто недостаточно, если несовпадение исчисляется миллисекундами на границе таймаута.

1. Найдите проблемные запросы в nginx. Возьмите строки с urt, близким к настроенному таймауту, и запишите точное время начала запроса — это $time_local минус $request_time (nginx логирует время *окончания* обработки, а не начала).

1. Найдите совпадения в логе приложения. По этому временному окну ищите записи о начале обработки того же запроса — обычно есть request ID, который стоит прокидывать через заголовок (например, X-Request-Id, который генерирует nginx через $request_id и передаёт бэкенду через proxy_set_header), чтобы не гадать по времени, а сопоставлять точно:

proxy_set_header X-Request-Id $request_id;

Если бэкенд логирует этот же ID в начале и в конце обработки запроса, у вас появляется однозначная связка "эта строка в access-логе nginx = эти строки в логе приложения", и дальше видно, где именно ушло время: на ожидание соединения к базе, на сам SQL-запрос, на сериализацию ответа или на GC-паузу между ними.

1. Проверьте GC-лог и метрики пула за то же окно. Если в момент задержки в GC-логе есть пауза, длина которой сопоставима с превышением таймаута — вот и причина. Если пауз нет, но метрика ожидания пула соединений в этот момент подскакивает — смотрите туда.

Отдельно стоит сразу настроить алерт не на факт 502 (это уже поздно, пользователь его увидел), а на превышение $upstream_response_time в X% случаев за скользящее окно — так вы увидите деградацию раньше, чем она перерастёт в обрывы соединений. Общий подход к разбору инцидентов по логам без привязки конкретно к nginx описан в статье про то, как читать логи и находить причину сбоя.

Частые вопросы