记一次开发、测试环境不打印日志的问题

余梦

前段时间接手了一个服务化项目,因为是从一个服务化项目中拆出来的,很多配置、代码基本都保留了原来的(都用到了),毕竟这个项目已经稳定运行了很长时间,一时不敢做太大的变更。中间遇到两次本地打好的可执行jar(mac系统)可以正常运行,但是同样的jar包扔到开发或者测试环境上就有问题的情况。这两个问题分别是:es客户端连接报错,dubbo filter日志无法输出。其实问题很简单,只不过当时有些细节没留意。现在大概回顾下这个过程,希望能加深大家对日志框架的理解以及正确优雅的使用日志框架。


问题描述

功能模块分拆出来服务化、配置基本保留(基本需要使用原工程所有配置,只是一个模块拆出来而已) 开始拿到这个项目时,用idea maven helper看了下,发现有jar冲突(log4j相关的冲突),想着以前都运行正常的,我就没去理会这个冲突(冲突也不是一定会有问题)。后来程序本地跑起来没有任何问题,客户端调用我本地服务都没有问题,放到开发环境报es客户端连接失败。


排查

本地可以,开发环境连接失败,首先想到的是开发环境端口、ip是否是通的。这个很快就排除了。通过报错的日志也没法看出问题出在哪里。这个新服务项目用到了es,查看es client相关类源码发现,这个框架内部使用的是log4j,

而我项目中用的是logback,并且log4j版本还有冲突,所以问题出现肯定和这个log4j有关系。于是排除掉冲突的版本,程序运行正常。其实问题到这里,大家应该有想到,es client里面依赖的是log4j,我项目用的是logback,日志打印上会不会有问题?为什么我本地运行没有问题,开发、测试环境均有问题。同样在我本地用springboot打包的jar,同一个jar包放到不同环境下,居然出现冲突。我们知道,java的类加载器加载类时候,同名不同版本的jar包,加载顺序是按jar包名字符串顺序加载的而且只加载一次,难道mac系统和linux系统上类加载器实现机制哪里有不同,还是springboot 打成jar包后运行机制的问题?这个感觉不科学啊,也和不少人交流过这个问题,没有得出来一个结论,至今想不通。以前遇到过windows上没问题,linux上jar冲突的,这个还好理解点,classloader在mac和linux上实现难道有什么差异,还是springboot在不同系统上哪里有bug?哪位同学如果知道,希望能答疑下。


日志无法输出的问题描述

因为需要,在项目中增加了一个dubbo filter,filter中使用到了dubbo内部封装的的日志api LoggerFactory获取日志输出对象。本地STDOUT可以正常输出日志,开发环境appender file不输出日志,本地appender file也不输出。


问题排查

通过在filter中增加log调试输出信息发现日志文件中没输出,以为我增加的配置和filter没打包进去,包没打好。后来本地打好包上传开发环境,依然发现不行。问题基本明朗了,锁定在filter中调用dubbo 内部封装的日志api上。于是查看dubbo 内部日志代码的实现,终于发现问题的原因所在。

dubbo内部,对常用的日志组件做了适配,对于后面新出来日志框架肯定是没有做适配的,不过因为有slf4j,这个也不是问题。
我们可以看到,如果没有设置dubbo.application.logger,那么dubbo内部使用的是log4j的 !如果获取log4j异常才会继续往下匹配其他的日志组件。因为我前面es client中用到了log4j,已经引入了log4j的jar包,所以dubbo使用的是log4j,就不会继续往后匹配日志组件了。现在问题就好解决了,要么在springboot启动函数里面设置dubbo.application.logger=slf4j,要么将log4j桥接到slf4j上,比如增加如slf4j-log4j12 或者log4j-over-slf4j。毕竟我们的系统用的是logback作为日志输出的。果然,在我检查maven配置到时候,发现log4j-over-slf4j在原来系统里面就直接被排除掉了。其实这个在springboot里面,默认就是引入的,目的是将不同框架里面用到log4j的地方全部桥接过来,统一使用slf4j门面。类似的还有jcl-over-slf4j,jul-over-slf4j等。这个问题我们就有同事遇到过,日志本地没问题,线上有问题,而且也是mac系统。。。。问题就说到这里,下面总结下。


关于日志系统的总结

我司java技术部门基本都在用springboot,springboot提供了很多日志组件的支持。默认是用的logback,如果我们需要使用其他日志组件建议直接依赖 spring-boot-starter-日志组件名,比如下面

<dependency>  
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-log4j2</artifactId>
            <version>1.5.4.RELEASE</version>
</dependency>


<dependency>  
    <groupId>org.springframework.boot</groupId>
    <artifactId>spring-boot-starter-log4j</artifactId>
    <version>1.3.8.RELEASE</version>
</dependency>  

这样内部就帮你把常见日志框架全部桥接好了,你的系统可能依赖很多第三方包,这些第三方包可能会依赖不同的日志组件,应用在日志输出时全部桥接过来了。

下面看看slf4j官方的图,它提供一个统一的门面接口,你在应用中去输出日志时,只需要使用它的接口即可,如何绑定到你指定的日志组件的,看下面这个图。

关于log4j,还有个坑,如果是一个系统中同时引入了 log4j-over-slf4j和slf4j-log4j12,可能会造成stack overflow异常的额。具体什么原因,有兴趣的可以去研究下,这里就不说了。最后说一句拿到项目的时候,也关注下maven配置,通过一些工具看下是否有冲突,有时候可能疏忽了。