Morphium 6.2.4 — Wenn Messaging stillschweigend stirbt

Manchmal ist die spannendste Geschichte hinter einem Release nicht das, was im CHANGELOG steht, sondern warum es da steht. Bei 6.2.4 war es ein Bug, den ich gerne nicht erlebt hätte. Er hat mich zu einer Hardening-Runde gezwungen, die das Messaging-System in Morphium an mehreren Stellen widerstandsfähiger macht. Hier die Geschichte und was am Ende dabei rausgekommen ist.

Das Symptom

Eine Anwendung in Produktion. Zwei Dienste tauschen über Morphium-Messaging Anfragen und Antworten aus. Läuft seit Stunden. Plötzlich: nichts mehr. Anfragen landen sauber in der Messaging-Collection, aber die Antworten kommen nicht. Oder erst nach gefühlten Ewigkeiten.

Im Log: Stille. Kein Stacktrace, keine Warnung, kein "messaging stopped". MongoDB ist erreichbar, der Change-Stream-Endpoint antwortet, die Anwendung crasht nicht. Sie ist nur halblebendig.

Beim genaueren Hinschauen: alle ~10 Sekunden wird eine Welle an Backlog abgearbeitet. Das war der entscheidende Hinweis. Es gibt im SingleCollectionMessaging einen Fallback-Poll, der genau alle 10 Sekunden prüft, ob Messages liegen geblieben sind, die der Change-Stream nicht ausgeliefert hat. Der griff noch. Alles andere lief nicht mehr.

Ein Restart der Anwendung hat das Problem behoben. Bis zum nächsten Mal.

Die falsche Fährte: hängender Cursor

Erste Hypothese, und die plausibelste, wenn man "Change-Stream geht nicht, Polling schon" hört: der CS-Cursor steckt fest. MongoDB-Change-Streams sind getunnelte Tailable Cursors. Unter Last kann es passieren, dass der Cursor zwar formal noch verbunden ist, aber keine Events mehr ausliefert. Die Gründe sind oft zu viel Traffic, der den Client gar nichts angeht, oder eine "Resume needed"-Zone ohne invalidate.

Daraus entstanden zwei der sechs Commits in 6.2.4. Beide sind unabhängig vom eigentlichen Bug nützlich.

Pipeline-Filter (Server-seitiges $match)

Der Change-Stream beobachtet eine ganze Messaging-Collection und liefert jeden Insert/Update an jeden lauschenden Client. Bei vielen Empfängern und vielen Topics wird das schnell zu einer ungesunden Menge an Wire-Traffic. Bisher filterte der Client lokal. Er decodete also Messages, nur um sie wegzuwerfen.

Mit dem neuen Pipeline-Filter wird ein $match-Stage als zweiter Pipeline-Schritt direkt im Aggregation-Pipeline des watch() mitgeschickt: nur Events, deren recipient der eigene Sender-Identifier oder null (Broadcast) ist und deren sender nicht der eigene ist, kommen überhaupt am Client an. Der Server filtert. Der Wire-Traffic schmilzt.

Wichtig dabei: $match läuft auf den realen MongoDB-Feldnamen (snake_case bei Camelcase-Java-Properties). Deshalb ging es Hand in Hand mit dem Field-Name-Translation-Fix in den Aggregator-Stages, der ebenfalls in 6.2.4 enthalten ist.

CS-Stall-Watchdog

Der zweite Commit nimmt die ursprüngliche Hypothese ernst: was, wenn der Change-Stream wirklich still steht, obwohl Backlog da ist? Es gibt jetzt einen passiven Watchdog mit zwei Signalen. Erstens ein Liveness-Marker, den der Change-Stream-Listener bei jedem Event aktualisiert. Zweitens das Wissen aus dem Fallback-Poll: liegt Backlog in der Collection, der der CS hätte sehen müssen?

Wenn beide Bedingungen zutreffen, also Liveness-Marker älter als 2 × FALLBACK_POLL_INTERVAL × pause und der Poll findet unverarbeitete Messages, dann startet der Watchdog den Cursor neu. Mit Log-Eintrag, mit Zähler:

Der Counter ist als messaging.getCsStallRestarts() öffentlich exponiert, als Health-Metrik. Idealwert: 0. Falls dauerhaft > 0, ist die Last auch nach Filterung zu hoch und man sollte sich setBatchSize(1) und Pause-Tuning ansehen.

Beide Commits sind gut und richtig. Aber sie waren nicht der eigentliche Bug.

Der Threaddump

Während die ersten Commits schon im Branch lagen, kam ein neuer Vorfall, und mit ihm ein Threaddump. 4 Stunden 22 Minuten Uptime, 279 Threads. Ich habe nach Msg gesucht (so heißt der SingleCollectionMessaging-Hauptthread, der sich in seinem run() selbst über setName(...) umtauft).

Nichts.

Aber: zwei Threads namens changeStream-... waren springlebendig. 49 Worker-Threads (msg-thr-N) idle, warten auf Arbeit. 100 decouple_thr-N Threads, die Decouplung-Pool-Worker, ebenfalls idle.

Das war der Moment, in dem mir klar wurde, was wir hier sehen: das Messaging-System hatte einen halben Schlaganfall. Der Change-Stream lebt, die Worker leben, nur der Hauptthread, der zwischen beidem vermittelt, ist weg. Und niemand hat es gemerkt.

Producer und Consumer: warum ein toter Hauptthread so unsichtbar ist

Wer SingleCollectionMessaging zum ersten Mal liest, denkt vielleicht: "Der Change-Stream-Callback verarbeitet die Messages, fertig." Tut er aber nicht.

handleChangeStreamEvent() (Z. 441–568) ist reiner Producer. Es macht nur zwei Dinge:

1. Schreibt das frisch eingetroffene Event in die processing-Queue (BlockingQueue<ProcessingElement>).
2. Markiert die Message-ID im idsInProgress-Set.

Das war's. Kein Listener-Aufruf, kein processMessage, kein lockAndProcess. Diese Architektur ist mit Absicht so: der Change-Stream ist eine Push-Quelle, sie sollte niemals durch lange Listener blockiert werden, sonst rennt der Cursor zurück, MongoDB hängt sich auf den Resume-Token, und im schlimmsten Fall gibt's ChangeStreamHistoryLost.

Der Consumer der Queue ist ausschließlich der Hauptthread in seinem run()-Loop:

Dort und nur dort: Re-Fetch der aktuellen Message-Version, Idempotenz-Checks, das Lock-Handling für exclusive Messages, und das queueOrRun, das die Listener-Lambdas in den msg-thr-N-Pool kippt.

Wenn dieser Thread tot ist:

• Der Change-Stream lebt brav weiter, schreibt Events in die processing-Queue.
• Niemand holt sie raus. Die Queue wächst, das idsInProgress-Set wird zur Halde.
• Listener werden nie aufgerufen.
• Die msg-thr-N-Worker bleiben idle, weil queueOrRun aus dem Hauptthread kommt. Und der ist tot.

Von außen sieht das wie eine Anwendung aus, die "noch was tut". Der Fallback-Poll zappelt alle 10 Sekunden, frisst aber an seinem Cursor und nicht an der toten Queue. Daher die scheinbar zufälligen Wellen an Aktivität.

Die zweite Verteidigungslinie: laut sterben statt leise

Wenn ein Bug schon so unsichtbar ist, will man ihn beim nächsten Mal hören. Daraus zwei weitere Commits:

catch (Throwable) im run()-Loop

Der originale Code hatte ein catch (Exception e) um den Hauptloop. Klingt vorsichtig, ist aber nicht genug. Errors, also OutOfMemoryError, StackOverflowError, LinkageError und Konsorten, sind keine Exceptions und wurden lautlos durchgelassen. Damit war der Thread auch lautlos tot.

Der Fix:

Throwable fängt alles, was vom Stack hochkommt, loggt mit Stack-Trace, und der Loop läuft weiter. Wenn beim nächsten Mal ein OutOfMemoryError durchkommt, sehen wir's wenigstens. Und können entscheiden, was zu tun ist.

Liveness-Check des Hauptthreads

Doppelt vernäht hält besser. Falls trotz catch (Throwable) der Hauptthread doch stirbt (nicht behandeltes terminate-Race, JVM-Bug, was auch immer), läuft jetzt alle 30 Sekunden ein Liveness-Check, der auf running == true und mainThread.isAlive() == false reagiert:

Das ist kein Reanimationsversuch. Der einmal gestorbene Thread ist tot, und ein Restart der Application ist die saubere Lösung. Aber jetzt steht es im Log. Klar, sichtbar, monitorbar.

Smoking Gun: 20 MB BSON

Vier Commits drauf, Branch grün, Diagnostik scharfgestellt. Beim nächsten Vorfall, der diesmal mit aktivierten Logs lief, kam dann das hier hochgeschwommen:

Zwanzig Megabyte. Das ist mehr als das harte 16-MB-Limit von BSON, ein zugegeben erstaunliches Server-Constraint. MongoDB lehnt das Dokument ab, der Driver wirft.

Der Stack erzählt die Geschichte: ein Listener verarbeitet eine eingehende Anfrage und ruft am Ende Msg.sendAnswer(...) auf. Die Antwort enthält offenbar ein deutlich größeres Resultat-Set, als wir je vermutet hatten. Der Insert in die Messaging-Collection schlägt fehl.

Und jetzt kommt der subtile Teil. Nämlich die Antwort auf die Frage: warum stirbt dabei der Empfänger-Thread?

sendAnswer() ist nicht der Sender im klassischen Sinn. Es wird aus einem Listener heraus aufgerufen, der gerade eine Anfrage beantwortet. Der Listener läuft nicht im Hauptthread, sondern in einem msg-thr-N-Worker. Eine geworfene MorphiumDriverException (jetzt MorphiumDocumentTooLargeException) wäre dort gefangen worden. Der Worker würde sie loggen und weiterarbeiten.

Aber das 20-MB-Dokument muss zuerst aufgebaut werden. Der BSON-Encoder allokiert das Dokument vollständig im Memory, bevor er das insert-Kommando verschickt. Bei Heap-Druck, mit 20 MB plus Java-Object-Overhead und mehreren parallelen Antworten, kann genau dieser Schritt einen OutOfMemoryError werfen. Und ein OutOfMemoryError ist im JVM-Stack ein ziemlich böser Mitbringsel: er kann an einer ganz anderen Stelle zuschlagen, als an der die Allokation stattfindet. Etwa: im Hauptthread, der gerade nebenbei seinen eigenen processing.poll(...) macht.

Genau das deckt sich mit dem Threaddump: kein Hauptthread mehr, aber CS und Worker leben. Der msg-thr-N-Worker hat überlebt. Den OutOfMemoryError hat die JVM einem anderen Thread zugewiesen. Der Hauptthread wurde Opfer der Heap-Crisis.

Der Driver-Level-Fix: MorphiumDocumentTooLargeException

Die App-seitige Härtung (catch (Throwable), Liveness-Check) sorgt dafür, dass solche Fälle nicht mehr stillschweigend passieren. Aber für die Diagnose selbst hilft eine zweite, viel allgemeinere Verbesserung:

Bisher kam jeder serverseitige BSON-Größenfehler als generische MorphiumDriverException mit der Message "Error: 10334 — BSONObj size: ... is invalid". Wer das programmatisch fangen wollte, musste den Errmsg parsen. Hässlich.

In 6.2.4 gibt es jetzt eine eigene Subklasse:

Sie wird zentral in SingleMongoConnection.readSingleAnswer() gemappt. Das ist der eine Choke-Point, durch den jede Server-Antwort durchgeht. Die neue Exception greift damit automatisch für insert, update, replace, save, findAndModify und jeden zukünftigen Write-Pfad. Keine Per-Call-Instrumentierung nötig. Erkennt sowohl Error 10334 (legacy) als auch Error 17280 (neuere Storage-Pfade) und fällt notfalls auf die errmsg-Substring-Erkennung zurück.

Code, der bisher generisches Exception-Handling hatte, kann jetzt gezielt fangen:

Was du nach dem Update im Log unterscheiden kannst

Nach dem Deploy sind das die vier Log-Zeilen, die du jetzt sehen kannst, jede mit ihrer eigenen Bedeutung:

Was bei MultiCollectionMessaging noch offen ist

Hier muss ich ehrlich sein: das oben beschriebene Hardening sitzt komplett in SingleCollectionMessaging. Der Grund ist architektonisch. SingleCollectionMessaging extends Thread und hat genau diesen einen run()-Loop, der sterben kann. Den haben wir gefixt.

MultiCollectionMessaging ist anders gebaut. Es ist kein Thread, sondern nutzt einen ScheduledExecutor mit scheduleWithFixedDelay(...) für das Polling und führt Listener direkt aus den ChangeStream-Callbacks aus. Der spezifische Bug "stiller Hauptthread-Tod" existiert dort so nicht.

Aber: es gibt analoge Risiken, die wir in 6.2.4 nicht angefasst haben.

• Der Polling-Pfad in MultiCollectionMessaging hat schon ein catch (Throwable) um den Scheduled-Body. Gut.
• Listener-Aufrufe direkt aus dem CS-Callback heraus: wenn dort ein Listener einen Error wirft, kann das den ChangeStream-Monitor mitreißen. Wir haben hier keinen Watchdog gebaut.
• Den Pipeline-Filter für CS-Volumen gibt es in Multi nicht.

Was beide Implementierungen gleichermaßen profitieren lässt: der Driver-Level-Fix mit der MorphiumDocumentTooLargeException. Der greift überall. SingleCollectionMessaging, MultiCollectionMessaging, normale morphium.store(...)-Aufrufe, Aggregations-Output. Wer auch immer ein 16-MB-Dokument an Mongo schickt, bekommt jetzt eine spezifische, fangbare Exception.

Dass MultiCollectionMessaging analoges Hardening braucht, steht damit auf der TODO-Liste. Vermutlich landet es in 6.2.5 oder 6.3.

Was sonst noch in 6.2.4 ist

Damit der CHANGELOG nicht ungenannt bleibt, in Stichpunkten:

• Aggregator: Field-Name-Translation in Pipeline-Stages. Java-camelCase-Felder werden auch innerhalb von Aggregations-Stages korrekt auf MongoDB-snake_case übersetzt. Praktischer Nebeneffekt: war Voraussetzung für den Pipeline-Filter im Messaging.
• Query.distinct() und explainDistinct(): gleiche Field-Name-Translation, gleicher Effekt. Distinct-Queries auf camelCase-Properties funktionieren jetzt korrekt.

Was zwischen 6.2.2 und 6.2.4 noch landete (6.2.3)

Falls du 6.2.3 verpasst hast, hier nochmal kompakt die Highlights:

• defaultQueryTimeoutMS: getrennt vom Connection-Pool-maxWaitTime. Endlich kann man "lange auf Connection warten, aber Query kurz timeout" konfigurieren.
• storeList(..., continueOnError): Batch-Stores, die bei Einzelfehlern weiterlaufen. ordered: false für Morphium.
• Batched versioned-entity updates: weniger Round-Trips bei Listen mit @Version-Feld.
• Auto-Retry bei transientem WriteConflict (Error 112): außerhalb von Transaktionen.
• CosmosDB-Kompatibilität: kein collation: null mehr in Write-Commands.
• Strukturierte writeErrors in Insert/Write-Commands. Endlich passend zu MongoDB's Wire-Format.
• Plus diverse PoppyDB-Fixes.

Bezug

Maven Central wie immer:

Quelle, CHANGELOG, Issues: github.com/sboesebeck/morphium

Lessons learned

Drei Sachen nehme ich für mich aus dieser Session mit:

1. catch (Exception) ist keine Verteidigung gegen Errors. Hauptloops, die einen Thread tragen, gehören mit catch (Throwable) umarmt. Egal wie defensiv der Restcode aussieht.
2. Producer/Consumer-Architektur muss überwacht werden. Wenn Producer und Consumer in unterschiedlichen Threads leben und nur über eine Queue kommunizieren, ist das Tod-Symptom asymmetrisch. Ein Liveness-Check auf den Consumer-Thread kostet wenig und sagt viel.
3. Schreibseitige Limits kommen oft im falschen Thread an. Eine OutOfMemoryError kann genau die Komponente reißen, die mit dem auslösenden Schreibvorgang gar nichts zu tun hat. Nur weil ein Stack auf "den Schreibenden" zeigt, heißt das nicht, dass der Schreibende dabei stirbt.

Bis zum nächsten Release.