終了フックが二重に走っていた - SIGTERMの持ち主が二人いたとき

デプロイのたびにSentryに同じエラーが1つずつ落ちていた。Transaction already closed。Prismaがトランザクションがすでに閉じられた後にクエリを実行しようとしてP2028で落ちるエラーだ。ユーザーには何の被害もなかった。BullMQの再試行がすぐ別のタスクでジョブを成功させ、完了ログは途切れなく続いていた。それでもデプロイとトラフィックが重なるたびに静かに再発する構造だった。このエラーを追ううちに、私はサーバーの終了フックが実は毎回二重に実行されていたことを知ることになった。

第1幕: DBがジョブより先に死ぬ

エラーが発生した時刻をCloudWatchのログと突き合わせると、タイムラインがぴったり一致した。ローリングデプロイが旧タスクにSIGTERMを送る。6秒後にapp.close()がクリーンアップを始め、PrismaエンジンがトランザクションをClose。その直後、まだ動いていたasset-processingジョブのupdateManyが閉じたトランザクションの上で実行され、P2028で失敗する。ユーザーがオーディオを連続アップロード中で、ちょうどデプロイの瞬間にアクティブなジョブがあり、そのジョブのクエリが死んだ。

原因は終了順序だった。NestJSは終了時にライフサイクルフックを決まった順序で呼ぶ。問題はBullMQワーカーを閉じることとPrismaの接続を切ることが同じ終了フェーズ(onApplicationShutdown)にあったことだ。同じフェーズの中ではモジュールの登録順序が実行順序を決めるが、よりによってPrismaが先に切れると、まだジョブを処理中だったワーカーのクエリが行き場を失う。

直すべき方向ははっきりしていた。ワーカーをより早いフェーズで閉じればよい。NestJSの終了フックには順序があり、beforeApplicationShutdownはどのモジュールのonApplicationShutdownよりも先に完了する。すべてのワーカーを見つけて、この早いフェーズでドレイン(アクティブなジョブが終わるまで待機)するサービスを1つ作った。

@Injectable()
export class WorkerDrainService implements BeforeApplicationShutdown {
  constructor(private readonly discovery: DiscoveryService) {}

  async beforeApplicationShutdown() {
    // 登録済みの全WorkerHostを見つけて、アクティブなジョブが終わるまで待つ。
    // このフェーズはPrismaが切れるonApplicationShutdownより先に終わる。
    const workers = this.discovery
      .getProviders()
      .filter((p) => p.instance instanceof WorkerHost);
    await Promise.all(workers.map((w) => w.instance.worker.close()));
  }
}

Worker.close()は再度呼んでも同じpromiseを返すため、既存のワーカー終了処理と衝突せず、Redisがない環境では静かに何もしない。デプロイがジョブと重なっても、今はジョブが先に終わってからDBが閉じる。単体テストを付けてPRを上げた。ここまでは普通の順序バグ修正だった。

第2幕: SIGTERMの持ち主が二人いた

どんでん返しはレビューから来た。この修正を検討していたレビュアーが終了経路全体を追っていて、こう問いかけた。SIGTERMは一体誰が処理しているのか?

確認してみると持ち主が二人いた。main.tsにこんな2行が別々に存在していた。

// ① Nest自身に終了シグナルを任せる (引数なしで呼ぶとSIGTERM・SIGINT全部を登録)
app.enableShutdownHooks();

// ② http-graceful-shutdownライブラリにも終了を任せる
setupGracefulShutdown(server, {
  onShutdown: async () => {
    await app.close(); // ここでライフサイクルフック全体が実行される
  },
});

両方ともSIGTERMを掴んでいる。Nodeはシグナルが来ると登録されたリスナーを順番に、互いの完了を待たずに全部呼び出す。だから実際にSIGTERMが来た瞬間、こういうことが起きる。Nestが登録したリスナーがapp.close()と同じ終了シーケンスを、HTTPドレインを待たずに即座に一度実行する。それとは別にhttp-graceful-shutdownは自分のやり方でHTTPコネクションを空にした後、onShutdownでapp.close()をもう一度呼ぶ。終了フックが二重に回るわけだ。

頭の中の推論だけでは確信が持てず、本番の終了ログを読み直した。証拠がそのまま残っていた。SIGTERMが記録された時刻から20ミリ秒後、HTTPドレインが終わる前にonModuleDestroyが始まっており、SpeechServiceとQueueMonitorServiceの終了フックのログがそれぞれ二重に記録されていた。事故に至らなかった唯一の理由は、各サービスのフックが二度呼ばれても安全なように(idempotentに)組まれていたからだ。防御的に書かれていたおかげで「二重実行」は障害ではなくログの違和感として残っており、その違和感が最終的にバグを捕まえさせてくれた。

1行を消す

修正は1行を消すことだった。

// main.ts
- app.enableShutdownHooks();

enableShutdownHooks()をなくせば、SIGTERMの持ち主はhttp-graceful-shutdown一つに整理される。失うものは何もない。そちらのonShutdownが呼ぶapp.close()がどのみちライフサイクルフック全体を実行するからだ。変わるのはフックが二度ではなく一度、しかもHTTPドレインが終わった後に回るという点だけだ。

1行だけの修正ほど実測が要る。ビルドしたサーバーに実際にSIGTERMを送り、シーケンスを目で確認した。

Received SIGTERM → health check 503 → HTTP connections closed
→ shutdown hooks run only once, after HTTP close
→ Drained 56/56 BullMQ workers in 211ms → shutdown completed → clean exit

本番ではフックがHTTPドレインの前に二重に回っていたのが、今はドレインの後に一度だけ回る。第1幕のワーカードレイン修正と合わさった状態で検証したので、2つの修正が一緒に動く統合的な挙動まで確認できたことになる。

もう一つの落とし穴も併せて記録しておいた。NODE_ENV=developmentではhttp-graceful-shutdownが即時終了モードで動作し、graceful経路をそもそも通らない。そのためこの検証は開発モードでは再現できない。NODE_ENV=stagingにダミーのシークレットを入れて本番と同じ経路を通るようにして、ようやく実測できた。終了経路を検証するときは、検証環境がその経路を実際に通っているかどうかからまず確認すべきだ。

終了コードから学んだこと

この話の教訓は終了シーケンスという狭い舞台を超える。

1つのシグナルには持ち主が1人であるべきだ。 graceful shutdownライブラリを組み込んだなら、フレームワークが提供する終了フックの自動登録を同時に有効にしてはいけない。両方が同じSIGTERMを掴んだ瞬間、終了シーケンスは静かに二重実行される。新しいツールを導入するときは、そのツールがどのシグナル・イベントの持ち主になるのか、そして既存に同じものを掴んでいるコードがないかをまず見るべきだ。

終了にも順序がある。 何かをクリーンアップするコードは、それに依存する作業がすべて終わった後に動くべきだ。DBはそのDBを使うジョブが終わった後に閉じるべきで、そのためにはジョブをより早いフェーズで空にする必要がある。フレームワークが終了フックにフェーズを分けているのは飾りではなく、こうした順序を表現するためにある。

防御的に書かれたコードが時間を稼いでくれる。 終了フックが二度呼ばれても安全なように組まれていなかったら、このバグはログの違和感ではなくデータ事故として先に姿を現していただろう。idempotentに組まれたフックが二重実行に耐えてくれたおかげで、私たちは事故ではなくログの中でそれを発見できた。必ず一度しか実行されないと信じて書かれたフックだったら、話はずっと悪かったはずだ。