You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@rocketmq.apache.org by 404828407 <40...@qq.com> on 2018/04/02 04:06:27 UTC
投稿 RocketMQ Master宕机后重启出现的严重问题分析
RocketMQ Master宕机后重启出现的严重问题分析
作者：卢松
以前发现RocketMQ的master机器宕机时会出现很多诡异的问题，所以最近做了一系列实验来试图找到问题的原因，也是想发现风险点。没想到发现了一个更严重的问题，下面会详细的说明下，另外出现问题的原因属于猜测，望高人看到后能指点下。
试验环境准备：
1.RocketMQ版本：阿里的3.2.6版本
2.集群包含2组broker，每组broker都是1master + 1slave，都设置成SYNC_MASTER、ASYNC_FLUSH模式。
3.每个broker上已经存储过好几个commitlog文件，并且已经有commitlog文件删除过（数据过期了）。
测试步骤：
1.尽量多的消费组、尽量多的消费者（10个以上）开始消费多个topic，消费者自始至终不停机。
2.在消费者消费时，突然把其中一组broker（姑且命名为BrokerA吧）的master断电（注意是断电或者硬盘损坏、不是kill -9）。
3.过一段时间（半小时左右），重启宕机的这个master。
观察现象，记录事后的现象及疑问：
1.BrokerA的slave机器一直存活着，master宕机后，消费者新的消费进度会存在slave上面。
2.宕机后，拉取BrokerA的master中的数据文件，文件没有损坏。
3.重启master后，消费客户端会从很久以前的queue offset开始拉取消息，为啥会去取到很久以前的queueOffset？
4.重启master后，这个master出现大量如下异常，异常日志达到10分钟每G的量：
{
"timestamp": "2017-12-28T00:18:48.620+0800",
"level": "WARN",
"thread": "FlushConsumeQueueService",
"logger": "RocketmqStoreError",
"message": "findMapedFileByOffset offset not matched, request Offset: 0, index: -6, mapedFileSize: 6000000, mapedFiles count: 2, StackTrace: \n\tjava.lang.Thread.getStackTrace(Thread.java:1567)\n\tcom.alibaba.rocketmq.common.UtilAll.currentStackTrace(UtilAll.java:59)\n\tcom.alibaba.rocketmq.store.MapedFileQueue.findMapedFileByOffset(MapedFileQueue.java:467)\n\tcom.alibaba.rocketmq.store.MapedFileQueue.commit(MapedFileQueue.java:442)\n\tcom.alibaba.rocketmq.store.ConsumeQueue.commit(ConsumeQueue.java:345)\n\tcom.alibaba.rocketmq.store.DefaultMessageStore$FlushConsumeQueueService.doFlush(DefaultMessageStore.java:1459)\n\tcom.alibaba.rocketmq.store.DefaultMessageStore$FlushConsumeQueueService.run(DefaultMessageStore.java:1479)\n\tjava.lang.Thread.run(Thread.java:722)"
}
5.另外还有大量的这种异常，这类异常显示大量消费客户端去拉取很久以前的消息。
{
"timestamp": "2017-12-28T00:39:01.748+0800",
"level": "WARN",
"thread": "PullMessageThread_15",
"logger": "RocketmqStoreError",
"message": "findMapedFileByOffset offset not matched, request Offset: 19382879484, index: -7, mapedFileSize: 1073741824, mapedFiles count: 2, StackTrace: \n\tjava.lang.Thread.getStackTrace(Thread.java:1567)\n\tcom.alibaba.rocketmq.common.UtilAll.currentStackTrace(UtilAll.java:59)\n\tcom.alibaba.rocketmq.store.MapedFileQueue.findMapedFileByOffset(MapedFileQueue.java:467)\n\tcom.alibaba.rocketmq.store.CommitLog.getMessage(CommitLog.java:664)\n\tcom.alibaba.rocketmq.store.DefaultMessageStore.getMessage(DefaultMessageStore.java:546)\n\tcom.alibaba.rocketmq.broker.processor.PullMessageProcessor.processRequest(PullMessageProcessor.java:283)\n\tcom.alibaba.rocketmq.broker.processor.PullMessageProcessor.processRequest(PullMessageProcessor.java:84)\n\tcom.alibaba.rocketmq.remoting.netty.NettyRemotingAbstract$1.run(NettyRemotingAbstract.java:172)\n\tjava.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)\n\tjava.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)\n\tjava.util.concurrent.FutureTask.run(FutureTask.java:166)\n\tjava.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)\n\tjava.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)\n\tjava.lang.Thread.run(Thread.java:722)"
}
这种现象的原因分析过程：
首先第二类异常出在PullMessageProcessor的拉取消息过程中，消费客户端不停拉取消息时，PullMessageProcessor会调用DefaultMessageStore.getMessage()，而在getMessage()中，更具体的是在CommitLog的public SelectMapedBufferResult getMessage(final long offset, final int size) 方法中，这个方法会调用MapedFileQueue的方法findMapedFileByOffset(final long offset, final boolean returnFirstOnNotFound)，具体看下图：
从代码上看，出现这个异常原因就是DefaultMessageStore.getMessage()中offsetPy拿到的值过小，这个值实际上是从ConsumeQueue的文件中读到的单条消息的CommitlogOffset，说明bufferConsumeQueue这个对象拿到的是老的数据。如下图：
bufferConsumeQueue对象又是根据offset定位的，offset是每一个queue的queueOffset，这个offset实际上是消费端拉取消息时传递过来的，它来自于两种地方，一是消费端自己拉取的消费进度，另外一种是消费端每次拉取消息，拉取不到后拿到的nextBeginOffset参数。如下图：
所以根源就出在这个nextBeginOffset的计算逻辑上，为什么nextBeginOffset会计算出过小的值，导致消费端一直在消费过小的queueOffset对应的消息？
我们先不去查这个问题的原因，就按照这个逻辑走下去，看看会发生什么情况。还是回到DefaultMessageStore.getMessage()中，当SelectMapedBufferResult selectResult = this.commitLog.getMessage(offsetPy, sizePy);拿不到数据后，selectResult返回的是null，这个方法最终返回的状态是GetMessageStatus.MESSAGE_WAS_REMOVING，表示消息的数据文件正在被删除。
而调用这个方法的PullMessageProcessor返回给消费客户端的是这个状态，请消费端立即尝试重新拉取消息：
消费客户端MQClientAPIImpl在方法PullResult processPullResponse(final RemotingCommand response) 处理这个返回状态，转换成NO_MATCHED_MSG的结果。
同样是消费客户端，在DefaultMQPushConsumerImpl的pullMessage(final PullRequest pullRequest)方法中，PullCallback是这么处理这种NO_MATCHED_MSG结果的：
从收到的nextBeginOffset开始，立即去重新拉取后面的消息。
而每次依然是去拉取很久前的消息，这样就形成了消费端不停拉取消息的日志，broker出现大量找不到消息的日志，并且broker负载很高。问题的关键是DefaultMessageStore.getMessage()中，为啥拿到的offsetPy是已经删除的commitlog offset，难道是/home/logs/rocketmq/store/consumequeue中文件损坏（这种可能性极低，目前还没有发现断电导致文件损坏的情况）？
那就有另一种可能：
master突然断电，master上数据就有可能丢失（没有来得及刷盘），consumequeue数据在master、slave的不一致。而消费端在master宕机后切换到slave上消费，消费进度也会提交到slave上，导致消费进度queue offset在master、slave上不一样。然后master重启后，消费端重新回到master拉取消息，master上的数据丢失了，master识别不出消费端提交的queue offset。
总结下，slave上存储的/home/logs/rocketmq/store/consumequeue比master新，假如slave上最小、最大offset是1000，15000，而这时候master的consumequeue最小、最大数据是1000，10000。当master重启后，消费客户端在slave上已经消费到15000，在master上会从15000开始去master上拉取消息进行消费，在DefaultMessageStore.getMessage()中，当发现offset overflow严重溢出（大于maxOffset）时，就可能会把nextBeginOffset设置为0（恰好此consumequeue的minoffset为0），下次就从offset=0开始拉取消息。
开始从0消费就会拉取很久前的消息数据了。
我猜测这不是rocketmq的bug，应该是RocketMQ审慎的选择，它的原则是：宁愿多消费，重复消费也不要漏消费。
之所以这么设计，我的猜测或者解释如下：
当consumeQueue的minOffset=0时，说明这个consumeQueue可能是新的queue，也可能是新扩容的queue，这时候为了避免有消息漏掉，在超过maxOffset这种奇怪的情况下，消费端下次消费就从0开始消费，宁愿重复消费也不要漏掉消费。
当minOffset大于0时，说明这个queue已经长时间存在过了，不会是新queue，也不会是新扩容的，只需从maxOffset继续消费就行了。
这么设计正常情况下没有问题，但是当一个topic下面的某个queue上积压了很多消息，并且minOffset=0时(表示没有删除过)。这时候master突然宕机了，slave上的数据比master新，并且消费客户端从slave上消费了这个queue上的消息。master重启后，消费客户端切换到master上消费，发现自己消费的消息对于master已经溢出了，根据上面的逻辑，就会从0重新消费，大量重复消费，并且会消费那些已经从commitlog中删除的消息，出现大量错误日志。
再看看刚发布不久的Apache RocketMQ 4.2.0版本中DefaultMessageStore.getMessage()这段的实现，
其中this.getMessageStoreConfig().isOffsetCheckInSlave()默认为false，默认不开启在slave上offset的检查。Apache版本的实现更复杂了一点，但是依然解决不了这个问题。
Apache版本的逻辑是：当master宕机后，slave数据比master新。消费端先从slave消费，master重启后，消费端再从master消费，当minoffset为0时还会从0开始从新消费。
当slave宕机后，master数据比slave的新，消费端从master消费消息。master再宕机，slave重启后，消费端从slave消费，这时候会从master上记录的消费进度开始消费。因为slave的数据总归是来自于master，并且slave已经同步了master的新数据。
好了，问题分析到现在，我大概能说的通这个问题了，虽然事实不一定如此，也少有人碰到这个问题。
如果出现这种情况，也不知道怎么解决的话。我想到方式是：保留现场，堆栈信息，broker端日志，客户端日志，master和slave的所有数据文件。处理好宕机临界点的数据，最终必须要重启master时，要拿备份的slave的数据文件覆盖master的数据文件，这些文件包括commitlog，consumequeue以及config下面的所有文件（消费进度），然后再重启。简单粗暴实用，避免master起来后负载飙升直至不可用的情况。
有什么风险呢？目前还不清楚。
总结：这是目前为止我发现的RocketMQ最严重的一个问题，Apache版本也有此问题。其他问题都是小打小闹，没有太大影响，唯独此问题需要慎重处理。问题根源还是数据不一致，不支持高可用。集群内数据不一致，服务器端又处理不好这种不一致。
不过按照Apache RocketMQ的规划，要到4.3.0版本才支持高可用，应该不需要等很久。对于这个问题提了个issue：https://issues.apache.org/jira/browse/ROCKETMQ-348
最后，以上都属于猜测，大概也许可能是这个问题导致的，还望有高手出来指点迷津，此文算是抛砖引玉了。
Re: 投稿 RocketMQ Master宕机后重启出现的严重问题分析
Posted by Von Gosling <vo...@apache.org>.
Hi，
感谢卢松的两篇文章，非常欢迎大家投稿 ~
鉴于RocketMQ的官方投稿流程刚刚启动，能否麻烦把文章在Google Doc上贴出来，然后user列表和我们讲下地址，我们一起看看先。对啦，麻烦授权以下账号修改权限:
lizhanhui@gmail.com
zhou@xinyu.im
fengjia10@gmail.com
Best Regards,
Von Gosling
> 在 2018年4月2日，12:27，yukon <yu...@apache.org> 写道：
>
> Hi,
>
> 非常欢迎撰写RocketMQ相关的技术文章，建议放到Google DOC上并共享出来方便大家进行Comment。
>
> Regards,
> yukon
>
> 2018-04-02 12:06 GMT+08:00 404828407 <404828407@qq.com <ma...@qq.com>>:
>
>
> RocketMQ Master宕机后重启出现的严重问题分析
>
>
> 作者：卢松
>
> 以前发现RocketMQ的master机器宕机时会出现很多诡异的问题，所以最近做了一系列实验来试图找到问题的原因，也是想发现风险点。没想到发现了一个更严重的问题，下面会详细的说明下，另外出现问题的原因属于猜测，望高人看到后能指点下。
>
> 试验环境准备：
> 1.RocketMQ版本：阿里的3.2.6版本
> 2.集群包含2组broker，每组broker都是1master + 1slave，都设置成SYNC_MASTER、ASYNC_FLUSH模式。
> 3.每个broker上已经存储过好几个commitlog文件，并且已经有commitlog文件删除过（数据过期了）。
>
> 测试步骤：
> 1.尽量多的消费组、尽量多的消费者（10个以上）开始消费多个topic，消费者自始至终不停机。
> 2.在消费者消费时，突然把其中一组broker（姑且命名为BrokerA吧）的master断电（注意是断电或者硬盘损坏、不是kill -9）。
> 3.过一段时间（半小时左右），重启宕机的这个master。
>
> 观察现象，记录事后的现象及疑问：
> 1.BrokerA的slave机器一直存活着，master宕机后，消费者新的消费进度会存在slave上面。
> 2.宕机后，拉取BrokerA的master中的数据文件，文件没有损坏。
> 3.重启master后，消费客户端会从很久以前的queue offset开始拉取消息，为啥会去取到很久以前的queueOffset？
> 4.重启master后，这个master出现大量如下异常，异常日志达到10分钟每G的量：
> {
> "timestamp": "2017-12-28T00:18:48.620+0800",
> "level": "WARN",
> "thread": "FlushConsumeQueueService",
> "logger": "RocketmqStoreError",
> "message": "findMapedFileByOffset offset not matched, request Offset: 0, index: -6, mapedFileSize: 6000000, mapedFiles count: 2, StackTrace: \n\tjava.lang.Thread.getStackTrace(Thread.java:1567)\n\tcom.alibaba.rocketmq.common.UtilAll.currentStackTrace(UtilAll.java:59)\n\tcom.alibaba.rocketmq.store.MapedFileQueue.findMapedFileByOffset(MapedFileQueue.java:467)\n\tcom.alibaba.rocketmq.store.MapedFileQueue.commit(MapedFileQueue.java:442)\n\tcom.alibaba.rocketmq.store.ConsumeQueue.commit(ConsumeQueue.java:345)\n\tcom.alibaba.rocketmq.store.DefaultMessageStore$FlushConsumeQueueService.doFlush(DefaultMessageStore.java:1459)\n\tcom.alibaba.rocketmq.store.DefaultMessageStore$FlushConsumeQueueService.run(DefaultMessageStore.java:1479)\n\tjava.lang.Thread.run(Thread.java:722)"
> }
>
> 5.另外还有大量的这种异常，这类异常显示大量消费客户端去拉取很久以前的消息。
> {
> "timestamp": "2017-12-28T00:39:01.748+0800",
> "level": "WARN",
> "thread": "PullMessageThread_15",
> "logger": "RocketmqStoreError",
> "message": "findMapedFileByOffset offset not matched, request Offset: 19382879484, index: -7, mapedFileSize: 1073741824 <tel:010%207374%201824>, mapedFiles count: 2, StackTrace: \n\tjava.lang.Thread.getStackTrace(Thread.java:1567)\n\tcom.alibaba.rocketmq.common.UtilAll.currentStackTrace(UtilAll.java:59)\n\tcom.alibaba.rocketmq.store.MapedFileQueue.findMapedFileByOffset(MapedFileQueue.java:467)\n\tcom.alibaba.rocketmq.store.CommitLog.getMessage(CommitLog.java:664)\n\tcom.alibaba.rocketmq.store.DefaultMessageStore.getMessage(DefaultMessageStore.java:546)\n\tcom.alibaba.rocketmq.broker.processor.PullMessageProcessor.processRequest(PullMessageProcessor.java:283)\n\tcom.alibaba.rocketmq.broker.processor.PullMessageProcessor.processRequest(PullMessageProcessor.java:84)\n\tcom.alibaba.rocketmq.remoting.netty.NettyRemotingAbstract$1.run(NettyRemotingAbstract.java:172)\n\tjava.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)\n\tjava.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)\n\tjava.util.concurrent.FutureTask.run(FutureTask.java:166)\n\tjava.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)\n\tjava.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)\n\tjava.lang.Thread.run(Thread.java:722)"
> }
>
>
> 这种现象的原因分析过程：
> 首先第二类异常出在PullMessageProcessor的拉取消息过程中，消费客户端不停拉取消息时，PullMessageProcessor会调用DefaultMessageStore.getMessage()，而在getMessage()中，更具体的是在CommitLog的public SelectMapedBufferResult getMessage(final long offset, final int size) 方法中，这个方法会调用MapedFileQueue的方法findMapedFileByOffset(final long offset, final boolean returnFirstOnNotFound)，具体看下图：
>
>
>
>
>
>
>
> 从代码上看，出现这个异常原因就是DefaultMessageStore.getMessage()中offsetPy拿到的值过小，这个值实际上是从ConsumeQueue的文件中读到的单条消息的CommitlogOffset，说明bufferConsumeQueue这个对象拿到的是老的数据。如下图：
>
>
>
> bufferConsumeQueue对象又是根据offset定位的，offset是每一个queue的queueOffset，这个offset实际上是消费端拉取消息时传递过来的，它来自于两种地方，一是消费端自己拉取的消费进度，另外一种是消费端每次拉取消息，拉取不到后拿到的nextBeginOffset参数。如下图：
>
>
>
> 所以根源就出在这个nextBeginOffset的计算逻辑上，为什么nextBeginOffset会计算出过小的值，导致消费端一直在消费过小的queueOffset对应的消息？
>
> 我们先不去查这个问题的原因，就按照这个逻辑走下去，看看会发生什么情况。还是回到DefaultMessageStore.getMessage()中，当SelectMapedBufferResult selectResult = this.commitLog.getMessage(offsetPy, sizePy);拿不到数据后，selectResult返回的是null，这个方法最终返回的状态是GetMessageStatus.MESSAGE_WAS_REMOVING，表示消息的数据文件正在被删除。
>
>
>
> 而调用这个方法的PullMessageProcessor返回给消费客户端的是这个状态，请消费端立即尝试重新拉取消息：
>
>
>
> 消费客户端MQClientAPIImpl在方法PullResult processPullResponse(final RemotingCommand response) 处理这个返回状态，转换成NO_MATCHED_MSG的结果。
>
>
>
> 同样是消费客户端，在DefaultMQPushConsumerImpl的pullMessage(final PullRequest pullRequest)方法中，PullCallback是这么处理这种NO_MATCHED_MSG结果的：
> 从收到的nextBeginOffset开始，立即去重新拉取后面的消息。
>
>
>
>
> 而每次依然是去拉取很久前的消息，这样就形成了消费端不停拉取消息的日志，broker出现大量找不到消息的日志，并且broker负载很高。问题的关键是DefaultMessageStore.getMessage()中，为啥拿到的offsetPy是已经删除的commitlog offset，难道是/home/logs/rocketmq/store/consumequeue中文件损坏（这种可能性极低，目前还没有发现断电导致文件损坏的情况）？
>
> 那就有另一种可能：
> master突然断电，master上数据就有可能丢失（没有来得及刷盘），consumequeue数据在master、slave的不一致。而消费端在master宕机后切换到slave上消费，消费进度也会提交到slave上，导致消费进度queue offset在master、slave上不一样。然后master重启后，消费端重新回到master拉取消息，master上的数据丢失了，master识别不出消费端提交的queue offset。
>
> 总结下，slave上存储的/home/logs/rocketmq/store/consumequeue比master新，假如slave上最小、最大offset是1000，15000，而这时候master的consumequeue最小、最大数据是1000，10000。当master重启后，消费客户端在slave上已经消费到15000，在master上会从15000开始去master上拉取消息进行消费，在DefaultMessageStore.getMessage()中，当发现offset overflow严重溢出（大于maxOffset）时，就可能会把nextBeginOffset设置为0（恰好此consumequeue的minoffset为0），下次就从offset=0开始拉取消息。
>
> 开始从0消费就会拉取很久前的消息数据了。
>
>
>
>
> 我猜测这不是rocketmq的bug，应该是RocketMQ审慎的选择，它的原则是：宁愿多消费，重复消费也不要漏消费。
>
> 之所以这么设计，我的猜测或者解释如下：
> 当consumeQueue的minOffset=0时，说明这个consumeQueue可能是新的queue，也可能是新扩容的queue，这时候为了避免有消息漏掉，在超过maxOffset这种奇怪的情况下，消费端下次消费就从0开始消费，宁愿重复消费也不要漏掉消费。
>
> 当minOffset大于0时，说明这个queue已经长时间存在过了，不会是新queue，也不会是新扩容的，只需从maxOffset继续消费就行了。
>
> 这么设计正常情况下没有问题，但是当一个topic下面的某个queue上积压了很多消息，并且minOffset=0时(表示没有删除过)。这时候master突然宕机了，slave上的数据比master新，并且消费客户端从slave上消费了这个queue上的消息。master重启后，消费客户端切换到master上消费，发现自己消费的消息对于master已经溢出了，根据上面的逻辑，就会从0重新消费，大量重复消费，并且会消费那些已经从commitlog中删除的消息，出现大量错误日志。
>
> 再看看刚发布不久的Apache RocketMQ 4.2.0版本中DefaultMessageStore.getMessage()这段的实现，
>
>
>
>
>
> 其中this.getMessageStoreConfig().isOffsetCheckInSlave()默认为false，默认不开启在slave上offset的检查。Apache版本的实现更复杂了一点，但是依然解决不了这个问题。
>
> Apache版本的逻辑是：当master宕机后，slave数据比master新。消费端先从slave消费，master重启后，消费端再从master消费，当minoffset为0时还会从0开始从新消费。
> 当slave宕机后，master数据比slave的新，消费端从master消费消息。master再宕机，slave重启后，消费端从slave消费，这时候会从master上记录的消费进度开始消费。因为slave的数据总归是来自于master，并且slave已经同步了master的新数据。
>
> 好了，问题分析到现在，我大概能说的通这个问题了，虽然事实不一定如此，也少有人碰到这个问题。
>
> 如果出现这种情况，也不知道怎么解决的话。我想到方式是：保留现场，堆栈信息，broker端日志，客户端日志，master和slave的所有数据文件。处理好宕机临界点的数据，最终必须要重启master时，要拿备份的slave的数据文件覆盖master的数据文件，这些文件包括commitlog，consumequeue以及config下面的所有文件（消费进度），然后再重启。简单粗暴实用，避免master起来后负载飙升直至不可用的情况。
>
> 有什么风险呢？目前还不清楚。
>
> 总结：这是目前为止我发现的RocketMQ最严重的一个问题，Apache版本也有此问题。其他问题都是小打小闹，没有太大影响，唯独此问题需要慎重处理。问题根源还是数据不一致，不支持高可用。集群内数据不一致，服务器端又处理不好这种不一致。
>
> 不过按照Apache RocketMQ的规划，要到4.3.0版本才支持高可用，应该不需要等很久。对于这个问题提了个issue：https://issues.apache.org/jira/browse/ROCKETMQ-348 <https://issues.apache.org/jira/browse/ROCKETMQ-348>
>
> 最后，以上都属于猜测，大概也许可能是这个问题导致的，还望有高手出来指点迷津，此文算是抛砖引玉了。
>
>
>
Re: 投稿 RocketMQ Master宕机后重启出现的严重问题分析
Posted by yukon <yu...@apache.org>.
Hi,
非常欢迎撰写RocketMQ相关的技术文章，建议放到Google DOC上并共享出来方便大家进行Comment。
Regards,
yukon
2018-04-02 12:06 GMT+08:00 404828407 <40...@qq.com>:
>
> RocketMQ Master宕机后重启出现的严重问题分析
>
> 作者：卢松
>
>
> 以前发现RocketMQ的master机器宕机时会出现很多诡异的问题，所以最近做了一系列实验来试图找到问题的原因，
> 也是想发现风险点。没想到发现了一个更严重的问题，下面会详细的说明下，另外出现问题的原因属于猜测，望高人看到后能指点下。
>
>
> *试验环境准备：*
>
> 1.RocketMQ版本：阿里的3.2.6版本
>
> 2.集群包含2组broker，每组broker都是1master + 1slave，都设置成SYNC_MASTER、ASYNC_FLUSH模式。
>
> 3.每个broker上已经存储过好几个commitlog文件，并且已经有commitlog文件删除过（数据过期了）。
>
>
> *测试步骤：*
>
> 1.尽量多的消费组、尽量多的消费者（10个以上）开始消费多个topic，消费者自始至终不停机。
>
> 2.在消费者消费时，突然把其中一组broker（姑且命名为BrokerA吧）的master断电（*注意是断电或者硬盘损坏、不是kill -9*）。
>
> 3.过一段时间（半小时左右），重启宕机的这个master。
>
>
> *观察现象，记录事后的现象及疑问：*
>
> 1.BrokerA的slave机器一直存活着，master宕机后，消费者新的消费进度会存在slave上面。
>
> 2.*宕机后，拉取BrokerA的master中的数据文件，文件没有损坏。*
>
> 3.重启master后，消费客户端会从很久以前的queue offset开始拉取消息，为啥会去取到很久以前的queueOffset？
>
> 4.重启master后，这个master出现大量如下异常，异常日志达到10分钟每G的量：
>
> {
>
> "timestamp": "2017-12-28T00:18:48.620+0800",
>
> "level": "WARN",
>
> "thread": "FlushConsumeQueueService",
>
> "logger": "RocketmqStoreError",
>
> "message": "findMapedFileByOffset offset not matched, request Offset:
> 0, index: -6, mapedFileSize: 6000000, mapedFiles count: 2, StackTrace:
> \n\tjava.lang.Thread.getStackTrace(Thread.java:
> 1567)\n\tcom.alibaba.rocketmq.common.UtilAll.currentStackTrace(UtilAll.
> java:59)\n\tcom.alibaba.rocketmq.store.MapedFileQueue.
> findMapedFileByOffset(MapedFileQueue.java:467)\n\
> tcom.alibaba.rocketmq.store.MapedFileQueue.commit(
> MapedFileQueue.java:442)\n\tcom.alibaba.rocketmq.store.
> ConsumeQueue.commit(ConsumeQueue.java:345)\n\tcom.alibaba.rocketmq.store.
> DefaultMessageStore$FlushConsumeQueueService.doFlush(DefaultMessageStore.
> java:1459)\n\tcom.alibaba.rocketmq.store.DefaultMessageStore$
> FlushConsumeQueueService.run(DefaultMessageStore.java:1479)
> \n\tjava.lang.Thread.run(Thread.java:722)"
>
> }
>
>
> 5.另外还有大量的这种异常，这类异常显示大量消费客户端去拉取很久以前的消息。
>
> {
>
> "timestamp": "2017-12-28T00:39:01.748+0800",
>
> "level": "WARN",
>
> "thread": "PullMessageThread_15",
>
> "logger": "RocketmqStoreError",
>
> "message": "findMapedFileByOffset offset not matched, request Offset:
> 19382879484, index: -7, mapedFileSize: 1073741824 <010%207374%201824>,
> mapedFiles count: 2, StackTrace: \n\tjava.lang.Thread.
> getStackTrace(Thread.java:1567)\n\tcom.alibaba.rocketmq.common.UtilAll.
> currentStackTrace(UtilAll.java:59)\n\tcom.alibaba.
> rocketmq.store.MapedFileQueue.findMapedFileByOffset(
> MapedFileQueue.java:467)\n\tcom.alibaba.rocketmq.store.
> CommitLog.getMessage(*CommitLog*.java:664)\n\tcom.alibaba.rocketmq.store.
> DefaultMessageStore.getMessage(*DefaultMessageStore*
> .java:546)\n\tcom.alibaba.rocketmq.broker.processor.*PullMessageProcessor*
> .processRequest(PullMessageProcessor.java:283)\n\tcom.alibaba.rocketmq.
> broker.processor.PullMessageProcessor.processRequest(
> *PullMessageProcessor*.java:84)\n\tcom.alibaba.rocketmq.remoting.netty.
> NettyRemotingAbstract$1.run(NettyRemotingAbstract.java:
> 172)\n\tjava.util.concurrent.Executors$RunnableAdapter.
> call(Executors.java:471)\n\tjava.util.concurrent.FutureTask$Sync.innerRun(
> FutureTask.java:334)\n\tjava.util.concurrent.FutureTask.
> run(FutureTask.java:166)\n\tjava.util.concurrent.
> ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)\
> n\tjava.util.concurrent.ThreadPoolExecutor$Worker.run(
> ThreadPoolExecutor.java:615)\n\tjava.lang.Thread.run(Thread.java:722)"
>
> }
>
>
>
> 这种现象的原因分析过程：
>
> 首先第二类异常出在PullMessageProcessor的拉取消息过程中，消费客户端不停拉取消息时，
> PullMessageProcessor会调用DefaultMessageStore.getMessage()，而在getMessage()中，更具体的是在CommitLog的public
> SelectMapedBufferResult getMessage(final long offset, final int size) 方法中，
> 这个方法会调用MapedFileQueue的方法findMapedFileByOffset(final long offset, final
> boolean returnFirstOnNotFound)，具体看下图：
>
>
>
>
>
> 从代码上看，出现这个异常原因就是DefaultMessageStore.getMessage()中offsetPy拿到的值过小，
> 这个值实际上是从ConsumeQueue的文件中读到的单条消息的CommitlogOffset，
> 说明bufferConsumeQueue这个对象拿到的是老的数据。如下图：
>
>
>
> bufferConsumeQueue对象又是根据offset定位的，offset是每一个queue的queueOffset，
> 这个offset实际上是消费端拉取消息时传递过来的，它来自于两种地方，一是消费端自己拉取的消费进度，另外一种是消费端每次拉取消息，
> 拉取不到后拿到的nextBeginOffset参数。如下图：
>
>
>
> 所以根源就出在这个nextBeginOffset的计算逻辑上，为什么nextBeginOffset会计算出过小的值，
> 导致消费端一直在消费过小的queueOffset对应的消息？
>
>
> 我们先不去查这个问题的原因，就按照这个逻辑走下去，看看会发生什么情况。还是回到DefaultMessageStore.getMessage()中，当SelectMapedBufferResult
> selectResult = this.commitLog.getMessage(offsetPy, sizePy);拿不到数据后，
> selectResult返回的是null，这个方法最终返回的状态是GetMessageStatus.MESSAGE_WAS_REMOVING，
> 表示消息的数据文件正在被删除。
>
>
>
> 而调用这个方法的PullMessageProcessor返回给消费客户端的是这个状态，请消费端立即尝试重新拉取消息：
>
>
>
> 消费客户端MQClientAPIImpl在方法PullResult processPullResponse(final
> RemotingCommand response) 处理这个返回状态，转换成NO_MATCHED_MSG的结果。
>
>
>
> 同样是消费客户端，在DefaultMQPushConsumerImpl的pullMessage(final PullRequest
> pullRequest)方法中，PullCallback是这么处理这种NO_MATCHED_MSG结果的：
>
> 从收到的nextBeginOffset开始，立即去重新拉取后面的消息。
>
>
>
> 而每次依然是去拉取很久前的消息，这样就形成了消费端不停拉取消息的日志，broker出现大量找不到消息的日志，并且broker负载很高。问题的关键是
> DefaultMessageStore.getMessage()中，为啥拿到的offsetPy是已经删除的commitlog offset，难道是
> /home/logs/rocketmq/store/consumequeue中文件损坏（这种可能性极低，目前还没有发现断电导致文件损坏的情况）？
>
>
> 那就有另一种可能：
>
> master突然断电，master上数据就有可能丢失（没有来得及刷盘），consumequeue数据在master、slave的不一致。
> 而消费端在master宕机后切换到slave上消费，消费进度也会提交到slave上，导致消费进度queue
> offset在master、slave上不一样。然后master重启后，消费端重新回到master拉取消息，master上的数据丢失了，master识别不出消费端提交的queue
> offset。
>
>
> 总结下，slave上存储的/home/logs/rocketmq/store/consumequeue比master新，
> 假如slave上最小、最大offset是1000，15000，而这时候master的consumequeue最小、最大数据是
> 1000，10000。当master重启后，消费客户端在slave上已经消费到15000，
> 在master上会从15000开始去master上拉取消息进行消费，在DefaultMessageStore.getMessage()中，当发现offset
> overflow严重溢出（大于maxOffset）时，就可能会把nextBeginOffset设置为0（
> 恰好此consumequeue的minoffset为0），下次就从offset=0开始拉取消息。
>
>
> 开始从0消费就会拉取很久前的消息数据了。
>
>
>
> 我猜测这不是rocketmq的bug，*应该是RocketMQ审慎的选择，它的原则是：宁愿多消费，重复消费也不要漏消费。*
>
>
> 之所以这么设计，我的猜测或者解释如下：
>
>
> *当consumeQueue的minOffset=0时，说明这个consumeQueue可能是新的queue，也可能是新扩容的queue，这时候为了避免有消息漏掉，在超过maxOffset这种奇怪的情况下，消费端下次消费就从0开始消费，宁愿重复消费也不要漏掉消费。*
>
>
> *当minOffset大于0时，说明这个queue已经长时间存在过了，不会是新queue，也不会是新扩容的，只需从maxOffset继续消费就行了。*
>
>
> 这么设计正常情况下没有问题，但是当一个topic下面的某个queue上积压了很多消息，并且minOffset=0时(表示没有删除过)。
> 这时候master突然宕机了，slave上的数据比master新，并且消费客户端从slave上消费了这个queue上的消息。
> master重启后，消费客户端切换到master上消费，发现自己消费的消息对于master已经溢出了，
> 根据上面的逻辑，就会从0重新消费，大量重复消费，并且会消费那些已经从commitlog中删除的消息，出现大量错误日志。
>
>
> 再看看刚发布不久的Apache RocketMQ 4.2.0版本中DefaultMessageStore.getMessage()*这段的*实现，
>
>
>
>
> 其中this.getMessageStoreConfig().isOffsetCheckInSlave()默认为false，
> 默认不开启在slave上offset的检查。Apache版本的实现更复杂了一点，但是依然解决不了这个问题。
>
>
> Apache版本的逻辑是：当master宕机后，slave数据比master新。消费端先从slave消费，
> master重启后，消费端再从master消费，当minoffset为0时还会从0开始从新消费。
>
> 当slave宕机后，master数据比slave的新，消费端从master消费消息。master再宕机，slave重启后，消费端从slave消费，
> 这时候会从master上记录的消费进度开始消费。因为slave的数据总归是来自于master，并且slave已经同步了master的新数据。
>
>
> 好了，问题分析到现在，我大概能说的通这个问题了，虽然事实不一定如此，也少有人碰到这个问题。
>
>
> 如果出现这种情况，也不知道怎么解决的话。我想到方式是：保留现场，堆栈信息，broker端日志，客户端日志，master和slave的所有数据文件。
> 处理好宕机临界点的数据，最终必须要重启master时，要拿备份的slave的数据文件覆盖master的数据文件，这些文件包括commitlog，
> consumequeue以及config下面的所有文件（消费进度），然后再重启。简单粗暴实用，避免master起来后负载飙升直至不可用的情况。
>
>
> 有什么风险呢？目前还不清楚。
>
>
> *总结：这是目前为止我发现的RocketMQ最严重的一个问题，**Apache版本也有此问题*。其他问题都是小打小闹，
> 没有太大影响，唯独此问题需要慎重处理。问题根源还是数据不一致，不支持高可用。集群内数据不一致，服务器端又处理不好这种不一致。
>
>
> 不过按照Apache RocketMQ的规划，要到4.3.0版本才支持高可用，应该不需要等很久。对于这个问题提了个issue：https:
> //issues.apache.org/jira/browse/ROCKETMQ-348
>
>
> 最后，*以上都属于猜测，大概也许可能是这个问题导致的，还望有高手出来指点迷津，此文算是抛砖引玉了。*
>
>
>
>
回复：投稿 RocketMQ Master宕机后重启出现的严重问题分析
Posted by 404828407 <40...@qq.com>.
cool
@hooligan
------------------ 原始邮件 ------------------
发件人: "hooligan"<79...@qq.com>;
发送时间: 2018年7月16日(星期一) 晚上11:46
收件人: "users"<us...@rocketmq.apache.org>;
主题: 回复：投稿 RocketMQ Master宕机后重启出现的严重问题分析
这个问题我这边也碰到过，是个非常严重的问题。。。而且碰到了两次，恢复起来特别麻烦，多谢分享
------------------
hooligan
------------------ 原始邮件 ------------------
发件人: "404828407"<40...@qq.com>;
发送时间: 2018年4月2日(星期一) 中午12:06
收件人: "users"<us...@rocketmq.apache.org>;
主题: 投稿 RocketMQ Master宕机后重启出现的严重问题分析
RocketMQ Master宕机后重启出现的严重问题分析
作者：卢松
以前发现RocketMQ的master机器宕机时会出现很多诡异的问题，所以最近做了一系列实验来试图找到问题的原因，也是想发现风险点。没想到发现了一个更严重的问题，下面会详细的说明下，另外出现问题的原因属于猜测，望高人看到后能指点下。
试验环境准备：
1.RocketMQ版本：阿里的3.2.6版本
2.集群包含2组broker，每组broker都是1master + 1slave，都设置成SYNC_MASTER、ASYNC_FLUSH模式。
3.每个broker上已经存储过好几个commitlog文件，并且已经有commitlog文件删除过（数据过期了）。
测试步骤：
1.尽量多的消费组、尽量多的消费者（10个以上）开始消费多个topic，消费者自始至终不停机。
2.在消费者消费时，突然把其中一组broker（姑且命名为BrokerA吧）的master断电（注意是断电或者硬盘损坏、不是kill -9）。
3.过一段时间（半小时左右），重启宕机的这个master。
观察现象，记录事后的现象及疑问：
1.BrokerA的slave机器一直存活着，master宕机后，消费者新的消费进度会存在slave上面。
2.宕机后，拉取BrokerA的master中的数据文件，文件没有损坏。
3.重启master后，消费客户端会从很久以前的queue offset开始拉取消息，为啥会去取到很久以前的queueOffset？
4.重启master后，这个master出现大量如下异常，异常日志达到10分钟每G的量：
{
"timestamp": "2017-12-28T00:18:48.620+0800",
"level": "WARN",
"thread": "FlushConsumeQueueService",
"logger": "RocketmqStoreError",
"message": "findMapedFileByOffset offset not matched, request Offset: 0, index: -6, mapedFileSize: 6000000, mapedFiles count: 2, StackTrace: \n\tjava.lang.Thread.getStackTrace(Thread.java:1567)\n\tcom.alibaba.rocketmq.common.UtilAll.currentStackTrace(UtilAll.java:59)\n\tcom.alibaba.rocketmq.store.MapedFileQueue.findMapedFileByOffset(MapedFileQueue.java:467)\n\tcom.alibaba.rocketmq.store.MapedFileQueue.commit(MapedFileQueue.java:442)\n\tcom.alibaba.rocketmq.store.ConsumeQueue.commit(ConsumeQueue.java:345)\n\tcom.alibaba.rocketmq.store.DefaultMessageStore$FlushConsumeQueueService.doFlush(DefaultMessageStore.java:1459)\n\tcom.alibaba.rocketmq.store.DefaultMessageStore$FlushConsumeQueueService.run(DefaultMessageStore.java:1479)\n\tjava.lang.Thread.run(Thread.java:722)"
}
5.另外还有大量的这种异常，这类异常显示大量消费客户端去拉取很久以前的消息。
{
"timestamp": "2017-12-28T00:39:01.748+0800",
"level": "WARN",
"thread": "PullMessageThread_15",
"logger": "RocketmqStoreError",
"message": "findMapedFileByOffset offset not matched, request Offset: 19382879484, index: -7, mapedFileSize: 1073741824, mapedFiles count: 2, StackTrace: \n\tjava.lang.Thread.getStackTrace(Thread.java:1567)\n\tcom.alibaba.rocketmq.common.UtilAll.currentStackTrace(UtilAll.java:59)\n\tcom.alibaba.rocketmq.store.MapedFileQueue.findMapedFileByOffset(MapedFileQueue.java:467)\n\tcom.alibaba.rocketmq.store.CommitLog.getMessage(CommitLog.java:664)\n\tcom.alibaba.rocketmq.store.DefaultMessageStore.getMessage(DefaultMessageStore.java:546)\n\tcom.alibaba.rocketmq.broker.processor.PullMessageProcessor.processRequest(PullMessageProcessor.java:283)\n\tcom.alibaba.rocketmq.broker.processor.PullMessageProcessor.processRequest(PullMessageProcessor.java:84)\n\tcom.alibaba.rocketmq.remoting.netty.NettyRemotingAbstract$1.run(NettyRemotingAbstract.java:172)\n\tjava.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)\n\tjava.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)\n\tjava.util.concurrent.FutureTask.run(FutureTask.java:166)\n\tjava.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)\n\tjava.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)\n\tjava.lang.Thread.run(Thread.java:722)"
}
这种现象的原因分析过程：
首先第二类异常出在PullMessageProcessor的拉取消息过程中，消费客户端不停拉取消息时，PullMessageProcessor会调用DefaultMessageStore.getMessage()，而在getMessage()中，更具体的是在CommitLog的public SelectMapedBufferResult getMessage(final long offset, final int size) 方法中，这个方法会调用MapedFileQueue的方法findMapedFileByOffset(final long offset, final boolean returnFirstOnNotFound)，具体看下图：
从代码上看，出现这个异常原因就是DefaultMessageStore.getMessage()中offsetPy拿到的值过小，这个值实际上是从ConsumeQueue的文件中读到的单条消息的CommitlogOffset，说明bufferConsumeQueue这个对象拿到的是老的数据。如下图：
bufferConsumeQueue对象又是根据offset定位的，offset是每一个queue的queueOffset，这个offset实际上是消费端拉取消息时传递过来的，它来自于两种地方，一是消费端自己拉取的消费进度，另外一种是消费端每次拉取消息，拉取不到后拿到的nextBeginOffset参数。如下图：
所以根源就出在这个nextBeginOffset的计算逻辑上，为什么nextBeginOffset会计算出过小的值，导致消费端一直在消费过小的queueOffset对应的消息？
我们先不去查这个问题的原因，就按照这个逻辑走下去，看看会发生什么情况。还是回到DefaultMessageStore.getMessage()中，当SelectMapedBufferResult selectResult = this.commitLog.getMessage(offsetPy, sizePy);拿不到数据后，selectResult返回的是null，这个方法最终返回的状态是GetMessageStatus.MESSAGE_WAS_REMOVING，表示消息的数据文件正在被删除。
而调用这个方法的PullMessageProcessor返回给消费客户端的是这个状态，请消费端立即尝试重新拉取消息：
消费客户端MQClientAPIImpl在方法PullResult processPullResponse(final RemotingCommand response) 处理这个返回状态，转换成NO_MATCHED_MSG的结果。
同样是消费客户端，在DefaultMQPushConsumerImpl的pullMessage(final PullRequest pullRequest)方法中，PullCallback是这么处理这种NO_MATCHED_MSG结果的：
从收到的nextBeginOffset开始，立即去重新拉取后面的消息。
而每次依然是去拉取很久前的消息，这样就形成了消费端不停拉取消息的日志，broker出现大量找不到消息的日志，并且broker负载很高。问题的关键是DefaultMessageStore.getMessage()中，为啥拿到的offsetPy是已经删除的commitlog offset，难道是/home/logs/rocketmq/store/consumequeue中文件损坏（这种可能性极低，目前还没有发现断电导致文件损坏的情况）？
那就有另一种可能：
master突然断电，master上数据就有可能丢失（没有来得及刷盘），consumequeue数据在master、slave的不一致。而消费端在master宕机后切换到slave上消费，消费进度也会提交到slave上，导致消费进度queue offset在master、slave上不一样。然后master重启后，消费端重新回到master拉取消息，master上的数据丢失了，master识别不出消费端提交的queue offset。
总结下，slave上存储的/home/logs/rocketmq/store/consumequeue比master新，假如slave上最小、最大offset是1000，15000，而这时候master的consumequeue最小、最大数据是1000，10000。当master重启后，消费客户端在slave上已经消费到15000，在master上会从15000开始去master上拉取消息进行消费，在DefaultMessageStore.getMessage()中，当发现offset overflow严重溢出（大于maxOffset）时，就可能会把nextBeginOffset设置为0（恰好此consumequeue的minoffset为0），下次就从offset=0开始拉取消息。
开始从0消费就会拉取很久前的消息数据了。
我猜测这不是rocketmq的bug，应该是RocketMQ审慎的选择，它的原则是：宁愿多消费，重复消费也不要漏消费。
之所以这么设计，我的猜测或者解释如下：
当consumeQueue的minOffset=0时，说明这个consumeQueue可能是新的queue，也可能是新扩容的queue，这时候为了避免有消息漏掉，在超过maxOffset这种奇怪的情况下，消费端下次消费就从0开始消费，宁愿重复消费也不要漏掉消费。
当minOffset大于0时，说明这个queue已经长时间存在过了，不会是新queue，也不会是新扩容的，只需从maxOffset继续消费就行了。
这么设计正常情况下没有问题，但是当一个topic下面的某个queue上积压了很多消息，并且minOffset=0时(表示没有删除过)。这时候master突然宕机了，slave上的数据比master新，并且消费客户端从slave上消费了这个queue上的消息。master重启后，消费客户端切换到master上消费，发现自己消费的消息对于master已经溢出了，根据上面的逻辑，就会从0重新消费，大量重复消费，并且会消费那些已经从commitlog中删除的消息，出现大量错误日志。
再看看刚发布不久的Apache RocketMQ 4.2.0版本中DefaultMessageStore.getMessage()这段的实现，
其中this.getMessageStoreConfig().isOffsetCheckInSlave()默认为false，默认不开启在slave上offset的检查。Apache版本的实现更复杂了一点，但是依然解决不了这个问题。
Apache版本的逻辑是：当master宕机后，slave数据比master新。消费端先从slave消费，master重启后，消费端再从master消费，当minoffset为0时还会从0开始从新消费。
当slave宕机后，master数据比slave的新，消费端从master消费消息。master再宕机，slave重启后，消费端从slave消费，这时候会从master上记录的消费进度开始消费。因为slave的数据总归是来自于master，并且slave已经同步了master的新数据。
好了，问题分析到现在，我大概能说的通这个问题了，虽然事实不一定如此，也少有人碰到这个问题。
如果出现这种情况，也不知道怎么解决的话。我想到方式是：保留现场，堆栈信息，broker端日志，客户端日志，master和slave的所有数据文件。处理好宕机临界点的数据，最终必须要重启master时，要拿备份的slave的数据文件覆盖master的数据文件，这些文件包括commitlog，consumequeue以及config下面的所有文件（消费进度），然后再重启。简单粗暴实用，避免master起来后负载飙升直至不可用的情况。
有什么风险呢？目前还不清楚。
总结：这是目前为止我发现的RocketMQ最严重的一个问题，Apache版本也有此问题。其他问题都是小打小闹，没有太大影响，唯独此问题需要慎重处理。问题根源还是数据不一致，不支持高可用。集群内数据不一致，服务器端又处理不好这种不一致。
不过按照Apache RocketMQ的规划，要到4.3.0版本才支持高可用，应该不需要等很久。对于这个问题提了个issue：https://issues.apache.org/jira/browse/ROCKETMQ-348
最后，以上都属于猜测，大概也许可能是这个问题导致的，还望有高手出来指点迷津，此文算是抛砖引玉了。
回复：投稿 RocketMQ Master宕机后重启出现的严重问题分析
Posted by hooligan <79...@qq.com>.
这个问题我这边也碰到过，是个非常严重的问题。。。而且碰到了两次，恢复起来特别麻烦，多谢分享
------------------
hooligan
------------------ 原始邮件 ------------------
发件人: "404828407"<40...@qq.com>;
发送时间: 2018年4月2日(星期一) 中午12:06
收件人: "users"<us...@rocketmq.apache.org>;
主题: 投稿 RocketMQ Master宕机后重启出现的严重问题分析
RocketMQ Master宕机后重启出现的严重问题分析
作者：卢松
以前发现RocketMQ的master机器宕机时会出现很多诡异的问题，所以最近做了一系列实验来试图找到问题的原因，也是想发现风险点。没想到发现了一个更严重的问题，下面会详细的说明下，另外出现问题的原因属于猜测，望高人看到后能指点下。
试验环境准备：
1.RocketMQ版本：阿里的3.2.6版本
2.集群包含2组broker，每组broker都是1master + 1slave，都设置成SYNC_MASTER、ASYNC_FLUSH模式。
3.每个broker上已经存储过好几个commitlog文件，并且已经有commitlog文件删除过（数据过期了）。
测试步骤：
1.尽量多的消费组、尽量多的消费者（10个以上）开始消费多个topic，消费者自始至终不停机。
2.在消费者消费时，突然把其中一组broker（姑且命名为BrokerA吧）的master断电（注意是断电或者硬盘损坏、不是kill -9）。
3.过一段时间（半小时左右），重启宕机的这个master。
观察现象，记录事后的现象及疑问：
1.BrokerA的slave机器一直存活着，master宕机后，消费者新的消费进度会存在slave上面。
2.宕机后，拉取BrokerA的master中的数据文件，文件没有损坏。
3.重启master后，消费客户端会从很久以前的queue offset开始拉取消息，为啥会去取到很久以前的queueOffset？
4.重启master后，这个master出现大量如下异常，异常日志达到10分钟每G的量：
{
"timestamp": "2017-12-28T00:18:48.620+0800",
"level": "WARN",
"thread": "FlushConsumeQueueService",
"logger": "RocketmqStoreError",
"message": "findMapedFileByOffset offset not matched, request Offset: 0, index: -6, mapedFileSize: 6000000, mapedFiles count: 2, StackTrace: \n\tjava.lang.Thread.getStackTrace(Thread.java:1567)\n\tcom.alibaba.rocketmq.common.UtilAll.currentStackTrace(UtilAll.java:59)\n\tcom.alibaba.rocketmq.store.MapedFileQueue.findMapedFileByOffset(MapedFileQueue.java:467)\n\tcom.alibaba.rocketmq.store.MapedFileQueue.commit(MapedFileQueue.java:442)\n\tcom.alibaba.rocketmq.store.ConsumeQueue.commit(ConsumeQueue.java:345)\n\tcom.alibaba.rocketmq.store.DefaultMessageStore$FlushConsumeQueueService.doFlush(DefaultMessageStore.java:1459)\n\tcom.alibaba.rocketmq.store.DefaultMessageStore$FlushConsumeQueueService.run(DefaultMessageStore.java:1479)\n\tjava.lang.Thread.run(Thread.java:722)"
}
5.另外还有大量的这种异常，这类异常显示大量消费客户端去拉取很久以前的消息。
{
"timestamp": "2017-12-28T00:39:01.748+0800",
"level": "WARN",
"thread": "PullMessageThread_15",
"logger": "RocketmqStoreError",
"message": "findMapedFileByOffset offset not matched, request Offset: 19382879484, index: -7, mapedFileSize: 1073741824, mapedFiles count: 2, StackTrace: \n\tjava.lang.Thread.getStackTrace(Thread.java:1567)\n\tcom.alibaba.rocketmq.common.UtilAll.currentStackTrace(UtilAll.java:59)\n\tcom.alibaba.rocketmq.store.MapedFileQueue.findMapedFileByOffset(MapedFileQueue.java:467)\n\tcom.alibaba.rocketmq.store.CommitLog.getMessage(CommitLog.java:664)\n\tcom.alibaba.rocketmq.store.DefaultMessageStore.getMessage(DefaultMessageStore.java:546)\n\tcom.alibaba.rocketmq.broker.processor.PullMessageProcessor.processRequest(PullMessageProcessor.java:283)\n\tcom.alibaba.rocketmq.broker.processor.PullMessageProcessor.processRequest(PullMessageProcessor.java:84)\n\tcom.alibaba.rocketmq.remoting.netty.NettyRemotingAbstract$1.run(NettyRemotingAbstract.java:172)\n\tjava.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)\n\tjava.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)\n\tjava.util.concurrent.FutureTask.run(FutureTask.java:166)\n\tjava.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)\n\tjava.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)\n\tjava.lang.Thread.run(Thread.java:722)"
}
这种现象的原因分析过程：
首先第二类异常出在PullMessageProcessor的拉取消息过程中，消费客户端不停拉取消息时，PullMessageProcessor会调用DefaultMessageStore.getMessage()，而在getMessage()中，更具体的是在CommitLog的public SelectMapedBufferResult getMessage(final long offset, final int size) 方法中，这个方法会调用MapedFileQueue的方法findMapedFileByOffset(final long offset, final boolean returnFirstOnNotFound)，具体看下图：
从代码上看，出现这个异常原因就是DefaultMessageStore.getMessage()中offsetPy拿到的值过小，这个值实际上是从ConsumeQueue的文件中读到的单条消息的CommitlogOffset，说明bufferConsumeQueue这个对象拿到的是老的数据。如下图：
bufferConsumeQueue对象又是根据offset定位的，offset是每一个queue的queueOffset，这个offset实际上是消费端拉取消息时传递过来的，它来自于两种地方，一是消费端自己拉取的消费进度，另外一种是消费端每次拉取消息，拉取不到后拿到的nextBeginOffset参数。如下图：
所以根源就出在这个nextBeginOffset的计算逻辑上，为什么nextBeginOffset会计算出过小的值，导致消费端一直在消费过小的queueOffset对应的消息？
我们先不去查这个问题的原因，就按照这个逻辑走下去，看看会发生什么情况。还是回到DefaultMessageStore.getMessage()中，当SelectMapedBufferResult selectResult = this.commitLog.getMessage(offsetPy, sizePy);拿不到数据后，selectResult返回的是null，这个方法最终返回的状态是GetMessageStatus.MESSAGE_WAS_REMOVING，表示消息的数据文件正在被删除。
而调用这个方法的PullMessageProcessor返回给消费客户端的是这个状态，请消费端立即尝试重新拉取消息：
消费客户端MQClientAPIImpl在方法PullResult processPullResponse(final RemotingCommand response) 处理这个返回状态，转换成NO_MATCHED_MSG的结果。
同样是消费客户端，在DefaultMQPushConsumerImpl的pullMessage(final PullRequest pullRequest)方法中，PullCallback是这么处理这种NO_MATCHED_MSG结果的：
从收到的nextBeginOffset开始，立即去重新拉取后面的消息。
而每次依然是去拉取很久前的消息，这样就形成了消费端不停拉取消息的日志，broker出现大量找不到消息的日志，并且broker负载很高。问题的关键是DefaultMessageStore.getMessage()中，为啥拿到的offsetPy是已经删除的commitlog offset，难道是/home/logs/rocketmq/store/consumequeue中文件损坏（这种可能性极低，目前还没有发现断电导致文件损坏的情况）？
那就有另一种可能：
master突然断电，master上数据就有可能丢失（没有来得及刷盘），consumequeue数据在master、slave的不一致。而消费端在master宕机后切换到slave上消费，消费进度也会提交到slave上，导致消费进度queue offset在master、slave上不一样。然后master重启后，消费端重新回到master拉取消息，master上的数据丢失了，master识别不出消费端提交的queue offset。
总结下，slave上存储的/home/logs/rocketmq/store/consumequeue比master新，假如slave上最小、最大offset是1000，15000，而这时候master的consumequeue最小、最大数据是1000，10000。当master重启后，消费客户端在slave上已经消费到15000，在master上会从15000开始去master上拉取消息进行消费，在DefaultMessageStore.getMessage()中，当发现offset overflow严重溢出（大于maxOffset）时，就可能会把nextBeginOffset设置为0（恰好此consumequeue的minoffset为0），下次就从offset=0开始拉取消息。
开始从0消费就会拉取很久前的消息数据了。
我猜测这不是rocketmq的bug，应该是RocketMQ审慎的选择，它的原则是：宁愿多消费，重复消费也不要漏消费。
之所以这么设计，我的猜测或者解释如下：
当consumeQueue的minOffset=0时，说明这个consumeQueue可能是新的queue，也可能是新扩容的queue，这时候为了避免有消息漏掉，在超过maxOffset这种奇怪的情况下，消费端下次消费就从0开始消费，宁愿重复消费也不要漏掉消费。
当minOffset大于0时，说明这个queue已经长时间存在过了，不会是新queue，也不会是新扩容的，只需从maxOffset继续消费就行了。
这么设计正常情况下没有问题，但是当一个topic下面的某个queue上积压了很多消息，并且minOffset=0时(表示没有删除过)。这时候master突然宕机了，slave上的数据比master新，并且消费客户端从slave上消费了这个queue上的消息。master重启后，消费客户端切换到master上消费，发现自己消费的消息对于master已经溢出了，根据上面的逻辑，就会从0重新消费，大量重复消费，并且会消费那些已经从commitlog中删除的消息，出现大量错误日志。
再看看刚发布不久的Apache RocketMQ 4.2.0版本中DefaultMessageStore.getMessage()这段的实现，
其中this.getMessageStoreConfig().isOffsetCheckInSlave()默认为false，默认不开启在slave上offset的检查。Apache版本的实现更复杂了一点，但是依然解决不了这个问题。
Apache版本的逻辑是：当master宕机后，slave数据比master新。消费端先从slave消费，master重启后，消费端再从master消费，当minoffset为0时还会从0开始从新消费。
当slave宕机后，master数据比slave的新，消费端从master消费消息。master再宕机，slave重启后，消费端从slave消费，这时候会从master上记录的消费进度开始消费。因为slave的数据总归是来自于master，并且slave已经同步了master的新数据。
好了，问题分析到现在，我大概能说的通这个问题了，虽然事实不一定如此，也少有人碰到这个问题。
如果出现这种情况，也不知道怎么解决的话。我想到方式是：保留现场，堆栈信息，broker端日志，客户端日志，master和slave的所有数据文件。处理好宕机临界点的数据，最终必须要重启master时，要拿备份的slave的数据文件覆盖master的数据文件，这些文件包括commitlog，consumequeue以及config下面的所有文件（消费进度），然后再重启。简单粗暴实用，避免master起来后负载飙升直至不可用的情况。
有什么风险呢？目前还不清楚。
总结：这是目前为止我发现的RocketMQ最严重的一个问题，Apache版本也有此问题。其他问题都是小打小闹，没有太大影响，唯独此问题需要慎重处理。问题根源还是数据不一致，不支持高可用。集群内数据不一致，服务器端又处理不好这种不一致。
不过按照Apache RocketMQ的规划，要到4.3.0版本才支持高可用，应该不需要等很久。对于这个问题提了个issue：https://issues.apache.org/jira/browse/ROCKETMQ-348
最后，以上都属于猜测，大概也许可能是这个问题导致的，还望有高手出来指点迷津，此文算是抛砖引玉了。