Excessive message re-deliveries when consuming from Pubsub

Question

I am noticing a lot of message re-deliveries in my application, even though I have configured max ack deadline for subscription (600 seconds). I am using the async client api for pull-based subscriptions.

Here is an example of the redelivery from my logs:

xxx@XXX-MacBook-Pro Downloads % grep 4352639842273916 ~/Downloads/a.txt 
2022/04/08 15:07:01.123 DEBUG [PubsubConsumerImpl] [Gax-11] #### RECEIVE : 4352639842273916
2022/04/08 15:07:01.123 DEBUG [PubsubConsumerImpl] [Gax-11] #### QUEUED : 4352639842273916
#### RETURNED : 33 : 4352639842273916
2022/04/08 15:07:05.332 DEBUG [PubsubMessageQueue] [github_events__0__0__20220408T2206Z] ### ACK 33 : 4352639842273916
2022/04/08 15:07:05.333 DEBUG [PubsubMessageQueue] [github_events__0__0__20220408T2206Z] ### clear ack 33:4352639842273916
#### 33 : 4352639842273916
2022/04/08 15:07:07.043 DEBUG [PubsubConsumerImpl] [Gax-13] #### RECEIVE : 4352639842273916
2022/04/08 15:07:07.043 WARN [PubsubConsumerImpl] [Gax-13] #### DUPLICATE : 4352639842273916
2022/04/08 15:07:57.352 DEBUG [PubsubConsumerImpl] [Gax-29] #### RECEIVE : 4352639842273916
2022/04/08 15:07:57.352 DEBUG [PubsubConsumerImpl] [Gax-29] #### QUEUED : 4352639842273916
#### RETURNED : 81 : 4352639842273916
2022/04/08 15:07:57.406 DEBUG [PubsubMessageQueue] [github_events__0__1__20220408T2207Z] ### ACK 81 : 4352639842273916
2022/04/08 15:07:57.407 DEBUG [PubsubMessageQueue] [github_events__0__1__20220408T2207Z] ### clear ack 81:4352639842273916
#### 81 : 4352639842273916
2022/04/08 15:08:49.184 DEBUG [PubsubConsumerImpl] [Gax-41] #### RECEIVE : 4352639842273916
2022/04/08 15:08:49.184 DEBUG [PubsubConsumerImpl] [Gax-41] #### QUEUED : 4352639842273916
#### RETURNED : 130 : 4352639842273916
2022/04/08 15:08:49.237 DEBUG [PubsubMessageQueue] [github_events__0__2__20220408T2208Z] ### ACK 130 : 4352639842273916
2022/04/08 15:08:49.237 DEBUG [PubsubMessageQueue] [github_events__0__2__20220408T2208Z] ### clear ack 130:4352639842273916
#### 130 : 4352639842273916

If you look at the line with “DUPLICATE”, it is getting re-delivered within 6 seconds and also, through a different grpc thread (Gax-11 and Gax-13) . Why is the same message being delivered to 2 different threads?

Fyi, in my application, I am trying to consume a batch of messages and ack them all when the processing is complete. I verified that my code is invoking ACK on all the processed messages. I am using flow control to manage the batch of consumed messages. But it doesn't seem to improve the duplicates situation.

Any help would be appreciated!

Answer 1

The main problem of receiving duplicate messages is that the subscriber is too slow to process and acknowledge messages within the deadline even though the maximum ack deadline is set high.. The solution that can be provided at this time is to reduce the subscriber’s queue size means reducing the number of messages that the subscriber pulls at a time. This way the subscriber will have less messages to process within the deadline.

You can reduce the number of outstanding messages for your subscriber. You can try by setting low values to the subscriber.

The reasons for the duplication behavior in subscriptions are due to :

• Messages in the subscriber’s queue are not being processed and ACK'd within the deadline.

• The client library continues to (automatically) extend the deadline hoping to be able to process these messages eventually.

• At some point, after several deadline extensions the client library gives up, so those messages are dropped and redelivered.

• Messages in Pub/Sub are delivered in batches, so not only the expired messages will be redelivered but also the ones belonging to these messages batches.

• The subscriber will have its queue full of duplicates, which slows down backlog consumption; The problem becomes worse and worse since current duplicates will expire as well and generate new duplicates.