研究背景
希望dubbo
服务端抛出的异常完整的传递给客户端,最终到达最高层,统一进行异常的处理和堆栈的记录。
不使用ExceptionFilter
会出现java原生的异常堆栈消失,没有空参构造器的自定义异常堆栈能够在服务端出现,而有空参构造器的自定义异常堆栈也消失的情况。
问题分析
2016-06-07 18:27:15.896 WARN 18362 --- [w I/O worker #1] c.a.d.c.s.support.kryo.CompatibleKryo : [DUBBO] class java.lang.StackTraceElement has no zero-arg constructor and this will affect the serialization performance, dubbo version: 2.8.4, current host: 172.16.0.185
我们使用的序列化方式是Kryo
,
分析日志和代码:
public Serializer getDefaultSerializer(Class type) {
if (type == null) {
throw new IllegalArgumentException("type cannot be null.");
}
if (!type.isArray() && !ReflectionUtils.checkZeroArgConstructor(type)) {
if (logger.isWarnEnabled()) {
logger.warn(type + " has no zero-arg constructor and this will affect the serialization performance");
}
return new JavaSerializer();
}
return super.getDefaultSerializer(type);
}
发现,原来是dubbox优化之后造成的结果,当需要被序列化的对象没有空参构造器时,dubbox会放弃使用Kryo
而使用java
序列化方案。很可能就是这个优化方案导致上述怪异情况的发生。
默认的ExceptionFilter
关键代码:
Throwable exception = result.getException();
// 如果是checked异常,直接抛出
if (! (exception instanceof RuntimeException) && (exception instanceof Exception)) {
return result;
}
// 在方法签名上有声明,直接抛出
try {
Method method = invoker.getInterface().getMethod(invocation.getMethodName(), invocation.getParameterTypes());
Class<?>[] exceptionClassses = method.getExceptionTypes();
for (Class<?> exceptionClass : exceptionClassses) {
if (exception.getClass().equals(exceptionClass)) {
return result;
}
}
} catch (NoSuchMethodException e) {
return result;
}
// 异常类和接口类在同一jar包里,直接抛出
String serviceFile = ReflectUtils.getCodeBase(invoker.getInterface());
String exceptionFile = ReflectUtils.getCodeBase(exception.getClass());
if (serviceFile == null || exceptionFile == null || serviceFile.equals(exceptionFile)){
return result;
}
// 是JDK自带的异常,直接抛出
String className = exception.getClass().getName();
if (className.startsWith("java.") || className.startsWith("javax.")) {
return result;
}
// 是Dubbo本身的异常,直接抛出
if (exception instanceof RpcException) {
return result;
}
// 否则,包装成RuntimeException抛给客户端
return new RpcResult(new RuntimeException(StringUtils.toString(exception)));
可以看出,
dubbo
对于符合上述所有条件的异常都是直接返回,并没有做处理,导致客户端接受到的服务端异常堆栈是丢失的。信息如下:
2016-06-07 14:19:26.096 ERROR 14278 --- [nio-8081-exec-2] o.a.c.c.C.[.[.[/].[dispatcherServlet] : Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed; nested exception is java.lang.ArrayIndexOutOfBoundsException: 异常] with root cause
java.lang.ArrayIndexOutOfBoundsException: 异常
而对于最后不符合条件的异常,会使用dubbo
的toString()
方法将异常转化为String
,然后再包一层RuntimeException
往外抛出,那么理论上我们将会看到一个detailMessage
类似堆栈,但没有堆栈的一段信息。如下所示:
2016-06-07 14:21:23.789 ERROR 14278 --- [nio-8081-exec-5] o.a.c.c.C.[.[.[/].[dispatcherServlet] : Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed; nested exception is java.lang.RuntimeException: org.simble.framework.config.exception.PropertiesException: 自定义异常
org.simble.framework.config.exception.PropertiesException: 自定义异常
at org.simble.framework.config.exception.PropertiesException.instance(PropertiesException.java:20)
at org.simble.framework.config.exception.PropertiesException.instance(PropertiesException.java:24)
at org.simble.framework.config.exception.PropertiesException$instance.call(Unknown Source)
at org.codehaus.groovy.runtime.callsite.CallSiteArray.defaultCall(CallSiteArray.java:48)
at org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:113)
at org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:125)
at org.simble.member.service.impl.HelloServiceImpl.testCustomException(HelloServiceImpl.groovy:22)
at org.simble.member.service.HelloService$testCustomException$0.call(Unknown Source)
at org.codehaus.groovy.runtime.callsite.CallSiteArray.defaultCall(CallSiteArray.java:48)
at org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:113)
at org.codehaus.groovy.runtime.callsite.AbstractCallSite.call(AbstractCallSite.java:117)
at org.simble.member.server.api.impl.HelloApiImpl.testCustomException(HelloApiImpl.groovy:27)
at com.alibaba.dubbo.common.bytecode.Wrapper1.invokeMethod(Wrapper1.java)
at com.alibaba.dubbo.rpc.proxy.javassist.JavassistProxyFactory$1.doInvoke(JavassistProxyFactory.java:46)
at com.alibaba.dubbo.rpc.proxy.AbstractProxyInvoker.invoke(AbstractProxyInvoker.java:72)
at com.alibaba.dubbo.rpc.protocol.InvokerWrapper.invoke(InvokerWrapper.java:53)
at com.alibaba.dubbo.rpc.filter.ExceptionFilter.invoke(ExceptionFilter.java:64)
at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)
at com.alibaba.dubbo.monitor.support.MonitorFilter.invoke(MonitorFilter.java:75)
at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)
at com.alibaba.dubbo.rpc.filter.TimeoutFilter.invoke(TimeoutFilter.java:42)
at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)
at com.alibaba.dubbo.rpc.filter.AccessLogFilter.invoke(AccessLogFilter.java:201)
at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)
at com.alibaba.dubbo.rpc.protocol.dubbo.filter.TraceFilter.invoke(TraceFilter.java:78)
at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)
at com.alibaba.dubbo.rpc.filter.ExecuteLimitFilter.invoke(ExecuteLimitFilter.java:50)
at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)
at com.alibaba.dubbo.rpc.filter.ContextFilter.invoke(ContextFilter.java:70)
at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)
at com.alibaba.dubbo.rpc.filter.GenericFilter.invoke(GenericFilter.java:132)
at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)
at com.alibaba.dubbo.rpc.filter.ClassLoaderFilter.invoke(ClassLoaderFilter.java:38)
at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)
at com.alibaba.dubbo.rpc.filter.EchoFilter.invoke(EchoFilter.java:38)
at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)
at com.alibaba.dubbo.rpc.protocol.dubbo.DubboProtocol$1.reply(DubboProtocol.java:113)
at com.alibaba.dubbo.remoting.exchange.support.header.HeaderExchangeHandler.handleRequest(HeaderExchangeHandler.java:84)
at com.alibaba.dubbo.remoting.exchange.support.header.HeaderExchangeHandler.received(HeaderExchangeHandler.java:170)
at com.alibaba.dubbo.remoting.transport.DecodeHandler.received(DecodeHandler.java:52)
at com.alibaba.dubbo.remoting.transport.dispatcher.ChannelEventRunnable.run(ChannelEventRunnable.java:82)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
] with root cause
可是实际上,我们服务端不光获取到上面这段message
超长的异常信息,还把异常的堆栈也打印了出来,也就是说看起来就好像错误信息被打印了两次。
为什么这次异常的堆栈被打印了出来?难道自定义异常有优待?肯定不是,一切信息肯定包含在代码中。
原因分析
回到刚才的ExceptionFilter
// 否则,包装成RuntimeException抛给客户端
return new RpcResult(new RuntimeException(StringUtils.toString(exception)));
这个乍看只是toString()
,可谁知道他在里面干了什么。我们就来看一下这个toString()
方法:
public static String toString(Throwable e) {
UnsafeStringWriter w = new UnsafeStringWriter();
PrintWriter p = new PrintWriter(w);
p.print(e.getClass().getName());
if (e.getMessage() != null) {
p.print(": " + e.getMessage());
}
p.println();
try {
e.printStackTrace(p);
return w.toString();
} finally {
p.close();
}
}
好像确实只是把异常的堆栈转化成字符串。
线索又断了。。
在偶然的一次尝试中。
如果我服务端的代码先捕获一遍异常,然后打印一遍堆栈在抛出
try {
throw new ArrayIndexOutOfBoundsException("异常");
} catch (ArrayIndexOutOfBoundsException e) {
e.printStackTrace()
throw e
}
这个时候,客户端就能够完整的记录下异常的堆栈。联想到dubbo
的toString()
方法里面也有printStackTrace()
这个方法,所以他也打出了堆栈。难道printStackTrace()
方法不为人知的还做了一些除了打印之外的事情?
来看下printStackTrace()
最终调用的代码:
private void printStackTrace(PrintStreamOrWriter s) {
// Guard against malicious overrides of Throwable.equals by
// using a Set with identity equality semantics.
Set<Throwable> dejaVu =
Collections.newSetFromMap(new IdentityHashMap<Throwable, Boolean>());
dejaVu.add(this);
synchronized (s.lock()) {
// Print our stack trace
s.println(this);
StackTraceElement[] trace = getOurStackTrace();
for (StackTraceElement traceElement : trace)
s.println("\tat " + traceElement);
// Print suppressed exceptions, if any
for (Throwable se : getSuppressed())
se.printEnclosedStackTrace(s, trace, SUPPRESSED_CAPTION, "\t", dejaVu);
// Print cause, if any
Throwable ourCause = getCause();
if (ourCause != null)
ourCause.printEnclosedStackTrace(s, trace, CAUSE_CAPTION, "", dejaVu);
}
}
注意看这一行:
StackTraceElement[] trace = getOurStackTrace();
通过私有方法getOurStackTrace()
获取了异常的堆栈:
private synchronized StackTraceElement[] getOurStackTrace() {
// Initialize stack trace field with information from
// backtrace if this is the first call to this method
if (stackTrace == UNASSIGNED_STACK ||
(stackTrace == null && backtrace != null) /* Out of protocol state */) {
int depth = getStackTraceDepth();
stackTrace = new StackTraceElement[depth];
for (int i=0; i < depth; i++)
stackTrace[i] = getStackTraceElement(i);
} else if (stackTrace == null) {
return UNASSIGNED_STACK;
}
return stackTrace;
}
发现调用原生的native
方法getStackTraceElement()
获取异常的堆栈并赋值给Throwable
的类变量stackTrace。
至此,应该差不多可以明白了,dubbo
的toString()
也好,还是自己printStackTrace()
,都阴差阳错的最终让Throwable
的类变量stackTrace被赋值,然后就出现了某些异常堆栈会被打出来,而其他满足ExceptionFilter
条件的异常堆栈被吃掉的怪异情况。
自定义ExceptionFilter
所以,解决我需求的办法也很简单,自定义一个ExceptionFilter
,手动的去给所有异常的堆栈赋值即可。
private void fillInStackTrace(Throwable exception) {
exception.setStackTrace(exception.getStackTrace());
}
稍微修改一下原来的invoke()
逻辑,在获取到exception
之后,预处理一下。
解决和不足
启用自定义的ExceptionFilter
,发现问题完美解决。唯一不足之处是,由于我们对于堆栈的处理并没有处理成String
,那么在异常传回客户端反序列化时,如果堆栈中包含的某些类在客户端中不存在时,会出现反序列化失败的情况,所以一定要保证所有的异常(主要是自定义异常)被客户端也依赖了。