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: 异常

而对于最后不符合条件的异常,会使用dubbotoString()方法将异常转化为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
}

这个时候,客户端就能够完整的记录下异常的堆栈。联想到dubbotoString()方法里面也有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。

至此,应该差不多可以明白了,dubbotoString()也好,还是自己printStackTrace(),都阴差阳错的最终让Throwable的类变量stackTrace被赋值,然后就出现了某些异常堆栈会被打出来,而其他满足ExceptionFilter条件的异常堆栈被吃掉的怪异情况。

自定义ExceptionFilter

所以,解决我需求的办法也很简单,自定义一个ExceptionFilter,手动的去给所有异常的堆栈赋值即可。

private void fillInStackTrace(Throwable exception) {
  exception.setStackTrace(exception.getStackTrace());
}

稍微修改一下原来的invoke()逻辑,在获取到exception之后,预处理一下。

解决和不足

启用自定义的ExceptionFilter,发现问题完美解决。唯一不足之处是,由于我们对于堆栈的处理并没有处理成String,那么在异常传回客户端反序列化时,如果堆栈中包含的某些类在客户端中不存在时,会出现反序列化失败的情况,所以一定要保证所有的异常(主要是自定义异常)被客户端也依赖了。

最后编辑于
©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 217,657评论 6 505
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 92,889评论 3 394
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 164,057评论 0 354
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 58,509评论 1 293
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 67,562评论 6 392
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 51,443评论 1 302
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 40,251评论 3 418
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 39,129评论 0 276
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 45,561评论 1 314
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 37,779评论 3 335
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 39,902评论 1 348
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 35,621评论 5 345
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 41,220评论 3 328
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 31,838评论 0 22
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 32,971评论 1 269
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 48,025评论 2 370
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 44,843评论 2 354

推荐阅读更多精彩内容

  • Spring Cloud为开发人员提供了快速构建分布式系统中一些常见模式的工具(例如配置管理,服务发现,断路器,智...
    卡卡罗2017阅读 134,656评论 18 139
  • 我是一朵半途而废的花,绝望之后依然等待开放。 清韵,愿做你成长路上的同行者。 文 |清韵 图 | 网络 ▲ 上周末...
    清韵难敲阅读 926评论 0 1
  • 这是日本的一部动漫,讲的是日本女子学院比赛的事。“战车道”,“花道”,“茶道”,是日本女子学院必须掌握的基本战技。...
    白玉山阅读 418评论 0 0