Transactions: the pending-ack replay thread can get stuck forever after a lost ledger read #26364
|
In case others have seen it: I ran into transaction pending-ack replay loop. On one broker, a pulsar-transaction-executor-N-1 thread was stuck forever inside MLPendingAckStore$PendingAckReplay.run(), sitting on Thread.sleep(1) (MLPendingAckStore.java:431), and it never recovered on its own. Versions: I confirmed this on 4.0.10. The same replay code is identical on branch-4.1 (4.1.x) and on branch-4.2 (4.2.x): the Thread.sleep(1) replay loop, the single-thread executors that are shared by hash, and the consumer that waits on pendingAckHandleFuture(). All line numbers below are from the 4.0.10 tag (pulsar-broker and managed-ledger). My observation: These replay executors are single-threaded, and many subscriptions share the same thread by hashing. When transactions are enabled, every persistent subscription builds a PendingAckHandle — even consumers that never use transactions — and PersistentSubscription.addConsumerInternal waits for pendingAckHandleFuture() before the consumer can be added. So, if one replay is stuck, every other subscription on that same thread cannot create consumers. It can even turn into a full broker restart if the health-check subscription happens to land on the stuck thread. How it gets stuck: the replay loop (MLPendingAckStore.java:406-439) keeps running until a read either succeeds or fails. A read failure sets isReadable = false (:470), and fillQueue() (:474-483) only starts a new read when outstandingReadsRequests == 0. So, if a read is sent but its callback never comes back:
The result is an endless 1ms sleep loop. Normally a watchdog would rescue this: ManagedLedgerImpl.checkReadTimeout() (ManagedLedgerImpl.java:4531) calls lastReadCallback.readFailed(TimeoutException) after a timeout. But that watchdog is turned off when managedLedgerReadEntryTimeoutSeconds=0, so nothing ever completes the read. Possible trigger: the read gets lost because the ledger it is reading is deleted underneath it — and this does not need a rare bookie garbage-collection race. New ledgers are created with timestamp=0 (ManagedLedgerImpl.java:618 on init, :1640 on rollover; the real timestamp is only written when the ledger is closed, :1846). And hasLedgerRetentionExpired(retentionTimeMs, 0) (:2770-2772) is always true for these system ledgers, which run with retention 0. So, an empty or just-rolled-over pending-ack ledger becomes eligible for deletion right away in internalTrimLedgers (:2967). In other words, the normal create-and-delete of empty ledgers is enough to race the replay read and make its callback disappear. Related issues I found:
A couple of directions that might help: giving PendingAckReplay its own time limit, independent of managedLedgerReadEntryTimeoutSeconds, so it can never loop forever on Thread.sleep(1) (:431); and moving pending-ack replay onto its own executor, the same way #24401 did for the transaction buffer, so one stuck replay can't block unrelated subscriptions. I have a small, repeatable local reproduction (one replay thread, small ledgers, read timeout set to 0) that leaves the executor stuck while the broker otherwise keeps running. Happy to share the reproduction and thread dumps. Has anyone seen this behavior? Does this analysis seem plausible? Could this explain the broker pod restarts, and is there a recommended configuration to avoid it besides setting managedLedgerReadEntryTimeoutSeconds to a non-zero value? |
Replies: 4 comments
|
Thanks for the unusually careful write-up — the stack frame, the line numbers and the co-hashing The short answer to your question
It's still reasonable defence-in-depth, but framing it as the mitigation would be misleading. The thing I think you'll find most interesting
// TopicTransactionBuffer.FillEntryQueueCallback.fillQueue()
if (cursor.hasMoreEntries()) {
outstandingReadsRequests.incrementAndGet();
cursor.asyncReadEntries(...);
} else {
if (entryQueue.size() == 0) {
isReadable = false; // <-- loop exits
}
}// MLPendingAckStore.FillEntryQueueCallback.fillQueue() -- v4.0.10 :474-483
if (cursor.hasMoreEntries()) {
outstandingReadsRequests.incrementAndGet();
readAsync(NUMBER_OF_PER_READ_ENTRY, this);
}
// no else branch
return isReadable;That escape was added by #13739 (
So the project diagnosed this exact stall in the sibling class four years ago, fixed it there, and Why I think the mechanism is differentThe loop guard and the read gate measure different things:
So "there is still work to do" and "there is still something to read" can disagree permanently, with Two smaller corrections, both in your favour in the sense that the bug is worse than stated:
Everything else you wrote holds: the co-hashed single-thread executors, What would settle itThe thread dump can't distinguish the cases — they all park on the same
And yes please — your reproduction would be very welcome. My analysis is code-level only; I Next stepsThis deserves a tracking issue rather than a Q&A thread — happy to open one, or feel free to file it Assisted-by: Claude (Opus 5, Fable) and OpenAI Codex (gpt-5.6-sol). The code paths, line |
|
Filed this as #26368 and opened #26369 with a fix. What the PR does
Three tests, each verified to fail when its corresponding change is reverted. What it does not fixBeing explicit, because it matters for whether this actually covers your incident:
All three are written up in #26368. Still useful from youThe fix addresses the state I could prove. It would be good to know it is the state you actually hit, Review on the PR is welcome, particularly on the Assisted-by: Claude (Opus 5, Fable) and OpenAI Codex (gpt-5.6-sol). The code paths, line numbers |
|
Thanks, @lhotari for the quick response and even the PR on that! We agree that managedLedgerReadEntryTimeoutSeconds is not a fix for this replay loop. A managed-ledger timeout becomes a plain ManagedLedgerException; MLPendingAckStore.readEntriesFailed does not set isReadable=false for it, so replay retries rather than terminating. Our proposed empty-ledger trim race was also incorrect. As you pointed out, internalTrimLedgers is bounded by the slowest durable cursor's mark-delete position. We have now compared two environments and appear to have observed both replay failure modes. SIT: silent replay stall Answers for the SIT incidents:
UAT: repeating read-failure loop
This is clearly the repeatedly failing-read case. It is not evidence of a lost callback because the callbacks were arriving with failures and replay was immediately issuing another read. Answers for the UAT incident:
A separate silent PendingAckReplay shutdown stall occurred again in UAT on 2026-08-05 without a corresponding "stat reply fail!" storm. That reinforces the conclusion that we have encountered both states at different times: the silent no-more-entries stall and the repeatedly failing-read loop. In the attachments you will find the test which I run to "prove" my thesis and the output of the test itself. |
|
This is excellent — thank you. The two environments plus the reproduction settle a lot. Your reproduction is the other state, and #26369 does not fix itI traced it against the PR head. Deleting the ledger gives Both of #26369's new exits are unreachable there: the completion branch requires I filed it instead: #26374, with your reproduction and the UAT numbers as the evidence. Your test's Why that half was never fixedWorth knowing, because it explains the shape: #12700's stated motivation was exactly your scenario — That also means the fix does not need a design discussion, which I had assumed it might: the pinned test On the SIT stallsYour reading matches mine. Silent, no error storm, brokers restarted 5–18 minutes earlier — that is the One detail worth flagging from your point 6: "broker shutdown unloaded topics, but the replay executor Also in #26369 since you last lookedA reviewer spotted that a read still in flight when the replay ends could deliver entries afterwards Nothing further needed from you unless the heap dump turns up. Thanks for the rigour on this one; the Assisted-by: Claude (Opus 5, Fable) and OpenAI Codex (gpt-5.6-sol). Code paths, line numbers and |
This is excellent — thank you. The two environments plus the reproduction settle a lot.
Your reproduction is the other state, and #26369 does not fix it
I traced it against the PR head. Deleting the ledger gives
BKNoSuchLedgerExistsOnMetadataServerException, whichisBkErrorNotRecoverableclassifies asnon-recoverable, so
createManagedLedgerExceptionreturnsLedgerNotExistException. WithautoSkipNonRecoverableData=false,OpReadEntry.internalReadEntriesFailedskips itsadvance-past-the-bad-ledger branch (that branch is gated on auto-skip) and fails the read without
moving the read position. In
readEntriesFailedthat exception matches none of the three cases thatclear
isReadable, so the out…