Mistakes that taught me the most

None of the bugs worth writing about were crashes.

A crash is easy. There's a stack trace, a line number, and an obvious thing that went wrong. The ones that taught me something were the ones where nothing appeared to be wrong at all, and the system was doing precisely what I'd told it to do.

The day time stopped

I was watching the cluster and noticed a log line that should have been there wasn't.

Then I noticed nothing was moving. No new entries. No errors either. Not on one node: on all three, at the same moment. Three separate processes, all perfectly calm, all doing nothing.

My first thought wasn't "there's a bug", it was "my laptop is hanging". So I checked CPU. Normal. Checked memory. Normal. Everything looked healthy, which was somehow worse, because a healthy system that isn't doing anything gives you nothing to pull on.

Eventually I went looking at the last entry each node had been processing before it went quiet. Same entry on all three. And that entry couldn't be parsed, a value that didn't fit where I was putting it, so the parse threw, and the throw went straight out of the apply loop and killed the thread.

Here's the part that took me a second to appreciate. This wasn't three coincidences. It was the system working exactly as designed.

The whole point of Raft is that every node applies the same commands in the same order, so they stay identical. Which means every node hits that entry. And every node dies on it, identically. Deterministic replication replicates your bugs as faithfully as it replicates your data, and three-node redundancy buys you nothing against a bug that's in the data itself.

Restarting doesn't help either. The entry is still in the log, and replay walks straight back into it.

The fix is small: catch the failure inside the loop, where the parse happens, so a node logs the bad entry, skips it, and carries on. Every node fails the same way, skips the same entry, and they stay identical, which is the property that actually matters. My code has a comment on that try now, mostly addressed to future me.

The clock that started over

Another one hiding in expiry.

A client sets a key with a two-second TTL. The entry goes into the log, and each node computes "expires at now + 2 seconds" when it applies it.

Looks fine. Now crash a node and restart it. It replays its log, reaches that entry, and computes now + 2 seconds again, except now is half an hour later. A key that expired long ago comes back to life, on that node only.

I saw it as a count that didn't match: one node reporting 60 items while the others said 59, at the same log position, and serving a key the leader had already dropped.

The bug is in what I stored. ttl = 2 seconds isn't a fact, it's an instruction, and an instruction is interpreted by whoever reads it, whenever they read it. expires at 14:32:07.412 is a fact, and it means the same thing on every node, forever.

So now the node that receives the write converts the TTL once, following memcached's rules, and the log carries an absolute deadline that every node stores as it is. The log should carry facts, not instructions to be interpreted later.

One assumption survives that fix, and it's worth saying out loud: each node still compares that deadline against its own wall clock. Identical deadlines make the nodes agree about what was stored, not about the exact instant it stops being visible. Two nodes whose clocks differ by a second will disagree for a second. Removing that would mean expiring entries through the log as well, which I haven't done.

The lock I held for five milliseconds

This one showed up as disappointing numbers rather than incorrect ones.

I had plenty of concurrent writers, and the throughput was far worse than that should have given me. Machine wasn't busy. Disk wasn't saturated. Just slow.

propose() was holding the RaftNode's lock while waiting for the WAL write to finish. An fsync on my laptop is around five milliseconds, and during every one of those, the node was locked. No other write could start. Worse, the node couldn't answer its peers either, so from the followers' point of view, the leader periodically stopped existing for five milliseconds at a stretch, which was enough to start elections.

Moving the wait outside the lock: one line, 5.9× throughput, and the spurious elections went away. "Never block while holding a lock" is advice I'd read many times without it meaning anything. It means something now.

The instrument was the outage

For a while I had a cluster that kept electing new leaders for no reason I could see. Nodes weren't dying. Network was fine. Leaders just kept being replaced.

The reason was my own logging. DEBUG level everywhere, 6.5 GB of it in three minutes, all going to the same disk the write-ahead log needed. The WAL's fsyncs were queueing behind log writes, so fsyncs got slow, so heartbeats got slow, so followers decided the leader was gone.

The tool I had added to watch the system was the reason the system kept falling over. Metrics logging ships turned off now, and I don't trust a measurement until I know what taking it costs.

It also taught me the relationship between the timers, which the Raft paper states plainly:

broadcastTime  ≪  electionTimeout  ≪  MTBF

A round trip to the followers has to be much faster than the election timeout, or a momentary hiccup looks like a dead leader. And the election timeout has to be much shorter than the time between real machine failures, or you're electing more than you're serving. BeeDB heartbeats every 300 ms with an election timeout between 1 and 2 seconds, so three to six heartbeats have to go missing before anyone panics. Get that ratio wrong, or let something else steal your disk, and you get a cluster that spends its life holding elections.

The common thread

Not one of these was a crash. Not one produced an error message pointing at the cause.

Every one of them was the system faithfully doing what I'd asked: applying the same command on every node, recomputing a TTL on replay, holding a lock until the work was done, writing down everything I said to write down.

That's the part I didn't expect from distributed systems. The hard bugs aren't where the machinery breaks. They're where it works perfectly, on an instruction you didn't realise you'd given.