Der Shutdown-Hook lief zweimal - als SIGTERM zwei Herren hatte

Bei jedem Deploy landete derselbe Fehler in Sentry. Transaction already closed. Prisma versuchte eine Query auszuführen, nachdem die Transaktion bereits geschlossen war, und starb mit P2028. Für die Nutzer entstand kein Schaden - der BullMQ-Retry ließ die Aufgabe sofort in einem anderen Task erneut erfolgreich durchlaufen, und die Completion-Logs blieben lückenlos. Trotzdem tauchte der Fehler still und leise immer wieder auf, sobald sich Deploy und Traffic überschnitten. Bei der Jagd nach diesem Fehler stellte sich heraus, dass unsere Shutdown-Hooks in Wirklichkeit bei jedem Beenden zweimal liefen.

Akt 1: Die DB stirbt vor dem Job

Als ich den Fehlerzeitpunkt mit den CloudWatch-Logs abglich, passte die Zeitlinie exakt zusammen. Das Rolling Deployment schickt dem alten Task ein SIGTERM. Sechs Sekunden später beginnt app.close() mit dem Aufräumen, und die Prisma-Engine schließt die Transaktion. Unmittelbar danach läuft updateMany eines noch aktiven asset-processing-Jobs auf einer bereits geschlossenen Transaktion und scheitert mit P2028. Ein Nutzer lud gerade fortlaufend Audiodateien hoch, sodass genau im Moment des Deploys ein aktiver Job existierte, dessen Query ins Leere lief.

Ursache war die Shutdown-Reihenfolge. Beim Beenden ruft NestJS die Lifecycle-Hooks in einer festgelegten Reihenfolge auf. Das Problem: Das Schließen der BullMQ-Worker und das Trennen der Prisma-Verbindung lagen in derselben Shutdown-Phase (onApplicationShutdown). Innerhalb einer Phase bestimmt die Reihenfolge der Modulregistrierung die Ausführungsreihenfolge - und ausgerechnet Prisma trennte zuerst, sodass die Query eines Workers, der noch einen Job verarbeitete, ins Leere lief.

Die Richtung der Korrektur war klar. Die Worker mussten in einer früheren Phase geschlossen werden. Die Shutdown-Hooks von NestJS haben eine Reihenfolge, und beforeApplicationShutdown ist immer abgeschlossen, bevor irgendein onApplicationShutdown eines Moduls startet. Ich schrieb einen Service, der alle Worker findet und sie in dieser früheren Phase drained - also wartet, bis aktive Jobs fertig sind.

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

  async beforeApplicationShutdown() {
    // Findet alle registrierten WorkerHost-Instanzen und wartet, bis aktive Jobs fertig sind.
    // Diese Phase endet, bevor Prisma in onApplicationShutdown getrennt wird.
    const workers = this.discovery
      .getProviders()
      .filter((p) => p.instance instanceof WorkerHost);
    await Promise.all(workers.map((w) => w.instance.worker.close()));
  }
}

Worker.close() gibt bei erneutem Aufruf dasselbe Promise zurück, kollidiert also nicht mit bestehendem Code, der Worker bereits schließt, und tut in Umgebungen ohne Redis still gar nichts. Überschneiden sich Deploy und Job jetzt zeitlich, ist der Job zuerst fertig, bevor die DB schließt. Ich ergänzte Unit-Tests und öffnete den PR. Bis hierhin war es ein gewöhnlicher Fix für einen Reihenfolge-Bug.

Akt 2: SIGTERM hatte zwei Herren

Die Wendung kam im Review. Ein Reviewer, der diese Änderung prüfte, ging den gesamten Shutdown-Pfad durch und stellte eine Frage: Wer verarbeitet SIGTERM eigentlich genau?

Bei der Prüfung stellte sich heraus: Es gab zwei Herren. In main.ts standen diese beiden Zeilen unabhängig voneinander.

// ① Überlässt Nest selbst das Shutdown-Signal (ohne Argument aufgerufen, registriert es SIGTERM und SIGINT gleichermaßen)
app.enableShutdownHooks();

// ② Überlässt auch der http-graceful-shutdown-Bibliothek das Beenden
setupGracefulShutdown(server, {
  onShutdown: async () => {
    await app.close(); // Hier laufen alle Lifecycle-Hooks
  },
});

Beide lauschen auf SIGTERM. Node ruft bei einem eintreffenden Signal alle registrierten Listener der Reihe nach auf, ohne aufeinander zu warten. Trifft also ein echtes SIGTERM ein, passiert Folgendes: Der von Nest registrierte Listener führt dieselbe Shutdown-Sequenz wie app.close() einmal aus - sofort, ohne auf den HTTP-Drain zu warten. Unabhängig davon leert http-graceful-shutdown auf seine eigene Art die HTTP-Verbindungen und ruft anschließend in onShutdown noch einmal app.close() auf. Die Shutdown-Hooks laufen also zweimal.

Da reine Kopfarbeit keine Gewissheit brachte, las ich die Produktions-Shutdown-Logs noch einmal durch. Der Beweis stand da schwarz auf weiß. 20 Millisekunden nach dem protokollierten SIGTERM begann onModuleDestroy, noch bevor der HTTP-Drain abgeschlossen war, und die Shutdown-Hook-Logs von SpeechService und QueueMonitorService waren jeweils doppelt vorhanden. Dass daraus kein Vorfall wurde, lag einzig daran, dass die Hooks jedes Services so geschrieben waren, dass ein zweifacher Aufruf sicher (idempotent) verlief. Dieser defensiven Schreibweise war es zu verdanken, dass die "doppelte Ausführung" als Geruch in den Logs blieb, statt als Störung aufzufallen - und genau dieser Geruch führte am Ende zum Fund des Bugs.

Eine Zeile löschen

Die Korrektur bestand darin, eine einzige Zeile zu löschen.

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

Ohne enableShutdownHooks() bleibt http-graceful-shutdown der alleinige Besitzer von SIGTERM. Verloren geht dabei nichts, denn das dort in onShutdown aufgerufene app.close() führt ohnehin alle Lifecycle-Hooks aus. Der einzige Unterschied: Die Hooks laufen nicht mehr zweimal, sondern einmal - und zwar erst, nachdem der HTTP-Drain abgeschlossen ist.

Gerade bei einer Ein-Zeilen-Korrektur braucht es eine reale Messung. Also schickte ich dem gebauten Server ein echtes SIGTERM und beobachtete die Sequenz mit eigenen Augen.

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

Liefen die Hooks in Produktion vorher zweimal vor dem HTTP-Drain, laufen sie jetzt nur noch einmal danach. Verifiziert wurde das im Zusammenspiel mit dem Worker-Drain-Fix aus Akt 1 - damit war auch das Zusammenspiel beider Korrekturen im Gesamtsystem geprüft.

Eine Falle habe ich mir zusätzlich notiert. Unter NODE_ENV=development schaltet http-graceful-shutdown sofort in den Immediate-Shutdown-Modus und durchläuft den graceful Pfad gar nicht erst. Diese Verifikation lässt sich im Development-Modus also nicht reproduzieren. Erst mit NODE_ENV=staging und Dummy-Secrets, die denselben Pfad wie in Produktion durchlaufen, war die reale Messung möglich. Wer den Shutdown-Pfad verifizieren will, muss zuerst sicherstellen, dass die Testumgebung diesen Pfad überhaupt tatsächlich durchläuft.

Was der Shutdown-Code gelehrt hat

Die Lehre aus dieser Geschichte reicht über die enge Bühne der Shutdown-Sequenz hinaus.

Ein Signal darf nur einen Besitzer haben. Wer eine graceful-shutdown-Bibliothek einbindet, darf nicht gleichzeitig die automatische Registrierung der Shutdown-Hooks des Frameworks aktiviert lassen. Sobald beide dasselbe SIGTERM abfangen, läuft die Shutdown-Sequenz still und leise zweimal. Wird ein neues Tool eingeführt, muss zuerst geklärt werden, welches Signal oder Event es sich zum Besitzer macht - und ob nicht bereits bestehender Code dasselbe abfängt.

Auch beim Beenden gibt es eine Reihenfolge. Code, der etwas aufräumt, darf erst laufen, nachdem alles beendet ist, was davon abhängt. Die DB darf erst schließen, nachdem die Jobs fertig sind, die sie nutzen - und dafür müssen die Jobs in einer früheren Phase geleert werden. Dass ein Framework seine Shutdown-Hooks in Phasen unterteilt, ist kein Zierrat, sondern genau dazu da, diese Reihenfolge auszudrücken.

Defensiv geschriebener Code verschafft Zeit. Wären die Shutdown-Hooks nicht so geschrieben gewesen, dass ein zweifacher Aufruf sicher verläuft, hätte sich dieser Bug nicht als Geruch in den Logs, sondern zuerst als Datenvorfall gezeigt. Nur weil die Hooks idempotent geschrieben waren, hielten sie die doppelte Ausführung aus, und wir konnten sie in den Logs entdecken statt bei einem Vorfall. Wäre der Hook in dem Glauben geschrieben worden, er laufe garantiert nur einmal, wäre die Geschichte deutlich schlechter ausgegangen.