Die Tests waren grün, aber es wurde nie eine Benachrichtigung verschickt

In Slack tauchte ein 500-Alert auf. Die Fehlermeldung kam mir fremd vor: Error: Custom Id cannot contain :. Die API, mit der Admins Antworten auf Nutzerfragen eintragen, starb gerade, und der Stacktrace zeigte auf Job.validateOptions von BullMQ.

Bis hierhin ein gewöhnlicher Bugreport. Ungewöhnlich wird die Geschichte erst nach dem Fund der Ursache. Der Code, der diesen Fehler warf, war im Deploy des Tages gar nicht angefasst worden. Er schlug seit dem Tag, an dem das Feature eingeführt wurde, jedes Mal fehl - zu 100%. Das heißt: Die Push-Benachrichtigungen, die diese Queue hätte verschicken sollen, wurden nie verschickt. Kein einziges Mal. Und die ganze Zeit über waren sämtliche Tests grün.

Die Ursache: ein einziges Zeichen

Der problematische Code sah so aus. Hier wird der Job in die Queue gelegt, der dem Nutzer eine Push-Nachricht schickt, sobald seine Frage beantwortet wurde.

await this.queue.add(ANSWER_NOTIFY_JOB_NAME, data, {
  jobId: `answer-notify:${data.questionId}`, // ← dieser Doppelpunkt
});

Die benutzerdefinierte jobId sollte verhindern, dass derselbe Job für dieselbe Frage zweimal eingereiht wird - nur wurde als Trennzeichen ein Doppelpunkt gewählt. BullMQ baut seine Redis-Keys mit Doppelpunkten zusammen und verbietet sie deshalb in benutzerdefinierten jobIds. Die genaue Bedingung in v5: Enthält die jobId einen Doppelpunkt und ergibt die Aufteilung am Doppelpunkt nicht genau 3 Teile, fliegt der Fehler. Die 3-Teile-Ausnahme ist ein Carve-out für das Legacy-Format von Repeatable Jobs, also ist ein 2-Teile-Wert wie answer-notify:123 immer Custom Id cannot contain :. Übrigens werden rein numerische jobIds ebenfalls abgelehnt, mit Custom Id cannot be integers - das Präfix einfach zu streichen ist also auch keine Lösung.

Dutzende andere Queues in der Codebasis benutzten alle Bindestriche. Nur diese eine Datei hatte einen Doppelpunkt.

Der Bug war vom ersten Tag an da - warum knallte es erst heute?

Der Fix ist eine Zeile: Doppelpunkt durch Bindestrich ersetzen. Die interessante Frage ist eine andere. Warum blieb Code, der immer fehlschlug, so lange still - und wurde ausgerechnet heute zum 500er?

Als das Feature zum ersten Mal deployt wurde, war das Enqueue so verpackt:

try {
  await this.queue.add(/* ... */);
  return true;
} catch (err) {
  this.logger.error("enqueue failed", err);
  return false; // ← hier verschwindet der Fehlschlag
}

Der Fehlschlag wird geloggt, und es wird false zurückgegeben. Der Aufrufer prüft den Rückgabewert nicht. Also wurde die Exception, die jedes Mal geworfen wurde, jedes Mal verschluckt, die API gab 200 zurück, und nur die Benachrichtigung löste sich lautlos in Luft auf.

Dann änderte ein am selben Tag gemergter Commit diesen Vertrag. Die Absicht: Wenn das Enqueue fehlschlägt, nicht mehr schlucken, sondern werfen - damit die in der Transaktion gesetzte Markierung "beantwortet" zurückgerollt und der Vorgang wiederholt werden kann. Eine Änderung in die richtige Richtung. In diesem Moment gab das seit jeher fehlschlagende Enqueue zum ersten Mal einen Laut von sich. Der 500er war kein Bug, den dieser Commit erzeugt hat, sondern der erste Schrei eines Bugs, der schon immer da war.

Das ist der Preis von Code, der Fehler verschluckt. Das Signal verschwindet, der Bug bleibt - und nimmt ein ganzes Feature mit.

Warum waren die Tests grün?

Für diese Queue gab es Tests. Eine Spec der üblichen Sorte: Wenn man das Enqueue aufruft, wird geprüft, ob queue.add mit den richtigen Argumenten aufgerufen wurde. Und das queue.add in diesem Test war ein Mock, der bedingungslos Erfolg meldete.

Das echte add von BullMQ validiert die jobId und lehnt Doppelpunkte ab. Das add des Mocks nimmt alles. Genau in dem Maß, in dem der Mock nachsichtiger ist als der echte Vertrag, ließ der Test eine Eingabe grün passieren, die in der Realität niemals durchkommen konnte. Wenn ein Mock vom echten Vertrag abweicht, bescheinigt ein grüner Test nicht lebendigem, sondern totem Code seine Funktion.

Beim Fixen habe ich zuerst dieses Loch gestopft. Das add des Queue-Mocks führt jetzt das echte Job.validateOptions von BullMQ aus. Diese Funktion ist reine Validierung ohne Redis und lässt sich direkt in Tests einhängen. Und ob die Absicherung wirklich eine ist, habe ich per Mutationstest geprüft: Doppelpunkt zurückgedreht, zugesehen, wie der Test genau an dieser Stelle rot wird - und erst dann committet. Wenn man den Bug zurückdreht und der Test trotzdem grün bleibt, existiert dieser Test praktisch nicht.

Es war kein Einzelfall

Hier aufzuhören hätte bedeutet, nur die Hälfte zu fixen. Wenn derselbe Fehler an einer Stelle steckt, steckt er mit hoher Wahrscheinlichkeit auch woanders. Also habe ich die "Klasse" des Defekts definiert - benutzerdefinierte jobIds mit Doppelpunkt - die gesamte Codebasis durchkämmt und mehrere Review-Agenten zur Gegenprüfung angesetzt. Zwei weitere Treffer.

Der eine war die Queue, die von Nutzern hochgeladene Audioaufnahmen transkribiert. jobId: "stt:${id}". Dort wurde der Fehler nach wie vor verschluckt, es gab also nicht einmal einen 500er. Die Prüfung ergab: Seit 12 Tagen war kein einziger Transkriptionsjob mehr in die Queue gelangt. Die Audiodateien wurden ordnungsgemäß gespeichert, der Fehlschlag landete nur im Log, und auf dem Bildschirm des Nutzers blieb das Textfeld für immer leer. Vollkommen symptomfrei.

Der andere war die Queue für Hinweis-E-Mails zu gebuchten Terminen. Die jobId bestand aus 4 durch Doppelpunkte getrennten Teilen, also kamen weder Reminder noch Stornierungshinweise jemals in der Queue an.

Die Producer aller drei Queues habe ich auf einen gemeinsamen jobId-Builder vereinheitlicht: eine Funktion, die mit Bindestrichen joint, eingeschleuste Doppelpunkte ersetzt und rein numerische Werte ablehnt. Zur Rückfallsicherung kam eine Lint-Regel dazu, die exakt das Muster "Doppelpunkt-Literal in einer jobId" fängt. Die rund 50 bestehenden Bindestrich-jobIds habe ich nicht zwangsweise auf den neuen Builder migriert. Ändert sich die jobId eines Repeatable Jobs, riskiert man doppelt registrierte Crons - also lieber gezielt nur die Defektklasse treffen.

Die zweite Falle: Feste jobIds töten den Retry lautlos

Schön wäre es, wenn die Geschichte hier endete, aber während der Review-Verifikation kam ein grundsätzlicheres Problem ans Licht. Sobald der Doppelpunkt gefixt ist, wird eine feste jobId wie answer-notify-123 lebendig - und genau diese feste jobId stand im Widerspruch zu dem Retry-Vertrag, der am selben Tag aufgesetzt worden war.

Wenn der Job-Hash zu einer jobId noch in Redis liegt, ignoriert BullMQ ein neues add ohne Fehler und gibt einfach die bestehende jobId zurück. Ein Verhalten, das der Prüfer bis hinunter in die Lua-Skripte von BullMQ nachvollzogen hat. Diese Queue lief aber mit removeOnComplete: { count: 100 }, der Hash eines gerade abgeschlossenen Jobs bleibt also liegen. Zusammengesetzt ergibt das folgendes Szenario: Der Benachrichtigungsjob schlägt einmal fehl. Vertragsgemäß wird die Markierung "beantwortet" zurückgerollt, der Admin versucht es erneut. Das neue Enqueue läuft gegen den noch vorhandenen Job-Hash, tut nichts und kehrt zurück, als wäre alles gut. Die Benachrichtigung geht nie raus - und diesmal gibt es weder einen Fehler noch eine DLQ.

Kaum ist das fehlerverschluckende catch weg, übernimmt die Dedupe-Logik der Library denselben Posten. Am Ende habe ich die benutzerdefinierte jobId aus dieser Queue komplett entfernt. Der Schutz vor Doppelversand wanderte auf die Consumer-Seite: Der Prozessor reserviert sich die Markierung "Benachrichtigung verschickt" atomar per bedingtem Update. Kommt der Job zweimal an, schickt nur die Seite den Push, die die Markierung zuerst ergattert hat.

Wer Duplikate über eine benutzerdefinierte jobId verhindert und gleichzeitig ein Design hat, das bei Fehlschlag erneut enqueued, sollte prüfen, ob sich die beiden Mechanismen nicht gegenseitig umbringen. Es könnte dieselbe Kombination sein wie bei uns: ein Retry, der lautlos zum No-op wird.

Wie groß war der Schaden?

Ein Feature, das 12 Tage tot war - das klingt nach großem Schaden, aber die Messung ergab etwas anderes. Bei den Antwort-Benachrichtigungen war das Feature in Produktion noch gar nicht in echter Nutzung, Verlust: null. Die E-Mail-Queue betraf nur bereits vergangene Termine, es gab nichts nachzusenden. Real zurückzuholen waren zwei nicht transkribierte Audioaufnahmen. Die gespeicherten Audiodateien wurden erneut transkribiert, damit war das erledigt.

Wir hatten Glück. Und dieses Glück wiederholt sich nicht. Wäre das Feature in echter Nutzung gewesen, wären 12 Tage an Benachrichtigungen und Transkriptionen unwiederbringlich weg gewesen - und weil die Jobs nie in der Queue existiert haben, hätte auch kein Deploy irgendetwas zurückgeholt. Ein Backfill-Skript zu schreiben war zweitrangig. Der Kern des Problems war, dass ein totes Feature 12 Tage lang unbemerkt tot sein konnte - das galt es zu beheben. Also landen Transkriptionsfehler jetzt nicht mehr nur im Log, sondern im Alert-Kanal, und der Pfad der Antwort-Benachrichtigungen wanderte in eine Outbox, die zusammen mit der Transaktion committet wird. Den Zustand "in der DB steht Erfolg, aber es gibt keinen Job" gibt es damit schlicht nicht mehr.

Was bleibt

Drei Dinge aus diesem Vorfall, die länger halten werden als der Code.

Erstens: Ein catch, das nur loggt und normal zurückkehrt, sorgt dafür, dass niemand etwas merkt - selbst wenn der Pfad zu 100% fehlschlägt. Wer schluckt, braucht mindestens eine Metrik oder einen Alert, der die Fehlschläge zählt; wer das nicht hat, sollte lieber werfen. Ein geworfener Fehler ist laut, wird aber gefixt. Ein verschluckter Fehler lebt 12 Tage.

Zweitens: Ein Mock muss so streng sein wie der echte Vertrag. Auf einem Mock, der bedingungslos Erfolg meldet, wird keine einzige Eingabe validiert. Hat die Library eine reine Validierungsfunktion, gehört sie in den Mock - und zur Absicherung wird es erst, wenn man den Bug zurückdreht und der Test rot wird.

Drittens: Defekte fängt man als Klasse. In derselben Codebasis passiert derselbe Fehler nicht nur einmal. Hat man einen gefunden, definiert man die Klasse, durchsucht alles - und geht bis zu dem Punkt, an dem eine Lint-Regel oder ein gemeinsamer Builder die Klasse dauerhaft aussperrt. Erst dann hat sich der eine Fund gelohnt.