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 (runJob and monitorResumedJob), 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 main always 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 -v

Against 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_RecoversTheTailBeforeUnregistering fails when the two calls are swapped (remove first, then flush): the tail is not recovered. The integration test fails on that version too.
  • TestRetireAttemptTrace_UnregistersWhenTheFlushFails fails 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 output
  • go vet ./... and go vet -tags e2e ./...: clean
  • go build ./...: clean
  • make test: passes
  • go test -race -timeout 10m ./... (the unit:race job): 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.

Closes #119 (closed)

Related to #120

Merge request reports

Loading
Loading