Dubbo 3.2.1协议端口复用，consumer端报错

[hkp2008]

• I have searched the issues of this repository and believe that this is not a duplicate.

Environment

• Dubbo version: 3.2.1
• Operating System version: win10
• Java version: 8

Steps to reproduce this issue

1. Provider 端配置

dubbo:
application:
name: demo-provider
metadataType: remote
protocol:
name: dubbo
port: 25110
ext-protocol: tri,
registry:
id: zk-registry
protocol: zookeeper
address: 192.168.110.2:2182

2. Consumer端配置
   dubbo:
   application:
   name: demo-provider
   protocol: tri
   metadataType: remote
   registry:
   id: zk-registry
   protocol: zookeeper
   address: 192.168.110.2:2182

问题：
provider端
protocol:
name: dubbo
ext-protocol: tri,
这么配置消费端正常消费

如果provider端改为：
protocol:
name: tri
ext-protocol: dubbo,

消费端报如下错误：

2023-05-18 17:26:36.237  WARN 34904 --- [pool-4-thread-1] o.a.d.r.proxy.InvokerInvocationHandler   :  [DUBBO] [Dubbo-Consumer] execute service com.demo.DeviceCacheService#getDeviceGroupInfoBySn cost 3117.215301 ms, this invocation almost (maybe already) timeout. Timeout: 1000ms
invocation context:
path=com.demo.DeviceCacheService;
remote.application=demo-consumer;
interface=com.demo.DeviceCacheService;
version=0.0.0;
timeout=1000;
group=null;
thread info: 
Start time: 263164536644299
+-[ Offset: 0.000000ms; Usage: 3117.215301ms, 100% ] Receive request. Client invoke begin. ServiceKey: com.demo.DeviceCacheService MethodName:getDeviceGroupInfoBySn
  +-[ Offset: 10.386101ms; Usage: 1050.441600ms, 33% ] Invoker invoke. Target Address: 192.168.110.26:25110
  +-[ Offset: 1061.036301ms; Usage: 1041.713000ms, 33% ] Invoker invoke. Target Address: 192.168.110.26:25110
  +-[ Offset: 2103.146901ms; Usage: 1013.415500ms, 32% ] Invoker invoke. Target Address: 192.168.110.26:25110, dubbo version: 3.2.1, current host: 192.168.110.26, error code: 3-4. This may be caused by , go to https://dubbo.apache.org/faq/3/4 to find instructions. 
Exception in thread "pool-4-thread-1" org.apache.dubbo.rpc.RpcException: Failed to invoke the method getDeviceGroupInfoBySn in the service com.demo.DeviceCacheService. Tried 3 times of the providers [192.168.110.26:25110] (1/2) from the registry 192.168.110.2:2182 on the consumer 192.168.110.26 using the dubbo version 3.2.1. Last error is: Invoke remote method timeout. method: getDeviceGroupInfoBySn, provider: DefaultServiceInstance{serviceName='demo-provider', host='192.168.110.26', port=25110, enabled=true, healthy=true, metadata={dubbo.endpoints=[{"port":25110,"protocol":"dubbo"},{"port":25110,"protocol":"tri"}], dubbo.metadata.revision=2944e6d1048e9dc79684a1ef0995194d, dubbo.metadata.storage-type=remote, timestamp=1684401953633}}, service{name='com.demo.DeviceCacheService',group='null',version='null',protocol='dubbo',port='25110',params={side=provider, release=3.2.1, methods=evictDeviceGroupInfo,evictDeviceGroupInfo,getDeviceGroupInfoBySn,getDeviceGroupInfoBySnWithVerifyStatus,updateDeviceGroupInfo,updateDeviceGroupInfo,userThisService, logger=slf4j, deprecated=false, dubbo=2.0.2, interface=com.demo.DeviceCacheService, service-name-mapping=true, timeout=1000, generic=false, ispuserver=true, retries=0, metadata-type=remote, application=demo-provider, prefer.serialization=fastjson2,hessian2, dynamic=true, REGISTRY_CLUSTER=zk-registry},}, cause: org.apache.dubbo.remoting.TimeoutException: Waiting server-side response timeout by scan timer. start time: 2023-05-18 17:26:35.221, end time: 2023-05-18 17:26:36.231, client elapsed: 1 ms, server elapsed: 1009 ms, timeout: 1000 ms, request: Request [id=2, version=2.0.2, twoWay=true, event=false, broken=false, mPayload=0, data=null], channel: /192.168.110.26:60965 -> /192.168.110.26:25110
	at org.apache.dubbo.rpc.cluster.support.FailoverClusterInvoker.doInvoke(FailoverClusterInvoker.java:114)
	at org.apache.dubbo.rpc.cluster.support.AbstractClusterInvoker.invoke(AbstractClusterInvoker.java:343)
	at org.apache.dubbo.rpc.cluster.router.RouterSnapshotFilter.invoke(RouterSnapshotFilter.java:46)
	at org.apache.dubbo.rpc.cluster.filter.FilterChainBuilder$CopyOfFilterChainNode.invoke(FilterChainBuilder.java:331)
	at org.apache.dubbo.monitor.support.MonitorFilter.invoke(MonitorFilter.java:108)
	at org.apache.dubbo.rpc.cluster.filter.FilterChainBuilder$CopyOfFilterChainNode.invoke(FilterChainBuilder.java:331)
	at org.apache.dubbo.rpc.cluster.filter.support.MetricsClusterFilter.invoke(MetricsClusterFilter.java:50)
	at org.apache.dubbo.rpc.cluster.filter.FilterChainBuilder$CopyOfFilterChainNode.invoke(FilterChainBuilder.java:331)
	at org.apache.dubbo.rpc.protocol.dubbo.filter.FutureFilter.invoke(FutureFilter.java:52)
	at org.apache.dubbo.rpc.cluster.filter.FilterChainBuilder$CopyOfFilterChainNode.invoke(FilterChainBuilder.java:331)
	at org.apache.dubbo.spring.security.filter.ContextHolderParametersSelectedTransferFilter.invoke(ContextHolderParametersSelectedTransferFilter.java:41)
	at org.apache.dubbo.rpc.cluster.filter.FilterChainBuilder$CopyOfFilterChainNode.invoke(FilterChainBuilder.java:331)
	at org.apache.dubbo.rpc.cluster.filter.support.ConsumerClassLoaderFilter.invoke(ConsumerClassLoaderFilter.java:40)
	at org.apache.dubbo.rpc.cluster.filter.FilterChainBuilder$CopyOfFilterChainNode.invoke(FilterChainBuilder.java:331)
	at org.apache.dubbo.rpc.cluster.filter.support.ConsumerContextFilter.invoke(ConsumerContextFilter.java:118)
	at org.apache.dubbo.rpc.cluster.filter.FilterChainBuilder$CopyOfFilterChainNode.invoke(FilterChainBuilder.java:331)
	at org.apache.dubbo.rpc.cluster.filter.FilterChainBuilder$CallbackRegistrationInvoker.invoke(FilterChainBuilder.java:194)
	at org.apache.dubbo.rpc.cluster.support.wrapper.AbstractCluster$ClusterFilterInvoker.invoke(AbstractCluster.java:91)
	at org.apache.dubbo.rpc.cluster.support.wrapper.MockClusterInvoker.invoke(MockClusterInvoker.java:103)
	at org.apache.dubbo.rpc.cluster.support.wrapper.ScopeClusterInvoker.invoke(ScopeClusterInvoker.java:131)
	at org.apache.dubbo.registry.client.migration.MigrationInvoker.invoke(MigrationInvoker.java:284)
	at org.apache.dubbo.rpc.proxy.InvocationUtil.invoke(InvocationUtil.java:57)
	at org.apache.dubbo.rpc.proxy.InvokerInvocationHandler.invoke(InvokerInvocationHandler.java:75)
	at com.demo.DeviceCacheServiceDubboProxy0.getDeviceGroupInfoBySn(DeviceCacheServiceDubboProxy0.java)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:567)
	at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:344)
	at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:213)
	at com.sun.proxy.$Proxy106.getDeviceGroupInfoBySn(Unknown Source)
	at com.demo.consumer.DeviceCacheServiceConsumer.getBySn(DeviceCacheServiceConsumer.java:14)
	at com.demo.consumer.Task.run(Task.java:15)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at java.base/java.lang.Thread.run(Thread.java:830)
Caused by: java.util.concurrent.ExecutionException: org.apache.dubbo.remoting.TimeoutException: Waiting server-side response timeout by scan timer. start time: 2023-05-18 17:26:35.221, end time: 2023-05-18 17:26:36.231, client elapsed: 1 ms, server elapsed: 1009 ms, timeout: 1000 ms, request: Request [id=2, version=2.0.2, twoWay=true, event=false, broken=false, mPayload=0, data=null], channel: /192.168.110.26:60965 -> /192.168.110.26:25110
	at java.base/java.util.concurrent.CompletableFuture.reportGet(CompletableFuture.java:395)
Caused by: java.util.concurrent.ExecutionException: org.apache.dubbo.remoting.TimeoutException: Waiting server-side response timeout by scan timer. start time: 2023-05-18 17:26:35.221, end time: 2023-05-18 17:26:36.231, client elapsed: 1 ms, server elapsed: 1009 ms, timeout: 1000 ms, request: Request [id=2, version=2.0.2, twoWay=true, event=false, broken=false, mPayload=0, data=null], channel: /192.168.110.26:60965 -> /192.168.110.26:25110

	at java.base/java.util.concurrent.CompletableFuture.get(CompletableFuture.java:2093)
	at org.apache.dubbo.rpc.AsyncRpcResult.get(AsyncRpcResult.java:208)
	at org.apache.dubbo.rpc.protocol.AbstractInvoker.waitForResultIfSync(AbstractInvoker.java:286)
	at org.apache.dubbo.rpc.protocol.AbstractInvoker.invoke(AbstractInvoker.java:189)
	at org.apache.dubbo.rpc.listener.ListenerInvokerWrapper.invoke(ListenerInvokerWrapper.java:71)
	at org.apache.dubbo.metrics.filter.MetricsFilter.invoke(MetricsFilter.java:58)
	at org.apache.dubbo.rpc.cluster.filter.FilterChainBuilder$CopyOfFilterChainNode.invoke(FilterChainBuilder.java:331)
	at org.apache.dubbo.rpc.cluster.filter.FilterChainBuilder$CallbackRegistrationInvoker.invoke(FilterChainBuilder.java:194)
	at org.apache.dubbo.rpc.protocol.ReferenceCountInvokerWrapper.invoke(ReferenceCountInvokerWrapper.java:78)
	at org.apache.dubbo.registry.client.ServiceDiscoveryRegistryDirectory$InstanceWrappedInvoker.invoke(ServiceDiscoveryRegistryDirectory.java:656)
	at org.apache.dubbo.rpc.cluster.support.AbstractClusterInvoker.invokeWithContext(AbstractClusterInvoker.java:382)
	at org.apache.dubbo.rpc.cluster.support.FailoverClusterInvoker.doInvoke(FailoverClusterInvoker.java:80)
	... 35 more
Caused by: org.apache.dubbo.remoting.TimeoutException: Waiting server-side response timeout by scan timer. start time: 2023-05-18 17:26:35.221, end time: 2023-05-18 17:26:36.231, client elapsed: 1 ms, server elapsed: 1009 ms, timeout: 1000 ms, request: Request [id=2, version=2.0.2, twoWay=true, event=false, broken=false, mPayload=0, data=null], channel: /192.168.110.26:60965 -> /192.168.110.26:25110
	at org.apache.dubbo.remoting.exchange.support.DefaultFuture.doReceived(DefaultFuture.java:217)
Caused by: org.apache.dubbo.remoting.TimeoutException: Waiting server-side response timeout by scan timer. start time: 2023-05-18 17:26:35.221, end time: 2023-05-18 17:26:36.231, client elapsed: 1 ms, server elapsed: 1009 ms, timeout: 1000 ms, request: Request [id=2, version=2.0.2, twoWay=true, event=false, broken=false, mPayload=0, data=null], channel: /192.168.110.26:60965 -> /192.168.110.26:25110

	at org.apache.dubbo.remoting.exchange.support.DefaultFuture.received(DefaultFuture.java:181)
	at org.apache.dubbo.remoting.exchange.support.DefaultFuture$TimeoutCheckTask.notifyTimeout(DefaultFuture.java:291)
	at org.apache.dubbo.remoting.exchange.support.DefaultFuture$TimeoutCheckTask.lambda$run$0(DefaultFuture.java:278)
	at org.apache.dubbo.common.threadpool.ThreadlessExecutor$RunnableWrapper.run(ThreadlessExecutor.java:141)
	at org.apache.dubbo.common.threadpool.ThreadlessExecutor.waitAndDrain(ThreadlessExecutor.java:70)
	at org.apache.dubbo.rpc.AsyncRpcResult.get(AsyncRpcResult.java:202)
	... 45 more

[AlbumenJ]

@icodening @EarthChen PTAL

[iJIAJIA]

@AlbumenJ
我们也碰到这个问题.

具体原因已经定位到了:
triple协议调用超时, 主要是首次连接请求时org.apache.dubbo.remoting.transport.netty4.NettyPortUnificationServerHandler#decode
进行协议检测的逻辑问题.
WirProtocol目前有4个实现, 其中 GrpcHttp2Protocol和TriHttp2Protocol都使用的Http2ProtocolDetector 进行的协议检测.
dubbo进行spi加载时, GrpcHttp2Protocol先于TriHttp2Protocol, 故所有tri协议都会被识别为GrpcHttp2Protocol.

NettyPortUnificationServerHandler在识别到协议后, 会基于实际的协议重新构造localUrl,

// 这里因为获取到的protocolName是grpc, 故返回的是默认的url, 即dubbo:// URL localURL = this.urlMapper.getOrDefault(protocolName, url);
后续在执行NettyConfigOperator时, 会因为是dubbo协议, 多了两个dubbo的ChannelHandler.

[AlbumenJ]

@AlbumenJ 我们也碰到这个问题.

具体原因已经定位到了: triple协议调用超时, 主要是首次连接请求时org.apache.dubbo.remoting.transport.netty4.NettyPortUnificationServerHandler#decode 进行协议检测的逻辑问题. WirProtocol目前有4个实现, 其中 GrpcHttp2Protocol和TriHttp2Protocol都使用的Http2ProtocolDetector 进行的协议检测. dubbo进行spi加载时, GrpcHttp2Protocol先于TriHttp2Protocol, 故所有tri协议都会被识别为GrpcHttp2Protocol.

NettyPortUnificationServerHandler在识别到协议后, 会基于实际的协议重新构造localUrl, // 这里因为获取到的protocolName是grpc, 故返回的是默认的url, 即dubbo:// URL localURL = this.urlMapper.getOrDefault(protocolName, url); 后续在执行NettyConfigOperator时, 会因为是dubbo协议, 多了两个dubbo的ChannelHandler.

Pure grpc protocol has been removed in #11544

[iJIAJIA]

@AlbumenJ 我们也碰到这个问题.
具体原因已经定位到了: triple协议调用超时, 主要是首次连接请求时org.apache.dubbo.remoting.transport.netty4.NettyPortUnificationServerHandler#decode 进行协议检测的逻辑问题. WirProtocol目前有4个实现, 其中 GrpcHttp2Protocol和TriHttp2Protocol都使用的Http2ProtocolDetector 进行的协议检测. dubbo进行spi加载时, GrpcHttp2Protocol先于TriHttp2Protocol, 故所有tri协议都会被识别为GrpcHttp2Protocol.
NettyPortUnificationServerHandler在识别到协议后, 会基于实际的协议重新构造localUrl, // 这里因为获取到的protocolName是grpc, 故返回的是默认的url, 即dubbo:// URL localURL = this.urlMapper.getOrDefault(protocolName, url); 后续在执行NettyConfigOperator时, 会因为是dubbo协议, 多了两个dubbo的ChannelHandler.

Pure grpc protocol has been removed in #11544

in which version? in current 3.2 branch, the GrpcHttp2Protocol SPI is still in use

[EarthChen]

@AlbumenJ 我们也碰到这个问题.
具体原因已经定位到了: triple协议调用超时, 主要是首次连接请求时org.apache.dubbo.remoting.transport.netty4.NettyPortUnificationServerHandler#decode 进行协议检测的逻辑问题. WirProtocol目前有4个实现, 其中 GrpcHttp2Protocol和TriHttp2Protocol都使用的Http2ProtocolDetector 进行的协议检测. dubbo进行spi加载时, GrpcHttp2Protocol先于TriHttp2Protocol, 故所有tri协议都会被识别为GrpcHttp2Protocol.
NettyPortUnificationServerHandler在识别到协议后, 会基于实际的协议重新构造localUrl, // 这里因为获取到的protocolName是grpc, 故返回的是默认的url, 即dubbo:// URL localURL = this.urlMapper.getOrDefault(protocolName, url); 后续在执行NettyConfigOperator时, 会因为是dubbo协议, 多了两个dubbo的ChannelHandler.

Pure grpc protocol has been removed in #11544

in which version? in current 3.2 branch, the GrpcHttp2Protocol SPI is still in use

Can you take a PR to fix it?

[lihuagang03]

triple和dubbo协议，端口不复用，使用两个不同的端口，应该不存在这个吧？