ConnectionWatchdog reconnecting even after client has been shutdown

[perlun]

Hi,

I rediscovered an issue today which causes some problems with tests where we do logging assertions (yeah, I know it's not super-great). Here is our Lettuce-related shutdown code:

    private void destroyRedisClient( RedisClient redisClient, @Nullable StatefulRedisConnection<String, byte[]> redisConnection ) {
        if ( redisConnection != null && redisConnection.isOpen() ) {
            try {
                redisConnection.close();
            }
            catch ( Exception e ) {
                logger.warn( "Error closing Redis connection", e );
            }
        }

        if ( redisClient.getResources() != null ) {
            try {
                redisClient.getResources().shutdown().await();
            }
            catch ( Exception ignored ) {
                // ignore
            }
        }

        try {
            redisClient.shutdown();
        }
        catch ( Exception ignored ) {
                // ignore
        }
    }

What puzzles me is that even after the above has executed (which should be fully synchronous & blocking if I understand things right), the ConnectionWatchdog is still trying to reconnect to this node for some reason. Here is an excerpt from the log:

    DEBUG 2021-04-28 11:06:30.124 [i.l.c.RedisChannelHandler] :: close()
    DEBUG 2021-04-28 11:06:30.124 [i.l.c.RedisChannelHandler] :: closeAsync()
    DEBUG 2021-04-28 11:06:30.124 [i.l.c.p.DefaultEndpoint] :: [channel=0xaa587818, /127.0.0.1:33772 -> localhost/127.0.0.1:49181, epid=0x1f] closeAsync()
    DEBUG 2021-04-28 11:06:30.124 [i.l.c.r.DefaultClientResources] :: Initiate shutdown (0, 2, SECONDS)
    DEBUG 2021-04-28 11:06:30.124 [i.l.c.p.CommandHandler] :: [channel=0xaa587818, /127.0.0.1:33772 -> localhost/127.0.0.1:49181, chid=0x25] channelInactive()
    DEBUG 2021-04-28 11:06:30.125 [i.l.c.p.DefaultEndpoint] :: [channel=0xaa587818, /127.0.0.1:33772 -> localhost/127.0.0.1:49181, epid=0x1f] deactivating endpoint handler
    DEBUG 2021-04-28 11:06:30.125 [i.l.c.p.CommandHandler] :: [channel=0xaa587818, /127.0.0.1:33772 -> localhost/127.0.0.1:49181, chid=0x25] channelInactive() done
    DEBUG 2021-04-28 11:06:30.125 [i.l.c.p.ConnectionWatchdog] :: [channel=0xaa587818, /127.0.0.1:33772 -> localhost/127.0.0.1:49181, last known addr=localhost/127.0.0.1:49181] channelInactive()
    DEBUG 2021-04-28 11:06:30.125 [i.l.c.r.DefaultEventLoopGroupProvider] :: Initiate shutdown (0, 2, SECONDS)
    DEBUG 2021-04-28 11:06:30.125 [i.l.c.p.ConnectionWatchdog] :: [channel=0xaa587818, /127.0.0.1:33772 -> localhost/127.0.0.1:49181, last known addr=localhost/127.0.0.1:49181] Reconnect scheduling disabled
    DEBUG 2021-04-28 11:06:30.125 [i.l.c.p.CommandHandler] :: [channel=0xaa587818, /127.0.0.1:33772 -> localhost/127.0.0.1:49181, chid=0x25] channelUnregistered()
    DEBUG 2021-04-28 11:06:30.125 [i.l.c.r.DefaultEventLoopGroupProvider] :: Release executor io.netty.channel.epoll.EpollEventLoopGroup@6e2c841d
    DEBUG 2021-04-28 11:06:30.129 [o.t.s.c.g.d.c.c.AbstrDockerCmd] :: Cmd: db28854a23bc3fa28e0e71f06a82bbca4f5164e317202a4dc76ab0eb36853f66,false
    DEBUG 2021-04-28 11:06:30.130 [o.t.s.c.g.d.c.e.InspectContainerCmdExec] :: GET: DefaultWebTarget{path=[/containers/db28854a23bc3fa28e0e71f06a82bbca4f5164e317202a4dc76ab0eb36853f66/json], queryParams={}}
    DEBUG 2021-04-28 11:06:30.134 [o.t.s.c.g.d.c.c.AbstrDockerCmd] :: Cmd: db28854a23bc3fa28e0e71f06a82bbca4f5164e317202a4dc76ab0eb36853f66,<null>
    DEBUG 2021-04-28 11:06:30.136 [i.l.c.AbstractRedisClient] :: Initiate shutdown (0, 2, SECONDS)
    DEBUG 2021-04-28 11:06:30.137 [i.l.c.r.DefaultEventLoopGroupProvider] :: Release executor io.netty.channel.epoll.EpollEventLoopGroup@6e2c841d
    DEBUG 2021-04-28 11:06:30.137 [i.l.c.r.DefaultEventLoopGroupProvider] :: Attempting to release io.netty.channel.epoll.EpollEventLoopGroup@6e2c841d but ref count is 0
    DEBUG 2021-04-28 11:06:30.179 [i.l.c.p.ConnectionWatchdog] :: Reconnecting, last destination was localhost:49182
    DEBUG 2021-04-28 11:06:30.179 [i.l.c.RedisClient] :: Resolved SocketAddress localhost:49182 using redis://********************************@localhost:49182
    DEBUG 2021-04-28 11:06:30.180 [i.l.c.p.ReconnectionHandler] :: Reconnecting to Redis at localhost:49182
    DEBUG 2021-04-28 11:06:30.181 [i.l.c.p.CommandHandler] :: [channel=0x577f978f, [id: 0x391e1664] (inactive), chid=0x26] channelRegistered()
    DEBUG 2021-04-28 11:06:30.182 [i.l.c.p.ConnectionWatchdog] :: Cannot reconnect to [localhost:49182]: finishConnect(..) failed: Connection refused: localhost/127.0.0.1:49182
    io.netty.channel.AbstractChannel$AnnotatedConnectException: finishConnect(..) failed: Connection refused: localhost/127.0.0.1:49182
    Caused by: java.net.ConnectException: finishConnect(..) failed: Connection refused
        at io.netty.channel.unix.Errors.throwConnectException(Errors.java:124)
        at io.netty.channel.unix.Socket.finishConnect(Socket.java:251)
        at io.netty.channel.epoll.AbstractEpollChannel$AbstractEpollUnsafe.doFinishConnect(AbstractEpollChannel.java:672)
        at io.netty.channel.epoll.AbstractEpollChannel$AbstractEpollUnsafe.finishConnect(AbstractEpollChannel.java:649)
        at io.netty.channel.epoll.AbstractEpollChannel$AbstractEpollUnsafe.epollOutReady(AbstractEpollChannel.java:529)
        at io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:465)
        at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:378)
        at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)
        at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
        at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
        at java.base/java.lang.Thread.run(Thread.java:834)

---

Hmm. Maybe I'm getting it now. We're seeing this logging because when the resources are being shutdown, some logging is emitted because of reconnection attempts happening before the resources have yet shutdown? WDYT of this theory @mp911de, could this be what's happening?

[mp911de]

The order in which resources are shut down is wrong. ClientResources must be disposed last because it contains the worker thread pools. Stopping threads before closing the connection/client leads to strange effects and is wrong API usage.

[perlun]

Thanks. As indicated in #1734 (comment), I tried this approach now, moving the redisClient.getResources().shutdown().await() call to be last, but I'm still seeing these log warnings unfortunately:

    DEBUG 2021-04-28 11:53:11.113 [o.t.s.c.g.d.c.c.AbstrDockerCmd] :: Cmd: 00f0d5ab0b028ca102b5c64dcdeec08f526ccdb24651b304db10beac6a0ab72b,false
    DEBUG 2021-04-28 11:53:11.113 [o.t.s.c.g.d.c.e.InspectContainerCmdExec] :: GET: DefaultWebTarget{path=[/containers/00f0d5ab0b028ca102b5c64dcdeec08f526ccdb24651b304db10beac6a0ab72b/json], queryParams={}}
    DEBUG 2021-04-28 11:53:11.120 [o.t.s.c.g.d.c.c.AbstrDockerCmd] :: Cmd: 00f0d5ab0b028ca102b5c64dcdeec08f526ccdb24651b304db10beac6a0ab72b,<null>
    INFO  2021-04-28 11:53:11.211 [i.l.c.p.ConnectionWatchdog] :: Reconnecting, last destination was localhost/127.0.0.1:49199
    INFO  2021-04-28 11:53:11.211 [i.l.c.p.ConnectionWatchdog] :: Reconnecting, last destination was localhost/127.0.0.1:49199
    WARN  2021-04-28 11:53:11.231 [i.l.c.p.ConnectionWatchdog] :: Cannot reconnect to [localhost:49199]: finishConnect(..) failed: Connection refused: localhost/127.0.0.1:49199
    WARN  2021-04-28 11:53:11.231 [i.l.c.p.ConnectionWatchdog] :: Cannot reconnect to [localhost:49199]: finishConnect(..) failed: Connection refused: localhost/127.0.0.1:49199

I assume we're still doing something wrong at our end, but first a final question: could you verify that the assumption that a proper RedisClient & getResources() sync shutdown should stop the ConnectionWatchdog is correct? There is no "static state" in that sense that could leave the ConnectionWatchdog hanging even after the client & resources are shutdown, right?

[perlun]

I found the root cause now...

We were leaving stale RedisClient & resource instances hanging in one of our tests. This was why we got the errors above. 😬

In this case, this was the proper fix to us. (ensure all resources are disposed of properly after the test)

    @AfterMethod
    public void tearDown() {
        subject.getServiceCache().invalidateAll();
    }

Sorry for the noise! I'll mark your reply as the correct answer now.

[perlun]

Hmm. Maybe I'm getting it now. We're seeing this logging because when the resources are being shutdown, some logging is emitted because of reconnection attempts happening before the resources have yet shutdown? WDYT of this theory @mp911de, could this be what's happening?

Blargh, please disregard the above. The problem I was seeing was actually WARN-level statements being emitted, which is a much bigger problem than the DEBUG statements above:

Gradle suite > Gradle test > SomeTest > some_test_method STANDARD_OUT
    DEBUG 2021-04-28 11:45:04.031 [r.u.Loggers$LoggerFactory] :: Using Slf4j logging framework

Gradle suite > Gradle test STANDARD_OUT
    DEBUG 2021-04-28 11:45:05.283 [o.t.s.c.g.d.c.c.AbstrDockerCmd] :: Cmd: 920c4064a767a6dea330dc1a4a058e5b57cf0ce1fd1e337e79e0849bb69b2b74,false
    DEBUG 2021-04-28 11:45:05.283 [o.t.s.c.g.d.c.e.InspectContainerCmdExec] :: GET: DefaultWebTarget{path=[/containers/920c4064a767a6dea330dc1a4a058e5b57cf0ce1fd1e337e79e0849bb69b2b74/json], queryParams={}}
    DEBUG 2021-04-28 11:45:05.288 [o.t.s.c.g.d.c.c.AbstrDockerCmd] :: Cmd: 920c4064a767a6dea330dc1a4a058e5b57cf0ce1fd1e337e79e0849bb69b2b74,<null>
    INFO  2021-04-28 11:45:05.375 [i.l.c.p.ConnectionWatchdog] :: Reconnecting, last destination was localhost/127.0.0.1:49196
    WARN  2021-04-28 11:45:05.392 [i.l.c.p.ConnectionWatchdog] :: Cannot reconnect to [localhost:49196]: finishConnect(..) failed: Connection refused: localhost/127.0.0.1:49196
    INFO  2021-04-28 11:45:05.429 [i.l.c.p.ConnectionWatchdog] :: Reconnecting, last destination was localhost/127.0.0.1:49196
    WARN  2021-04-28 11:45:05.443 [i.l.c.p.ConnectionWatchdog] :: Cannot reconnect to [localhost:49196]: finishConnect(..) failed: Connection refused: localhost/127.0.0.1:49196

Gradle suite > Gradle test > SomeTest > some_other_test_method FAILED
    java.lang.AssertionError: WARN log event encountered; no log events were expected. Log message:
    Cannot reconnect to [localhost:49196]: finishConnect(..) failed: Connection refused: localhost/127.0.0.1:49196
        at org.testng.Assert.fail(Assert.java:93)
        at SomeTest.some_other_test_method(SomeTest.java:103)

The order in which resources are shut down is wrong. ClientResources must be disposed last because it contains the worker thread pools. Stopping threads before closing the connection/client leads to strange effects and is wrong API usage.

Thanks, this might be the root cause for all my headache in fact. 🙇 Will test this approach right away and see if it helps.

[perlun]

Blargh, please disregard the above. The problem I was seeing was actually WARN-level statements being emitted, which is a much bigger problem than the DEBUG statements above:

For the record (helping my future self and others): This was the solution to my problem: #1734 (reply in thread)