Reconnecting to Redis instance indefinitely

[ahmetgeymen]

Hello, I try to deploy a spring boot service trying to connect GCP Memorystore redis instance through GKE cluster (VPC native). Despite using without any issue on my local machine with docker-compose, after deploying over GCP, I encountered with the following issue. I also logged with DEBUG level for io.lettuce.core. The whole log is added at the end.

At first, it tries to connect Redis and succeeds. After that the connection is closed due to inactivity but immediately it tries to reconnect again. This cause endless logs like

Reconnected to redis:6379, Channel channel=0x881b8234, /10.20.1.28:36256 -> redis/10.0.1.151:6379
Reconnected to redis:6379, Channel channel=0x881b8234, /10.20.1.28:36256 -> redis/10.0.1.151:6379
Reconnected to redis:6379, Channel channel=0x881b8234, /10.20.1.28:36256 -> redis/10.0.1.151:6379
....

I tried to use both pooling or regular lettuce client config but couldn't overcome this situation. For anyone with any clue or guess I appreciate a lot.

Thanks

2021-01-19 19:21:47.825 DEBUG [auth,,,] 1 --- [enerContainer-1] io.lettuce.core.RedisClient              : Trying to get a Redis connection for: RedisURI [host='redis', port=6379]
2021-01-19 19:21:48.735 DEBUG [auth,,,] 1 --- [enerContainer-1] io.lettuce.core.EpollProvider            : Starting without optional epoll library
2021-01-19 19:21:48.741 DEBUG [auth,,,] 1 --- [enerContainer-1] io.lettuce.core.KqueueProvider           : Starting without optional kqueue library
2021-01-19 19:21:48.747 DEBUG [auth,,,] 1 --- [enerContainer-1] i.l.c.r.DefaultEventLoopGroupProvider    : Allocating executor io.netty.channel.nio.NioEventLoopGroup
2021-01-19 19:21:48.748 DEBUG [auth,,,] 1 --- [enerContainer-1] i.l.c.r.DefaultEventLoopGroupProvider    : Creating executor io.netty.channel.nio.NioEventLoopGroup
2021-01-19 19:21:48.838 DEBUG [auth,,,] 1 --- [enerContainer-1] i.l.c.r.DefaultEventLoopGroupProvider    : Adding reference to io.netty.channel.nio.NioEventLoopGroup@245afb37, existing ref count 0
2021-01-19 19:21:49.037 DEBUG [auth,,,] 1 --- [enerContainer-1] io.lettuce.core.RedisClient              : Resolved SocketAddress redis:6379 using RedisURI [host='redis', port=6379]
2021-01-19 19:21:49.041 DEBUG [auth,,,] 1 --- [enerContainer-1] io.lettuce.core.RedisClient              : Connecting to Redis at redis:6379
2021-01-19 19:21:49.942 DEBUG [auth,,,] 1 --- [ioEventLoop-6-1] io.lettuce.core.protocol.CommandHandler  : [channel=0x5dd2c38a, [id: 0x29643055] (inactive), chid=0x1] channelRegistered()
2021-01-19 19:21:50.029 DEBUG [auth,,,] 1 --- [ioEventLoop-6-1] io.lettuce.core.protocol.CommandHandler  : [channel=0x5dd2c38a, /10.20.1.28:36116 -> redis/10.0.1.151:6379, chid=0x1] channelActive()
2021-01-19 19:21:50.034 DEBUG [auth,,,] 1 --- [ioEventLoop-6-1] i.lettuce.core.protocol.DefaultEndpoint  : [channel=0x5dd2c38a, /10.20.1.28:36116 -> redis/10.0.1.151:6379, epid=0x1] activateEndpointAndExecuteBufferedCommands 0 command(s) buffered
2021-01-19 19:21:50.034 DEBUG [auth,,,] 1 --- [ioEventLoop-6-1] i.lettuce.core.protocol.DefaultEndpoint  : [channel=0x5dd2c38a, /10.20.1.28:36116 -> redis/10.0.1.151:6379, epid=0x1] activating endpoint
2021-01-19 19:21:50.036 DEBUG [auth,,,] 1 --- [ioEventLoop-6-1] i.lettuce.core.protocol.DefaultEndpoint  : [channel=0x5dd2c38a, /10.20.1.28:36116 -> redis/10.0.1.151:6379, epid=0x1] flushCommands()
2021-01-19 19:21:50.038 DEBUG [auth,,,] 1 --- [ioEventLoop-6-1] i.lettuce.core.protocol.DefaultEndpoint  : [channel=0x5dd2c38a, /10.20.1.28:36116 -> redis/10.0.1.151:6379, epid=0x1] flushCommands() Flushing 0 commands
2021-01-19 19:21:50.041 DEBUG [auth,,,] 1 --- [ioEventLoop-6-1] i.l.core.protocol.ConnectionWatchdog     : [channel=0x5dd2c38a, /10.20.1.28:36116 -> redis/10.0.1.151:6379, last known addr=redis/10.0.1.151:6379] channelActive()
2021-01-19 19:21:50.043 DEBUG [auth,,,] 1 --- [ioEventLoop-6-1] io.lettuce.core.protocol.CommandHandler  : [channel=0x5dd2c38a, /10.20.1.28:36116 -> redis/10.0.1.151:6379, chid=0x1] channelActive() done
2021-01-19 19:21:50.050 DEBUG [auth,,,] 1 --- [ioEventLoop-6-1] io.lettuce.core.RedisClient              : Connecting to Redis at redis:6379: Success
2021-01-19 19:21:50.133 DEBUG [auth,,,] 1 --- [ioEventLoop-6-1] i.l.core.protocol.ConnectionWatchdog     : [channel=0x5dd2c38a, /10.20.1.28:36116 -> redis/10.0.1.151:6379, last known addr=redis/10.0.1.151:6379] userEventTriggered(ctx, io.lettuce.core.ConnectionEvents$Activated@1b781987)
2021-01-19 19:21:50.537 DEBUG [auth,,,] 1 --- [enerContainer-1] io.lettuce.core.RedisClient              : Resolved SocketAddress redis:6379 using RedisURI [host='redis', port=6379]
2021-01-19 19:21:50.538 DEBUG [auth,,,] 1 --- [enerContainer-1] io.lettuce.core.RedisClient              : Connecting to Redis at redis:6379
2021-01-19 19:21:50.625 DEBUG [auth,,,] 1 --- [ioEventLoop-6-2] io.lettuce.core.protocol.CommandHandler  : [channel=0x2b12e8fd, [id: 0xa42547c7] (inactive), chid=0x2] channelRegistered()
2021-01-19 19:21:50.627 DEBUG [auth,,,] 1 --- [ioEventLoop-6-2] io.lettuce.core.protocol.CommandHandler  : [channel=0x2b12e8fd, /10.20.1.28:36132 -> redis/10.0.1.151:6379, chid=0x2] channelActive()
2021-01-19 19:21:50.628 DEBUG [auth,,,] 1 --- [ioEventLoop-6-2] i.lettuce.core.protocol.DefaultEndpoint  : [channel=0x2b12e8fd, /10.20.1.28:36132 -> redis/10.0.1.151:6379, epid=0x2] activateEndpointAndExecuteBufferedCommands 0 command(s) buffered
2021-01-19 19:21:50.628 DEBUG [auth,,,] 1 --- [ioEventLoop-6-2] i.lettuce.core.protocol.DefaultEndpoint  : [channel=0x2b12e8fd, /10.20.1.28:36132 -> redis/10.0.1.151:6379, epid=0x2] activating endpoint
2021-01-19 19:21:50.628 DEBUG [auth,,,] 1 --- [ioEventLoop-6-2] i.lettuce.core.protocol.DefaultEndpoint  : [channel=0x2b12e8fd, /10.20.1.28:36132 -> redis/10.0.1.151:6379, epid=0x2] flushCommands()
2021-01-19 19:21:50.628 DEBUG [auth,,,] 1 --- [ioEventLoop-6-2] i.lettuce.core.protocol.DefaultEndpoint  : [channel=0x2b12e8fd, /10.20.1.28:36132 -> redis/10.0.1.151:6379, epid=0x2] flushCommands() Flushing 0 commands
2021-01-19 19:21:50.628 DEBUG [auth,,,] 1 --- [ioEventLoop-6-2] i.l.core.protocol.ConnectionWatchdog     : [channel=0x2b12e8fd, /10.20.1.28:36132 -> redis/10.0.1.151:6379, last known addr=redis/10.0.1.151:6379] channelActive()
2021-01-19 19:21:50.629 DEBUG [auth,,,] 1 --- [ioEventLoop-6-2] io.lettuce.core.protocol.CommandHandler  : [channel=0x2b12e8fd, /10.20.1.28:36132 -> redis/10.0.1.151:6379, chid=0x2] channelActive() done
2021-01-19 19:21:50.629 DEBUG [auth,,,] 1 --- [ioEventLoop-6-2] io.lettuce.core.RedisClient              : Connecting to Redis at redis:6379: Success
2021-01-19 19:21:50.635 DEBUG [auth,,,] 1 --- [enerContainer-1] io.lettuce.core.RedisChannelHandler      : dispatching command AsyncCommand [type=SUBSCRIBE, output=PubSubOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command]
2021-01-19 19:21:50.636 DEBUG [auth,,,] 1 --- [ioEventLoop-6-2] i.l.core.protocol.ConnectionWatchdog     : [channel=0x2b12e8fd, /10.20.1.28:36132 -> redis/10.0.1.151:6379, last known addr=redis/10.0.1.151:6379] userEventTriggered(ctx, io.lettuce.core.ConnectionEvents$Activated@3c99d307)
2021-01-19 19:21:50.640 DEBUG [auth,,,] 1 --- [enerContainer-1] i.lettuce.core.protocol.DefaultEndpoint  : [channel=0x2b12e8fd, /10.20.1.28:36132 -> redis/10.0.1.151:6379, epid=0x2] write() writeAndFlush command AsyncCommand [type=SUBSCRIBE, output=PubSubOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command]
2021-01-19 19:21:50.643 DEBUG [auth,,,] 1 --- [enerContainer-2] io.lettuce.core.RedisChannelHandler      : dispatching command AsyncCommand [type=PSUBSCRIBE, output=PubSubOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command]
2021-01-19 19:21:50.645 DEBUG [auth,,,] 1 --- [enerContainer-2] i.lettuce.core.protocol.DefaultEndpoint  : [channel=0x2b12e8fd, /10.20.1.28:36132 -> redis/10.0.1.151:6379, epid=0x2] write() writeAndFlush command AsyncCommand [type=PSUBSCRIBE, output=PubSubOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command]
2021-01-19 19:21:50.723 DEBUG [auth,,,] 1 --- [ioEventLoop-6-2] io.lettuce.core.protocol.CommandHandler  : [channel=0x2b12e8fd, /10.20.1.28:36132 -> redis/10.0.1.151:6379, chid=0x2] write(ctx, AsyncCommand [type=SUBSCRIBE, output=PubSubOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], promise)
2021-01-19 19:21:50.738 DEBUG [auth,,,] 1 --- [enerContainer-2] i.lettuce.core.protocol.DefaultEndpoint  : [channel=0x2b12e8fd, /10.20.1.28:36132 -> redis/10.0.1.151:6379, epid=0x2] write() done
2021-01-19 19:21:50.743 DEBUG [auth,,,] 1 --- [enerContainer-1] i.lettuce.core.protocol.DefaultEndpoint  : [channel=0x2b12e8fd, /10.20.1.28:36132 -> redis/10.0.1.151:6379, epid=0x2] write() done
2021-01-19 19:21:50.824 DEBUG [auth,,,] 1 --- [ioEventLoop-6-2] io.lettuce.core.protocol.CommandEncoder  : [channel=0x2b12e8fd, /10.20.1.28:36132 -> redis/10.0.1.151:6379] writing command AsyncCommand [type=SUBSCRIBE, output=PubSubOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command]
2021-01-19 19:21:50.837 DEBUG [auth,,,] 1 --- [ioEventLoop-6-2] io.lettuce.core.protocol.CommandHandler  : [channel=0x2b12e8fd, /10.20.1.28:36132 -> redis/10.0.1.151:6379, chid=0x2] write(ctx, AsyncCommand [type=PSUBSCRIBE, output=PubSubOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], promise)
2021-01-19 19:21:50.839 DEBUG [auth,,,] 1 --- [ioEventLoop-6-2] io.lettuce.core.protocol.CommandEncoder  : [channel=0x2b12e8fd, /10.20.1.28:36132 -> redis/10.0.1.151:6379] writing command AsyncCommand [type=PSUBSCRIBE, output=PubSubOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command]
2021-01-19 19:21:52.139  INFO [auth,,,] 1 --- [nio-8080-exec-1] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring DispatcherServlet 'dispatcherServlet'
2021-01-19 19:21:52.140  INFO [auth,,,] 1 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Initializing Servlet 'dispatcherServlet'
2021-01-19 19:21:52.327 DEBUG [auth,,,] 1 --- [ioEventLoop-6-2] io.lettuce.core.protocol.CommandHandler  : [channel=0x2b12e8fd, /10.20.1.28:36132 -> redis/10.0.1.151:6379, chid=0x2] Received: 164 bytes, 2 commands in the stack
2021-01-19 19:21:52.332 DEBUG [auth,,,] 1 --- [ioEventLoop-6-2] io.lettuce.core.protocol.CommandHandler  : [channel=0x2b12e8fd, /10.20.1.28:36132 -> redis/10.0.1.151:6379, chid=0x2] Stack contains: 2 commands
2021-01-19 19:21:52.334 DEBUG [auth,,,] 1 --- [ioEventLoop-6-2] i.l.core.protocol.RedisStateMachine      : Decode LatencyMeteredCommand [type=SUBSCRIBE, output=PubSubOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.AsyncCommand]
2021-01-19 19:21:52.832  INFO [auth,,,] 1 --- [           main] s.a.ScheduledAnnotationBeanPostProcessor : No TaskScheduler/ScheduledExecutorService bean found for scheduled processing
2021-01-19 19:21:52.836 DEBUG [auth,,,] 1 --- [ioEventLoop-6-2] i.l.core.protocol.RedisStateMachine      : Decoded LatencyMeteredCommand [type=SUBSCRIBE, output=PubSubOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.AsyncCommand], empty stack: true
2021-01-19 19:21:52.845  INFO [auth,,,] 1 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Completed initialization in 705 ms
2021-01-19 19:21:53.028  INFO [auth,,,] 1 --- [           main] com.mycompany.myapp.ApplicationKt        : Started ApplicationKt in 105.095 seconds (JVM running for 111.906)
2021-01-19 19:21:53.145 DEBUG [auth,,,] 1 --- [ioEventLoop-6-2] io.lettuce.core.protocol.CommandHandler  : [channel=0x2b12e8fd, /10.20.1.28:36132 -> redis/10.0.1.151:6379, chid=0x2] Stack contains: 1 commands
2021-01-19 19:21:53.146 DEBUG [auth,,,] 1 --- [ioEventLoop-6-2] i.l.core.protocol.RedisStateMachine      : Decode LatencyMeteredCommand [type=PSUBSCRIBE, output=PubSubOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.AsyncCommand]
2021-01-19 19:21:53.146 DEBUG [auth,,,] 1 --- [ioEventLoop-6-2] i.l.core.protocol.RedisStateMachine      : Decoded LatencyMeteredCommand [type=PSUBSCRIBE, output=PubSubOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.AsyncCommand], empty stack: true
2021-01-19 19:21:53.246 DEBUG [auth,,,] 1 --- [ioEventLoop-6-2] i.l.core.protocol.RedisStateMachine      : Decode null
2021-01-19 19:21:53.246 DEBUG [auth,,,] 1 --- [ioEventLoop-6-2] i.l.core.protocol.RedisStateMachine      : Decoded null, empty stack: true
2021-01-19 19:21:55.249 DEBUG [auth,,,] 1 --- [ioEventLoop-6-1] io.lettuce.core.protocol.CommandHandler  : [channel=0x5dd2c38a, /10.20.1.28:36116 -> redis/10.0.1.151:6379, chid=0x1] channelInactive()
2021-01-19 19:21:55.250 DEBUG [auth,,,] 1 --- [ioEventLoop-6-1] i.lettuce.core.protocol.DefaultEndpoint  : [channel=0x5dd2c38a, /10.20.1.28:36116 -> redis/10.0.1.151:6379, epid=0x1] deactivating endpoint handler
2021-01-19 19:21:55.251 DEBUG [auth,,,] 1 --- [ioEventLoop-6-1] i.lettuce.core.protocol.DefaultEndpoint  : [channel=0x5dd2c38a, /10.20.1.28:36116 -> redis/10.0.1.151:6379, epid=0x1] notifyQueuedCommands adding 0 command(s) to buffer
2021-01-19 19:21:55.251 DEBUG [auth,,,] 1 --- [ioEventLoop-6-1] io.lettuce.core.protocol.CommandHandler  : [channel=0x5dd2c38a, /10.20.1.28:36116 -> redis/10.0.1.151:6379, chid=0x1] channelInactive() done
2021-01-19 19:21:55.252 DEBUG [auth,,,] 1 --- [ioEventLoop-6-1] i.l.core.protocol.ConnectionWatchdog     : [channel=0x5dd2c38a, /10.20.1.28:36116 -> redis/10.0.1.151:6379, last known addr=redis/10.0.1.151:6379] channelInactive()
2021-01-19 19:21:55.252 DEBUG [auth,,,] 1 --- [ioEventLoop-6-1] i.l.core.protocol.ConnectionWatchdog     : [channel=0x5dd2c38a, /10.20.1.28:36116 -> redis/10.0.1.151:6379, last known addr=redis/10.0.1.151:6379] scheduleReconnect()
2021-01-19 19:21:55.252 DEBUG [auth,,,] 1 --- [ioEventLoop-6-1] i.l.core.protocol.ConnectionWatchdog     : [channel=0x5dd2c38a, /10.20.1.28:36116 -> redis/10.0.1.151:6379, last known addr=redis/10.0.1.151:6379] Reconnect attempt 1, delay 1ms
2021-01-19 19:21:55.257 DEBUG [auth,,,] 1 --- [ioEventLoop-6-1] io.lettuce.core.protocol.CommandHandler  : [channel=0x5dd2c38a, /10.20.1.28:36116 -> redis/10.0.1.151:6379, chid=0x1] channelUnregistered()
2021-01-19 19:21:55.359  INFO [auth,,,] 1 --- [xecutorLoop-1-1] i.l.core.protocol.ConnectionWatchdog     : Reconnecting, last destination was redis/10.0.1.151:6379
2021-01-19 19:21:55.365 DEBUG [auth,,,] 1 --- [xecutorLoop-1-1] io.lettuce.core.RedisClient              : Resolved SocketAddress redis:6379 using RedisURI [host='redis', port=6379]
2021-01-19 19:21:55.367 DEBUG [auth,,,] 1 --- [xecutorLoop-1-1] i.l.core.protocol.ReconnectionHandler    : Reconnecting to Redis at redis:6379
...

[jpdev01]

news?

[mp911de]

Auto-reconnect is intended to happen indefinitely if the remote peer drops the connection or the connection is disconnected otherwise without intentionally closing (StatefulConnection.close()) the connection.