分享一次关于RabbitMQ重复消费的故障

背景

前天3月29号，刚准备吃饭，手机上收到了系统上一个Error Alert提示，打开进去看原来是出现一次重试超时，后面是正常的。然后无意跳去看一下所有服务总览页面，发现另一个服务有几个error，于是进入详情，发现一直提示“验证码637592发送失败，data not accepted”。

业务逻辑

以上报错来自一个邮件推送服务，利用webman+rabbitmq（采用的workerman/rabbitmq）做的异步消费。在程序设计方面，所有的环节都有做catch处理，最终都是保证返回ack。不应该会出现同一条邮件重复发送，紧接着又看了一下具体的系统日志，发现发送邮件的整体日志都是正常的，只是邮件发送的结果是data not accepted，它不会影响ack的返回，同时还有进程退出启动的日志。

更诡异的是，仅仅只有进程onWorkerStop的业务日志和onWorkerStart启动的业务日志，并没有出现workerman调度进程输出的日志（我们都知道在workerman下，假设进程出现异常或者自己exit了，主进程会监听到并输出具体的退出错误日志），同时利用workerman的status命令，查到exist_count为12，但是exist_status为0，并且去查workerman.log的日志，也没有进程退出的信息。
status命令结果：

workerman.log的日志内容：

线上问题先处理

先解决线上故障，我们具体排查发现推送邮件给SMTP服务时，一直是失败的（给我们内部发邮件都是失败的），所以联系运维同学帮排查，的确是SMTP服务出问题了（它发给收件人之后，但是请求另一个组件时耗时很久，直到对方返回504时，它才把结果返回给我们），于是在运维修正之后，我们这边再推邮件就正常了，也没有重复消费的问题。

疑惑

思来想去，不得其解，因为用webman这么久，从来没遇到这种情况，于是当晚把上述问题跟walkor描述了一下，很快第二天早上他回复了，最后他指引出：如果没有出现workerman进程调度日志，并且exit_status是0，那说明是有调用到Worker::stopAll()导致的，而workerman/rabbitmq的库，它在disconnect时，会调用到该方法。于是自己测试了一下主动stopAll方法，大部分现象可以还原。但是我们业务逻辑除了onWorkerStop外，自己并不会主动的disconnect，那它是在哪里被调度的呢？

定位

再次看disconnect方法，它继承的是bunny/Client的，仔细看了一下，调用链路如下：在select loop下，会触发read，当stream是eof时，则主动disconnect，进而导致Worker::stopAll()。

那么问题来了，为什么stream是eof？另外我发现workerman/rabbitmq实现心跳时，假设它失败也会调用stopAll，联想到当时线上发送邮件时，耗时了非常久，并且我偶然间通过本地x-debug断点调试时，也会出现这个问题。那是不是跟心跳有关系？也就是在heartbeat到期后，因为进程还一直在被阻塞，它根本无法响应，所以出现异常了？

所以再次做了一次测试，本地将业务逻辑直接sleep 120s，heartbeat设置为30s，测试果真和线上故障时所有细节一致。然后又反验证一次，把业务逻辑设置为sleep 30s，heartbeat设置为60s，系统运行正常，没有重复消费的问题，消息有正常被消费。这下，可以明确知道是这个原因引起的了。

根本原因

但是回到根本，为什么heartbeat没有被执行，它的stream就是eof了？有点知识盲区了，问了下AI，我关联了几个重要文件，并阐述了过程，它提到了这个机制：RabbitMQ的heartbeat frame。

根据它的描述，我又再一次看了下rabbitmq的文档，里面的确提到了这个机制（其实我之前一直以为workerman/rabbitmq设置的heartbeat是一个普通的Timer）：https://www.rabbitmq.com/docs/heartbeats#heartbeats-interval 当heartbeat连续两次失效后，该端会认为对方已经不可达，然后就会主动关闭链接。

这样一来就完全解释得通了，并且后面联系运维拿到了当时rabbitmq的日志，和文档描述一致，有心跳丢失导致连接断开的日志：

以上就是整个过程，问题产生是由好几个因素诱发，最终得一层一层去剥开，并且也发现了本身业务代码一些不足需要去弥补。如果有相似使用场景的，可以关注下这里的问题。

在这里还是得感谢walkor的细心指出，不然真找不出头绪！