过期的Invoker 连接 持续在 时间轮线程中执行重连任务，抛出大量异常

[fl061157]

异常栈如下：

at org.apache.dubbo.remoting.transport.netty4.NettyClient.doConnect(NettyClient.java:238)
    at org.apache.dubbo.remoting.transport.netty4.NettyClient.doConnect(NettyClient.java:171)
    at org.apache.dubbo.remoting.transport.AbstractClient.connect(AbstractClient.java:220)
    at org.apache.dubbo.remoting.transport.AbstractClient.reconnect(AbstractClient.java:274)
    at org.apache.dubbo.remoting.exchange.support.header.HeaderExchangeClient.reconnect(HeaderExchangeClient.java:171)
    at org.apache.dubbo.remoting.exchange.support.header.ReconnectTimerTask.doTask(ReconnectTimerTask.java:52)
    at org.apache.dubbo.remoting.exchange.support.header.AbstractTimerTask.run(AbstractTimerTask.java:87)
    at org.apache.dubbo.common.timer.HashedWheelTimer$HashedWheelTimeout.expire(HashedWheelTimer.java:653)
    at org.apache.dubbo.common.timer.HashedWheelTimer$HashedWheelBucket.expireTimeouts(HashedWheelTimer.java:732)
    at org.apache.dubbo.common.timer.HashedWheelTimer$Worker.run(HashedWheelTimer.java:454)
    at java.lang.Thread.run(Thread.java:748)

可以确定的是 我们注册中心（Nacos）已经 通知 Consumer刷新Invoker列表了。 查阅代码 ServiceDiscoveryRegistryDirectory.refreshInvoker 方法已经触发。 接着触发了 ServiceDiscoveryRegistryDirectory.destroyUnusedInvokers 方法 接着触发了 DubboInvoker.destroyUnusedInvokers.destroyInternal 方法 接着触发了 HeaderExchangeClient.doClose 方法 但是在 private void doClose() { if (heartBeatTimer != null) { heartBeatTimer.cancel(); heartBeatTimer = null; } if (reconnectTimer != null) { reconnectTimer.cancel(); reconnectTimer = null; } }
使用的是 reconnectTimer.cancel(); reconnectTimer 是一个 Timeout 。
而在 ReconnectTimerTask 的父类 AbstractTimerTask 中会进行reput public void run(Timeout timeout) throws Exception { Collection<Channel> c = channelProvider.getChannels(); for (Channel channel : c) { if (channel.isClosed()) { continue; } doTask(channel); } reput(timeout, tick); } Reput 中重新将 task放入 时间轮，生成一个新的 timeout

private void reput(Timeout timeout, Long tick) { if (timeout == null || tick == null) { throw new IllegalArgumentException(); } if (cancel) { return; } Timer timer = timeout.timer(); if (timer.isStop() || timeout.isCancelled()) { return; } timer.newTimeout(timeout.task(), tick, TimeUnit.MILLISECONDS); }

reput 中 重新生成了一个 新的timout 如上，因此 这个 时间轮重试任务将一直执行。

HeaderExchangeClient中关闭的是一个旧的 Timeout，最终导致 异常一直打印。

于是想请问一下 HeaderExchangeClient 的 doClose方法中 是否应该使用 heartBeatTimerTask.cancel()

[AlbumenJ]

使用的 Dubbo 版本是多少，之前有一个 ReconnectTimerTask 的问题，在 3.1.4 已经修复

[fl061157]

我们使用 3.1.2 版本

[AlbumenJ]

看了一下是 #10938 修复的

[AlbumenJ]

在 3.1.3 版本中才发布的

[fl061157]

但是 好像 Reput 的 timeout 还是 不会被 cancel。 因为 结果被丢弃了， 这样 还是会重复 重连 过期的 DubboInvoker的 NettyClient。 因为 我们用的K8S 。 KubeProxy 的 端口并不会因为 实例挂掉而关闭，因此这个 异常重连 每天打的日志就比较多， 大概每天有百万以上这样的错误日志。

[fl061157]

不好意思，看到你处理了 channel.close() 虽然 在时间轮中，ReconnectTimerTask 还会执行， 因为 还会Reput。 但 channel.isClose() 后 不会在执行 doTask了。

[AlbumenJ]

不好意思，看到你处理了 channel.close() 虽然 在时间轮中，ReconnectTimerTask 还会执行， 因为 还会Reput。 但 channel.isClose() 后 不会在执行 doTask了。

从注册中心摘掉的连接不应该还在 ReconnectTimerTask 的，你可以看下升级 Dubbo 版本后还有没有

[XingyuFu]

我们这边也有类似的问题，3.0.12版本： 当provider机器因为缩容销毁时，正好有业务请求。 看了下，大体执行顺序是：

1. 线程A进行业务请求，根据invokers获取到这个invoker
2. 线程B收到注册中心的消息，重新设置invokers，并开始把这个invoker销毁
3. 线程A已得知这个invoker要销毁，打印了"Invoker for service ".... ", this invoker should not be used any longer"
4. 线程B销毁client，ReferenceCountExchangeClient里将原本的client销毁，并放了一个LazyConnectExchangeClient进去
5. 线程A正常执行invoke方法，使用LazyConnectExchangeClient建立连接，成功获得结果

之后这个LazyConnectExchangeClient，因为那台机器已经销毁了，就开始不断的重连任务，ReconnectTimerTask一直在打印重连失败的异常日志。 从打印的日志上，我能看到线程A执行成功，并返回了正常的结果。也能看到，线程A触发的连接建立和线程B触发的连接关闭在统一毫秒。 看起来，就像是线程B销毁了连接，但线程A的LazyConnectExchangeClient正好重新创建了一个，没被close。 这个时间线是我根据日志和代码逻辑梳理出的，虽然复现的概率不大，但毕竟发布频率高，最近开始有报了。 @AlbumenJ 还请帮忙看下这个？

[AlbumenJ]

Please upgrade to 3.1.9.

[AlbumenJ]

May related with https://github.com/apache/dubbo/pull/11780

[XingyuFu]

May related with #11780

@AlbumenJ 这里做，的确能够解决销毁时client重连的问题了。 但对于invoker销毁时已经选择了这个invoker的请求，在竞争到读锁后会因为invoker的销毁抛出异常。所以这可能会引入新的问题：通常情况下的业务方，都不会接受“provider销毁时，consumer可能有请求失败”这种情况。 不知道针对抛出这个RpcException的情况，你们是否有别的改进？比如重新触发invoker的reselect？

[fl061157]

感觉上是为了处理注册中心脑裂问题。虽然注册中心上endpoint不存在，但实际服务及连接还在。服务依然可用。如果不触发连接close 内存也可能爆掉。

---- 回复的原邮件 ---- | 发件人 | @.> | | 日期 | 2023年04月13日 16:00 | | 收件人 | @.> | | 抄送至 | @.>@.> | | 主题 | Re: [apache/dubbo] 过期的Invoker 连接 持续在 时间轮线程中执行重连任务，抛出大量异常 (Issue #11289) |

May related with #11780

@AlbumenJ 这里做，的确能够解决销毁时client重连的问题了。 但对于invoker销毁时已经选择了这个invoker的请求，在竞争到读锁后会因为invoker的销毁抛出异常。所以这可能会引入新的问题：通常情况下的业务方，都不会接受“provider销毁时，consumer可能有请求失败”这种情况。 不知道针对抛出这个RpcException的情况，你们是否有别的改进？比如重新触发invoker的reselect？

— Reply to this email directly, view it on GitHub, or unsubscribe. You are receiving this because you authored the thread.Message ID: @.***>

[XingyuFu]

有点像，但并不一样，因为下游的provider会在之后确实销毁。 但对于这个新创建的client而言，directory的invokers中没它，它的连接也是不通的，但因为没close，所以就会一直存在，属于“逃逸”。它没被管理起来，所以也不会被调用。但因为时间轮线程一直尝试重连，所以也不会被垃圾回收。 上面的https://github.com/apache/dubbo/pull/11780 的确可以有效地避免这个client被真正连接使用，所以它不会被放入时间轮线程里，就可以被回收。 但对于这样因为并发错误选择了invoker的请求，感觉直接异常中断，还是有损失的。想的是，是否可以把这部分的损失减少。

[AlbumenJ]

在竞争到读锁后会因为invoker的销毁抛出异常。

这里实际上不多，因为服务目录的地址是已经先刷新了的，所以新请求不会有问题。只有“已经从服务目录拿了地址-刚准备调用”这个时机的请求会影响。

比如重新触发invoker的reselect？

默认 Dubbo 是有重试的，会尝试 2 次

[XingyuFu]

@AlbumenJ 我们把这个pr合了过来，但之后发现还会有这样的问题，依旧有重连已销毁provider ip的任务在不断执行。 问下，https://github.com/apache/dubbo/pull/10938 这个也是必须的吗？我看3.0.12版本也没有。

[AlbumenJ]

@AlbumenJ 我们把这个pr合了过来，但之后发现还会有这样的问题，依旧有重连已销毁provider ip的任务在不断执行。 问下，#10938 这个也是必须的吗？我看3.0.12版本也没有。

这个也需要的

[neverlaughtingboy]

@AlbumenJ 我最近也遇到了这个问题，我的场景是这样的，消费端的 dubbo 版本是 3.2.0，jdk 版本是17，服务端的 dubbo 版本是 3.1.10，jdk版本是1.8，都在容器环境，注册中心是 nacos，当时服务端由于 oom 被 Kubernets 给 kill 了，后面消费端出现了很多 ReconnectTimerTask 尝试重连已经下线的消费端失败的错误日志，当时消费端应该有6个副本，这些错误日志集中在其中两个副本，然后我看了 3.2.0 的源码，你上面提到的 #10938 和 #11780 应该在 3.2.0 的版本都已经合进去了，能帮忙分析下为啥还会出现这个问题吗。

[AlbumenJ]

这个 ReconnectTimerTask 会持续多久，在一段时间以后还会有报错吗

[neverlaughtingboy]

我遇到的情况至少持续了40分钟左右，因为40分钟之后我重启了有这个问题的消费端副本才解决这个报错

[AlbumenJ]

1. 服务端 kill 以后有重新拉起吗
2. 需要再复现的时候从日志看一下 Nacos 是什么时候推送的新地址，Dubbo 是否有关闭连接的行为

[neverlaughtingboy]

1. 服务端 kill 以后有重新拉起吗
2. 需要再复现的时候从日志看一下 Nacos 是什么时候推送的新地址，Dubbo 是否有关闭连接的行为

1. 重新拉起了
2. Nacos 推送新地址的时机不好判断，MSE Nacos 上只能看到有推送，但看不到推送的内容，服务端当时有这个日志： 消费端的报错是这个： 另外发现不是 OOM Killing 的，人为手动 Killing 也有这个问题

[AlbumenJ]

1. 服务端 kill 以后有重新拉起吗
2. 需要再复现的时候从日志看一下 Nacos 是什么时候推送的新地址，Dubbo 是否有关闭连接的行为

1. 重新拉起了
2. Nacos 推送新地址的时机不好判断，MSE Nacos 上只能看到有推送，但看不到推送的内容，服务端当时有这个日志： 消费端的报错是这个： 另外发现不是 OOM Killing 的，人为手动 Killing 也有这个问题

能加下钉钉 albumenj，我们看一下具体的场景吗

[CrazyHZM]

@fl061157 @neverlaughtingboy Does the problem still exist?