Morphium 6.3.7 und 6.3.8: Fehler, die wir alle hatten

Im letzten Post ging es um Fehler, die nie jemand hatte. Gefunden per Code-Review, gefixt bevor sie jemandem auf die Füße fallen konnten. Diesmal ist es genau umgekehrt. Morphium 6.3.7 und 6.3.8 bestehen fast komplett aus Fehlern, die wir alle hatten - seit Monaten, teilweise seit Jahren. Wir haben sie nur nicht gesehen. Und der Grund, warum wir sie jetzt sehen, ist simpel: wir haben endlich mal richtig hingeschaut.

PoppyDB auf einem echten Bus

Die Geschichte fängt Mitte August an. Auf einem Message-Bus in einer Abnahmeumgebung, drei Knoten, gut 30 Clients, haben wir das MongoDB-Replica-Set testweise rausgenommen und PoppyDB an dieselbe Stelle gesetzt. Gleicher Port, gleiche Hosts, Dump per mongorestore rein, Clients davon nichts erzählt. Und dann haben wir zugeschaut. Nicht "läuft, passt", sondern richtig: Heap-Histogramme nach Full GC, Verbindungszähler auf den Knoten, Log-Auswertungen über Tage.

Ich hatte erwartet, dass PoppyDB dabei ein paar Kratzer abbekommt. Das ist ja der Sinn der Übung. Was ich nicht erwartet hatte: dass die Hälfte der Befunde gar nichts mit PoppyDB zu tun hat, sondern mit dem Client. Also mit Morphium selbst. Also mit dem Teil, der seit Jahren gegen MongoDB in Produktion läuft.

Ein Double pro Event, für immer

Fangen wir trotzdem mit PoppyDB an. Nach ein paar Tagen sahen die Secondaries komisch aus: Live-Set nach GC bei 23 Prozent des Heaps, der Primary bei 5. Auf einem Replica-Set, wo alle drei dieselben Daten halten. Das Heap-Histogramm zeigte Millionen von java.lang.Double. Millionen. Wer braucht Millionen Doubles auf einem Datenbankserver?

Die Antwort: niemand. Der InMemoryDriver legt jede Antwort auf ein Kommando in eine Map, und der Eintrag verschwindet erst, wenn der Aufrufer ihn abholt. Auf dem Primary macht das der Netty-Handler brav für jede Anfrage. Der Replikations-Pfad auf den Secondaries hat die Antwort aber einfach weggeworfen - für jedes Update, jedes Delete, jeden Drop. Übrig blieb pro repliziertem Event genau ein "ok": 1.0. Lokal nachgemessen: 20.000 Updates auf dem Primary, plus 20.000 Doubles auf jedem Secondary. Bei zwölf Events pro Sekunde sind das ungefähr 0,8 GB am Tag, bis der Knoten in die Memory-Watermark läuft.

44 Stunden nach dem Fix: exakt null Doubles auf allen drei Knoten. Nicht weniger. Null. Das ist die Art Bestätigung, die ich mag.

Der Client war's aber auch

Und jetzt der Teil, der mir wirklich peinlich ist. Die Knoten haben pro Sekunde zwischen 1,5 und 4,3 neue TCP-Verbindungen gesehen. Dauerhaft. Über 61 Stunden waren das auf einem Secondary 937.000 Verbindungsaufbauten - bei 150 bis 220 Verbindungen, die zu irgendeinem Zeitpunkt überhaupt offen waren.

Die Ursache sitzt im PooledDriver und ist eigentlich logisch, wenn man sie einmal sieht: lastUsed auf einer Verbindung wird nur durch echte Anwendungszugriffe aufgefrischt, nicht durch den Heartbeat, der jede Sekunde drüberläuft. Das ist auch richtig so, sonst könnte der Pool nach einem Burst nie wieder schrumpfen. Aber bei einem Client, der wenig zu tun hat, waren damit nach 30 Sekunden alle Verbindungen "idle". Der Sweep hat sie geschlossen, der Refill hat sie sofort wieder aufgebaut, weil minConnectionsPerHost erfüllt sein muss. Ein TCP-Handshake alle 30 Sekunden pro Verbindung, pro Client, für immer. Und das auf Verbindungen, über die die ganze Zeit gesunder Heartbeat-Traffic lief.

Ich hab das lokal gegen ein Replica-Set nachgestellt, um sicher zu sein: 9 Verbindungen, 10 Sekunden Idle-Zeit, gemessen 0,90 Reconnects pro Sekunde. Poolgröße durch Idle-Zeit, auf die zweite Stelle. Zehnfache Idle-Zeit, ein Zehntel Reconnects. Der Heartbeat fünfmal langsamer: keine Änderung. Das ist der Bug, keine Frage.

Dazu kam gleich noch einer: der Heartbeat auf der SingleMongoConnection hat bei jedem Hello die komplette SCRAM-Authentifizierung mitgeschickt. Auch auf einer Verbindung, die seit einer Stunde authentifiziert war. Auf einem Cluster mit Auth sind das rund 7.200 Logins pro Stunde pro Knoten, die niemand gebraucht hat. Als Verbindungs-Churn unsichtbar, weil der Socket ja nie wechselt.

Beide Bugs treffen MongoDB genauso wie PoppyDB. Beide sind alt. Aufgefallen sind sie erst, weil wir für PoppyDB die Verbindungszähler auf den Knoten angeschaut haben - und die Zahlen auf den MongoDB-Bussen daneben genauso aussahen.

Rolling Restart - der Bug-Verstecker

Das ist die Geschichte, wegen der ich diesen Post eigentlich schreibe.

Irgendwann wollte ich wissen, was passiert, wenn alle drei PoppyDB-Knoten gleichzeitig weg sind. Stromausfall, Rechenzentrums-Wartung, whatever. Ein Rolling Restart hatten wir oft genug gemacht, das ging immer. Also: alle drei runter, alle drei hoch.

Ergebnis: Daten alle da. Indizes alle weg. Jeder einzelne. Die TTL-Indizes auf den Messaging-Collections liefen nicht mehr, eine Collection war unbemerkt auf 9.500 Dokumente gewachsen, und jede Query auf dem heißen Pfad war ein Collection-Scan. Der Dump hatte halt nur Dokumente enthalten, nie die Index-Definitionen. Und warum ist das nie aufgefallen? Weil ein Rolling Restart das strukturell verdeckt. Der neu startende Knoten holt sich seine Indizes per Initial Sync vom laufenden Peer. Solange irgendein Knoten oben bleibt, ist alles gut. Erst wenn alle aus ihrem Dump lesen, gibt es keinen Peer mehr, von dem man abschreiben könnte.

Also Fix: der Dump trägt jetzt die Indizes mit. Klingt trivial, hat aber eine Falle: die Indizes müssen nach den Daten angelegt werden, nicht davor. createIndex befüllt die Expiry-Queue eines TTL-Index aus den Dokumenten, die in dem Moment da sind, und der Sweep bootstrappt eine leer angelegte Queue nie nach. Index vor Daten, und jedes restaurierte Dokument wäre für immer unverfallbar. Derselbe Bug in neuer Verkleidung.

Fix gebaut, acht neue Tests, Vollsuite mit über 2.200 Tests grün, auf die Abnahme, Komplett-Restart. Und: zwei von drei Knoten kamen nie wieder. Der Cluster lief auf einem Bein. Von außen war das einzige Symptom "node is recovering", im Log des hängenden Knotens scrollte pro Versuch ein Stacktrace durch.

Der Fix hatte seinen eigenen Bug mitgebracht. Der JSON-Parser liefert beim Restore jede Zahl als Long. Also war expireAfterSeconds als Long registriert. Der Restore selbst fand das völlig okay. Aber sobald ein Peer per listIndexes nachfragte, ging der Long als Int64 über den Draht, und auf der anderen Seite setzt IndexDescription.fromMap seine Felder reflektiv - auf ein Integer-Feld. IllegalArgumentException, Initial Sync fehlgeschlagen, nächster Versuch, dasselbe. Für immer. 13 TTL-Indizes über alle Datenbanken, jeder einzelne ein Grund, nie wieder hochzukommen.

Und wieder: weder die acht neuen Tests noch die Vollsuite haben das gesehen. Weil "aus dem Dump restauriert" und "danach von einem Peer abgefragt" einzeln getestet waren, nie zusammen. Und weil ein Rolling Restart genau diese Kombination nicht auslösen kann.

Die Lehre ist eigentlich banal und trotzdem hat sie mich kalt erwischt: ein Rolling Restart ist als Test für Restore-Pfade wertlos. Er testet, ob ein Knoten von seinen Peers lernen kann. Er testet nie, ob ein Knoten alleine hochkommt. Jetzt gibt es einen E2E-Test, der ein komplettes Replica-Set gleichzeitig killt, aus den Dumps neu startet und prüft, dass jeder Knoten wieder PRIMARY oder fertig synchronisierter SECONDARY wird - nicht nur, dass die Daten wieder da sind. Und ein Knoten, dessen Initial Sync fünfmal mit identischem Fehler scheitert, schreibt jetzt ein NODE STUCK IN RECOVERY ins Log, das man nicht übersehen kann.

Verifikation mit dem fertigen 6.3.7: alle drei Knoten gleichzeitig runter, alle drei nach zehn Sekunden oben, 15 TTL-Indizes intakt, Task-Zahlen identisch. Vorher: einer von drei.

6.3.8: der Watchdog, der Wolf rief

Fünf Tage später das nächste Release. Diesmal hatte der Change-Stream-Watchdog Aufmerksamkeit verdient: 2.229 Alarme in sieben Tagen, ein Prozess stand bei Restart Nummer 260. Jeder Alarm wirft den Cursor weg und baut ihn ohne Resume-Token neu auf. Das ist also kein "Log ist etwas laut", das ist eine Störung. Und bei tausenden False Positives wäre ein echter Stall sowieso unsichtbar gewesen.

83 Prozent der Alarme lagen in Minute :00 und :01. Stündlicher Cron. Der schickte Requests im Fire-and-Forget-Stil, und die Empfänger haben brav geantwortet - an jemanden, der keine Antwort erwartet. Solche Antworten werden absichtlich nicht als "processed" markiert, damit ein später registrierter Listener sie noch bekommt. Nur hat der Poll jede Antwort als relevant angesehen, und so wurden die verwaisten Antworten bei jedem Poll-Tick neu geholt. Ihre volle TTL lang, 60 Sekunden, rund 120 Mal pro Instanz. Und weil Antworten eine höhere Priorität haben, haben sie die echten Nachrichten aus dem Poll-Fenster gedrängt. Die Backlog-Flagge stand dauerhaft auf "ja", und der Watchdog hat aus "Stream ist still und der Poll findet was" auf "Cursor hängt" geschlossen. Was einfach kein Beweis ist. Ein Client, der selten adressierte Nachrichten bekommt, sieht legitim minutenlang nichts.

Der Poll holt jetzt nur noch Antworten, auf die diese Instanz tatsächlich wartet, und der Watchdog braucht eine Beobachtung, die einen vollen Schwellwert lang gehalten hat. Das hat eine Grenze, die ich lieber hinschreibe als verstecke: auf einem sehr ruhigen Deployment mit einem still gestorbenen Cursor schlägt der Watchdog nicht mehr an, und die Zustellung fällt auf Poll-Latenz zurück. Der Fallback-Poll liefert trotzdem. Dafür gibt es jetzt einen Test, der einen lebenden Cursor per Reflection stumm schaltet und prüft, dass der Restart kommt. "Der Watchdog feuert überhaupt" war vorher eine ungetestete Annahme.

Zwei weitere Sachen in 6.3.8 hätte ich gerne früher gewusst. Erstens: ein kerngesunder Follower hat sich selbst gelöscht und komplett neu synchronisiert, obwohl er exakt dieselben 100 Dokumente hatte wie der Primary. Der dbHash hat die BSON-Bytes verbatim gehasht, und die Feldreihenfolge ist zwischen dem normalen Insert-Pfad und dem Replay-Pfad nicht dieselbe. Gleiche Daten, andere Bytes, anderer Hash, "Divergenz", Full Sync. Und Full Sync heißt: erst droppen, dann kopieren. Der Test hat den Follower bei null Dokumenten erwischt. Das passiert nur unter Last, in einem 200-Millisekunden-Fenster, das es auf einem Entwicklerrechner praktisch nicht gibt.

Zweitens: mongosh konnte PoppyDB-Change-Streams nicht lesen. Jeder offizielle Treiber hat den Stream abgebrochen, sobald Messaging-Traffic floss. clusterTime ging als int64 raus statt als BSON-Timestamp, und ein synthetisches Event hatte gar kein _id. Morphiums eigener Treiber ist bei beidem tolerant. Deshalb ist es nie aufgefallen. Da steckt eine Lehre drin, die über PoppyDB hinausgeht: der eigene, tolerante Client ist der schlechteste Tester für Wire-Kompatibilität, den man haben kann.

Und jetzt?

Auf develop liegt schon der nächste. Diesmal auf dem produktiven Bus, also gegen MongoDB, nichts mit PoppyDB: geht die Antwort auf einen Write verloren, schickt Morphium den Write auf dem neu aufgelösten Primary noch mal. Die _id vergibt aber der Client. Wenn der erste Versuch in Wahrheit durchgegangen war, kollidiert der Retry mit sich selbst, und der Aufrufer bekommt einen Duplicate-Key-Fehler für einen Write, der geklappt hat. 142 Mal in 24 Stunden. 131 davon endeten als HTTP 500 für eine Nachricht, die gespeichert war und ganz normal verarbeitet wurde. Das wird 6.3.9.

Was bleibt: die Suite mit ihren 2.200 Tests ist grün, und das heißt genau eines - die Fälle, an die wir gedacht haben, funktionieren. Der Rest kam diesmal vom Zuschauen. Vom Heap-Histogramm, vom Verbindungszähler, vom Log der letzten sieben Tage. Und von dem einen Mal, wo ich einfach alles gleichzeitig ausgeschaltet habe.

Morphium 6.3.8 gibt es auf Maven Central, die Changelogs auf GitHub: 6.3.7 und 6.3.8.