从解决一个java.lang.NoSuchMethodError想到的

2023-03-10 13:01:36

今天在发布系统部署一个web app的时候，发现应用服务器（tomcat 7.0.26)不能正常启动，于是远程登陆到服务器上查看应用服务器的启动日志，在tomcat_home的logs/localhost.log.2014-03-17上发现了一段如下错误信息:

java.lang.NoSuchMethodError: org.slf4j.spi.LocationAwareLogger.log(Lorg/slf4j/Marker;Ljava/lang/String;ILjava/lang/String;[Ljava/lang/Object;Ljava/lang/Throwable;)V
at org.apache.commons.logging.impl.SLF4JLocationAwareLog.error(SLF4JLocationAwareLog.java:225)
at org.springframework.web.context.ContextLoader.initWebApplicationContext(ContextLoader.java:319)
at com.alibaba.citrus.webx.context.WebxComponentsLoader.initWebApplicationContext(WebxComponentsLoader.java:117)
at org.springframework.web.context.ContextLoaderListener.contextInitialized(ContextLoaderListener.java:112)
at org.apache.catalina.core.StandardContext.listenerStart(StandardContext.java:4779)
at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5273)
at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:150)
at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:895)
at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:871)
at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:615)
at com.taobao.tomcat.deploy.TomcatHostConfig.deployDirectory(TomcatHostConfig.java:482)
at com.taobao.tomcat.deploy.TomcatHostConfig.deployWarDirectory(TomcatHostConfig.java:366)
at com.taobao.tomcat.deploy.TomcatHostConfig.deployDirectories(TomcatHostConfig.java:339)

...后面的错误信息省略。

分析思路:

1、这是一个tomcat启动时的方法调用栈信息，结合web.xml中配置信息，发现配置了一个webx（一个阿里开源的webx框架）的WebxContextLoaderListener ，这个类的主要作用是在应用服务器启动的时候，初始化webapp的applicationContext,为webx的组件初始化提供支持。

（这不是我们叙述的重点，所以不重点讲述）。

分析栈信息，定位到org.springframework.web.context.ContextLoader类的319行，

logger.error("Context initialization failed", ex);

这是一个捕获RuntimeException的catch块写error日志，这个logger对象的创建在270行

Log logger = LogFactory.getLog(ContextLoader.class);

查看类的import 声明 import org.apache.commons.logging.LogFactory ,结合对java日志知识的复习（点击这里）。

可以知道采用的是commons-logging的日志接口（有可能是commons-logging，或者是jcl-over-slf4j的包引入的），

于是查看一下webapp的maven依赖树，把和日志相关的jar包都提取出来：

1、接口API包：

org.slf4j.slf4j-api-1.5.6.jar

slf4j-api-1.7.5.jar

2、日志框架包：

logback-core-1.0.13.jar

logback-classic-1.0.13.jar

jakarta.log4j-1.2.15.jar
apache-log4j-log4j-1.2.15.jar
log4j-log4j-1.2.15.jar

3、日志适配器包：

org.slf4j.slf4j-log4j12-1.5.6.jar

4、其他日志到slf4j日志的桥接包：

jcl-over-slf4j-1.7.5.jar

从以上包来看，可以分析出一下结论：

1、slf4j-api有两个不同的版本。

2、系统中既有logback，也有log4j,但是slf4j-api在静态绑定选择时，因为有slf4j-log4j包的存在，会出现多个绑定的问题。

3、commons-logging日志接口被jcl-over-slf4j桥接到slf4j日志接口了。

出现的异常是否和这个结论有关系呢？

回到栈信息，可以看到Log logger = LogFactory.getLog(ContextLoader.class); 这一行获取日志器的日志器工厂LogFactory 应该是在JCL-over-slf4j包内定义的，查看源码，

public Log getInstance(String name) throws LogConfigurationException {
Log instance = loggerMap.get(name);
if (instance != null) {
return instance;
} else {
Log newInstance;
Logger slf4jLogger = LoggerFactory.getLogger(name);
if (slf4jLogger instanceof LocationAwareLogger) {
newInstance = new SLF4JLocationAwareLog((LocationAwareLogger) slf4jLogger);
} else {
newInstance = new SLF4JLog(slf4jLogger);
}
Log oldInstance = loggerMap.putIfAbsent(name, newInstance);
return oldInstance == null ? newInstance : oldInstance;
}
}

我们可以看到代码进入了标红的这一行，也就是利用一个适配器模式，把slf4jLogger转换成了org.apache.commons.logging.Log, 最后由这个LocationAwareLogger 抛出了一个错误信息，

java.lang.NoSuchMethodError: org.slf4j.spi.LocationAwareLogger.log(Lorg/slf4j/Marker;Ljava/lang/String;ILjava/lang/String;[Ljava/lang/Object;Ljava/lang/Throwable;)V

而LocationAwareLogger 这个类是在slf4j-api中定义的，前面的分析我们看到打包后的WEB-INF下有两个slf4j-api的包，

其中在slf4j-api-1.5.6中的定义是这样的：

void log(org.slf4j.Marker marker, java.lang.String s, int i, java.lang.String s1, java.lang.Throwable throwable);

而在slf4j-api-1.7.5中的定义是这样的：

void log(org.slf4j.Marker marker, java.lang.String s, int i, java.lang.String s1, java.lang.Object[] objects, java.lang.Throwable throwable);

回顾《深入理解jvm》里面关于字节描述符的知识，我们知道错误信息提示的是需要找

log(Marker,String,int,String,Object[],Throwable) 这样的一个方法，但是没有找到，

说明编译时和运行时采用了不一样的jar .

再通过maven依赖树，查询到org.slf4j.slf4j-api-1.5.6.jar是被一个单点登录的jar依赖间接引入的，于是在父工程里面排除掉

org.slf4j.slf4j-api-1.5.6.jar间接依赖（顺便也排除掉了org.slf4j.slf4j-log4j12-1.5.6.jar这个适配器包），问题得到解决。

事后，我们再回顾出现的错误信息，java.lang.NoSuchMethodError ，其实这个类的继承体系结构

java.lang.Object

java.lang.Throwable

java.lang.Error

java.lang.LinkageError

java.lang.IncompatibleClassChangeError

java.lang.NoSuchMethodError

就已经告诉了我们出问题的线索了 ，比如ImcompatibleClassChangeError的英文注释是这么说的： 
Thrown when an incompatible class change has occurred to some class definition. The definition of some class, on which the currently executing method depends, has since changed.
（大意是：当不兼容的类变化作用在了类的定义时，异常抛出。当前执行方法依赖的类定义发生了改变） 。

所以在查找问题时，异常本身的注释也是我们找问题的一个好办法。

----------------------------------------------------------------

回顾整个问题的解决过程，发现这次解决问题是采用源码分析+maven依赖树的静态分析方法，我们有什么办法知道有问题的Class文件是jvm加载的哪个jar的么？

1）方法1：

jvm里面有一个跟踪classload的参数：

-XX:+TraceClassLoading

我们修改catalina.sh ，加上这个参数JAVA_OPTS=$JAVA_OPTS" "-XX:+TraceClassLoading ，然后把标准输出重定向到一个临时日志文件：

1>/tmp/logs/tomcat.log

在这个临时日志中，我们找到了

[Loaded org.slf4j.spi.LocationAwareLogger from file:~/eclipse_workspace/webapp/target/exploded/webapp.war/WEB-INF/lib/org.slf4j.slf4j-api-1.5.6.jar]

说明运行时的确是使用到了slf4j-1.5.6版本的Jar包，和编译classpath使用的jar包版本不一致。

2）方法2：

阿里的聚石写了一个housemd的工具，安装方法可以点击这里（https://github.com/CSUG/HouseMD) , 启动后运行如下命令attach到tomcat进程：

housemd `jps|grep Bootstrap|awk '{print $1}'`

然后loaded classname 就可以得到运行时类所在的jar .

要自己实现的话，比如我们要获取一个Test.class类是被哪个jar导入的，可以这样

URL url = Log.class.getClassLoader().getResource("Test.class");

url.getFile();

另外，还可以用loaded -h 命令查看类加载器树，

、

要自己实现的话可以这样：

for(ClassLoader cl = Log.class.getClassLoader(); cl != null ; cl = cl.getParent()){

　　System.out.println(cl.getName());

}

那么我们能否在应用打包的时候，就分析出存在jar冲突的地方呢？我的思路是这样的：

1、在应用打包成功以后，把应用的class的jar包拷贝到一个临时文件夹。

2、对这些jar包中的字节码文件，做如下操作：

1）使用asm分析出class 导入的class .

2)对每一个导入的class获取 build classpath下的jar列表，如果jar的个数大于等于2 ，则表明有jar冲突。

3）输出jar冲突信息到控制台。

目前，我已经在本机mac环境下实现了基本功能，接下来的计划是做成maven插件，放到整个maven应用的build cycle中去。

码农公寓

相关文章