A Go test that passed 40,000 times, then lost a write under load

Say a client writes a value and gets a success back. Later, the value is gone. It happens once in production, around the time a node restarts, and every test is green. A week later a CI job fails on a test nobody touched. The re-run passes, so someone adds a retry and moves on.

Bugs like this need a rare timing, such as a partition during a leader election, or a crash after a write was acknowledged but before it reached the disk. Production hits that timing eventually, because it runs all day on busy machines.

A test that passes 40,000 times

Here is a write path cut down to one test, which you can save as wal_test.go in a new module (go mod init wal) and run. The caller puts an entry on a queue and is told the write is safe. A background goroutine moves queued entries to disk, and shutdown tells it to stop.

package wal

import (
    "testing"
    "time"
)

func TestAckedWriteSurvivesShutdown(t *testing.T) {
    queue := make(chan string, 8)
    stop, done := make(chan struct{}), make(chan struct{})
    var disk []string

    go func() { // the writer moves queued entries to disk
        defer close(done)
        for {
            select {
            case e := <-queue:
                disk = append(disk, e)
            case <-stop:
                return // bug: anything still in the queue is lost
            }
        }
    }()

    queue <- "x=1"                    // the caller is told the write is safe
    time.Sleep(50 * time.Microsecond) // "give the writer a moment"
    close(stop)
    <-done
    if len(disk) != 1 {
        t.Fatalf("acknowledged write lost: disk=%v", disk)
    }
}

The bug is in the writer's select. If an entry is still in the queue when the stop signal arrives, both cases are ready. The Go spec says select then picks one of them by uniform pseudo-random selection. If stop wins, the writer returns and the acknowledged entry is lost.

On my 16-core Apple M4 Max laptop with Go 1.27.1, the test passed 40,000 runs in a row while the machine was idle (go test -count=10000, four times). Then I kept every core busy with 32 copies of yes > /dev/null and ran 60,000 more. The test failed 23 times, between 1 and 7 times per 10,000 runs.

The race detector does not catch it. go test -race stayed quiet for 2,200 runs, because there is no data race: closing done orders the writer's last append before the test reads disk.

When the test does fail, this is all you get:

--- FAIL: TestAckedWriteSurvivesShutdown (0.00s)
    wal_test.go:30: acknowledged write lost: disk=[]

There is nothing in that output you can run again. The next run makes its own random choices, and in the 40,000 idle runs, no run lost the write.

Why normal tests miss these bugs

A test controls its inputs. It does not control the clock, goroutine scheduling, the network or the disk, and in a distributed system those decide when things happen:

• time.Now and timers follow the wall clock, so whether a timeout fires first depends on how busy the machine is.

• The Go runtime decides which goroutine runs next, on several OS threads, and since Go 1.14 it can preempt goroutines asynchronously. There is no way to hand the scheduler a seed.

• A TCP connection over localhost does not lose or reorder bytes, and it never runs into a partition. On a real network, packets get lost and reordered, connections stall and break, and partitions happen.

• A write that returned is not durable until it is synced, and a test process does not crash between the two.

So a normal test explores a small part of the timings your system can see, mostly the ones an idle laptop produces, and sleeps and retries make this worse. Say someone added the sleep in the example after the test failed once. Without it, the test failed 971 times in 2,000 runs on the same laptop. The sleep did not fix the bug. It made the losing timing rarer, which made the bug harder to find. A retry in CI does the same for the whole suite: it turns a test that hit a bad timing into a green check mark.

That is why I treat a flaky test in a distributed system as a bug report until I can show otherwise. It may have hit a timing the code mishandles, and it came with no steps to reproduce it.

What deterministic simulation testing is

Deterministic simulation testing (DST) takes those sources of nondeterminism away from the machine and gives them to the test. In its usual form, you run the whole system, every node, inside one process, in a simulated world with its own clock, network and disk. The clock there runs on virtual time: it jumps from one event to the next and never waits. Every random choice comes from one number, the seed: which message arrives next, how long it takes, which ready task runs first, whether a disk write survives a crash.

Then you add faults on purpose. The simulator delays and drops messages or delivers them out of order, cuts the network into partitions, crashes and restarts nodes, and fails disk writes. A test runs many seeds and checks, after each run, that the system kept its promises, for example that no acknowledged write was lost.

When a seed fails, you replay it: you run the same seed again and get the same run. Every message and every fault lands at the same point as before, and the run ends in the same failure. The seed is the reproduction. You can add logging or step through the run in a debugger, and once you have a fix, you run the same seed to see whether it passes. After a code change, though, the same seed can take a different path, so one passing seed does not prove the fix.

Apply that to the example. A simulator that controlled the writer's select would make its choice from the seed, so a losing seed would lose the write on every replay.

None of this is new. FoundationDB's simulation runs a whole cluster deterministically in a single-threaded process. It injects faults from broken connections and rebooting machines up to whole datacenters, and the team estimates they have run the equivalent of about a trillion CPU-hours of simulation. TigerBeetle's simulator, the VOPR, stubs out the clock, the network and the disk. It drops and reorders packets, partitions the network, corrupts disk reads and writes, and replays any failure from its seed and Git commit.

Antithesis takes a different route. It built a deterministic hypervisor that runs your whole system on a single CPU core, so the software inside does not have to change. Any bug it finds can be reproduced. FoundationDB and TigerBeetle went the other way: their code is written to run inside their own simulators. FoundationDB even built its own runtime, Flow, which runs the same code in production or in simulation.

Why this is hard in Go

A simulator has to make every choice itself, and the scheduler's choices are not the only ones a Go test cannot control:

• Besides select, the spec leaves map iteration order unspecified, and since Go 1.20 the global math/rand generator gets a random seed at startup.

• net and os call into the operating system, which a test cannot partition or crash.

Since Go 1.25, the clock is the exception. That release added the testing/synctest package to the standard library. synctest.Test runs a function in a "bubble" whose goroutines see a fake clock. That clock moves forward only when every goroutine in the bubble is durably blocked. Durably blocked means only another goroutine in the bubble can wake it, for example because it waits on a channel created inside the bubble. Tests with timeouts run fast, and the times they read are the same on every run.

I put the example in a bubble with a second file in the same package:

package wal

import (
    "testing"
    "testing/synctest"
)

func TestAckedWriteInBubble(t *testing.T) {
    synctest.Test(t, TestAckedWriteSurvivesShutdown)
}

With the sleep, go test -count=10000 -run TestAckedWriteInBubble passed 10,000 runs out of 10,000, both idle and with every core busy. The fake clock does not move until the writer has emptied the queue and blocked again, so the window for the bug never opens. With the time.Sleep line and the time import deleted, it failed 5,017 times in 10,000: select still picks a ready case at random, and nothing records which one it picked.

Apart from the clock, synctest leaves a test without the controls DST needs. Its API takes no seed, and its documentation says nothing about goroutine order. It has no simulated network or disk and no way to inject faults such as crashes, and the same documentation tells you to avoid the network and use a fake.

So DST in Go today means picking a trade-off. One way is to write the core of a system as a state machine that a simulator drives. The etcd/raft library is built like this: it implements only the Raft algorithm and leaves network and disk I/O to the caller. That gives exact replay, but only for code written that way. The other way is to run ordinary goroutine code and take control of the runtime underneath it. That works with the code you already have. Exact replay is the hard part, because the simulator would have to take over the scheduler and every item in the list at the start of this section.

What I am building

faultline is an open-source deterministic simulation testing tool for Go that runs inside go test. Its first release, v0.1.0, is out. It runs code written for its simulator, plus etcd/raft through a ready-made harness. Running ordinary goroutine code like the example above is the next phase on the roadmap.

Comments

[pm25coder]

Small addition, because the retry point is quantitative and I think it is stronger than the post states it.

Taking your own counts at face value (23 failures in 60,000 runs with the time.Sleep, 971 in 2,000 without), the sleep drops the per-run failure probability from about 0.49 to 3.8e-4 -- roughly a 1,270x loss of detectability. That is the part worth naming: the sleep does not make the bug rare, it moves the test below the detection floor of whatever runs it. A CI job that runs the test once goes red 0.04% of the time; run that daily for a year and there is still about a 13% chance it never went red at all. The retry is then the last step of a test that was already made blind, not a separate mistake.

The fix in the example sits in the writer, not the test. On stop, drain before returning:

case <-stop:
    for {
        select {
        case e := <-queue:
            disk = append(disk, e)
        default:
            return
        }
    }

That is correct here only because the sole producer enqueues before close(stop), so program order hands the drain the happens-before it relies on. Worth stating as the precondition: drain-on-stop is safe only once admission has stopped. Add a concurrent producer and the drain can see an empty queue and return while a write is still in flight -- the same acknowledged-but-lost window, one level up. So: stop admission, drain, return. Or acknowledge only after the append, which removes the window instead of narrowing it.

One more, from your synctest numbers: with the sleep, the bubble turns 40,000 idle passes into 10,000/10,000 deterministic ones, over the same buggy program. A green that replays is a stronger false signal than a flaky one. The flake at least says something is wrong; a stable pass says it is covered.

(No Go toolchain on this box, so I could not run your example. The probability figures are arithmetic on your counts, not my own runs.)