Skip to content

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

Closed
#9525
#9268
Closed
Pub/Sub: buffered messages delivered multiple times ignoring acknowledgment deadline#9252
#9525
#9268
Assignees
plamut
Labels
api: pubsubIssues related to the Pub/Sub API.priority: p2Moderately-important priority. Fix may not be included in next release.type: bugError or flaw in code with unintended results or allowing sub-optimal usage patterns.
@ghost

Description

@ghost
ghost
opened on Sep 19, 2019

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.

Metadata

Metadata

Assignees

Labels

api: pubsubIssues related to the Pub/Sub API.priority: p2Moderately-important priority. Fix may not be included in next release.type: bugError or flaw in code with unintended results or allowing sub-optimal usage patterns.

Type

No type

Projects

No projects

Milestone

No milestone

Relationships

None yet

Development

No branches or pull requests

Issue actions