目前,Java下应用最广泛的日志系统主要就是两个系列: log4j和slf4j+logback 。
其中,slf4j只包含日志的接口,logback只包括日志的具体实现,两者加起来才是一个完整的日志系统。Log4j则同时包含了日志接口和实现。
这两套日志系统之间有可以相互兼容的组件,分别是slf4j-log4j12和 log4j-over-slf4j,引入之后就可以用log4j打出slf4j接口的日志,或者用logback打出log4j接口的日志。
背景知识介绍到这里,再简单说一下标题里提到的问题。问题的现象就是我们在war包里配置了log4j的日志级别为info, 但在catalina里却一直在打大量的debug日志。初看现象肯定很诡异,前期各种研究tomcat配置也没什么头绪。直到磁盘压力太大,去看jstack发现大量进程是等待在Logback代码中,才发现之前关注错了重点。再去具体了解了java下的日志系统后,问题也就很明了了。
先把几个事实摆出来:
1. 打出的debug日志都是用slf4j写的,根据堆栈得知logback具体执行了日志打印
2. logback在无配置文件时默认debug级别
3. 我们的war包中同时包含logback,log4j和slf4j-log4j12
4. Slf4j无法主动选择具体的日志实现
想必看到这里,大家也明白了问题所在。根据我们引入的包,log4j和logback都可以实现打印slf4j日志,而具体谁来打,不是一个用正常办法可以控制的事情,在这个具体案例下,logback就成了具体的日志打印者。而因为我们其实是想用lo4j打日志,所以没有配logback配置,所以logback就按默认的debug级别打了大量日志。
解决办法也很简单,就是把logback的包全去掉。看似有些暴力,但确实是最合理的一个解决办法。
最后提供一个排查日志问题的通用套路,免得找不到方向乱看。
1. 找几行不符合自己日志配置的具体日志,翻阅对应代码,看看是哪个日志接口打的
2. 查jar包,看看这套日志框架有哪些具体实现
3. 把多的jar包去掉