确认后一次又一次收到来自Google Pub / Sub订阅的消息[Heisenbug]

Posted 2023-02-16

【中文标题】确认后一次又一次收到来自Google Pub / Sub订阅的消息[Heisenbug]

【英文标题】：Message is received from Google Pub/Sub subscription again and again after acknowledge[Heisenbug]

【发布时间】：2020-04-10 23:04:14

【问题描述】：

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

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

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

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

日志示例：

//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订阅页面包含下图：

StackDriver 确认图：

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

【参考方案1】：

尝试检查 Stackdriver 以查看您是否为 missing acknowledgement deadlines。

重复之间的两小时等待时间非常有趣。您之前是否尝试过延长您的消息截止日期？ （这方面的信息在上面的链接中。）

【讨论】：

为什么是 2 小时？因为我设置了 max-ack-extension-period: 7200

确认截止日期为 600 秒

我在GitHub Google Cloud Client Libraries for Go 上找到了一个帖子，描述了您的问题。我无法在 Java 客户端库上找到相同的内容。尝试将您的消息截止日期减少到 600 条以下。

最初的消息截止日期是 10 秒（默认值），当我设置 600 秒时它试图解决问题，所以消息截止日期与该问题无关

您是否检查了 Stackdriver 日志以了解您是否错过了确认截止日期？

【参考方案2】：

在此处查看更多信息：How to cleanup the JdbcMetadataStore?

根据我们的结论，最好不要在处理后立即从元数据存储表中删除条目。一些外部工作应该不时地做这个伎俩，并且只针对那些足够旧的条目进行删除，我们确信 Pub/Sub 不会再向我们重新传递相同的消息。

【讨论】：

是的，这是我目前的状态。但我认为这是一种解决方法。我想我以错误的方式配置了 google pub/sub 或 spring-cloud-gcp。极不可能，但它可能是库或 pub/sub 中的错误。重新投递正常，预计异常。但是在我们的例子中，成功的回调被调用，但消息没有从订阅中删除，我们一次又一次地得到它。所以我们不能只是忽略重复，我们必须重复确认才能从订阅中删除消息

一次又一次意味着无穷无尽