Three flaky tests, and what they were hiding

Between 29 September and 1 October, four pull requests fixed nine tests in tuios that failed now and then on CI and passed on a rerun: #256, #296, #315 and #316. Two of the nine were bugs in the product, and the work turned up a third. Those tests were right to fail.

The easy fix for a flaky test is to raise the timeout. It is one line, the build goes green, and the test now checks a little less than it did. None of the nine fixes did that. Each one found the event the test was really waiting for and waited for that instead. #256 put it in one line: "This is a condition wait. No timeout changed."

This post is about three of the nine.

A hook that waited on itself

TestAStateChangeAfterAnAttachReachesTheAttachingClientOnce checks that a client that attaches to a session gets a state change made just after the attach, and gets it once. CI failed it three times, on three unrelated pull requests, with this pair:

attach_state_race_test.go:199: a state pushed just after this client attached never reached it
attach_state_race_test.go:166: the daemon never applied the push

The test attaches a first client, then installs a hook that runs when a client gets its attach reply. The hook pushes a state change and waits for the daemon to apply it. Then a second client attaches and fires the hook.

The test installed the hook as soon as the first client read its own attach reply. But the daemon's attach handler keeps running after it sends the reply. On a slow machine the first handler reached the hook itself. The hook then ran on the first client's connection goroutine. Its push queued behind the hook on that same goroutine, and the hook waited 5 seconds for a push that could not run until the hook returned. The second client's own 5 second wait ran out at the same moment. Two failures, one cause.

I could not make it fail on my machine. 400 runs under -race, with GOMAXPROCS=2 and 200 of them beside a full package run, gave no failures. The race needs a scheduler as slow as a CI runner.

So I made the scheduler slow where it mattered. A 50 ms sleep before the hook in handleAttach made the old test fail 5 runs of 5, with the same two messages CI printed. That is the negative control: the test fails for the reason I think it fails, on demand.

The fix asks the daemon a question on the first connection and waits for the answer:

func waitForHandlerIdle(t *testing.T, c *TUIClient) {
	t.Helper()
	msg, err := NewMessage(MsgList, nil)
	if err != nil {
		t.Fatalf("list message: %v", err)
	}
	if err := c.send(msg); err != nil {
		t.Fatalf("send list: %v", err)
	}
	for {
		resp, err := c.recv()
		if err != nil {
			t.Fatalf("wait for the list reply: %v", err)
		}
		if resp.Type == MsgSessionList {
			return
		}
	}
}

The daemon serves one connection in order. When the list reply comes back, the attach handler before it has returned. The question is a barrier. With the same 50 ms sleep in place, the new test passed 20 runs of 20.

This bug was in the test. The product delivered the push as soon as the hook let the goroutine go.

A broken pipe that should have been an error

tuios answers herdr's socket protocol, one JSON request per connection, so tools built for herdr work in a tuios pane. One process may hold at most 64 connections at once. The 65th gets an error, rate_limited, with "Close some and try again".

TestHerdrConnectionsPerCallerAreCapped opened 64 connections, slept 300 ms, opened one more and expected rate_limited. On CI it sometimes got a broken pipe instead.

There were two bugs here, one on each side.

The test's bug was the sleep. Its 64 held connections were idle, and the daemon drops an idle connection after its 2 second I/O timeout. On a slow runner, some of the 64 were gone before the 65th arrived, and the count was never full. The new test holds 64 waits for output that never prints, so each connection stays busy. It then reads the daemon's own counter until it says 64, and opens a new wait for any connection the daemon dropped:

deadline := time.Now().Add(20 * time.Second)
for count() < herdrConnsPerCaller {
	if time.Now().After(deadline) {
		t.Fatalf("the daemon counted %d of %d connections", count(), herdrConnsPerCaller)
	}
	for i, c := range held {
		if !alive(c) {
			_ = c.Close()
			held[i] = hold()
		}
	}
	time.Sleep(10 * time.Millisecond)
}

The deadline here is 20 seconds, where the old test slept a fixed 300 ms. A passing run never waits for the deadline. It waits until the count is right.

The product's bug was in the refusal. The daemon wrote rate_limited and closed the connection before it read the client's request. On a unix socket, closing with unread data resets the connection. And an answer sent before the client writes races the client's write. Either way, the client saw a broken pipe or a reset. The fix in serveHerdr carries the reason in a comment:

if !d.herdrConns.take(cs.peerPID, herdrConnsPerCaller) {
	// Read the request before the refusal. Closing a unix socket with
	// the request still unread resets it, and an answer sent before the
	// client writes races that write: either way the client saw a
	// broken pipe instead of rate_limited.
	writeHerdr(conn, herdrRequestID(conn), nil, "rate_limited", "this process has too many connections open on the herdr socket. Close some and try again")
	return
}

A real client hits this too. A tool that opened too many connections could not tell "slow down" from "the daemon crashed", so it had no reason to back off and try again. The PR's stress run: the base failed 1 run in 300 with the CI broken pipe, and the fix passed 600 of 600, and 100 of 100 under -race.

The same PR found another bug in the product. vt.grid.String wrote a shared blank row while it held only the read lock on the pane. Two waits on one pane raced on that row, and the race detector flagged TestWaitsEndWithTheirClient in most -race runs. That fix is 194af0cf.

The shell echoed the command twice

TestCapturePaneReportsHistoryAndRevision types a command into a shell and waits for it to finish:

seq 1 60; echo DONE-MARK

The test waited until the pane's text held DONE-MARK twice, once in the command line and once in the output. Then it captured the pane and checked that at least 30 of the 60 rows had scrolled into history. Under -race it failed 6 runs of 50, with a history of 0 rows.

The marker was on the screen twice before seq had run at all.

The text reached the pane's terminal before the shell had started its line editor. The terminal still had echo on, so it echoed the text as it arrived. Then the shell's line editor started, drew its prompt, and drew the pending input again after it. Two copies of the command line, and so two copies of DONE-MARK, with no output yet. -race slows the shell's start enough to make that common.

The fix makes the marker impossible to echo:

-"seq 1 60; echo DONE-MARK\n"
+"seq 1 60; echo DONE''-MARK\n"

The shell joins DONE''-MARK into DONE-MARK when it runs echo. The command line holds DONE''-MARK, which does not match. The test now waits for \nDONE-MARK\n, a line that only the output can produce. After the fix it passed 50 of 50 runs under -race and 200 of 200 without.

The product was fine here. As the PR says: "The product reports history correctly." The test was counting the wrong thing, and only a slow start showed it.

Three of the other six

The rest were smaller. Three of them are worth a line.

• A capture claimed its file name by creating an empty file, and filled it later with os.WriteFile. A reader in between saw an empty screenshot. That is a product bug: a file manager or a file watcher would see it too. Now the claim is a hidden file beside the name, and Save writes a hidden temporary file and renames it into place (3f7f2e88). The e2e test had failed 1 run in 360.
• TestEveryVerbExampleReachesItsHandler used one 750 ms budget for two jobs: to bound a hang, and as the time to wait on a verb that blocks on purpose. Under load an ordinary verb went over it. Verbs that answer now get one minute, which only bounds a hang. The new comment: "This test proves a verb reaches its handler, not how fast the handler is."
• A snooze test raced the timer that wakes overdue items. The fix calls wakeDue directly, which does the timer's work at once.

Breaking the fix on purpose

A test that claims to cover a race has to fail when the race comes back. For a race that a laptop will not reproduce, I put a delay where the race needs one, and watch the old test fail. Then I keep the delay and watch the new test pass. #256 used a 50 ms delay. #296 used a 1 ms delay after the snooze loads and a 50 ms delay in the SSH reader.

This is the rule e2e/tui/NEGATIVE_CONTROLS.md opens with: "A regression test that has never been observed to fail on broken code is not evidence." The same file records what the end-to-end suite cannot catch. It runs tuios as a child process, so -race on the test binary instruments only the harness. The grid race above was found by a unit test under -race, which is where a memory race has to be caught.

Earlier posts covered the other half of this: tests that could not fail, and a flake that was a real bug in how -w finds a window.