Reboot Redis service process, unable to receive key expired events

[Lvbuqing]

spring boot v2.7.14

I found the following problem when using the spring-data-redis component to monitor the key expiration function of Redis. Here are the steps to reproduce my problem:

1. Start Redis normally, and configure the properties of Redis.conf: notify-keyspace-events Ex
2. Start spring boot
3. Go to Redis to create a new key, and then set an expiration time of 3 seconds for this key
4. After 3 seconds, my springboot log output this expired key
   Everything is normal here, continue to operate.
5. Close the Redis service process, and the springboot log will print the log of Redis connection failure. After about 5 seconds, restart the Redis service process
6. Repeat step 3. At this time, the springboot log shows that Redis is connected successfully, but I cannot receive the expired key. When I restart springboot, repeat step 3, and I can receive the expired key again.
   To sum up, I suspect that the spring-data-redis component is not fully connected to Redis. After restarting Redis, the system cannot receive a new key with an expiration time.

My configuration is as follows:

Let me summarize again,
When spring-data-redis is connected normally, restarting the Redis process will result in failure to receive expired keys, but the Redis connection is normal (not sure if it is normal, see the log is normal)

[jxblum]

The first thing to realize is, the RedisMessageListenerContainer is a Spring SmartLifecycle bean (Javadoc, source). Therefore, it can be started and stopped during the lifecycle of your Spring [Boot] application, without necessarily having to restart the application.

Why is this relevant?

The RedisMessageListenerContainer acquires a single connection (i.e. RedisConnection) for subscriptions (here) from the container's "configured" RedisConnectionFactory. The connection factory will either be a LettuceConnectionFactory or JedisConnectionFactory depending on the configured Redis client driver library (Lettuce or Jedis) in use by your application. By default, Lettuce, when using Spring Boot. This connection gets established on SmartLifecycle.start(), which you can observe by tracing from here.

TIP: Continue tracing to here, then here, and finally, here, which leads to Subscriber.initialize(..), where the connection is established.

NOTE: Subsequently, the connection is closed on SmartLifecyle.stop(), after the container unsubscribes, or closes all subscriptions. Start from stop() and trace down to here.

All of this is to say, if you code some health check logic to detect that when the connection between your application and the Redis server is stale, then you can restart the RedisMessageListenerContainer, perhaps on some application event, once the Redis server comes back up and is available again.

Another option would be to configure low-level network client options on the connection in an attempt to recover from a (possible) temporary disconnect.

For example, in Lettuce, using Spring Data Redis LettuceClientConfiguration (Javadoc), passed to the LettuceConnectionFactory, to configure ClientOptions (Javadoc) and set the disconnect behavior.

Typically, recovering from failed connections is a driver concern, or perhaps best handled by a connection pool. This is not necessarily something a framework, like Spring Data Redis, should handle. One reason for this is, recovery, and the method of doing so, can vary greatly by environment (think cloud vs. non-managed environments, and so on).

Additionally, requirements and SLAs can vary by application UC.

[jxblum]

In general, Spring Data Redis classes & components used to create and manage connections between your Spring Boot application (using Spring Data Redis under-the-hood) and a Redis server were not meant to be reused if the components are destroyed, or (possibly) lose connection.

This is evident in the Spring Data Redis connection factory classes, for the JedisConnectionFactory here (then here) , as well as for the LettuceConnectionFactory here (then here), which is enforced when the factory is destroyed.

All connections to a previously failed Redis server would be stale (i.e. the system network pipe would be broken) and new connections would need to be established, or somehow, connections would need to be re-established (or refreshed) and ideally verified, once the network recovers, to resume communication. This later bit typically involves configuration and support at the driver-level (e.g. Jedis or Lettuce), so is largely outside the control of any framework or library.

[jxblum]

Having made the statements above, I am in the process of writing some tests and running some experiments by trying to configure the Redis driver to handle failed connections based on provided Redis driver configuration options, and see what happens.

[jxblum]

FYI, I completed my initial round of testing and it would seem the Lettuce Redis client driver and library handles automatic reconnection, if the Redis server goes down and then comes back up.

I have simple, Spring Boot, Spring Data Redis ChatBot application (see here) using the Spring Data Redis RedisMessageListenerContainer and Redis Pub/Sub to publish and subscribe to Chats in "chatroom" channel.

I started the backend, Redis server manually:

$ redis-server 
77084:C 04 Aug 2023 18:32:40.704 # oO0OoO0OoO0Oo Redis is starting oO0OoO0OoO0Oo
77084:C 04 Aug 2023 18:32:40.704 # Redis version=6.2.8, bits=64, commit=00000000, modified=0, pid=77084, just started
77084:C 04 Aug 2023 18:32:40.704 # Warning: no config file specified, using the default config. In order to specify a config file use redis-server /path/to/redis.conf
77084:M 04 Aug 2023 18:32:40.705 * Increased maximum number of open files to 10032 (it was originally set to 256).
77084:M 04 Aug 2023 18:32:40.705 * monotonic clock: POSIX clock_gettime
                _._                                                  
           _.-``__ ''-._                                             
      _.-``    `.  `_.  ''-._           Redis 6.2.8 (00000000/0) 64 bit
  .-`` .-```.  ```\/    _.,_ ''-._                                  
 (    '      ,       .-`  | `,    )     Running in standalone mode
 |`-._`-...-` __...-.``-._|'` _.-'|     Port: 6379
 |    `-._   `._    /     _.-'    |     PID: 77084
  `-._    `-._  `-./  _.-'    _.-'                                   
 |`-._`-._    `-.__.-'    _.-'_.-'|                                  
 |    `-._`-._        _.-'_.-'    |           https://redis.io       
  `-._    `-._`-.__.-'_.-'    _.-'                                   
 |`-._`-._    `-.__.-'    _.-'_.-'|                                  
 |    `-._`-._        _.-'_.-'    |                                  
  `-._    `-._`-.__.-'_.-'    _.-'                                   
      `-._    `-.__.-'    _.-'                                       
          `-._        _.-'                                           
              `-.__.-'                                               

77084:M 04 Aug 2023 18:32:40.707 # Server initialized
77084:M 04 Aug 2023 18:32:40.709 * Loading RDB produced by version 6.2.8
77084:M 04 Aug 2023 18:32:40.709 * RDB age 782530 seconds
77084:M 04 Aug 2023 18:32:40.709 * RDB memory usage when created 2.22 Mb
77084:M 04 Aug 2023 18:32:40.709 # Done loading RDB, keys loaded: 0, keys expired: 0.
77084:M 04 Aug 2023 18:32:40.709 * DB loaded from disk: 0.002 seconds
77084:M 04 Aug 2023 18:32:40.709 * Ready to accept connections

And, then I started by my application:

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::                (v3.1.0)

2023-08-06T19:06:57.970-07:00  INFO 94172 --- [           main] d.r.p.c.SpringRedisChatClientApplication : Starting SpringRedisChatClientApplication using Java 17.0.6 with PID 94172 (/Users/jblum/pivdev/spring-data-examples-workspace/redis-experiments/spring-data-redis-experiments/target/classes started by jblum in /Users/jblum/pivdev/spring-data-examples-workspace/redis-experiments)
2023-08-06T19:06:57.973-07:00  INFO 94172 --- [           main] d.r.p.c.SpringRedisChatClientApplication : The following 1 profile is active: "famous-quotes"
2023-08-06T19:06:58.381-07:00  INFO 94172 --- [           main] .s.d.r.c.RepositoryConfigurationDelegate : Multiple Spring Data modules found, entering strict repository configuration mode
2023-08-06T19:06:58.383-07:00  INFO 94172 --- [           main] .s.d.r.c.RepositoryConfigurationDelegate : Bootstrapping Spring Data Redis repositories in DEFAULT mode.
2023-08-06T19:06:58.416-07:00  INFO 94172 --- [           main] .s.d.r.c.RepositoryConfigurationDelegate : Finished Spring Data repository scanning in 13 ms. Found 0 Redis repository interfaces.
2023-08-06T19:06:59.674-07:00  INFO 94172 --- [           main] d.r.p.c.SpringRedisChatClientApplication : Started SpringRedisChatClientApplication in 2.031 seconds (process running for 2.362)
REDIS PUB/SUB [2023-08-06-19-07-04 - Jean-Luc Godard: "To be or not to be. That's not really a question."]
REDIS PUB/SUB [2023-08-06-19-07-07 - Eleanor Roosevelt: "It is better to light a candle than curse the darkness."]
REDIS PUB/SUB [2023-08-06-19-07-10 - John Burroughs: "The smallest deed is better than the greatest intention."]
REDIS PUB/SUB [2023-08-06-19-07-13 - Maya Angelou: "We may encounter many defeats but we must not be defeated."]
...
..
.

NOTE: I have ChatBots that generate the chats (or messages) sent through the Redis pub/sub subsystem.

After the application is running and outputing chat (messages) to the console, I kill the Redis server, upon which, I see the following output from my Spring Boot, Spring Data Redis application:

2023-08-06T19:08:01.584-07:00  INFO 94172 --- [xecutorLoop-1-9] i.l.core.protocol.ConnectionWatchdog     : Reconnecting, last destination was localhost/127.0.0.1:6379
2023-08-06T19:08:01.584-07:00  INFO 94172 --- [ecutorLoop-1-10] i.l.core.protocol.ConnectionWatchdog     : Reconnecting, last destination was localhost/127.0.0.1:6379
2023-08-06T19:08:01.591-07:00  WARN 94172 --- [ioEventLoop-4-4] i.l.core.protocol.ConnectionWatchdog     : Cannot reconnect to [localhost/<unresolved>:6379]: Connection refused: localhost/127.0.0.1:6379
2023-08-06T19:08:01.591-07:00  WARN 94172 --- [ioEventLoop-4-3] i.l.core.protocol.ConnectionWatchdog     : Cannot reconnect to [localhost/<unresolved>:6379]: Connection refused: localhost/127.0.0.1:6379
2023-08-06T19:08:10.678-07:00  INFO 94172 --- [ecutorLoop-1-11] i.l.core.protocol.ConnectionWatchdog     : Reconnecting, last destination was localhost/<unresolved>:6379
2023-08-06T19:08:10.678-07:00  INFO 94172 --- [ecutorLoop-1-10] i.l.core.protocol.ConnectionWatchdog     : Reconnecting, last destination was localhost/<unresolved>:6379
2023-08-06T19:08:10.679-07:00  WARN 94172 --- [ioEventLoop-4-3] i.l.core.protocol.ConnectionWatchdog     : Cannot reconnect to [localhost/<unresolved>:6379]: Connection refused: localhost/127.0.0.1:6379
2023-08-06T19:08:10.679-07:00  WARN 94172 --- [ioEventLoop-4-4] i.l.core.protocol.ConnectionWatchdog     : Cannot reconnect to [localhost/<unresolved>:6379]: Connection refused: localhost/127.0.0.1:6379

I then restart the Redis server, and afterwards, my Spring application reconnects and continues sending and receive chats:

2023-08-06T19:08:18.878-07:00  INFO 94172 --- [ecutorLoop-1-12] i.l.core.protocol.ConnectionWatchdog     : Reconnecting, last destination was localhost/<unresolved>:6379
2023-08-06T19:08:18.878-07:00  INFO 94172 --- [xecutorLoop-1-1] i.l.core.protocol.ConnectionWatchdog     : Reconnecting, last destination was localhost/<unresolved>:6379
2023-08-06T19:08:18.883-07:00  INFO 94172 --- [ioEventLoop-4-6] i.l.core.protocol.ReconnectionHandler    : Reconnected to localhost/<unresolved>:6379
2023-08-06T19:08:18.884-07:00  INFO 94172 --- [ioEventLoop-4-5] i.l.core.protocol.ReconnectionHandler    : Reconnected to localhost/<unresolved>:6379
REDIS PUB/SUB [2023-08-06-19-08-18 - Jack Welch: "Change before you have to."]
REDIS PUB/SUB [2023-08-06-19-08-18 - William Lyon Phelps: "If at first you don't succeed, find out if the loser gets anything."]
REDIS PUB/SUB [2023-08-06-19-08-18 - Jules Renard: "Laziness is nothing more than the habit of resting before you get tired."]
...
..
.

This is a fairly basic example, but goes to demonstrate that it would seem, when using Lettuce anyway, the Lettuce client driver and library seems to reestablish any failed/stale connections automatically.

I did not experiment with timeouts or other Redis driver settings/options yet, nor did I try Jedis. But, the basic infrastructure seems to be in place when using Lettuce.

[Lvbuqing]

I don't deny your test. In fact, I also saw the reconnection log from the console log, which can also indicate that lettuce has successfully connected to Redis, and can also read and write data correctly. but.
Have you ever thought that your test direction may be wrong at the beginning, sorry, this is my problem, my problem is that when inheriting org.springframework.data.redis.listener.KeyExpirationEventMessageListener, the data cannot be received after restarting, its core It is indeed Redis's Pub/Sub, sorry, I have a problem with using it here. Can you test it again?

@slf4j
@configuration
@EnableRedisRepositories(enableKeyspaceEvents = RedisKeyValueAdapter.EnableKeyspaceEvents.ON_STARTUP)
public class RedisKeyExpiredListener extends KeyExpirationEventMessageListener {

@Bean
RedisMessageListenerContainer container(RedisConnectionFactory redisConnectionFactory) {
    RedisMessageListenerContainer container = new RedisMessageListenerContainer();
    container.setConnectionFactory(redisConnectionFactory);
    return container;
}

/**
 * Creates new {@link MessageListener} for {@code __keyevent@*__:expired} messages.
 *
 * @param listenerContainer must not be {@literal null}.
 */
public RedisKeyExpiredListener(RedisMessageListenerContainer listenerContainer) {
    super(listenerContainer);
}

@Override
protected void doHandleMessage(Message message) {
    super.doHandleMessage(message);
}

@EventListener
public void handleExpiredEvent(RedisKeyExpiredEvent<String> event) {
    String expiredKey = new String(event.getId());
    log.info("Key expired：{}", expiredKey);
}

}

[jxblum]

Not sure what you mean by this?

Have you ever thought that your test direction may be wrong at the beginning

I suppose I can expand on my test to include a KeyExpirationEventMessageListener, but I really don't think it has anything to do with the "kind" of MessageListener you are using, and mostly, everything to do with the type of Redis connection you configured.

For instance, I just ran the same test again using Jedis. When I killed the Redis server, the Spring application (Redis client) started throwing Exceptions:

2023-08-06T23:42:38.212-07:00 ERROR 99279 --- [   scheduling-1] o.s.s.s.TaskUtils$LoggingErrorHandler    : Unexpected error occurred in scheduled task

org.springframework.data.redis.RedisConnectionFailureException: Cannot get Jedis connection
	at org.springframework.data.redis.connection.jedis.JedisConnectionFactory.fetchJedisConnector(JedisConnectionFactory.java:271) ~[spring-data-redis-3.1.0.jar:3.1.0]
	at org.springframework.data.redis.connection.jedis.JedisConnectionFactory.getConnection(JedisConnectionFactory.java:454) ~[spring-data-redis-3.1.0.jar:3.1.0]
	at org.springframework.data.redis.core.RedisConnectionUtils.fetchConnection(RedisConnectionUtils.java:193) ~[spring-data-redis-3.1.0.jar:3.1.0]
	at org.springframework.data.redis.core.RedisConnectionUtils.doGetConnection(RedisConnectionUtils.java:144) ~[spring-data-redis-3.1.0.jar:3.1.0]
	at org.springframework.data.redis.core.RedisConnectionUtils.getConnection(RedisConnectionUtils.java:105) ~[spring-data-redis-3.1.0.jar:3.1.0]
	at org.springframework.data.redis.core.RedisTemplate.execute(RedisTemplate.java:393) ~[spring-data-redis-3.1.0.jar:3.1.0]
	at org.springframework.data.redis.core.RedisTemplate.execute(RedisTemplate.java:373) ~[spring-data-redis-3.1.0.jar:3.1.0]
	at org.springframework.data.redis.core.RedisTemplate.convertAndSend(RedisTemplate.java:953) ~[spring-data-redis-3.1.0.jar:3.1.0]
	at io.vmware.spring.data.redis.pubsub.client.SpringRedisChatClientApplication.lambda$newRedisPublishingChatEventListener$1(SpringRedisChatClientApplication.java:70) ~[classes/:na]
	at example.chat.event.ChatEventPublisher.lambda$fire$0(ChatEventPublisher.java:40) ~[classes/:na]
	at java.base/java.util.concurrent.CopyOnWriteArrayList.forEach(CopyOnWriteArrayList.java:807) ~[na:na]
	at java.base/java.util.concurrent.CopyOnWriteArraySet.forEach(CopyOnWriteArraySet.java:425) ~[na:na]
	at example.chat.event.ChatEventPublisher.fire(ChatEventPublisher.java:40) ~[classes/:na]
	at example.chat.service.provider.EventDrivenChatService.send(EventDrivenChatService.java:45) ~[classes/:na]
	at example.chat.bot.provider.FamousQuotesChatBot.sendChat(FamousQuotesChatBot.java:223) ~[classes/:na]
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:na]
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77) ~[na:na]
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:na]
	at java.base/java.lang.reflect.Method.invoke(Method.java:568) ~[na:na]
	at org.springframework.scheduling.support.ScheduledMethodRunnable.run(ScheduledMethodRunnable.java:84) ~[spring-context-6.0.9.jar:6.0.9]
	at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54) ~[spring-context-6.0.9.jar:6.0.9]
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539) ~[na:na]
	at java.base/java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) ~[na:na]
	at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) ~[na:na]
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) ~[na:na]
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) ~[na:na]
	at java.base/java.lang.Thread.run(Thread.java:833) ~[na:na]
Caused by: redis.clients.jedis.exceptions.JedisConnectionException: Failed to connect to any host resolved for DNS name.
	at redis.clients.jedis.DefaultJedisSocketFactory.connectToFirstSuccessfulHost(DefaultJedisSocketFactory.java:63) ~[jedis-4.3.2.jar:na]
	at redis.clients.jedis.DefaultJedisSocketFactory.createSocket(DefaultJedisSocketFactory.java:87) ~[jedis-4.3.2.jar:na]
	at redis.clients.jedis.Connection.connect(Connection.java:180) ~[jedis-4.3.2.jar:na]
	at redis.clients.jedis.Connection.initializeFromClientConfig(Connection.java:338) ~[jedis-4.3.2.jar:na]
	at redis.clients.jedis.Connection.<init>(Connection.java:53) ~[jedis-4.3.2.jar:na]
	at redis.clients.jedis.Jedis.<init>(Jedis.java:214) ~[jedis-4.3.2.jar:na]
	at redis.clients.jedis.JedisFactory.makeObject(JedisFactory.java:181) ~[jedis-4.3.2.jar:na]
	at org.apache.commons.pool2.impl.GenericObjectPool.create(GenericObjectPool.java:571) ~[commons-pool2-2.11.1.jar:2.11.1]
	at org.apache.commons.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:298) ~[commons-pool2-2.11.1.jar:2.11.1]
	at org.apache.commons.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:223) ~[commons-pool2-2.11.1.jar:2.11.1]
	at redis.clients.jedis.util.Pool.getResource(Pool.java:34) ~[jedis-4.3.2.jar:na]
	at redis.clients.jedis.JedisPool.getResource(JedisPool.java:373) ~[jedis-4.3.2.jar:na]
	at redis.clients.jedis.JedisPool.getResource(JedisPool.java:17) ~[jedis-4.3.2.jar:na]
	at org.springframework.data.redis.connection.jedis.JedisConnectionFactory.fetchJedisConnector(JedisConnectionFactory.java:262) ~[spring-data-redis-3.1.0.jar:3.1.0]
	... 26 common frames omitted
	Suppressed: java.net.ConnectException: Connection refused
		at java.base/sun.nio.ch.Net.pollConnect(Native Method) ~[na:na]
		at java.base/sun.nio.ch.Net.pollConnectNow(Net.java:672) ~[na:na]
		at java.base/sun.nio.ch.NioSocketImpl.timedFinishConnect(NioSocketImpl.java:549) ~[na:na]
		at java.base/sun.nio.ch.NioSocketImpl.connect(NioSocketImpl.java:597) ~[na:na]
		at java.base/java.net.SocksSocketImpl.connect(SocksSocketImpl.java:327) ~[na:na]
		at java.base/java.net.Socket.connect(Socket.java:633) ~[na:na]
		at redis.clients.jedis.DefaultJedisSocketFactory.connectToFirstSuccessfulHost(DefaultJedisSocketFactory.java:73) ~[jedis-4.3.2.jar:na]
		... 39 common frames omitted
	Suppressed: java.net.ConnectException: Connection refused
		at java.base/sun.nio.ch.Net.pollConnect(Native Method) ~[na:na]
		at java.base/sun.nio.ch.Net.pollConnectNow(Net.java:672) ~[na:na]
		at java.base/sun.nio.ch.NioSocketImpl.timedFinishConnect(NioSocketImpl.java:542) ~[na:na]
		at java.base/sun.nio.ch.NioSocketImpl.connect(NioSocketImpl.java:597) ~[na:na]
		at java.base/java.net.SocksSocketImpl.connect(SocksSocketImpl.java:327) ~[na:na]
		at java.base/java.net.Socket.connect(Socket.java:633) ~[na:na]
		at redis.clients.jedis.DefaultJedisSocketFactory.connectToFirstSuccessfulHost(DefaultJedisSocketFactory.java:73) ~[jedis-4.3.2.jar:na]
		... 39 common frames omitted

Upon restarting the Redis server, Jedis was unable to recover the connection, and the subscription simply stopped generating events (callbacks) to my MessageListener.

So, not all things are equal in the case, and you were not specific about what Redis client driver library you were using in your application to begin with. Were you using Lettuce or Jedis?

Also, to state this slightly differently, what would you expect Spring Data Redis to do in this case?

As I previously stated, this sort of disconnected/reconnected situation is precisely the responsibility of a driver.

[Lvbuqing]

I'm really sorry that I didn't describe it clearly before. I use Lettuce because it is the default driver.
What I hope is that when Redis restarts, the subscription will still continue, maybe this can be a default configuration option.
glad for your answer

[jxblum]

I just retested with Lettuce again, but I waited a little longer.

Either the Lettuce i.l.core.protocol.ConnectionWatchdog uses come sort of incremental backoff, or somewhere, down inside Spring Data Redis that I have not uncovered during testing, there is a backoff in play. I know the RedisMessageListenerContainer uses backoff when lazily registering listeners and subscribing to the topic channels.

It took ~1 minute for subscription to startup again after I let it encounter an Exception:

REDIS PUB/SUB [2023-08-06-23-58-01 - Jack Welch: "Change before you have to."]
...
..
.
2023-08-06T23:58:01.349-07:00  INFO 1918 --- [xecutorLoop-1-7] i.l.core.protocol.ConnectionWatchdog     : Reconnecting, last destination was localhost/127.0.0.1:6379
2023-08-06T23:58:01.349-07:00  INFO 1918 --- [xecutorLoop-1-8] i.l.core.protocol.ConnectionWatchdog     : Reconnecting, last destination was localhost/127.0.0.1:6379
2023-08-06T23:58:01.355-07:00  WARN 1918 --- [ioEventLoop-4-4] i.l.core.protocol.ConnectionWatchdog     : Cannot reconnect to [localhost/<unresolved>:6379]: Connection refused: localhost/127.0.0.1:6379
2023-08-06T23:58:01.355-07:00  WARN 1918 --- [ioEventLoop-4-3] i.l.core.protocol.ConnectionWatchdog     : Cannot reconnect to [localhost/<unresolved>:6379]: Connection refused: localhost/127.0.0.1:6379
2023-08-06T23:58:10.344-07:00  INFO 1918 --- [xecutorLoop-1-9] i.l.core.protocol.ConnectionWatchdog     : Reconnecting, last destination was localhost/<unresolved>:6379
2023-08-06T23:58:10.344-07:00  INFO 1918 --- [xecutorLoop-1-8] i.l.core.protocol.ConnectionWatchdog     : Reconnecting, last destination was localhost/<unresolved>:6379
2023-08-06T23:58:10.345-07:00  WARN 1918 --- [ioEventLoop-4-3] i.l.core.protocol.ConnectionWatchdog     : Cannot reconnect to [localhost/<unresolved>:6379]: Connection refused: localhost/127.0.0.1:6379
2023-08-06T23:58:10.345-07:00  WARN 1918 --- [ioEventLoop-4-4] i.l.core.protocol.ConnectionWatchdog     : Cannot reconnect to [localhost/<unresolved>:6379]: Connection refused: localhost/127.0.0.1:6379
2023-08-06T23:58:18.544-07:00  INFO 1918 --- [ecutorLoop-1-11] i.l.core.protocol.ConnectionWatchdog     : Reconnecting, last destination was localhost/<unresolved>:6379
2023-08-06T23:58:18.544-07:00  INFO 1918 --- [ecutorLoop-1-10] i.l.core.protocol.ConnectionWatchdog     : Reconnecting, last destination was localhost/<unresolved>:6379
2023-08-06T23:58:18.546-07:00  WARN 1918 --- [ioEventLoop-4-6] i.l.core.protocol.ConnectionWatchdog     : Cannot reconnect to [localhost/<unresolved>:6379]: Connection refused: localhost/127.0.0.1:6379
2023-08-06T23:58:18.546-07:00  WARN 1918 --- [ioEventLoop-4-5] i.l.core.protocol.ConnectionWatchdog     : Cannot reconnect to [localhost/<unresolved>:6379]: Connection refused: localhost/127.0.0.1:6379
2023-08-06T23:58:34.941-07:00  INFO 1918 --- [ecutorLoop-1-12] i.l.core.protocol.ConnectionWatchdog     : Reconnecting, last destination was localhost/<unresolved>:6379
2023-08-06T23:58:34.941-07:00  INFO 1918 --- [xecutorLoop-1-1] i.l.core.protocol.ConnectionWatchdog     : Reconnecting, last destination was localhost/<unresolved>:6379
2023-08-06T23:58:34.943-07:00  WARN 1918 --- [ioEventLoop-4-8] i.l.core.protocol.ConnectionWatchdog     : Cannot reconnect to [localhost/<unresolved>:6379]: Connection refused: localhost/127.0.0.1:6379
2023-08-06T23:58:34.943-07:00  WARN 1918 --- [ioEventLoop-4-7] i.l.core.protocol.ConnectionWatchdog     : Cannot reconnect to [localhost/<unresolved>:6379]: Connection refused: localhost/127.0.0.1:6379
2023-08-06T23:59:04.076-07:00 ERROR 1918 --- [   scheduling-1] o.s.s.s.TaskUtils$LoggingErrorHandler    : Unexpected error occurred in scheduled task

org.springframework.dao.QueryTimeoutException: Redis command timed out
	at org.springframework.data.redis.connection.lettuce.LettuceExceptionConverter.convert(LettuceExceptionConverter.java:68) ~[spring-data-redis-3.1.0.jar:3.1.0]
	at org.springframework.data.redis.connection.lettuce.LettuceExceptionConverter.convert(LettuceExceptionConverter.java:41) ~[spring-data-redis-3.1.0.jar:3.1.0]
	at org.springframework.data.redis.PassThroughExceptionTranslationStrategy.translate(PassThroughExceptionTranslationStrategy.java:40) ~[spring-data-redis-3.1.0.jar:3.1.0]
	at org.springframework.data.redis.FallbackExceptionTranslationStrategy.translate(FallbackExceptionTranslationStrategy.java:38) ~[spring-data-redis-3.1.0.jar:3.1.0]
	at org.springframework.data.redis.connection.lettuce.LettuceConnection.convertLettuceAccessException(LettuceConnection.java:248) ~[spring-data-redis-3.1.0.jar:3.1.0]
	at org.springframework.data.redis.connection.lettuce.LettuceConnection.await(LettuceConnection.java:961) ~[spring-data-redis-3.1.0.jar:3.1.0]
	at org.springframework.data.redis.connection.lettuce.LettuceConnection.lambda$doInvoke$4(LettuceConnection.java:818) ~[spring-data-redis-3.1.0.jar:3.1.0]
	at org.springframework.data.redis.connection.lettuce.LettuceInvoker$Synchronizer.invoke(LettuceInvoker.java:665) ~[spring-data-redis-3.1.0.jar:3.1.0]
	at org.springframework.data.redis.connection.lettuce.LettuceInvoker.just(LettuceInvoker.java:109) ~[spring-data-redis-3.1.0.jar:3.1.0]
	at org.springframework.data.redis.connection.lettuce.LettuceConnection.publish(LettuceConnection.java:621) ~[spring-data-redis-3.1.0.jar:3.1.0]
	at org.springframework.data.redis.core.RedisTemplate.lambda$convertAndSend$29(RedisTemplate.java:953) ~[spring-data-redis-3.1.0.jar:3.1.0]
	at org.springframework.data.redis.core.RedisTemplate.execute(RedisTemplate.java:406) ~[spring-data-redis-3.1.0.jar:3.1.0]
	at org.springframework.data.redis.core.RedisTemplate.execute(RedisTemplate.java:373) ~[spring-data-redis-3.1.0.jar:3.1.0]
	at org.springframework.data.redis.core.RedisTemplate.convertAndSend(RedisTemplate.java:953) ~[spring-data-redis-3.1.0.jar:3.1.0]
	at io.vmware.spring.data.redis.pubsub.client.SpringRedisChatClientApplication.lambda$newRedisPublishingChatEventListener$1(SpringRedisChatClientApplication.java:70) ~[classes/:na]
	at example.chat.event.ChatEventPublisher.lambda$fire$0(ChatEventPublisher.java:40) ~[classes/:na]
	at java.base/java.util.concurrent.CopyOnWriteArrayList.forEach(CopyOnWriteArrayList.java:807) ~[na:na]
	at java.base/java.util.concurrent.CopyOnWriteArraySet.forEach(CopyOnWriteArraySet.java:425) ~[na:na]
	at example.chat.event.ChatEventPublisher.fire(ChatEventPublisher.java:40) ~[classes/:na]
	at example.chat.service.provider.EventDrivenChatService.send(EventDrivenChatService.java:45) ~[classes/:na]
	at example.chat.bot.provider.FamousQuotesChatBot.sendChat(FamousQuotesChatBot.java:223) ~[classes/:na]
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:na]
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77) ~[na:na]
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:na]
	at java.base/java.lang.reflect.Method.invoke(Method.java:568) ~[na:na]
	at org.springframework.scheduling.support.ScheduledMethodRunnable.run(ScheduledMethodRunnable.java:84) ~[spring-context-6.0.9.jar:6.0.9]
	at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54) ~[spring-context-6.0.9.jar:6.0.9]
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539) ~[na:na]
	at java.base/java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) ~[na:na]
	at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) ~[na:na]
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) ~[na:na]
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) ~[na:na]
	at java.base/java.lang.Thread.run(Thread.java:833) ~[na:na]
Caused by: io.lettuce.core.RedisCommandTimeoutException: Command timed out after 1 minute(s)
	at io.lettuce.core.internal.ExceptionFactory.createTimeoutException(ExceptionFactory.java:59) ~[lettuce-core-6.2.4.RELEASE.jar:6.2.4.RELEASE]
	at io.lettuce.core.internal.Futures.awaitOrCancel(Futures.java:246) ~[lettuce-core-6.2.4.RELEASE.jar:6.2.4.RELEASE]
	at io.lettuce.core.LettuceFutures.awaitOrCancel(LettuceFutures.java:74) ~[lettuce-core-6.2.4.RELEASE.jar:6.2.4.RELEASE]
	at org.springframework.data.redis.connection.lettuce.LettuceConnection.await(LettuceConnection.java:959) ~[spring-data-redis-3.1.0.jar:3.1.0]
	... 27 common frames omitted

2023-08-06T23:59:05.044-07:00  INFO 1918 --- [xecutorLoop-1-1] i.l.core.protocol.ConnectionWatchdog     : Reconnecting, last destination was localhost/<unresolved>:6379
2023-08-06T23:59:05.044-07:00  INFO 1918 --- [xecutorLoop-1-2] i.l.core.protocol.ConnectionWatchdog     : Reconnecting, last destination was localhost/<unresolved>:6379
2023-08-06T23:59:05.046-07:00  WARN 1918 --- [oEventLoop-4-10] i.l.core.protocol.ConnectionWatchdog     : Cannot reconnect to [localhost/<unresolved>:6379]: Connection refused: localhost/127.0.0.1:6379
2023-08-06T23:59:05.046-07:00  WARN 1918 --- [ioEventLoop-4-9] i.l.core.protocol.ConnectionWatchdog     : Cannot reconnect to [localhost/<unresolved>:6379]: Connection refused: localhost/127.0.0.1:6379
2023-08-06T23:59:35.143-07:00  INFO 1918 --- [ecutorLoop-1-11] i.l.core.protocol.ConnectionWatchdog     : Reconnecting, last destination was localhost/<unresolved>:6379
2023-08-06T23:59:35.143-07:00  INFO 1918 --- [ecutorLoop-1-12] i.l.core.protocol.ConnectionWatchdog     : Reconnecting, last destination was localhost/<unresolved>:6379
2023-08-06T23:59:35.145-07:00  WARN 1918 --- [oEventLoop-4-11] i.l.core.protocol.ConnectionWatchdog     : Cannot reconnect to [localhost/<unresolved>:6379]: Connection refused: localhost/127.0.0.1:6379
2023-08-06T23:59:35.145-07:00  WARN 1918 --- [oEventLoop-4-12] i.l.core.protocol.ConnectionWatchdog     : Cannot reconnect to [localhost/<unresolved>:6379]: Connection refused: localhost/127.0.0.1:6379


2023-08-07T00:00:04.084-07:00 ERROR 1918 --- [   scheduling-1] o.s.s.s.TaskUtils$LoggingErrorHandler    : Unexpected error occurred in scheduled task

org.springframework.dao.QueryTimeoutException: Redis command timed out
	at org.springframework.data.redis.connection.lettuce.LettuceExceptionConverter.convert(LettuceExceptionConverter.java:68) ~[spring-data-redis-3.1.0.jar:3.1.0]
	at org.springframework.data.redis.connection.lettuce.LettuceExceptionConverter.convert(LettuceExceptionConverter.java:41) ~[spring-data-redis-3.1.0.jar:3.1.0]
	at org.springframework.data.redis.PassThroughExceptionTranslationStrategy.translate(PassThroughExceptionTranslationStrategy.java:40) ~[spring-data-redis-3.1.0.jar:3.1.0]
	at org.springframework.data.redis.FallbackExceptionTranslationStrategy.translate(FallbackExceptionTranslationStrategy.java:38) ~[spring-data-redis-3.1.0.jar:3.1.0]
	at org.springframework.data.redis.connection.lettuce.LettuceConnection.convertLettuceAccessException(LettuceConnection.java:248) ~[spring-data-redis-3.1.0.jar:3.1.0]
	at org.springframework.data.redis.connection.lettuce.LettuceConnection.await(LettuceConnection.java:961) ~[spring-data-redis-3.1.0.jar:3.1.0]
	at org.springframework.data.redis.connection.lettuce.LettuceConnection.lambda$doInvoke$4(LettuceConnection.java:818) ~[spring-data-redis-3.1.0.jar:3.1.0]
	at org.springframework.data.redis.connection.lettuce.LettuceInvoker$Synchronizer.invoke(LettuceInvoker.java:665) ~[spring-data-redis-3.1.0.jar:3.1.0]
	at org.springframework.data.redis.connection.lettuce.LettuceInvoker.just(LettuceInvoker.java:109) ~[spring-data-redis-3.1.0.jar:3.1.0]
	at org.springframework.data.redis.connection.lettuce.LettuceConnection.publish(LettuceConnection.java:621) ~[spring-data-redis-3.1.0.jar:3.1.0]
	at org.springframework.data.redis.core.RedisTemplate.lambda$convertAndSend$29(RedisTemplate.java:953) ~[spring-data-redis-3.1.0.jar:3.1.0]
	at org.springframework.data.redis.core.RedisTemplate.execute(RedisTemplate.java:406) ~[spring-data-redis-3.1.0.jar:3.1.0]
	at org.springframework.data.redis.core.RedisTemplate.execute(RedisTemplate.java:373) ~[spring-data-redis-3.1.0.jar:3.1.0]
	at org.springframework.data.redis.core.RedisTemplate.convertAndSend(RedisTemplate.java:953) ~[spring-data-redis-3.1.0.jar:3.1.0]
	at io.vmware.spring.data.redis.pubsub.client.SpringRedisChatClientApplication.lambda$newRedisPublishingChatEventListener$1(SpringRedisChatClientApplication.java:70) ~[classes/:na]
	at example.chat.event.ChatEventPublisher.lambda$fire$0(ChatEventPublisher.java:40) ~[classes/:na]
	at java.base/java.util.concurrent.CopyOnWriteArrayList.forEach(CopyOnWriteArrayList.java:807) ~[na:na]
	at java.base/java.util.concurrent.CopyOnWriteArraySet.forEach(CopyOnWriteArraySet.java:425) ~[na:na]
	at example.chat.event.ChatEventPublisher.fire(ChatEventPublisher.java:40) ~[classes/:na]
	at example.chat.service.provider.EventDrivenChatService.send(EventDrivenChatService.java:45) ~[classes/:na]
	at example.chat.bot.provider.FamousQuotesChatBot.sendChat(FamousQuotesChatBot.java:223) ~[classes/:na]
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:na]
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77) ~[na:na]
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:na]
	at java.base/java.lang.reflect.Method.invoke(Method.java:568) ~[na:na]
	at org.springframework.scheduling.support.ScheduledMethodRunnable.run(ScheduledMethodRunnable.java:84) ~[spring-context-6.0.9.jar:6.0.9]
	at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54) ~[spring-context-6.0.9.jar:6.0.9]
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539) ~[na:na]
	at java.base/java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) ~[na:na]
	at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) ~[na:na]
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) ~[na:na]
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) ~[na:na]
	at java.base/java.lang.Thread.run(Thread.java:833) ~[na:na]
Caused by: io.lettuce.core.RedisCommandTimeoutException: Command timed out after 1 minute(s)
	at io.lettuce.core.internal.ExceptionFactory.createTimeoutException(ExceptionFactory.java:59) ~[lettuce-core-6.2.4.RELEASE.jar:6.2.4.RELEASE]
	at io.lettuce.core.internal.Futures.awaitOrCancel(Futures.java:246) ~[lettuce-core-6.2.4.RELEASE.jar:6.2.4.RELEASE]
	at io.lettuce.core.LettuceFutures.awaitOrCancel(LettuceFutures.java:74) ~[lettuce-core-6.2.4.RELEASE.jar:6.2.4.RELEASE]
	at org.springframework.data.redis.connection.lettuce.LettuceConnection.await(LettuceConnection.java:959) ~[spring-data-redis-3.1.0.jar:3.1.0]
	... 27 common frames omitted

2023-08-07T00:00:05.242-07:00  INFO 1918 --- [xecutorLoop-1-4] i.l.core.protocol.ConnectionWatchdog     : Reconnecting, last destination was localhost/<unresolved>:6379
2023-08-07T00:00:05.242-07:00  INFO 1918 --- [xecutorLoop-1-5] i.l.core.protocol.ConnectionWatchdog     : Reconnecting, last destination was localhost/<unresolved>:6379
2023-08-07T00:00:05.247-07:00  INFO 1918 --- [ioEventLoop-4-1] i.l.core.protocol.ReconnectionHandler    : Reconnected to localhost/<unresolved>:6379
2023-08-07T00:00:05.247-07:00  INFO 1918 --- [ioEventLoop-4-2] i.l.core.protocol.ReconnectionHandler    : Reconnected to localhost/<unresolved>:6379
...
..
.
REDIS PUB/SUB [2023-08-07-00-00-05 - Samuel Beckett: "We are all born mad. Some remain so."]

You can see the timestamps in the output, but the subscription eventually started back up again.

[Lvbuqing]

ok give me a few minutes and i'll verify right away

[jxblum]

I am in the PDT timezone (US Westcoast), and it is 12:11 AM here, so I will be signing off shortly.

Feel free to post any interesting things you might uncover, and I can continue to investigate this more tomorrow. I am not going to do anything with this ticket until I can touch base with the team, first.

FYI, most of driver (connection) recovery options, including the backoff recovery option for the RedisMessageListenerContainer in Spring Data Redis, are configurable using Spring Boot, Spring Data Redis, or the Lettuce client driver directly, if necessary.

The command timeout is configurable from the connection factory (i.e. LettuceConnectionFactory), using (Lettuce) TimeoutOptions in the (Lettuce) ClientOptions encapsulated by the Spring Data Redis LettuceClientConfigurationBuilder.

[Lvbuqing]

I did receive the log that the connection was successful, as I said in the description above, but, after restarting, after waiting for several minutes, my KeyExpirationEventMessageListener still could not receive the new expired key

[jxblum]

Hmm, tomorrow (err, later today), I will change my test arrangement slightly to use a KeyExpirationEventMessageListener and see what I find.

[Lvbuqing]

Good night, I am here at 15:23:08 on August 7, 2023, Beijing time, and I look forward to continuing the discussion tomorrow