Morphium 6.3.7 and 6.3.8: Bugs We All Had

The last post was about bugs nobody ever hit. Found by code review, fixed before they could land on anyone's feet. This time it is the exact opposite. Morphium 6.3.7 and 6.3.8 consist almost entirely of bugs we all had - for months, some of them for years. We just never saw them. And the reason we see them now is simple: we finally looked properly.

PoppyDB on a real bus

The story starts mid-August. On a message bus in an acceptance environment, three nodes, a good 30 clients, we took out the MongoDB replica set and put PoppyDB in its place. Same port, same hosts, dump restored via mongorestore, clients told nothing. And then we watched. Not "runs, fine", but properly: heap histograms after full GC, connection counters on the nodes, log analysis over days.

I expected PoppyDB to pick up a few scratches. That is the point of the exercise. What I did not expect: half of the findings had nothing to do with PoppyDB at all, but with the client. Meaning Morphium itself. Meaning the part that has been running against MongoDB in production for years.

One Double per event, forever

Let's start with PoppyDB anyway. After a few days the secondaries looked odd: live set after GC at 23 percent of the heap, the primary at 5. On a replica set where all three hold the same data. The heap histogram showed millions of java.lang.Double. Millions. Who needs millions of Doubles on a database server?

The answer: nobody. The InMemoryDriver puts every command reply into a map, and the entry only leaves once the caller fetches it. On the primary the Netty handler does that for every request. The replication path on the secondaries, however, simply threw the reply away - for every update, every delete, every drop. What remained was exactly one "ok": 1.0 per replicated event. Measured locally: 20,000 updates on the primary, plus 20,000 Doubles on each secondary. At twelve events per second that is roughly 0.8 GB per day until the node hits the memory watermark.

44 hours after the fix: exactly zero Doubles on all three nodes. Not fewer. Zero. That is the kind of confirmation I like.

But the client was guilty too

And now the part that is genuinely embarrassing. The nodes saw between 1.5 and 4.3 new TCP connections per second. Constantly. Over 61 hours that added up to 937,000 connection establishments on one secondary - for 150 to 220 connections that were ever open at any given time.

The cause sits in the PooledDriver and is actually logical once you see it: lastUsed on a connection is only refreshed by real application borrows, not by the heartbeat that runs over it every second. Which is correct, otherwise the pool could never shrink again after a burst. But for a client with little to do, that meant all its connections were "idle" after 30 seconds. The sweep closed them, the refill immediately rebuilt them because minConnectionsPerHost has to be satisfied. One TCP handshake every 30 seconds per connection, per client, forever. On connections carrying healthy heartbeat traffic the whole time.

I reproduced it locally against a replica set to be sure: 9 connections, 10 seconds idle time, measured 0.90 reconnects per second. Pool size divided by idle time, to the second decimal. Ten times the idle time, a tenth of the reconnects. Heartbeat five times slower: no change. That is the bug, no question.

Right next to it another one: the heartbeat on SingleMongoConnection sent the complete SCRAM authentication along with every hello. Even on a connection that had been authenticated for an hour. On a cluster with auth that is about 7,200 logins per hour per node that nobody needed. Invisible as connection churn, because the socket never changes.

Both bugs hit MongoDB just as much as PoppyDB. Both are old. They only surfaced because we looked at the connection counters on the nodes for PoppyDB's sake - and the numbers on the MongoDB buses next door looked exactly the same.

Rolling restart - the bug hider

This is the story I am actually writing this post for.

At some point I wanted to know what happens when all three PoppyDB nodes are gone at once. Power outage, data center maintenance, whatever. We had done rolling restarts often enough, those always worked. So: all three down, all three up.

Result: all data present. All indexes gone. Every single one. The TTL indexes on the messaging collections stopped working, one collection had silently grown to 9,500 documents, and every query on the hot path was a collection scan. The dump had only ever contained documents, never the index definitions. And why did nobody notice? Because a rolling restart structurally hides it. The restarting node fetches its indexes from a running peer via initial sync. As long as any node stays up, everything is fine. Only when all of them read from their dumps is there no peer left to copy from.

So, fix: the dump now carries the indexes. Sounds trivial, but has a trap: the indexes have to be created after the data, not before. createIndex seeds a TTL index's expiry queue from the documents present at that moment, and the sweep never re-bootstraps a queue that came up empty. Index before data, and every restored document would be permanently un-expirable. The same bug in a new disguise.

Fix built, eight new tests, full suite of over 2,200 tests green, onto acceptance, full-cluster restart. And: two of three nodes never came back. The cluster ran on one leg. From the outside the only symptom was "node is recovering", in the log of the stuck node a stack trace scrolled past per attempt.

The fix had brought its own bug along. The JSON parser delivers every number as Long on restore. So expireAfterSeconds was registered as a Long. The restore itself was perfectly happy with that. But as soon as a peer asked via listIndexes, the Long went over the wire as Int64, and on the other side IndexDescription.fromMap sets its fields reflectively - onto an Integer field. IllegalArgumentException, initial sync failed, next attempt, same thing. Forever. 13 TTL indexes across all databases, every single one a reason never to come up again.

And again: neither the eight new tests nor the full suite saw it. Because "restored from a dump" and "then queried by a peer" were each tested alone, never together. And because a rolling restart cannot trigger exactly that combination.

The lesson is actually banal and still caught me cold: a rolling restart is worthless as a test for restore paths. It tests whether a node can learn from its peers. It never tests whether a node can come up on its own. There is now an E2E test that kills a complete replica set at once, restarts it from the dumps and checks that every node becomes PRIMARY or a fully synced SECONDARY again - not merely that the data is back. And a node whose initial sync fails five times with the identical error now writes a NODE STUCK IN RECOVERY line into the log that you cannot miss.

Verification with the final 6.3.7: all three nodes down at once, all three up after ten seconds, 15 TTL indexes intact, task counts identical. Before: one out of three.

6.3.8: the watchdog that cried wolf

Five days later, the next release. This time the change stream watchdog deserved attention: 2,229 alarms in seven days, one process was at restart number 260. Every alarm discards the cursor and rebuilds it without a resume token. So this is not "the log is a bit noisy", this is a disruption. And with thousands of false positives a real stall would have been invisible anyway.

83 percent of the alarms fell into minute :00 and :01. Hourly cron. It sent requests fire-and-forget style, and the receivers dutifully answered - to someone who was not expecting an answer. Such answers are deliberately not marked as processed, so that a listener registered later still receives them. Only the poll considered every answer relevant, so the orphaned answers got re-fetched on every poll tick. For their full TTL, 60 seconds, around 120 times per instance. And because answers carry a higher priority, they pushed the real messages out of the poll window. The backlog flag stayed permanently on "yes", and the watchdog concluded from "stream is silent and the poll finds something" that the cursor was stuck. Which simply is not proof. A client that rarely receives addressed messages legitimately sees nothing for minutes.

The poll now only fetches answers this instance is actually waiting for, and the watchdog needs an observation that has held for a full threshold. That has a limit I would rather write down than hide: on a very quiet deployment with a silently dead cursor the watchdog no longer fires, and delivery falls back to poll latency. The fallback poll still delivers. In return there is now a test that silences a live cursor via reflection and checks that the restart happens. "The watchdog fires at all" used to be an untested assumption.

Two more things in 6.3.8 I would have liked to know earlier. First: a perfectly healthy follower dropped itself and re-synced from scratch although it held exactly the same 100 documents as the primary. dbHash hashed the BSON bytes verbatim, and the field order is not the same between the normal insert path and the replay path. Same data, different bytes, different hash, "divergence", full sync. And full sync means: drop first, then copy. The test caught the follower at zero documents. That only happens under load, in a 200 millisecond window that practically does not exist on a developer machine.

Second: mongosh could not read PoppyDB change streams. Every official driver aborted the stream as soon as messaging traffic flowed. clusterTime went out as int64 instead of a BSON timestamp, and one synthetic event had no _id at all. Morphium's own driver is tolerant of both. That is why it never came up. There is a lesson in there that goes beyond PoppyDB: your own tolerant client is the worst tester for wire compatibility you could possibly have.

And now?

The next one is already on develop. This time on the production bus, so against MongoDB, nothing to do with PoppyDB: when the reply to a write is lost, Morphium re-sends the write on the freshly resolved primary. But the _id is assigned by the client. If the first attempt had in fact gone through, the retry collides with itself, and the caller gets a duplicate key error for a write that worked. 142 times in 24 hours. 131 of them ended as an HTTP 500 for a message that was stored and processed perfectly normally. That will be 6.3.9.

What remains: the suite with its 2,200 tests is green, and that means exactly one thing - the cases we thought of work. The rest came from watching this time. From the heap histogram, the connection counter, the log of the last seven days. And from that one time I simply switched everything off at once.

Morphium 6.3.8 is on Maven Central, the changelogs on GitHub: 6.3.7 and 6.3.8.