Квота на 95 писем и одно письмо: постмортем ночного SIGBUS в celery

Разбор ночного инцидента на Tech Path Finder по тому же каркасу, который я описывал в «Диск на сто процентов и восемьдесят семь тысяч»: коротко, хронология, пять «почему», что сработало, пункты. Проект мой, дежурил тоже я, так что фамилию в пятом «почему» искать не будем.

Обнаружено: 03:00. Активная фаза: около полутора минут. Последствие: сутки без писем верификации.

Коротко

Дневная квота писем, 95 штук, выбрана за полторы минуты. Отправлено при этом одно письмо.

Кого задело: всех, кто регистрировался на платформе до конца суток. Письмо с подтверждением адреса не уходило, а без подтверждения аккаунт не активируется.

Корень: healthcheck контейнера каждые тридцать секунд импортировал приложение целиком, вместе с ним поднимался prometheus_client в multiprocess-режиме и заводил в tmpfs новый комплект mmap-файлов. Убирать их некому. За трое суток накопилось 22945 файлов, отведённые 64 мегабайта кончились, и запись метрики из воркера стала физически невозможной.

Как подняли: перезапуск контейнера. tmpfs при старте создаётся заново и уносит с собой все 22945 файлов.

Чтобы не повторить: unset переменной в healthcheck, tmpfs до 256 МБ, счёт писем после SMTP вместо счёта до, отдельный алерт на смерть исполнителя.

Хронология

Восстановлена по метрикам, логам контейнера и содержимому tmpfs. Ноль это момент деплоя, после которого healthcheck начал работать в текущем виде.

T+0        деплой; tmpfs /tmp/prom_multiproc пустая, 64 МБ свободно
           далее каждые 30 с healthcheck поднимает процесс: +3 файла
T+72 ч     в каталоге 22945 файлов, свободно 0 байт
03:00      воркер пишет метрику в свой mmap, страницу некуда сбросить
           SIGBUS, форк умирает; task_postrun не выполняется, метрика не пишется
03:00      acks_late возвращает неподтверждённое сообщение в очередь
           следующий форк умирает так же; цикл примерно раз в секунду
03:01:30   счётчик писем в Redis дошёл до 95, ушёл алерт «дневной лимит исчерпан»
           петля продолжается, но каждая попытка теперь выходит на лимите
03:0x      разбор, перезапуск контейнера
           до 00:00 UTC письма верификации не отправляются: квота исчерпана

В этой хронологии важно, чего в ней нет. Нет ни одной записи мониторинга между T+0 и 03:00, хотя течь работала все трое суток. И нет ни одной записи о смерти процессов, хотя за полторы минуты их умерло около сотни.

Пять «почему»

1. Почему сгорела дневная квота писем? Счётчик в Redis дошёл до 95 при одном фактически отправленном письме.
2. Почему счётчик дошёл до 95? Он инкрементируется первой строкой задачи, до дедупа и до SMTP, а задача переотправлялась брокером примерно раз в секунду.
3. Почему задача переотправлялась? Форк-исполнитель умирал, не подтвердив сообщение. При task_acks_late и task_reject_on_worker_lost неподтверждённое сообщение возвращается в очередь, и потолка попыток у этого механизма нет.
4. Почему форк умирал? SIGBUS при записи метрики в mmap-файл на файловой системе, где кончилось место.
5. Почему кончилось место? Healthcheck каждые тридцать секунд поднимал питоновский процесс, который импортировал приложение, поднимал prometheus_client в multiprocess-режиме и заводил себе комплект файлов. mark_process_dead привязан к сигналу celery worker_process_shutdown, а healthcheck не воркер и такого сигнала не шлёт.
6. Почему не заметили за трое суток? На заполнение tmpfs нет алерта. А телеметрия исходов задач висит на task_postrun, который в процессе, убитом сигналом, не выполняется никогда.

Корень: healthcheck, импортирующий приложение целиком, при PROMETHEUS_MULTIPROC_DIR, выставленной на весь контейнер.

Способствующие: счётчик писем считает попытки; телеметрия слепа к смерти по сигналу; tmpfs 64 МБ без запаса на рост числа серий; порядок проверок в email-задачах продублирован восемь раз.

Механизм

Пять «почему» дают скелет. Дальше подробности, ради которых, собственно, и стоит читать чужие постмортемы.

Счётчик, который нельзя спросить. Проверка лимита выглядела так:

def _check_daily_limit() -> bool:
    """Инкрементирует дневной счётчик и возвращает True, если лимит не превышен."""
    r = _get_cached_redis()
    today = datetime.now(UTC).strftime("%Y%m%d")
    key = f"{_EMAIL_DAILY_PREFIX}{today}"
    count = r.incr(key)
    ...
    if count > _EMAIL_DAILY_LIMIT:
        _alert_daily_limit_reached()
        return False
    return True

Функция называется «проверить», а делает incr. Узнать у неё, осталось ли в квоте место, невозможно, не заняв это место: она устроена как турникет, который отвечает на вопрос «пропустите ли вы меня» тем, что пропускает.

Вызывалась она первой строкой в каждой из восьми email-задач:

def send_welcome_email_task(email, full_name, verification_url) -> None:
    if not _check_daily_limit():
        return
    if not _email_dedup_check(email, "welcome"):   # ← дедуп ПОСЛЕ инкремента
        logger.info("Welcome email dedup skip for %s", email)
        return
    ...
    asyncio.run(svc.send_welcome_email(...))       # ← а SMTP вот тут, ниже

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

Петля, у которой нет потолка. Celery настроен так:

task_acks_late=True,
task_reject_on_worker_lost=True,
worker_prefetch_multiplier=1,

Настройки выбраны осознанно. Брокер получает подтверждение после выполнения задачи, а не в момент выдачи; если исполнитель умер на середине, сообщение возвращается в очередь. Для письма с подтверждением адреса это то, что нужно: отправить дважды неприятно, потерять хуже.

Обратная сторона описана в документации, но вживую её видишь редко. Возврат в очередь здесь работает не как retry. У retry есть счётчик попыток и потолок, за которым задача уходит в мёртвую очередь. Тут нет ни счётчика, ни потолка, потому что прикладной уровень в происходящем не участвует вовсе: сообщение не подтверждено, и брокер по своему протоколу обязан выдать его снова. Пока исполнитель умирает, брокер будет выдавать. Он не устанет раньше вас.

Отчёт пишет покойник. Метрики исходов висели на сигнале task_postrun:

@task_postrun.connect(weak=False)
def _on_task_postrun(sender=None, state=None, **_):
    celery_task_total.labels(task=name, state=state).inc()

task_postrun выполняется в том же процессе, что и сама задача. До процесса, убитого сигналом, эта строчка не доходит: ни SIGKILL, ни SIGBUS, ни визит OOM-killer не оставляют времени дописать метрику. worker_process_shutdown не выполняется по той же причине.

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

22945 файлов. SIGBUS в Python редкость. Это сигнал про физическую невозможность обратиться к странице памяти, и в прикладном коде на него натыкаются практически единственным способом: записью в mmap-файл там, где кончилось место.

mmap-файлы здесь пишет prometheus_client. Celery форкается, каждый процесс пула ведёт собственный набор файлов, общий каталог лежит в tmpfs:

tmpfs:
  - /tmp/prom_multiproc:mode=1777,size=64m

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

В каталоге лежало 22945 файлов: 12044 counter, 5450 gauge_livesum, 5449 histogram. В пуле при этом два процесса. Двадцать три тысячи комплектов на два процесса объясняются одной строкой из compose:

healthcheck:
  test:
    [
      "CMD-SHELL",
      "/app/.venv/bin/python -m celery -A app.core.celery_app inspect ping 2>&1 | grep -q pong",
    ]
  interval: 30s

Раз в тридцать секунд docker поднимает питоновский процесс, чтобы спросить у воркера одно слово. Процесс импортирует app.core.celery_app, вместе с ним поднимается prometheus_client, обнаруживает в окружении PROMETHEUS_MULTIPROC_DIR, выставленную на весь контейнер, и делает единственное, что умеет в этом режиме: заводит на себя, на свой новенький pid, полный комплект файлов под все зарегистрированные метрики.

Дальше процесс получает «pong», удовлетворённо выходит и оставляет комплект лежать. Он вообще ничей: зашёл, спросил, ушёл и завёл на себя дело, которое теперь некому закрыть.

Трое суток, раз в тридцать секунд, примерно по три файла за визит. 22945. Сходится без остатка.

Что сработало и что нет

Сработало, и это стоит записать отдельно, иначе разбор выглядит как порка.

Лимит писем сделал ровно то, ради чего ставился. Он выглядел как виновник, а работал как предохранитель: остановил цикл на девяносто пятой попытке и разбудил меня. Без него петля молотила бы в SMTP до утра, и разговор был бы уже не про метрики, а про репутацию домена.

Алерт о квоте дошёл за секунды после срабатывания. acks_late не потерял ни одной задачи, что, по иронии, и создало петлю: настройка отработала как обещано.

Не сработало вот что. Трое суток течи прошли без единой записи в мониторинге: алерта на заполнение tmpfs нет. Сотня смертей процессов прошла молча: телеметрия слепа к смерти по сигналу. Первый сигнал о технической аварии пришёл в виде бизнесового алерта про письма, то есть на четыре звена дальше места, где всё сломалось.

Пункты

Исполнитель везде Константин Потапов, проект сольный.

Предотвратить. Сделано в тот же день.

Переменная снимается для одной команды healthcheck:

test:
  [
    "CMD-SHELL",
    "unset PROMETHEUS_MULTIPROC_DIR; /app/.venv/bin/python -m celery -A app.core.celery_app inspect ping 2>&1 | grep -q pong",
  ]

Именно unset, не пустое значение. prometheus_client смотрит на наличие ключа в окружении (values.get_value_class), а не на его содержимое. С PROMETHEUS_MULTIPROC_DIR= он остался бы в многопроцессном режиме и сложил бы тот же комплект в рабочий каталог контейнера. Течь никуда бы не делась, она переехала бы туда, где нет ни лимита в 64 мегабайта, ни SIGBUS, ни вообще способа однажды это заметить.

Там же tmpfs с 64 мегабайт до 256: прежний размер брался под два процесса пула, без запаса на рост числа серий.

Квота стала считать письма. Проверка лимита теперь read-only, счёт переехал в отдельную функцию после фактической отправки, дедуп встал первым:

def _should_send(recipient: str, email_type: str) -> bool:
    if not _email_dedup_check(recipient, email_type):
        logger.info("Email dedup skip type=%s recipient=%s", email_type, recipient)
        return False
    return not _daily_limit_reached()

    try:
        asyncio.run(svc.send_welcome_email(email, full_name, verification_url))
        _register_email_sent()          # ← счёт после SMTP, а не до

Все восемь задач ходят через один _should_send. Раньше каждая держала обе проверки у себя, и порядок, в котором они стоят, был записан восемь раз подряд. Неправильный порядок, соответственно, тоже восемь раз подряд.

Заметить раньше. Сделано частично.

О WorkerLostError теперь рассказывает главный процесс, единственный участник происшествия, который его пережил:

@task_failure.connect(weak=False)
def _on_worker_lost(sender=None, exception=None, **_):
    if not isinstance(exception, WorkerLostError):
        return
    name = str(getattr(sender, "name", None) or "unknown")
    celery_task_total.labels(task=name, state="failure").inc()
    celery_worker_lost_total.labels(task=name).inc()

Фильтр по типу исключения обязателен: обычные ошибки уже посчитал postrun внутри исполнителя, и без фильтра каждая ложилась бы в failure дважды.

Алерт tpf-celery-worker-lost заведён отдельно от «фоновые задачи падают», и разница не косметическая. Упавшая задача это одна невыполненная работа. Исполнитель, умерший при acks_late, это работа, которая теперь крутится в очереди без конца и жжёт всё, что в системе считается по попыткам. Будить по этим двум поводам надо по-разному.

Открытый пункт: алерта на заполнение tmpfs по-прежнему нет. Ровно та проверка, отсутствие которой дало трое суток тишины, до сих пор не написана.

Тушить быстрее. Открыто. Runbook на «форки умирают, очередь крутится» не написан. В ту ночь спасло то, что упёрлось в предохранитель, а не то, что я знал, куда смотреть.

Научиться. Тестов по итогам три вида. На квоту: одна задача, переотправленная пять раз, двигает счётчик на единицу. На метрику: worker_lost считается, обычное исключение не задваивается. И на docker-compose: что healthcheck снимает переменную, что снимает именно через unset, и что у tmpfs есть запас.

Третий выглядит дико. Регулярное выражение по YAML, ни строчки прикладного кода, тест на опечатку в конфиге. Но дефект жил именно в конфиге, а у правила «нашёл баг, напиши тест» нет сноски про инфраструктуру.

Сюда же этот разбор.

Что осталось в голове

Инцидент случился на третьи сутки после деплоя и в три часа ночи. Обе подробности выглядят значительно и не значат ничего: течь работала с первой минуты, просто наливала по три файла в тридцать секунд при ёмкости в 64 мегабайта. Дату и час назначило деление одного числа на другое.

Между тем, что я увидел, и тем, что произошло, оказалось четыре звена. Ни одно из них само по себе не дефект: и healthcheck, и tmpfs, и acks_late, и лимит на письма поставлены осознанно и делают то, о чём их просили.

Починить один счётчик было бы приятно. Симптом бы исчез, алерт замолчал, письма считались бы честно. Форки при этом продолжили бы умирать раз в секунду, и я бы об этом по-прежнему не знал.

Карточка проекта: tech-path-finder.