Pub/Sub: buffered messages delivered multiple times ignoring acknowledgment deadline

I noticed a problem where buffered messages in pubsub library are delivered multiple times ignoring acknowledgment deadline. I have a subscription with acknowledgment deadline set to 5 minutes but messages are delivered multiple times to the same subscriber after about 30 seconds.

My code example starts a subscriber client with max_messages set to 1. When two messages are sent to the subscriptions, the second message is always duplicated. This same behavior also happens with higher max_messages values. For example, using the default value 100 for max_messages, when 150 messages are sent to the subscription, some of the messages are duplicated if the processing of the first 100 messages takes more than 30 seconds.

I understand that with large backlog of small messages, the messages can get redelivered (Dealing with large backlogs of small messages), however, shouldn't the messages be re-delivered only after the ack_deadline is exceeded?

Environment details

• OS type and version: Ubuntu 18.04.3 LTS
• Python version and virtual environment information: Python 3.7.3
• google-cloud-pubsub version: google-cloud-pubsub==1.0.0

Steps to reproduce

1. Create a subscription with a high ack_deadline.
2. Start subscriber (see code examples): python subscriber.py -p PROJECT_ID SUBSCRIPTION_NAME.
3. Send two messages to the pubsub topic.
4. The second message is duplicated.

Code example

Example subscriber code here: https://gist.github.com/qvik-olli/0bfd4ace2d06def1675a76fbc20493e5

Logs

From the subscriber script:

2019-09-19 14:10:37,740 INFO ThreadPoolExecutor-ThreadScheduler_0: [652240118977134] got message with content: b'0'
2019-09-19 14:10:37,740 INFO ThreadPoolExecutor-ThreadScheduler_0: [652240118977134] sleeping
2019-09-19 14:11:17,747 INFO ThreadPoolExecutor-ThreadScheduler_0: [652240118977134] done sleeping
2019-09-19 14:11:17,819 INFO ThreadPoolExecutor-ThreadScheduler_1: [652240118977135] got message with content: b'1'
2019-09-19 14:11:17,819 INFO ThreadPoolExecutor-ThreadScheduler_1: [652240118977135] sleeping
2019-09-19 14:11:57,859 INFO ThreadPoolExecutor-ThreadScheduler_1: [652240118977135] done sleeping
2019-09-19 14:11:57,986 ERROR ThreadPoolExecutor-ThreadScheduler_0: [652240118977135] Duplicate message!!!

With debug logging from the pubsub library:

2019-09-19 14:10:35,175 DEBUG Thread-LeaseMaintainer: The current p99 value is 10 seconds.
2019-09-19 14:10:35,176 DEBUG Thread-LeaseMaintainer: Snoozing lease management for 6.301498 seconds.
2019-09-19 14:10:37,634 DEBUG Thread-ConsumeBidirectionalStream: recved response.
2019-09-19 14:10:37,634 DEBUG Thread-ConsumeBidirectionalStream: Processing 2 received message(s), currenty on hold 0.
2019-09-19 14:10:37,740 DEBUG Thread-ConsumeBidirectionalStream: Sent request(s) over unary RPC.
2019-09-19 14:10:37,740 DEBUG Thread-ConsumeBidirectionalStream: Message backlog over load at 1.00, pausing.
2019-09-19 14:10:37,740 DEBUG Thread-ConsumeBidirectionalStream: Scheduling callbacks for 1 new messages, new total on hold 1.
2019-09-19 14:10:37,740 INFO ThreadPoolExecutor-ThreadScheduler_0: [652240118977134] got message with content: b'0'
2019-09-19 14:10:37,740 INFO ThreadPoolExecutor-ThreadScheduler_0: [652240118977134] sleeping
2019-09-19 14:10:37,740 DEBUG Thread-ConsumeBidirectionalStream: paused, waiting for waking.
2019-09-19 14:10:41,477 DEBUG Thread-LeaseMaintainer: The current p99 value is 10 seconds.
2019-09-19 14:10:41,477 DEBUG Thread-LeaseMaintainer: Renewing lease for 1 ack IDs.
2019-09-19 14:10:41,539 DEBUG Thread-LeaseMaintainer: Sent request(s) over unary RPC.
2019-09-19 14:10:41,539 DEBUG Thread-LeaseMaintainer: Snoozing lease management for 5.628947 seconds.
2019-09-19 14:10:47,168 DEBUG Thread-LeaseMaintainer: The current p99 value is 10 seconds.
2019-09-19 14:10:47,168 DEBUG Thread-LeaseMaintainer: Renewing lease for 1 ack IDs.
2019-09-19 14:10:47,238 DEBUG Thread-LeaseMaintainer: Sent request(s) over unary RPC.
2019-09-19 14:10:47,238 DEBUG Thread-LeaseMaintainer: Snoozing lease management for 1.232672 seconds.
2019-09-19 14:10:48,471 DEBUG Thread-LeaseMaintainer: The current p99 value is 10 seconds.
2019-09-19 14:10:48,471 DEBUG Thread-LeaseMaintainer: Renewing lease for 1 ack IDs.
2019-09-19 14:10:48,584 DEBUG Thread-LeaseMaintainer: Sent request(s) over unary RPC.
2019-09-19 14:10:48,584 DEBUG Thread-LeaseMaintainer: Snoozing lease management for 0.579531 seconds.
2019-09-19 14:10:49,164 DEBUG Thread-LeaseMaintainer: The current p99 value is 10 seconds.
2019-09-19 14:10:49,164 DEBUG Thread-LeaseMaintainer: Renewing lease for 1 ack IDs.
2019-09-19 14:10:49,242 DEBUG Thread-LeaseMaintainer: Sent request(s) over unary RPC.
2019-09-19 14:10:49,242 DEBUG Thread-LeaseMaintainer: Snoozing lease management for 5.177725 seconds.
2019-09-19 14:10:54,420 DEBUG Thread-LeaseMaintainer: The current p99 value is 10 seconds.
2019-09-19 14:10:54,420 DEBUG Thread-LeaseMaintainer: Renewing lease for 1 ack IDs.
2019-09-19 14:10:54,477 DEBUG Thread-LeaseMaintainer: Sent request(s) over unary RPC.
2019-09-19 14:10:54,477 DEBUG Thread-LeaseMaintainer: Snoozing lease management for 6.448523 seconds.
2019-09-19 14:11:00,926 DEBUG Thread-LeaseMaintainer: The current p99 value is 10 seconds.
2019-09-19 14:11:00,926 DEBUG Thread-LeaseMaintainer: Renewing lease for 1 ack IDs.
2019-09-19 14:11:01,002 DEBUG Thread-LeaseMaintainer: Sent request(s) over unary RPC.
2019-09-19 14:11:01,002 DEBUG Thread-LeaseMaintainer: Snoozing lease management for 7.749161 seconds.
2019-09-19 14:11:02,469 DEBUG Thread-Heartbeater: Sent heartbeat.
2019-09-19 14:11:08,752 DEBUG Thread-LeaseMaintainer: The current p99 value is 10 seconds.
2019-09-19 14:11:08,752 DEBUG Thread-LeaseMaintainer: Renewing lease for 1 ack IDs.
2019-09-19 14:11:08,813 DEBUG Thread-LeaseMaintainer: Sent request(s) over unary RPC.
2019-09-19 14:11:08,813 DEBUG Thread-LeaseMaintainer: Snoozing lease management for 4.640038 seconds.
2019-09-19 14:11:13,454 DEBUG Thread-LeaseMaintainer: The current p99 value is 10 seconds.
2019-09-19 14:11:13,454 DEBUG Thread-LeaseMaintainer: Renewing lease for 1 ack IDs.
2019-09-19 14:11:13,532 DEBUG Thread-LeaseMaintainer: Sent request(s) over unary RPC.
2019-09-19 14:11:13,532 DEBUG Thread-LeaseMaintainer: Snoozing lease management for 4.966822 seconds.
2019-09-19 14:11:17,747 INFO ThreadPoolExecutor-ThreadScheduler_0: [652240118977134] done sleeping
2019-09-19 14:11:17,748 DEBUG Thread-CallbackRequestDispatcher: Handling 1 batched requests
2019-09-19 14:11:17,818 DEBUG Thread-CallbackRequestDispatcher: Sent request(s) over unary RPC.
2019-09-19 14:11:17,818 DEBUG Thread-CallbackRequestDispatcher: Current load: 0.00
2019-09-19 14:11:17,818 DEBUG Thread-CallbackRequestDispatcher: Released held message to leaser, scheduling callback for it, still on hold 0.
2019-09-19 14:11:17,819 INFO ThreadPoolExecutor-ThreadScheduler_1: [652240118977135] got message with content: b'1'
2019-09-19 14:11:17,819 INFO ThreadPoolExecutor-ThreadScheduler_1: [652240118977135] sleeping
2019-09-19 14:11:17,819 DEBUG Thread-CallbackRequestDispatcher: Did not resume, current load is 1.00.
2019-09-19 14:11:18,499 DEBUG Thread-LeaseMaintainer: The current p99 value is 41 seconds.
2019-09-19 14:11:18,499 DEBUG Thread-LeaseMaintainer: Renewing lease for 1 ack IDs.
2019-09-19 14:11:18,575 DEBUG Thread-LeaseMaintainer: Sent request(s) over unary RPC.
2019-09-19 14:11:18,575 DEBUG Thread-LeaseMaintainer: Snoozing lease management for 18.568330 seconds.
2019-09-19 14:11:32,469 DEBUG Thread-Heartbeater: Sent heartbeat.
2019-09-19 14:11:37,144 DEBUG Thread-LeaseMaintainer: The current p99 value is 41 seconds.
2019-09-19 14:11:37,144 DEBUG Thread-LeaseMaintainer: Renewing lease for 1 ack IDs.
2019-09-19 14:11:37,470 DEBUG Thread-LeaseMaintainer: Sent request(s) over unary RPC.
2019-09-19 14:11:37,470 DEBUG Thread-LeaseMaintainer: Snoozing lease management for 5.602221 seconds.
2019-09-19 14:11:43,072 DEBUG Thread-LeaseMaintainer: The current p99 value is 41 seconds.
2019-09-19 14:11:43,072 DEBUG Thread-LeaseMaintainer: Renewing lease for 1 ack IDs.
2019-09-19 14:11:43,146 DEBUG Thread-LeaseMaintainer: Sent request(s) over unary RPC.
2019-09-19 14:11:43,146 DEBUG Thread-LeaseMaintainer: Snoozing lease management for 22.866717 seconds.
2019-09-19 14:11:57,859 INFO ThreadPoolExecutor-ThreadScheduler_1: [652240118977135] done sleeping
2019-09-19 14:11:57,859 DEBUG Thread-CallbackRequestDispatcher: Handling 1 batched requests
2019-09-19 14:11:57,923 DEBUG Thread-CallbackRequestDispatcher: Sent request(s) over unary RPC.
2019-09-19 14:11:57,924 DEBUG Thread-CallbackRequestDispatcher: Current load: 0.00
2019-09-19 14:11:57,924 DEBUG Thread-CallbackRequestDispatcher: Current load is 0.00, resuming consumer.
2019-09-19 14:11:57,924 DEBUG Thread-ConsumeBidirectionalStream: woken.
2019-09-19 14:11:57,924 DEBUG Thread-ConsumeBidirectionalStream: waiting for recv.
2019-09-19 14:11:57,924 DEBUG Thread-ConsumeBidirectionalStream: recved response.
2019-09-19 14:11:57,924 DEBUG Thread-ConsumeBidirectionalStream: Processing 1 received message(s), currenty on hold 0.
2019-09-19 14:11:57,985 DEBUG Thread-ConsumeBidirectionalStream: Sent request(s) over unary RPC.
2019-09-19 14:11:57,986 DEBUG Thread-ConsumeBidirectionalStream: Message backlog over load at 1.00, pausing.
2019-09-19 14:11:57,986 DEBUG Thread-ConsumeBidirectionalStream: Scheduling callbacks for 1 new messages, new total on hold 0.
2019-09-19 14:11:57,986 ERROR ThreadPoolExecutor-ThreadScheduler_0: [652240118977135] Duplicate message!!!
2019-09-19 14:11:57,986 DEBUG Thread-ConsumeBidirectionalStream: paused, waiting for waking.
2019-09-19 14:11:57,986 DEBUG Thread-CallbackRequestDispatcher: Handling 1 batched requests
2019-09-19 14:11:58,087 DEBUG Thread-CallbackRequestDispatcher: Sent request(s) over unary RPC.
2019-09-19 14:11:58,088 DEBUG Thread-CallbackRequestDispatcher: Current load: 0.00
2019-09-19 14:11:58,088 DEBUG Thread-CallbackRequestDispatcher: Current load is 0.00, resuming consumer.
2019-09-19 14:11:58,088 DEBUG Thread-ConsumeBidirectionalStream: woken.
2019-09-19 14:11:58,088 DEBUG Thread-ConsumeBidirectionalStream: waiting for recv.
2019-09-19 14:12:02,470 DEBUG Thread-Heartbeater: Sent heartbeat.
2019-09-19 14:12:06,013 DEBUG Thread-LeaseMaintainer: The current p99 value is 81 seconds.
2019-09-19 14:12:06,013 DEBUG Thread-LeaseMaintainer: Snoozing lease management for 71.733369 seconds.

[plamut]

@qvik-olli Thanks for the detailed report!

This sounds as if the request(s) to modify the message acknowledge deadline do not arrive in time, and the backend re-sends the message. Can you check if the subscription's max ACK deadline is indeed set to 300 seconds (5 minutes), and not just to e.g. the reported 30 seconds because of a typo or something?

Technical details:
Received messages that exceed the max_messages setting are put into a waiting buffer until the lease manager's load drops under a certain threshold, at which point some of these messages are released to the lease management.

The messages in the buffer are not lease-managed, and if they need to wait there for longer than the acknowledgment deadline, the backend assumes they got lost and re-sends them.

Processing the first message takes ~40 seconds, which exceeds the default subscription's ACK deadline of 10 seconds. However, if the deadline is indeed correctly set to 300 seconds (5 minutes), the reported behavior is actually surprising and would require a deeper look.

Thank you @plamut for your quick response. I'm sure about the ack deadline and I double-checked that it is 300 seconds (5 minutes).

You can forget what I said about 30 seconds. I did some further testing and it seems that there is some dynamic timeout that seems to be changing depending on how long does it take to process a batch of messages. This timeout seems to ignore ack deadline.

I did some tests with larger amount of messages. I used the script you can find in my first message. I set the message handler to sleep 1 second when a message arrived. max_messages was set to 1 and ack deadline was set to 600 seconds:

2019-09-20 09:09:29,188 INFO MainThread: Subscriber started
2019-09-20 09:09:34,777 INFO ThreadPoolExecutor-ThreadScheduler_0: [652265204686881] got message with content: b'1'
2019-09-20 09:09:34,778 INFO ThreadPoolExecutor-ThreadScheduler_0: [652265204686881] sleeping
2019-09-20 09:09:35,779 INFO ThreadPoolExecutor-ThreadScheduler_0: [652265204686881] done sleeping
2019-09-20 09:09:35,850 INFO ThreadPoolExecutor-ThreadScheduler_1: [652265204686882] got message with content: b'2'
2019-09-20 09:09:35,851 INFO ThreadPoolExecutor-ThreadScheduler_1: [652265204686882] sleeping
2019-09-20 09:09:36,852 INFO ThreadPoolExecutor-ThreadScheduler_1: [652265204686882] done sleeping
---snip---sending 60 messages with each taking 1 second to handle---
2019-09-20 09:10:36,946 INFO ThreadPoolExecutor-ThreadScheduler_9: [652265204686939] got message with content: b'59'
2019-09-20 09:10:36,947 INFO ThreadPoolExecutor-ThreadScheduler_9: [652265204686939] sleeping
2019-09-20 09:10:37,948 INFO ThreadPoolExecutor-ThreadScheduler_9: [652265204686939] done sleeping
2019-09-20 09:10:37,997 INFO ThreadPoolExecutor-ThreadScheduler_6: [652265204686940] got message with content: b'60'
2019-09-20 09:10:37,997 INFO ThreadPoolExecutor-ThreadScheduler_6: [652265204686940] sleeping
2019-09-20 09:10:38,998 INFO ThreadPoolExecutor-ThreadScheduler_6: [652265204686940] done sleeping
2019-09-20 09:10:39,170 ERROR ThreadPoolExecutor-ThreadScheduler_3: [652265204686891] Duplicate message!!!
2019-09-20 09:10:39,259 ERROR ThreadPoolExecutor-ThreadScheduler_0: [652265204686892] Duplicate message!!!
2019-09-20 09:10:39,377 ERROR ThreadPoolExecutor-ThreadScheduler_5: [652265204686893] Duplicate message!!!
---snip---all together 145 duplicate messages---
2019-09-20 09:10:54,913 ERROR ThreadPoolExecutor-ThreadScheduler_8: [652265204686938] Duplicate message!!!
2019-09-20 09:10:55,011 ERROR ThreadPoolExecutor-ThreadScheduler_9: [652265204686939] Duplicate message!!!
2019-09-20 09:10:55,125 ERROR ThreadPoolExecutor-ThreadScheduler_6: [652265204686940] Duplicate message!!!
2019-09-20 09:10:59,245 INFO ThreadPoolExecutor-ThreadScheduler_7: [652265042758581] got message with content: b'1'
2019-09-20 09:10:59,245 INFO ThreadPoolExecutor-ThreadScheduler_7: [652265042758581] sleeping
2019-09-20 09:11:00,246 INFO ThreadPoolExecutor-ThreadScheduler_7: [652265042758581] done sleeping
2019-09-20 09:11:00,318 INFO ThreadPoolExecutor-ThreadScheduler_4: [652265042758582] got message with content: b'2'
2019-09-20 09:11:00,318 INFO ThreadPoolExecutor-ThreadScheduler_4: [652265042758582] sleeping
2019-09-20 09:11:01,320 INFO ThreadPoolExecutor-ThreadScheduler_4: [652265042758582] done sleeping
---snip---sending another 60 messages---
2019-09-20 09:12:00,801 INFO ThreadPoolExecutor-ThreadScheduler_9: [652265042758639] got message with content: b'59'
2019-09-20 09:12:00,801 INFO ThreadPoolExecutor-ThreadScheduler_9: [652265042758639] sleeping
2019-09-20 09:12:01,803 INFO ThreadPoolExecutor-ThreadScheduler_9: [652265042758639] done sleeping
2019-09-20 09:12:01,886 INFO ThreadPoolExecutor-ThreadScheduler_2: [652265042758640] got message with content: b'60'
2019-09-20 09:12:01,886 INFO ThreadPoolExecutor-ThreadScheduler_2: [652265042758640] sleeping
2019-09-20 09:12:02,887 INFO ThreadPoolExecutor-ThreadScheduler_2: [652265042758640] done sleeping
2019-09-20 09:12:03,077 ERROR ThreadPoolExecutor-ThreadScheduler_7: [652265042758640] Duplicate message!!!
2019-09-20 09:12:14,436 INFO ThreadPoolExecutor-ThreadScheduler_4: [652264914144087] got message with content: b'1'
2019-09-20 09:12:14,436 INFO ThreadPoolExecutor-ThreadScheduler_4: [652264914144087] sleeping
2019-09-20 09:12:15,437 INFO ThreadPoolExecutor-ThreadScheduler_4: [652264914144087] done sleeping
2019-09-20 09:12:15,609 INFO ThreadPoolExecutor-ThreadScheduler_8: [652264914144088] got message with content: b'2'
2019-09-20 09:12:15,609 INFO ThreadPoolExecutor-ThreadScheduler_8: [652264914144088] sleeping
2019-09-20 09:12:16,610 INFO ThreadPoolExecutor-ThreadScheduler_8: [652264914144088] done sleeping
---snip---sending another 60 messages---
2019-09-20 09:13:16,882 INFO ThreadPoolExecutor-ThreadScheduler_2: [652264914144145] got message with content: b'59'
2019-09-20 09:13:16,882 INFO ThreadPoolExecutor-ThreadScheduler_2: [652264914144145] sleeping
2019-09-20 09:13:17,883 INFO ThreadPoolExecutor-ThreadScheduler_2: [652264914144145] done sleeping
2019-09-20 09:13:17,948 INFO ThreadPoolExecutor-ThreadScheduler_3: [652264914144146] got message with content: b'60'
2019-09-20 09:13:17,948 INFO ThreadPoolExecutor-ThreadScheduler_3: [652264914144146] sleeping
2019-09-20 09:13:18,949 INFO ThreadPoolExecutor-ThreadScheduler_3: [652264914144146] done sleeping
2019-09-20 09:13:19,194 ERROR ThreadPoolExecutor-ThreadScheduler_4: [652264914144146] Duplicate message!!!
2019-09-20 09:13:46,466 INFO ThreadPoolExecutor-ThreadScheduler_8: [652264749734941] got message with content: b'1'
2019-09-20 09:13:46,466 INFO ThreadPoolExecutor-ThreadScheduler_8: [652264749734941] sleeping
2019-09-20 09:13:47,467 INFO ThreadPoolExecutor-ThreadScheduler_8: [652264749734941] done sleeping
2019-09-20 09:13:47,512 INFO ThreadPoolExecutor-ThreadScheduler_1: [652264749734942] got message with content: b'2'
2019-09-20 09:13:47,512 INFO ThreadPoolExecutor-ThreadScheduler_1: [652264749734942] sleeping
2019-09-20 09:13:48,513 INFO ThreadPoolExecutor-ThreadScheduler_1: [652264749734942] done sleeping
---snip---sending 100 messages---
2019-09-20 09:15:30,324 INFO ThreadPoolExecutor-ThreadScheduler_2: [652264749735038] sleeping
2019-09-20 09:15:31,325 INFO ThreadPoolExecutor-ThreadScheduler_2: [652264749735038] done sleeping
2019-09-20 09:15:31,372 INFO ThreadPoolExecutor-ThreadScheduler_3: [652264749735039] got message with content: b'99'
2019-09-20 09:15:31,372 INFO ThreadPoolExecutor-ThreadScheduler_3: [652264749735039] sleeping
2019-09-20 09:15:32,373 INFO ThreadPoolExecutor-ThreadScheduler_3: [652264749735039] done sleeping
2019-09-20 09:15:32,418 INFO ThreadPoolExecutor-ThreadScheduler_0: [652264749735040] got message with content: b'100'
2019-09-20 09:15:32,418 INFO ThreadPoolExecutor-ThreadScheduler_0: [652264749735040] sleeping
2019-09-20 09:15:33,419 INFO ThreadPoolExecutor-ThreadScheduler_0: [652264749735040] done sleeping
2019-09-20 09:15:33,573 ERROR ThreadPoolExecutor-ThreadScheduler_8: [652264749735001] Duplicate message!!!
2019-09-20 09:15:33,693 ERROR ThreadPoolExecutor-ThreadScheduler_1: [652264749735002] Duplicate message!!!
2019-09-20 09:15:33,811 ERROR ThreadPoolExecutor-ThreadScheduler_6: [652264749735003] Duplicate message!!!
---snip---all together 95 duplicate messages---
2019-09-20 09:15:43,785 ERROR ThreadPoolExecutor-ThreadScheduler_6: [652264749735038] Duplicate message!!!
2019-09-20 09:15:43,858 ERROR ThreadPoolExecutor-ThreadScheduler_7: [652264749735039] Duplicate message!!!
2019-09-20 09:15:43,938 ERROR ThreadPoolExecutor-ThreadScheduler_0: [652264749735040] Duplicate message!!!

So when I started the subscriber and sent the first 60 messages, I got 145 duplicates. When I sent another 60 messages, I got just one duplicate message. After that, I sent 100 messages and I got a high amount of duplicates again.

[plamut]

Interesting, I will try to run it today myself and see if I can reproduce it. I do not see anything apparent in the client itself, but I have not looked too deeply yet.

Update:
I was able to reproduce the reported behavior, and it's indeed unexpected. The key bit is that both messages need to be delivered in a single server response (so that one of them is temporarily put on hold into a buffer).

This can be achieved by rapidly publishing them one after another, i.e. without waiting on each individual publish future, which results in both messages being sent to the backend in the same publish batch.

[plamut]

After experimenting with various things, I was not able to pinpoint the exact source of the issue (in the client at least).

It appears that if the delay in the message handler is considerably shorter than 10 seconds, the issue is not reproducible. The probability of a duplicate message increases when the time.sleep() interval is around 10 seconds (8 - 12), and approaches one with delays longer than that.

I also tried disabling the automatic modifications of the ACK deadlines, just in case the related client's logic is flawed:

diff --git a/pubsub/google/cloud/pubsub_v1/subscriber/_protocol/dispatcher.py b/pubsub/google/cloud/pubsub_v1/subscriber/_protocol/dispatcher.py
index 2b257482930..d6b1d2c54d0 100644
--- a/pubsub/google/cloud/pubsub_v1/subscriber/_protocol/dispatcher.py
+++ b/pubsub/google/cloud/pubsub_v1/subscriber/_protocol/dispatcher.py
@@ -152,7 +156,10 @@ class Dispatcher(object):
         """
         ack_ids = [item.ack_id for item in items]
         seconds = [item.seconds for item in items]
-
+        #################
+        _LOGGER.debug(f"\x1b[33m(DISABLED) Modifying ACK deadline to {seconds}, ACK IDs: {ack_ids}\x1b[0m")
+        return
+        ######################
         request = types.StreamingPullRequest(
             modify_deadline_ack_ids=ack_ids, modify_deadline_seconds=seconds
         )

The result was the same, which makes me think it might be something with the subscription on the backend (the ACK deadline is set to 300 seconds), and that the deadline expected by the server is actually around 10 seconds, in my case at least.

I did some further testing and it seems that there is some dynamic timeout that seems to be changing depending on how long does it take to process a batch of messages. This timeout seems to ignore ack deadline.

I got a similar impression. The actual server-side deadline does not seem to be static. If it was really, say, 10 seconds, a sleep delay of 8 seconds should almost definitely not reproduce the issue, and at the same time a delay of 12 seconds should always reproduce it - but the outcome of the test script was not deterministic.

Labeling as a backend issue until further evidence.

[kamalaboulhosn]

I don't think this is a backend issue. Looking at some logs, it appears that the server is delivering the message based on its understanding of the ack deadline with no unexpected duplicates. I think there are two things at play here:

1. The client library sets the ack deadline on the stream based on the 99th percentile ack latency. This overrides the ack deadline set on the subscription at the time it is created. By default, this deadline is 10 seconds. We do this because there is a tradeoff with ack deadlines between more time to process and delays in redelivery if a client goes down or becomes unhealthy. The client library changes the ack deadline for the streams it creates and then calls ModifyAckDeadline up to the specified max_lease_duration in the FlowControl settings.

2. It looks like these ModifyAckDeadlines are arriving a little late, a second or two beyond the time of the deadline expiry. I suspect this means that the client library is not sending the ModifyAckDeadlines soon enough, possibly because they are buffered or something like that.

[plamut]

The client library sets the ack deadline on the stream based on the 99th percentile ack latency.

Indeed, although the issue was reproducible even with these calls disabled. However, it appears that the topic ACK deadline is overridden even before pulling the messages start, i.e. when the stream is established. This key piece of info is missing in the client debug logs and needs to be added (along with the fix for the observed behavior).

Thanks for checking the backend logs, @kamalaboulhosn !