Skip to content

CISqlServer: both retries are test-side races (scheduled-poll status assertion + unsynchronized outbox drain) #3821

Description

@jeremydmiller

Both retries on CISqlServer in the last green main run (30877953106) are test-side races, not
product bugs. They became attributable only because of the retry-ledger work in #3810. Diagnosis and
fixes below.

CISqlServer is currently the wall-clock pole (959s), so its flakes are the most visible in the repo.


1. should_reasign_incoming_envelope_to_owner_id asserts a state the poller deliberately moves past

Persistence.SqlServerMessageStoreTests.should_reasign_incoming_envelope_to_owner_id
  stored.Status should be EnvelopeStatus.Incoming but was EnvelopeStatus.Handled

SqlServerMessageStore.PollForScheduledMessagesAsync does two things in one call: it reassigns
ownership and flips the row to Incoming (via uspMarkIncomingOwnership), and then hands the
envelope straight to the execution pipeline:

// SqlServerMessageStore.cs:459
await runtime.EnqueueDirectlyAsync(envelopes);

The test passes the live runtime. ObjectMother.Envelope() has
Destination = TransportConstants.RepliesUri (local://replies), so the envelope is enqueued onto a
live local queue, executed, and marked Handled — all while the test is still on its way to reading
the row back.

Measured locally by sampling the row after the poll:

PROBE t=0ms    count=1 :: status=Incoming owner=1
PROBE t=250ms  count=1 :: status=Handled  owner=1
PROBE t=500ms  count=1 :: status=Handled  owner=1
...

The window is well under 250ms. This also explains why the failure reports a status mismatch and
not an owner mismatch: MarkIncomingEnvelopeAsHandledAsync writes status and keep_until and
leaves owner_id alone, so the first assertion still passes and the second one fails. That matches
the CI output exactly.

Fix: pass a substituted IWolverineRuntime. The poll uses runtime for nothing but
EnqueueDirectlyAsync, so this isolates the database behaviour that the test actually exists to
cover, and makes the row stable. The substitute is then also asserted against, which adds coverage —
the test never verified the hand-off before.

Applies to both copies: SqlServerMessageStoreTests and
SqlServerMessageStore_with_IdAndDestination_Identity.

2. sending_recovered_messages_when_sender_starts_up never waits for the sender's outbox to drain

sqlserver_durability_end_to_end.sending_recovered_messages_when_sender_starts_up
  PersistedOutgoingCount() should be 0L but was 10L

WaitForMessagesToBeProcessed only synchronises on the receiver: receiver.trace_doc reaching
the expected count and receiver.wolverine_incoming_envelopes reaching zero. The assertion that
follows is against the sender's outgoing table, which nothing has waited on.

Deletion of outgoing rows is asynchronous by construction — DurableSendingAgent.MarkSuccessfulAsync
posts to a RetryBlock rather than awaiting it:

public override Task MarkSuccessfulAsync(OutgoingMessageBatch outgoing)
    => _deleteOutgoingMany.PostAsync(outgoing.Messages.ToArray());

So every send can have succeeded — the receiver has all 10 trace docs — while all 10 deletes are
still queued in the block. That is precisely the reported should be 0 but was 10.

The test has carried a // This test "blinks" comment for a long time, and the RavenDb twin already
reads the outgoing count inside its wait loop purely for its trace line
(ravendb_durability_end_to_end.cs:155) without ever adding it to the exit condition — someone hit
this before and stopped at instrumentation.

Fix: add outgoingCount == 0 to the wait loop's exit condition, and report the last observed
counts in the timeout message instead of a bare "All messages were not received".

Caveat, stated plainly: unlike #1, I could not reproduce this one locally. Instrumenting the
loop to record the outgoing count at the moment the old exit condition first became true gave
outgoingCount=0 on every one of 6 measured runs — the drain completes in under 250ms on a quiet
machine. The fix closes a synchronisation gap that demonstrably exists in the code path, but the
timing evidence for it is the CI failure itself, not a local red/green.

The same gap exists in the Marten twin (marten_durability_end_to_end.cs), fixed here too, and in
the RavenDb twin — left alone deliberately, because there is no ravendb service in
docker-compose.yml and I am not shipping a change to an exit condition I cannot run.


Scope

  • SqlServerMessageStoreTests / SqlServerMessageStore_with_IdAndDestination_Identity — substituted runtime + hand-off assertion
  • sqlserver_durability_end_to_end — wait for the outbox drain; drop the stale "blinks" comment
  • marten_durability_end_to_end — same wait-loop fix
  • RavenDb twin — follow-up, not runnable locally

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions