example/orderstatus: the grace-period test can hang closing readAll's franz-go client, spinning so the synctest clock never advances

[Zaba505]

What happens

TestInit_cuts_short_a_retried_record_still_waiting_when_the_grace_period_runs_out in example/orderstatus/app sometimes never ends. It hangs in its last step, p.readAll(t, c, statusTopic) (app_test.go#L635), when readAll closes its own franz-go client (app_test.go#L252-L275). It isn't a deadlock: the process spins at over 100% CPU and the synctest bubble's clock never moves.

I found it while triaging #1094. It's a different failure from #1094's, which is an exit 0 at SIGTERM. At 549437f, with Go 1.27.2, franz-go v1.22.2 and kfake v0.0.0-20261018232743-f49d7ddc2cb4, under -race, it hung:

• in 1 of 4 runs of go -C example/orderstatus test -race -count=1 -v -run '^TestInit_cuts_short_a_retried_record_still_waiting_when_the_grace_period_runs_out$' ./app, which ended with panic: test timed out after 10m0s;
• in 1 of 69 runs of the whole ./app package, from a test binary built with -race and run without a timeout. It spun at about 140% CPU for 6 minutes until I sent SIGQUIT.

Both runs hung at the same place. The goroutines in the bubble, from both dumps:

sync.(*WaitGroup).Wait                         kgo.(*Client).close (client.go:1436)
                                               <- (*processor).readAll (app_test.go:275) <- app_test.go:635
chan receive (durable)                         kgo.(*source).killSessionOnClose (source.go:964)
net.(*pipe).write <- tls.(*Conn).closeNotify   kgo.(*brokerCxn).die <- handleResp
net.(*pipe).write <- tls.(*Conn).Write         kfake.(*clientConn).write
select (durable)                               kgo.(*Broker).request <- RetriableRequest <- (*Client).pushMetrics
runnable                                       first dump: kgo.(*metrics).appendTo, compressing metrics for pushMetrics
                                               second dump: kgo.(*brokerCxn).watchCtxCancel <- broker.do, goroutine 413208

In the second dump, the request goroutines under pushMetrics' Broker.request have IDs above 413,000, against about 1,500 for the rest of the test. Something keeps starting goroutines.

Why

This hasn't been triaged; what follows comes from the dumps and from reading the code.

• Two parties write on one net.Pipe at once. franz-go's client closes a connection and sends its close_notify, while kfake writes a response on the same connection. Neither reads, and net.Pipe has no buffer. humustest's docs expect this standoff: crypto/tls's five-second write deadline breaks it, and "inside a synctest bubble that wait takes no time".
• That holds only if the bubble's clock advances, which needs every goroutine in it to be durably blocked. A goroutine was runnable in both dumps. Client.close waits on killSessionOnClose with a one-second timeout, and that timeout never fired either, which is consistent with a clock that never moved.
• What stays runnable looks like pushMetrics, franz-go's KIP-714 client metrics. On Close it sends a terminating push through RetriableRequest, and kfake answers GetTelemetrySubscriptions. The goroutine IDs suggest that request is retried in a loop that never blocks on a timer. I haven't confirmed which loop it is.

Expected

The test ends every time: readAll closes its client and returns. It passes under -race -count without hanging.

References

• example/orderstatus: the grace-period test can send SIGTERM before the retried record is fetched, so the App exits 0 #1094, whose triage found this
• story(example): wire the order status processor's App: settings, secrets as files, mTLS, probes and main #1011 / story(example): wire the order status processor's App: settings, secrets as files, mTLS, probes and main #1066, which added the test and readAll

[Zaba505]

One more data point. Run alone, from the same -race test binary, with nothing else running, the test didn't hang in 200 runs (-test.count=1 -test.timeout=2m, one process per run).

Both hangs in the report happened while other -race test processes ran on the machine at the same time. So load looks like part of the trigger. That's an inference from where the hangs happened, not a reproduction.

[Zaba505]

Triage

Verdict: a reproducible bug in humustest's in-memory network, seen through the order status test. On the Host, crypto/tls's close_notify write waits for its peer to read until a 5s write deadline. franz-go clears that deadline when a write on the same connection finishes at the same moment. Then close_notify waits forever, readAll's Close never returns, and the bubble's clock keeps moving. It is wider than reported: any readAll in the package can hang, and so can any TLS client on the Host that resets a write deadline while it closes. #1121 is filed to fix it.

Is this a misuse of humus?

No. The test is humus's own: the order status example's App test, which #1066 added for #1011. It dials kfake through humustest's Host inside a synctest bubble, as humustest's docs ask.

The package owns the behaviour. The connection is humustest's, a net.Pipe from Host.Dial, and humustest's docs promise how its TLS connections close:

A connection on the network is a net.Pipe, which has no buffer. When both ends of a TLS connection close at once, each waits to send its close_notify alert until crypto/tls's five-second write deadline passes. Inside a synctest bubble that wait takes no time; outside one, it is real.

The end user can't defend against it. The close is franz-go's, from Client.Close, and so is the deadline reset, inside writeConn. humustest gives no way to buffer a connection or bound its writes.

The strongest argument for misuse: franz-go writes on a connection while another of its goroutines closes it, and humustest can't answer for a library that clears crypto/tls's deadline. It doesn't hold. On a real socket the same steps are harmless: the 24-byte alert goes into the kernel's buffer and Close returns at once, as the loopback run below shows. humustest's conformance tests exist for "the scenarios that the in-memory network must get right exactly as a real one does". #653 found this divergence, documented it, and left removing it, "buffering the network's connections", to "the network's own story".

Is it a feature request?

No. The hang contradicts the paragraph above. It promises that each end waits "until crypto/tls's five-second write deadline passes", and that "inside a synctest bubble that wait takes no time". Here the deadline never passes, because it is gone. The docs site's testing page promises the same.

It also breaks what #1011's test needs, and what the report expects: a test that ends.

Restoring the promise isn't an API change, and neither is correcting the two paragraphs.

Is it reproducible?

Yes. I ran each test 4 times under -race, each in its own go test process, at 549437f, with Go 1.27.2, franz-go v1.22.2 and kfake v0.0.0-20261018232743-f49d7ddc2cb4. No container is involved. Each test asserts that Close returns.

scenario	what the test controls	Close	runs failed
readAll's close, the reset after close_notify starts	holds the long-poll Fetch's cut-short read until the session-kill Fetch is written, and that write's deadline reset until crypto/tls writes close_notify	hasn't returned after 1m of bubble time	4 of 4
readAll's close, the reset before close_notify	holds the cut-short read until the reset has run	returns after 5s of bubble time	0 of 4
a TLS client on the Host, the reset while close_notify waits	a peer that never reads; the test resets the write deadline once close_notify is being written	hasn't returned after 1m of bubble time	4 of 4
the same, on a loopback socket	the same steps on humus.OSHost()	returns in 0.6ms to 1.1ms	0 of 4
a TLS client on the Host, no reset	a peer that never reads	returns after 5s of bubble time	0 of 4
TestInit_cuts_short_a_retried_record_still_waiting_when_the_grace_period_runs_out, the report's test, as a baseline		returns	0 of 4
TestInit_delays_PostgreSQL_from_a_trusted_scenario, as a baseline		returns	0 of 4

Unforced, it is rare and needs load. None of 1,200 runs of the report's test alone hung, 16 to 40 at a time; 13 failed with #1094's exit 0. One of 240 runs of the whole ./app package's -race test binary hung, 12 at a time. It hung in the readAll of TestInit_delays_PostgreSQL_from_a_trusted_scenario (faults_test.go#L84), not the report's test. Its stuck goroutines are the report's, and the forced runs':

• killSessionOnClose, waiting at source.go:964;
• crypto/tls's closeNotify writing 24 bytes, from brokerCxn.die in handleResp;
• kfake's clientConn.write writing 43 bytes, at client_conn.go:195;
• kfake's clientConn.read, waiting at client_conn.go:142.

readAll's close, the reset after close_notify starts: Close never returns. The test polls as readAll does, so a long-poll Fetch is in flight when it closes the client. It wraps each connection franz-go dials, above and below crypto/tls, and holds two calls so that the close runs in the hang's order. Times are bubble time since the close:

1. Close stops the consumer's session, which cuts short the long-poll Fetch's read: read Fetch v18 [... time_to_read 1s err context canceled].
2. Close sends the Fetch that kills the fetch session, on the same connection: 0s the session-kill Fetch is written on the long-poll Fetch's connection: 43 bytes, err <nil>. kfake reads it, then waits at client_conn.go:142 until the long-poll Fetch's response is written. Nothing on kfake's side reads the pipe any more.
3. The cut-short read makes franz-go close the connection: read from broker canceled, closing connection and killing any other in-flight requests on this connection.
4. crypto/tls sets its deadline and writes close_notify, which nobody reads: 0s the write deadline beneath crypto/tls is set 5s ahead, 0s crypto/tls writes close_notify: 24 bytes.
5. The session-kill Fetch's write returns, and its deferred reset clears that deadline: 0s the write deadline beneath crypto/tls is set to none.
6. The bubble's clock runs on. franz-go pushes client metrics and reaps a connection, and the test's 1m timer fires: 24.25s ... wrote PushTelemetry v0, 54.25s ... wrote PushTelemetry v0, 59s ... reaped connections, 1m0s Close hasn't returned; meanwhile the client wrote: Fetch 1, PushTelemetry 2.
7. Only closing the cluster ends it: close_notify's write returns after 1m0s: io: read/write on closed pipe.

With the reset before step 4, the deadline survives and ends the wait: 5s close_notify's write returns after 5s: write pipe: i/o timeout. Then Close returns.

A TLS client on the Host, the reset while close_notify waits: Close never returns. On loopback it returns at once. There is no franz-go and no kfake. The server finishes its handshake and doesn't read. The client closes, and the test resets the write deadline once crypto/tls writes close_notify.

1. On the Host: the write deadline beneath crypto/tls is set 5s ahead, crypto/tls writes close_notify: 24 bytes, the write deadline beneath crypto/tls is set to none. Then nothing until the test's 1m timer: close_notify's write returns after 1m0s: io: read/write on closed pipe.
2. On loopback, with the same steps: close_notify's write returns after 39.911µs: <nil>, Close returned after 642.726µs.

This corrects the report in three places:

• The bubble's clock moves. In the forced runs, a minute of bubble time passed while Close waited. franz-go pushed metrics at 24s and 54s and reaped a connection at 59s. In the unforced hang's dump, franz-go's metadata loop and reaper, kfake's run loop and another connection's goroutines show no wait of a minute or more: they had woken recently. The CPU goes to the bubble running through time, not to a goroutine that never blocks.
• pushMetrics isn't retrying in a loop. It pushes about once every 30s of bubble time, the interval kfake's subscription sets. It was runnable in the dumps because the clock kept bringing its next push, and its requests, and the other loops', start the new goroutines. It is one of the timers that keep synctest from reporting the deadlock, not the cause.
• killSessionOnClose's 1s timeout does run out. It is the session-kill Fetch's context, but once that Fetch is written, only its response or the connection's death ends the wait. Both are behind the goroutine stuck in close_notify. In the forced runs, killSessionOnClose was still at source.go:964 after a minute.

The hang isn't specific to the report's test. Any of the package's 16 readAll calls can hit it.

Why

Three pieces meet. Each is harmless alone.

• humustest's connections have no buffer. crypto/tls's Close sends close_notify when no Write is in flight, and closeNotify bounds that write with SetWriteDeadline(time.Now().Add(time.Second * 5)). On the Host's net.Pipe, the write waits for the peer to read, so the deadline is all that ends it. On a socket, the alert goes into the kernel's buffer. Reproduced by the Host scenarios.
• kfake stops reading. Its reader takes one request at a time per connection, as Kafka does. Once it has read the session-kill Fetch, it waits for the long-poll Fetch's response to be written before it reads again (client_conn.go#L136-L149). Its writer is blocked writing that response, because the client's reader is the goroutine that is closing the connection. Reproduced: both are among the stuck goroutines.
• franz-go clears the deadline. writeConn ends every write with defer cxn.conn.SetWriteDeadline(time.Time{}). Given a zero time, net.Pipe's set stops the deadline's timer and leaves its channel open, so a write already waiting on it waits forever. Reproduced: step 5.

franz-go's Close makes them meet. It stops the consumer's session, and the source's fetch returns as soon as its context is done, without waiting for its response. So Close goes straight on to killSessionOnClose, while the long-poll Fetch's response reader fails and closes the connection. The session-kill Fetch goes on that connection if franz-go loads it before it dies.

The window that matters is a few lines of writeConn, between the TLS write returning and the deferred reset (broker.go#L1499-L1515). The reset clears the deadline only if crypto/tls sets it inside that window. Load makes a preemption there likely, which is why the report saw it only with other -race tests running. I got the window from franz-go's code and forced it in the tests. I didn't catch it unforced with the wrappers in place.

Once it happens, nothing in the bubble ends it. Client.close waits for killSessionOnClose, whose Fetch waits behind the dying connection's reader. franz-go's metadata loop, reaper and metrics loop, and kfake's cluster, always have a timer pending. So synctest keeps advancing the clock, and never reports the deadlock.

Other ways into the same code, which I reasoned from code and didn't reproduce:

• The App's own shutdown. queue/kafka's Service leaves the group and closes its client. Leaving stops the session in the same way, so an App test on the Host can hang at <-status instead of in readAll. queue/kafka's tests and cmd/orderevents's tests run franz-go over TLS on the Host too.
• Any TLS client on the Host. The Host scenario needs no franz-go, only a peer that isn't reading and a write deadline reset while close_notify waits. Resetting the deadline after a write, as writeConn does, is a common Go pattern.
• Outside a bubble, the wait is just as permanent. The deadline is gone, so real time doesn't end it either.

#1121 is filed to fix it:

• a TLS connection on the Host finishes closing when its write deadline is reset while close_notify waits, as it does on loopback;
• readAll closes its client when franz-go's session-kill Fetch resets that deadline;
• the fix doesn't rely on crypto/tls's 5s deadline surviving;
• the triage's tests join humustest's conformance tests and app_test.go;
• humustest's TLS paragraph and the testing page say what the Host does.

[Zaba505]

Fixed by #1123 (story #1121), merged as 418776f.

The Host's network no longer uses net.Pipe. Each connection is now an in-memory pipe that buffers up to 256 KiB in each direction, as a real socket does. So crypto/tls's close_notify write no longer waits on a peer that isn't reading. franz-go's SetWriteDeadline(time.Time{}) clearing the 5s deadline has nothing left to hold open, whichever order the two run in.

The triage's reproductions are now tests. The Host scenarios joined humustest's conformance tests, on the Host and, under -tags conformance, on loopback. The readAll scenarios joined example/orderstatus/app/app_test.go. They fail on the commit before the fix and pass after it. The TLS paragraphs of humustest's package doc and of the "Testing a humus App" page now describe the buffered connection.