Skip to content

Fix two ways a grpctunnel goroutine could outlive its test and panic the package - #167

Merged
shawnburke merged 2 commits into
mainfrom
shawn/grpctunnel-flake
Oct 14, 2026
Merged

shawnburke merged 2 commits into
mainfrom
shawn/grpctunnel-flake

Conversation

@shawnburke

Copy link
Copy Markdown
Collaborator

Symptom

go test -race ./server/grpctunnel/ failed intermittently, about once in twenty runs when other packages ran alongside it, with the package finishing faster than a passing run. Reproduced on clean main with the full log captured:

panic: Log in goroutine after TestCall_ServerCancelAbortsBackend has completed:
  ERROR  grpc-tunnel  Call execution failed  {"callId": "c1", ..., "error": "context canceled"}
    call_handler.go:235

A goroutine logging through zaptest after its test has returned is a panic, and a panic ends the package run early.

Root cause (commit 1)

handleCallFrame removed a call from the call table as soon as the server's Cancel frame arrived, while the call goroutine was still unwinding the backend and had its error and completion log lines left to write. The table is what the heartbeat check and the test barrier in newTestCallTable use to mean "a call goroutine is still running", so the barrier saw an empty table, the test returned, and the goroutine's log landed on a finished test.

The cancel path now cancels and closes the body but leaves removal to the goroutine's own defer, as every other path already did. TestCall_ServerCancelKeepsCallInTableUntilGoroutineExits pins the invariant and fails deterministically against the old code.

TestCall_ServerCancelAbortsBackend × 400 under -race before after
panics 1 0

Same class, found while looking (commit 2)

Start ran startAsync on a goroutine outside the wait group, so Close could return with registration, worker startup and the "gRPC tunnel started" log line still to happen. Looping Start and Close under -race hit it within the first couple of iterations. startAsync is now counted in the wait group; its registration loop and the loops it launches already exit on the parent context, so a Close during startup still returns promptly. TestStartThenClose_WaitsForStartup covers it.

Verification

  • make -C agent test and make -C agent test-race pass.
  • Five further runs of the four-package -race invocation that originally failed: grpctunnel ok every time.
  • Not changed here: grpctunnel is still not in RACE_CLEAN_PKGS. It has been clean across every race run on this branch, so promoting it is a reasonable follow-up once this has soaked.

🤖 Generated with Claude Code

shawnburke and others added 2 commits October 15, 2026 08:13
The grpctunnel package failed intermittently under the race detector
with "panic: Log in goroutine after TestCall_ServerCancelAbortsBackend
has completed", on the "Call execution failed" line in runCall.

handleCallFrame removed a call from the table as soon as the server's
Cancel frame arrived, while the call goroutine was still unwinding the
backend and had its error and completion log lines left to write. The
table is what the heartbeat check and the test barrier in
newTestCallTable use to mean "a call goroutine is still running", so
the barrier saw an empty table, the test returned, and the goroutine
logged through a finished test's logger. A panic ends the package run,
which is why the failing run was shorter than a passing one.

The cancel path now cancels and closes the body but leaves removal to
the goroutine's own defer, as every other path already did. A Data
frame for a cancelled call that has not yet left the table now fails
its pipe write at once instead of being dropped as unknown, with the
same debug line either way.

TestCall_ServerCancelKeepsCallInTableUntilGoroutineExits pins the
invariant and fails deterministically against the old code. Running
TestCall_ServerCancelAbortsBackend 400 times under -race panicked once
before the change and is clean after it.

Co-Authored-By: Claude Fable 5.1 <noreply@anthropic.com>
Start ran startAsync on a goroutine outside the wait group. A Close
that raced it returned with registration, worker startup and the
"gRPC tunnel started" line still to happen: workers were added to the
wait group after Wait had returned, and the log line landed after the
caller had torn the client down. Under the test logger that is the
same "Log in goroutine after test has completed" panic as the
cancelled-call case, and startAsync showed up as the other goroutine
in that position when Start and Close were looped under -race.

startAsync is now counted in the wait group, so Close waits for it.
Its registration loop already aborts on the parent context, and the
loops it launches exit on the same context, so a Close during startup
still returns promptly. TestStartThenClose_WaitsForStartup loops
Start and Close fifty times and fails under -race against the old
code on the first iteration or two.

Co-Authored-By: Claude Fable 5.1 <noreply@anthropic.com>
@shawnburke
shawnburke requested a review from keithfz October 14, 2026 21:19
@shawnburke
shawnburke merged commit 5ef450f into main Oct 14, 2026
20 checks passed
@shawnburke
shawnburke deleted the shawn/grpctunnel-flake branch October 14, 2026 22:30
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