Rocketmq重复消费问题

一.背景：

• 背景：测试环境Rocketmq的server端有2台服务器(X.X.X.55和X.X.X.49)，在测试同事反馈推送有问题(重复消费)的前一天早上，发现49这台服务器上的mq进程没有了，于是手动重启了49的mq服务(也正是这次重启，误导了问题排查的方向)
• 业务场景：业务端通过Rocketmq生产和消费消息，其中消费的消息会调用极光接口，推送至app端，正常情况下，每生产一条消息，消费者只消费一次，app端只会收到一条推送通知
• 反馈问题：同一条消息，app端收到多条相同的推送通知
• 猜测原因：Rocketmq在消费消息时产生了异常，MessageListenerConcurrently接口返回了RECONSUME_LATER标志

---

二.如何在控制台查看是否有消息积压或消费失败

• RocketMQ Console查看：
  
• 参数：

名称	作用
#Topic	topic名称
%RETRY%messageConsumerGroupTest	重试队列：当消息发送失败，会将发送失败的消息发送到topic为%RETRY%groupname 的队列中
#Broker Offset	topic在该broker上存储(生产)的消息偏移量
#Consumer Offset	topic在broker上消息的消息偏移量
#Diff	topic在该broker上的消息积压量，#Diff = (#Broker Offset) - (#Consumer Offset )
Diff Total	该Consumer Group下积压的消息总数
%DLQ%+consumergroup	死信队列：消费失败到一定次数(默认16次)，就会被发送到死信队列，上图未出现

• 上图分析：

1）以%RETRY%为前缀的topic的#Diff的值不为0，说明对应的topic在消费端出现了消费失败后的消息积压
2）前缀不为%RETRY%的topic的#Diff的值不为0，说明该topic出现了消息积压

---

三.重复消费排查过程

• 排查步骤1：是否有消息积压
• 排查步骤：

1）打开RocketMQ Console——>Consumer——>ConsumerProgress
2）在 consumer group name输入框输入 messageConsumerGroupTest
3）查看topic消费信息

• 结果：

当我们拿着测试的手机，手机上在不断的收到重复推送通知，但查看控制台，显示没有任何的消息积压

• 分析：

当时很奇怪，收到多条相同的推送，肯定是重复消费了，但控制台却没有显示消息积压(原因就详见本文末尾的问题5解释)，只能将信将疑的去排查Consumer客户端是否出了问题

---

• 排查2：业务代码消费日志是有否异常
• 步骤

1）登录业务代码所在的服务器，查看消息消费日志

• 结果

1）同一条推送通知，有被不断的触发的日志，但未见Exception和Error相关的可能造成消费失败的日志

• 分析：

突然又回想起前一天49 服务器上的mq进程突然没了，于是就怀疑问题出在Rocketmq的server端

---

• 排查3：Rocketmq server端是否有异常
• 排查步骤：

1）查看mq的进程是否正常(namesrv和broker)
2）查看服务器的内存和硬盘空间是否不足
3）查看/rocketmqlogs目录下的各个日志是否有异常
4）查看防火墙是不是打开，或者mq相关服务的端口号无法访问

• 结果：

1） rocketmq的nameserver和broker的进程服务正常
2）服务所在的服务器内存和磁盘空间正常
3）服务器端各个日志文件中，也未发现有error日志
4）防火墙是关闭的

mq相关进程：ps -ef|grep rocketmq

内存和磁盘空间，free -h 、df -h

防火墙状态，systemctl status firewalld

server端相关日志，${user.home}/logs/rocketmqlogs目录下

• 分析：

在Rocketmq的服务器端，各种可能情况，检查了一遍未发现任何异常，只能一脸懵逼的去Debug单步调式业务代码，看能不能发现问题

---

• 排查4：Consumer 客户端是有否异常
• 步骤

1）Idea中启动相关服务debug单步调试
2）PostMan模拟用户请求本地服务，触发Rocketmq生产者生产消息
3）本地服务的消费者消费消息，调用极光接口发送推送通知，处理相关业务
4）观察app端推送通知及控制台日志输出情况

• 结果

1）app端在不断的接收到重复的推动通知
2）同一条消息，被不断的触发消费
3）debug时，在Rocketmq的源码中捕捉到了异常

Consumer客户端的核心是实现MessageListenerConcurrently接口，消费成功返回CONSUME_SUCCESS，消费失败返回RECONSUME_LATER，注意业务代码(非源码)此处的异常捕捉级别为Exception，正是这个异常级别，导致异常日志没有被打印出来

1）当debug单步调试到业务代码的某一处时，代码突然跳到Rocketmq的源码的ConsumeMessageConcurrentlyService类的run()方法中，在status = listener.consumeMessage(Collections.unmodifiableList(this.msgs), context)代码处捕获了一个异常，该方法的返回值为消息消费状态。
2）如下图的源码，可以看到，当发生异常时listener.consumeMessage方法的返回值为null，当status为null时，status会被赋值为ConsumeConcurrentlyStatus.RECONSUME_LATER状态(即消费失败)
3）如下图，造成业务代码异常的原因是：org.mybatis.spring.transaction.SpringManagedTransaction.getTimeout()Ljava/lang/Integer，这是mybatis抛出的一个异常，正常情况下，这个异常应该在业务代码处就被捕捉到(业务代码处确实有捕捉异常方法，只是捕捉的级别是Exception)，但奇怪的是这个异常并没有被业务代码捕捉到，而被Rocketmq的消费监听方法捕捉到，造成了消费失败
4）为什么这个mybatis的异常没有业务代码捕捉到，而是被Rocketmq捕捉到，仔细观察两者异常捕捉的代码，发现业务代码处的异常捕捉级别是Excption，Rocketmq源码的异常捕捉级别是Throwable，而Mybatis抛出的正是Error级别的日志，所以Mybatis抛出的异常没有被业务代码捕捉到，当我们把业务代码处的异常捕捉级别改为Throwable时，就能在日志中查看到异常日志信息。

当把业务代码的异常捕捉，改为Throwable级别，就可以捕捉到异常信息，并在日志中打印出来

• 由上面debug调式带来的疑问

1）为什么mybatis的异常没有业务代码捕捉到，而是被Rocketmq捕捉到？
原因：业务代码处的异常捕捉级别是Excption，mq的异常捕捉级别是Throwable，而当mybatis抛出的Error级别的日志，而Error级别的日志不能被Exception捕捉到。

Error类和Exception类的父类都是throwable类，他们的区别是：
1）Error类一般是指与虚拟机相关的问题，如系统崩溃，虚拟机错误，内存空间不足，方法调用栈溢等。对于这类错误的导致的应用程序中断，仅靠程序本身无法恢复和和预防，遇到这样的错误，建议让程序终止。
2）Exception类表示程序可以处理的异常，可以捕获且可能恢复。遇到这类异常，应该尽可能处理异常，使程序恢复运行，而不应该随意终止异常。

2）是什么原因造成的mybatis抛出异常？
原因：org.mybatis.spring.transaction.SpringManagedTransaction.getTimeout()Ljava/lang/Integer，出现这个错误的原因主要是spring-mybatis和mybatis版本不匹配，参考博客链接:https://blog.csdn.net/AirMario/article/details/53446228，本项目中将mybatis的依赖版本由1.4.1改为1.3.1之后，就可以了，版本号改完之后整个mq的消费异常问题也解决了。

3）异常被rocketmq的client端捕捉到了，那client端的mq日志输出到那去了？
查看mq源码中的日志配置文件logback_rocketmq_client.xml，发现日志被输出到client服务的${user.home}/logs/rocketmqlogs目录下

登录rocketmq client端服务器查看日志

4）mq的消息消费失败后，会重复消费，重复消费的次数？
在mq的server端启动时会打印关于消费失败的重试机制，关键字为：messageDelayLevel

5）为什么明明是重复消费，但在排查1中RocketMQ的控制台中看到的#Diff都为0？
原因：
1）#Diff表示某个topic的生产和消费的差值。在排查1中，虽然我们的消息是消费失败了，但生产的消息都是被消费了(即使是消费失败了，但也触发ConsumerListener消费了，也属于被消费了)。
2）当我们把mq的Consumer端的进程kill掉，再过一段时间，就会发现%RETRY%messageConsumerGroupTest和其它的topic的#Diff的值不为0，如标题三中的示例图。

• 最终解决方法：

• 将mq消息消费模块的pom.xml文件中mybatis的版本号由1.4.1改为1.3.1，并将相关业务代码的异常捕捉级别改为Throwable

• 反思：

整个MQ异常问题的处理过程持续了1天半，其中大半的时间浪费在了MQ server端的排查。
从项目第一次引入Rocketmq作为消息中间件到现在也有一年多的时间了，期间虽然一直在写相关的业务代码，但仅"知其然，不知其所以然"，一直没有深入了解整个MQ的架构、原理、特性。
直到这次出现问题，才发现自己对mq的底层实现知之甚少。
所以要关注源码，关注底层实现，多写笔记。
最后，借用《黑客与画家》里的一句话：如果自己就是潮水的一部分，怎么能看见潮流的方向呢？