Тесты были зелёными, а уведомление не отправилось ни разу

В Slack упало оповещение о 500-й. Сообщение об ошибке выглядело незнакомо: Error: Custom Id cannot contain :. Падал API, через который администратор публикует ответ на вопрос пользователя, а стек-трейс указывал на Job.validateOptions из BullMQ.

До этого места история выглядит как обычный баг-репорт. Необычной она становится после того, как нашлась причина. Код, бросавший эту ошибку, не менялся в том дневном деплое. Он падал каждый раз, в 100% случаев, с того самого дня, когда фича появилась. А это значит, что пуш-уведомления, которые должна была отправлять эта очередь, не отправлялись ни разу. И всё это время тесты были зелёными.

Причина в одном символе

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

await this.queue.add(ANSWER_NOTIFY_JOB_NAME, data, {
  jobId: `answer-notify:${data.questionId}`, // ← вот это двоеточие
});

Кастомный jobId здесь нужен, чтобы задача по одному вопросу не встала в очередь дважды, но в качестве разделителя выбрали двоеточие. BullMQ собирает ключи Redis через двоеточие и поэтому запрещает его в кастомных jobId. Для v5 точное условие такое: если в jobId есть двоеточие и при разбиении по нему получается не три части, бросается ошибка. Исключение для трёх частей - это оговорка ради легаси-формата repeatable-задач, так что двухчастный answer-notify:123 гарантированно получает Custom Id cannot contain :. К слову, чисто числовой jobId тоже отклоняется с Custom Id cannot be integers, так что просто убрать префикс - тоже не выход.

Десятки других очередей в кодовой базе везде использовали дефис. Двоеточие было только в этом файле.

Баг жил с первого дня. Почему же он взорвался только сегодня

Исправление занимает одну строку: поменять двоеточие на дефис. Интересный вопрос в другом. Почему код, падавший всегда, всё это время молчал и превратился в 500-ю именно сегодня?

Когда фича впервые уехала в прод, enqueue был обёрнут вот так.

try {
  await this.queue.add(/* ... */);
  return true;
} catch (err) {
  this.logger.error("enqueue failed", err);
  return false; // ← сбой исчезает здесь
}

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

Потом в тот же день влился коммит, поменявший этот контракт. Идея была правильная: если enqueue не удался, не глотать сбой, а бросать исключение, чтобы откатить проставленную в транзакции отметку "отвечено" и дать возможность повторить. В этот момент всегда падавший enqueue впервые подал голос. 500-я была не багом того коммита, а первым криком бага, который жил там всегда.

Вот цена кода, глотающего ошибки. Сигнал исчезает, а баг остаётся и забирает с собой целую фичу.

Почему тесты были зелёными

У этой очереди были тесты. Обычный спек: вызываем enqueue и проверяем, что queue.add вызван с правильными аргументами. И queue.add в этом тесте был моком, который всегда успешен.

Настоящий add в BullMQ валидирует jobId и отклоняет двоеточия. add мока принимает что угодно. Ровно настолько, насколько мок снисходительнее реального контракта, тест пропускал зелёным вход, который в реальности не пройдёт никогда. Когда мок расходится с реальным контрактом, зелёный тест сертифицирует не живой код, а мёртвый.

Исправляя баг, я первым делом закрыл эту дыру. Мок очереди теперь прогоняет в своём add настоящий Job.validateOptions из BullMQ. Эта функция - чистая валидация, работающая без Redis, так что её можно положить в тест как есть. А потом я проверил мутационным тестом, что защита действительно защищает: вернул двоеточие, увидел, что тест краснеет ровно в этом месте, и только после этого закоммитил. Если баг вернули, а тест всё ещё зелёный, такого теста всё равно что нет.

Случай был не один

Остановиться здесь значило бы исправить только половину. Если одна и та же ошибка есть в одном месте, велика вероятность, что она есть и в других. Я определил "класс" дефекта - кастомный jobId с двоеточием - прочесал всю кодовую базу и повесил несколько ревью-агентов на перекрёстную проверку. Нашлись ещё два случая.

Первый - очередь, транскрибирующая в текст загруженные пользователями аудио. jobId: "stt:${id}". Здесь ошибка по-прежнему проглатывалась, так что не было даже 500-й. Проверка показала: уже 12 дней ни одна задача транскрипции не попадала в очередь. Аудиофайлы исправно сохранялись, сбои оседали только в логах, а на экране пользователя текст оставался пустым навсегда. Полное отсутствие симптомов.

Второй - очередь информационных писем о запланированных событиях. Её jobId состоял из четырёх частей через двоеточие, поэтому ни напоминания, ни уведомления об отмене в очередь вообще не попадали.

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

Вторая ловушка: фиксированный jobId тихо убивает ретраи

Хорошо бы истории на этом закончиться, но проверка на ревью вскрыла проблему поглубже. После исправления двоеточия оживает фиксированный jobId вида answer-notify-123, а этот фиксированный jobId сам по себе противоречил контракту ретраев, установленному в тот же день.

Если хеш задачи с тем же jobId ещё лежит в Redis, BullMQ без всякой ошибки игнорирует новый add и возвращает существующий jobId. Проверяющий дочитал до Lua-скриптов BullMQ и подтвердил это поведение. А у этой очереди стоит removeOnComplete: { count: 100 }, так что хеш только что завершённой задачи остаётся на месте. Складываем и получаем такой сценарий. Задача уведомления один раз падает. По контракту отметка "отвечено" откатывается, администратор повторяет попытку. Новый enqueue натыкается на оставшийся хеш задачи, не делает ничего и возвращается как будто успешно. Уведомление не уйдёт никогда, но на этот раз нет ни ошибки, ни DLQ.

Мы убрали catch, глотавший сбои, и его место занял dedupe библиотеки. В итоге из этой очереди кастомный jobId убрали совсем. Защиту от дублей перенесли на сторону консюмера: процессор атомарно захватывает отметку "уведомление отправлено" условным обновлением. Даже если задача придёт дважды, пуш отправит только та сторона, которая первой захватила отметку.

Если у вас дубли блокируются кастомным jobId и одновременно есть дизайн с повторной постановкой при сбое, стоит проверить, не убивают ли эти два механизма друг друга. Может оказаться, как у нас, что комбинация превращает ретрай в тихий no-op.

Каким оказался ущерб

Фича, мёртвая 12 дней, звучит как большой ущерб, но замеры показали другое. Уведомления об ответах относились к фиче, которой в проде ещё никто по-настоящему не пользовался, потерь ноль. В очереди писем остались только прошедшие события, повторно отправлять было нечего. Реально восстанавливать пришлось два нетранскрибированных аудио. Их перегнали заново из сохранённых файлов.

Нам повезло. И это везение не повторяется. Будь фича в реальном использовании, 12 дней уведомлений и транскрипций пропали бы безвозвратно, и деплой не вернул бы ничего, потому что задачи в очереди никогда не создавались. Скрипт бэкфилла был делом второстепенным. Суть, как я решил, в другом: исправить сам факт, что мёртвая фича 12 дней считалась живой. Поэтому сбои транскрипции теперь не оседают в логах, а поднимаются в канал оповещений, а путь уведомлений об ответах переехал на outbox, коммитящийся вместе с транзакцией, чтобы состояния "в БД записан успех, а задачи нет" больше не существовало.

Что осталось

Три вещи из этой истории, которые переживут сам код.

Во-первых, catch, который только пишет в лог и возвращает норму, делает так, что даже стопроцентно падающий путь никто не замечает. Если уж глотать, рядом обязана быть метрика или алерт, считающие сбои, а если их нет, лучше бросать. Брошенная ошибка шумит, но её чинят; проглоченная живёт 12 дней.

Во-вторых, мок обязан быть таким же строгим, как реальный контракт. Поверх всегда успешного мока не валидируется ни один вход. Если в библиотеке есть чистая функция валидации, посадите её в мок и убедитесь, вернув баг, что тест краснеет. Только тогда это защита.

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