Skip to content

The no-quorum timer test races its own timeout budget and flakes in CI #56

Description

@HectorIFC

Context

test/malachi/cluster/replication_server_test.exs:135, "a committed batch cancels its no-quorum timer (no stale timeout messages)", fails intermittently in CI on a timing budget rather than on the property it tests:

1) test pipelined fan-out a committed batch cancels its no-quorum timer (no stale timeout messages)
   test/malachi/cluster/replication_server_test.exs:135
   match (=) failed
   code:  assert {:ok, 0} = ReplicationServer.replicate(primary, @segment, [primary, follower], 0, records(["a"]))
   left:  {:ok, 0}
   right: {:error, :no_quorum}

Seen on https://github.com/HectorIFC/malachi/actions/runs/33117271941, one failure out of 1201 tests. It is a flake, not a regression, and the evidence is that the same commit f9c642a passed and failed at the same time: the push run (33117270102) and the pull_request run (33117271941) were created one second apart on that identical SHA, and only the second one failed. In the last 40 CI runs it has failed once.

It surfaced on the ra 3.1.10 bump (#6), which is a coincidence worth writing down so nobody re-diagnoses it later: lib/malachi/cluster/replication_server.ex makes zero :ra. calls, so the failing path does not touch the bumped library at all. The full suite including the multinode tag (1222 tests) and the 3-node chaos certification both pass under 3.1.10.

Why it flakes

follow_timeout is doing two jobs at once in this test, and they pull in opposite directions.

park_and_push/8 arms the no-quorum timer at park time with exactly that value (lib/malachi/cluster/replication_server.ex:705):

timer = Process.send_after(self(), {:replicate_timeout, segment_id, ref}, state.follow_timeout)

and a normal resolution cancels it (:749). So follow_timeout is simultaneously how long the commit has to reach quorum and how soon a stale message would arrive if the cancel were missing. The test needs it short, so that the 300ms sleep is long enough to catch a stale timer, and it sets 150ms (:140). The commit then has to beat its own timer within those same 150ms.

On a two-core runner with two concurrent CI runs, in a file that is async: true, 150ms is not the comfortable margin it looks like. The commit loses the race, {:error, :no_quorum} comes back, and the assertion fails on the setup line rather than on the stale-message check the test is actually about.

Not reproducible locally on an 8-core machine: 25 runs idle and 12 runs under synthetic load (16 busy loops) all passed. The reproduction needs the runner's core count, not just its load.

Fix

Widen the budget so a healthy commit cannot lose the race, keeping the 1.5x ratio between the timer and the sleep that makes a stale message detectable:

# test/malachi/cluster/replication_server_test.exs:140 and :151
primary = start_broker(follow_timeout: 1000)
...
Process.sleep(1500)

A local two-replica commit takes on the order of a millisecond, so 1000ms removes the margin problem rather than shrinking it. The cost is about 1.2 seconds of extra sleeping in an async: true file, which does not hold up the rest of the suite.

Two alternatives were considered and rejected. Retrying the replicate when it comes back {:error, :no_quorum} keeps the timings short but can mask a genuine regression that makes commits slow, which is the opposite of what this test exists for. Asserting on the server's internal timer state instead of on the traced message would be deterministic, but it trades an observable property (no stale message ever arrives) for a structural one, and couples the test to the state shape.

This is pre-existing debt rather than fallout from any current work, so it belongs in its own commit.

Metadata

Metadata

Assignees

Labels

bugSomething isn't workingtests

Projects

Status
Backlog

Relationships

None yet

Development

No branches or pull requests

Issue actions