前言
前几天, 在 Linux 上部署一个 war 包应用时, tomcat 直接起不来, 查看 tomcat 的日志, catalina.out 里没啥特别的, 但是查看 localhost 日志, 发现栈溢出了.
- [root@localhost logs]# VIM localhost.2019-12-26.log
- 26-Dec-2019 16:27:31.811 INFO [localhost-startStop-1] org.apache.catalina.core.ApplicationContext.log No Spring webApplicationInitializer types detected on classpath
- 26-Dec-2019 16:27:31.855 SEVERE [localhost-startStop-1] org.apache.catalina.core.StandardContext.listenerStart Exception sending context initialized event to listener instance of class [org.springframework.Web.context.ContextLoaderListener]
- java.lang.StackOverflowError
- at org.slf4j.impl.Log4jLoggerFactory.getLogger(Log4jLoggerFactory.java:58)
- at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:358)
- at org.apache.log4j.Category.<init>(Category.java:57)
- at org.apache.log4j.Logger.<init>(Logger.java:37)
- at org.apache.log4j.Log4jLoggerFactory.getLogger(Log4jLoggerFactory.java:43)
- at org.apache.log4j.LogManager.getLogger(LogManager.java:45)
- at org.slf4j.impl.Log4jLoggerFactory.getLogger(Log4jLoggerFactory.java:66)
- at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:358)
- at org.apache.log4j.Category.<init>(Category.java:57)
- at org.apache.log4j.Logger.<init>(Logger.java:37)
- at org.apache.log4j.Log4jLoggerFactory.getLogger(Log4jLoggerFactory.java:43)
- at org.apache.log4j.LogManager.getLogger(LogManager.java:45)
- at org.slf4j.impl.Log4jLoggerFactory.getLogger(Log4jLoggerFactory.java:66)
- at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:358)
- at org.apache.log4j.Category.<init>(Category.java:57)
- at org.apache.log4j.Logger.<init>(Logger.java:37)
- at org.apache.log4j.Log4jLoggerFactory.getLogger(Log4jLoggerFactory.java:43)
- at org.apache.log4j.LogManager.getLogger(LogManager.java:45)
- at org.slf4j.impl.Log4jLoggerFactory.getLogger(Log4jLoggerFactory.java:66)
- at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:358)
- at org.apache.log4j.Category.<init>(Category.java:57)
- at org.apache.log4j.Logger.<init>(Logger.java:37)
- at org.apache.log4j.Log4jLoggerFactory.getLogger(Log4jLoggerFactory.java:43)
- at org.apache.log4j.LogManager.getLogger(LogManager.java:45)
- at org.slf4j.impl.Log4jLoggerFactory.getLogger(Log4jLoggerFactory.java:66)
- at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:358)
- at org.apache.log4j.Category.<init>(Category.java:57)
- at org.apache.log4j.Logger.<init>(Logger.java:37)
当时脑子昏得很, 所幸搜索引擎上找到了解决办法,
https://www.jb51.net/article/143486.htm
后边呢, 忙着改 bug, 没时间细想, 但总感觉还是有点糊里糊涂的. 今天彻底排查了一下, 清晰多了.
slf4j 与其他日志的关系
slf4j, 通俗来说, 只是一个 API 类型的 jar 包, 没有定义实现; 具体的日志实现框架有哪些呢, 主要有 log4j,logback, 大家可以看看下面这个图 (懒得自己画了, 从前面那个链接里拿的):
这种接口和实现的关系, 在软件设计里, 就是为了对上层提供统一的编程入口, 比如, 我们写日志, 只需要使用 slf4j 里的接口和类, 而不用直接使用 log4j/logback 等, 方便替换; 这个类似于 java 的 spi 机制, 比如, java 官方定义 jdbc 接口, 各厂商实现 jdbc 接口, 提供出自己的驱动包, 比如 MySQL-driver,oracle-driver 等.
slf4j 如何寻找自身的实现
在 spi 里, java.util.ServiceLoader 通过寻找当前线程类加载器路径下的 META-INF/services / 接口的全名来寻找实现类;
在 slf4j 里, 则是通过如下机制, 大家可以查看下面的源码:
这个工程里, 我们只添加了如下的 maven 依赖:
- <dependencies>
- <dependency>
- <groupId>org.slf4j</groupId>
- <artifactId>slf4j-API</artifactId>
- <version>1.7.25</version>
- </dependency>
- </dependencies>
测试代码也很简单:
- import org.slf4j.Logger;
- import org.slf4j.LoggerFactory;
- public class Test {
- public static void main(String[] args) {
- Logger logger = LoggerFactory.getLogger(Test.class);
- logger.info("hahha");
- }
- }
output 如下:
- SLF4J: Failed to load class "org.slf4j.impl.StaticLoggerBinder".
- SLF4J: Defaulting to no-operation (NOP) logger implementation
- SLF4J: See http://www.slf4j.org/codes.html#StaticLoggerBinder for further details.
只要关注第一行即可, load class org.slf4j.impl.StaticLoggerBinder 失败了. 这个类, 就是 slf4j-API 和 slf4j-API 的实现之间的粘合剂.
画个图:
我图里说了, 两个包内, 都是有 org.slf4j.impl.StaticLoggerBinder 这个类的, 我不骗大家, 大家可以看下面这个 module 的源码:
pom 依赖主要有:
- <dependencies>
- <dependency>
- <groupId>org.slf4j</groupId>
- <artifactId>slf4j-API</artifactId>
- <version>1.7.24</version>
- </dependency>
- <dependency>
- <groupId>ch.qos.logback</groupId>
- <artifactId>logback-classic</artifactId>
- <version>1.2.3</version>
- <scope>compile</scope>
- </dependency>
- <dependency>
- <groupId>org.slf4j</groupId>
- <artifactId>slf4j-log4j12</artifactId>
- <version>1.7.25</version>
- </dependency>
- </dependencies>
这里面有 slf4j 的多个实现, logback 和 slf4j-log4j. 同样的测试类, 此时会输出:
- SLF4J: Class path contains multiple SLF4J bindings.
- // 这里在 logback-classic-1.2.3.jar 包里找到了包名和类名全匹配的类
- SLF4J: Found binding in [jar:file:/D:/soft/Repo_backup/ch/qos/logback/logback-classic/1.2.3/logback-classic-1.2.3.jar!/org/slf4j/impl/StaticLoggerBinder.class]
- // 在 slf4j-log4j12 也找到了
- SLF4J: Found binding in [jar:file:/D:/soft/Repo_backup/org/slf4j/slf4j-log4j12/1.7.25/slf4j-log4j12-1.7.25.jar!/org/slf4j/impl/StaticLoggerBinder.class]
- SLF4J: See http://www.slf4j.org/codes.html#multiple_bindings for an explanation.
- SLF4J: Actual binding is of type [ch.qos.logback.classic.util.ContextSelectorStaticBinder]
所以, slf4j-API 的做法其实很原始, 你晓得噻, classpath 下通常有很多 jar 包, 这里, slf4j-API 就是去 classpath 下找全类名匹配 org.slf4j.impl.StaticLoggerBinder 的 class 文件, 找到几个算几个, 一个没有就报错, 多了就警告, 然后随便选一个 (其实是看哪个 class 在前面).
核心代码:
slf4j-API 包内: org.slf4j.LoggerFactory#bind
- private final static void bind() {
- try {
- // 通过 classLoader.getResources(org/slf4j/impl/StaticLoggerBinder.class) 查找 class 文件
- Set<URL> staticLoggerBinderPathSet = findPossibleStaticLoggerBinderPathSet();
- // 如果有多个, 警告一下
- reportMultipleBindingAmbiguity(staticLoggerBinderPathSet);
- ...
- // StaticLoggerBinder 就是前面说了半天的那个类, 在 slf4j-API 里是不存在的, 如果整个 classpath 下都没有, 但这里又去调用其静态方法, 会直接抛异常 NoClassDefFoundError, 被 catch 住;
- // 如果存在呢, 就会使用 classloader 加载 StaticLoggerBinder, 但这个顺序没法保证, 假设有 logback-classic 和 slf4j-log4j 两个实现, 就看类加载器先加载哪个了
- StaticLoggerBinder.getSingleton();
- INITIALIZATION_STATE = SUCCESSFUL_INITIALIZATION;
- reportActualBinding(staticLoggerBinderPathSet);
- fixSubstituteLoggers();
- replayEvents();
- // release all resources in SUBST_FACTORY
- SUBST_FACTORY.clear();
- } catch (NoClassDefFoundError ncde) {
- String msg = ncde.getMessage();
- if (messageContainsOrgSlf4jImplStaticLoggerBinder(msg)) {
- INITIALIZATION_STATE = NOP_FALLBACK_INITIALIZATION;
- Util.report("Failed to load class \"org.slf4j.impl.StaticLoggerBinder\".");
- Util.report("Defaulting to no-operation (NOP) logger implementation");
- Util.report("See" + NO_STATICLOGGERBINDER_URL + "for further details.");
- } else {
- failedBinding(ncde);
- throw ncde;
- }
- }
- }
大家可以看我的注释,
StaticLoggerBinder 就是前面说了半天的那个类, 在 slf4j-API 里是不存在的, 如果整个 classpath 下都没有, 但这里又去调用其静态方法, 会直接抛异常 NoClassDefFoundError, 被 catch 住;
如果存在呢, 就会使用 classloader 加载 StaticLoggerBinder, 但这个顺序没法保证, 假设有 logback-classic 和 slf4j-log4j 两个实现, 就看类加载器先加载哪个了
我这里说了一点, 存在多个实现的时候, 先加载哪个, 后加载哪个, 全看 classloader.
大家可以实际测一下, 一般来说, 在 Windows 下和 Linux 下, 会有不同的表现的, 坑吧, 谁让你进了这充满 bug 的行业呢, 很多很奇怪的问题, 都是 classloader 在不同 OS 下, 获取到的 jar 包顺序不同导致的:
- public class Test {
- public static void main(String[] args) throws NoSuchMethodException, InvocationTargetException, IllegalAccessException {
- Logger logger = LoggerFactory.getLogger(Test.class);
- logger.info("hahha");
- // 打印 jar 包的加载顺序
- ClassLoader loader = Test.class.getClassLoader();
- Method getURLs = loader.getClass().getMethod("getURLs");
- getURLs.setAccessible(true);
- URL[] o = (URL[]) getURLs.invoke(loader);
- for (URL url : o) {
- System.out.println(url);
- }
- }
- }
问题真相揭秘
回到问题, 我仔细研究了一晚上, 在本地复现了问题, 可参考 module 测试代码:
这个 module 里, pom 依赖如下:
堆栈, 发现大概是这样的, 图小可以单独 tab 页查看:
我这里也有对堆栈的文字解释:
at org.apache.log4j.Category.(Category.java:57) | log4j-over-slf4j |
---|---|
at org.apache.log4j.Logger. | log4j-over-slf4j 包,已经死循环了 |
at org.apache.log4j.Log4jLoggerFactory.getLogger(Log4jLoggerFactory.java:43) | log4j-over-slf4j 包 |
at org.apache.log4j.LogManager.getLogger(LogManager.java:45) | log4j-over-slf4j,这个 LogManager 是 log4j 包里的,因为 log4j-over-slf4j 是一个 log4j 的冒充者,所以它也有这个类 |
at org.slf4j.impl.Log4jLoggerFactory.getLogger(Log4jLoggerFactory.java:66) | slf4j-log4j12, 实现了 slf4j,进行了 static bind 的 |
at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:358) | slf4j-api |
at org.apache.log4j.Category. | log4j-over-slf4j |
at org.apache.log4j.Logger. | log4j-over-slf4j |
关于 log4j-over-slf4j, 可进一步阅读:
揭秘过程揭秘
真相可能足够简单, 但是在找真相的过程反而更难一些, 因为这个包, 其实在 Windows 下跑是没问题的, 在 Linux 有问题, 魔幻?
并不魔幻. 因为这个 war 包里, 本来是 log4j 依赖的:
- <dependency>
- <groupId>log4j</groupId>
- <artifactId>log4j</artifactId>
- </dependency>
相当于: log4j-over-slf4j 和 log4j 共存, 我们说了, log4j-over-slf4j 里, 提供了 log4j 的类, 包名和类名都一样, 谁知道先加载哪一个呢? 谁知道, Windows 下先加载哪个, Linux 下先加载哪个呢? 这个就是要靠运气的时候了, 所以是偶现.
不信你把我们上面测试的 module 里, 照下面这样操作, Windows 下, 立马就好了
之前不记得采用这种方式来验证, 为此, 还专门定义了一个自定义 classloader, 先加载 slf4j-log4j jar 包, 再代理给 parent, 可参考:
总结
这个问题还是比较有意思的, 我也还没有完全弄懂, 但大概了解了.
关于 classloader 在 Windows 和 Linux 下的不同表现的问题, 可参考:
博主之前也写了一篇, 关于这个的:
了不得, 我可能发现了 Jar 包冲突的秘密
关于日志, 博主之前还写了一篇:
面试题: 应用中很多 jar 包, 比如 spring,mybatis,Redis 等等, 各自用的日志系统各异, 怎么用 slf4j 统一输出?(上)
本次博客的相关代码:
大家有问题请留言, 大家觉得有帮助, 请点赞哦, 这个也是对我的鼓励.
谢谢大家!
来源: https://www.cnblogs.com/grey-wolf/p/12104977.html