Skip to content

Retry ledger: record WHY a flaky test failed, not just which one (GH-3787) - #3810

Merged
jeremydmiller merged 1 commit into
mainfrom
gh-3787/ledger-first-attempt-failure-reason
Aug 3, 2026
Merged

Retry ledger: record WHY a flaky test failed, not just which one (GH-3787)#3810
jeremydmiller merged 1 commit into
mainfrom
gh-3787/ledger-first-attempt-failure-reason

Conversation

@jeremydmiller

Copy link
Copy Markdown
Member

The ledger named the test that only passed on a retry and threw away the reason. Bobcat's log keeps only the [FLAKY] ... passed on attempt 2 line for a test that eventually passed — the first attempt's failure appears nowhere at all. That is the difference between a lead and a name.

It is currently load-bearing. Of the four flaky tests standing on main on 2026-08-03, two were undiagnosable for exactly this reason, and the note already sitting on multi_tenancy_through_virtual_hosts records its own next step as:

Next step is to dump the tracked session on the FIRST attempt rather than infer from the assertion.

Which is this.

The change

Each retried test now carries the failing attempt's ErrorType and message into the ledger JSON, the job step summary, and the cross-job roll-up:

- **CIOracle**
  - `OracleTests.Transport.clear_all_wolverine_storage.is_idempotent`
    - attempt 1: Shouldly.ShouldAssertException — counts.Queued should be 1L but was 2L

One trap worth recording

The reason comes from SupervisorAttempt.Outcome — the test's own error — and deliberately not from Disposition.Reason. The latter is the supervisor's rationale for retrying:

a failure is retried in a fresh process, within the budget, to separate flaky from broken

…which is the same sentence for every retry in the repository. The first version of this change read that field. It compiled, serialized and rendered perfectly, and carried no information whatsoever. Only forcing a real retry and reading the output showed the difference — a green run could never have caught it.

Backwards compatibility

FlakyTests stays a plain string array. flakiness-report.sh flattens it with map(.FlakyTests[]), and the baseline it diffs against is downloaded from an earlier run's artifact, so the new field is additive and read through // [] — without that default a single pre-change baseline would null the whole roll-up.

Verification

End to end with a test rigged to fail its first attempt and pass on the retry:

"FlakyFailures": [
  {
    "Test": "SqliteTests.TempFlakyProbe.fails_once_then_passes",
    "Attempt": 1,
    "ErrorType": "System.InvalidOperationException",
    "Reason": "System.InvalidOperationException : Deliberate first-attempt failure for ledger probe"
  }
]

Both the step summary and the roll-up render it under the test name. Aggregation and rendering were also checked against a mixed set containing a pre-change ledger, which degrades to the name alone rather than failing. bash -n passes on the script.

🤖 Generated with Claude Code

https://claude.ai/code/session_01WHAuhdWS3XeAk16swV9G8m

…3787)

The ledger named the test that only passed on a retry and threw away the
reason, and Bobcat's log keeps only the `[FLAKY] ... passed on attempt 2` line
for a test that eventually passed -- the first attempt's failure appears
nowhere at all. That is the difference between a lead and a name.

It is currently load-bearing. Of the four flaky tests standing on main on
2026-08-03, two were undiagnosable for exactly this reason, and the note
already sitting on multi_tenancy_through_virtual_hosts records its own next
step as "dump the tracked session on the FIRST attempt rather than infer from
the assertion" -- which is this.

Each retried test now carries the failing attempt's ErrorType and message into
the ledger JSON, the job step summary, and the cross-job roll-up.

The reason comes from SupervisorAttempt.Outcome, the test's own error, and
deliberately not from Disposition.Reason. The latter is the supervisor's
rationale for retrying -- "a failure is retried in a fresh process, within the
budget, to separate flaky from broken" -- and is the same sentence for every
retry in the repository. The first version of this commit read that field: it
compiled, serialized and rendered perfectly, and carried no information. Only
forcing a real retry showed the difference.

FlakyTests stays a plain string array. flakiness-report.sh flattens it with
map(.FlakyTests[]), and the baseline it diffs against is downloaded from an
EARLIER run's artifact, so the new field is additive and read through `// []`
-- without that default a single older baseline would null the whole roll-up.

Verified end to end with a test rigged to fail its first attempt and pass on
the retry: the ledger records the real exception type and message, and both the
step summary and the roll-up render it under the test name. Aggregation and
rendering were also checked against a mixed set containing a pre-change ledger,
which degrades to the name alone rather than failing.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01WHAuhdWS3XeAk16swV9G8m
@jeremydmiller
jeremydmiller merged commit a94d602 into main Aug 3, 2026
34 checks passed
erdtsieck pushed a commit to erdtsieck/wolverine that referenced this pull request Aug 4, 2026
JasperFxGH-3763)

Follow-up to JasperFx#3810, prompted by trying to use it.

JasperFx#3810 made the MQTT `Broken pipe` flake legible for the first time:

    MQTTnet.Exceptions.MqttCommunicationException : Broken pipe
      ---- System.Net.Sockets.SocketException : Broken pipe

That is a real lead, and it is not enough. The message alone is equally
consistent with three different bugs, and three local experiments were needed
to start telling them apart:

  - teardown ordering, since both flaky classes stop the broker before the
    hosts still connected to it -- refuted, 10 runs of a faithful reproduction
    including one with real tracked traffic, no exception either way;
  - a port collision between worker processes, via PortFinder handing the same
    port to two of them -- refuted, MQTTnet throws SocketException "Address
    already in use", which would fail the class outright rather than produce a
    broken pipe;
  - a keep-alive drop under CI load, which is what is left, and which needs a
    call site to confirm.

Six concurrent full-suite local runs did not reproduce it, so the next real
occurrence is on CI, and the thing that would separate the remaining candidates
is the one field the ledger throws away. WorkerOutcome already carries it.

The stack goes to the ledger JSON only, capped at 12 frames. The step summary,
the annotation and the roll-up are all glanceable surfaces and a stack would
drown them; the JSON is already a downloadable artifact, which is the right
place for something you go looking for on purpose.

Verified with a test rigged to fail its first attempt: the ledger records the
frames down to file and line, the step summary is unchanged, and the roll-up jq
ignores the new field.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01WHAuhdWS3XeAk16swV9G8m
ArieGato pushed a commit to ArieGato/wolverine that referenced this pull request Aug 4, 2026
Both retries on CISqlServer in the last green main run were races in the
tests, not product bugs. They only became attributable because of the
retry-ledger work in JasperFxGH-3810.

should_reasign_incoming_envelope_to_owner_id asserted a state that
PollForScheduledMessagesAsync deliberately moves past. The poll reassigns
ownership and flips the row to Incoming, then hands the envelope straight
to the execution pipeline via IWolverineRuntime.EnqueueDirectlyAsync.
ObjectMother.Envelope() is addressed to local://replies, so with the live
runtime the envelope is executed and marked Handled within ~250ms --
measured by sampling the row after the poll. That also explains the exact
failure shape: MarkIncomingEnvelopeAsHandledAsync writes status and leaves
owner_id alone, so the OwnerId assertion passed and the Status assertion
failed. Both copies of the test now pass a substituted runtime, which
isolates the database behaviour under test and additionally asserts the
hand-off that was never covered before.

sending_recovered_messages_when_sender_starts_up asserted on the sender's
outgoing table while WaitForMessagesToBeProcessed only synchronised on the
receiver. Outgoing rows are deleted asynchronously --
DurableSendingAgent.MarkSuccessfulAsync posts to a RetryBlock rather than
awaiting it -- so every send can have succeeded while all 10 deletes are
still queued, which is the reported "should be 0 but was 10". The wait loop
now also waits for the sender's outbox to drain and reports the last
observed counts on timeout.

Note: unlike the first race, the second was NOT reproduced locally. The
outgoing count was already 0 at the moment the old exit condition first
became true on all 6 measured runs; the drain finishes in under 250ms on a
quiet machine. The fix closes a synchronisation gap that exists by
construction, but the timing evidence is the CI failure itself.

The same gap in marten_durability_end_to_end is fixed here too. The RavenDb
twin has it as well and is deliberately left alone -- there is no ravendb
service in docker-compose.yml and the exit condition is not runnable
locally.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01WHAuhdWS3XeAk16swV9G8m
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