DEV Community: SACHIN INDWAR

Three Raft bugs that only existed once I added log compaction

SACHIN INDWAR — Tue, 13 Oct 2026 17:47:07 +0000

I implemented Raft from the paper in Go — leader election, log replication, snapshotting, joint-consensus membership changes — with a linearizable key/value store on top.

The difficult part wasn't implementing the happy path. It was finding the defects that only became reachable once log compaction removed the redundancy that had been hiding them.

Adding snapshotting exposed three real bugs. A deterministic simulator I had built beforehand caught the subtlest one and pinned it to a single seed — seed 188 — which then reproduced it exactly throughout the diagnosis. The other two were caught by a storage conformance suite and a restart test. This post walks through each one, from trigger to regression test, along with the false positive I refused to count.

Repo: sAchin-680/Distributed-KV-Store-with-Raft-Deterministic-Simulation-Testing

Why ordinary tests miss this class of bug

Raft's correctness depends on the interleaving — which message arrives first, which is lost, whose timer fires first. An integration test samples whatever interleaving the OS scheduler produces on a fast, healthy machine. The orderings where consensus breaks — say, a message from long ago arriving after the entries it refers to have been compacted away — almost never come up that way. And when one does, it's gone before you can look at it.

Deterministic simulation testing, the approach FoundationDB and TigerBeetle are known for, attacks both problems: run the whole cluster on one thread, draw every source of nondeterminism from one seeded random source, and a run becomes repeatable from its seed.

Determinism has to be designed in

In Go, that only works if you control time, network, disk — and the goroutine scheduler. The scheduler forces the architecture: if consensus logic is spread across goroutines talking over channels, no virtual clock will make it replayable.

So the Raft core is a pure, synchronous state machine — no clock, no goroutines, no channels, no I/O:

func (r *RawNode) Tick()
func (r *RawNode) Step(m Message) error
func (r *RawNode) Propose(cmd []byte) (Index, error)
func (r *RawNode) Messages() []Message
func (r *RawNode) Applied() []LogEntry

Everything nondeterministic sits behind an interface, and the simulator swaps it out:

Concern	Production	Simulation
Time	`time.Now` / timers	virtual clock
Network	gRPC	in-memory queue with fault injection
Disk	bbolt	in-memory map
Scheduling	one goroutine per node	one single-threaded event loop

A CI script fails the build if a clock, goroutine, channel, mutex or package-level math/rand call appears inside the core, because this property degrades silently.

Note the trade-off in that table, because it matters later: the simulator runs the real consensus core, but not bbolt and not the node driver. It can only find bugs in the code it actually executes.

The four lines determinism depended on

The event loop is a priority queue ordered by virtual time, and simultaneous events are routine — every node's first tick is at t=0. Go's container/heap makes no promise about the order of equal elements, so without a tiebreaker the same seed could execute differently on different runs. Every event gets an insertion sequence number:

func (q *eventQueue) Less(i, j int) bool {
    if q.items[i].at != q.items[j].at {
        return q.items[i].at < q.items[j].at
    }
    return q.items[i].seq < q.items[j].seq
}

(The other trap is Go's randomized map iteration, which can't be caught statically. Every peer list in the core is a sorted slice, and a test runs each seed twice and compares a hash of the full event trace.)

What the simulator checks

Faults drawn from the seed: dropped, duplicated, delayed and reordered messages; partitions and heals; crashes and restarts. After every event: at most one leader per term, no committed entry ever changes, the commit index never decreases, applied never exceeds committed. At the end of a run: logs match pairwise, and no two nodes applied different commands at the same index.

A seed reproduces its run. Here's the same seed three times, recorded on a Linux box, not my laptop:

$ for i in 1 2 3; do simctl run --seed=2; done
seed 2: ok — 169359 events in 246.926ms (30000ms virtual) ... trace 26c664211d16bfc0
seed 2: ok — 169359 events in 254.286ms (30000ms virtual) ... trace 26c664211d16bfc0
seed 2: ok — 169359 events in 247.318ms (30000ms virtual) ... trace 26c664211d16bfc0

Only the wall-clock time changes. To be precise about how far that's been verified: the same trace hash appears in the repo's docs, recorded on my development machine with a different Go minor version. That's two machines and two toolchains for this seed, plus CI replaying failures — not a proof that every build on every platform agrees.

The full campaign, from a fresh run whose raw output is committed to the repo:

{{CAMPAIGN_OUTPUT}}

The three bugs

Bug 1: a late message mistaken for an attack on the committed log

How it was found: the simulator, seed 188.

Trigger. The leader sends an AppendEntries starting near the beginning of the log. The network delays it. Meanwhile the follower receives newer appends, commits past them, takes a snapshot and compacts the old entries away. Then the stale message finally arrives.

Root cause. The follower ran its normal conflict scan on the stale message. The scan compares each incoming entry's term with the term the follower holds at that index — but those indices had been compacted. An entry the follower simply no longer had was reported as conflicting, and the node refused the append as an attempt to overwrite its committed prefix.

Before compaction this code was correct: the old entries were still there, the scan verified them, and found no conflict.

Consequence. The follower raised a safety error on a perfectly legitimate, merely late, message. To check how rare the trigger is, I removed the fix and re-ran the campaign:

$ simctl fuzz --count=300 --max-failures=0      # fix removed
ran 300 seeds in 1m27.659s (3 seeds/sec, 364034 entries committed, 48795440 events)
1 failing seed(s):
  seed 188: sim: step append-req on node 1: raft: leader entry at index 1
            conflicts with committed index 57: raft: safety violation

One seed out of 300. It needs a log long enough to compact and a message delayed long enough to span the compaction. That seed reproduced it identically on every run, including after I fixed the wrong thing first and had to go back.

Fix. A guard before the scan (raft/replication.go):

if m.PrevLogIndex < r.log.committed {
    r.send(Message{
        Type: MsgAppendResp, To: m.From,
        Success: true, MatchIndex: r.log.committed, ReadID: m.ReadID,
    })
    return nil
}

Why ignoring the entries is safe. It looks alarming to return without processing the message, so here's the invariant:

Messages from older terms are rejected before this handler runs, so this one comes from the current leader.
Everything at or below the follower's commit index is committed. By Raft's Leader Completeness and Log Matching properties, the current leader's log agrees with ours at every one of those indices. There is nothing to verify and nothing to change.
The message may also carry entries above our commit index. We drop them — but the reply says MatchIndex: committed, not "everything you sent". We never acknowledge an entry we don't hold, so the leader can't count us toward committing it.
The leader only ever moves its record of our progress forward (if m.MatchIndex > pr.Match), so a low-but-true answer can't rewind it. It resends the later entries on the next round.

So the cost of the early return is at most one extra round trip, and it can't affect safety.

The same change also floors the leader's rejection backoff at the follower's confirmed match index. A delayed rejection could otherwise make the leader resend entries the follower had already committed. That wasn't the cause of seed 188, but it's the same family: a late message acting on a world that has moved on.

Regression tests. TestStaleAppendBelowCommitIndexIsAnswered builds the exact sequence — append 60 entries, commit 58, snapshot and compact, then deliver a stale append from index 1 — and asserts it's answered with success, MatchIndex 58, and an unchanged commit index. TestStaleRejectionCannotRewindBelowMatch covers the delayed rejection. Seed 188 runs in the campaign above.

Bug 2: the log grew forever behind a snapshot that claimed to shorten it

How it was found: the storage conformance suite, which runs the same tests against the in-memory store and bbolt. The simulator couldn't have found this one — it never runs bbolt.

Trigger. A leader takes a snapshot but deliberately keeps a tail of entries past the snapshot point, so a follower that's one entry behind can be repaired with entries instead of the whole state machine. Later it compacts up to an index below the snapshot boundary.

Root cause. The bbolt store used one field for two different things: the log floor (the oldest entry still answerable) and the snapshot boundary. They're equal right up until a leader keeps a tail. Once they diverged, Compact saw an index at or below its "floor", concluded it had already run, and returned.

The fix was to give them separate fields (storage/bolt.go):

// snapIndex and snapTerm describe the newest snapshot.
snapIndex raft.Index
snapTerm  raft.Term

// floorIndex and floorTerm describe the oldest entry still answerable:
// the last one discarded by compaction. Separate from the snapshot —
// the floor sits *below* the snapshot boundary when a tail is kept.
floorIndex raft.Index
floorTerm  raft.Term

Compact now short-circuits only when upto <= s.floorIndex.

Consequence. No error, no failed assertion — just a log that never got shorter, behind a snapshot that said it had been compacted. In production, a disk-space leak you notice days later. Any test that doesn't specifically check "did the log actually get shorter?" passes straight through it.

Regression test. TestCompactBelowTheSnapshotBoundaryStillWorks: append 60 entries, save a snapshot at 60, compact to a lower index, and assert the entries below it are actually gone — against both storage implementations.

Bug 3: a restarted node came back with a fraction of its data — and reported healthy

How it was found: while making the simulator's model of a restarting node correct (more on that below). The real defect lives in the node driver, which the simulator doesn't run, so it's covered by a cluster test rather than a seed.

Trigger. A node that has taken a snapshot and compacted its log restarts.

Root cause. On startup, the node resumed applying entries from its persisted applied index — but never rebuilt its state machine from its own snapshot first. Without compaction this was invisible: the whole log was still there, so replay produced the right state anyway. Wrong code path, right outcome, for exactly as long as nothing was ever discarded.

Fix. Restore from the node's own snapshot before the run loop starts, so nothing can observe a half-built state machine (node/node.go):

func (n *Node) restoreFromDisk() error {
    _, snap, err := n.cfg.Storage.InitialState()
    if err != nil {
        return fmt.Errorf("node: reading initial state: %w", err)
    }
    if snap.IsEmpty() {
        return nil
    }
    // ... the state machine must support snapshots, or the node cannot recover
    if err := snapshotter.Restore(snap.Data, snap.LastIncludedIndex); err != nil {
        return fmt.Errorf("node: restoring snapshot at index %d: %w",
            snap.LastIncludedIndex, err)
    }
    return nil
}

Consequence. Once compaction existed, the discarded entries were gone. The node came back, answered requests, voted in elections — and held the wrong data.

Regression test. TestNodeRestoresFromItsOwnSnapshot runs a real cluster with a low snapshot threshold, writes 60 keys, restarts the leader, and asserts all 60 keys are still there.

The finding I didn't count

The first snapshot-enabled fuzz run reported eleven seeds with state machine divergence. That looked like eleven more bugs.

It wasn't. The simulator's own model restarted a node with an empty state machine — the same mistake as bug 3, but in the test harness — so two correct nodes legitimately had histories starting at different points. The checker compared them by list position and called it divergence.

I fixed it twice over: the simulated node now restores from its snapshot, and the checker compares by log index instead of position, which states the property that actually matters — no two nodes disagree about what's at index i — without caring where each history begins.

A failing run means something disagrees, not the code is wrong. Counting your tool's bugs as findings poisons every future result.

How I know the checker isn't just quiet

A campaign with zero violations looks exactly like a broken checker. So there's a negative control.

Raft assumes a node's term, vote and log survive a crash. --disk-loss=0.5 deliberately breaks that: a restarting node loses its persisted state half the time. That must break safety somewhere:

$ simctl fuzz --count=41 --disk-loss=0.5 --max-failures=0
ran 41 seeds in 10.686s (4 seeds/sec, 31781 entries committed, 5206831 events)
23 failing seed(s):
  seed 1: safety violation [committed-entries-never-change] ...
  seed 6: safety violation [state-machines-agree] ...
  ...

23 of 41 seeds fail: 15 because a committed entry was later replaced, 8 because two nodes applied different entries at the same index. Each run stops at its first violation, so these are the first properties broken. Any one of them reproduces exactly from its seed:

$ simctl run --seed=27 --disk-loss=0.5
safety violation [committed-entries-never-change] at t=26106ms (seed 27):
  committed index 119 changed: node 1 committed term 1 (8488d043) at t=2520ms,
  node 3 now has term 3 (c38200e5)

The unit tests get the same treatment: 22 seeded mutations, each a plausible mistake paired with the test that should catch it. That check found three tests that could not fail — one measured nothing at all, and two pre-vote tests passed whether or not the bug they were named after was present.

What the evidence does and doesn't establish

Evidence	Establishes	Does not establish
10,000 seeded runs, no violations	No checked property was violated in those executions, under the simulator's fault model	That this Raft is correct
Identical trace hashes	Repeatability for the tested seeds on the machines and toolchains tried	Agreement across every build and platform
22/22 seeded mutations caught	Those specific mistakes are detected by their tests	Complete mutation coverage
Disk-loss negative control	The checker detects at least this class of injected failure	Detection of every possible safety defect
Real-cluster chaos + linearizability checks	The recorded client histories satisfy the model	Correctness under all workloads and faults

The last row covers the simulator's blind spot. Because it replaces gRPC, bbolt and the Go scheduler, a separate rig runs a real cluster in containers with tc/netem packet loss and iptables partitions, records every client operation, and checks the history is linearizable with Porcupine. Those runs can't be replayed, but they exercise exactly what the simulator stubs out — which, as bugs 2 and 3 show, is where real defects also live.

The lesson

The biggest lesson wasn't that a simulator found a bug. It was that all three bugs had been hidden by the absence of a feature.

Before compaction, replaying the log masked a broken restart path. Before the log floor diverged from the snapshot boundary, a storage bug stayed dormant. Before a delayed message could cross a compaction boundary, the conflict check behaved correctly.

Adding the feature removed those safety nets. Because the core was deterministic, the subtlest failure became a reproducible sequence of events — seed 188 — rather than an intermittent symptom. And because the simulator can't see everything, the conformance suite and restart test caught what it couldn't.

That's why I now treat the testing architecture as part of the system design, not something added after implementation.

Reproduce it

make fuzz FUZZ_SEEDS=10000                     # the campaign
make replay SEED=2                             # one execution, with its trace
make mutation                                  # the 22 seeded mutations
bin/simctl fuzz --count=41 --disk-loss=0.5 --max-failures=0   # the negative control

sAchin-680 / Distributed-KV-Store-with-Raft-Deterministic-Simulation-Testing

A Raft consensus implementation in Go built from scratch using real HTTP communication between processes to demonstrate leader election, heartbeats, and distributed systems fundamentals.

Distributed KV Store with Raft + Deterministic Simulation Testing

A linearizable key/value store on hand-written Raft — verified by a deterministic simulator that replays any failure from a single integer.

Overview · System design · Verification · Performance · Operations · Getting started · Docs

Overview

Raft implemented from the paper — leader election, log replication, snapshotting and joint-consensus membership changes — with a linearizable key/value store on top.

The part that matters is what surrounds it. A deterministic simulation framework controls time and the network, injects partitions and crashes from a seeded random source, and reproduces any execution exactly. When a randomized run finds a safety violation it prints one number, and that number is enough for anyone to replay the identical failure, byte for byte, indefinitely.

Everything below was measured, not estimated.

Simulation campaign	10,000 seeds, 1.7 billion events, 83 simulated hours in under 4 minutes, 0

…

View on GitHub

Next in this series: why my alert for leader elections uses a threshold derived from cluster size, and how a rolling upgrade showed the old constant was in the worst possible place.

I'm Sachin, an SRE / platform engineer working on observability, Kubernetes and distributed systems — currently open to new roles. LinkedIn · GitHub

Tracing a 3x Memory Blow-Up in Grafana's Time Comparison

SACHIN INDWAR — Fri, 07 Aug 2026 15:15:46 +0000

While contributing to Grafana, I picked up a memory issue in the Time Comparison feature — a follow-up to earlier performance work I had done in the same area.

A comparison panel was consuming significantly more memory than expected. The interesting part: the extra memory wasn't coming from real data.

This post covers how I traced it to the root cause and fixed it.

Background

Time Comparison overlays an earlier period onto the current one — for example, this week vs. last week. The comparison data is fetched from the earlier window and shifted forward before rendering:

Query → DataFrame → Prepare frame → Shift → Render
                         │
                         └─ Gap filling

The important detail: gap filling ran before the comparison frame was shifted.

The Problem

I reproduced the issue with:

Parameter	Value
Series	500
Window	6h
Interval	20s
Compare offset	24h

A single-period panel contained roughly 540,000 points, so a comparison panel should be about 2× the baseline.

Instead, the compare frame contained 3,240,500 points — ~6× the baseline — and consumed 76.4 MB.

The question was: where did the extra points come from?

Investigation

I first verified the baseline to rule out the query returning unexpected data. It was correct.

Then I used a reproducible browser harness and a heap snapshot to inspect the extra memory. Most of it was null rows introduced during gap filling — not real samples, not copies.

Following the frame through the preparation pipeline revealed why. When gap filling ran, the compare frame still represented data 24 hours in the past, but the gap-filler was using the current time range as its reference:

   Compare frame                         Current range
   [===== 6h =====]                      [===== 6h =====]
          └───────────────  24h  ───────────────┘
                gap-filler reads this offset as one gap

At a 20-second interval, 24 hours is:

24 × 60 × 60 / 20 = 4,320 intervals

So up to 4,320 null positions per series were introduced purely because the frame hadn't been shifted yet. The frame was then shifted forward, leaving most of that padding outside the visible range — where nothing draws it.

Root Cause

The issue was the reference range gap filling used. It evaluated the compare frame against the current range instead of the range the frame actually represented:

Before                         After
──────                         ─────
Compare frame                  Compare frame
     ↓                              ↓
Gap-fill vs current range      Use frame's effective range
     ↓                              ↓
Shift by 24h                   Gap-fill
                                    ↓
                               Shift by 24h

The Fix

I changed the gap-filling logic to account for the compare frame's own offset when determining its effective time range. This means:

genuine gaps are still filled
non-comparison frames are unchanged
the unnecessary null padding is eliminated

Results

Scenario	Before	After
Compare points	3,240,500	1,081,000
Compare heap	76.4 MB	22.8 MB
12× dashboard heap	822.5 MB	225.0 MB

The compare frame went from roughly 6× to 2× the baseline — consistent with the actual amount of data being rendered. I also verified it in the browser: the reproduced panel dropped from 144.2 MB to 84.4 MB.

What I Learned

1. Performance bugs can be data-flow bugs. The problem wasn't an expensive algorithm — it was a correct operation running against the wrong state.

2. Profile before optimizing. The heap snapshot showed the extra memory was synthetic null data, which immediately narrowed the search.

3. Large-codebase bugs often live between components. This one emerged from the interaction between time comparison, frame preparation, gap filling, and time shifting — not from a single isolated function.

Closing

This reinforced a lesson I keep coming back to while contributing to large open source projects:

When debugging performance, follow the data — not just the allocations.

The fix is up as a pull request against Grafana:

TimeComparison: Stop padding compare frames across the compare offset #129934

sAchin-680 posted on Aug 03, 2026

Follow-up to the memory investigation in #129681.

Compare frames are gap-filled while still sitting in their own earlier window - the panel only shifts them onto the current range afterwards. Measuring them against the unshifted current range reads the whole compare offset as a gap, so each frame gets padded with a null row per interval across it. Those rows then travel forward with the shift and land outside the visible range, where nothing can see them.

The fix measures a compare frame against the window it actually covers. Genuine gaps inside a frame still fill, and non-compare frames are untouched.

Measured with @drew08t's benchmark from #129806 (500 series, 6h window, 20s interval, 24h offset):

Scenario	Prepared points	Heap
Compare — before	3,240,500	76.4 MB
Compare — after	1,081,000	22.8 MB
Dashboard 12x compare — before	38,886,000	822.5 MB
Dashboard 12x compare — after	12,972,000	225.0 MB

Compare now reports 2.00x the points of a single-period baseline instead of 6.00x — two periods of 500 series should cost exactly twice one period, and it now does.

Also confirmed in a browser on the four-panel harness, toggling the fix in one session: the compare panel goes from 144.2 MB to 84.4 MB, with compare frames back to their true 1080 points. It now sits alongside an equivalent 1000-series non-compare panel (81.7 MB), the remaining ~3 MB being genuine compare overhead.

Note the benchmark in #129806 is still a draft, so those numbers aren't reproducible from main until it lands.

Ref #125104

View on GitHub