接着上一篇讲。
一个异常日志处理的例子:
抛出异常的地方为:
try{
... ...//省略N行
}catch( Exception e){
throw new RuntimeException ("jar文件加载异常!name="+jarFileName, e);
}
打印异常的地方为:
logger.error(e, "类文件加载失败");
这是很正常的手法,打印出堆栈信息,并附加上一些额外信息。
最初,异常堆栈信息是这样的:
(堆栈信息有点多,大家快速往下面看……)
类文件加载失败 java.lang.RuntimeException: jar文件加载异常!D:optappWebSphereoutput eportfileloadclass照片.jar at com.proj.report.common.util.ClassLoaderUtils.loadJar(ClassLoaderUtils.java:123) at com.proj.report.backmanage.addin.control.ClassLoadController.loadClass(ClassLoadController.java:41) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:597) at org.zollty.framework.mvc.support.HandlerMetaInfo.invokeMethod(HandlerMetaInfo.java:34) at org.zollty.framework.mvc.handler.support.ControllerHandler.invoke(ControllerHandler.java:60) at org.zollty.framework.mvc.handler.support.HandlerChainImpl.doNext(HandlerChainImpl.java:50) at com.proj.report.backmanage.interceptor.AccessRightInterceptor.dispose(AccessRightInterceptor.java:62) at sun.reflect.GeneratedMethodAccessor43.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:597) at org.zollty.framework.mvc.support.HandlerMetaInfo.invokeMethod(HandlerMetaInfo.java:34) at org.zollty.framework.mvc.handler.support.InterceptorHandler.invoke(InterceptorHandler.java:58) at org.zollty.framework.mvc.handler.support.HandlerChainImpl.doNext(HandlerChainImpl.java:50) at com.proj.report.backmanage.interceptor.AdminRightInterceptor.dispose(AdminRightInterceptor.java:56) at sun.reflect.GeneratedMethodAccessor42.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:597) at org.zollty.framework.mvc.support.HandlerMetaInfo.invokeMethod(HandlerMetaInfo.java:34) at org.zollty.framework.mvc.handler.support.InterceptorHandler.invoke(InterceptorHandler.java:58) at org.zollty.framework.mvc.handler.support.HandlerChainImpl.doNext(HandlerChainImpl.java:50) at org.zollty.framework.mvc.servlet.DispatcherController.handleRequest(DispatcherController.java:52) at org.zollty.framework.mvc.DispatcherServlet.dispatcher(DispatcherServlet.java:69) at org.zollty.framework.mvc.DispatcherServlet.doPost(DispatcherServlet.java:33) at javax.servlet.http.HttpServlet.service(HttpServlet.java:637) at javax.servlet.http.HttpServlet.service(HttpServlet.java:717) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:298) at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:857) at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:588) at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:489) at java.lang.Thread.run(Thread.java:619) Caused by: java.util.zip.ZipException: error in opening zip file at java.util.zip.ZipFile.open(Native Method) at java.util.zip.ZipFile.(ZipFile.java:114) at java.util.jar.JarFile.(JarFile.java:133) at java.util.jar.JarFile.(JarFile.java:70) at com.proj.report.common.util.ClassLoaderUtils.loadJar(ClassLoaderUtils.java:120) ... 39 more
这是一个很简单的报错,但是堆栈却是一大堆,让人茫然。其实,我想说的是,这个堆栈信息还算少的,在Websphere下,报错信息还要多,我们的错误日志文件,通常都是1分钟几M甚至几十M,我下载的日志文件有800多M的。
经过我对很多日志文件的分析,发现其中90%的报错信息是冗余的。
经过我对异常的特殊处理,现在错误日志变成了如下形式:
16:07:59,415 ERROR ClassLoadController:29 - 类文件加载失败 |- java.lang.RuntimeException: jar文件加载异常!D:optappWebSphereoutput eportfileloadclass照片.jar
at com.proj.report.common.util.ClassLoaderUtils.loadJar(ClassLoaderUtils.java:123)
at com.proj.report.backmanage.addin.control.ClassLoadController.loadClass(ClassLoadController.java:41)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
... 6 more
at com.proj.report.backmanage.interceptor.AccessRightInterceptor.dispose(AccessRightInterceptor.java:62)
... 6 more
at com.proj.report.backmanage.interceptor.AdminRightInterceptor.dispose(AdminRightInterceptor.java:56)
... 23 more
Caused by: java.util.zip.ZipException: error in opening zip file
at java.util.zip.ZipFile.open(Native Method)
at java.util.zip.ZipFile.(ZipFile.java:114)
at java.util.jar.JarFile.(JarFile.java:133)
... 1 more
at com.proj.report.common.util.ClassLoaderUtils.loadJar(ClassLoaderUtils.java:120)
... 39 more
注意看,上面的错误日志少了很多,某些地方用“... 6 more”“... 23 more”代替了。
这样精简之后,对于错误的定位就清晰多了。
例如,我来分析一下上面的日志:
1)首先,读它的错误信息:
类文件加载失败 |- java.lang.RuntimeException: jar文件加载异常!D:optappWebSphereoutput eportfileloadclass照片.jar
我了解错误的概况“类文件加载失败了”,进一步原因是“照片.jar这个jar文件加载异常”
2)再看紧跟着错误信息的下面三行错误经过的类路径:
com.proj.report.common.util.ClassLoaderUtils.loadJar(ClassLoaderUtils.java:123)
at com.proj.report.backmanage.addin.control.ClassLoadController.loadClass(ClassLoadController.java:41)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
从这三行数据,我得知,这个异常信息是从ClassLoaderUtils.loadJar(ClassLoaderUtils.java:123)这个地方被new出来的。可以猜测,这个地方有如下一个语句:throw new RuntimeException()。又根据下面有Caused by: java.util.zip.ZipException语句,所以断定,真正的写法是throw new RuntimeException(e),其中这个e的类型是java.util.zip.ZipException。
在这之后的数据,是程序调用的轨迹,大概就是经过Http进入到了拦截器和Servlet,进而到了Action(Controller),我只记录了一些核心的轨迹信息。一般来说,这些轨迹信息是毫无用处的。你甚至可以全部去掉。只保留项目包名“com.proj.report.*”开头的信息即可。
再看Caused by语句,这个才是错误的真正原始出处,可以看到,是
java.util.zip.ZipException: error in opening zip file
at java.util.zip.ZipFile.open(Native Method)
也就是说,最底层、最源头的错误,是从ZipFile.open(Native Method)里面new出来的。错误信息是:error in opening zip file
再接着往后面看,看到了最后,是:
com.proj.report.common.util.ClassLoaderUtils.loadJar(ClassLoaderUtils.java:120)
... 39 more
这代表,在我们自己写的程序中,错误的最源头是
ClassLoaderUtils.loadJar(ClassLoaderUtils.java:120)
是从这个工具类的第120行抛出来的。
那么,完整的错误轨迹,错误的原因和错误出处,我们都是非常清楚了。而且,根据上面信息,我还可以分析出程序调用的轨迹:(一般来说,没必要,用处不大)
经过上层程序的层层调用,到达了:
ClassLoadController.loadClass(xx)
然后调用了:
ClassLoaderUtils.loadJar(xx)
在这个方法中的如下之处:
ClassLoaderUtils.loadJar(ClassLoaderUtils.java:120)
即120行,抛出了错误信息。
这就是核心的程序运行轨迹,至于loadClass之上的轨迹和loadJar之后的轨迹,是其他API的运行轨迹,属于我们无法控制的范围,故打印出来意义不大。当然,我写的这个异常处理工具,是可以设定的,例如,如果你想看看SpringAPI的运行轨迹,你可以在不排除它的包名,比如org.springframework.mvc。
这样还不够,我还写了一个更强大的工具:ExceptionWrapper,重写了Throwable的方法。从底层去改造异常信息。说实话,SUN JDK里面的那个Throwable设计得并不好,之前我一直在IBM JDK上做测试,没发现问题,换到SUN JDK就出问题了。详见我写的一篇文章介绍:
http://www.cnblogs.com/zollty/p/3396252.html
像Open JDK 和GUN JDK,都是改进过的。我写的这个ExceptionWrapper,可以替代JDK自带的RuntimeException使用。功能更强大。以后我会专门写一篇文章来介绍这个工具。
用ExceptionWrapper包装后,最终的错误堆栈信息为:
类文件加载失败 |- jar文件加载异常!D:optwasfileloadclass照片.jar
Caused by: java.util.zip.ZipException: error in opening zip file
at java.util.zip.ZipFile.open(Native Method)
at java.util.zip.ZipFile.(ZipFile.java:114)
at java.util.jar.JarFile.(JarFile.java:133)
... 1 more
at com.proj.report.common.util.ClassLoaderUtils.loadJar(ClassLoaderUtils.java:122)
at com.proj.report.backmanage.addin.control.ClassLoadController.loadClass(ClassLoadController.java:41)
... 7 more
at com.proj.report.backmanage.interceptor.AccessRightInterceptor.dispose(AccessRightInterceptor.java:62)
... 7 more
at com.proj.report.backmanage.interceptor.AdminRightInterceptor.dispose(AdminRightInterceptor.java:56)
这样,我满意了。从上面的堆栈信息中,我能很清晰的看到错误的原因和报错的地方,以及程序运行的轨迹,几乎接近完美。