Поправить пятисотки на приложении в кубе - это просто!
Не мог не вставить эту глупую картинку peka face, потому что дебажить пятисотки в кубере в облаках на самом деле не так просто, как многим кажется, а заголовок статьи конечно же же наполнен жиром сарказма и иронии.
Четыре недели с 502: как мы гасили ошибки в бот-сервисе одну за другой
Расскажу историю о том, как суммарно около четырёх недель мы последовательно находили и устраняли причины 502-ошибок в одном из наших сервисов.
Большая часть этого времени ушла не на сами фиксы - а на то, чтобы вообще понять что происходит. Пока не было нормальных логов и метрик, двигаться было некуда: каждая следующая причина становилась видна только тогда, когда предыдущая была закрыта и шум от неё уходил. Плюс нужно было просто накопить статистику - увидеть паттерн, а не единичный случай.
Одна из тех историй, когда, починив что-то одно, видишь следующее - и так несколько итераций подряд.
Кто такой бот-сервис
У нас есть сервис, который занимается обработкой входящих вебхуков от внешнего корпоративного чат-инструмента - назовём его просто бот-сервис.
Он крутится в Kubernetes, за ним AWS ALB, трафик идёт от ботового фреймворка вендора.
Написан на Node.js + Express. Ничего экзотического.
Vendor Bot Framework
|
| HTTPS, keep-alive
v
+------------------+
| DNS | Route53 / Cloudflare
+--------+---------+
|
v
+------------------+ +----------------------------------+
| AWS ALB |<--| AWS Load Balancer Controller |
+--------+---------+ | - следит за K8s Endpoints |
| | - регистрирует/дерегистрирует |
| | поды в target group ALB |
+------+------+ +----------------------------------+
v v
+----------+ +----------+
| Pod 1 | | Pod 2 | (Pod N ...)
| Node.js | | Node.js |
| :3000 | | :3000 |
+----------+ +----------+Именно в этой цепочке и живут все проблемы, о которых пойдёт речь.
Как сервис стал боевым
Долгое время бот-сервис жил в относительно тихом режиме: небольшая нагрузка, в основном внутреннее использование. Мониторинг был минимальный - сервис работает, и ладно.
Потом сервис начал получать реальный трафик от живых пользователей. Стали потихоньку поглядывать на метрики - рестартов нет, CPU и память в пределах нормы, всё выглядело спокойно.
И вот однажды прилетел вопрос: "а почему у нас 502 ошибки?"
Первые 502: клиент жалуется, мы в темноте
На тот момент не было почти никакой зацепки. Метрики приложения есть, Prometheus есть, Grafana есть. Но конкретно по ALB - тишина. ALB стоял давно, логирование для него никто не включал: всё работало, зачем.
Понятно было только одно: где-то есть 502. Откуда, от кого, когда именно, что в это время делал бэкенд - непонятно совсем.
Попробовали несколько вещей наугад - ничего не изменилось. Нужна была хоть какая-то зацепка.
Первая гипотеза: keepAlive таймауты
Погуглили "node.js alb 502" - нашли сразу две статьи, которые объясняли одну и ту же механику. Ссылки будут в конце статьи.
Суть такая: у Node.js http.Server дефолтный keepAliveTimeout равен 5 секундам.
У AWS ALB дефолтный idle timeout - 60 секунд.
То есть ALB держит соединение открытым 60 секунд, а Node.js закрывает его уже через 5.
Когда ALB пытается отправить новый запрос по уже закрытому соединению - получаем 502 и ECONNRESET на стороне приложения.
Исправляется просто: выставить keepAliveTimeout на сервере чуть больше, чем таймаут ALB, чтобы Node.js никогда не закрывал соединение раньше балансера.
server.keepAliveTimeout = 65000; server.headersTimeout = 66000;
(headersTimeout должен быть чуть больше keepAliveTimeout - иначе Node.js может отбросить запрос, который пришёл в самый последний момент перед закрытием соединения)
Добавили это в server.ts, задеплоили. Стало заметно лучше - часть 502 пропала. Казалось, нашли причину и дальше заживём.
Ошибок стало меньше, но они не исчезли. Значит, была ещё какая-то другая причина - или несколько. И без нормальных данных двигаться дальше было некуда.
Шаг 0. Включаем логи ALB
Зашли в настройки load balancer в AWS Console - Attributes - Access logs - Enable.
Указали S3-бакет, включили все доступные на тот момент поля.
Настроили сбор из S3 в OpenSearch через существующий pipeline.
После этого у нас появился полноценный лог каждого запроса через балансер, включая:
elb_status_code- что ответил сам ALB клиентуtarget_status_code- что ответил под балансеру (или "-", если не ответил вообще)target_processing_time- сколько под думалrequest- метод, URL, протоколuser_agent- кто стучится
С этого момента стало можно нормально разбираться.
Причина #1 - Rolling deploy без preStop hook
Полез в OpenSearch - там теперь лежат ALB access-логи.
Запрос простой: ищем elb_status_code: 502 по нашему домену за последнюю неделю.
Картина такая: несколько одиночных 502 в разное время суток, и один раз сразу 10 штук подряд. Примеры из лога:
- 1 запрос, target_processing_time 0.084s, ответа от пода нет
- 1 запрос, 0.476s, ответа нет
- 1 запрос, 2.069s, ответа нет
- 1 запрос, 1.284s, ответа нет
- 10 запросов подряд, ответа нет ни от одного
target_status_code: null и target_processing_time меньше нескольких секунд - ALB до пода достучался, а вот HTTP-ответа так и не получил.
Это не таймаут приложения, это обрыв соединения на уровне TCP.
Первый же вопрос: что происходило в это время с подами?
Иду в Prometheus, смотрю kube_pod_container_status_restarts_total - рестартов нет.
Смотрю kube_pod_info - количество подов менялось.
А значит что? Правильно - роллинг-деплой.
Алгоритм роллинг-деплоя в Kubernetes примерно такой:
- Kubernetes посылает SIGTERM умирающему поду
- Одновременно убирает его из Endpoints
- ALB обновляет свой список целей - но не мгновенно, это занимает несколько секунд
В этот зазор ALB ещё продолжает гнать трафик на уже умирающий под.
Под получает SIGTERM, начинает завершаться - и новый запрос от ALB уже некому обработать. Отсюда 502.
Решение классическое - preStop хук: заставляем контейнер немного подождать перед завершением, чтобы ALB успел дерегистрировать цель.
lifecycle:
preStop:
exec:
command: ["sleep", "15"]Небольшое отступление для тех, кто на свежих версиях Kubernetes.
Начиная с версии 1.29 появилась фича PodLifecycleSleepAction - нативный sleep прямо в preStop без костыля через exec и системную команду. В 1.30 она включена по умолчанию, в 1.34 вышла в GA(beta?).
Если у вас k8s >= 1.30, можно писать так:
lifecycle:
preStop:
sleep:
seconds: 15Чище, без зависимости от наличия sleep в образе, сразу понятно что происходит.
У нас на тот момент была более старая версия кластера, поэтому пошли через exec.
Добавили в деплоймент, задеплоили. Это был PR #1.
Вместе с ним отключили автоскейлинг воркер-компонента - он создавал лишний шум деплоев без реальной надобности (PR #2).
После этого единичные 502 при деплоях пропали. Казалось, всё.
Причина #2 - OOMKill
Вскоре прилетело сразу 10 штук 502 за один раз.
Снова OpenSearch - время совпадает, снова target_status_code: null.
Иду смотреть что было с подами в это время.
kube_pod_container_status_last_terminated_reason{reason="OOMKilled"}.Один из подов получил OOMKill - память стрельнула до ~800 MiB при лимите 800 Mi.
Под умер, ALB не успел дерегистрировать - 10 одновременных запросов получили 502.
Смотрю лимиты в деплойменте - да, 800 Mi, и это явно было на грани.
Откуда такой спайк - скорее всего, транзиентный пик нагрузки, в Node.js такое бывает при обработке нескольких тяжёлых запросов одновременно.
Подняли лимит памяти до 1536 Mi (PR #3). После этого OOMKill больше не повторялся.
Причина #3 - CPU throttling -> liveness probe перезапускает контейнеры
Спустя несколько дней - новый инцидент, уже серьёзнее. Пять 502, target_processing_time от 13 до 24 секунд. Три пода.
Это уже не про деплой и не про память.
Лезу в Prometheus, смотрю container_cpu_cfs_throttled_seconds_total.
Треть всего CPU-времени поды просто не получают из-за лимита.
Node.js - однопоточный event loop. Когда CFS-шедулер Linux троттлит процесс, event loop стоит.
Стоит event loop - не отвечают HTTP-эндпоинты.
Не отвечают эндпоинты - liveness probe падает.
Смотрю конфигурацию проб через kubectl:
livenessProbe: periodSeconds: 10 failureThreshold: 6 timeoutSeconds: 10
То есть нужно 6 подряд неудачных проб с периодом 10 секунд - 60 секунд при жёстком троттлинге.
CPU-лимит в 200m - это 0.2 ядра. При нагрузке это катастрофически мало для Node.js с event loop.
Поднимаем CPU limit с 200m до 500m (PR #4).
После деплоя картина в Prometheus:
С 35% упало до 4-10%. Лайвнес-килы прекратились.
Причина #4 - Graceful shutdown: Node.js и SIGTERM
Казалось бы, всё починили. Но нет.
После деплоя PR #4 начали появляться два новых паттерна в OpenSearch:
- target_processing_time: 0.078s, target_status_code: null
- target_processing_time: 3.924s, target_status_code: null
460-ошибки (client closed connection):
Всё это - только от user-agent вендора, только во время деплоев.
preStop: sleep 15 у нас есть, это проверено через kubectl describe rs.
preStop hook даёт поду 15 секунд до того, как Kubernetes пошлёт SIGTERM.
Но что происходит после SIGTERM?
По умолчанию Node.js http.Server на SIGTERM не делает ничего специального.
Процесс завершается, все open TCP-соединения - сброшены. Мгновенно.
А бот-фреймворк вендора держит keep-alive соединения с сервером.
Одно соединение - много запросов. Когда соединение рвётся прямо во время обработки запроса - ALB получает 502. Когда клиент пробует переиспользовать соединение, которого уже нет - 460.
Значит нам нужен явный обработчик SIGTERM, который:
1. Перестаёт принимать новые соединения (server.close())
2. Ждёт пока завершатся активные запросы
server.keepAliveTimeout = 65000;
server.headersTimeout = 66000;
process.on('SIGTERM', () => {
logger.info('SIGTERM received, closing HTTP server');
server.close(() => {
logger.info('HTTP server closed');
process.exit(0);
});
// backstop: если активный запрос завис и server.close() никогда не вызовет колбэк -
// выходим принудительно за 2 секунды до SIGKILL, чтобы завершение было контролируемым
setTimeout(() => {
logger.warn('Forced exit after timeout');
process.exit(1);
}, 25000).unref();
});
Добавили в src/server.ts, открыли PR #5. Ревью прошло без замечаний.
Но после деплоя ожидаемых строк в логах не появилось.
Ни "SIGTERM received", ни "HTTP server closed" - ничего.
Обработчик как будто не существовал.
Причина #5 - Node.js не получает SIGTERM: yarn как PID 1
CMD ["yarn", "start"] А start в package.json: "start": "NODE_ENV=production node -r newrelic --enable-source-maps build/src/server.js"
Вот и проблема. Когда контейнер стартует через CMD ["yarn", "start"], процесс yarn становится PID 1 в контейнере. Yarn Classic (1.x) не пробрасывает сигналы дочерним процессам. Kubernetes посылает SIGTERM yarn, yarn его просто игнорирует, node - дочерний процесс - не получает ничего.
PID 1: yarn
-> sh -c "NODE_ENV=production node ..."
-> node build/src/server.js <- SIGTERM сюда не доходитРешение простое - убрать yarn из цепочки и запустить node напрямую как PID 1.
ENV NODE_ENV=production CMD ["node", "-r", "newrelic", "--enable-source-maps", "build/src/server.js"]
NODE_ENV=production был захардкожен в yarn start - просто перенесли в ENV в Dockerfile.
PID 1: node build/src/server.js <- получает SIGTERM напрямую от Kubernetes
Причина #6 - server.close() не закрывает idle-соединения
После деплоя PR #6 shutdown-логи наконец появились. "SIGTERM received" - есть. "HTTP server closed" - есть. Но несколько 460 всё равно проскакивали.
Смотрю тайминг: 460 появляются в самом конце жизни пода, уже после того как server.close() отработал.
Тонкость в том, что server.close() перестаёт принимать новые соединения и ждёт завершения активных запросов - но idle keep-alive соединения при этом не закрывает. Бот-фреймворк вендора держит пул таких соединений открытыми между запросами. Если соединение было idle в момент shutdown - server.close() его не трогает. Оно висит до истечения terminationGracePeriodSeconds, потом прилетает SIGKILL от Kubernetes - и в этот момент соединение рвётся без предупреждения. Клиент пытается использовать мёртвое соединение - получает 460.
Решение: явно закрыть все idle-соединения до вызова server.close().
server.closeIdleConnections();
server.close(() => {
process.exit(0);
});
closeIdleConnections() немедленно завершает соединения, по которым нет активных запросов. Активные - продолжают обрабатываться до конца. Именно такой порядок нужен.
Важно: closeIdleConnections() появился в Node.js 18.2.0. На более старых версиях (16.x и ниже) метода нет - понадобится либо обновить Node.js, либо вручную отслеживать и закрывать idle-соединения.
Итоговая схема: все слои и настройки
Настройки соединений:
+-----------------------------------------------+
| Слой | Параметр | Значение |
+-----------------------------------------------+
| AWS ALB | idle timeout | 60s |
| Node.js | keepAliveTimeout | 65s (>60s) |
| Node.js | headersTimeout | 66s (>65s) |
| Pod | CPU limit | 500m |
| Pod | memory limit | 1536Mi |
+-----------------------------------------------+
keepAliveTimeout должен быть больше ALB idle timeout,
иначе Node.js закроет соединение раньше ALB -> 502.
Завершение пода (rolling deploy / OOMKill / restart):
t= 0s K8s удаляет под из Endpoints
K8s запускает preStop hook
|
+-- preStop: sleep 15s
| (ждём пока ALB дерегистрирует под,
| иначе запросы идут на умирающий под -> 502)
|
t=15s preStop завершён
K8s отправляет SIGTERM -> node (PID 1)
| (именно node, не yarn -- Yarn Classic сигналы не пробрасывает)
|
+-- server.closeIdleConnections()
| (закрываем idle keep-alive прямо сейчас,
| иначе доживут до SIGKILL и дадут 460)
|
+-- server.close()
| (перестаём принимать новые соединения,
| ждём завершения активных запросов)
|
+-- setTimeout(force exit, 25s)
(страховка: если запрос завис и server.close()
не вызвал колбэк -- выходим до SIGKILL)
t=?s активные запросы завершились -> process.exit(0)
t=30s K8s: SIGKILL (terminationGracePeriodSeconds)
Итого окно для активных запросов: 30 - 15 = 15sЧто добавляли по пути
Помимо параметров и кода, по ходу расследования добавляли и инструменты обсервабилити:
- Логирование - добавили явное логирование события получения SIGTERM и закрытия HTTP-сервера. Раньше это было чёрным ящиком - не было понятно, что происходило с сервером в момент завершения.
- Анализ ALB-логов - настроили регулярный разбор target_status_code, target_processing_time и elb_status_code в OpenSearch. Раньше смотрели только на наличие 5xx - теперь ещё и на то, ответил ли под вообще.
- Prometheus-запросы - добавили в регулярный осмотр метрики CFS-троттлинга (container_cpu_cfs_throttled_seconds_total) и количество терминированных контейнеров с причиной (kube_pod_container_status_last_terminated_reason). Без этого CPU-проблема выглядела бы просто как "иногда 502".
Итог
keepAlive fix - keepAliveTimeout 65s, headersTimeout 66s - убирает 502 от гонки таймаутов Node.js vs ALB
- PR #1 - preStop: sleep 15 - фиксит 502 при роллинг-деплоях
- PR #2 - отключение автоскейлинга воркера - убирает лишние деплои
- PR #3 - memory limit 800Mi -> 1536Mi - фиксит OOMKill при пиках нагрузки
- PR #4 - CPU limit 200m -> 500m - фиксит CPU throttle -> liveness probe перезапускает контейнеры
- PR #5 - graceful shutdown на SIGTERM - фиксит 502/460 при завершении подов
- PR #6 - node как PID 1 в Dockerfile - фиксит то что SIGTERM вообще не доходил до Node.js
- PR #7 - server.closeIdleConnections() перед server.close() - фиксит 460 от idle keep-alive соединений
Суммарно на весь дебаг ушло около четырёх недель. Не потому что фиксы сложные - большинство из них несложные. А потому что без логов и метрик каждый следующий шаг был невозможен: сначала нужно было включить ALB логи, потом накопить статистику, потом разобраться с первой причиной - и только тогда стала видна вторая. Каждый закрытый слой убирал шум и открывал следующий. На самом деле было 9 исправлений, но я смог вспомнить только 7 из них.
После всех фиксов ошибки 502/504/460 ушли полностью, клиенты рады, сервис работает на отлично.
Несколько выводов, которые оставлю здесь для себя и тех, кто столкнётся с похожим:
- Если первый фикс помог - не спешите радоваться. Несколько независимых причин могут маскировать друг друга. Смотрите на абсолютное количество ошибок, не только на тренд
- Включите ALB access logs сразу. target_status_code: null и target_processing_time вместе сразу говорят где именно рвётся цепочка - не тратьте время на угадывание
- preStop: sleep N - обязательный минимум для любого сервиса за ALB при роллинг-деплоях (на самом деле не всегда, но пусть будет обязательным для статьи)
- CPU-лимит в Kubernetes - это не просто "ограничение". Для однопоточных рантаймов (Node.js, Python GIL) троттлинг убивает не производительность, а живость сервиса целиком
- Дефолтный http.Server в Node.js не делает graceful shutdown - надо писать руками
- Написать SIGTERM-обработчик недостаточно - надо убедиться что процесс вообще получает сигнал. CMD ["yarn", "start"] в Dockerfile делает yarn PID 1, и Yarn Classic сигналы не пробрасывает. Запускайте node напрямую
- 460 от ALB - это не "клиент сам ушёл". Это часто симптом того, что сервер рвёт keep-alive соединения без предупреждения
- server.close() в Node.js не закрывает idle keep-alive соединения - без closeIdleConnections() они будут висеть до SIGKILL и давать 460 в самом конце
Ссылки
Tuning HTTP Keep-Alive in Node.js (про keepAliveTimeout, headersTimeout и откуда берутся 502 при Node.js за ALB)
AWS ALB access logs - список всех полей и как включить
AWS ALB - настройка idle timeout и других атрибутов балансера
Express.js - graceful shutdown и работа с http.Server
Kubernetes - preStop hooks и жизненный цикл пода
Kubernetes KEP-3960 - нативный sleep в preStop (PodLifecycleSleepAction, GA в 1.34)