logback自定义kafkaAppender， 日志循环输出导致代码死锁

序

其实这个问题在一年前就发现并解决了，当时忙着做需求就没有整理出来~ 恰巧这段时间又“闲赋在家”，于是记录分享下

问题描述

现在需要将系统日志同步给kafka，而logback的appender扩展正适合做这个事：只需要写Appender的实现类，然后再在append方法内将数据发送给kafka就可以了。

具体怎么写自定义appender可以看我之前写的文章，大致思路是一样的
基于logback扩展的traceId方案

但当我测试代码的时候发现了一个严重的问题，在同步日志的模式下，系统启动卡住至少30秒，而用异步appender的方式就不会有这个问题。

解决思路

从表现来看，springboot启动长时间卡死，很有可能是内部发生了死锁。
使用jstack查看线程dump日志，果不其然，确实有锁等待的情况发生，等待的锁对象是位于0x0000000686400000的一个ProducerMetadata实例

搜索这个实例地址，果不其然发现有另外一个线程也wait在这个实例上，并且也是在同样的地方阻塞住了

进入代码ProducerMetadata类中阅读，发现ProducerMetadata作用是管理生产者所需的元数据信息，比如有哪些topic，有哪些broker，从ProducerMetadata里都可以知道。

再让我们定位到具体的方法内部

通过代码和注释我们可以知道这段代码是在send时，先检查当前的元数据是否是最新的，如果不是最新的，则使用syn+wait等待kafka的元数据更新，直到更新成功或者超时。这块代码会为ProducerMetadata实例加上synchronized（上图的obj就是ProducerMetadata）。

这样就可以解释的通同步日志下springboot启动卡死的原因了:

springboot启动时会打印log日志，而log日志执行到kafkaAppender的append时，kafka client调用send方法，send方法中ProducerMetadata会被syn+线程wait等待元数据更新到最新版本，但迟迟没有别的线程来唤醒它，最后超时了，springboot才启动成功

那我们要知道的就是为什么没有线程来notify它。

继续阅读代码，唯一能够notify它的代码如下图所示，它就是更新ProducerMetadata中元数据的代码。所以正常情况下就是kafka 在send前都会检查元数据是否是最新的，如果不是最新的，则等待拉取到最新元数据的线程通知它再继续往下执行

在同步模式下我们对notifyAll()这行打下断点，查看是否执行到，结果果然是没有。
此时切换到异步模式，再尝试，发现notifyAll是可以被执行到的

结合断点情况和线程dump日志的结果，我怀疑是不是因为负责拉取数据并notifyAll的线程也跑到
time.wait()里去了呢

切回同步模式，我们再对之前的time.wait()这行打下断点。果不其然，通过对第二次wait时的线程堆栈往前回溯，发现就是因为update方法里也有log.info代码，导致导致在同步模式下，update和send的线程都在同一处被wait，没有线程notify它们。

解决方法

专有线程消费kafka组件本身的log

对于属于kafka本身的log日志，延迟处理，而不是同步处理

1. 准备一个特殊队列队列，专门存放kafka本身的日志
   
2. 准备一个专门的线程，消费kafka日志。这块也可以改成定时消费，比如3秒，而不是一直while(true)
   
   可能小伙伴会说kafka的日志即便单独处理输出，不也是会造成无限递归(send的og日志又触发send)输出日志吗？其实不然。
   logback的框架已经考虑这一点了
   
   在同一线程内，一条log只会输出一次，递归输出时，guard的值为true，直接被阻断。