TimedOutboxSweeper misses ticks when pool threads are blocked, and one Task.Run per publish confirm delays MarkDispatched under load #4560

Describe the bug

Some teams use Post/PostAsync with the InMemoryOutbox and a producer whose publisher confirms arrive out of band, most often Kafka. In that setup the message is only marked dispatched when the confirm arrives, and anything never confirmed has to be re-sent by TimedOutboxSweeper running in the same process. We have reports that under load on Kubernetes (EKS) the sweeper runs rarely or not at all, so unconfirmed messages pile up in memory and are lost if the pod restarts.

We couldn't reproduce it on demand, so we measured each candidate cause separately. Every experiment uses the real TimedOutboxSweeper with TimerInterval = 1 on net9.0 with DOTNET_PROCESSOR_COUNT constrained.

1. The sweeper's tick runs on the shared thread pool and is late whenever pool threads are blocked.

TimedOutboxSweeper.StartAsync creates a System.Threading.Timer whose callback is async void Sweep (TimedOutboxSweeper.cs:77, :104). The callback runs on a pool thread; the comment at :128 ("on a timer thread, so blocking is OK") is wrong. With 200 pool work items blocked:

So a plain BackgroundService awaiting a PeriodicTimer would not fix this. Only a dedicated thread kept time.

A long queue alone did not delay the tick. With 100k+ short Task.Run items pending, the sweeper still ticked every 1.00 s; the runtime appears to queue timer firings ahead of ordinary pool work. The tick only slips when workers are busy or blocked.

2. KafkaMessageProducer (and RmqMessageProducer in RMQ.Sync) queue one Task.Run per delivery report.

See KafkaMessageProducer.RaisePublishConfirmation (:456) and RMQ.Sync/RmqMessageProducer.cs:282-307. This doesn't starve the tick under normal load. Under overload, though, pending work grew by about one item per Post, MarkDispatched fell behind, and the sweeper re-sent messages that had in fact been delivered: about 100 re-sends per sweep in our run. Confirms should be drained through a bounded channel by one long-running worker (as InMemoryMessageProducer already does) rather than one pool item each.

3. The sweeper has no protection against failure.

• An exception rethrown from OutboxProducerMediator.BackgroundDispatchUsingAsync (:762), for example a ConfigurationException from producer lookup, escapes async void Sweep and crashes the process, taking the in-memory outbox with it. TimedOutboxArchiver catches everything (:129-132); the sweeper doesn't.
• CreateScope() (TimedOutboxSweeper.cs:111) is outside the try. If it throws, for example during shutdown, the InMemoryLock is never released, and every later tick logs "Outbox Sweeper is still running - abandoning attempt" for good.
• TimerInterval isn't validated. 0 sweeps once and never again; a negative value makes StartAsync throw.
• No cancellation token or timeout reaches the sweep (OutboxSweeper.cs:79, TimedOutboxSweeper.cs:124). A degraded broker can hold one 100-message sweep for minutes (5 s MessageTimeoutMs per message).

4. You can't see any of this in telemetry.

Nothing records tick lag (when the tick was due vs. when Sweep ran), sweep duration, messages found per sweep, or the abandon/skip events (TimedOutboxSweeper.cs:136, OutboxProducerMediator.cs:775, which are logs only). Draft PR #4484 adds outbox added/cleared counts and publish duration, which is complementary; this issue covers the sweeper's own health signals.

Related

• Each Post sorts the whole in-memory outbox to count outstanding messages, even with no limit set #4554: the outstanding-message check runs on every Post under DI defaults. We hit the same defect; that issue covers it, and this one doesn't duplicate it. It is one source of the pool blocking in (1): each check parks a pool thread in a synchronous .Wait() on a static semaphore (OutboxProducerMediator.cs:1334). Details are in a comment there.
• fix(outbox): enforce maxOutStandingMessages for an async-only outbox #4552: adds GetAwaiter().GetResult() inside the same check for async-only outboxes.
• Add outbox metrics #4484: outbox metrics (draft).

Proposed scope

• Run the sweeper on a dedicated thread.
  • Add an optional TimeProvider parameter; source compatibility only.
  • Make Sweep public and awaitable so it can be tested.
  • Catch everything inside the sweep.
  • Release the lock on every path.
  • Validate TimerInterval.
  • Pass a cancellation token to the sweep.
• Drain Kafka and RMQ.Sync confirms through a bounded channel instead of one Task.Run per delivery report.
• Add OpenTelemetry metrics for the sweeper: tick lag, sweep duration, messages found, abandon/skip counts.
• Add a harness under samples/ that reproduces Post + InMemoryOutbox + async confirms under constrained CPU and shows the new telemetry.

To Reproduce

Two scratch console apps, which we'll turn into the samples/ harness:

• Tick latency: start a TimedOutboxSweeper whose IDistributedLock records each ObtainLockAsync call, park 200 Task.Run(() => gate.Wait()) items, and compare its ticks with a dedicated-thread loop. Run with DOTNET_PROCESSOR_COUNT=1 or 2.
• Full pipeline: CommandProcessor + OutboxProducerMediator + InMemoryOutbox + TimedOutboxSweeper, with a fake producer that delivers on a non-pool thread and calls Task.Run per confirm, as Kafka does. Use 64 concurrent posters.

Further technical details

• Brighter: master at 2890f8610, V10.X
• Observed: EKS under CPU limits. Measured: macOS, .NET 9, DOTNET_PROCESSOR_COUNT = 1 / 2

Analysis and experiments were prepared with the help of an AI assistant.