记录Rocketmq定时消息不消费问题的排查过程

写在前面

此本记录了一个项目中测试环境发生的奇怪问题（还好只是测试环境，线上的话问题就大了），就是rocketmq的定时消息莫名其妙不消费问题，出现过几次。一开始没时间只能抱着万能的重启大法，果然重启大法好，重启马上正常了。结果过了10来天，又出现了，只能硬着头皮去排查了。

问题根源初步确认

测试妹子反映又有数据没入库了，因为我们的整个项目强依赖rocketmq，整个处理逻辑都是通过mq做异步解耦，所以数据没入库第一时间会去排查mq的日志，看看这个数据是否有回来。由于我们库中有业务标识(这里就不细说了)。通过业务标识找到属于当前数据的mq的msgId(rocketmq的唯一标识)，如下图：

由于代码加了不同类型的日志，这个很明显就是重试的标识，也就是当前的消息还没找到匹配的消息(比如系统A与系统B分离，B要等A处理完才能拿到A的数据来匹配，但是这里由于A还没处理完，B数据就回来了，找不到数据匹配，所以只能重发回到mq，加了特定的延迟的时间，后面再重新投递，已达到满足系统需求的效果)，但是这个msgId的消息从此就没有再回来了，因为没有其他打印日志了。所以基本可以确认是延迟消息不消费导致的。

问题根源再次确认。

回到本地写了个延迟消息的测试类，果然还是不消费，消息一去不复返。如果直接发送的消息是可以正常消费的(非延迟消息)，然后本地也搭建了一个rocketmq来测试下，发现延迟消息正常，这。。。难道mq看心情消费的？这不，还是要一步步查找问题根源，不然说服不了测试啊，因为这个问题提了好几个bug。。。。

了解rocketmq定时消息原理以及处理过程。

• 定时消息的处理过程
• 
  原来定时消息是优先存储到SCHEDULE_TOPIC_XXXX目录中，然后ScheduleMessageService轮询取检查是否到达了发送时间，如果到达了发送时间，再发送到真正的topic。举个粟子，比如我发送的延迟消息主题为topic_test，会先到达SCHEDULE_TOPIC_XXXX中，比如延迟是5秒，5秒之后，定时任务会将消息重新发送到topic_test的目录中，此时才是真正的消费。
  
  此处可以再次验证是定时消息不消费导致的，因为下发的一条消息，SCHEDULE_TOPIC_XXXX目录中的某个queueId的目录中的刷盘有时间变化，而topic_test一直不变，说明没有消息进入到topic_test目录中。(rocketmq定时消息原理更深了解的可自行百度或看《RocketMq技术内幕》这本书）

源码调试

没办法，只能硬着头皮调试源码了，但是调试源码这事情，很多时候可能的结果就是无终而返，但是还是得尝试一下吧，不然没有别的法子了。嗯，rocketmq动起来。

启动了NameServer以及BrokerServer，调试这个定时任务类

发现这里的逻辑是，当前定时任务跑完时，继续创建下一个定时任务，这里闯入的delayLevel延迟时间为100ms，继续点进去看。

发现这里调用的是jdk的Timer类，而这里时间是当前的时间加上延迟时间就是下一次定时任务执行的时间。条数直接按F8跳过多次，确定100ms就执行了一次，轮询速度还是非常快的。看到这，脑子灵光一现有了头绪，这里的时间是System.currentTimeMillis()，说明是当前时间。这让我想起了测试环境的一个骚操作，
当前日期里面竟然有8月30号的日志？这明显修改过服务器的时间。这时候有了一个猜想，当时间是8月30号的时候，比如是2020-08:30 00:00:00.000创建定时任务的时候机上100毫秒就是 2020-08:30 00:00:00.100 也就是下一个定时任务的时间，这个时间如果我们把服务器时间再修改为当前时间，比如现在是2020-07-28 00:00:00, 这定时任务会不会不跑了呢? 大概9成是这个问题了吧？

结论求证

根据猜想，继续调试源码的ScheduleMessageService类，这个时候把本地的window时间修改为2020-08-30，当调试到创建完定时任务的时候

把服务器时间修改为当前时间（2020-07-28）果然，定时任务从此停止了，因为这个定时任务要到 2020-08:30 00:00:00.100 才执行啊，所以所有定时消息都没反应了，至此，真相找到。验证了开始的重启为啥就正常了呢，因为rocketmq重启之后，定时任务重新创建了，所以就正常了。

后记

没事千万不要修改服务器的时间啊，如果真有修改的需求，记得把所有应用都重启一下，不然应用里面有定时任务的需求，会出现各种奇奇怪怪的问题，又浪费时间，真是冤大头。