同时使用注解和 xml 的方式引用 dubbo 服务产生的异常问题排查实战

一、现象

使用 nacos 作注册中心的线上 dubbo 消费端应用每隔 1 分钟就会抛出以下异常（为使描述简单化，文章中使用本地 demo 来复现），该异常表示无法连接到 172.17.0.1:20881 这台提供端

21:11:49.843 [dubbo-client-idleCheck-thread-1] ERROR org.apache.dubbo.remoting.exchange.support.header.ReconnectTimerTask.doTask(51) -  [DUBBO] Fail to connect to HeaderExchangeClient [channel=org.apache.dubbo.remoting.transport.netty4.NettyClient [172.17.0.1:0 -> /172.17.0.1:20881]], dubbo version: 2.7.3, current host: 172.17.0.1
org.apache.dubbo.remoting.RemotingException: client(url: dubbo://172.17.0.1:20881/com.example.dubbo.HelloService?anyhost=true&application=dubbo-consumer-app&bean.name=com.example.dubbo.HelloService&category=providers&check=false&codec=dubbo&deprecated=false&dubbo=2.0.2&dynamic=true&generic=false&heartbeat=60000&interface=com.example.dubbo.HelloService&lazy=false&methods=sayHello&path=com.example.dubbo.HelloService&pid=56029&protocol=dubbo&register=true&register.ip=172.17.0.1&release=2.7.3&remote.application=dubbo-provider-app&server=netty4&side=consumer&sticky=false&timestamp=1683113373687) failed to connect to server /172.17.0.1:20881, error message is:拒绝连接: /172.17.0.1:20881
	at org.apache.dubbo.remoting.transport.netty4.NettyClient.doConnect(NettyClient.java:166)
	at org.apache.dubbo.remoting.transport.AbstractClient.connect(AbstractClient.java:190)
	at org.apache.dubbo.remoting.transport.AbstractClient.reconnect(AbstractClient.java:246)
	at org.apache.dubbo.remoting.exchange.support.header.HeaderExchangeClient.reconnect(HeaderExchangeClient.java:155)
	at org.apache.dubbo.remoting.exchange.support.header.ReconnectTimerTask.doTask(ReconnectTimerTask.java:49)
	at org.apache.dubbo.remoting.exchange.support.header.AbstractTimerTask.run(AbstractTimerTask.java:87)
	at org.apache.dubbo.common.timer.HashedWheelTimer$HashedWheelTimeout.expire(HashedWheelTimer.java:648)
	at org.apache.dubbo.common.timer.HashedWheelTimer$HashedWheelBucket.expireTimeouts(HashedWheelTimer.java:727)
	at org.apache.dubbo.common.timer.HashedWheelTimer$Worker.run(HashedWheelTimer.java:449)
	at java.lang.Thread.run(Thread.java:748)
Caused by: io.netty.channel.AbstractChannel$AnnotatedConnectException: 拒绝连接: /172.17.0.1:20881
	at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
	at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:717)
	at io.netty.channel.socket.nio.NioSocketChannel.doFinishConnect(NioSocketChannel.java:325)
	at io.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.finishConnect(AbstractNioChannel.java:340)
	at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:635)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:582)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:499)
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:461)
	at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:884)
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
	... 1 more
Caused by: java.net.ConnectException: 拒绝连接
	... 11 more

二、问题排查

经过确认，172.17.0.1:20881 这台提供端确实已经下线，所以才会无法连接。

通过查询 dubbo 源码得知，ReconnectTimerTask 是一个定时任务，其实例被 DubboInvoker 实例持有，当 DubboInvoker 对应的消费端服务与对端的提供端服务断开连接时，该定时任务就会定时重连提供端。正常情况下不会出现这种异常，因为提供端下线以后，会通过注册中心通知到消费端，消费端对应的 DubboInvoker 实例会被销毁，从而重连定时任务也会被销毁。

找到出问题的 HelloService 在应用中的使用方式，发现既有通过 @Reference 注解的方式使用，又有通过 xml 配置的方式使用。首先，将 arthas 连接到出问题的消费端应用，然后执行以下命令

ognl '#context=@org.apache.dubbo.config.spring.extension.SpringExtensionFactory@CONTEXTS.iterator.next, #context.getBean("helloService").handler.invoker.directory.urlInvokerMap'

得到结果为

发现 HelloService 服务的 RegistryDirectory 实例中确实还存在已经下线的提供端，说明提供端下线后该消费端没有感知到

接着，使用 arthas 监控看看消费端的服务监听 notify 方法是否生效，运行以下命令

watch org.apache.dubbo.registry.support.FailbackRegistry notify params

然后，将 20880 那台服务提供端也下线，看看 watch 命令的输出，如下所示

说明服务下线通知功能是正常的，不过这里的 RegistryDirectory 实例和上面使用 ognl 表达式查询的 RegistryDirectory 实例不是同一个，使用 ognl 表达式查询的实例如下

说明 HelloService 服务被 refer 了两次，也就是生成了两个服务引用，但是只有一个引用的服务监听生效。

三、结论

联系到 HelloService 在应用中有注解和 xml 两种引用方式，调试一遍服务引用的创建过程，发现在 NacosRegistry 中有这么一段服务订阅代码

这段代码的意思是，当相同的服务引用被创建了两次，只有第一次创建的引用会订阅服务。所以通过注解和 xml 两种方式创建 HelloService 服务引用时，会导致其中一个引用不会订阅服务变更，导致无法感知提供端下线，就会出现不断重连提供端的现象。

四、解决方案

应用中应当禁止同时使用注解和 xml 的方式来引用 dubbo 服务。