feat(observability): make a resumed or failed drive explain itself in the apply log - #1027
Conversation
Two gaps left an apply silent for the drive that actually ran it: - The engine's log callback was wired only by the drive that started an apply, so the apply log stream went quiet the moment the apply changed hands. Both resume paths now wire it for as long as they drive engine work; a detached grouped resume unwires it from the goroutine that outlives the call. - Every resume announced itself as a heartbeat expiry, a cause this path never checks — the claim arm that selected the apply is decided by the operator's claim query and is not carried here. It now reports what it knows and leaves the cause to the claim logs.
A failing apply wrote nothing to the apply log: the failure and retryable helpers moved state and left the reason in the server logs alone, so the CLI and the PR summary — which render that stream — showed an apply going terminal with nothing stating why. Both helpers now record the transition they make, and expiry records why operator recovery stopped retrying, so the stream carries the whole arc from the first paused attempt to the permanent failure. The failure record now has a single owner, so the call sites that logged their own copy no longer do.
There was a problem hiding this comment.
Pull request overview
This PR improves operator-facing observability by ensuring resumed drives continue streaming engine logs into the apply log, and by recording explicit failure/expiry causes in the apply log so the CLI and PR failure summaries are self-explanatory.
Changes:
- Wire Spirit engine log capture for resumed drives (sequential resume + grouped/atomic resume, including detached polling).
- Record permanent and retryable failure transitions as durable apply-log entries (and remove duplicate call-site logging).
- Record operator retry-budget expiry as a durable apply-log entry, with unit/integration tests covering the new behavior.
Reviewed changes
Copilot reviewed 7 out of 7 changed files in this pull request and generated 2 comments.
Show a summary per file
| File | Description |
|---|---|
| pkg/tern/local_resume_engine_logging_integration_test.go | Integration test asserting resumed drives capture Spirit engine log lines into apply logs. |
| pkg/tern/local_control_resume.go | Adds Spirit log wiring to resume paths; improves resume messaging and removes duplicate failure logging. |
| pkg/tern/local_apply_grouped.go | Removes duplicated apply-log failure events and routes failures through the centralized failure helpers. |
| pkg/tern/local_apply_failure.go | Adds durable apply-log entries for permanent and retryable failures. |
| pkg/tern/apply_failure_log_test.go | Unit tests asserting failure helpers append the expected apply-log entries. |
| pkg/api/operator.go | Appends an apply-log entry when operator recovery expires a retryable apply. |
| pkg/api/operator_test.go | Unit test verifying expiry appends the expected apply-log entry. |
💡 Add a code-review agent skill or configure MCP servers for context-aware, tailored reviews. Learn more in the docs.
…s attempt count in budget A detached grouped resume polls under a context that deliberately outlives its caller, but its engine log wiring held the caller's context — so capture ended the moment the caller returned and the rest of the schema change went unrecorded. The wiring is now bound to the context the poll runs under. The paused-attempt record counted drives against the recovery budget, two quantities that diverge because a recovery claim advances the apply's attempt counter. At the last attempt the record read past its own limit. It now reports the attempt counter the budget is measured against.
…tored cause Consolidating the failure record onto one owner moved two call sites' framing into the message passed to failApplyWithTasks, which is stored as the apply's and every task's error message — not just written to the log. That prefixed a cause an operator reads in status output and PR comments with wording meant for the log line. The stored cause is the engine's text again. The apply log entry carries its own framing, and the recovery entry that precedes it already establishes that the drive was a resumed one.
|
🤖 Review findings - created by Kiran's code review agent - for pull/1027, 339ed56. Verdict: 7 findings — 0 blocking, 3 non-blocking, 4 suggestions; safe to land. CI is 31/31 GREEN on head 339ed56: the earlier Integration RED was a re-run-confirmed flake (TestFullWorkflow_Spirit_PlanApplyVerify stalled on a saturated runner) plus 10m job-budget exhaustion (green baselines already run 8m22s–9m20s; this PR added only ~0.8s to pkg/tern) — not a PR-introduced hang, though the suite's ~9m-of-10m budget headroom is a repo-level fragility worth a follow-up. Non-blocking
General suggestions
The one thing that could have broken, verifiedThe riskiest mechanism is the detached grouped resume's log-capture handover on the spirit engine's single global callback slot (pkg/tern/local_control_resume.go:855-868) — the one thing that could both corrupt observability and, per the initial CI cancellation, hang tests. The hang theory was refuted: Verified correct
This review was generated by Claude Code (claude-fable-5). |
The sequential path is the one most applies take, and it wrote the failure only to the server logs — so the apply's own history showed it reach a terminal state with nothing stating why, on exactly the path an operator is most likely to be reading. Route it through the same log owners as every other path, and report the retry budget as attempts remaining so the first pause reads as a countdown rather than "0 of 10". Also folds the operator's three near-identical best-effort apply-log appends into one helper, so a future contract change cannot miss one. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
…rests on A resume that hands its polling to a goroutine outliving the caller rewires the engine's apply-log callback on that goroutine's own context. The reason is now covered: a callback still holding the caller's cancelled context records nothing, so the engine lines for the rest of the schema change would be lost. The apply log store fixture stops ignoring its context, which is what makes the difference observable — the real store treats a cancelled context as a failed write, not a silently dropped one. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
|
🤖 All seven addressed. Two went to their own PR or commit rather than inline:
On the CI note in your verdict: the 10-minute Integration budget bit again on #1019 (cancelled at 10m11s, every prior step green). Tracked as a follow-up to split the Reviewed and addressed by Claude Code (claude-opus-5). |
Why this matters
The apply log stream is the only account of a schema change an operator actually reads — it is what the CLI renders and what a failed apply folds into its PR summary comment. Two of the moments most worth reading were absent from it.
An apply that changes hands mid-flight goes quiet. The engine's log lines were wired into the stream only by the drive that started the apply, so the first lease handover ended engine capture for good — and the drive that finishes the work, the one an operator is trying to read, contributes nothing.
An apply that fails says nothing about why. The failure paths moved the apply to its terminal state and left the reason in the server logs alone. Read from the CLI or the PR comment, the apply reached
failedfor no stated cause; the retry budget drained across attempts with only gaps between them to show for it.What it does
Wires engine log capture on both resume paths. A resumed drive now routes the engine's own lines into the apply's stream, so an apply reads the same whether one driver or four carried it. The wiring goes up before the engine accepts the resume and comes down with the drive that polls the work; a detached resume polls past the call it started in, so that goroutine unwires it instead.
Stops the resume asserting a cause it never checked. Every resume announced a heartbeat expiry. The claim arm that selected the apply — a stale heartbeat, a pending control request, a parked cutover — is decided by the claim query and is not carried into the drive, so the message now reports what this drive knows and leaves the cause to the claim logs.
Gives a failed apply a stated cause. Both failure paths record their transition: a permanent failure at error level, and a retryable one at warn naming the attempt it spent, so the recovery budget visibly drains instead of showing as silence between attempts. Expiry records why recovery stopped, closing the arc from first paused attempt to permanent failure. The record has one owner now, so call sites that logged their own copy no longer duplicate it in the fold.
🤖 Generated with Claude Code