humus: a SIGTERM can be reported as a Service returning, when the Service returns as soon as it is cancelled

[Zaba505]

What happens

TestApp_Run_telemetry_a_failed_shutdown_is_joined_into_the_cause fails now and then. The App was stopped by SIGTERM, but the exit Status's cause holds only the telemetry shutdown error, not the signal:

--- FAIL: TestApp_Run_telemetry_a_failed_shutdown_is_joined_into_the_cause (0.00s)
    app_telemetry_test.go:521:
        	Error Trace:	/home/runner/work/humus/humus/app_telemetry_test.go:521
        	Error:      	Target error should be in err chain:
        	            	expected: "context canceled"
        	            	in chain: "shut down telemetry: flush logs: collector unavailable"
        	            		"shut down telemetry: flush logs: collector unavailable"
        	            		"flush logs: collector unavailable"
        	Test:       	TestApp_Run_telemetry_a_failed_shutdown_is_joined_into_the_cause
        	Messages:   	the signal is still in the cause

That run was the Build job of run 39160233524, attempt 1 on #935 (go1.27.2, linux/amd64). It passed on a re-run. The change in #935 was only to kube.

It reproduces locally on main (2f45ce1):

go test -race -count=3000 -cpu=2 -run '^TestApp_Run_telemetry_a_failed_shutdown_is_joined_into_the_cause$' .

It failed once in 3,000 runs at -cpu=2, once in 3,000 at -cpu=4, and never in 5,000 at -cpu=1.

Why

This looks like a race in App.run, not just a flaky test. It hasn't been triaged yet: the explanation below comes from reading the code.

• The test's Service is a fakeService with no serve func. Its Serve waits for its context and returns nil (app_test.go#L48-L54).
• run serves under serveCtx, a child of sigCtx (app.go#L389-L394). SIGTERM cancels sigCtx, and with it serveCtx, so the Service returns at once.
• run then selects between <-sigCtx.Done() and <-served (app.go#L401-L410). If the Service's nil reaches served before run's goroutine is scheduled, both cases are ready and Go picks one at random.
• If it picks served, signalled stays false and run returns 0, nil (app.go#L443-L446). The signal is gone, and only the telemetry error is joined into the cause (app.go#L301-L307).

The same choice affects more than this test:

• The exit Status: an App whose Services return as soon as they're cancelled can exit with no cause after a SIGTERM, instead of context.Canceled.
• A Drain: it can see ErrServiceReturned as its ShutdownCause, instead of the signal (app.go#L415-L419). A Drain that acts on why the App is stopping then takes the wrong branch.
• The lifecycle log: it reports the shutdown as a Service returning on its own.

Expected

When the signal context is done by the time run handles a Service's return, it is a signal shutdown:

• Status.Cause() holds the signal's cause, and any telemetry shutdown error is joined to it;
• the Drain's ShutdownCause is the signal's cause, not ErrServiceReturned.

The test passes every time under -race -count at any -cpu.

References

• story(humus): build telemetry before Init, log through it and shut it down last #671, which added the telemetry shutdown join this test covers
• story(kube): constrain a custom resource's fields with typed rules, kube.Rules and kube.Field #935, the PR whose CI run hit it

[Zaba505]

Triage

Verdict: A reproducible bug in App.run, not only a flaky test. A signal, or a cancel of Run's context, that comes before Run waits in step 8 is lost about half the time when a Service returns on it. The status then has no cause, and the Drain's ShutdownCause wraps ErrServiceReturned, so the lifecycle page's load-balancer Drain lets Shutdown run at once after SIGTERM. That is worse than reported. Once Run waits, the signal always wins. #961 is filed to fix it.

Is this a misuse of humus?

No. The end user owns their Service's Serve, and stopping on Serve's context is what humus asks of a job, a queue consumer or the health Service: "A Service may stop on it, as a job, a queue consumer or a health Service does" (app.go#L51-L54). The package owns what happens next: whether the signal or the Serve result started the shutdown, the status's cause, and what the Drain is told.

The end user can't defend against it. The race is inside run, between steps 7 and 8. A Drain learns the cause only from ShutdownCause, which is what's wrong, and nothing keeps a signal from coming early. The strongest case for misuse is that the reported test signals before the App waits. It doesn't hold: Run listens for signals from step 2, "before the telemetry and Init, so a signal during a slow Builder or a slow Init cancels it" (lifecycle.md). Nothing in the docs makes a signal before step 8 count for less. A pod that gets SIGTERM as it starts takes the same path.

Is it a feature request?

No. It contradicts these promises:

• Run's doc: "The status is 0, with the signal as its cause, after a signal; 0 with no cause when a Service returned nil on its own" (app.go#L255-L258), and the lifecycle page's exit codes: "a signal stopped the App and it shut down in time | the signal" (lifecycle.md#L591).
• ErrServiceReturned "is in a shutdown's cause when a Service's Serve returned before any signal came" (drain.go#L38-L40). Here the signal came first, and the Service returned because of it.
• ShutdownCause: "After a signal, it is the cause the signal gave the Process's NotifyContext. [...] When the context passed to Run was cancelled, it is that context's cause" (drain.go#L46-L51). The lifecycle page's deregisteringDrain relies on it to wait "only after a signal" (lifecycle.md#L343-L360).
• job's doc: "When a run returns nil after a signal, [...] the App exits 0, with the signal as the cause" (job/doc.go#L60-L62).
• Revision 2 of #687: "humus.ShutdownCause(ctx) returns the signal's cause after a signal, or an error wrapping humus.ErrServiceReturned when a Service returned first", and step 10 of #630's revision: "Return 0 with the signal as the cause".

A fix restores these. It changes no exported name, signature, field, default or documented guarantee, so it isn't an API change.

Is it reproducible?

Yes. At 4ddf294, the tip of main, where app.go, drain.go and job are unchanged since 2f45ce1. Go 1.27.0 linux/amd64, bedrock v0.25.0, go.opentelemetry.io/otel/log v1.47.0, every run under -race, no containers.

The reported test fails at the reporter's settings, with the reporter's error. Three other root tests fail the same way:

existing test, -count=3000 per run	-cpu=1	-cpu=2	-cpu=4
TestApp_Run_telemetry_a_failed_shutdown_is_joined_into_the_cause	0 of 4 runs (0 of 12,000)	0 of 4 (0 of 12,000)	4 of 4 (5 of 12,000)
TestApp_Run_SIGTERM_exits_0_with_the_signal_as_its_cause	not run	0 of 4 (0 of 12,000)	1 of 4 (6 of 12,000)
TestApp_Run_interrupt_exits_0	not run	0 of 4 (0 of 12,000)	3 of 4 (7 of 12,000)
TestApp_Run_a_whole_App	not run	1 of 4 (2 of 12,000)	2 of 4 (3 of 12,000)

Their failures read cause = <nil>, want the signal, errors.Is(<nil>, context.Canceled) = false and cause = <nil>, want interrupt signal received. Each of these tests sends its signal as soon as p.Notified fires, which is step 2 of Run, before the telemetry, Init and Serve. TestShutdownCause, which calls synctest.Wait() before it signals, passed in 4 runs out of 4.

To take the timing out, the triage's tests deliver the signal from the App's own logger, as Run logs "serving" in step 7. The logger holds Run there with synctest.Wait() until a Service that stops on Serve's context has returned. Each test runs 20 Apps, each in its own bubble:

scenario	what is checked	runs failed	Apps that lost the signal, per run
SIGTERM	the exit status	4 of 4	14, 10, 14, 12 of 20
SIGTERM, telemetry shutdown fails	the signal joined into the cause	4 of 4	9, 11, 13, 8
SIGTERM, with a Drain	ShutdownCause	4 of 4	10, 8, 10, 11
SIGTERM, deregisteringDrain	Shutdown 3s after SIGTERM	4 of 4	11, 13, 13, 11
Run's context cancelled, with a Drain	ShutdownCause	4 of 4	9, 13, 5, 7
SIGTERM, a job whose run returns nil	the exit status	4 of 4	9, 12, 11, 12
SIGTERM once Run waits	the exit status	0 of 4	0, 0, 0, 0

SIGTERM as the App starts serving: the status loses the signal. One Service, which returns nil once Serve's context is done.

1. Run starts the Serve goroutine and logs "serving" (app.go#L389-L395). The test delivers SIGTERM there. It cancels the signal context and, with it, Serve's, and the Service's nil reaches served.
2. Run's select (app.go#L401-L410) finds both cases ready and picks one.
3. When it picks served, the App exits with code 0, cause <nil>. When it picks the signal, code 0, cause terminated signal received.
4. With a telemetry shutdown that fails, the cause is shut down telemetry: flush logs: collector unavailable, instead of terminated signal received and that error joined. That is the reported failure.

A Drain that waits on a load balancer: Shutdown comes at once after SIGTERM. The lifecycle page's deregisteringDrain, with an API that serves until Shutdown and a Service that stops on Serve's context, as the health Service does. The load balancer reports the target draining 3s after SIGTERM.

1. SIGTERM comes as Run logs "serving", and the second Service's nil reaches served.
2. When the select picks served, the Drain's ShutdownCause is humus: a Service returned before any signal, and deregisteringDrain returns at once: Shutdown 0s after SIGTERM, 0 polls, code 0, cause <nil>. That happened in 11 of 20 Apps in the first run.
3. Otherwise the Drain polls until the target is draining: Shutdown 3s after SIGTERM, 4 polls, code 0, cause terminated signal received.

Cancelling Run's context as the App starts serving does the same: ShutdownCause humus: a Service returned before any signal, code 0, cause <nil>, instead of ShutdownCause the test harness stopped the App, code 0, cause the test harness stopped the App.

This corrects the report in four places:

• The lifecycle log doesn't report a Service returning. It never says why the App stops. Every App in the first scenario logged the same serving, shutting down and stopped, whichever case the select picked.
• Only a signal that comes before Run waits is lost. Once Run waits in step 8, the signal won in 80 Apps out of 80. "An App whose Services return as soon as they're cancelled can exit with no cause after a SIGTERM" holds only for a signal, or a cancel of Run's context, between step 2 and the wait. In a pod, that is a SIGTERM as the App starts, with an Init that returns its Services anyway.
• The exit code doesn't change. It is 0, or 1 with a failed telemetry shutdown, either way. Only the cause changes. bedrock.Main never reads the cause (bedrock's os.go#L99-L104). In production, the loss shows in a Drain's ShutdownCause. In tests and other callers of Run, it shows in the status too.
• It reaches past this test and past SIGTERM. Three other root tests fail the same way (the first table). Cancelling Run's context loses its cause from ShutdownCause, and a job whose run returns nil after a signal exits with no cause.

Why

• Run serves under serveCtx, a child of the signal context (app.go#L389). A signal cancels both. A Service that stops on Serve's context returns at once, and its goroutine sends the result on served (app.go#L393). Reproduced.
• When the signal comes before Run reaches the select, both cases can be ready once it does. The Go spec says: "If one or more of the communications can proceed, a single one that can proceed is chosen via a uniform pseudo-random selection." Reproduced: 5 to 14 of each 20 Apps lost the signal.
• run decides from the case that ran, not from whether the signal context is done. When the select picks served, signalled stays false. The Drain is given serviceReturned(err) (app.go#L415-L419), and run returns 0, nil (app.go#L443-L447), dropping the cause it read at L411. Run then joins the telemetry error into that nil cause, with nothing beside it (app.go#L301-L307). Reproduced.
• Once Run waits in the select, the signal always wins. Cancelling a context closes its Done channel before it cancels its children (context.go#L564-L574), so Serve's context is done only after the signal context's channel is closed. A waiting select is woken by the first case that fires, and only once (runtime/chan.go#L872-L905). I got that from Go's code, and the variation reproduced it: 0 of 80 Apps lost the signal.
• The window opens at step 2, when Run starts listening for signals, and closes when the select waits. A signal in it is lost only when Init still returns its Services. An Init that fails on its cancelled context exits through the startup failure path, which has no select. That is reasoned from code.
• The reported test fails only with more than one CPU. With one, the Serve goroutine can't run until Run's goroutine has passed the select, so only the signal is ready. That is reasoned from code, and -cpu=1 failed in 0 of 12,000 iterations.
• On humus.Main's default telemetry, a simple processor writes the "serving" record to standard output synchronously (telemetry/new.go#L388-L389), between starting the Serve goroutines and the select. That gives a Serve on another CPU time to return. I got that from the code and didn't reproduce it.

#961 is filed to fix it:

• a signal, or Run's context's cause, stays the status's cause and ShutdownCause when a Service returns on it before Run waits, with a failed telemetry shutdown joined to it;
• the cause holds whichever of the signal and the Serve result reaches Run first;
• the triage's tests merged into app_test.go, app_telemetry_test.go and shutdown_cause_test.go, and the four tests above passing at -count=3000 -cpu=4;
• humus: a SIGTERM can be reported as a Service returning, when the Service returns as soon as it is cancelled #959 closed once the fix is merged.

[Zaba505]

Fixed in #965, merged as 25b0a30.

The order in which a signal and a Serve result reach Run no longer decides the shutdown's cause. Each Service's Serve result now records whether the signal, or the cancellation of Run's context, had come when Serve returned:

• A Service that returns on the signal makes the shutdown the signal's, even if it returns before Run starts to wait. The exit status then has the signal as its cause, a failed telemetry shutdown is joined to it, and ShutdownCause is the signal's cause, so a Drain that waits on a load balancer waits. After Run's context is cancelled at the same point, ShutdownCause is the context's cause.
• A job whose run returns nil after such a signal exits 0 with the signal as its cause.
• A Service that returns on its own before any signal still starts a shutdown whose cause wraps ErrServiceReturned.
• When the Service returned on the signal, Run still calls the Drain, as it does when it is already waiting.

The triage's reproductions are now tests in app_test.go, app_telemetry_test.go and shutdown_cause_test.go, next to tests for the opposite order and for the Drain. The tests that flaked pass under go test -race -count=3000 -cpu=4. Run's doc, ShutdownCause's doc and the lifecycle page now state the rule.