The race detector saw my requests in order

· 10 min read
Contents

I run a small Go proxy on my LAN, in front of the GPU boxes that serve my local LLMs. Clients can ask it for a model by a short alias, and it looks the alias up in a map to decide where the request goes. That map can now be replaced while the proxy is running, by a config reload, so every read of it has to take a lock. A read that skips the lock is the kind of bug that does nothing at all until one request lands in the middle of a reload, and I have no interest in meeting it there.

To prove the lock was there, I took it away, one place at a time, and waited for Go's race detector to object. The detector (go test -race) is the tool I argue with least. It doesn't sample, it doesn't guess, and when it prints WARNING: DATA RACE it hands over both stack traces. It reports what happens at runtime, and only that. I wrote a test that ran an unlocked read twenty times per run next to a writer, removed the lock, and the detector found nothing. I would love to report a bug in the race detector here. I can't. By its definition there was no race in that run, because my test had put the accesses in order, and in doing so handed the bug a perfectly good alibi.

Why the proxy needed the lock#

The program is the same Go LAN proxy as in the post about a mutant that switched a real GPU. It was getting a hot config reload: on SIGHUP, the signal that triggers the reload, it replaces its alias map and a naming setting (which model names /v1/models lists) while requests are reading them. Both moved behind a sync.RWMutex, and readers go through a naming() helper that takes the read lock.

Then the proof, under -race: one goroutine calls SetNaming, the setter for the naming setting, 50 times while the test sends requests. The first version, in shape (arguments elided):

go func() { for i := range 50 { r.p.SetNaming(...) } }()
for range 20 {
	r.get(t, "/v1/models")                                  // reads naming() under the RLock
	r.post(t, "/v1/chat/completions", `{"model":"coder"}`) // route() reads the alias map
}

A GET reads the naming under the lock, and a POST for the alias coder makes route() look the alias up in the map.

Which mutants the test killed#

I check fixes like this one with hand-written mutants: copy the module, undo one condition, run the copy's tests, and see whether any test notices the damage. Here each mutant took the lock out of one place.

  • No lock inside SetNaming: KILLED, DATA RACE.
  • No lock inside naming(): KILLED, DATA RACE.
  • route() reads p.Aliases directly, without the lock: SURVIVED.

Two out of three looks like a working test until you ask which read the third mutant touches. It is the alias lookup in route(), the one a chat completion's model name goes through. The survivor is the lookup that every chat request makes, because of course it is.

How one connection ordered the requests#

The test client reused one keep-alive connection. Go's net/http server runs one goroutine per connection, and that goroutine reads a request, calls the handler, then reads the next request on the same connection. So the GET and the POST of each iteration ran on the same server goroutine, one after the other.

The race detector doesn't watch the clock; it tracks which memory accesses are ordered by synchronization. The Go memory model says that a writer's Unlock is synchronized before a later RLock returns. So the GET's RLock paired with the writer's Unlock, which gave the detector a happens-before edge from the write to the GET. The POST came after the GET on the same goroutine, so its unlocked read of the map was ordered after that write as well, and nothing got reported.

That edge covers only the writes made before the GET took its lock. A write that came later would still race with the POST, and the detector would say so. For the edge to hide everything, the writer has to be done by then. Nothing recorded the timing in the proxy's test; the demo further down shows how quickly 50 writes finish next to the first request.

The detector reports pairs of accesses that no synchronization orders. My test had ordered them itself, through a lock the mutant never touched, on the request just before. That is the alibi: a locked GET standing directly in front of the unlocked read, vouching for the timeline, and my own test had placed it there, twenty times per run.

The fix: no locked request in front of the read#

The fix is to stop giving the POST a locked predecessor on its goroutine. GETs and POSTs go out from separate goroutines in parallel, so they mostly run on separate connections:

var wg sync.WaitGroup
for range 10 {
	wg.Add(2)
	go func() { defer wg.Done(); r.get(t, "/v1/models") }()
	go func() { defer wg.Done(); r.post(t, "/v1/chat/completions", `{"model":"coder"}`) }()
}
wg.Wait()

Against this test the same mutant was KILLED by DATA RACE.

The lesson was cheap to apply twice. A later review found a second read site that skipped the lock, where the proxy resolves a stream id's alias. The first test never reached that code at all, so no arrangement of its requests could have caught it. Missing a bug because your test lines things up is at least a subtle mistake. Missing one because your test never goes there is the other kind. It got its own concurrent test, and that test killed the mutant for it.

Rebuilding it outside the proxy#

I wanted to see the mechanism without the rest of the proxy around it, partly because I had just been wrong about my own test and no longer extended myself much credit. So I wrote a small demo: an http.Handler with an RWMutex, a locked GET, a POST whose map read skips the lock (the mutant, built in), and a writer goroutine with 50 SetNaming calls. Five test shapes, 20 runs each with go test -race, counting the runs that printed a race report:

Test shapeRace reported
GET then POST, 20 times, one keep-alive connection0 of 20
10 GET goroutines and 10 POST goroutines in parallel18 of 20
GET then POST, 20 times, keep-alives disabled0 of 20
POST only, 20 times, one keep-alive connection20 of 20
GET then POST, 20 times, writer still writing throughout20 of 20

The parallel version from the fix shows up as it should:

==================
WARNING: DATA RACE
Read at 0x00c0000d3168 by goroutine 61:
  racedemo.(*proxy).ServeHTTP()
      racedemo/proxy.go:33 +0xf3
  net/http.serverHandler.ServeHTTP()
      net/http/server.go:3311 +0x2a1
  net/http.(*conn).serve()
      net/http/server.go:2073 +0xda4
  net/http.(*Server).Serve.gowrap3()
      net/http/server.go:3464 +0x46

Previous write at 0x00c0000d3168 by goroutine 11:
  racedemo.(*proxy).SetNaming()
      racedemo/proxy.go:18 +0xf3
  racedemo.TestParallel.func1()

And the sequential one passes, every time, with the lock still missing:

=== RUN   TestSequential
--- PASS: TestSequential (0.01s)
PASS
ok  	racedemo	1.027s

A hundredth of a second, with the lock gone. Quick, green and wrong, all three at once, which is my least favourite way to be reassured.

Two rows surprised me. The third row: turning keep-alives off, so every request gets its own connection and its own server goroutine, did not bring the race back. Something between one request and the next still chained them in order, and I didn't go looking for what. The second surprise is the parallel row: 18 of 20, not 20. In two runs it reported nothing, and I didn't dig into what ordered the accesses those times either. A test that catches the bug nine times in ten is a working test with a hobby. Leaving two unexplained rows in a five-row table took more restraint than anything else in this demo; net/http is a large place to go looking for a happens-before edge, and I have a fair idea how that afternoon would end.

A timing probe in the demo explains the first row. Across five runs the 50-write goroutine finished after 91 to 272 µs, and the first request reached its handler after 526 to 928 µs. The writes are over before the first request arrives: the concurrency I had so carefully staged had finished and gone home before the audience sat down. From then on, the first locked read is synchronized with the last write, and everything ordered after that read, on that connection or not, is safe in the detector's eyes, lock or no lock.

The last two rows show the two ways out, and either one is enough. With no locked GET in front of it, the unlocked read is caught every time. With a writer that keeps writing for the whole loop, it is caught every time too, sequential requests and all. The parallel fix works by the first route: in the demo's race reports the writer has already finished, and what the POSTs lack is a locked request ordered in front of them.

So the one connection in the proxy's test is an edge I can name, and the demo shows that a shared connection isn't the only thing that can line requests up. In the demo, what hid the race was a locked read sequenced before the unlocked one, after the writer had finished. In the proxy's test the first half is certain and the second was never measured. A test that wants the detector to see a reader has to break at least one of them: no locked request in front of the reader, or writes still going while it reads.

Mutate the lock at every read site#

Mutating the lock away only in the setter tells you whether the test can see the writer. Mutating it away at each read site tells you whether the test can see that reader, and that is a separate question with a separate answer. Here the setter mutant and the helper mutant both died. The alias lookup in route() sailed through until the test stopped lining its requests up, and the first test never reached the stream-id lookup at all, until it got a test of its own.

Two read sites, two concurrent tests, and now each of the lock's readers dies under -race when its lock goes. The detector applied one rule the whole way through, and I grant it that through slightly clenched teeth: two accesses with nothing ordering them get a report, and a locked request in front of the read counts as ordering. Before I believe a quiet -race again, I'll list what the test sends ahead of each read. For this test the list had one entry, GET /v1/models, twenty times. A guest list one line long, and that one line was the alibi.

Filed under: go, testing, concurrency, local-llm

Sources#