example/orderstatus: the grace-period test can send SIGTERM before the retried record is fetched, so the App exits 0

[Zaba505]

What happens

TestInit_cuts_short_a_retried_record_still_waiting_when_the_grace_period_runs_out in example/orderstatus/app fails now and then. The App was stopped by SIGTERM while the test expected a retried record to be waiting out its 5m delay. The App exited 0 when it should have exited 1 with a *humus.GracePeriodError:

--- FAIL: TestInit_cuts_short_a_retried_record_still_waiting_when_the_grace_period_runs_out (0.08s)
    app_test.go:623:
        	Error Trace:	/home/runner/work/humus/humus/example/orderstatus/app/app_test.go:623
        	Error:      	Not equal:
        	            	expected: 1
        	            	actual  : 0
        	Test:       	TestInit_cuts_short_a_retried_record_still_waiting_when_the_grace_period_runs_out
        	Messages:   	cause: terminated signal received

It failed in both "Test (example/orderstatus)" and "Order status walkthrough (testcontainers)" in the merge-group run 39228587681 (go1.27.2, linux/amd64), and that run took #1079 out of the merge queue.

#1079 doesn't touch example/orderstatus/app. The test passed on #1079's own CI, and on a re-queue the same change merged.

It hasn't failed this way locally on main (369613f) in about 1,800 runs, at -cpu=1, 2 and 4:

go -C example/orderstatus test -race -count=500 -cpu=4 -run '^TestInit_cuts_short_a_retried_record_still_waiting_when_the_grace_period_runs_out$' ./app

Why

This hasn't been triaged; the explanation below comes from reading the code.

• The test's only sign that the App is ready is the readiness probe (app_test.go#L616-L621). After it, the test sends SIGTERM and expects the retried record to be in flight.
• Readiness is the kafka Service's Joined monitor (app.go#L122). It turns true when partitions are assigned (service.go#L562-L563), which happens before any record is fetched.
• If the SIGTERM lands between the assignment and the retried record reaching the projector, nothing is in flight. Shutdown then stops polling and leaves the group within the grace period, and the App exits 0.

Expected

The test sends SIGTERM only once the retried record is waiting out its delay, and passes every time under -race -count at any -cpu.

References

• 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
• story(example): produce an order's events by hand with a small CLI #1014 / story(example): produce an order's events by hand with a small CLI #1079, the PR whose merge group hit it

[Zaba505]

Triage

Verdict: a reproducible bug in the test, not in the App or in queue/kafka. The test sends SIGTERM once readiness is 200 and the bubble is idle. Neither means the retried record has reached the projector. When SIGTERM lands first, the App exits 0, as queue/kafka's docs promise. #1099 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, added by #1066 for #1011. No end user owns it.

The App does what the docs promise in both orders:

• Readiness is health.Readiness(consumer.Joined()) (app.go#L122). Joined is "unhealthy until franz-go first hands the member an assignment". It promises a join, not a fetch.
• On SIGTERM, the Service "stops polling, lets each partition's record in flight finish, commits, leaves the group and returns". With no record in flight, that ends well inside 20s, and the App exits 0.

Is it a feature request?

No. #1011's acceptance criteria ask for this test: "a retried record still waiting at SIGTERM is cut short when the grace period runs out. The App exits 1 with a *humus.GracePeriodError, and a second App processes the record." The test checks that only when the record is waiting at SIGTERM, and it doesn't make sure it is.

A fix changes the test, not the API. queue/kafka, the projector and the App behave as documented.

Is it reproducible?

Yes. I ran each test 4 times under -race, at 549437f, with Go 1.27.2, franz-go v1.22.2 and kfake v0.0.0-20261018232743-f49d7ddc2cb4, all in a synctest bubble on humustest's Host, as the test runs. The App code and the test are unchanged since 369613f, the commit the report links.

scenario	what the test controls	App's exit	runs failed
SIGTERM after readiness, before the first Fetch	the cluster holds the App's first Fetch until after SIGTERM	0, terminated signal received	4 of 4
the first Fetch fails once	the cluster closes the first Fetch's connection; the steps are app_test.go's	0, terminated signal received	4 of 4
SIGTERM after the first Fetch	the cluster holds the first Fetch, then answers it before SIGTERM	1, *humus.GracePeriodError of 20s	0 of 4
app_test.go's steps, nothing controlled	counts the Fetches that reach the cluster	1, *humus.GracePeriodError of 20s	0 of 4
the existing test, as a baseline		1, *humus.GracePeriodError of 20s	1 of 4, a hang (#1098)

Each failing test asserts what app_test.go asserts, and fails with the CI's message: expected: 1, actual: 0, cause: terminated signal received.

SIGTERM before the first Fetch: the App exits 0. The franz-go logs, captured with humustest's telemetry, in order:

1. entering OnPartitionsAssigned with=orders.events[0], orders.retry[0], then partitions assigned … orders.retry. Joined turns healthy here.
2. fetching offsets, read OffsetFetch, read ListOffsets, then wrote Fetch v18. The cluster holds that Fetch.
3. The readiness probe returns 200. The test sends SIGTERM.
4. shutting down, read Fetch v18 … err=context canceled, partitions revoked, leaving group, stopped.

order-1 has no status and nothing is committed on orders.retry. That's right for a record that never reached the projector. The App exits 0.

The first Fetch fails once: the App exits 0, with the test's own steps. The cluster closes the connection of the App's first Fetch, and touches nothing else:

1. wrote Fetch v18, then read Fetch v18 … err=EOF and read from broker errored, killing connection.
2. franz-go backs off on a timer before it fetches again.
3. synctest.Wait() returns, the probe returns 200 and the test sends SIGTERM. One Fetch has reached the cluster, and no record has.
4. shutting down. The App exits 0.

Without control, the first Fetch wins. In the uncontrolled runs, 2 Fetches had reached the cluster by the time synctest.Wait() returned. The log shows read Fetch v18 … bytes_read=327 and updated uncommitted … orders.retry[0{0=>1 r1 e0}] before shutting down. That is why the report's 1,800 local runs passed. I also ran the whole package 69 times, as CI does, and this test never exited 0.

A second failure, not this one: a hang. One baseline run and one of the 69 package runs never ended. The test spun in its last readAll, closing its own franz-go client, and the bubble's clock never advanced. That is a different bug from this report's exit 0, and #1098 reports it.

The report says the window is between the assignment and the record reaching the projector. That's right. What makes the test pass is that the window usually closes before synctest.Wait() returns, not before the readiness probe.

Why

The test's only sync point before SIGTERM is <-p.h.Listening(probesAddr), synctest.Wait() and a readiness probe.

• Readiness is reached before the record is fetched. franz-go calls OnPartitionsAssigned before it fetches offsets. The Service's assigned turns Joined healthy there. The OffsetFetch, the ListOffsets and the Fetch all come after. Reproduced: the first scenario's probe returns 200 with the Fetch held.
• synctest.Wait() doesn't wait for timers. It returns once every goroutine in the bubble is durably blocked, and a goroutine waiting on a timer is. When nothing on the path to the first Fetch waits on a timer, the record is in the projector's 5m wait by then. When something does, synctest.Wait() returns first. A failed Fetch is one such wait: franz-go's source backs off on a timer before it fetches again. Reproduced by the second scenario. A failed offset load waits a second before it reloads; I got that from franz-go's code and didn't reproduce it.
• What took that path in CI, I didn't find. Both failing jobs in run 39228587681 ran the whole module under -race, with -cover in one and -tags testcontainers in the other. Neither run of mine hit it. That part is reasoned from code: any timer on the path from the assignment to the record reaching the projector produces exactly the CI failure.

queue/kafka's own grace-period test, TestService_grace_period_cuts_the_record_in_flight_short, doesn't depend on this. It waits until its Processor has the record before it sends SIGTERM.

#1099 is filed to fix it:

• the test sends SIGTERM only once the retried record is waiting out its delay, whatever franz-go waits on before its first Fetch;
• the triage's reproductions, merged into app_test.go, pass 4 runs out of 4 with the fix;
• after the fix merges, this discussion gets a comment linking it, and is closed as Resolved.

[Zaba505]

Fixed in #1122, merged as 19b0dd7.

TestInit_cuts_short_a_retried_record_still_waiting_when_the_grace_period_runs_out no longer sends SIGTERM once readiness is 200. A new helper, signalWhileWaiting, waits until the Kafka Service has counted the retried record as consumed. The Service does that just before it hands the record to the projector. The helper then calls synctest.Wait() and sends SIGTERM only while the record is waiting out its 5m delay.

The triage's reproductions are now tests in app_test.go: the first Fetch held until after readiness, and the first Fetch failing once. A third test covers the first offset load failing once. All three failed 4 of 4 with the old timing. With the fix, -count=500 passed all 2000 runs under -race. The App and queue/kafka are unchanged. The hang in the test's last readAll is still tracked separately in #1098.