记一次logback导致服务无响应排查过程

1. 前沿

记录最近收到测试环境服务无响应处理过程。

2. 定位

2.1 排查服务资源使用情况

通过top命令和阿里云监控发现服务cpu和资源都正常,第一反应是死锁。

2.2 导出线程信息

通过jstack -l命令导出线程信息发现服务所有响应到卡住logback的log上，因为以前也遇到logback死锁导致类似异常,发现服务的logback版本是1.1.11版本(该版本有死锁bug)后，愉快的升级到1.2.3版。然而很快的服务还是出现无响应。再仔细观察了logback配置后发现有配置console，又愉快地把console配置删掉。结果又出现无响应

2.3 导出堆栈信息

旧的版本是正常，查了下这期迭代改动发现什么异常。只好老老实实导出jmap导出堆栈信息下来查看是否异常。通过堆栈信息hsf的AsyncAppenderBase.ArrayBlockingQueue确实已经满了导致了堵塞。

2.4 查看io是否异常

怀疑是不是io异常导致，联系了运维排查后发现是正常的。其实也符合逻辑，如果是io异常应该是连启动都启动不了，如果是io抖动应该后续也会恢复并且不是必现。

2.5 查看logback代码

旧的版本是正常，查了下这期迭代改动发现什么异常。查看AsyncAppenderBase了解AsyncAppenderBase是通过生产者消费者模式来实现异步log的。
生产者调用append时会把log发在ArrayBlockingQueue里。

消费者AsyncAppenderBase.Work会取拉取ArrayBlockingQueue的log进行写入。发现AsyncAppenderBase.Work只捕获了InterruptedException异常如果是其他异常就会导致AsyncAppenderBase.Work推出，从而导致AsyncAppenderBase.put都卡住。

查看了堆栈信息发现服务起了4个AsyncAppenderBase

但查看线程栈信息却发现只有3个AsyncAppender-Worker-null(公司event-sdk框架在设置异步log时没有设置name导致线程名都是AsyncAppender-Worker-null)。估计很有可能是因为异步消费异常导致线程退出的。

2.6 修改logback源码确定原因

修改代码重新部署后，通过postman批量调用服务接口后很快出现无响应，兴奋的查看日志异常后结合代码很快发现了问题原因。由于升级业务方接口版本导致包冲突，从而导致log在消费时json格式化异常，消费线程退出。定位到具体原因后问题也就很快解决了。