Flush buffered acknowledgements from the shutdown wait - #1663
Conversation
c44f3b9 to
6de8842
Compare
|
Thanks @hyeongguen-song, great analysis and writeup. I have three asks so we can close this class of bug for good if you're up for it.
This would make the drain a guarantee of the shutdown path itself, and also covers This would need to be inside the loop: the polling thread can hold a just-polled message when the queue looks empty. What do you think?
Let me know your thoughts. |
6de8842 to
fc0f737
Compare
Messages left in the acknowledgement buffer below the acknowledgement threshold were never flushed on shutdown. The processor spun for the whole acknowledgementShutdownTimeout, logged Acknowledgements did not finish in 20000 ms. Proceeding with shutdown. and then cleared the buffer, so those messages were never deleted from SQS and were redelivered once the visibility timeout expired. Drain the buffer from the shutdown wait loop instead, which makes the flush a guarantee of the shutdown path itself rather than something that depends on a scheduled execution being armed. This also covers acknowledgementInterval = ZERO with a positive threshold, where no scheduled execution is ever created and a remainder was lost on every shutdown. The flush waits for the ack queue to drain so batches are not needlessly split, and it is retried on every iteration of the wait loop: the polling thread may be holding a message it has already polled but not yet added to the buffer, in which case the queue looks empty while the message is in neither the queue nor the buffer. Also make running volatile in AbstractOrderingAcknowledgementProcessor. It is written under lifecycleMonitor but read without synchronization from the polling and scheduler threads, so those threads had no guarantee of observing stop(). Issue awspring#1661
fc0f737 to
b5ab913
Compare
|
All three make sense to me — pushed. Details below. 1. Flush from the shutdown wait. Agreed, and your
Implemented as you described, gated on private void flushRemainingAcks() {
if (!this.acks.isEmpty()) {
return;
}
this.context.lock();
try {
this.context.executeAllAcks();
}
finally {
this.context.unlock();
}
}The futures go through 2. I could not reproduce the ~1-in-3 rate, though. On JDK 17.0.19 / arm64, 15
So the visibility of 3. Tests. Replaced my test with your A and B. A uses a latch in the Full module is green: 636 tests, 0 failures, 6 skipped, spotless checks enabled, One thing I noticed while working through your "the polling thread can hold a Message<T> polledMessage = this.acks.poll(1, TimeUnit.SECONDS); // removed from acks
if (polledMessage != null) {
addMessageToBuffer(polledMessage); // not in the buffer yetIn between, the message is in neither |
|
Thanks for the issue and PR @hyeongguen-song. This addresses both the sub-threshold remainder scenario you initially brought up, the interval = ZERO case, and makes
Yes, let's squash this one as well. It's a narrow window that can only affect one message per shutdown, but as you said under contention it widens up. |
…1664) hasAcksLeft() decided whether the shutdown wait was done by looking at the ack queue and the buffer. A message the polling thread has already taken off the queue but not yet added to the buffer is in neither: Message<T> polledMessage = this.acks.poll(1, TimeUnit.SECONDS); if (polledMessage != null) { addMessageToBuffer(polledMessage); If the wait loop sampled in that window it saw nothing left and returned, waitAcknowledgementsToFinish() then set isTimeoutElapsed and cleared the buffer, and the polling thread added the message to a buffer nothing would ever flush. Unlike the shutdown timeout case, this dropped the message with no warning at all. Track the messages that have been received but are not in the queue nor the buffer yet, and include them in hasAcksLeft(). The counter is incremented before the message is offered to the queue and decremented after it has been added to the buffer, so it is never undercounted; the brief double counting while the message sits in the buffer only makes the wait more conservative. At most one message per shutdown can be in this window, but it widens whenever addMessageToBuffer() has to wait on the buffer lock, which happens while an execution is being dispatched - and for AcknowledgementOrdering.ORDERED, that dispatch takes the ordered execution lock while holding the buffer lock. Follow-up to #1663.
Messages left in the acknowledgement buffer below the acknowledgement threshold were never flushed on shutdown. The processor spun for the whole acknowledgementShutdownTimeout, logged Acknowledgements did not finish in 20000 ms. Proceeding with shutdown. and then cleared the buffer, so those messages were never deleted from SQS and were redelivered once the visibility timeout expired. Drain the buffer from the shutdown wait loop instead, which makes the flush a guarantee of the shutdown path itself rather than something that depends on a scheduled execution being armed. This also covers acknowledgementInterval = ZERO with a positive threshold, where no scheduled execution is ever created and a remainder was lost on every shutdown. The flush waits for the ack queue to drain so batches are not needlessly split, and it is retried on every iteration of the wait loop: the polling thread may be holding a message it has already polled but not yet added to the buffer, in which case the queue looks empty while the message is in neither the queue nor the buffer. Also make running volatile in AbstractOrderingAcknowledgementProcessor. It is written under lifecycleMonitor but read without synchronization from the polling and scheduler threads, so those threads had no guarantee of observing stop(). Issue #1661 (cherry picked from commit 40721da)
…1664) hasAcksLeft() decided whether the shutdown wait was done by looking at the ack queue and the buffer. A message the polling thread has already taken off the queue but not yet added to the buffer is in neither: Message<T> polledMessage = this.acks.poll(1, TimeUnit.SECONDS); if (polledMessage != null) { addMessageToBuffer(polledMessage); If the wait loop sampled in that window it saw nothing left and returned, waitAcknowledgementsToFinish() then set isTimeoutElapsed and cleared the buffer, and the polling thread added the message to a buffer nothing would ever flush. Unlike the shutdown timeout case, this dropped the message with no warning at all. Track the messages that have been received but are not in the queue nor the buffer yet, and include them in hasAcksLeft(). The counter is incremented before the message is offered to the queue and decremented after it has been added to the buffer, so it is never undercounted; the brief double counting while the message sits in the buffer only makes the wait more conservative. At most one message per shutdown can be in this window, but it widens whenever addMessageToBuffer() has to wait on the buffer lock, which happens while an execution is being dispatched - and for AcknowledgementOrdering.ORDERED, that dispatch takes the ordered execution lock while holding the buffer lock. Follow-up to #1663. (cherry picked from commit 423f8b7)
Messages left in the acknowledgement buffer below the acknowledgement threshold were never flushed on shutdown. The processor spun for the whole acknowledgementShutdownTimeout, logged Acknowledgements did not finish in 20000 ms. Proceeding with shutdown. and then cleared the buffer, so those messages were never deleted from SQS and were redelivered once the visibility timeout expired. Drain the buffer from the shutdown wait loop instead, which makes the flush a guarantee of the shutdown path itself rather than something that depends on a scheduled execution being armed. This also covers acknowledgementInterval = ZERO with a positive threshold, where no scheduled execution is ever created and a remainder was lost on every shutdown. The flush waits for the ack queue to drain so batches are not needlessly split, and it is retried on every iteration of the wait loop: the polling thread may be holding a message it has already polled but not yet added to the buffer, in which case the queue looks empty while the message is in neither the queue nor the buffer. Also make running volatile in AbstractOrderingAcknowledgementProcessor. It is written under lifecycleMonitor but read without synchronization from the polling and scheduler threads, so those threads had no guarantee of observing stop(). Issue awspring#1661 (cherry picked from commit 40721da)
…wspring#1664) hasAcksLeft() decided whether the shutdown wait was done by looking at the ack queue and the buffer. A message the polling thread has already taken off the queue but not yet added to the buffer is in neither: Message<T> polledMessage = this.acks.poll(1, TimeUnit.SECONDS); if (polledMessage != null) { addMessageToBuffer(polledMessage); If the wait loop sampled in that window it saw nothing left and returned, waitAcknowledgementsToFinish() then set isTimeoutElapsed and cleared the buffer, and the polling thread added the message to a buffer nothing would ever flush. Unlike the shutdown timeout case, this dropped the message with no warning at all. Track the messages that have been received but are not in the queue nor the buffer yet, and include them in hasAcksLeft(). The counter is incremented before the message is offered to the queue and decremented after it has been added to the buffer, so it is never undercounted; the brief double counting while the message sits in the buffer only makes the wait more conservative. At most one message per shutdown can be in this window, but it widens whenever addMessageToBuffer() has to wait on the buffer lock, which happens while an execution is being dispatched - and for AcknowledgementOrdering.ORDERED, that dispatch takes the ordered execution lock while holding the buffer lock. Follow-up to awspring#1663. (cherry picked from commit 423f8b7)
Messages left in the acknowledgement buffer below the acknowledgement threshold were never flushed on shutdown. The processor spun for the whole acknowledgementShutdownTimeout, logged Acknowledgements did not finish in 20000 ms. Proceeding with shutdown. and then cleared the buffer, so those messages were never deleted from SQS and were redelivered once the visibility timeout expired. Drain the buffer from the shutdown wait loop instead, which makes the flush a guarantee of the shutdown path itself rather than something that depends on a scheduled execution being armed. This also covers acknowledgementInterval = ZERO with a positive threshold, where no scheduled execution is ever created and a remainder was lost on every shutdown. The flush waits for the ack queue to drain so batches are not needlessly split, and it is retried on every iteration of the wait loop: the polling thread may be holding a message it has already polled but not yet added to the buffer, in which case the queue looks empty while the message is in neither the queue nor the buffer. Also make running volatile in AbstractOrderingAcknowledgementProcessor. It is written under lifecycleMonitor but read without synchronization from the polling and scheduler threads, so those threads had no guarantee of observing stop(). Issue #1661 (cherry picked from commit 40721da)
…1664) hasAcksLeft() decided whether the shutdown wait was done by looking at the ack queue and the buffer. A message the polling thread has already taken off the queue but not yet added to the buffer is in neither: Message<T> polledMessage = this.acks.poll(1, TimeUnit.SECONDS); if (polledMessage != null) { addMessageToBuffer(polledMessage); If the wait loop sampled in that window it saw nothing left and returned, waitAcknowledgementsToFinish() then set isTimeoutElapsed and cleared the buffer, and the polling thread added the message to a buffer nothing would ever flush. Unlike the shutdown timeout case, this dropped the message with no warning at all. Track the messages that have been received but are not in the queue nor the buffer yet, and include them in hasAcksLeft(). The counter is incremented before the message is offered to the queue and decremented after it has been added to the buffer, so it is never undercounted; the brief double counting while the message sits in the buffer only makes the wait more conservative. At most one message per shutdown can be in this window, but it widens whenever addMessageToBuffer() has to wait on the buffer lock, which happens while an execution is being dispatched - and for AcknowledgementOrdering.ORDERED, that dispatch takes the ordered execution lock while holding the buffer lock. Follow-up to #1663. (cherry picked from commit 423f8b7)
📢 Type of change
📜 Description
Fixes #1661.
Messages left in the acknowledgement buffer below
acknowledgementThresholdarenever flushed on shutdown. The processor spins for the whole
acknowledgementShutdownTimeout, logsand then clears the buffer, so those messages are never deleted from SQS and are
redelivered once the visibility timeout expires.
The buffer is now drained from the shutdown wait loop:
runninginAbstractOrderingAcknowledgementProcessoris also madevolatile.💡 Motivation and Context
There are two independent ways to lose the remainder, and draining from the
shutdown wait covers both:
With a scheduled execution.
AbstractOrderingAcknowledgementProcessor.stop()sets
running = falsebefore callingdoStop(), soscheduleNextExecution()refuses to arm the next execution. The polling thread keeps running until the
shutdown timeout elapses (
shouldKeepPollingAcks()), so it goes on movingmessages into the buffer, and each threshold execution pushes
lastAcknowledgementforward. The one already-armed execution then fires withlastAcknowledgementnewer than the time it was armed, skips the flush becausenowis not afterlastAcknowledgement + ackInterval, and cannot re-arm.With no scheduled execution at all.
ScheduledAcknowledgementExecution.start()only arms anything when
ackInterval != Duration.ZERO. WithacknowledgementInterval = ZEROand a positive threshold — a configurationdoStart()explicitly allows — the threshold path is the only flush mechanism,so a sub-threshold remainder is lost on every shutdown.
Making the drain part of the shutdown path itself covers both, instead of
depending on a scheduled execution existing and being armed.
Two details in the implementation:
polling thread may be holding a message it has already polled but not yet added
to the buffer, in which case the queue looks empty while the message is in
neither the queue nor the buffer.
runningwas written underlifecycleMonitorbut read unsynchronized from thepolling and scheduler threads via
isRunning(), so neither thread had anyguarantee of observing
stop().This is load-dependent in the scheduled case, which is why it is easy to miss. It
needs the threshold path to be the dominant flush path, i.e. messages arriving
faster than one
acknowledgementIntervalper batch. We hit it in production aftera scaling change raised per-pod throughput several-fold: pod terminations started
leaving a small number of messages undeleted, visible as a gap between
NumberOfMessagesReceivedandNumberOfMessagesDeletedand as a spike inApproximateAgeOfOldestMessagematching the visibility timeout.💚 How did you test it?
Two new tests, one per loss path. Both are behaviour-only and do not reach into
internals:
givenScheduledAcknowledgement_whenStoppedWithRemainderBelowThreshold_...acksexactly
acknowledgementThresholdmessages, waits on a latch in theacknowledgement executor so the threshold flush is known to have completed, then
acks a sub-threshold remainder and stops. The interval outlasts the shutdown
timeout, so a scheduled execution exists but provably cannot fire during the
test.
givenZeroIntervalAndThreshold_whenStoppedWithRemainderBelowThreshold_...usesacknowledgementInterval = ZERO, where no scheduled execution exists.Both fail on
mainand pass with this change. Measured on JDK 17.0.19, 15consecutive runs each:
main+volatileonlymainunchangedOn failure each test spins the full 10 s shutdown timeout and loses exactly the
5-message remainder.
The three existing shutdown tests could not catch either path: they all use
acknowledgementInterval(Duration.ZERO)so no scheduled execution is evercreated, and they use exactly 100 messages against a threshold of 10, so no
remainder is ever left in the buffer.
Full module:
./mvnw -pl spring-cloud-aws-sqs -am testgives 636 tests, 0failures, 0 errors, 6 skipped, spotless checks enabled, including the LocalStack
integration tests.
Rebased onto
mainafter #1662 landed, and re-verified with no local patchesapplied.
📝 Checklist
No documentation change needed: this restores the documented behaviour rather
than changing it.
🔮 Next steps
Users who cannot wait for a release can switch to an
ImmediateAcknowledgementProcessor, which has no buffer and no scheduler, bysetting
acknowledgementInterval(Duration.ZERO)and leavingacknowledgementThresholdunset —StandardSqsComponentFactoryselects it whenthe interval is
ZEROand the threshold isnullor0. Anyone who hasexplicitly configured a positive threshold needs to set it back to
0as well,otherwise they still get the batching processor and the second path above.