问题现象
某天测试同学说最新版代码出的包日志打印有问题:1,日志输出目录变更了;2,日志格式也变更了;
跟我们定义的logback.xml完全不一样。
解决过程
日志出问题,先检查最终打到包里的logback.xml是否正确。直接解压看,正常的。用相同的代码在本地IDE跑,日志都是按照logback.xml中设置打印。没办法,再回去出问题的机器上看日志,发现日志格式是公司内部定义的;此时另外一个同学说有可能我们的logback.xml被覆盖了,在classpath中有另外一个logback.xml。有道理,去lib下搜一把。
找到了,确实是某个下游依赖库也引入另外一个logback.xml,立马找负责该库的兄弟解决问题,重新出包,done,日志恢复正常。但这样也不是方法,如果后面哪位兄弟再搞出一个logback文件,坑还得再才踩。翻下logback文档,发现可以指定具体logback.xml,不走默认配置,加以下启动参数:
-Dlogback.configurationFile=xxx/logback.xml
彻底解决问题~
相关思考
还有一个疑问,当前有两个logback.xml,为什么是我们的被覆盖?因为日志文件是打在jar包里的,那其实属于classloader加载jar包顺序的问题。google一下答案,找到一个说法:java加载jar的先后顺序是由操作系统决定(可参考深入探讨Java类加载器),而Linux系统决定的依据是该jar在系统中的INode值。
这样看,应该是我们jar包的inode值比下游依赖包的inode值大;下游依赖包被先加载,我们的包后加载。classloader遇到相同的logback.xml文件,就不在加载了。
由于没有保留案发现场,只能自己在本地再做一个测试,先搞两个测试库jar-a, jar-b,classpath中均有logback.xml,再搞另外一个java项目依赖这两库。以下是两个jar中定义的logback.xml中部分内容
<!-- jar-a的logback -->
<appender name="Console" class="ch.qos.logback.core.ConsoleAppender">
<encoder charset="UTF-8">
<pattern>[A-main] - %d{HH:mm:ss.SSS} [%thread] %-5level %logger - %msg%n</pattern>
</encoder>
</appender>
<!-- jar-b的logback -->
<appender name="Console" class="ch.qos.logback.core.ConsoleAppender">
<encoder charset="UTF-8">
<pattern>[B-main] - %d{HH:mm:ss.SSS} [%thread] %-5level %logger - %msg%n</pattern>
</encoder>
</appender>
将最终应用的项目打包:
打印代码:
log.info("i am robot");
看结果,先看inode:
jar-a的inode值比jar-b的大,再看实际日志输出:
classloader最终读取了jar-b中的logback.xml。好,同一台机换个inode:
这回jar-a的inode值比jar-b的小,再看实际日志输出:
看起来是inode值小的会被先加载,说得通了。然后第二天,问题出现了;我在另外两台机子上试,结果却是无论怎么改inode值,结果始终不变。此时心里是崩溃的~~~没办法,再找google大师问一把,最后在官方文档上翻到这样一句话:
The order in which the JAR files in a directory are enumerated in the expanded class path is not specified and may vary from platform to platform and even from moment to moment on the same machine. A well-constructed application should not depend upon any particular order. If a specific order is required, then the JAR files can be enumerated explicitly in the class path.
大意为:同一个目录下,jvm加载jar包顺序是无法保证的,每个系统的都不一样,甚至同一个系统不同的时刻加载都不一样。