Caluga - Java blog

Morphium 6.3.4 bis 6.3.6: Fehler beheben, die nie jemand hatte

Morphium 6.3.4 bis 6.3.6: Fehler beheben, die nie jemand hatte

Morphium 6.3.4, 6.3.5 und inzwischen auch 6.3.6 sind raus, auf Maven Central. Drei Releases innerhalb von zwei Tagen, das fünfte in einer Woche. Und dieses hier ist anders als alle davor: kein einziger Fix darin geht auf einen Bug-Report zurück. Niemand ist auf diese Fehler gestoßen. Kein Stacktrace aus der Produktion, kein Issue, nichts. Alle wurden durch reinen Code-Review gefunden - von AIs.

Und ja, ich habe dazu Gefühle. Gemischte.

AI-Review - warum eigentlich?

Ich habe AI-Agenten auf den Change-Stream- und Replikations-Code losgelassen. Bewusst nicht ein Modell, sondern mehrere: OpenAI, Anthropic und opencode, in Kollaboration. Jeder reviewt für sich, aus verschiedenen Blickwinkeln. Bei zwei der Findings stand hinterher sogar dabei, dass zwei unabhängige Agenten denselben Bug von entgegengesetzten Enden gefunden haben - einer kam von der Change-Stream-Seite, einer vom Replikations-Konsum. Wenn zwei Reviewer mit unterschiedlichem Training auf derselben Codezeile landen, sollte man besser mal hingucken.

Gefunden haben sie eine Bug-Klasse, für die meine Testsuite schlicht blind ist: Fehler, die nur unter Last existieren. Nicht die Sorte "die Assertion ist falsch". Eher die Sorte "das Timing-Fenster zwischen diesen zwei Threads frisst still deine Daten".

Was war denn nun kaputt?

Eine Kostprobe, alles in 6.3.4 gefixt:

  • Ein Resume-Check, der zu früh prüfte. Ob ein Change Stream fortsetzbar ist, wurde beim Registrieren geprüft - der eigentliche Replay lief aber später, auf einem anderen Thread, während die Eviction bei jedem Write munter weiterlief. Ein als "sauber" validierter Resume konnte in genau dieser Lücke Events verlieren. Der Konsument bekam dann den Rest geliefert, mit einem unsichtbaren Loch in der Mitte.
  • Live-Events, die den History-Replay überholen. Ein Live-Event mit Sequenz 105 konnte vor den nachgespielten 101 bis 104 ankommen. Auf einem Replica-Secondary überschreibt das im Zweifel ein neues Dokument mit einem alten Stand. Still, versteht sich.
  • 10.000 mal 300KB sind 3GB. Die Watch-Cursor-Queues waren nur über die Anzahl begrenzt. Ein einziger langsamer Consumer mit großen Dokumenten konnte damit Gigabytes auf dem Primary festnageln. Ausgerechnet auf dem Knoten, dessen OOM den ganzen Cluster mitnimmt.
  • Ein Initial Sync, der über einem toten Watch "Erfolg" meldet. Die Backpressure parkt während des Syncs den Watch-Reader - und der geparkte Reader ist blöderweise der einzige Thread, der merken könnte, dass der Primary den Cursor längst gekillt hat. Das Sync-Gate hat fröhlich geöffnet.
  • Ein gestoppter Sync-Thread, der in die Daten seines Nachfolgers schreibt. stop() wartet 5 Sekunden auf den Thread, der Socket-Read wartet aber bis zu 60. Der verwaiste Thread tauchte später mit fertigem Read wieder auf und hat einfach mal Daten geschrieben, die längst seinem Nachfolger gehörten.

Das Muster ist immer dasselbe: still. Keine Exception, keine Log-Zeile, kein roter Test. Nur Daten, die leise falsch sind und darauf warten, dass Lastprofil und Fehlerfall in der Produktion mal zusammenkommen.

Und dazu kam noch ein Bug, der einen echten "Sturm" ausgelöst hat und dafür sorgte, dass wir am selben Tag noch 6.3.5 rausgebracht haben. Ein Folgefehler, der genauso echtes MongoDB getroffen hätte - via Poppy kam er nur schneller ans Licht (ich weiß nicht, ob ich mich darüber freuen soll...).

Der Fehler: der in 6.3.4 eingeführte Resume-Window-Guard lässt den Server einen 286-Fehler senden, wenn das Resume-Token hinter dem letzten Token des Servers liegt. Der Client sollte dann eigentlich den Stream resetten und frisch starten. Dummerweise - ein simpler Programmierfehler - wurde das Token clientseitig wiederverwendet. Also wieder derselbe Fehler, wieder dasselbe Token, und so weiter: Endless Loop. Das hat zu extremer Last auf den MongoDB- und PoppyDB-Servern geführt, quasi ein selbstgebautes DDoS.

Und 6.3.6? Das war der unheimlichste von allen. Bei einem Rolling Restart der Server blieb genau einer von rund dreißig Clients einfach stehen: keine Messages mehr, keine Fehlermeldung, kein einziger Log-Eintrag - aber der HTTP-Teil kerngesund, alle Health-Checks grün. Ein Thread-Dump später war klar: sämtliche Heartbeat-Threads des Treibers waren weg. Die Ursache, nach einigem Graben: die Topologie-Verwaltung hat Hosts unter ihrem normalisierten Namen eingetragen, beim Aufräumen aber gegen die unnormalisierten Namen aus dem Server-Hello verglichen. Meldet ein Server ein Member in anderer Schreibweise - SERV-MSG1 statt serv-msg1 - hielt der Treiber seinen eigenen, gerade eingetragenen Host für "nicht mehr im Replica Set" und warf ihn raus. Ein paar solcher Hellos im Failover-Fenster, und die komplette Topologie samt Seed-Liste war leergefressen. Danach: Stille, für immer. Ein Großbuchstabe Unterschied, ein toter Client.

Ein echter "Release-Storm" durch solche Dinge. Dummerweise konnten die mehr als 2000 Testcases von Morphium die echte Last eines genutzten Systems bisher nicht abbilden. Wobei - jetzt schon: wir können die Mechanismen inzwischen nachbilden, haben für jeden dieser Fehler einen Regressionstest geschrieben, und der Qualifikationslauf für 6.3.6 war der erste der ganzen Woche, der komplett ohne einen einzigen Retry durchlief.

Die Hassliebe

Erst der Hass: keiner dieser Fehler ist je aufgetreten. Der Code lief. Die Suite war grün. Alle zufrieden. Und dann drückt mir ein Haufen Sprachmodelle einen Stapel akribisch begründeter Findings in die Hand, mit Zeilennummern, Race-Fenstern und durchgespielten Fehlerszenarien - und plötzlich habe ich eine Woche Arbeit, die ich nicht bestellt habe. Verifikation, Regressionstests, Fixes über drei Module, zwei volle Testmatrix-Läufe, und ein Benchmark musste auch noch her, um zu beweisen, dass die Fixes nichts kosten (tun sie nicht, der Durchsatz ist unverändert). Das ist echte Arbeit für Fehler, die es von außen betrachtet gar nicht gab. Danke auch.

Und jetzt die Liebe: ich weiß natürlich, dass genau diese Sichtweise Quatsch ist. Das sind die schlimmsten Bugs überhaupt, gerade weil sie noch nicht passiert sind. Stille Divergenz schreibt keinen Bug-Report. Die taucht Monate später als "die Daten auf dem Knoten sehen komisch aus" auf, und dann viel Spaß bei der Suche nach der Ursache. Jedes Finding wurde übrigens erst gegen den Code verifiziert, bevor auch nur eine Zeile angefasst wurde - das waren keine Halluzinationen. Das war die Art Review, die ein sehr geduldiger, sehr pedantischer Kollege machen würde, wenn er eine Woche Zeit pro Datei hätte. Hat halt niemand.

Ein Finding hat sich einen Sonderplatz verdient: ein Test, der in CI seit Ewigkeiten als "flaky" galt, war gar nicht flaky. Sein sporadisches Scheitern war ein echter Bug - ein harter Integer-Cast im Messaging-Poll-Pfad, der an 64-Bit-Zahlen stirbt. Ausgerechnet der Pfad, über den sich das Messaging nach einem Failover erholt. Die "Flakiness" war der Bug und hat monatelang höflich angeklopft. Wir haben immer nur auf Retry gedrückt 😉

Und jetzt?

Der Review hat nicht nur Fixes produziert, sondern auch Hausaufgaben. Auf dem 6.4.0-Milestone liegen jetzt ein paar neue Issues: ein Test-Harness, das mit Invarianten arbeitet statt Dokumente zu zählen (denn eine Suite, die zählt, sieht von alledem oben nichts), ein Umbau, damit nicht mehr pro Change Stream ein Thread geparkt wird, und der Rest der Sync-Shutdown-Härtung.

Heftige Woche. Fünf Releases, ein gutes Dutzend Fixes mit sauberer Root Cause, etliche grüne Volläufe der Testmatrix, ein Benchmark. Alles für Fehler, die nie jemand hatte. Noch nicht. Und genau wegen diesem "noch" mache ich das wieder. Grummelnd, aber ich mach's.

Morphium 6.3.6 gibt es auf Maven Central, das vollständige Changelog auf GitHub.