确认后反复收到来自Google Pub/Sub订阅的消息[Heisenbug] [英] Message is received from Google Pub/Sub subscription again and again after acknowledge[Heisenbug]

问题描述

我想注意的是，我将描述的场景很少发生，而且在大多数情况下，一切都按预期进行.

I would like to notice that the scenarion I will describe happen rare enough and in most cases everything works as expected.

我在 Pub/Sub 端有 1 个主题和 1 个订阅.

I have 1 topic and 1 subscription on Pub/Sub side.

我的 Java 应用程序侦听订阅，进行一些处理并将确认发回.由于 google Pub/Sub 保证至少交付一次，我们根据 objectGeneration 标头和 'objectId' 标头在我们这边进行消息重复数据删除.

My java application listens for subscription, does some processing and sends acknowledge back. Because of fact that google Pub/Sub guarantees at least once delivery, we do message deduplication on our side based on objectGeneration header and 'objectId' header.

有时我们会看到我们的应用程序一次又一次地接受已确认的消息，这是意外行为.

Sometimes we see that message that was acknowldged is accepted by our application again and again and it is unexpected behaviour.

日志示例:

//first
2019-12-17 20:51:57.375 INFO 1 --- [sub-subscriber3] bucketNotificationFlow : Received new message from pub-sub: GenericMessage [payload={....}, headers={.....objectGeneration=1576615916875106, eventTime=2019-12-17T20:51:56.874940Z, objectId=Small_files_bunch/100_12_1.csv, ....
....
2019-12-17 20:51:57.698 INFO 1 --- [sub-subscriber3] .i.g.PubSubMessageAcknowledgementHandler : Acknowledged message - 1576615916875106
...
//duplicate 1
2019-12-17 20:51:59.663 INFO 1 --- [sub-subscriber4] bucketNotificationFlow : Received new message from pub-sub: GenericMessage [payload={...}, headers={ objectGeneration=1576615916875106, eventTime=2019-12-17T20:51:56.874940Z, objectId=Small_files_bunch/100_12_1.csv", ....
...
2019-12-17 20:51:59.704 INFO 1 --- [sub-subscriber4] c.b.m.i.DiscardedMessagesHandler : Duplicate message received GenericMessage [ headers={idempotent.keys=[objectGeneration.1576615916875106, objectId.Small_files_bunch/100_12_1.csv], ...
....
//duplicate 2
2019-12-17 22:52:02.239 INFO 1 --- [sub-subscriber1] bucketNotificationFlow : Received new message from pub-sub: GenericMessage [payload={...}, headers={objectGeneration=1576615916875106, eventTime=2019-12-17T20:51:56.874940Z, objectId=Small_files_bunch/100_12_1.csv, ...
...
2019-12-17 22:52:02.339 INFO 1 --- [sub-subscriber1] c.b.m.i.DiscardedMessagesHandler : Duplicate message received GenericMessage [ headers={idempotent.keys=[objectGeneration.1576615916875106, objectId.Small_files_bunch/100_12_1.csv], ...

// and so on each 2 hours

确认代码:

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); //from logs we see that this line was invoked
        },
        e -> {
            removeFromIdempotentStore(targetMessage, false);
            log.error("Failed to acknowledge message - {}", generation, e);
        }
);

GCP 订阅页面包含下图:

GCP subscription page contains following diagram:

StackDriver 确认图:

StackDriver acknowledge diagram:

任何想法发生了什么，如何排除故障并修复它?

Any ideas what is going on, how to troubleshoot it and fix it ?

推荐答案

尝试检查 Stackdriver，看看您是否是 错过确认截止日期.

Try checking Stackdriver to see if you are missing acknowledgement deadlines.

重复之间的两小时等待时间非常有趣.您之前是否尝试过延长消息截止日期?(关于此的信息在上面的链接中.)

The two hour wait time between duplicates is very interesting. Have you tried expanding your message deadline before? (Info on this is at the above link.)

这篇关于确认后反复收到来自Google Pub/Sub订阅的消息[Heisenbug]的文章就介绍到这了，希望我们推荐的答案对大家有所帮助，也希望大家多多支持IT屋！