一次日志打印错乱引出对jvm加载jar包顺序的研究

2019独角兽企业重金招聘Python工程师标准>>>

问题现象

某天测试同学说最新版代码出的包日志打印有问题：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包顺序是无法保证的，每个系统的都不一样，甚至同一个系统不同的时刻加载都不一样。

这下终于豁然开朗了~

转载于:https://my.oschina.net/ericquan8/blog/1523496