Caluga - Java blog

Morphium 6.2.6: Der Timeout, der sich mit 100 multiplizierte

Morphium 6.2.6: Der Timeout, der sich mit 100 multiplizierte

Morphium 6.2.6 ist auf Maven Central. Nach Versionsnummer ein Patch-Release — inhaltlich ist es das wichtigste 6.2.x bisher. Denn die Kernfrage, die dieses Release beantwortet, lautet: Was passiert eigentlich, wenn der Primary eines Replicasets stirbt? Die ehrliche Antwort war bis jetzt: nichts Gutes.

Das Experiment: kill -9 auf den Primary

Der Auslöser war ein Vorfall in einer Produktionsumgebung: Primary weg, und der Service erholte sich nicht. Nicht langsam — gar nicht. Writes hingen, das Messaging blieb tot, erst ein Neustart der Anwendung half.

Dabei ist der Vertrag eines Replicaset-Treibers eigentlich klar: Stirbt der Primary — Crash, eingefrorene VM, Netzwerk-Partition —, wählt das Replicaset in ein paar Sekunden einen neuen, der Treiber merkt das, verbindet sich um, und die Anwendung läuft weiter. Genau das haben wir nachgestellt: lokales 3-Knoten-Replicaset, Dauerlast mit Writes und Messaging, und dann dem Primary nacheinander alles angetan, was das echte Leben so bereithält — SIGTERM, kill -9, SIGSTOP (eine eingefrorene VM ist aus Treibersicht eine Netzwerk-Partition), Neustart während der Primary down ist.

Das Ergebnis vor 6.2.6: nach einem harten Kill ein einziger erfolgreicher Write in 45 Sekunden, Messaging dauerhaft tot. Der Failover, den das Replicaset in ~10 Sekunden erledigt hatte, kam beim Treiber schlicht nie an. Und die Ursache war keine einzelne — es war eine Kette von Bugs, die sich gegenseitig verdeckt haben.

Bug #1: readNextMessage Ă— 100

Der Hauptdarsteller. Beim Lesen einer Antwort vom Server tolerierte readNextMessage bis zu 100 aufeinanderfolgende Socket-Timeouts, bevor es aufgab. Klingt nach Robustheit, ist aber Arithmetik: Der konfigurierte Timeout wird damit effektiv mit 100 multipliziert. Aus maxWaitTime = 60s wird über eine Stunde — pro Operation, pro Connection.

In der Praxis heißt das: Jede Operation, die auf einer Connection zum toten Primary unterwegs war, hing nicht 60 Sekunden, sondern quasi für immer. Kein Fehler, kein Retry, kein Failover — nur Threads, die geduldig auf einen Host warten, den es nicht mehr gibt. Der Timeout ist jetzt eine harte Gesamt-Deadline.

Bug #2: Die Step-down-Erkennung, die nie feuerte

Wenn ein Write auf einem Ex-Primary landet, antwortet MongoDB mit einem "not primary"-Fehler, und der Treiber soll den Write auf dem neuen Primary wiederholen. Diesen Code gab es in Morphium — er verglich die Fehlermeldung mit dem String "not primary". Die tatsächliche Meldung lautet aber "Error: 10107 - not primary". Der Vergleich konnte nie matchen. Klassischer Dead Code, der wie Fehlerbehandlung aussieht.

Step-downs werden jetzt über die Mongo-Fehlercodes erkannt (10107, 189, 91, 11600, 11602, 13435) und der Write auf dem frisch aufgelösten Primary wiederholt. Netzwerkfehler und ausbleibende Antworten werden genauso behandelt — at-least-once, wie retryWrites beim offiziellen Treiber.

Bug #3: Ein "No such host" und das Messaging war fĂĽr immer tot

Morphiums Messaging hängt an einem Change Stream. Der ChangeStreamMonitor behandelte die Exception "No such host" als fatal und beendete sich permanent — und genau diese Exception entsteht ganz regulär in dem kurzen Fenster, in dem ein Host während des Failovers aus der Host-Liste evicted und noch nicht wieder eingetragen ist. Ein einziger unglücklich getimter Fehler, und das Messaging kam bis zum Anwendungsneustart nicht wieder. Jetzt: Retry statt Selbstaufgabe, und die Fehlerbehandlung ist in ein testbares handleWatchError() extrahiert.

Und der Rest der Kette

Es geht noch weiter, in Kurzform:

  • Primary-Discovery ĂĽber Secondaries scheiterte, wenn der im hello angekĂĽndigte Primary sich in GroĂź-/Kleinschreibung oder Port-Schreibweise vom Eintrag in der Host-Map unterschied — der Vergleich lief ohne normalizeHostKey.
  • Tote Hosts wurden zu langsam erkannt: Heartbeat-hellos und der Connect-Handshake liefen mit maxWaitTime statt mit einem eng begrenzten Timeout. Die Eviction schlieĂźt jetzt auch gerade ausgeliehene Connections, damit in-flight-Operationen sofort fehlschlagen und der Retry greift, statt in Bug #1 zu laufen.
  • SingleMongoConnectDriver schlief beim Reconnect nach einem null-hello sleepBetweenErrorRetries * 10000 Millisekunden — ein Tippfehler, der aus Sekunden ~16 Minuten machte.

Jeder dieser Bugs für sich wäre ärgerlich. Zusammen ergaben sie ein System, in dem der Failover-Pfad schlicht nie zu Ende lief: Wer an Bug #2 vorbeikam, hing in Bug #1; wer da rauskam, verlor das Messaging an Bug #3.

Nachher

Dieselbe Testsuite nach den Fixes: nach einem harten Kill des Primary ist die Anwendung ~25 Sekunden später wieder auf vollem Schreibdurchsatz, keine verlorenen Messages — über alle Szenarien, inklusive Freeze und Restart bei totem Primary. Die Recovery-Zeit skaliert dabei im Wesentlichen mit connectionTimeout plus der Election-Dauer des Replicasets selbst.

Die Szenarien sind als manuelle Testsuite im Repo (FailoverReproTest), damit dieser Pfad nie wieder ungetestet verrottet. Und das ist auch die eigentliche Lehre: Failover-Code ist Code, der fast nie läuft — und genau dann funktionieren muss, wenn alles andere gerade brennt. Code, der nur im Katastrophenfall ausgeführt wird, ist so gut wie ungetestet, wenn man die Katastrophe nicht regelmäßig selbst herbeiführt.

Eine Praxis-Warnung am Rande, die beim Testen aufgefallen ist: Entities mit @WriteSafety(level = SafetyLevel.WAIT_FOR_ALL_SLAVES) warten bei einem degradierten Replicaset (ein Knoten fehlt) serverseitig bei jedem Write auf das konfigurierte Timeout. Wer das im Einsatz hat, sollte prĂĽfen, ob MAJORITY nicht das ist, was eigentlich gemeint war.

Außerdem gefixt: findOneAndUpdate löschte Dokumente

Der zweite Fix in diesem Release, der einen eigenen Absatz verdient — weil es um stillen Datenverlust geht: Bei Entities mit @Cache(readCache = true) hat findOneAndUpdate(Map) bei einem Cache-Hit das gefundene Dokument gelöscht statt geupdatet (#214). Der Read-Cache-Zweig war aus findOneAndDelete() kopiert worden — inklusive des Delete.

Der Fix ist konzeptionell: Ein find-and-update hat immer einen Schreib-Seiteneffekt und wird deshalb jetzt grundsätzlich nie mehr aus dem Read-Cache bedient. Das Kommando geht immer zur Datenbank, und eine erfolgreiche Änderung invalidiert den Read-Cache des Typs.

Alles andere in 6.2.6

SingleMongoConnectDriver

  • dropCollection konnte sich selbst deadlocken: Der Writer hielt die einzige Connection und pollte gleichzeitig exists(), das sich ebenfalls eine Connection leihen wollte — Minuten Stillstand, wann immer die Collection tatsächlich existierte. Die Connection wird jetzt vor dem Polling freigegeben; dazu ist das connectionInUse-Flag jetzt ein AtomicBoolean mit compareAndSet statt eines racigen plain boolean (#215).

InMemoryDriver

  • findAndModify unterstĂĽtzt jetzt $setOnInsert sowie die upsert/new-Flags — wie echtes MongoDB, inklusive Regression-Test fĂĽr Upserts mit $and-verschachteltem _id-Filter (#202, #203, #204).
  • Dotted Field-Paths: find schreibt Query-Keys mit Punkten nicht mehr um (Pfade mit GroĂźbuchstaben-Segmenten matchen jetzt korrekt), und distinct löst dotted Paths in das verschachtelte Dokument auf.

Aufgeräumt

  • SequenceGenerator: ~40 duplizierte Zeilen Lock-Lifecycle aus getNextValue()/getNextBatch() in ein gemeinsames withSequenceLock() extrahiert — kein Verhaltensunterschied (#171).
  • Legacy-Vector/Hashtable in Cache, Cache-Synchronizer und JMS-Producer durch ConcurrentHashMap/CopyOnWriteArrayList ersetzt; Listener-Iteration ist damit sicher gegen ConcurrentModificationException. Verbliebene printStackTrace()-Aufrufe laufen jetzt ĂĽber SLF4J (#173, #212).

Test-Infrastruktur

  • Neuer manual-Test-Tag: Die echten Failover-Tests (die lokale mongod-Prozesse killen) sind sauber von den CI-tauglichen external-Tests getrennt und laufen nie mehr versehentlich in der CI mit.

Upgrade

<dependency>
    <groupId>de.caluga</groupId>
    <artifactId>morphium</artifactId>
    <version>6.2.6</version>
</dependency>

6.2.6 ist ein Drop-in-Upgrade von 6.2.x — keine API-Änderungen. Wer ein Replicaset einsetzt oder @Cache(readCache = true) zusammen mit findOneAndUpdate nutzt, sollte nicht lange warten. Die vollständigen Notes liegen im GitHub-Release.

Wie immer: Feedback, Issues und PRs sind auf GitHub willkommen. Happy coding!