平台迁移到云平台后,交易逐步恢复正常,在日常监控业务情况时,发现一个业务突然出现大量异常,本文记录排查过程。
1. 发现问题
下图红色部分,为大量报出异常的应用,排查发现,错误出现在处理交易通知的时候。在系统收到通知后,回继续逻辑,然后将结果放入MQ中,由通知系统下发给商户。问题就出在消息写入MQ的结果上,代码中判断写入状态为 SendStatus.SEND_OK时,写入成功,但是现在执行了异常流程,更奇怪的是,后续业务并没有受影响。
2. 分析与排查
现在知道了以下前提:
- MQ写入状态不是:SendStatus.SEND_OK
- 后续业务正常,说明消息实际是写入成功了
2.1 RocketMq的投递状态
FLUSH_DISK_TIMEOUT
如果 Broker 设置MessageStoreConfig的FlushDiskType=SYNC_FLUSH(默认是ASYNC_FLUSH),并且代理没有在MessageStoreConfig的syncFlushTimeout(默认是5秒)时间内完成刷盘,您将获得这个状态。FLUSH_SLAVE_TIMEOUT
如果 Broker 的角色是 SYNC_MASTER (默认是ASYNC_MASTER),并且 Slave Broker 没有在MessageStoreConfig的syncFlushTimeout(默认是5秒)时间内完成同步,您将得到这个状态。SLAVE_NOT_AVAILABLE
消息发送成功,但是此时Slave不可用。如果Broker服务器的角色是同步Master,即SYNC_MASTER(默认是异步Master服务器即ASYNC_MASTER),但没有配置slave Broker服务器,则将返回该状态——无Slave服务器可用。SEND_OK
SEND_OK 并不意味着它是可靠的。为了确保没有信息会丢失,应启用 SYNC_MASTER 或 SYNC_FLUSH
从以上可以猜测,系统当前的投递状态应该是“ SLAVE_NOT_AVAILABLE”,但是由于日志没有打印投递异常时的具体状态值,所以要想验证具体的状态,只能想其他办法了。
2.2 arthas 查看方法变量的值
Arthas 是Alibaba开源的Java诊断工具,深受开发者喜爱。
当你遇到以下类似问题而束手无策时,Arthas可以帮助你解决:
这个类从哪个 jar 包加载的?为什么会报各种类相关的 Exception?
我改的代码为什么没有执行到?难道是我没 commit?分支搞错了?
遇到问题无法在线上 debug,难道只能通过加日志再重新发布吗?
线上遇到某个用户的数据处理有问题,但线上同样无法 debug,线下无法重现!
是否有一个全局视角来查看系统的运行状况?
有什么办法可以监控到JVM的实时运行状态?
怎么快速定位应用的热点,生成火焰图?
目前业务虽然报错,但是实际逻辑还是完整的,为了最小化影响,不能采取紧急的修复,所以决定使用arthas观察一下相关方法的内部变量值,看看投递状态到底是什么。
首先,找到报错的代码处,添加一个日志打印出投递状态,然后将类编译。
if (Objects.nonNull(sendResult) && sendResult.getSendStatus() == SendStatus.SEND_OK) {
result = true;
}
else {
// 新增异常日志
logger.error("error sendStatus:{}", (Object)sendResult.getSendStatus());
}
然后将编译好的类,上传到服务器,按照arthas的操作指南,定位到要调试的应用。
$ $ java -jar arthas-boot.jar
* [1]: 35542
[2]: 71560 my-app.jar
my-app进程是第2个,则输入2,再输入回车/enter。Arthas会attach到目标进程上,并输出日志:
[INFO] Try to attach process 71560
[INFO] Attach process 71560 success.
[INFO] arthas-client connect 127.0.0.1 3658
,---. ,------. ,--------.,--. ,--. ,---. ,---.
/ O \ | .--. ''--. .--'| '--' | / O \ ' .-'
| .-. || '--'.' | | | .--. || .-. |`. `-.
| | | || |\ \ | | | | | || | | |.-' |
`--' `--'`--' '--' `--' `--' `--'`--' `--'`-----'
wiki: https://arthas.aliyun.com/doc
version: 3.0.5.20181127201536
pid: 71560
time: 2018-11-28 19:16:24
$
redefine
加载外部的.class文件,redefine jvm已加载的类。
这里,我们用重新编译好的添加了日志打印的类,替换jvm里的类。
在arthas终端界面,执行命令:
redefine /tmp/YourClass.class
替换完成后,观察应用日志,发现投递状态确实为“ SLAVE_NOT_AVAILABLE”/
2.3 检测RocketMq双主集群
在控制台可见,集群能够正常的识别,但是消息记录中,slave节点确实都为0,问题确实存在。
经过运维的再三排查,说集群配置没有问题。再经过数个小时的强迫性排查后,在晚上运维给出了一个让人啼笑皆非的原因:
🐶🐶🐶🐶🐶🐶🐶🐶🐶🐶🐶🐶🐶🐶🐶🐶🐶🐶🐶🐶🐶🐶
🐶slave节点的10911端口没有开放,导致无法与master实时同步🐶
🐶🐶🐶🐶🐶🐶🐶🐶🐶🐶🐶🐶🐶🐶🐶🐶🐶🐶🐶🐶🐶🐶
年轻人,希望你“耗子尾汁”!
年轻人,希望你“耗子尾汁”!!
年轻人,希望你“耗子尾汁”!!!
3. 收获
在排错过程中,不要完全相信任何人,特别是运维。
要避免灯下黑的现象。