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

作者：钱嘉鑫
链接：https://www.jianshu.com/p/dc9a180cca61
来源：简书
著作权归作者所有。商业转载请联系作者获得授权，非商业转载请注明出处。