Skip to content

fix(test): stop the serve tests racing on the shared log buffer - #1098

Merged
kgaughan merged 1 commit into
goss-org:masterfrom
vsolano9:fix/flaky-serve-test-log-buffer-race
Aug 6, 2026
Merged

fix(test): stop the serve tests racing on the shared log buffer#1098
kgaughan merged 1 commit into
goss-org:masterfrom
vsolano9:fix/flaky-serve-test-log-buffer-race

Conversation

@vsolano9

@vsolano9 vsolano9 commented Aug 6, 2026

Copy link
Copy Markdown
Contributor

make cov fails on master roughly half the time. I hit it on #1097 and went looking for what I'd broken; it turned out to be already there, so here's the fix on its own.

Measured

Same command as the coverage job, go test -race -coverpkg=./... -coverprofile=c.out ./..., on clean master fbc8318:

Branch DATA RACE
master (8 runs) 4
master (12 more runs) 7
this branch (12 runs) 0

Cause

Four serve tests capture log output the same way:

var logOutput bytes.Buffer
log.SetOutput(&logOutput)

log.SetOutput is process-wide, but the buffer is per-test, and three of the four tests are t.Parallel()TestServeWithNoContentNegotiation, TestServeNegotiatingContent, TestServeHandlesConcurrentRequests. Go runs those together after the sequential tests finish, so they share whichever buffer was installed last. One test's request goroutines write into it through log.Printf while another reads it with String().

Every trace is the same shape:

Write at 0x00c0000d4540 by goroutine 474:
  bytes.(*Buffer).grow()
  log.(*Logger).output()
  github.com/goss-org/goss/outputs.logTrace()          traces.go:11
  github.com/goss-org/goss.healthHandler.ServeHTTP()   serve.go:93
  github.com/goss-org/goss.TestServeHandlesConcurrentRequests.func1()

Previous read at 0x00c0000d4540 by goroutine 452:
  bytes.(*Buffer).String()
  github.com/goss-org/goss.TestServeNegotiatingContent.func1()   serve_test.go:182

TestServeHandlesConcurrentRequests fires 16 concurrent requests, so it is usually the writer, but it isn't the culprit — it is doing exactly what it was added in #1092 to do. The shared buffer is the problem.

Fix

A mutex-guarded buffer, syncBuffer, in a new logbuffer_test.go. Test-only, no production code touched. The logger stays global and no test changes what it asserts — only the buffer becomes safe to touch from two goroutines.

What this deliberately does not fix

The routing is still wrong: a parallel test's log lines can land in another test's buffer. That is harmless today because the three parallel tests only t.Logf the buffer — the two tests that actually assert on it, TestServeCacheWithNoContentNegotiation and TestServeCacheNegotiatingContent, are sequential and finish before any parallel test starts.

Fixing it properly means giving each test its own logger, which means changing how outputs and serve get theirs. That is a real change to non-test code and it belongs in its own PR. Happy to do it if you want it.

One thing worth recording: in 24 runs of the full suite under -race, I saw TestServeCacheNegotiatingContent/immediately re-request but different accept header, cache should be warm fail once, asserting the cache was warm when the 100ms window had expired under race instrumentation. It did not reproduce in 12 further runs on either master or this branch, so it looks like a separate load-sensitive flake rather than anything to do with this change. Flagging it rather than quietly leaving it out.

AI assistance

This contribution was prepared with AI assistance. Every number above is from running the stated command locally, Go 1.26.5, macOS arm64.

The serve tests capture log output by pointing the process-wide logger
at a local buffer with log.SetOutput. Four tests do that, and three of
them run with t.Parallel(), so they all run at once against whichever
buffer was installed last: one test's request goroutines write through
log.Printf while another test reads the same buffer with String().

The race detector catches it. make cov (go test -race) fails on master
in 11 of 20 runs here, always with the same pair of stacks -- a
bytes.Buffer grow from outputs.logTrace under
TestServeHandlesConcurrentRequests against a bytes.Buffer String from
TestServeNegotiatingContent or TestServeWithNoContentNegotiation.

Guard the buffer with a mutex. The logger stays global and no test
changes what it asserts; only the buffer becomes safe to touch from two
goroutines. Same 12 runs of the same command are clean afterwards.

Fixing the routing properly -- so a parallel test reads only its own log
lines -- means giving each test its own logger, which is a larger change
to how outputs and serve get their logger. This just stops CI failing.

Signed-off-by: Victor Solano <victor.solanonunez@gmail.com>
@kgaughan
kgaughan merged commit 4a1a0bf into goss-org:master Aug 6, 2026
11 checks passed
vsolano9 added a commit to vsolano9/goss that referenced this pull request Aug 6, 2026
Picks up goss-org#1098 (serve-test log-buffer race fix), which is the cause of the
stale red `coverage` check on this PR's previous head 6a9d2dd.

Signed-off-by: Victor Solano <victor.solanonunez@gmail.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants