fix(daemon): Reconcile a failed attempt's trace before the retry
What this MR does and why?
A retried job runs each attempt under a job ID of its own, and the mock server keeps a separate trace for each of those IDs. The retry branch of runJob unregistered the failed attempt's trace writer without reconciling that trace first, and the only FlushTrace ran after the attempt loop, under the last attempt's ID. So whatever the event stream had dropped from a failed attempt never reached the log file, and nothing reported it: RemoveTraceWriter discards the job's trace accounting, so a flush for that ID afterwards finds no writer and recovers nothing. The failed attempt's output is the part a user opens a retried job's log to read.
The retry branch now calls a small helper, retireAttemptTrace, while jobID still names the attempt that just ended. It flushes that attempt's trace against the mock server and only then removes the writer. Every attempt writes to the same traceTarget, so the recovered tail lands in the same log file, ahead of the next attempt's output. This is the fix the issue suggests; I kept it in a helper because, as the issue says, getting the order wrong is silent (TestFlushTraceAfterRemoveWritesNothing from !150 (merged) pins that at the client level).
Two details:
- The flush is bounded by the same 5 second timeout as the flush after the loop. That value was written out twice already (
runJobandmonitorResumedJob), so all three now read one constant,traceFlushTimeout. No value changes. - A flush that fails (the mock server errors, or the run is cancelled while the request is out) still unregisters the writer, as
mainalways did. The retry has to move on to the next job ID either way, and a late frame for the old ID must not reach a writer the next attempt now shares.
site/content/architecture/how-it-works.md now says that reconciliation happens attempt by attempt.
Not in this MR: #120, the wait-error path (a timed-out job, for one) that tears the trace down without reconciling it. #120 suggests fixing both paths behind one flush-then-remove helper, and retireAttemptTrace takes its context as a parameter so that path can call it with a fresh one, as #120 asks. I kept it out because it also moves the timeout notice after the flush, which changes how a timed-out job's log ends, and that seemed worth reviewing on its own.
Steps to reproduce
The loss needs the event stream to drop a frame of the failed attempt. In normal use that happens when a subscriber's buffer overflows, while the daemon's event stream is reconnecting, or when the attempt's last trace update races its final state. The regression test produces the drop on demand instead: TestRunJob_Retry_ReconcilesTheFailedAttemptsTrace in the new pkg/daemon/retry_trace_test.go puts a reverse proxy in front of the in-process mock server that holds back the daemon's GET /internal/events. While it is held the mock server has no subscriber, so the first attempt's last line (first attempt's tail) is only in the mock server's copy of the trace. The test then releases the stream, fails that attempt, lets the retry pass under a new job ID, and reads the log file the history store wrote.
go test ./pkg/daemon/ -run 'TestRunJob_Retry_ReconcilesTheFailedAttemptsTrace|TestRetireAttemptTrace' -count=1 -vAgainst main (27ee326d), with the test file copied over and a stand-in for the helper that does what main does (a bare RemoveTraceWriter) so the file compiles, the log holds second attempt and nothing from the first attempt, and TestRunJob_Retry_ReconcilesTheFailedAttemptsTrace fails; it failed 20 runs out of 20. With this change it passes, 50 runs out of 50 under -race and 200 out of 200 without.
The failure on main
[runner #1/flaky] job queued for persistent runner
[runner #1/flaky] attempt 1/2 failed (reason=script_failure, exit_code=1), retrying...
[runner #1/flaky] retrying (attempt 2/2)
[runner #1/flaky] finished (status=passed, duration=0s, attempts=2)
retry_trace_test.go:187:
Error: Not equal:
expected: 1
actual : 0
Test: TestRunJob_Retry_ReconcilesTheFailedAttemptsTrace
Messages: the failed attempt's tail must reach the log exactly once:
second attempt
--- FAIL: TestRunJob_Retry_ReconcilesTheFailedAttemptsTrace (0.03s)Two smaller tests pin the helper itself, and each one fails against the mistake it is there for:
TestRetireAttemptTrace_RecoversTheTailBeforeUnregisteringfails when the two calls are swapped (remove first, then flush): the tail is not recovered. The integration test fails on that version too.TestRetireAttemptTrace_UnregistersWhenTheFlushFailsfails when the helper keeps the writer registered after a failed flush: the old job ID's next frame reaches the shared writer.
What I ran
All on golang:1.25 (go1.25.14), the image the pipeline uses:
gofmt -l cmd/ pkg/ e2e/: no outputgo vet ./...andgo vet -tags e2e ./...: cleango build ./...: cleanmake test: passesgo test -race -timeout 10m ./...(theunit:racejob): passes
I did not run make test-integration or the other Docker tiers, since the machine I ran these on has no Docker; the test:integration jobs of this merge request's pipeline cover them.
Relevant issues and other links
Closes #119 (closed)
Related to #120