记一次log4j不打印日志的踩坑记

### 起因

前几天一个跑有java应用的生产集群（200多台物理机）升级了一个版本，重启后发现约有50台机器日志不能正常输出，但其程序确能正常的运行，在生产环境中，日志是非常重要的一个监控手段，如果没有日志输出，无疑是非常危险的。


### 排查 & 解决

发现这一情况后，立即开始从jdk环境和版本，cpu负载，内存gc，线程stack，死锁，磁盘容量等多方面排查，但均没有发现异常情况，唯一的一点信息是Java进程重启时重定向到out文件里面的控制台输出，如下（以下均为复现时的输出）：

```
SLF4J: Class path contains multiple SLF4J bindings.
SLF4J: Found binding in [jar:file:/Users/qindongliang/.m2/repository/org/apache/logging/log4j/log4j-slf4j-impl/2.3/log4j-slf4j-impl-2.3.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in [jar:file:/Users/qindongliang/.m2/repository/org/slf4j/slf4j-log4j12/1.7.12/slf4j-log4j12-1.7.12.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: See http://www.slf4j.org/codes.html#multiple_bindings for an explanation.
SLF4J: Actual binding is of type [org.apache.logging.slf4j.Log4jLoggerFactory]
```

起初并没有在意日志包冲突的这个细节，因为其他正常启动并能够正常打印log的机器中，也有同样的输出。所以基本肯定与这个冲突关系不大。

但苦于没有其他日志输出，并且当前的进程是在正常的Runnable状态中，所以又把目光回到了刚才的out文件，经过与正常机器中大部分out文件比较，发现了一点端倪。


（1）大多数能够正常打印log机器的out文件输出是：

```
SLF4J: Class path contains multiple SLF4J bindings.
SLF4J: Found binding in [jar:file:/Users/qindongliang/.m2/repository/org/apache/logging/log4j/log4j-slf4j-impl/2.3/log4j-slf4j-impl-2.3.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in [jar:file:/Users/qindongliang/.m2/repository/org/slf4j/slf4j-log4j12/1.7.12/slf4j-log4j12-1.7.12.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: See http://www.slf4j.org/codes.html#multiple_bindings for an explanation.
SLF4J: Actual binding is of type [org.apache.logging.slf4j.Log4jLoggerFactory]
```

（2）少部分正常打印log的机器和其他不打印log的机器的out文件输出是：

```
SLF4J: Class path contains multiple SLF4J bindings.
SLF4J: Found binding in [jar:file:/Users/qindongliang/.m2/repository/org/slf4j/slf4j-log4j12/1.7.12/slf4j-log4j12-1.7.12.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in [jar:file:/Users/qindongliang/.m2/repository/org/apache/logging/log4j/log4j-slf4j-impl/2.3/log4j-slf4j-impl-2.3.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: See http://www.slf4j.org/codes.html#multiple_bindings for an explanation.
SLF4J: Actual binding is of type [org.slf4j.impl.Log4jLoggerFactory]
```

对比上面两个输出文件中的第三行，第四行和最后一行，发现不同的机器有可能输出的不一样，另外一点能够得到的是正常的机器sfl4j binding最后一行都是一样的类：

```
org.apache.logging.slf4j.Log4jLoggerFactory
```

而少数正常和所有不正常的slf4j binding的类是：

```
org.slf4j.impl.Log4jLoggerFactory
```

这明显是slf4j binding包冲突造成的，经过调查发现，前者是log4j2.x用的工厂实现类，而后者是兼容log4j1.x用的工厂类，他们分别位于：

```
log4j-slf4j-impl-2.3.jar
```

和

```
slf4j-log4j12-1.7.12.jar
```

这两个jar包中，都有各自的StaticLoggerBinder类，所以才造成了冲突，因为我们用的是log4j2的日志组件，所以解决的方法就是移除掉与其冲突的log4j 1.x的slf4j-log4j12-1.7.12.jar包即可。

在移除后，我们再次重启任务，发现这下日志又可以正常输出了，至此算是解决了这个问题。

### 思考 & 总结

看起来我们已经完美解决这个问题了，但实际上这才刚刚开始，仅仅凭表面现象去解决问题是不够的，我们还要向深钻研和向广度类比。

比如：

常用的日志组件都有哪些？

log4j1 和 log4j2的区别是什么？

slf4j是什么，用来解决什么问题？

log4j与slf4j有什么关系？

slf4j是如何处理冲突的？

为什么同样有日志包冲突的机器，有的能够正常工作，有的却不能？

为什么同样的slf4j binding类，有的能正常输出log，有的却不能？

如何能提前发现冲突问题和避免？

只有弄懂了上面的这些问题，我们才能真正的理解这类问题的本质，这里面思考和学习的过程，对自身的提升其实是非常有益的，这也是一般工程师和优秀的工程师的差距地方。有想法的同学可以先尝试思考一下，下一篇文章我们继续分析和总结。




有什么问题可以扫码关注微信公众号：我是攻城师(woshigcs) 关注公众号的朋友，可以加入我们的：攻城师互助交流群，一起学习！