Dubbo client can not supported string message

问题

线上突然抛出下面的异常

2019-09-26 15:35:22,325 ERROR [DubboClientHandler-ip2:15196-thread-2] c.a.d.r.e.s.h.HeaderExchangeHandler:: {}  [DUBBO] Dubbo client can not supported string message:  in channel: NettyChannel [channel=[id: 0x5210fa0a, /ip1:43814 => /ip2:15196]], url: dubbo://ip2:15196/com.....alge.eta.service.EtaService?accesslog=false&anyhost=true&application=system-dispatch&check=false&codec=dubbo&default.executes=100&default.loadbalance=roundrobin&dubbo=2.5.3&heartbeat=60000&interface=com.....alge.eta.service.EtaService&logger=slf4j&methods=getModelResult,getXingTangModelResult&pid=1&retries=0&side=consumer&timeout=400&timestamp=1568871901241, dubbo version: 2.5.3, current host: ip1
java.lang.Exception: Dubbo client can not supported string message:  in channel: NettyChannel [channel=[id: 0x5210fa0a, /ip1:43814 => /ip2:15196]], url: dubbo://ip2:15196/com.....alge.eta.service.EtaService?accesslog=false&anyhost=true&application=system-dispatch&check=false&codec=dubbo&default.executes=100&default.loadbalance=roundrobin&dubbo=2.5.3&heartbeat=60000&interface=com.....alge.eta.service.EtaService&logger=slf4j&methods=getModelResult,getXingTangModelResult&pid=1&retries=0&side=consumer&timeout=400&timestamp=1568871901241
	at com.alibaba.dubbo.remoting.exchange.support.header.HeaderExchangeHandler.received(HeaderExchangeHandler.java:180) ~[dubbo-2.5.3.jar!/:2.5.3]
	at com.alibaba.dubbo.remoting.transport.DecodeHandler.received(DecodeHandler.java:52) ~[dubbo-2.5.3.jar!/:2.5.3]
	at com.alibaba.dubbo.remoting.transport.dispatcher.ChannelEventRunnable.run(ChannelEventRunnable.java:82) ~[dubbo-2.5.3.jar!/:2.5.3]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_201]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_201]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_201]

这个异常有些少,于是我们查看应用日志期望可以发现更多信息,根据什么线索呢?线上的trace_id没有打印,那么只能根据线程日志查看,也就是:DubboClientHandler-ip2-thread-2。于是发现下面的异常日志

2019-09-26 15:35:22,310 WARN [DubboClientHandler-ip2:15196-thread-2] c.a.d.r.e.s.DefaultFuture:: {}  [DUBBO] The timeout response finally returned at 2019-09-26 15:35:22.310, response Response [id=1254844, version=null, status=50, event=false, error=Failed to send response: Response [id=1254844, version=2.0.0, status=20, event=false, error=null, result=RpcResult [result=[com.....alge.eta.dto.ResultRiderDTO@17bdd760, com.....alge.eta.dto.ResultRiderDTO@198283d3, com.....alge.eta.dto.ResultRiderDTO@323b5e16, com.....alge.eta.dto.ResultRiderDTO@66d2204d, com.....alge.eta.dto.ResultRiderDTO@43fc4bb6, com.....alge.eta.dto.ResultRiderDTO@3b1ffa8c, com.....alge.eta.dto.ResultRiderDTO@241b5a75, com.....alge.eta.dto.ResultRiderDTO@59b14bb], exception=null]], cause: java.util.ConcurrentModificationException
java.util.ConcurrentModificationException
	at java.util.ArrayList$Itr.checkForComodification(ArrayList.java:909)
	at java.util.ArrayList$Itr.next(ArrayList.java:859)
	at com.alibaba.com.caucho.hessian.io.CollectionSerializer.writeObject(CollectionSerializer.java:100)
	at com.alibaba.com.caucho.hessian.io.Hessian2Output.writeObject(Hessian2Output.java:408)
	at com.alibaba.com.caucho.hessian.io.JavaSerializer.writeObject(JavaSerializer.java:203)
	at com.alibaba.com.caucho.hessian.io.Hessian2Output.writeObject(Hessian2Output.java:408)
	at com.alibaba.dubbo.common.serialize.support.hessian.Hessian2ObjectOutput.writeObject(Hessian2ObjectOutput.java:92)
	at com.alibaba.dubbo.rpc.protocol.dubbo.DubboCodec.encodeResponseData(DubboCodec.java:200)
	at com.alibaba.dubbo.remoting.exchange.codec.ExchangeCodec.encodeResponse(ExchangeCodec.java:276)
	at com.alibaba.dubbo.remoting.exchange.codec.ExchangeCodec.encode(ExchangeCodec.java:77)
	at com.alibaba.dubbo.rpc.protocol.dubbo.DubboCountCodec.encode(DubboCountCodec.java:39)
	at com.alibaba.dubbo.remoting.transport.netty.NettyCodecAdapter$InternalEncoder.encode(NettyCodecAdapter.java:81)
	at org.jboss.netty.handler.codec.oneone.OneToOneEncoder.handleDownstream(OneToOneEncoder.java:66)
	at org.jboss.netty.channel.DefaultChannelPipeline.sendDownstream(DefaultChannelPipeline.java:591)
	at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendDownstream(DefaultChannelPipeline.java:776)
	at org.jboss.netty.channel.SimpleChannelHandler.writeRequested(SimpleChannelHandler.java:304)
	at com.alibaba.dubbo.remoting.transport.netty.NettyHandler.writeRequested(NettyHandler.java:99)
	at org.jboss.netty.channel.SimpleChannelHandler.handleDownstream(SimpleChannelHandler.java:266)
	at org.jboss.netty.channel.DefaultChannelPipeline.sendDownstream(DefaultChannelPipeline.java:591)
	at org.jboss.netty.channel.DefaultChannelPipeline.sendDownstream(DefaultChannelPipeline.java:582)
	at org.jboss.netty.channel.Channels.write(Channels.java:611)
	at org.jboss.netty.channel.Channels.write(Channels.java:578)
	at org.jboss.netty.channel.AbstractChannel.write(AbstractChannel.java:251)
	at com.alibaba.dubbo.remoting.transport.netty.NettyChannel.send(NettyChannel.java:98)
	at com.alibaba.dubbo.remoting.transport.AbstractPeer.send(AbstractPeer.java:51)
	at com.alibaba.dubbo.remoting.exchange.support.header.HeaderExchangeHandler.received(HeaderExchangeHandler.java:171)
	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:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)
, result=null], channel: /ip1:43814 -> /ip2:15196, dubbo version: 2.5.3, current host: ip1

问题已经清楚,将异常信息反馈给接口提供方。根据响应response id(1254844)查找与之匹配的请求request id(1254844),查找到对应的业务日志定位到出现问题的trace_id(订单id),根据订单id定位到业务影响点,确认影响范围

2019-09-26 15:35:21,645 ERROR [immediately-dispatch-44] c.d.d.f.r.r.i.OrderSendTimeOutFilter:getModelResult:287 {orderId=483047323593828352} 调用送达时间预测模型异常,etaService#getModelResult
com.alibaba.dubbo.rpc.RpcException: Failed to invoke the method getXingTangModelResult in the service com.....alge.eta.service.EtaService. Tried 1 times of the providers [ip2:15196] (1/2) from the registry 172.24.0.6:2186 on the consumer ip1 using the dubbo version 2.5.3. Last error is: Invoke remote method timeout. method: getXingTangModelResult, provider: dubbo://ip2:15196/com.....alge.eta.service.EtaService?accesslog=false&anyhost=true&application=system-dispatch&check=false&default.executes=100&default.loadbalance=roundrobin&dubbo=2.5.3&interface=com.....alge.eta.service.EtaService&logger=slf4j&methods=getModelResult,getXingTangModelResult&pid=1&retries=0&side=consumer&timeout=400&timestamp=1568871901241, cause: Waiting server-side response timeout. start time: 2019-09-26 15:35:21.244, end time: 2019-09-26 15:35:21.645, client elapsed: 0 ms, server elapsed: 401 ms, timeout: 400 ms, request: Request [id=1254844, version=2.0.0, twoway=true, event=false, broken=false, data=RpcInvocation [methodName=getXingTangModelResult, parameterTypes=[interface java.util.List], arguments=[[com.....alge.eta.dto.EtaRiderDTO@7de6164, com.....alge.eta.dto.EtaRiderDTO@44ac0621, com.....alge.eta.dto.EtaRiderDTO@60af7dfc, com.....alge.eta.dto.EtaRiderDTO@3940bef0, com.....alge.eta.dto.EtaRiderDTO@2bfb5818, com.....alge.eta.dto.EtaRiderDTO@380cd692, com.....alge.eta.dto.EtaRiderDTO@2ce11da9, com.....alge.eta.dto.EtaRiderDTO@37614eb1, com.....alge.eta.dto.EtaRiderDTO@7b618db0, com.....alge.eta.dto.EtaRiderDTO@2116bec, com.....alge.eta.dto.EtaRiderDTO@27733f2, com.....alge.eta.dto.EtaRiderDTO@1ed63260, com.....alge.eta.dto.EtaRiderDTO@593b5139, com.....alge.eta.dto.EtaRiderDTO@47a389e5, com.....alge.eta.dto.EtaRiderDTO@81e1, com.....alge.eta.dto.EtaRiderDTO@7dfd635c, com.....alge.eta.dto.EtaRiderDTO@669f1bed, com.....alge.eta.dto.EtaRiderDTO@7e872fed]], attachments={path=com.....alge.eta.service.EtaService, interface=com.....alge.eta.service.EtaService, version=0.0.0, timeout=400}]], channel: /ip1:43814 -> /ip2:15196
	at com.alibaba.dubbo.rpc.cluster.support.FailoverClusterInvoker.doInvoke(FailoverClusterInvoker.java:101) ~[dubbo-2.5.3.jar!/:2.5.3]
	at com.alibaba.dubbo.rpc.cluster.support.AbstractClusterInvoker.invoke(AbstractClusterInvoker.java:227) ~[dubbo-2.5.3.jar!/:2.5.3]
	at com.alibaba.dubbo.rpc.cluster.support.wrapper.MockClusterInvoker.invoke(MockClusterInvoker.java:72) ~[dubbo-2.5.3.jar!/:2.5.3]
	at com.alibaba.dubbo.rpc.cluster.support.AvailableCluster$1.doInvoke(AvailableCluster.java:43) ~[dubbo-2.5.3.jar!/:2.5.3]
	at com.alibaba.dubbo.rpc.cluster.support.AbstractClusterInvoker.invoke(AbstractClusterInvoker.java:227) ~[dubbo-2.5.3.jar!/:2.5.3]
	at com.alibaba.dubbo.rpc.cluster.support.wrapper.MockClusterInvoker.invoke(MockClusterInvoker.java:72) ~[dubbo-2.5.3.jar!/:2.5.3]
	at com.alibaba.dubbo.rpc.proxy.InvokerInvocationHandler.invoke(InvokerInvocationHandler.java:52) ~[dubbo-2.5.3.jar!/:2.5.3]
	at com.alibaba.dubbo.common.bytecode.proxy18.getXingTangModelResult(proxy18.java) ~[?:2.5.3]
	at com.....dispatch.filter.rules.riderfilter.impl.OrderSendTimeOutFilter.getModelResult(OrderSendTimeOutFilter.java:281) ~[dispatch-filter-rules-1.72.0.jar!/:1.72.0]
	at com.....dispatch.filter.rules.riderfilter.impl.OrderSendTimeOutFilter.beforeFilter(OrderSendTimeOutFilter.java:101) ~[dispatch-filter-rules-1.72.0.jar!/:1.72.0]
	at com.....dispatch.filter.rules.riderfilter.AbstractRiderFilter.filter(AbstractRiderFilter.java:34) ~[dispatch-filter-rules-1.72.0.jar!/:1.72.0]
	at com.....dispatch.struct.dispatcher.AbstractSingleDispatcher.filterInner(AbstractSingleDispatcher.java:93) ~[dispatch-struct-1.0-SNAPSHOT.jar!/:1.0-SNAPSHOT]
	at com.....dispatch.struct.dispatcher.AbstractSingleDispatcher.filterRiders(AbstractSingleDispatcher.java:87) ~[dispatch-struct-1.0-SNAPSHOT.jar!/:1.0-SNAPSHOT]
	at com.....dispatch.dispatch.SystemSingleDispatcher.filterRiders(SystemSingleDispatcher.java:382) ~[system-dispatch-impl-0.0.1-SNAPSHOT.jar!/:0.0.1-SNAPSHOT]
	at com.....dispatch.struct.dispatcher.ConfigurableAbstractSingleAsyncDispatcher.dispatch(ConfigurableAbstractSingleAsyncDispatcher.java:33) ~[dispatch-struct-1.0-SNAPSHOT.jar!/:1.0-SNAPSHOT]
	at com.....dispatch.provider.SystemDispatchProviderImpl.startDispatch(SystemDispatchProviderImpl.java:112) ~[system-dispatch-impl-0.0.1-SNAPSHOT.jar!/:0.0.1-SNAPSHOT]
	at com.....dispatch.provider.SystemDispatchProviderImpl.lambda$null$0(SystemDispatchProviderImpl.java:65) ~[system-dispatch-impl-0.0.1-SNAPSHOT.jar!/:0.0.1-SNAPSHOT]
	at com.....wireless.threadpool.MonitoringTask.run(MonitoringTask.java:50) ~[wireless-threadpool-0.0.1-SNAPSHOT.jar!/:0.0.1-SNAPSHOT]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_201]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_201]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_201]
Caused by: com.alibaba.dubbo.remoting.TimeoutException: Waiting server-side response timeout. start time: 2019-09-26 15:35:21.244, end time: 2019-09-26 15:35:21.645, client elapsed: 0 ms, server elapsed: 401 ms, timeout: 400 ms, request: Request [id=1254844, version=2.0.0, twoway=true, event=false, broken=false, data=RpcInvocation [methodName=getXingTangModelResult, parameterTypes=[interface java.util.List], arguments=[[com.....alge.eta.dto.EtaRiderDTO@7de6164, com.....alge.eta.dto.EtaRiderDTO@44ac0621, com.....alge.eta.dto.EtaRiderDTO@60af7dfc, com.....alge.eta.dto.EtaRiderDTO@3940bef0, com.....alge.eta.dto.EtaRiderDTO@2bfb5818, com.....alge.eta.dto.EtaRiderDTO@380cd692, com.....alge.eta.dto.EtaRiderDTO@2ce11da9, com.....alge.eta.dto.EtaRiderDTO@37614eb1, com.....alge.eta.dto.EtaRiderDTO@7b618db0, com.....alge.eta.dto.EtaRiderDTO@2116bec, com.....alge.eta.dto.EtaRiderDTO@27733f2, com.....alge.eta.dto.EtaRiderDTO@1ed63260, com.....alge.eta.dto.EtaRiderDTO@593b5139, com.....alge.eta.dto.EtaRiderDTO@47a389e5, com.....alge.eta.dto.EtaRiderDTO@81e1, com.....alge.eta.dto.EtaRiderDTO@7dfd635c, com.....alge.eta.dto.EtaRiderDTO@669f1bed, com.....alge.eta.dto.EtaRiderDTO@7e872fed]], attachments={path=com.....alge.eta.service.EtaService, interface=com.....alge.eta.service.EtaService, version=0.0.0, timeout=400}]], channel: /ip1:43814 -> /ip2:15196
	at com.alibaba.dubbo.remoting.exchange.support.DefaultFuture.get(DefaultFuture.java:107) ~[dubbo-2.5.3.jar!/:2.5.3]
	at com.alibaba.dubbo.remoting.exchange.support.DefaultFuture.get(DefaultFuture.java:84) ~[dubbo-2.5.3.jar!/:2.5.3]
	at com.alibaba.dubbo.rpc.protocol.dubbo.DubboInvoker.doInvoke(DubboInvoker.java:96) ~[dubbo-2.5.3.jar!/:2.5.3]
	at com.alibaba.dubbo.rpc.protocol.AbstractInvoker.invoke(AbstractInvoker.java:144) ~[dubbo-2.5.3.jar!/:2.5.3]
	at com.alibaba.dubbo.rpc.listener.ListenerInvokerWrapper.invoke(ListenerInvokerWrapper.java:74) ~[dubbo-2.5.3.jar!/:2.5.3]
	at com.alibaba.dubbo.monitor.support.MonitorFilter.invoke(MonitorFilter.java:75) ~[dubbo-2.5.3.jar!/:2.5.3]
	at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91) ~[dubbo-2.5.3.jar!/:2.5.3]
	at com.....wireless.dubbo.filter.InvokeResultLogFilter.invoke(InvokeResultLogFilter.java:36) ~[dubbo-integration-0.0.1-SNAPSHOT.jar!/:0.0.1-SNAPSHOT]
	at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91) ~[dubbo-2.5.3.jar!/:2.5.3]
	at com.alibaba.dubbo.rpc.protocol.dubbo.filter.FutureFilter.invoke(FutureFilter.java:53) ~[dubbo-2.5.3.jar!/:2.5.3]
	at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91) ~[dubbo-2.5.3.jar!/:2.5.3]
	at com.alibaba.dubbo.rpc.filter.ConsumerContextFilter.invoke(ConsumerContextFilter.java:48) ~[dubbo-2.5.3.jar!/:2.5.3]
	at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91) ~[dubbo-2.5.3.jar!/:2.5.3]
	at com.alibaba.dubbo.rpc.protocol.InvokerWrapper.invoke(InvokerWrapper.java:53) ~[dubbo-2.5.3.jar!/:2.5.3]
	at com.alibaba.dubbo.rpc.cluster.support.FailoverClusterInvoker.doInvoke(FailoverClusterInvoker.java:77) ~[dubbo-2.5.3.jar!/:2.5.3]
	... 20 more

问题总结

  1. dubbo线程中的客户端日志统一采用客户端句柄+服务端ip:端口+线程id(例如案例中的:DubboClientHandler-ip2:15196-thread-2)的格式。按照此格式可以定位到客户端侧同一个线程与同一个服务端的通信日志。协助客户端定位问题
  2. dubbo的请求与响应也有匹配的id可以进行跟踪,例如案例中的请求id与响应id(1254844)

问题思考与复现

为什么会出现发送字符串的异常?在dubbo官网查询到该问题的分析讨论以及解决方法:https://github.com/apache/dubbo/issues/2006

该bug已经在2.5.6中修复,修复方法为:在响应出现异常时复位Buffer。ExchangeCodec.encodeResponse方法中如果出现异常需要复位Buffer。

查看服务方使用的dubbo是2.5.3版本。为了验证结论使用该版本的dubbo成功复现了问题

复现步骤:

  1. 服务端使用的dubbo版本为2.5.3
  2. 服务端异步写响应数据,使其一定出现并发修改异常
  3. 客户端在收到并发修改异常后需要休眠等待一会便可复现上面的问题:Thread.sleep(1000 * 60);

复现代码:

// 提供者实现
@Component
public class ITestProviderImpl implements ITestProvider {

    @Override
    public List<ITestResultDTO> test() {
        List<ITestResultDTO> data = Lists.newLinkedList();
        for (int i=0;i<1;i++){
            ITestResultDTO result = new ITestResultDTO();
            data.add(result);
            try {
                TimeUnit.MILLISECONDS.sleep(10);
            } catch (InterruptedException e) {
                e.printStackTrace();
            }
        }
        new Thread(() -> {
            data.forEach(iTestResultDTO -> {
                List<ITestResultSubDTO> subData = Lists.newLinkedList();
                iTestResultDTO.setData(subData);
                int j = 0;
                while(true){
                    if (j%2==0) {
                        ITestResultSubDTO result = new ITestResultSubDTO();
                        subData.add(result);
                    } else {
                        subData.remove(0);
                    }
                }
            });
        }).start();
        return data;
    }
}
// 消费者,一定确认消费者不要走injvm协议,一定走remote远程协议,不然无法复现
public class ITestProviderTest extends UnitTestBase {

    @Resource
    private ITestProvider myTestProviderImpl;

    @Test
    public void test() throws InterruptedException {
        List<ITestResultDTO> data = null;
        try {
            data = myTestProviderImpl.test();
        } catch (Exception e) {
            e.printStackTrace();
        }
        System.out.println(data);
        // 重中之重,没有这个休眠是不能复现问题的
        Thread.sleep(1000 * 60);
    }

}
  • 0
    点赞
  • 0
    收藏
    觉得还不错? 一键收藏
  • 0
    评论

“相关推荐”对你有帮助么?

  • 非常没帮助
  • 没帮助
  • 一般
  • 有帮助
  • 非常有帮助
提交
评论
添加红包

请填写红包祝福语或标题

红包个数最小为10个

红包金额最低5元

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

抵扣说明:

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

余额充值