URL
date
slug
status
tags
summary
type
RocketMQ 4.6.0 Message Trace 功能异常排查
背景
使用RocketMQ已经有5年以上了，但是对于Message Trace这个功能还没怎么用过。之前也想用来着，但是从RocketMQ-Console里访问总是报错。并且因为我们每条日志都记录了traceId，通过traceId我们可以把上下游链路串联起来，也能达到Message Trace的效果，所以一直也没有对上述的报错仔细排查。
现象
我们来看看到底是什么报错，让我们的Message Trace进程，迟到了这么多年。
问题1——测试环境报错
这个是我们qa环境的报错。能查到具体的消息，但是点击Message Trace Detail就报错。看错误描述应该是找不到对应的消息
问题2——生产环境报错
这个和测试环境的报错类似，也是点击Message Trace Detail的时候报错，但是提示信息不一样，看描述应该是找不到RMQ_SYS_TRACE_TOPIC这个topic的route信息
问题3——开发环境缺少trace信息
开发环境 点击Message Trace Detail 能弹出看似正常的Dialog，但是里面只有一条Pub信息，也就是producer发消息的那个节点，而没有消费者消息的节点。
排查
针对以上3个问题，我们一一给出解答
问题1
这个解答可能会让你大跌眼镜——问题的关键竟然在于语言切换。切换成简体中文版，点击按钮就会报错，而开发环境恰好当时切换到了英文版，所以可以点开。这个问题真的挺让人汗颜的，也就不会时间去深究了
问题2
这个应该是由于我们的生产环境没有开启自动创建topic的功能，因为Message Trace这个功能是的trace信息，是借助了一个topic去保存的，这个topic默认就是RMQ_SYS_TRACE_TOPIC。我们手动把这个topic建上，并且把语言切换到英文，应该就可以顺利点开了，如开发环境一样。
问题3
相比上面2个问题，这个问题就会显得稍微复杂一些了。这里先给出结论：因为rocketmq-client在启动过程中，对于消费者组的trace组件启动的时候报错了。导致consumer的trace hook没起作用，所以也就没有收集到消费相关的trace信息了。
我们能在rocketmq的日志文件里看到如下异常
这个就是我们consumer端的TraceDispatcher启动失败的异常了。它的启动失败不会影响主流程，并且日志也是在rocketmq单独的日志文件里的，所以不太容易被关注到。
那么具体是因为什么启动失败了呢？接下来我们就需要通过阅读源代码来得出结论了
首先根据报错信息找到调用链路，可以看到就是在DefaultMQPushConsumer启动的时候报错的
consumer如果有设置traceDispatcher，那么在它启动的时候会同时启动traceDispatcher
而traceDispatcher启动的时候，会先启动traceProducer
这里有2点要特殊说明一下：
- traceProducer的类型是DefaultMQProducer，它也是一个RocketMQ的生产者
- 它的instanceName是一个固定的前缀加上nameServer的地址
我们继续看traceProducer的start方法
原来生产者在启动的时候也会同时启动traceDispatcher，这是用来收集发送端的trace信息的，不过这里针对的都是普通的producer。traceProducer不会再设置traceDispatcher，不然就套娃了。
那么我们继续看defaultMQProducerImpl.start，这个就是报错的地方了
可以看到，报错的原因就是因为同一个mQClientFactory内，存在了同名的producer。我们再找找着个traceProducer的producerGroup写的是什么。
可以看到，traceProducer的producerGroup是一个写死的值。那实际上只要创建1个以上的AsyncTraceDispatcher就会导致刚才的问题。我们来找找创建AsyncTraceDispatcher的地方：
这里其实就是在producer和consumer的构造函数里创建出来的。所以，只要producer数量+consumer数量 > 1，那么就会报上述异常，超出几个就会报多少次。
我们没有直接使用原生rocketmq的API，而是通过rocketmq-spring这个项目来使用的。在它的AutoConfiguration里，是会优先创建并启动producer，consumer会在所有singletons实例化完成之后被注入到容器中。
终于，问题3真相大白了，原来是rocketmq 4.6.0的bug。找了下官方github也有类似的issue
问题在4.6.1版本中被修复了
扩展阅读——Message Trace原理
这个知识点我们先来考考chatgpt，看看它怎么回答
首先，Message Trace主要有三种节点类型
- Pub 发送
- SubBefore 消费开始
- SubAfter 消费结束
根据这三种类型，我们需要在发送和消费的地方做埋点。RocketMQ本身就提供了一系列的Hook机制，可以在发送消息或者消费消息的时候进行拦截。
下面我们贴两段源代码，内容非常简单，就是收集发送的trace信息和消费的trace信息的
上面的代码整体比较简单，我列一下需要注意的2点
- 发送消息的时候，traceBeans数量永远为1，对于批量发消息的场景，也是一样的，因为批量消息也是1个Message，在实现上使用了子类MessageBatch来做的
- 消费消息的时候，traceBeans数量是根据1个批次（默认为1）的消息量来的
可以看到，trace信息组装完成之后，会append到localDispatcher里，我们来看看是如何处理的
很简单，这里只是把trace信息塞到了1个有界队列ArrayBlockingQueue里，队列长度是1024，并且在队列满了的时候，会打印日志。此时trace信息会被丢弃。这一看就是一个典型的 生产-消费 模式，那我们再看看这个traceContextQueue的消费逻辑
AsyncRunnable会消费traceContextQueue，并且尽量凑成1个批次（batchSize为100），当然如果trace信息不够也不会硬等，timeout了就继续循环。然后把这个批次打包成AsyncAppenderRequest，并提交到traceExecutor这个线程池中执行。
AsyncAppenderRequest里前半部分组装逻辑我们不去深究，就看flushData就可以了
这里是每到maxMessageSize或者是整体组装完了，就会发送trace数据到远端。那么具体是怎么发的呢？
可以看到，底层用的是traceProducer，原来是通过新增了一个特殊的producer来实现的。
背景
RocketMQ的相识和使用已经有大概5年以上了，但是对于Message Trace这个功能还没怎么用过。之前想用来着，但是从RocketMQ-Console里访问总是报错。并且因为增加了全局Trace，通过日志我们也能达到Message Trace的效果，所以一直也没有对上述的报错仔细排查。
现象
我们来看看到底是什么报错，让我们的Message Trace进程，迟到了这么多年。
问题1——测试环境报错
这个是我们qa环境的报错。能查到具体的消息，但是点击Message Trace Detail就报错。看错误描述应该是找不到对应的消息
问题2——生产环境报错
这个和测试环境的报错类似，也是点击Message Trace Detail的时候报错，但是提示信息不一样，看描述应该是找不到RMQ_SYS_TRACE_TOPIC这个topic的route信息
问题3——开发环境缺少trace信息
开发环境 点击Message Trace Detail 能弹出看似正常的Dialog，但是里面只有一条Pub信息，也就是producer发消息的那个节点，而没有消费者消息的节点。
排查
针对以上3个问题，我们一一给出解答
问题1
这个解答可能会让你大跌眼镜——问题的关键竟然在于语言切换。切换成简体中文版，点击按钮就会报错，而开发环境恰好当时切换到了英文版，所以可以点开。这个问题真的挺让人汗颜的，也就不会时间去深究了
问题2
这个应该是由于我们的生产环境没有开启自动创建topic的功能，因为Message Trace这个功能是的trace信息，是借助了一个topic去保存的，这个topic默认就是RMQ_SYS_TRACE_TOPIC。我们手动把这个topic建上，并且把语言切换到英文，应该就可以顺利点开了，如开发环境一样。
问题3
相比上面2个问题，这个问题就会显得稍微复杂一些了。这里先给出结论：因为rocketmq-client在启动过程中，对于消费者组的trace组件启动的时候报错了。导致consumer的trace hook没起作用，所以也就没有收集到消费相关的trace信息了。
我们能在rocketmq的日志文件里看到如下异常
这个就是我们consumer端的TraceDispatcher启动失败的异常了。它的启动失败不会影响主流程，并且日志也是在rocketmq单独的日志文件里的，所以不太容易被关注到。
那么具体是因为什么启动失败了呢？接下来我们就需要通过阅读源代码来得出结论了
首先根据报错信息找到调用链路，可以看到就是在DefaultMQPushConsumer启动的时候报错的
consumer如果有设置traceDispatcher，那么在它启动的时候会同时启动traceDispatcher
而traceDispatcher启动的时候，会先启动traceProducer
这里有2点要特殊说明一下：
- traceProducer的类型是DefaultMQProducer，它也是一个RocketMQ的生产者
- 它的instanceName是一个固定的前缀加上nameServer的地址
我们继续看traceProducer的start方法
原来生产者在启动的时候也会同时启动traceDispatcher，这是用来收集发送端的trace信息的，不过这里针对的都是普通的producer。traceProducer不会再设置traceDispatcher，不然就套娃了。
那么我们继续看defaultMQProducerImpl.start，这个就是报错的地方了
可以看到，报错的原因就是因为同一个mQClientFactory内，存在了同名的producer。我们再找找着个traceProducer的producerGroup写的是什么。
可以看到，traceProducer的producerGroup是一个写死的值。那实际上只要创建1个以上的AsyncTraceDispatcher就会导致刚才的问题。我们来找找创建AsyncTraceDispatcher的地方：
这里其实就是在producer和consumer的构造函数里创建出来的。所以，只要producer数量+consumer数量 > 1，那么就会报上述异常，超出几个就会报多少次。
我们没有直接使用原生rocketmq的API，而是通过rocketmq-spring这个项目来使用的。在它的AutoConfiguration里，是会优先创建并启动producer，consumer会在所有singletons实例化完成之后被注入到容器中。
终于，问题3真相大白了，原来是rocketmq 4.6.0的bug。找了下官方github也有类似的issue
问题在4.6.1版本中被修复了
扩展阅读——Message Trace原理
这个知识点我们先来考考chatgpt，看看它怎么回答
首先，Message Trace主要有三种节点类型
- Pub 发送
- SubBefore 消费开始
- SubAfter 消费结束
根据这三种类型，我们需要在发送和消费的地方做埋点。RocketMQ本身就提供了一系列的Hook机制，可以在发送消息或者消费消息的时候进行拦截。
下面我们贴两段源代码，内容非常简单，就是收集发送的trace信息和消费的trace信息的
上面的代码整体比较简单，我列一下需要注意的2点
- 发送消息的时候，traceBeans数量永远为1，对于批量发消息的场景，也是一样的，因为批量消息也是1个Message，在实现上使用了子类MessageBatch来做的
- 消费消息的时候，traceBeans数量是根据1个批次（默认为1）的消息量来的
可以看到，trace信息组装完成之后，会append到localDispatcher里，我们来看看是如何处理的
很简单，这里只是把trace信息塞到了1个有界队列ArrayBlockingQueue里，队列长度是1024，并且在队列满了的时候，会打印日志。此时trace信息会被丢弃。这一看就是一个典型的 生产-消费 模式，那我们再看看这个traceContextQueue的消费逻辑
AsyncRunnable会消费traceContextQueue，并且尽量凑成1个批次（batchSize为100），当然如果trace信息不够也不会硬等，timeout了就继续循环。然后把这个批次打包成AsyncAppenderRequest，并提交到traceExecutor这个线程池中执行。
AsyncAppenderRequest里前半部分组装逻辑我们不去深究，就看flushData就可以了
这里是每到maxMessageSize或者是整体组装完了，就会发送trace数据到远端。那么具体是怎么发的呢？
可以看到，底层用的是traceProducer，原来是通过新增了一个特殊的producer来实现的。
- 作者:黑微狗
- 链接:https://blog.hwgzhu.com/article/rocketmq-4.6.0-message-trace
- 声明:本文采用 CC BY-NC-SA 4.0 许可协议，转载请注明出处。
.jpeg?table=block&id=9c5834f3-d0d0-4740-bf3c-7b77e72b9452){kind=tracking}