テストは緑なのに、通知は一度も送信されていなかった

Slack に 500 のアラートが上がった。エラーメッセージに見覚えがなかった。Error: Custom Id cannot contain :。管理者がユーザーの質問に回答を登録する API が死んでいて、スタックトレースは BullMQ の Job.validateOptions を指していた。

ここまでは平凡なバグレポートだ。この話が平凡でなくなるのは、原因を突き止めたあとである。このエラーを投げているコードは、その日のデプロイで変わったものではなかった。機能が最初に入った日から毎回、100%失敗し続けていたのだ。つまり、このキューが送るはずだったプッシュ通知は、これまで一度も送信されたことがないということになる。そしてその間、テストはすべて緑だった。

原因は一文字

問題のコードはこういう形をしていた。質問に回答が付いたらユーザーにプッシュを送るジョブを、キューに入れる場所だ。

await this.queue.add(ANSWER_NOTIFY_JOB_NAME, data, {
  jobId: `answer-notify:${data.questionId}`, // ← このコロン
});

同じ質問に対してジョブが二重に入らないようカスタム jobId を付けたのだが、区切り文字にコロンを使ってしまった。BullMQ は Redis のキーをコロンで組み立てるため、カスタム jobId のコロンを禁止している。v5 での正確な条件はこうだ。jobId にコロンが含まれ、かつコロンで分割した断片が3個でなければ投げる。3断片の例外はレガシーの repeatable ジョブ形式のためのカーブアウトなので、answer-notify:123 のような2断片は必ず 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 は、無条件に成功するモックだった。

実際の BullMQ の add は jobId を検証し、コロンを拒否する。モックの add は何でも受け取る。モックが実際の契約より寛容である分だけ、テストは現実では絶対に通らない入力を緑で通していた。モックが実際の契約と違えば、緑のテストは生きているコードではなく、死んだコードを保証する。

修正のついでに、まずこの穴をふさいだ。キューのモックの add が BullMQ の実際の Job.validateOptions を通るように変えた。この関数は Redis なしで動く純粋な検証なので、テストにそのまま載せられる。そしてガードが本当にガードなのか、ミューテーションテストで確かめた。コロンを元に戻してみて、テストがまさにその箇所で赤くなるのを見届けてからコミットした。バグを元に戻してもテストが緑のままなら、そのテストは無いのと同じだ。

一件では済まなかった

ここで止まっていたら、半分しか直していないことになる。同じミスが一箇所にあるなら、ほかの場所にもある可能性が高い。欠陥の「クラス」を定義して - コロンが混ざったカスタム jobId - コードベースを全数捜索し、レビュー用のエージェントを複数付けてクロスチェックまでかけた。さらに2件出てきた。

一つは、ユーザーがアップロードした音声をテキストに文字起こしするキューだった。jobId: "stt:${id}"。こちらはエラーを依然として握りつぶしていたので、500 すら出ていなかった。調べてみると、12日前から文字起こしジョブが一件もキューに入っていなかった。音声ファイルは正常に保存され、失敗はログにだけ残り、ユーザーの画面ではテキストが永遠に空のまま。完全な無症状だった。

もう一つは、予約された日程の案内メールのキューだった。jobId がコロン区切りの4断片で、リマインダーもキャンセル案内もキューにまったく入っていなかった。

3つのキューの producer を、共通の jobId ビルダー一つに統一した。ハイフンで結合し、コロンが混ざれば置換し、純粋な数字を拒否する関数だ。再発防止として、コロンのリテラルが jobId に入るパターンだけを正確に捕まえる lint ルールも追加した。既存のハイフン jobId 50箇所あまりを無理に新しいビルダーへ移行することはしなかった。repeatable ジョブの jobId が変わると cron が二重登録されるリスクがあるので、欠陥クラスだけを狙い撃つ方を選んだ。

二つ目の罠: 固定 jobId はリトライを静かに殺す

話がここで終わればよかったのだが、レビューの検証中にもっと根本的な問題が出てきた。コロンを直すと answer-notify-123 のような固定 jobId が生き返るのだが、この固定 jobId 自体が、同じ日に立てたリトライの契約と矛盾していたのだ。

BullMQ は、同じ jobId のジョブハッシュが Redis に残っていると、新しい add をエラーなしで無視して既存の jobId を返す。検証者が BullMQ の Lua スクリプトまで読んで確認した挙動だ。ところがこのキューは removeOnComplete: { count: 100 } なので、完了したばかりのジョブのハッシュもそのまま残る。組み合わせると、こういうシナリオになる。通知ジョブが一度失敗する。契約どおり「回答済み」の印をロールバックし、管理者がリトライする。新しい enqueue は残っているジョブハッシュに引っかかって何もせず、成功したかのように返る。通知は永遠に出ないのに、今度はエラーも DLQ もない。

失敗を握りつぶす catch を消したら、ライブラリの dedupe が同じ席を引き継いだ格好だ。結局このキューではカスタム jobId を丸ごと外した。重複送信の防止はコンシューマー側へ移し、プロセッサーが「通知送信済み」の印を条件付き更新でアトミックに先取りするようにした。ジョブが二重に入ってきても、印を先に取った側だけがプッシュを撃つ。

カスタム jobId で重複を防いでいて、かつ失敗時に再 enqueue する設計が同居しているなら、二つの仕掛けが互いを殺していないか確かめてみる価値がある。うちのように「リトライが静かに no-op になる」組み合わせかもしれない。

被害はどれくらいだったか

12日間死んでいた機能と聞けば被害は大きそうだが、実測の結果は違った。回答通知は、その機能がまだ本番で実利用前だったため損失は0件。メールのキューも過去の日程ばかりで、再送すべき対象がなかった。実際に回収が必要だったのは、文字起こしされていなかった音声2件。残っていた音声ファイルで再度文字起こしして復旧した。

運が良かった。そしてこの運は繰り返さない。実利用中の機能だったなら、12日分の通知と文字起こしがそのまま消えていたはずで、ジョブがそもそもキューに作られたことがない以上、デプロイでは何も回収できなかっただろう。バックフィルのスクリプトを書くことは二の次だった。死んだ機能が12日間死んでいたと誰も知らなかった、という事実を直すのが本質だと判断した。そこで、文字起こしの失敗がもうログにだけ残るのではなくアラートのチャンネルに上がるようにし、回答通知の経路はトランザクションと一緒にコミットされるアウトボックスへ移して、「DB には成功が記録されているのにジョブは無い」という状態そのものを無くした。

残ったもの

今回の件でコードより長く残るであろう三つのこと。

一つ目。catch でログだけ残して正常に返すコードは、その経路が100%失敗していても誰にも気づかせない。握りつぶすなら、最低でも失敗を数えるメトリクスかアラートがセットで必要で、それが無いなら投げたほうがいい。投げられたエラーはうるさいが直される。握りつぶされたエラーは12日間生き延びる。

二つ目。モックは実際の契約と同じだけ厳格でなければならない。無条件に成功するモックの上では、どんな入力も検証されない。ライブラリに純粋な検証関数があるならモックに通し、バグを元に戻してテストが赤くなるところまで確認して、初めてガードだ。

三つ目。欠陥はクラスで捕まえる。同じコードベースで同じミスは一度きりでは起きない。一つ見つけたらクラスを定義して全数捜索し、lint ルールなり共通ビルダーなりでそのクラスが二度と入って来られないように塞ぐところまで行って、初めて一度の発見が元を取る。