2

I experience very strange floating bug() when I test application in GCP environment. I can't find out concrete steps to reproduce but it really happens from time to time.

I see that message was successfully acknowledged:

2019-12-06 12:37:47.348  INFO 1 --- [sub-subscriber3] .i.g.MyAcknowledgementHandler : Acknowledged message - 1575635858865987

I have following code to acknowledge:

        var generation = message.getHeaders().get("objectGeneration");
        pubSubMessage = message.getHeaders().get(GcpPubSubHeaders.ORIGINAL_MESSAGE, BasicAcknowledgeablePubsubMessage.class)
        pubSubMessage.ack().addCallback(
                v -> {
                    removeFromIdempotentStore(targetMessage, false);
                    log.info("Acknowledged message - {}", generation);
                },
                e -> {
                    removeFromIdempotentStore(targetMessage, false);
                    log.error("Failed to acknowledge message - {}", generation, e);
                }
        );

Also I see following log:

2019-12-06 12:37:48.868 WARN 1 --- [sub-subscriber1] c.b.m.i.MyDiscardedMessagesHandler : Duplicate message received GenericMessage [... headers={gcp_pubsub_acknowledgement=org.springframework.cloud.gcp.pubsub.integration.inbound.PubSubInboundChannelAdapter$1@1abafe68, bxwid=12345, errorChannel=org.springframework.messaging.core.GenericMessagingTemplate$TemporaryReplyChannel@3c3efd63, idempotent.keys=[objectId.mixed emails.csv, objectGeneration.1575635858865987].....

And it repeats endless. Additionally I see in the subscription diagram that message still there(after acknowledgement callback invocation)

Discard logic:

....
.gateway(nexrFlow, idempotentByHeader("objectId")); 


Consumer<GatewayEndpointSpec> idempotentByHeader(String objectIdHeader) {
    return endpointSpec -> endpointSpec.advice(idempotentByHeaderInterceptor(objectIdHeader))
            .errorChannel(errorChannel())
            .replyTimeout(0L);
}

default IdempotentReceiverInterceptor idempotentByHeaderInterceptor(String header) {
    MessageProcessor<String> headerSelector = message -> headerExpression(header).apply(message);
    var interceptor = new IdempotentReceiverInterceptor(new MetadataStoreSelector(headerSelector, idempotencyStore()));
    interceptor.setDiscardChannel(idempotentDiscardChannel());
    return interceptor;
}

I have no ideas how to troubleshoot it. Any ideas?

gstackoverflow
  • 31,683
  • 83
  • 267
  • 574
  • Did you check the value of `ObjectID` stored? I guess that the deduplication is performed on this field – guillaume blaquiere Dec 09 '19 at 16:30
  • @guillaume blaquiere yes I did it. This header contains file name – gstackoverflow Dec 09 '19 at 16:52
  • And you are sure of your message uniqueness? there isn't 2 send in the same time? – guillaume blaquiere Dec 09 '19 at 17:02
  • @guillaume blaquiere I am 100% sure it is the same messages. they always have the same *message_id* – gstackoverflow Dec 10 '19 at 11:50
  • @gstackoverflow in order to reproduce this correctly, could you provide us with your Pub/Sub client version and [AckDeadline](https://github.com/googleapis/google-cloud-go/issues/778#issuecomment-334065162)? – Javier Bóbeda Dec 11 '19 at 08:23
  • @Javier Bóbeda I am not sure I understand what *Pub/Sub client version* means. But I use **spring-boot 2.2.0.RELEASE** which contains version of **spring-cloud-gcp-starter-pubsub** – gstackoverflow Dec 11 '19 at 09:55
  • https://stackoverflow.com/questions/59391264/message-is-received-from-google-pub-sub-subscription-again-and-again-after-ackno – gstackoverflow Dec 22 '19 at 16:03
  • As explained by Maximus Macdonald in that thread, the best path would be to contact Google Cloud Platform. Their internal tools that will help to troubleshoot this in much more detail. – Javier Bóbeda Jan 17 '20 at 08:24

1 Answers1

3

Pub/sub is designed to guarantee at-least-one-message delivery, so this is expected behavior. Check out the product FAQs for the official explanation.

As stated there, one reason for frequent duplicates is that messages are not acknowledged within the acknowledgement deadline. If the processing of that message takes more time than the deadline, the message gets resent. That is why I was asking for the AckDeadline in my previous comment. By default it should be 10 seconds. You can check how you have it configured in your console, clicking on the subscription you are using. You can try to increase it in order to wait more for the messages finishing being processed. Do it by clicking in edit once inside the subscription.

However even if you are acknowledging within the deadline sometimes duplicates will occur. This is necessary in order to guarantee at-least-once delivery.

David
  • 7,623
  • 1
  • 19
  • 46
Javier Bóbeda
  • 428
  • 1
  • 10