Heartbeat can fail to protect an in-flight message, so the queue delivers it twice

[blehnen]

ConsumerHeartbeat intermittently reports more processed messages than were sent. Seen twice, on different data rows, on two different branches:

PR	Row	Expected	Actual
#291	(7, 45, 280, 3, inMemoryDb: true, enableChaos: true)	7	8
#294 (commit conversion)	(7, 45, 180, 3, inMemoryDb: false, enableChaos: false)	7	9

Why it is the test, not the change

• Passes in isolation. 3/3 both times, including the row that had just failed. It only fails inside the full 200+ test run.
• The second occurrence is on the non-chaos row, so injected faults are not required to trigger it.
• It exercises the synchronous consumer — ConsumerCancelWorkShared uses creator.CreateConsumer(...). The branch it failed on converts only the asynchronous consumer's commit; ProcessMessage.cs and MessageProcessing.cs are untouched in that diff.

The race

ConsumerCancelWorkShared.RunConsumerInternal asserts messageCount == processedCount. The scenario is deliberately a race: a "bad" consumer takes messages, is disposed mid-flight, the heartbeat monitor resets its in-flight messages, and a good consumer picks them up. If the monitor resets a message the good consumer is already working — or the bad consumer completed one before disposal — the message is processed twice and the count overshoots.

Under full-suite load the workers are slower, which widens the window. The overshoot size tracks that: 8 the first time, 9 the second.

What to consider

The assertion may simply be wrong for what the scenario can guarantee. The test is about the heartbeat resetting stalled work, and reprocessing is the mechanism it relies on — so an exact-equality count is a stronger claim than the design supports. IsGreaterThanOrEqualTo(messageCount, ...) plus a separate assertion that every message reached a terminal state may be what was meant.

Worth deciding deliberately rather than re-running until green, which is what happened on #291.

Related

• Note that ConsumerHeartbeat and ConsumerCancelWork are also the two scenarios with no asynchronous-consumer equivalent (audited 2026-09-10), so whatever is decided here should shape the ConsumerAsyncHeartbeat test that Remaining synchronous calls on the async receive path — blocks the next release #284's heartbeat conversion needs.

[blehnen]

This is a bug; it never happened until our async changes. Needed to be addressed before the next version can ship

[blehnen]

Correcting this issue: the reasoning above is wrong, and the assertion is right.

I suggested that Assert.AreEqual(messageCount, processedCount) "may simply be the wrong assertion for what the scenario can guarantee" and floated relaxing it to IsGreaterThanOrEqualTo. That should not be done, and the argument I gave for it does not hold.

The overcount can only mean one thing. I offered two explanations — the monitor resetting a message the good consumer is already working, or the bad consumer completing one before disposal. The second is impossible in this direction: if the bad consumer completed a message, that message is gone and the good consumer never sees it, so the count comes out low. Only the first explanation produces an overcount, and it means a message that was actively being processed had its heartbeat treated as expired and was handed to a second worker.

That is precisely what the heartbeat exists to prevent. So every occurrence of this failure is a real defect, not a scenario the test over-specifies. Exact equality is the correct assertion.

One occurrence is now explained, and it was a regression. While finishing #284's heartbeat work (#301) this test failed twice on SQL Server with the same signature (7 → 8, 7 → 9). The cause was in that branch: SQL Server registers its own SendHeartBeatCommandHandler because its statement declares @date inside the batch, and only the synchronous handler was registered explicitly — so the new asynchronous interface resolved to the relational handler, which passes @date as a parameter. Every beat threw the variable name '@date' has already been declared, was caught and logged by HeartBeatWorker, and the heartbeat column never advanced. The monitor then reset live messages. Registering SQL Server's own handler for the asynchronous interface fixed it; the test passes consistently again.

Worth noting how close that came to shipping: the failure looked exactly like this issue, and I attributed it here twice rather than investigating it.

Still open: the two original sightings. Both were SQLite (inMemoryDb: true, enableChaos: true and inMemoryDb: false, enableChaos: false), and both predate the heartbeat change, so they need their own root cause. The question to answer is the same one: what stopped a beat from landing inside the expiry window for a message the good consumer held?

The configuration makes that worth looking at closely — HeartBeat.ThreadPoolConfiguration.ThreadsMax = 2 in SharedSetup, against workerCount = 3 in two consumer containers, with a heartbeat that (before #301) blocked its thread for the whole transport round trip. Expiry is 10s and the beat cron is every 3s, so roughly three chances to land one; a saturated heartbeat pool under full-suite load is a plausible way to miss all three. That is a hypothesis, not a finding — it needs instrumenting the beat timestamps per message and the monitor's reset decisions before anyone claims it.

What should not happen: relaxing the assertion, or re-running until green. Both were on the table in the text above; neither is appropriate for a defect that means a queue delivered the same message to two workers at once.

Also worth considering separately: a reset does not invalidate the original worker's claim on the message — there is no fencing token, so the first worker can still commit a message that has already been redelivered and processed. That is a design-level gap rather than this test's problem, but it is the reason a missed heartbeat turns straight into duplicate processing rather than something recoverable.

[blehnen]

Root cause, with measurements

HeartBeatWorker already logs every beat at Trace. The integration test logger was sending everything below Error to the console, which dotnet test swallows — routing it to a file gives a per-message beat timeline. Running the SQLite ConsumerHeartbeat rows with that on:

• The beat cron is every 3s; the expiry the monitor resets against is 10s.
• On a passing, unloaded run the worst gap between consecutive beats for a single message is 6.06s.
• Gaps cluster at ~6s, which is exactly two cron slots — beats are being skipped.
• 190 we will try to re-run the statement warnings in a three-test run: the transport is retrying under contention, which is what makes a beat slow enough to overrun its slot.

Three things combine:

1. SendHeartBeatInternal returns immediately if a beat is already in flight, so a slow beat silently costs the next one. Nothing records that it happened.
2. Nothing bounds how long a beat may take. A stuck beat suppresses every successor indefinitely.
3. A worker never checks that its own claim survived. SetCancel fires when a beat throws, but not when beats merely stop landing. So when the monitor resets a message whose heartbeat aged out, the original worker carries on and commits — which is why a lapse produces double processing rather than a recoverable redelivery.

With a 10s window and a 3s cron there are about three chances to land a beat. Two slow beats and the message is reset under a live, healthy worker.

Scope

Core, and every transport that has a heartbeat — SQL Server, PostgreSQL, SQLite, Redis and LiteDb. All three parts above are in DotNetWorkQueue: the guard in HeartBeatWorker, the absent timeout, and HeartBeatMonitor driving the reset the same way for every transport. The memory transport is exempt because heartbeats are disabled there.

SQLite is where it is easiest to trigger, not where it lives — file-lock contention makes beats slow. A network stall does the same on the others.

Did this work cause it?

Measured rather than argued. Same test, same instrument, same machine, at the commit before #285 and at current master:

	base (pre-#285)	master
worst gap	6.00s	6.06s
gaps > 9s	0	0
p99 gap	3.64s	5.99s
p50 gap	1.40s	2.82s
statement retries	172	190

The tail is unchanged, and the tail is what crosses the threshold. The p50/p99 shift is real but middling gaps do not reset anything. This is one run per side and neither reproduced the failure, so the honest reading is "no evidence the async work widened the tail", not "proven unrelated". The mechanism itself predates the series: the skip guard, the missing timeout and the missing claim check are all older than #284.

Fix

1. Make a skipped beat visible rather than silent.
2. Bound a beat, so a stuck one cannot suppress its successors forever.
3. Trip the worker's cancellation token when the last successful beat has aged past the expiry, reusing the mechanism that already exists for a throwing beat. A worker that has lost its claim must stop rather than finish and commit.

(3) is the one that turns this from duplicate processing into ordinary at-least-once redelivery, and it is the part worth reviewing closely.

Also found

That test logger builds its paths with Windows separators, so on Linux and in Docker the integration logs land as oddly-named files rather than under Logs/. Worth a look on its own — it likely means Jenkins has not been producing usable integration logs.

[blehnen]

Measured: it is the scheduler, not the worker

Two of my hypotheses in this issue were wrong, so this time I instrumented it — the point the scheduler delivers a tick, and either side of the transport call. SQLite, three ConsumerHeartbeat runs, 376 ticks:

beat duration	p50 39ms, p99 1.32s, worst 1.53s
beats longer than the 3s slot	0
ticks skipped because a beat was in flight	0
tick arrival interval (cron = 3.00s)	p50 2.97s, worst 9.00s

Every tick produced a send; none was skipped. The worker updates the row in 39 milliseconds. The scheduler delivered one tick 9.00s after the previous, against a 10s expiry — two slots gone, one second of margin left.

So the earlier candidates are dead: it is not the skip-if-running guard, not a slow beat, not the transport, and not the reset query. It is tick latency in the heartbeat scheduler, which dispatches every beat through an internal memory queue and consumer. Split out as #303.

What #302 does about this issue

It fixes the half that turns a lapse into duplicate processing: the worker never noticed its own claim had gone stale, so when the monitor handed the message to someone else, the original worker carried on and completed it too. It now cancels and logs.

That makes a lapse recoverable rather than silent. It does not prevent one — the cancellation token is advisory, and a handler that ignores it (our own HandleFakeMessages does) still runs to completion. Preventing the lapse is #303.

On whether this work introduced it

Measured at the commit before #285 and at master, same test and instrument: worst beat gap 6.00s vs 6.06s, zero gaps over 9s on either side. The tail is what crosses the threshold and it is unchanged. One run per side, so: no evidence the async work widened it, rather than proof it did not. The mechanism — an advisory-only heartbeat with no claim check, and a scheduler that can be two slots late — predates the series.

Worth recording that one occurrence in this issue was a regression, just not from the async conversion generally: the SQL Server registration bug in #301 killed every beat on the synchronous consumer too, and I filed those failures here as a flake twice before investigating them.

Leaving this issue open until #302 merges; #303 carries the prevention.

[blehnen]

Fixed by #302, in the half that turns a lapse into duplicate processing: a worker now records when a beat actually lands, checks that age on every tick against the transport's configured time provider, and cancels itself past the expiry rather than completing a message the monitor has already given to someone else.

What that does not do is prevent the lapse, and the cancellation is advisory — a handler that ignores the token still runs to completion. Preventing it is #303: the beat takes 39ms at the median and is never skipped, while the scheduler delivered one tick 9.00s after the previous against a 10s expiry. The lapse is tick latency in a scheduler that dispatches every heartbeat through an internal queue and consumer.

Two other things came out of this and are filed separately:

• Heartbeat scheduler delivers ticks late enough to lose a message's claim #303 — the scheduler latency above, the actual prevention.
• Timestamps are taken from DateTime.UtcNow in places that bypass the configured time provider #304 — roughly 40 places in shipping code taking timestamps from DateTime.UtcNow directly, bypassing the configured time provider. HeartBeatWorker was one of them, which is why a claim's age was being judged against a different clock from the one the monitor ages the stored heartbeat with.

For the record, since this issue carried two wrong readings of mine: the overshoot was never a flaky assertion — an overcount can only mean the good consumer processed a message twice — and one occurrence was a regression I introduced in #301 and filed here as a flake twice before investigating it. Measured at the commit before #285 and at master, the beat-gap tail is unchanged (6.00s vs 6.06s, zero gaps over 9s either side), so there is no evidence the async work widened it.