test: remove the timing races in the RIE invoke and telemetry tests - #190
carole-lavillonniere wants to merge 1 commit into
Conversation
TestRie_InvokeWaitingForInitError ordered the invoke against initialization
with time.Sleep(200ms) and drove the invoke from a goroutine that called
require.* and then wg.Done(). Both are load-bearing:
- The invoke request is what triggers init here, so if the goroutine is not
scheduled within 200ms the test calls Init() itself, init fails, the server
shuts down, and the invoke lands on a dead listener.
- require.* outside the test goroutine ends it through runtime.Goexit, which
skips the un-deferred wg.Done(). wg.Wait() then blocks forever, so a
request error does not fail the test -- it hangs the whole package until
the go test timeout fires and panics every other test with it.
Under `go test -race` this reproduced 10 out of 10 runs locally, and it is what
broke the weekly release: a 10m timeout panic with
`running tests: TestRie_InvokeWaitingForInitError`.
Wait on an httptrace WroteRequest signal instead of sleeping, let the invoke be
the only thing that starts init, and close a channel from a defer so a failed
assertion reports the failure rather than deadlocking. Bounded waits replace the
bare channel receives so a genuine regression fails in seconds with a message.
TestRIE_TelemetryAPI asserted the log-line count as soon as the server reported
itself shut down, but log lines reach subscribers asynchronously; CI saw 5 of 6.
Poll for the expected count before checking the platform events.
![aws-sam-tooling-bot[bot]](https://avatars.githubusercontent.com/b/1290?s=60&v=4){kind=small}
| assert.Equal(t, initErr, serverErr) | ||
|
|
||
| wg.Wait() | ||
| waitForClose(t, invokeDone, "invoke request did not complete") |
There was a problem hiding this comment.
[CONCURRENCY] The invoke goroutine is only joined on the happy path. Every t.Fatal/require failure before this line exits the test goroutine through runtime.Goexit while the goroutine is still inside http.DefaultClient.Do:
waitForClose(t, requestSent, ...)failing means the request is still in flight by definitionwaitForClose(t, server.Done(), ...)andrequire.Error(t, initErr)can both fail with the request outstanding
When Do later returns, the goroutine calls assert.NoError(t, err) on a *testing.T that is already done, and the testing package panics with Log in goroutine after TestRie_InvokeWaitingForInitError has completed — taking the whole test binary down, which is the same collateral damage this PR is removing.
Registering the join as a cleanup makes it run on every exit path, including Goexit:
invokeDone := make(chan struct{})
t.Cleanup(func() {
select {
case <-invokeDone:
case <-time.After(30 time.Second):
t.Error("invoke request did not complete")
}
})
go func() {
defer close(invokeDone)
...
}()and then the trailing waitForClose(t, invokeDone, ...) can be dropped. t.Error is used rather than t.Fatal because the cleanup runs outside the test body.
| for _, mock := range []*functional.InMemoryEventsApi{httpEventsApi, tcpEventsApi} { | ||
| // Log lines are relayed to subscribers asynchronously and are not guaranteed to | ||
| // have all been delivered by the time the server reports itself shut down. | ||
| require.Eventually(t, func() bool { return len(mock.LogLines()) == expectedLogLines }, |
There was a problem hiding this comment.
[GENERAL] Polling for the log lines fixes the flake, but folding the count assertion into the Eventually condition with == loses the upper bound that assert.Len(t, mock.LogLines(), 6) provided, and makes the outcome timing-dependent if a 7th line ever shows up: whether the poll happens to observe the transient 6 decides between pass and a 10-second timeout with a message that never reports the count actually seen.
Poll for the lower bound and keep the exact assertion afterwards, so the wait is unchanged but an unexpected extra line fails deterministically and the failure prints the real length:
require.Eventually(t, func() bool { return len(mock.LogLines()) >= expectedLogLines },
10time.Second, 10*time.Millisecond,
"expected at least %d log lines to be delivered over the Telemetry API", expectedLogLines)
mock.CheckSimpleInitExpectations(initStartTime, initFinishTime, expectedInitEvents, initPayload)
mock.CheckSimpleExtensionExpectations(expectedExtensionEvents)
mock.CheckSimpleInvokeExpectations(invokeStartTime, invokeFinishTime, invokeID, expectedInvokeEvents, initPayload)
assert.Len(t, mock.LogLines(), expectedLogLines)|
|
||
| // waitForClose blocks until ch is closed and fails the test instead of letting the whole | ||
| // package hit the go test timeout when it never is. | ||
| func waitForClose(t *testing.T, ch <-chan struct{}, msg string) { |
There was a problem hiding this comment.
[CONCURRENCY] TestRie_SigtermDuringInvoke (lines 118-147 of this file) still has the exact deadlock this helper was added to remove, and it is the sibling of the test being fixed:
go func() {
resp, err := http.Post(...)
require.NoError(t, err) // off the test goroutine
...
wg.Done() // not deferred
}()
time.Sleep(200 time.Millisecond)
sigCh <- syscall.SIGTERMIf the goroutine is not scheduled within 200ms, SIGTERM shuts the server down first and http.Post hits a closed listener. require.NoError then ends the goroutine via runtime.Goexit, the un-deferred wg.Done() is skipped, and wg.Wait() blocks until the go test timeout panics the whole package — the failure mode described in the PR description.
The ordering there is load-bearing (the test wants the invoke to land after SIGTERM but while the listener still accepts), so it cannot take the requestSent trick verbatim. At minimum, switching the goroutine to assert and deferring the WaitGroup release converts the hang into a reported failure:
go func() {
defer wg.Done()
resp, err := http.Post(...)
if !assert.NoError(t, err) {
return
}
defer func() { assert.NoError(t, resp.Body.Close()) }()
...
}()
1 participant
What does this change do?
Removes two timing races in
internal/lambda-managed-instances/aws-lambda-rie/test/rie_test.go. Test-only; no production code is touched.TestRie_InvokeWaitingForInitError— the invoke goroutine callsrequire.*and ends with a non-deferredwg.Done():Two problems, and they compound:
require.*outside the test goroutine ends it throughruntime.Goexit, which skips the un-deferredwg.Done().wg.Wait()then blocks forever, so a request error does not fail the test — it hangs the package until thego testtimeout fires and panics every other test in the binary along with it. testify documents thatrequiremust not be used off the test goroutine.time.Sleep(200ms)orders the invoke against initialization. The invoke request is what triggers init here, via thesync.OnceValueinaws-lambda-rie/internal/app.go. If that goroutine is not scheduled within 200ms, the test callsInit()itself, init fails, the server shuts down, and the invoke lands on a dead listener.This change waits on an
httptraceWroteRequestsignal instead of sleeping, lets the invoke be the only thing that starts init, and closes a channel from adeferso a failed assertion reports the failure rather than deadlocking. The bare channel receives become bounded waits, so a genuine regression fails in seconds with a message instead of consuming the package timeout.TestRIE_TelemetryAPI— assertsassert.Len(t, mock.LogLines(), 6)as soon as the server reports itself shut down, but log lines reach subscribers asynchronously through the relay, so they are not guaranteed to have all arrived. Our CI saw 5 of 6, withextension tcp: test stdout logmissing. This change polls for the expected count before checking the platform events.Why is it needed? What is the use case?
We (LocalStack) build the RIE from a fork, and these two tests have failed our weekly release job repeatedly. The
TestRie_InvokeWaitingForInitErrorhang is the expensive one: it shows up as a 10-minute package timeout that takes the whole run down.Being straight about how this reproduces, because it affects how much you should care:
Our fork predates a0f264a, which made
raptor.Server.Shutdowndrain in-flight responses instead of callinghttpServer.Close(). On a tree without that commit the invoke reliably fails withEOFwhen the server tears the connection down mid-response, and the deadlock above triggers 10 runs out of 10 undergo test -race. Onmainas it stands today, the unfixed test passes 10/10 in the same conditions — graceful shutdown means the request rarely errors, so the deadlock is latent rather than active.So this is defence in depth for the first test: the hazard is that any future error from that request — a slow runner, a change in shutdown timing, a port collision — turns into a silent 10-minute package timeout instead of a one-line failure. The 200ms sleep is an independent race that no shutdown behaviour protects against. The telemetry log-line race is live on
mainregardless.How did you test it?
go test -race, fullaws-lambda-rie/testpackage, on this branch:main, unfixed, isolated run ofTestRie_InvokeWaitingForInitErrormain, with this changeThat third row is the point of the change: the same underlying error, reported in a tenth of a second by the one test responsible instead of taking the whole binary down ten minutes later.
make testspasses, andmake compile-lambda-linux-allbuilds all three targets. I could not runmake integ-tests— no Docker in this environment — so the Python e2e suite is unverified; happy for CI to cover that.Checklist
make integ-tests-and-compile—testsand the compile targets pass;integ-testsneeds Docker, which I do not have hereBy submitting this pull request, I confirm that my contribution is made under the terms of the Apache 2.0 license.