Лимит в 512 МБ убивал контейнер ровно на пятый день работы

MAATRIX

Контейнер падал не от пика трафика и не в момент деплоя — он держался четыре дня, спокойно работал, а на пятый день ровно в одно и то же время суток получал OOMKilled и уходил в перезапуск. Такая регулярность сбивает с толку сильнее, чем хаотичные падения: кажется, что должен быть внешний триггер — cron, бэкап, чей-то скрипт. На деле причина оказалась внутри процесса, и нашли её только тогда, когда перестали искать событие и начали искать тренд.

Что сломалось и как это выглядело в логах

Сервис — обычное API-приложение на Node.js за nginx, задеплоено через docker-compose с лимитом:

services:
  api:
    image: registry.internal/api:latest
    deploy:
      resources:
        limits:
          memory: 512M
    restart: unless-stopped

Первый сигнал — алерт от Uptime Kuma: сервис не отвечает на /health. В логах контейнера — тишина, никакого исключения, никакого stack trace, процесс просто исчез. docker inspect по контейнеру показывал:

"State": {
  "Status": "running",
  "OOMKilled": true,
  "ExitCode": 137
}

Код 137 — это 128 + 9, то есть процесс получил SIGKILL. В dmesg на хосте нашлась стандартная запись ядерного OOM killer:

Memory cgroup out of memory: Killed process 18213 (node) total-vm:1298456kB, anon-rss:524288kB, file-rss:0kB

Само по себе OOMKilled не новость — рассказ о том, как ядро вообще выбирает жертву и почему это не всегда виновный процесс, разобран отдельно в статье про механизм OOM killer. Здесь же интереснее не сам факт убийства, а его периодичность: контейнер перезапускался в понедельник в 03:14, в субботу в 03:09, в четверг в 03:20 — то есть с разбросом в 10-15 минут, но с интервалом примерно в пять суток от предыдущего рестарта. Это не совпадало ни с одним cron-заданием на хосте, ни с расписанием бэкапов, ни с деплоями — деплои случались раз в одну-две недели и никак не коррелировали с моментом падения.

Что показали метрики: рост без всплесков нагрузки

В Grafana был дашборд с container_memory_usage_bytes из cAdvisor. Первое, что бросилось в глаза при взгляде на пятидневное окно: график памяти — не пила и не плато с редкими скачками, а почти идеальная прямая, ползущая вверх с постоянным наклоном. Ни один деплой, ни один всплеск RPS не менял угол наклона этой линии — она росла одинаково что в рабочие часы с нагрузкой, что ночью почти без запросов.

Это сразу натолкнуло на мысль, что дело не в трафике: если бы память утекала на каждый запрос, график был бы неровным, с ускорением роста в часы пик. А тут рост шёл по времени, а не по количеству обработанных запросов — что обычно указывает на что-то, что копится по таймеру или по количеству вызовов какой-то фоновой функции, а не по HTTP-нагрузке напрямую.

Дополнительно смотрели метрику process_resident_memory_bytes из встроенного prom-client — она росла синхронно с cAdvisor, то есть утечка была не в сторонних процессах контейнера (их и не было — один PID на контейнер), а именно в самом Node.js-процессе.

Гипотезы, которые отбросили

Прежде чем разбирать код, проверили несколько версий, показавшихся правдоподобными:

• Наплыв соединений и keep-alive сокеты. Проверили ss -s внутри контейнера в разное время суток — число открытых сокетов колебалось в разумных пределах и не росло монотонно. Утечки файловых дескрипторов не было: ls /proc/1/fd | wc -l держался стабильным.
• Логи, буферизуемые в памяти перед записью. У приложения был winston с транспортом в stdout без файлового буфера — Docker сам стримит stdout в драйвер логирования, приложение ничего не держит в памяти сверх текущей строки.
• Рост кучи V8 из-за GC, который не успевает подчищать. Проверили process.memoryUsage() в отладочном эндпоинте: heapUsed действительно рос, но медленнее, чем rss — то есть основной рост шёл не в управляемой куче V8, а в чём-то, что не освобождается штатным сборщиком мусора или лежит вне JS-кучи (буферы, внешние объекты).
• Утечка в клиенте Redis или Postgres из-за незакрытых соединений. Пул подключений к Postgres (pg-pool) держал фиксированное число соединений, pg_stat_activity на стороне базы показывал стабильное количество активных клиентов — рост не оттуда.
• Что дело в самом Docker или overlay-файловой системе. Проверили на соседнем контейнере с тем же образом, но без реального трафика (тестовый стенд) — там память тоже медленно росла, только фоновым таймером, без единого HTTP-запроса. Это было ключевым наблюдением: раз рост шёл даже без трафика, значит, утечка привязана к внутреннему таймеру приложения, а не к обработке запросов.

Последний пункт и стал поворотным — он резко сузил круг подозреваемых до кода, который выполняется по расписанию независимо от нагрузки.

Реальная причина: список в модуле метрик, который никогда не чистился

В приложении был самописный модуль для дашборда admin-панели — он держал в памяти последние N запросов для отображения «недавней активности»: время, путь, код ответа, длительность. Задумывался как кольцевой буфер на 1000 записей. Код выглядел так:

const recentRequests = [];
const MAX_RECENT = 1000;

function trackRequest(entry) {
  recentRequests.push(entry);
  if (recentRequest.length > MAX_RECENT) {
    recentRequests.shift();
  }
}

Опечатка recentRequest вместо recentRequests в условии превращала проверку длины в обращение к undefined — на этот случай была общая обвязка try/catch вокруг вызова trackRequest, которая проглатывала исключение и писала в лог debug-уровня, отключённый в проде. В результате push продолжал работать, а shift никогда не вызывался: массив рос на одну запись при каждом обработанном запросе и ни разу не усекался.

Тут же объясняется и независимость роста от типа нагрузки в тестовом стенде: там стоял отдельный health-check от внешнего монитора, дергавший /health каждые 5 секунд — этого было достаточно, чтобы массив рос даже без «настоящего» трафика, просто медленнее. На проде с реальным RPS рост шёл быстрее, но не пропорционально — потому что каждая запись в массиве весит немного (несколько сотен байт со строками пути и таймстампом), и по-настоящему заметным эффект становится, когда счёт идёт на сотни тысяч и миллионы объектов, удерживаемых в памяти без права на сборку мусора.

Ровно пять дней — это не магическое число, а следствие конкретной комбинации: среднего RPS сервиса, размера одной записи и объёма памяти, который оставался свободным после старта процесса и загрузки всех модулей. Смените нагрузку или лимит — и интервал до падения сдвинется. Дальше в статье не будет точных цифр «столько-то МБ в сутки» как универсального ориентира — у вас эти числа будут другие в зависимости от вашего RPS и размера объекта, который утекает; важна методика поиска, а не конкретное значение наклона графика.

Как ловили утечку: heap snapshot diff и что он показал

Раз проблема не в куче V8 напрямую (см. heapUsed выше), можно было бы решить, что снимки кучи не помогут. На практике они всё равно помогли — потому что JS-массив с объектами физически живёт в managed heap, просто в разработке ошибочно предположили, что раз heapUsed рос медленнее rss, то виноват не JS-объект, а что-то внешнее. Правильнее было сразу сравнить два снимка кучи с разницей в сутки и посмотреть retained size по типам объектов — это быстрее, чем перебирать гипотезы вручную.

Процесс:

node --inspect=0.0.0.0:9229 server.js

Дальше через Chrome DevTools (chrome://inspect) подключились к процессу, сняли heap snapshot в момент t0, ещё один — через 24 часа (t0+1d), и сравнили их через режим Comparison. В сравнении по убыванию retained size на первом месте оказался массив с несколькими сотнями тысяч объектов формы { path, status, duration, timestamp } — ровно структура из trackRequest. Путь до него в графе объектов (retainers) вёл через модуль admin-дашборда до глобальной переменной модуля, которая никогда не обнулялась.

Если снимать снимки в контейнере без GUI, тот же diff можно получить через heapdump:

const heapdump = require('heapdump');
process.on('SIGUSR2', () => {
  heapdump.writeSnapshot(`/tmp/heap-${Date.now()}.heapsnapshot`);
});

docker exec api kill -USR2 1
# через сутки
docker exec api kill -USR2 1
docker cp api:/tmp/heap-*.heapsnapshot ./

Файлы .heapsnapshot затем открываются в DevTools локально (вкладка Memory → Load) для сравнения. Этот способ подробнее описан в статье про то, как поймать утечку памяти за неделю до падения — там же разобрана методика регулярного снятия снимков по расписанию, чтобы не ждать реального падения для диагностики.

Что изменили: код, лимиты, алерты

Правки внесли на нескольких уровнях, потому что исправление одной опечатки решает конкретный баг, но не защищает от следующей утечки такого же рода.

В коде — заменили самописный «кольцевой буфер» на настоящий, с фиксированным размером через модуль без риска рассинхронизации имени переменной:

class RingBuffer {
  #items = [];
  constructor(private maxSize) {}
  push(item) {
    this.#items.push(item);
    if (this.#items.length > this.maxSize) {
      this.#items.splice(0, this.#items.length - this.maxSize);
    }
  }
  toArray() {
    return this.#items;
  }
}
const recentRequests = new RingBuffer(1000);

Заодно убрали общий try/catch вокруг вспомогательных вызовов вроде trackRequest — он не должен маскировать ошибки в некритичном для бизнес-логики коде путём полного проглатывания исключения. Вместо этого ошибка логируется на уровне warn вне зависимости от режима debug/prod.

В лимитах контейнера — лимит памяти оставили тем же (512 МБ достаточно для нормальной работы сервиса без утечки), но добавили mem_reservation пониже, чтобы Docker раньше сигнализировал о приближении к границе, и настроили health-check, который проверяет не только HTTP-ответ, но и текущий rss процесса через /proc/self/status, отдавая unhealthy при приближении к 90% лимита — это позволяет Docker перезапустить контейнер превентивно, до жёсткого OOMKilled, и с более информативным логом на выходе. Общий разбор того, как выставлять resources.limits для CPU и памяти в docker-compose, есть в статье про лимиты ресурсов Docker.

В мониторинге — добавили алерт в Grafana не на факт превышения памяти (это уже поздно), а на скорость роста: если container_memory_usage_bytes растёт быстрее заданного порога в час на протяжении нескольких часов подряд, срабатывает предупреждение задолго до пятого дня. Это тот же принцип, что описан в разборе похожего инцидента, где каждую ночь падал не тот процесс из-за oom_score_adj — там тоже помогло смотреть не на факт падения, а на предшествующую ему динамику метрик.

Отдельно завели еженедельную задачу: снимать heap snapshot по расписанию и складывать в S3-совместимое хранилище с ротацией на 4 недели — это дёшево по месту и даёт возможность найти начало утечки по историческим данным, если что-то похожее повторится с другим модулем.

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