记一次dubbo调用的奇怪异常
以前更多的使用公司内部的框架,对dubbo不怎么熟悉。
服务升级时,dubbo调用偶尔会产生调用失败,Caused by:SOF异常
经过多次和服务方沟通,服务方均表示服务方未发现任何异常,在服务方日志中也确实没有发现任何异常,排查时就先排除了服务方可能。
根据Caused by:SOF FastJson异常,首先想到的是fastjson的循环引用导致的SOF bug,但排查发现Fastjson是1.2.69,又检查了服务方的fastjosn是1.2.73,考虑是fastjson问题,故首先尝试了升级调用方的fastjson看是否能够解决,发现不可以。
再继续排查,有几个比较难以理解的点影响排查
- dubbo选择的是Hessian序列化协议,怎么会是fastjson SOF?
- 服务端为什么会没有任何异常提示?
- 异常堆栈中为什么没有任何和fastjson有关系的上下文?
- 为什么会偶尔发生?
- 发生异常的一直是同一个接口服务?
经过各种排查,发现服务端确实正常,服务方正常返回了结果;调用方和服务方线程数等资源均没有明显升高,调用方引用的api包和服务方也吻合;在本地使用相同的参数反序列化也完成正常;
咨询对dubbo较为熟悉的同学,也没得到有效的反馈,尝试撸dubbo源码,发现Hessian反序列化中确实没有fastjson影子
排查陷入了困境。
异常提示:
[ERROR] msg:methodName Exception, request is:{xxxxxxx}||exception=com.alibaba.dubbo.rpc.RpcException: Failed to invoke the method methodName in the service xxxxxserviceName. Tried 1 times of the providers [ip] from the registry registryip on the consumer consumerip using the dubbo version xxx. Last error is: null
at com.alibaba.dubbo.rpc.cluster.support.FailoverClusterInvoker.doInvoke(FailoverClusterInvoker.java:111)
at com.alibaba.dubbo.rpc.cluster.support.AbstractClusterInvoker.invoke(AbstractClusterInvoker.java:244)
at com.alibaba.dubbo.rpc.cluster.support.wrapper.MockClusterInvoker.invoke(MockClusterInvoker.java:75)
at com.alibaba.dubbo.rpc.proxy.InvokerInvocationHandler.invoke(InvokerInvocationHandler.java:52)
at com.alibaba.dubbo.common.bytecode.proxy5.fetchAllTravelChannels(proxy5.java)
xxxxxxx......
at sun.reflect.GeneratedMethodAccessor447.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:644)
at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:633)
at org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:70)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:175)
at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:93)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:688
at com.alibaba.dubbo.common.bytecode.Wrapper9.invokeMethod(Wrapper9.java)
at com.alibaba.dubbo.rpc.proxy.javassist.JavassistProxyFactory$1.doInvoke(JavassistProxyFactory.java:47)
at com.alibaba.dubbo.rpc.proxy.AbstractProxyInvoker.invoke(AbstractProxyInvoker.java:76)
at com.alibaba.dubbo.config.invoker.DelegateProviderMetaDataInvoker.invoke(DelegateProviderMetaDataInvoker.java:52)
at com.alibaba.dubbo.rpc.protocol.InvokerWrapper.invoke(InvokerWrapper.java:56)
at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:72)
at com.alibaba.dubbo.rpc.filter.ExceptionFilter.invoke(ExceptionFilter.java:62)
at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:72)
at com.alibaba.dubbo.monitor.support.MonitorFilter.invoke(MonitorFilter.java:75)
at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:72)
at com.alibaba.dubbo.rpc.filter.TimeoutFilter.invoke(TimeoutFilter.java:42)
at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:72)
at com.alibaba.dubbo.rpc.protocol.dubbo.filter.TraceFilter.invoke(TraceFilter.java:78)
at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:72)
at com.alibaba.dubbo.rpc.filter.ContextFilter.invoke(ContextFilter.java:73)
at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:72)
at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:72)
at com.alibaba.dubbo.rpc.filter.ClassLoaderFilter.invoke(ClassLoaderFilter.java:38)
at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:72)
at com.alibaba.dubbo.rpc.filter.EchoFilter.invoke(EchoFilter.java:38)
at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:72)
at com.alibaba.dubbo.rpc.protocol.dubbo.DubboProtocol$1.reply(DubboProtocol.java:104)
at com.alibaba.dubbo.remoting.exchange.support.header.HeaderExchangeHandler.handleRequest(HeaderExchangeHandler.java:96)
at com.alibaba.dubbo.remoting.exchange.support.header.HeaderExchangeHandler.received(HeaderExchangeHandler.java:173)
at com.alibaba.dubbo.remoting.transport.DecodeHandler.received(DecodeHandler.java:51)
at com.alibaba.dubbo.remoting.transport.dispatcher.ChannelEventRunnable.run(ChannelEventRunnable.java:57)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
Caused by: java.lang.StackOverflowError
at com.alibaba.fastjson.serializer.MapSerializer.write(MapSerializer.java:108)
at com.alibaba.fastjson.serializer.MapSerializer.write(MapSerializer.java:44)
at com.alibaba.fastjson.serializer.MapSerializer.write(MapSerializer.java:271)
at com.alibaba.fastjson.serializer.MapSerializer.write(MapSerializer.java:44)
at com.alibaba.fastjson.serializer.ListSerializer.write(ListSerializer.java:135)
at com.alibaba.fastjson.serializer.MapSerializer.write(MapSerializer.java:271)
at com.alibaba.fastjson.serializer.MapSerializer.write(MapSerializer.java:44)
at com.alibaba.fastjson.serializer.MapSerializer.write(MapSerializer.java:271)
at com.alibaba.fastjson.serializer.MapSerializer.write(MapSerializer.java:44)
at com.alibaba.fastjson.serializer.ListSerializer.write(ListSerializer.java:135)
at com.alibaba.fastjson.serializer.MapSerializer.write(MapSerializer.java:271)
.......
在已经阻塞后续流程的情况下,打算在服务端和调用端废弃JavaBean返回,直接采用json数据返回,暂时解决问题,让后续流程继续。
在统计问题发生频率时,偶然看到,调用方异常堆栈的异常提示上面,偶尔会出现一个warn日志
[WARN][com.alibaba.com.caucho.hessian.io.SerializerFactory:655] _undef||_msg=Hessian/Burlap: 'xxxxClassName' is an unknown class in org.springframework.boot.loader.LaunchedURLClassLoader@20ad9418:
java.lang.ClassNotFoundException: xxxxClassName
瞬间感觉前面出现了光明
立马检查调用方是不是缺少了jar,发现调用方确实不存在这个jar,但全局搜索,对这个jar完全无任何依赖,多次咨询服务方,均被告知确定不需要这个依赖,又陷入了困境
尝试着将提取服务方返回的数据,并未发现问题。
没有任何思路的情况下,决定检查服务方的代码,各种申请,终于获得查看服务方源码权限。仔细阅读服务方这一接口的代码,终于发现,在服务方返回的JavaBean的层次中,存在一个Map<String, Object>的属性,而在接口中,map的一个value值是xxxxClassName类型,瞬间感觉又看到了光明
经过分析,调用方在反hessian序列化时,确实是无法解析这个xxxxClassName类型,但是还是无法解释fastjson导致的SOF.
有了思路,先尝试解决线上问题吧,尽管还有些没有解释通
和服务方沟通,修改了Map中的类型,转为了json对象,上线后,观察发现,问题得到了解决。
事后,多次再思考追踪,有几点始终无法理解
- 为什么那个warn日志偶尔才会出现
- 始终还是无法解释fastjson的sof问题
做个笔记,记录下问题,方便下次遇到时有思路。
欢迎dubbo的大佬们给与帮忙,脑子里有东西堵着理解不了很不舒服。