分布式环境下flume实例的日志收集+KafkaLog4jAppender死锁问题定位及解决

一、背景

目前使用flume（apache下的一个开源的顶级项目,是一个分布式,可扩展,高可用,高可靠的,轻量级数据收集框架,主要用来做数据的收集,聚合,和传输）进行日志数据的传输与分发，flume集群有多台机器，每个机器上均有20左右个flume在运行，对于flume的指标监控，我们采用的jvm exporter + prometheus + grafana，实现了对flume的全方位的指标监控（jvm、source、channel、sink），flume本身采用slf4j桥接log4j的方式将日志打印到本地日志文件，这种日志存储方式在分布式环境下是不利于日志信息的查看与异常定位的，所以将这些日志统一收集并存储起来进行监控是最优雅的方式。

二、技术方案

方案一

在每台flume的机器上再额外部署一个flume实例，这个flume实例使用 Taildir Source + Memory Channel + ElasticSearch Sink 将本机上业务flume实例的日志采集起来然后存储到ES集群。

优点：

1. 已有的flume实例无需做任何改动，业务侵入性为零；
2. 配置方便，平坦无坑，监控文件并采集新增行是flume天然的特性，也是被用的最广泛、最成熟的flume source。

缺点：

1. 需要在每台机器上都部署一个额外的flume实例，以后新增机器后都需要重复这样的操作，增加了运维复杂性；
2. 需要在这个额外的flume配置文件中增加其他业务flume的日志文件路径，当业务flume实例多了以后，填写配置文件也是及其痛苦的一件事（不要问我为什么这么说o(╯□╰)o）。

方案二

业务flume实例直接将日志发送至kafka，kafka的数据到ES的数据同步就采用一个flume实例即可：Kafka Source + ElasticSearch Sink。我们知道在log4j中，决定日志存到哪的组件是appender，恰好kafka项目中有一个KafkaLog4jAppender，可以直接将log4j的日志发送至kafka的topic。

优点：

1. 只需要修改一下log4j.properties即可将flume日志统一收集起来，运维起来最方便；

缺点：

1. 对业务flume实例有些须的侵入性；
2. 有未知的技术坑。

最终选型

在我看来，方案二目前是最优雅的方式了。虽然没试过，可能会有未知坑，但是这才是我们技术人的乐趣所在。

三、实施过程

1. 下载KafkaLog4jAppender的jar包以及依赖
在maven中央仓库中，可以看到，KafkaLog4jAppender最新版为2.4，但为了与flume的lib下的kafka jar版本（2.0.1）保持一致，我们选择2.0.1版本进行下载：

另外也可以看到依赖的其他jar包只有slf4j与kafka，这两个在flume的libs下都已经有了，所以就不必下载了：

按照flume的插件放置规范，下载好的kafka-log4j-appender-2.0.1.jar放到plugins.d/kafka-log4j-appender/lib下，不存在目录需自己创建。
2. 配置log4j.properties

增加kafka appender

flume.root.logger=INFO,FILE  增加KAFKA

配置kafka appender

log4j.appender.KAFKA=org.apache.kafka.log4jappender.KafkaLog4jAppender
log4j.appender.KAFKA.topic=srvlog_flume
log4j.appender.KAFKA.syncSend=true
log4j.appender.KAFKA.brokerList=broker1:9092,broker2:9092,broker3:9092
log4j.appender.KAFKA.compressionType=none
log4j.appender.KAFKA.layout=net.logstash.log4j.JSONEventLayoutV1

log4j.properties完整配置如下

flume.root.logger=INFO,FILE,KAFKA
flume.log.dir=./logs
flume.log.file=flume

log4j.logger.org.apache.flume.lifecycle = INFO
log4j.logger.org.jboss = WARN
log4j.logger.org.mortbay = INFO
log4j.logger.org.apache.avro.ipc.NettyTransceiver = WARN
log4j.logger.org.apache.hadoop = INFO
log4j.logger.org.apache.hadoop.hive = ERROR
log4j.logger.org.apache.kafka = INFO

# 这是原有的file appender，最好保留原有日志文件，用于效果对比
log4j.appender.FILE=org.apache.log4j.RollingFileAppender
log4j.appender.FILE.MaxFileSize=100MB
log4j.appender.FILE.MaxBackupIndex=10
log4j.appender.FILE.File=${flume.log.dir}/${flume.log.file}.log
log4j.appender.FILE.layout=org.apache.log4j.PatternLayout
log4j.appender.FILE.layout.ConversionPattern=%d{dd MMM yyyy HH:mm:ss,SSS} %-5p [%t] (%C.%M:%L) %x - %m%n

# 这是我们新增的kafka log4j appender
log4j.appender.KAFKA=org.apache.kafka.log4jappender.KafkaLog4jAppender
log4j.appender.KAFKA.topic=srvlog_flume
log4j.appender.KAFKA.syncSend=false
log4j.appender.KAFKA.brokerList=broker1:9092,broker2:9092,broker3:9092
log4j.appender.KAFKA.compressionType=none
log4j.appender.KAFKA.layout=net.logstash.log4j.JSONEventLayoutV1

完成上述两步后，就可以启动flume实例了，这时候诡异的事情就发生了，实例启动后，flume.log居然没有任何日志输出了，另外kafka的topic中也没有数据写入，就好像是程序没启动一般。。

四、KafkaLog4jAppender死锁问题定位及解决

1.问题定位

首先经过一番google后确认，配置文件写的没有问题，通过grafana上的监控看到，flume已经不收集数据也不写入数据了：

JVM的堆内存占用也没有出现疯涨，可以排除内存泄露：

这时候，jvm那些问题排查工具就派上用场了：jvisualvm、jstack、jstat等等，jvisualvm的图形化界面可以说是非常便捷，我们使用它来排查问题，
由于我们的flume开启了jmx，所以我们可以使用本地的jvisualvm远程连接服务器上的flume jvm实例：

点击界面上方的线程，提示出现了死锁，需要生成线程dump排查：

这时在界面上会生成线程dump信息，将信息完整复制下来粘贴到文本编辑器中，搜索“BLOCK”关键字，看下是哪些线程被锁住了，发现“main线程”与"kafka-producer-network-thread"两个线程被锁住了：


在截图中可以看到，main线程锁住了<4c211e14>(org.apache.log4j.spi.RootLogger)对象，并且在等待<18a64fce> (org.apache.kafka.clients.Metadata)对象锁，而kafka-producer-network-thread线程则相反，锁住了<18a64fce> (org.apache.kafka.clients.Metadata)对象，在等待main线程的<4c211e14>(org.apache.log4j.spi.RootLogger)对象锁，这便形成了是一个死锁，如果不手动停掉程序，程序会永远这样僵持下去。
在kafka 的jira中其实已经有人提出过此问题：KafkaLog4jAppender deadlocks when logging from producer network thread
回复是在log4j中提高org.apache.kafka.clients.Metadata类的输出级别至warn：

另外，我们在线程dump中可以看到kafka-producer-network-thread线程线程等待main线程的锁发生在Metadata类的285行：

可以看到这里用也到了log对象，而此时，main线程还被锁在初始化logger的地方，所以框架应该还没初始化kafkaLog4jAppender，这就完美形成了一个死锁。如果将Metadata类的输出级别提升至warn，那么285行代码就不会被输出，就不会用到log对象，所以kafka-producer-network-thread线程就不会被锁。

2.解决方案

在log4j.properties中添加如下：

log4j.logger.org.apache.kafka.clients.Metadata=warn,KAFKA

再次启动flume，日志正常输出至文件与kafka。

五、最终效果