[Bug] Kafka: message committed without executing subscriber during shutdown, then replayed out of order after FallbackWindowLookbackSeconds
Summary
Kafka: message committed without executing subscriber during shutdown, then replayed out of order after FallbackWindowLookbackSeconds
Steps to Reproduce
During a rolling restart, a received message can be committed to Kafka without its subscriber ever running. The row stays in Scheduled state and is only picked up by the retry processor after FallbackWindowLookbackSeconds. The result is a message on a single partition executing minutes after a higher-offset message from the same partition, with Retries = 0 and no warning or error in the logs.
I understand CAP is at-least-once and does not promise partition ordering after a subscriber failure. This report is about a case where no failure happened and no subscriber code ran: the dispatcher refused the message because CAP was stopping, the caller could not see that, and it committed the offset anyway. The shutdown path that should have prevented this waits on a task that is always already completed.
Environment
- DotNetCore.CAP 10.0.2 (code references below are against
masterat e52b8508) - Transport: Kafka (Confluent.Kafka 2.14.2),
enable.auto.commit = false(CAP default) - Storage: PostgreSQL
FallbackWindowLookbackSeconds = 360,EnableSubscriberParallelExecute = false, noGroupConcurrent- Kubernetes, several replicas, rolling restart
Observed behaviour
Two messages M1 (lower offset) and M2 (higher offset) on the same partition:
| Time | Event |
|---|---|
| 14:37:54.0 | M1 produced and consumed by the pod that was shutting down |
| ~14:40:56 | M2 executed on the pod that took over the partition |
| 14:43:56.2 | M1 executed, Retries = 0, no exception, no retry warning |
M1 executed 362 s after it was stored: FallbackWindowLookbackSeconds plus the wait for the next retry tick (up to FailedRetryInterval). Its row had Added ≈ produce time and status Scheduled until then.
Root cause
On host shutdown
Bootstrappercancels its CTS (IBootstrapper.Default.cs#L122). That token is linked into both theDispatcher(IDispatcher.Default.cs#L60) and theConsumerRegister(IConsumerRegister.Default.cs#L59), so the dispatcher stops accepting work at the same instant polling is asked to stop. There is no ordering between the two.ConsumerRegister.Disposewaits on_compositeTask(#L95), but that field is alwaysTask.CompletedTask(#L165). The listening loops are fire-and-forget (#L134), so nothing is actually drained.The Kafka loop only checks the token at the top of each iteration (KafkaConsumerClient.cs#L107) and
Consume(timeout)(#L113) does not take it, so one more message can be returned after cancellation. The callback stores it asScheduled(IDataStorage.PostgreSql.cs#L197) and callsEnqueueToExecute.EnqueueToExecutesees cancellation and returns silently, without logging (IDispatcher.Default.cs#L118-L121). If it gets past that check,SubscribeExecutorthrowsOperationCanceledExceptionbefore invoking the subscriber (ISubscribeExector.Default.cs#L90) and the dispatcher swallows it (#L132-L135). The method returns a plainValueTask, so the caller cannot distinguish "executed" from "dropped".The very next line commits the offset (IConsumerRegister.Default.cs#L260). Kafka now considers the message done and never redelivers it.
KafkaConsumerClient.DisposeAsynccallsDispose()withoutClose()(KafkaConsumerClient.cs#L157-L161). Per the Confluent.Kafka docs forConsumer.Dispose, no leave-group request is sent and the group only rebalances aftersession.timeout.ms(default 45 s). With the default eager assignment strategy that stalls the whole group. M2's ~3 minute delay is consistent with several pods doing this in sequence during the rollout, though I have not proven that part from CAP code alone.The
Scheduledrow is later returned by the retry query, which selectsScheduledas well asFailedrows older than the lookback (IDataStorage.PostgreSql.cs#L349-L350), and executed byMessageNeedToRetryProcessor(IProcessor.NeedRetry.cs#L97-L103).Retriesis only incremented on the failure path (ISubscribeExector.Default.cs#L144), so the audit trail looks like a clean first attempt.
Ordering is silently handed from Kafka's offset-ordered redelivery to CAP's time-based fallback, which knows nothing about partitions.
Expected behaviour
- No commit when the dispatcher refuses. If
EnqueueToExecutedeclines a message because CAP is stopping,ConsumerRegistermust not commit the offset. Leaving it uncommitted (or callingRejectAsync) lets the next assignee receive it from the broker in order. - Ordered shutdown. Stop polling first, wait for in-flight callbacks with a bounded timeout, then cancel the dispatcher. Today
_compositeTaskdoes not track the listening loops, so the existing 2 s wait is a no-op. - A dropped message must be visible. The early return in
EnqueueToExecuteshould log at warning level like itsEnqueueToPublishcounterpart does. - Kafka:
Close()beforeDispose()so the group rebalances immediately instead of aftersession.timeout.ms.
Possible fix directions
- Have
EnqueueToExecutereturn aValueTask<bool>(accepted or refused). InConsumerRegister, commit only ontrue; onfalseskip the commit (and optionally delete the just-stored row so the fallback does not execute it out of order later). - Track the listening tasks in
_compositeTaskand cancel the consumer token before the dispatcher token, with a configurable drain timeout. - In
KafkaConsumerClient.DisposeAsync, call_consumerClient.Close()beforeDispose().
Expected Behavior
No response
Actual Behavior
No response
Log Output
CAP Configuration
Transport Used
None
Storage Provider
None
Environment
No response
Additional Context
No response
Source: dotnetcore/CAP