debbo最终打印结果显示_dubbo的Exception堆栈被吃处理

研究背景

希望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 dejaVu =

Collections.newSetFromMap(new IdentityHashMap());

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,那么在异常传回客户端反序列化时,如果堆栈中包含的某些类在客户端中不存在时,会出现反序列化失败的情况,所以一定要保证所有的异常(主要是自定义异常)被客户端也依赖了。

评论
添加红包

请填写红包祝福语或标题

红包个数最小为10个

红包金额最低5元

当前余额3.43前往充值 >
需支付:10.00
成就一亿技术人!
领取后你会自动成为博主和红包主的粉丝 规则
hope_wisdom
发出的红包
实付
使用余额支付
点击重新获取
扫码支付
钱包余额 0

抵扣说明:

1.余额是钱包充值的虚拟货币,按照1:1的比例进行支付金额的抵扣。
2.余额无法直接购买下载,可以购买VIP、付费专栏及课程。

余额充值