今天在发布系统部署一个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中去。