踩坑记——使用slf4j+logback记录日志

Posted 2020-10-07 小菜变大鸟

 刚开始的jar包版本如下，因为选择jar包版本不同导致的一些坑，踩过了就记录下来：

<spring.version>3.1.0.RELEASE</spring.version>
<slf4j.version>1.7.25</slf4j.version>
<logback.version>1.2.3</logback.version>
<logback.ext.version>0.1.1</logback.ext.version>

commons-logging：scope为provided，这样是为了打包时不会被带上，也就是不使用commons-logging而是准备使用slf4j
jcl-over-slf4j：这个是桥接包，将已经使用commons-logging记录日志又没法改变(spring默认使用的就是commons-logging)的jar包的日志桥接到slf4
slf4j-api：这就是我们要用的slf4j的日志接口，其实和commons-logging一样都是接口，不是具体实现
logback-classic：具体的日志实现，真正记录日志的jar
logback-ext-spring：为了将logback和spring集成而使用的包，如果不用这个包也可以记录日志，但会有个问题(下文会说)

<!-- log -->
<dependency>
<groupId>commons-logging</groupId>
<artifactId>commons-logging</artifactId>
<version>${commons-logging.version}</version>
<scope>provided</scope>
</dependency>
<dependency>
<groupId>org.slf4j</groupId>
<artifactId>jcl-over-slf4j</artifactId>
<version>${slf4j.version}</version>
</dependency>
<dependency>
<groupId>org.slf4j</groupId>
<artifactId>slf4j-api</artifactId>
<version>${slf4j.version}</version>
</dependency>
<dependency>
<groupId>ch.qos.logback</groupId>
<artifactId>logback-classic</artifactId>
<version>${logback.version}</version>
</dependency>
<dependency>
<groupId>org.logback-extensions</groupId>
<artifactId>logback-ext-spring</artifactId>
<version>${logback.ext.version}</version>
</dependency>

准备好依赖后，开始配置logback的使用环境
在web.xml中配置logback的监听器，ch.qos.logback.ext.spring.web.LogbackConfigListener类就是logback-ext-spring.jar中的
logback默认也会查找几个地方的配置文件，不过我喜欢自定义路径，毕竟并不是所有公司都会讲配置全部放到resources目录下而是统一在硬盘上进行的管理

<!-- logback -->
<context-param>
<param-name>logbackExposeWebAppRoot</param-name>
<param-value>false</param-value>
</context-param>
<context-param>
<param-name>logbackConfigLocation</param-name>
<param-value>file:/opt/config/testservice/logback.xml</param-value>
</context-param>
<listener>
<listener-class>ch.qos.logback.ext.spring.web.LogbackConfigListener</listener-class>
</listener>

问题一：
程序正常启动，本来很开心的一件事，却遇到了转折，当改了java文件的代码并保存后，tomcat热部署reload会导致在项目重新加载过程中爆出异常——说可能导致内存泄露？？纳里，表示完全是懵逼的

静下心看了看，发现居然是logback-1这个线程在重载的过程中没有被释放掉，那么每重载一次就会多出一个logback线程，当然也就会造成内存泄露了；在eclipse的debug视图的dubug窗口中查看线程，确实也是这种情况，重载前只有一个logback-1线程，重载后却有两个同名的logback-1了：

重载后如下图，报出内存泄露异常也是对的

那么什么原因造成的呢？我跟着监听器ch.qos.logback.ext.spring.web.LogbackConfigListener跟了下代码，发现是contextDestroyed执行时报错，所以也懒得深究原因了(其实就是代码写的有问题，在logback-ext-spring的0.1.2版本修复了)。

 

将logback-ext-spring从0.1.1替换到0.1.2(高于0.1.1就行）问题就解决了，看来这个jar包的作者也发现这个问题并修复了。我最后使用的版本就是<logback.ext.version>0.1.3</logback.ext.version>；完全看自己了最高版本目前是0.1.4而我的spring是3.1的最高只能和0.1.3的一起使用。

 

问题二：

     当解决了问题一后，以为终于可以好好玩耍了(其实完全可以正常玩耍了，只是强迫症。。。)；同样看了下debug视图的debug窗口，发现刚启动的时候只有一个logback-1线程

之后，每一分钟会多出一个logback-n线程，一共会多出到logback-8，记一个日志有必要这么多线程么？

 

刚开始以为是哪里代码又问题，后来一想不可能，启动后什么也没做就慢慢增加，所以猜测是logback内部有什么猫腻，然后找到了logback-core内部创建线程池的地方，果然发现指定了常驻线程池的线程数

 

JDK文档，明确写了“保留在池中的线程数”，这个我是觉得有点多了，所以我就开始找低版本的

发现CoreConstants类中SCHEDULED_EXECUTOR_POOL_SIZE这个常量随着版本在变化，如下：

1.1.9以上  　　 8
1.1.8 　　 　　 2
1.1.7 　　 　　 2
1.1.6及以下 　 无

最终分析，个人觉得没必要开启常驻内存8个线程来记录日志，所以我选择了1.1.7(参考maven仓库使用记录，选择使用人数较多的)

最终确定jar包版本：

<spring.version>3.1.0.RELEASE</spring.version>
<slf4j.version>1.7.25</slf4j.version>
<logback.version>1.1.7</logback.version>
<logback.ext.version>0.1.3</logback.ext.version>

总结：jar包并不是越新越好，而是要看你用了哪些功能，以上来就使用最新的包往往会出现一些与预期不一致的效果，解决起来又比较头疼~~

 

 

 

最终确定jar包版本：