Skip to content

Log the cause when a capture recovery settlement fails - #2058

Merged
ppXD merged 1 commit into
mainfrom
fix/say-why-a-capture-settlement-failed
Sep 30, 2026
Merged

ppXD merged 1 commit into
mainfrom
fix/say-why-a-capture-settlement-failed

Conversation

@ppXD

@ppXD ppXD commented Sep 30, 2026

Copy link
Copy Markdown
Owner

Summary

  • AgentRunLogCaptureRecoveryService.RecoverClaimAsync turned any exception from SettleAsync into a lost lease and logged nothing. A guard RAISE (P0001), a unique violation, a dropped connection and a settlement timeout all left the claim leased and idle until its lease expired, with no trace of why. That is why the retry-clause refusal fixed in Check capture retries against the settling transaction's start #2057 looked like an unreproducible flake.
  • The catch now logs a Warning with the run id, the intent id, and the state and last_error_code the settlement was writing. When a PostgresException is in the exception chain, it also logs that exception's SqlState and MessageText. For any other cause both are null, and the attached exception carries the cause. The warning says the claim waits out its lease before a later wave re-claims it. Before it writes, SettleAsync can replace the observed outcome with Superseded or recovery-exhausted, so it records the outcome it writes in a SettlementAttempt. The log therefore names the write the guard actually judged.
  • The outcome does not change. A settlement that raises is still counted as a lost lease and keeps its lease. No other typed outcome exists for an unwritten settlement, and retrying inside the wave would only repeat a deterministic refusal.
  • Left as is: the lease re-check and DbUpdateConcurrencyException exits in SettleAsync stay unlogged. They are real lease losses, or impossible under the row lock. The RecoverAsync catch still drops its cause, but it settles as a typed recovery-operation-exception retry.

Test plan

  • A_settlement_the_database_refuses_is_logged_with_the_write_it_refused_and_still_waits_out_its_lease, a Theory with 2 rows. RefusedCaptureSettlementInterceptor makes the guard refuse only the owned intent's settlement write, retry or terminal, and a due neighbour sits ahead of that intent. The test asserts:
    • a Warning, with RunId set
    • Outcome/OutcomeCode of the refused write: SourceFinalized/complete-backend-unavailable, or ExternalStateIndeterminate/recovery-exhausted with MaxAttempts = 1
    • SqlState P0001 and a MessageText naming the intent
    • LostLease >= 1 and the claim still leased
    • the neighbour settled and not logged
  • A_settlement_that_outlives_its_budget_is_logged_without_a_database_cause_and_still_waits_out_its_lease: SlowCaptureSettlementInterceptor holds the owned run's settlement read until the settlement budget cancels it. The test asserts SqlState and MessageText null, an OperationCanceledException, and the same lost-lease outcome.
  • Mutations, each red:
    • log call removed: all 3 tests
    • refusal!.SqlState: the budget test, with a NullReferenceException escaping ReconcileAsync
    • logging the observed outcome instead of the written one: the exhausted row
    • dropping attempt.Outcome = settled: the exhausted row
    • refusal seam no longer scoped to the owned intent: both rows, on the neighbour
  • Integration: AgentRunLog* + *LogCapture* family, 112 of 112. The recovery flow class 5 runs in a row, 24 of 24 each time. Each new test alone in a cold process, 3 times each.
  • Unit: full suite, 11588 of 11589 (1 skipped). dotnet build CodeSpace.sln: 0 errors.

Depends on #2057.

AgentRunLogCaptureRecoveryService.RecoverClaimAsync counted any
exception from SettleAsync as a lost lease and logged nothing. A guard
RAISE, a unique violation, a dropped connection and a settlement
timeout all looked the same: the claim sat leased and idle until its
lease expired, with no trace of why. That is how the retry-clause
refusal fixed by 0240 passed for an unreproducible flake.

The catch now logs a warning naming the run, the intent, and the state
and last_error_code the settlement was writing. When a PostgresException
is in the exception chain it adds that exception's SqlState and
MessageText. For any other cause, such as a settlement cancelled at the
end of its budget, both are null and the attached exception carries
the cause. The warning also says the claim waits out its lease before
a later wave re-claims it.

The state and code named are the ones the guard judged. Before it
writes, SettleAsync can replace the outcome it observed with Superseded
or recovery-exhausted, so it records the outcome it is writing in a
SettlementAttempt that the catch reads. The catch no longer names the
outcome it passed in.

The outcome is unchanged. A settlement that raises is presumed
unwritten, so its claim keeps this wave's owner and lease whatever the
cause, and no typed outcome other than a lost lease exists for that.
Retrying inside the wave would only repeat a deterministic refusal.
The service now takes an ILogger from the container.
@ppXD
ppXD merged commit 7862d83 into main Sep 30, 2026
7 checks passed
ppXD added a commit that referenced this pull request Oct 4, 2026
After #2058, AgentRunLogCaptureRecoveryService still had three paths
that dropped the cause of a claim it could not settle.

RecoverClaimAsync turned any exception from the recovery step into a
typed retry, recovery-operation-exception, and discarded the exception.
A deterministic fault then repeats on every retry until the intent is
exhausted into ExternalStateIndeterminate, and nothing says why. It is
now logged as a warning in the shape #2058 uses: run, intent, the
exception, and the SQLSTATE and message text of any PostgresException
in its chain, plus the retry the step's outcome became. The line is
written before the settlement runs, so it names that outcome without
promising it: on the last allowed attempt the settlement exhausts the
intent instead, a changed worker fence supersedes it, and a lost lease
writes nothing, and the line says so rather than "recovered again once
the retry falls due".

SettleAsync returned a lost lease with no log line when its lease
re-check failed and when its write matched no row
(DbUpdateConcurrencyException). Each exit now logs a warning naming the
run, the intent, the outcome it discarded, and why: lease-expired,
reclaimed, row-version-changed, or claim-row-missing (which the
ON DELETE RESTRICT key and the DELETE guard make unreachable today).
The concurrency exit names the write it discarded, which the settlement
may already have replaced with an exhausted or superseded outcome, not
the outcome it observed. The level is Warning, not Information: the
constructor makes a lease outlive both bounded steps of a claim, so a
live worker loses one only when a step overruns the bound its
cancellation sets, the process stalls, or the row changes under the
settlement's own FOR UPDATE lock. None of that is routine. Each loss
costs a re-claim and another recovery attempt, and for a legacy intent
that attempt counts toward exhaustion. It is not an Error either,
because the fence keeps the loss safe.

Nothing read the LostLease tally, because the recurring job discards
the reconcile summary. ReconcileAsync now logs the summary at
Information when its wave claimed anything, as AgentRunReconcilerService
and AgentRunSpoolReaper log theirs, so the job and its handler stay
thin dispatchers.

Every path still returns the same settlement or retry as before.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant