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

[jxblum]

I just had 1 more quick thought...

Redis is not a persistent store (i.e. Redis stores everything in memory by default; no data is written to disk), and on restart, there would be no data initially, not unless you are using a clustered, highly available (HA) configuration (like Redis Cluster or Sentinel), along with a GII (perhaps). So, wouldn't the server not have any data (keys) on restart to begin with, not unless your application is already generating new keys with an expiration after restart (e.g. using SET myKey myValue EX 2, or similar command)?

If there is no data, or existing keys, there would be no expiration and no message listener to trigger.

Sorry, I am just thinking out loud and probably need to sleep on this. Will run some more tests tomorrow.

[Lvbuqing]

That's right, my Redis is stand-alone. I manually create a new key, give it an expiration time, and then test that I restart Redis after seeing the expired message on the console. After Redis restarts successfully, I will create a new key with an expiration time, and find that the console does not The corresponding log output, according to your description, takes about one minute to successfully connect. I have created an expired key many times and tested it for about 3 to 5 minutes, but I still cannot receive it. You can rest first, we will see tomorrow, the body is the most important

[jxblum]

Quick update...

I switched my example/test application to generate key/values with expiration (scheduled) and listen for RedisKeyExpiredEvents.

TIP: I noticed in your configuration (above) that your custom Spring bean/component RedisKeyExpiredListener containing the @EventListener, RedisKeyExpiredEvent handler method extends the SD Redis KeyExpirationEventMessagListener class, which is technically unnecessary. Although, it won't solve the problem, the configuration might be better arranged as follows, keeping the SD Redis infrastructure classes separate from your application classes with focus on handling expired Redis keys. Overall, there is a lot going on in your RedisKeyExpiredListener class: registering SD (Redis) Repositories, serving as a Spring @Configuration class, etc.

I managed to successfully reproduce the problem:

...
..
.
2023-08-07T14:10:45.599-07:00  INFO 58710 --- [   scheduling-1] i.v.s.d.r.p.c.d.RedisKeyValueGenerator   
: KEY [key13] VALUE [36143838-5e86-42c4-b7b9-c3cc6d6f3457] with EXPIRATION [PT1S]

2023-08-07T14:10:45.608-07:00  WARN 58710 --- [nerContainer-12] d.r.p.c.e.ExpiringRedisKeysEventListener 
: KEY [key12] expired

2023-08-07T14:10:45.856-07:00  INFO 58710 --- [xecutorLoop-1-7] i.l.core.protocol.ConnectionWatchdog     
: Reconnecting, last destination was localhost/127.0.0.1:6379

2023-08-07T14:10:45.856-07:00  INFO 58710 --- [xecutorLoop-1-6] i.l.core.protocol.ConnectionWatchdog     
: Reconnecting, last destination was localhost/127.0.0.1:6379

2023-08-07T14:10:45.863-07:00  WARN 58710 --- [ioEventLoop-4-3] i.l.core.protocol.ConnectionWatchdog     
: Cannot reconnect to [localhost/<unresolved>:6379]: Connection refused: localhost/127.0.0.1:6379

2023-08-07T14:10:45.863-07:00  WARN 58710 --- [ioEventLoop-4-4] i.l.core.protocol.ConnectionWatchdog     
: Cannot reconnect to [localhost/<unresolved>:6379]: Connection refused: localhost/127.0.0.1:6379

2023-08-07T14:10:46.600-07:00  INFO 58710 --- [   scheduling-1] i.v.s.d.r.p.c.d.RedisKeyValueGenerator   
: KEY [key14] VALUE [e498ebe4-8285-4356-ad15-574b23ec0fa2] with EXPIRATION [PT1S]

2023-08-07T14:10:54.854-07:00  INFO 58710 --- [xecutorLoop-1-7] i.l.core.protocol.ConnectionWatchdog     
: Reconnecting, last destination was localhost/<unresolved>:6379

2023-08-07T14:10:54.854-07:00  INFO 58710 --- [xecutorLoop-1-8] i.l.core.protocol.ConnectionWatchdog     
: Reconnecting, last destination was localhost/<unresolved>:6379

2023-08-07T14:10:54.860-07:00  INFO 58710 --- [ioEventLoop-4-3] i.l.core.protocol.ReconnectionHandler    
: Reconnected to localhost/<unresolved>:6379

2023-08-07T14:10:54.860-07:00  INFO 58710 --- [   scheduling-1] i.v.s.d.r.p.c.d.RedisKeyValueGenerator   
: KEY [key15] VALUE [0083fd07-143f-45cc-b491-179f3205d1d8] with EXPIRATION [PT1S]

2023-08-07T14:10:54.860-07:00  INFO 58710 --- [ioEventLoop-4-4] i.l.core.protocol.ReconnectionHandler    
: Reconnected to localhost/<unresolved>:6379

2023-08-07T14:10:54.861-07:00  INFO 58710 --- [   scheduling-1] i.v.s.d.r.p.c.d.RedisKeyValueGenerator   
: KEY [key16] VALUE [8ae9c614-637e-450d-8864-f89ff2140be9] with EXPIRATION [PT1S]

2023-08-07T14:10:54.862-07:00  INFO 58710 --- [   scheduling-1] i.v.s.d.r.p.c.d.RedisKeyValueGenerator   
: KEY [key17] VALUE [23608c50-9e42-4b75-9e28-dac2749fd2c2] with EXPIRATION [PT1S]

2023-08-07T14:10:54.864-07:00  INFO 58710 --- [   scheduling-1] i.v.s.d.r.p.c.d.RedisKeyValueGenerator   
: KEY [key18] VALUE [b443ccfe-94d4-4f01-b44d-df7b4b399dd4] with EXPIRATION [PT1S]
...
..
.

As you can see, there are no more RedisKeyExpiredEvents being logged after the Redis server is restarted and the Spring application successfully reconnects.

This is precisely your situation.

[jxblum]

I need to do some additional testing, but I think the problem boils down to the fact that the SD Redis KeyExpirationEventMessageListener class only gets initialized (calling, init()) on application startup (as it should), and not reinitialized (in effect) when the Redis server connection is lost and subsequently reestablished due to a Redis server or network issue.

The reason this is important is because the KeyExpirationEventMessageListener (and extension of the SD Redis KeyspaceEventMessageListener) sends configuration to the Redis server to notify on keyspace events (such as key expired events) during initialization.

This configuration is applied to the Redis server by getting a Redis connection from the RedisConnectionFactory configured on the RedisMessageListenerContainer. The Redis connection is opened, Redis server configuration for "notify-keyspace-events" is applied, and then the connection is closed. That is it; one and done.

Therefore, this configuration is only applied once in the Spring container lifecycle callback (i.e. InitializingBean.afterPropertiesSet()) when the application starts up. So, on Redis server restart, the server knows nothing about the (previous) configuration for "notify-keyspace-events".

The real question is whether this should be applied by the application, or be a configuration option for the Redis server itself.

The problem with it being application-specific is that you may deploy multiple instances of the applications (redundancy for high availability or fault tolerance), all of which will attempt to config "notify-keyspace-events", when technically, only 1 application instance need do so. Therefore, it would be better to do so at the Redis server or servers.

[jxblum]

There are a couple of solutions to this problem that involves a manual workaround.

The first thing I tried that worked was:

1. Start my Spring Boot application.

2. Let the app generate keys and handle (log) key expired events:

2023-08-07T17:17:05.667-07:00  INFO 80983 --- [           main] d.r.p.c.SpringRedisChatClientApplication 
: Started SpringRedisChatClientApplication in 1.957 seconds (process running for 2.287)

2023-08-07T17:17:05.676-07:00  INFO 80983 --- [   scheduling-1] i.v.s.d.r.p.c.d.RedisKeyValueGenerator   
: KEY [key1] VALUE [65796e16-e619-4abe-b957-9b876cf1080e] with EXPIRATION [PT1S]

2023-08-07T17:17:06.668-07:00  INFO 80983 --- [   scheduling-1] i.v.s.d.r.p.c.d.RedisKeyValueGenerator   
: KEY [key2] VALUE [fdf9a80f-9692-4a74-9c28-5a2dac6d6f4c] with EXPIRATION [PT1S]

2023-08-07T17:17:06.720-07:00  WARN 80983 --- [enerContainer-1] d.r.p.c.e.ExpiringRedisKeysEventListener 
: Key [key1] Expired

2023-08-07T17:17:07.669-07:00  INFO 80983 --- [   scheduling-1] i.v.s.d.r.p.c.d.RedisKeyValueGenerator   :
 KEY [key3] VALUE [9848784b-ef95-40fb-b9b3-16aa43a2392e] with EXPIRATION [PT1S]

2023-08-07T17:17:07.727-07:00  WARN 80983 --- [enerContainer-2] d.r.p.c.e.ExpiringRedisKeysEventListener 
: Key [key2] Expired
...
..
.

3. Kill (CTRL-C) the Redis server, causing the failed connection event to be logged by the application:

2023-08-07T17:17:11.979-07:00  INFO 80983 --- [xecutorLoop-1-1] i.l.core.protocol.ConnectionWatchdog     : Reconnecting, last destination was localhost/127.0.0.1:6379

2023-08-07T17:17:11.979-07:00  INFO 80983 --- [ecutorLoop-1-12] i.l.core.protocol.ConnectionWatchdog     : Reconnecting, last destination was localhost/127.0.0.1:6379

2023-08-07T17:17:11.985-07:00  WARN 80983 --- [ioEventLoop-4-3] i.l.core.protocol.ConnectionWatchdog     : Cannot reconnect to [localhost/<unresolved>:6379]: Connection refused: localhost/127.0.0.1:6379
...
..
.

4. Then, restart the Redis server; again, this reconnect event is logged by the application:

2023-08-07T17:17:21.076-07:00  INFO 80983 --- [xecutorLoop-1-2] i.l.core.protocol.ConnectionWatchdog     
: Reconnecting, last destination was localhost/<unresolved>:6379

2023-08-07T17:17:21.076-07:00  INFO 80983 --- [xecutorLoop-1-1] i.l.core.protocol.ConnectionWatchdog     
: Reconnecting, last destination was localhost/<unresolved>:6379

2023-08-07T17:17:21.081-07:00  INFO 80983 --- [ioEventLoop-4-3] i.l.core.protocol.ReconnectionHandler    
: Reconnected to localhost/<unresolved>:6379

2023-08-07T17:17:21.081-07:00  INFO 80983 --- [   scheduling-1] i.v.s.d.r.p.c.d.RedisKeyValueGenerator   
: KEY [key9] VALUE [357a3de4-2602-4fc4-97bf-6c8c2a266b4e] with EXPIRATION [PT1S]

2023-08-07T17:17:21.081-07:00  INFO 80983 --- [ioEventLoop-4-4] i.l.core.protocol.ReconnectionHandler    
: Reconnected to localhost/<unresolved>:6379
...
..
.

5. The app then continues to store keys with expiration in the Redis server as before, but does NOT log any key expiration events due to explicit, but missing Redis server keyspace notification configuration:

2023-08-07T17:17:21.082-07:00  INFO 80983 --- [   scheduling-1] i.v.s.d.r.p.c.d.RedisKeyValueGenerator   
: KEY [key10] VALUE [35ebd3c0-dd93-423c-b3c5-fed654c68a4b] with EXPIRATION [PT1S]

2023-08-07T17:17:21.083-07:00  INFO 80983 --- [   scheduling-1] i.v.s.d.r.p.c.d.RedisKeyValueGenerator   
: KEY [key11] VALUE [dfa511e5-7901-4843-a66c-6b7c793e38ab] with EXPIRATION [PT1S]

2023-08-07T17:17:21.084-07:00  INFO 80983 --- [   scheduling-1] i.v.s.d.r.p.c.d.RedisKeyValueGenerator   
: KEY [key12] VALUE [79a8ae48-7bbd-4470-86d2-94f98e00b2a4] with EXPIRATION [PT1S]
...
..
.

6. Using the redis-cli, manually apply the necessary configuration to the Redis server to send notification on keyspace events (the same as applied by Spring Data Redis's KeyExpirationEventMessageListener, this and this):

127.0.0.1:6379> config set notify-keyspace-events EA
OK

7. After this configuration is applied to the Redis server using the redis-cli, the application then resumes receiving key expiration events as before:

2023-08-07T17:18:44.666-07:00  INFO 80983 --- [   scheduling-1] i.v.s.d.r.p.c.d.RedisKeyValueGenerator   
: KEY [key100] VALUE [1b302389-e50d-4f73-8129-9a6f1ffa0d1a] with EXPIRATION [PT1S]

2023-08-07T17:18:44.711-07:00  WARN 80983 --- [enerContainer-7] d.r.p.c.e.ExpiringRedisKeysEventListener 
: Key [key99] Expired

2023-08-07T17:18:45.667-07:00  INFO 80983 --- [   scheduling-1] i.v.s.d.r.p.c.d.RedisKeyValueGenerator   
: KEY [key101] VALUE [6854e128-9bf0-446d-9122-57d00cb93237] with EXPIRATION [PT1S]

2023-08-07T17:18:45.718-07:00  WARN 80983 --- [enerContainer-8] d.r.p.c.e.ExpiringRedisKeysEventListener 
: Key [key100] Expired

2023-08-07T17:18:46.670-07:00  INFO 80983 --- [   scheduling-1] i.v.s.d.r.p.c.d.RedisKeyValueGenerator   
: KEY [key102] VALUE [a2de8680-300f-4bea-9660-755817a71310] with EXPIRATION [PT1S]

2023-08-07T17:18:46.725-07:00  WARN 80983 --- [enerContainer-9] d.r.p.c.e.ExpiringRedisKeysEventListener 
: Key [key101] Expired
...
..
.

Of course, you can prevent any lapse in key expiration event notification if the configuration is applied directly to the Redis server itself, in the redis.conf file.

TIP: See the Redis documentation for more details.

In the meantime, I will need to speak with @mp911de and/or @christophstrobl on what, if anything, we may want the Spring Data Redis framework to handle.

[jxblum]

1 last thing...

I ran 1 last test, by including a custom redis.conf file in my project to test the direct configuration of the Redis server to notify on keyspace events, such as key expiration (see here).

I then started the Redis server with:

$ redis-6.2.8/src/redis-server <absolute-path-to>/redis-experiments/spring-data-redis-experiments/src/main/resources/redis.conf

Where <absolute-path-to> is the home directory of my redis-experiments project working directory.

Of course, you can simply change the default configuration of Redis in the redis-6.2.8/redis.conf file (for whatever version of Redis you are running), but I prefer to keep custom configuration separate (and managed, in source control along with the application source that depends on the precise Redis server configuration).

This resulted in key expiration events been sent immediately after the Redis server was restarted.

[Lvbuqing]

Do I need to get the Redis reconnection event, and then call KeyspaceEventMessageListener.init() to meet my needs?

[mp911de]

Ideally, your server is already configured at startup with the appropriate notify-keyspace-events setting. Spring Data Redis' KeyspaceEventMessageListener.init() is only meant for development purposes so that you can get started easier within a development environment. It isn't meant for production usage.

[Lvbuqing]

Ideally, your server is already configured at startup with the appropriate notify-keyspace-events setting. Spring Data Redis' KeyspaceEventMessageListener.init() is only meant for development purposes so that you can get started easier within a development environment. It isn't meant for production usage.

Can such a mechanism be added?
In the case of not restarting the application, in the case of disconnection and reconnection, perform the operation performed for the first start, so as to avoid the problem that the data cannot be obtained after restarting the Redis service

[mp911de]

No and we do not want to evolve around a feature that needs to be addressed on a different level. Database restarts aren't within the scope of what Spring Data Redis handles. It is an infrastructure concern that must be provided by your platform.

[Lvbuqing]

No and we do not want to evolve around a feature that needs to be addressed on a different level. Database restarts aren't within the scope of what Spring Data Redis handles. It is an infrastructure concern that must be provided by your platform.

can you provide a solution to the problem

[mp911de]

Sure.
Specificy the notify-keyspace-events settings in your redis.conf and configure your Redis Server to run with the configuration.

[Lvbuqing]

Sure. Specificy the notify-keyspace-events settings in your redis.conf and configure your Redis Server to run with the configuration.

The premise of my question is that the notify-keyspace-events Ex of redis.conf has been configured

[mp911de]

Thanks for pointing this out as I was under the impression that you were asking for re-applying the notification config after reconnect.

Another aspect plays into this as well. When restarting the Redis service that loads data from a RDB file, then Redis quite early expires keys. At that time, Lettuce or the general RedisMessagingListenerContainer might have not yet been reconnected. In such a case, the early expirations are not delivered because no listener has reconnected.

Related, on a network partition, where Redis remains functional but the application gets disconnected for a while, the application doesn't receive expiration messages while Redis expires keys. Both are problems that we cannot solve.

From the entire discussion, is there still something to do here or that we can help you with or can we close this ticket?

[Lvbuqing]

Thanks for pointing this out as I was under the impression that you were asking for re-applying the notification config after reconnect.

Another aspect plays into this as well. When restarting the Redis service that loads data from a RDB file, then Redis quite early expires keys. At that time, Lettuce or the general RedisMessagingListenerContainer might have not yet been reconnected. In such a case, the early expirations are not delivered because no listener has reconnected.

Related, on a network partition, where Redis remains functional but the application gets disconnected for a while, the application doesn't receive expiration messages while Redis expires keys. Both are problems that we cannot solve.

From the entire discussion, is there still something to do here or that we can help you with or can we close this ticket?

This is not the case, as I mentioned above, what I said is that after restarting redis, create an expired key, and the RedisMessagingListenerContainer listener cannot receive the newly added key of the redis service after restarting.
You can test it. After restarting redis, add an expired key again. You will find that unless the application is restarted, you will not receive any key expiration events.

[jxblum]

@Lvbuqing - Regarding:

can you provide a solution to the problem

Again, see my earlier comments above, here and here.

Regarding:

This is not the case, as I mentioned above, what I said is that after restarting redis, create an expired key, and the RedisMessagingListenerContainer listener cannot receive the newly added key of the redis service after restarting.
You can test it. After restarting redis, add an expired key again. You will find that unless the application is restarted, you will not receive any key expiration events.

But it does, and it will.

Using the solutions I presented above, which I thoroughly tested, you will get your UC to work.

1. You will NOT need to restart your Spring [Boot] Data Redis application

2. And, you WILL start receiving (key expired) events (again) for the new keys you add with expiration after the Redis server comes back online and your application reconnects.

Fortunately, the Lettuce driver includes a Watchdog service that enables your application to reconnect, unlike Jedis. So, you must use Lettuce (as you have been doing).

The correct way to configure your Redis server is by setting notify-keyspace-events EA in a "custom" redis.conf file (like this) that you then pass to the Redis server when starting.

$ redis-6.2.8/src/redis-server <absolute-path-to>/custom/redis.conf

Subsequently, you can also manage this "custom" redis.conf file in source control along with the application source depending on this specific Redis configuration, which differs from the default settings for Redis (e.g. notify-keyspace-events is disabled by default).

[jxblum]

1 last thing...

It is not appropriate for your (Spring Data Redis) application to send this configuration to the Redis server, for several reasons:

1. First, if you have 100 instances of your application deployed for redundancy (HA, fault tolerance, etc), then all 100 instances are going to send this configuration command to the Redis server when you declare the SD Redis KeyExpirationEventMessageListener in your Spring application configuration. Imagine if you have 1,000 app instances, or 10,000. Only 1 app instance need send this command.

2. Second, what if the individual application instances vary in configuration slightly (using different Spring profiles), by region of customers your app instances serve. Some set notify-keyspace-events to EA, others to a different value (e.g. Km). There are a range of values you can use for notify-keyspace-events.

3. Following onto #2, it is more likely that multiple different applications are all connecting to and sharing a single data source (Redis server(s)). Each "different" application might have different requirements (specification) for the notify-keyspace-events Redis conf property. What takes precedence? Who decides?

In summary, I question:

1. Why this configuration for the Redis server was even added to Spring Data Redis (i.e. the KeyExpirationEventMessageListener component) to begin with...

2. And, why it is basically enabled by default (this, and then this).

As @mp911de stated already, this is both an infrastructure (i.e. "data management policy") and application concern. The framework definitely should not be deciding in this case, no matter how "convenient".

[Lvbuqing]

According to your operation, restart the Redis service process and execute the command: config set notify-keyspace-events EA.
I do get the key expired event without restarting the app.
However, this configuration has already been configured in my Redis.conf configuration, as shown in the figure:

Why do I still have to execute the above command after restarting? I am a bit confused here, I hope jxblum can help me analyze it, thank you

[jxblum]

Hmm, are you certain that the modifiedredis.conf file (in your image) is being used when you (re)start your Redis server?

During my testing, when I customized the redis.conf file by setting the notify-keyspace-events configuration property to EA and then (re)starting my Redis server with this custom redis.conf file, it took a few seconds, but eventually my Spring Boot/Data Redis application started receiving key expired events again.

NOTE: In the redis.conf file shipped with a plain vanilla Redis server installation, the default value for notify-keyspace-events is empty, meaning notifications are disabled (see here).

I did NOT have to manually issue the Redis command > config set notify-keyspace-events EA from the redis-cli.

I retested with my application again, and I got the same results.

1. First, I start the Redis server with:

$ redis-server /Users/jblum/redis-experiments/spring-data-redis-experiments/src/main/resources/redis.conf 

54013:C 09 Aug 2023 11:54:26.453 # oO0OoO0OoO0Oo Redis is starting oO0OoO0OoO0Oo
54013:C 09 Aug 2023 11:54:26.453 # Redis version=6.2.8, bits=64, commit=00000000, modified=0, pid=54013, just started
54013:C 09 Aug 2023 11:54:26.453 # Configuration loaded
54013:M 09 Aug 2023 11:54:26.453 * Increased maximum number of open files to 10032 (it was originally set to 256).
54013:M 09 Aug 2023 11:54:26.453 * monotonic clock: POSIX clock_gettime
                _._                                                  
           _.-``__ ''-._                                             
      _.-``    `.  `_.  ''-._           Redis 6.2.8 (00000000/0) 64 bit
  .-`` .-```.  ```\/    _.,_ ''-._                                  
 (    '      ,       .-`  | `,    )     Running in standalone mode
 |`-._`-...-` __...-.``-._|'` _.-'|     Port: 6379
 |    `-._   `._    /     _.-'    |     PID: 54013
  `-._    `-._  `-./  _.-'    _.-'                                   
 |`-._`-._    `-.__.-'    _.-'_.-'|                                  
 |    `-._`-._        _.-'_.-'    |           https://redis.io       
  `-._    `-._`-.__.-'_.-'    _.-'                                   
 |`-._`-._    `-.__.-'    _.-'_.-'|                                  
 |    `-._`-._        _.-'_.-'    |                                  
  `-._    `-._`-.__.-'_.-'    _.-'                                   
      `-._    `-.__.-'    _.-'                                       
          `-._        _.-'                                           
              `-.__.-'                                               

54013:M 09 Aug 2023 11:54:26.455 # Server initialized
54013:M 09 Aug 2023 11:54:26.455 * Loading RDB produced by version 6.2.8
54013:M 09 Aug 2023 11:54:26.455 * RDB age 12 seconds
54013:M 09 Aug 2023 11:54:26.455 * RDB memory usage when created 1.02 Mb
54013:M 09 Aug 2023 11:54:26.455 # Done loading RDB, keys loaded: 0, keys expired: 1.
54013:M 09 Aug 2023 11:54:26.455 * DB loaded from disk: 0.000 seconds
54013:M 09 Aug 2023 11:54:26.455 * Ready to accept connections

2. Then, I run my Spring application from inside my IDE.

3. I kill the Redis server, wait a few seconds, and then restart it.

4. The complete Spring application log looks like follows (scroll to the right):

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

2023-08-09T11:54:08.308-07:00  INFO 54010 --- [           main] d.r.p.c.SpringRedisChatClientApplication : Starting SpringRedisChatClientApplication using Java 17.0.6 with PID 54010 (/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-09T11:54:08.311-07:00  INFO 54010 --- [           main] d.r.p.c.SpringRedisChatClientApplication : The following 1 profile is active: "generate-redis-keys-values"
2023-08-09T11:54:08.654-07:00  INFO 54010 --- [           main] .s.d.r.c.RepositoryConfigurationDelegate : Multiple Spring Data modules found, entering strict repository configuration mode
2023-08-09T11:54:08.655-07:00  INFO 54010 --- [           main] .s.d.r.c.RepositoryConfigurationDelegate : Bootstrapping Spring Data Redis repositories in DEFAULT mode.
2023-08-09T11:54:08.677-07:00  INFO 54010 --- [           main] .s.d.r.c.RepositoryConfigurationDelegate : Finished Spring Data repository scanning in 11 ms. Found 0 Redis repository interfaces.
2023-08-09T11:54:09.740-07:00  INFO 54010 --- [           main] d.r.p.c.SpringRedisChatClientApplication : Started SpringRedisChatClientApplication in 1.722 seconds (process running for 2.006)
2023-08-09T11:54:09.752-07:00  INFO 54010 --- [   scheduling-1] i.v.s.d.r.p.c.d.RedisKeyValueGenerator   : KEY [key1] VALUE [c0f8bef6-644e-4f3d-b004-60217187be5c] with EXPIRATION [PT1S]
2023-08-09T11:54:10.744-07:00  INFO 54010 --- [   scheduling-1] i.v.s.d.r.p.c.d.RedisKeyValueGenerator   : KEY [key2] VALUE [f17166d0-50ad-46b8-96c6-737622ab0185] with EXPIRATION [PT1S]
2023-08-09T11:54:10.819-07:00  WARN 54010 --- [enerContainer-1] d.r.p.c.e.ExpiringRedisKeysEventListener : Key [key1] Expired
2023-08-09T11:54:11.744-07:00  INFO 54010 --- [   scheduling-1] i.v.s.d.r.p.c.d.RedisKeyValueGenerator   : KEY [key3] VALUE [ebece36a-eacf-4ab4-8721-8aec88f56504] with EXPIRATION [PT1S]
2023-08-09T11:54:11.825-07:00  WARN 54010 --- [enerContainer-2] d.r.p.c.e.ExpiringRedisKeysEventListener : Key [key2] Expired
2023-08-09T11:54:12.739-07:00  INFO 54010 --- [   scheduling-1] i.v.s.d.r.p.c.d.RedisKeyValueGenerator   : KEY [key4] VALUE [1683446b-416a-4095-95f9-d21916abf13c] with EXPIRATION [PT1S]
2023-08-09T11:54:12.831-07:00  WARN 54010 --- [enerContainer-3] d.r.p.c.e.ExpiringRedisKeysEventListener : Key [key3] Expired
2023-08-09T11:54:13.743-07:00  INFO 54010 --- [   scheduling-1] i.v.s.d.r.p.c.d.RedisKeyValueGenerator   : KEY [key5] VALUE [dbe8cc56-8f28-4da8-ae51-cc0b500a5888] with EXPIRATION [PT1S]
2023-08-09T11:54:13.840-07:00  WARN 54010 --- [enerContainer-4] d.r.p.c.e.ExpiringRedisKeysEventListener : Key [key4] Expired
2023-08-09T11:54:14.294-07:00  INFO 54010 --- [xecutorLoop-1-9] i.l.core.protocol.ConnectionWatchdog     : Reconnecting, last destination was localhost/127.0.0.1:6379
2023-08-09T11:54:14.294-07:00  INFO 54010 --- [ecutorLoop-1-10] i.l.core.protocol.ConnectionWatchdog     : Reconnecting, last destination was localhost/127.0.0.1:6379
2023-08-09T11:54:14.301-07:00  WARN 54010 --- [ioEventLoop-4-3] i.l.core.protocol.ConnectionWatchdog     : Cannot reconnect to [localhost/<unresolved>:6379]: Connection refused: localhost/127.0.0.1:6379
2023-08-09T11:54:14.304-07:00  WARN 54010 --- [ioEventLoop-4-4] i.l.core.protocol.ConnectionWatchdog     : Cannot reconnect to [localhost/<unresolved>:6379]: Connection refused: localhost/127.0.0.1:6379
2023-08-09T11:54:14.739-07:00  INFO 54010 --- [   scheduling-1] i.v.s.d.r.p.c.d.RedisKeyValueGenerator   : KEY [key6] VALUE [e7c69559-7059-4cee-bd11-d379fc62ae01] with EXPIRATION [PT1S]
2023-08-09T11:54:23.389-07:00  INFO 54010 --- [ecutorLoop-1-10] i.l.core.protocol.ConnectionWatchdog     : Reconnecting, last destination was localhost/<unresolved>:6379
2023-08-09T11:54:23.389-07:00  INFO 54010 --- [ecutorLoop-1-11] i.l.core.protocol.ConnectionWatchdog     : Reconnecting, last destination was localhost/<unresolved>:6379
2023-08-09T11:54:23.391-07:00  WARN 54010 --- [ioEventLoop-4-4] i.l.core.protocol.ConnectionWatchdog     : Cannot reconnect to [localhost/<unresolved>:6379]: Connection refused: localhost/127.0.0.1:6379
2023-08-09T11:54:23.391-07:00  WARN 54010 --- [ioEventLoop-4-3] i.l.core.protocol.ConnectionWatchdog     : Cannot reconnect to [localhost/<unresolved>:6379]: Connection refused: localhost/127.0.0.1:6379
2023-08-09T11:54:31.597-07:00  INFO 54010 --- [ecutorLoop-1-12] i.l.core.protocol.ConnectionWatchdog     : Reconnecting, last destination was localhost/<unresolved>:6379
2023-08-09T11:54:31.597-07:00  INFO 54010 --- [xecutorLoop-1-1] i.l.core.protocol.ConnectionWatchdog     : Reconnecting, last destination was localhost/<unresolved>:6379
2023-08-09T11:54:31.603-07:00  INFO 54010 --- [ioEventLoop-4-5] i.l.core.protocol.ReconnectionHandler    : Reconnected to localhost/<unresolved>:6379
2023-08-09T11:54:31.604-07:00  INFO 54010 --- [   scheduling-1] i.v.s.d.r.p.c.d.RedisKeyValueGenerator   : KEY [key7] VALUE [9fae3b2a-8410-4ed6-9288-c90923c8376c] with EXPIRATION [PT1S]
2023-08-09T11:54:31.604-07:00  INFO 54010 --- [ioEventLoop-4-6] i.l.core.protocol.ReconnectionHandler    : Reconnected to localhost/<unresolved>:6379
2023-08-09T11:54:31.605-07:00  INFO 54010 --- [   scheduling-1] i.v.s.d.r.p.c.d.RedisKeyValueGenerator   : KEY [key8] VALUE [91372834-58cc-43e1-839f-86521d3ee84a] with EXPIRATION [PT1S]
2023-08-09T11:54:31.605-07:00  INFO 54010 --- [   scheduling-1] i.v.s.d.r.p.c.d.RedisKeyValueGenerator   : KEY [key9] VALUE [c3200a35-5ff6-4ee5-ae26-7c3668a28037] with EXPIRATION [PT1S]
2023-08-09T11:54:31.606-07:00  INFO 54010 --- [   scheduling-1] i.v.s.d.r.p.c.d.RedisKeyValueGenerator   : KEY [key10] VALUE [0abf28c4-66aa-4ce0-89a8-a75cfbfe5e4c] with EXPIRATION [PT1S]
2023-08-09T11:54:31.607-07:00  INFO 54010 --- [   scheduling-1] i.v.s.d.r.p.c.d.RedisKeyValueGenerator   : KEY [key11] VALUE [7320f891-3bb1-4cea-97d5-717b9e5a8df0] with EXPIRATION [PT1S]
2023-08-09T11:54:31.608-07:00  INFO 54010 --- [   scheduling-1] i.v.s.d.r.p.c.d.RedisKeyValueGenerator   : KEY [key12] VALUE [e4ced7fa-b2c3-4249-9fd6-26eb38c75fcd] with EXPIRATION [PT1S]
2023-08-09T11:54:31.609-07:00  INFO 54010 --- [   scheduling-1] i.v.s.d.r.p.c.d.RedisKeyValueGenerator   : KEY [key13] VALUE [557af73c-a639-488a-be4e-dc8b13feba0f] with EXPIRATION [PT1S]
2023-08-09T11:54:31.610-07:00  INFO 54010 --- [   scheduling-1] i.v.s.d.r.p.c.d.RedisKeyValueGenerator   : KEY [key14] VALUE [59597669-4bad-45f4-b864-4600aeafef6d] with EXPIRATION [PT1S]
2023-08-09T11:54:31.610-07:00  INFO 54010 --- [   scheduling-1] i.v.s.d.r.p.c.d.RedisKeyValueGenerator   : KEY [key15] VALUE [673936f6-7b0d-44b8-85b5-ae4e4494ea85] with EXPIRATION [PT1S]
2023-08-09T11:54:31.611-07:00  INFO 54010 --- [   scheduling-1] i.v.s.d.r.p.c.d.RedisKeyValueGenerator   : KEY [key16] VALUE [b296d640-8d4c-4121-9a35-abb947cbc4a6] with EXPIRATION [PT1S]
2023-08-09T11:54:31.612-07:00  INFO 54010 --- [   scheduling-1] i.v.s.d.r.p.c.d.RedisKeyValueGenerator   : KEY [key17] VALUE [d4260c54-6c3b-4ba4-a931-af7d676e5ba1] with EXPIRATION [PT1S]
2023-08-09T11:54:31.613-07:00  INFO 54010 --- [   scheduling-1] i.v.s.d.r.p.c.d.RedisKeyValueGenerator   : KEY [key18] VALUE [0f8cb03b-6b26-4ef3-ac10-4474c6710a8b] with EXPIRATION [PT1S]
2023-08-09T11:54:31.614-07:00  INFO 54010 --- [   scheduling-1] i.v.s.d.r.p.c.d.RedisKeyValueGenerator   : KEY [key19] VALUE [62e5b9de-4150-4b60-98a2-02207bb25919] with EXPIRATION [PT1S]
2023-08-09T11:54:31.614-07:00  INFO 54010 --- [   scheduling-1] i.v.s.d.r.p.c.d.RedisKeyValueGenerator   : KEY [key20] VALUE [be99d809-7ad8-454f-9341-41b3cec84b4a] with EXPIRATION [PT1S]
2023-08-09T11:54:31.615-07:00  INFO 54010 --- [   scheduling-1] i.v.s.d.r.p.c.d.RedisKeyValueGenerator   : KEY [key21] VALUE [50b4e7dd-721c-49aa-a6d4-b99afcda5e18] with EXPIRATION [PT1S]
2023-08-09T11:54:31.616-07:00  INFO 54010 --- [   scheduling-1] i.v.s.d.r.p.c.d.RedisKeyValueGenerator   : KEY [key22] VALUE [7013f0fd-b748-4bf7-9096-65cf057846da] with EXPIRATION [PT1S]
2023-08-09T11:54:31.749-07:00  INFO 54010 --- [   scheduling-1] i.v.s.d.r.p.c.d.RedisKeyValueGenerator   : KEY [key23] VALUE [155fbd54-635d-4331-acac-fe3dcf432c97] with EXPIRATION [PT1S]
2023-08-09T11:54:32.612-07:00  WARN 54010 --- [enerContainer-5] d.r.p.c.e.ExpiringRedisKeysEventListener : Key [key9] Expired
2023-08-09T11:54:32.612-07:00  WARN 54010 --- [enerContainer-6] d.r.p.c.e.ExpiringRedisKeysEventListener : Key [key6] Expired
2023-08-09T11:54:32.612-07:00  WARN 54010 --- [enerContainer-7] d.r.p.c.e.ExpiringRedisKeysEventListener : Key [key13] Expired
2023-08-09T11:54:32.613-07:00  WARN 54010 --- [enerContainer-8] d.r.p.c.e.ExpiringRedisKeysEventListener : Key [key12] Expired
2023-08-09T11:54:32.613-07:00  WARN 54010 --- [enerContainer-9] d.r.p.c.e.ExpiringRedisKeysEventListener : Key [key10] Expired
2023-08-09T11:54:32.614-07:00  WARN 54010 --- [nerContainer-10] d.r.p.c.e.ExpiringRedisKeysEventListener : Key [key8] Expired
2023-08-09T11:54:32.614-07:00  WARN 54010 --- [nerContainer-11] d.r.p.c.e.ExpiringRedisKeysEventListener : Key [key11] Expired
2023-08-09T11:54:32.614-07:00  WARN 54010 --- [nerContainer-12] d.r.p.c.e.ExpiringRedisKeysEventListener : Key [key7] Expired
2023-08-09T11:54:32.713-07:00  WARN 54010 --- [nerContainer-13] d.r.p.c.e.ExpiringRedisKeysEventListener : Key [key19] Expired
2023-08-09T11:54:32.713-07:00  WARN 54010 --- [nerContainer-14] d.r.p.c.e.ExpiringRedisKeysEventListener : Key [key16] Expired
2023-08-09T11:54:32.714-07:00  WARN 54010 --- [nerContainer-15] d.r.p.c.e.ExpiringRedisKeysEventListener : Key [key21] Expired
2023-08-09T11:54:32.715-07:00  WARN 54010 --- [nerContainer-16] d.r.p.c.e.ExpiringRedisKeysEventListener : Key [key20] Expired
2023-08-09T11:54:32.715-07:00  WARN 54010 --- [nerContainer-17] d.r.p.c.e.ExpiringRedisKeysEventListener : Key [key18] Expired
2023-08-09T11:54:32.715-07:00  WARN 54010 --- [nerContainer-18] d.r.p.c.e.ExpiringRedisKeysEventListener : Key [key14] Expired
2023-08-09T11:54:32.715-07:00  WARN 54010 --- [nerContainer-19] d.r.p.c.e.ExpiringRedisKeysEventListener : Key [key17] Expired
2023-08-09T11:54:32.716-07:00  WARN 54010 --- [nerContainer-20] d.r.p.c.e.ExpiringRedisKeysEventListener : Key [key22] Expired
2023-08-09T11:54:32.716-07:00  WARN 54010 --- [nerContainer-21] d.r.p.c.e.ExpiringRedisKeysEventListener : Key [key15] Expired
2023-08-09T11:54:32.751-07:00  INFO 54010 --- [   scheduling-1] i.v.s.d.r.p.c.d.RedisKeyValueGenerator   : KEY [key24] VALUE [0b7942ed-b0a8-45b4-9d03-26293abf6df2] with EXPIRATION [PT1S]
2023-08-09T11:54:32.813-07:00  WARN 54010 --- [nerContainer-22] d.r.p.c.e.ExpiringRedisKeysEventListener : Key [key23] Expired
2023-08-09T11:54:33.752-07:00  INFO 54010 --- [   scheduling-1] i.v.s.d.r.p.c.d.RedisKeyValueGenerator   : KEY [key25] VALUE [9c1a8187-316a-417b-8569-87cd3c4bd9eb] with EXPIRATION [PT1S]
2023-08-09T11:54:33.824-07:00  WARN 54010 --- [nerContainer-23] d.r.p.c.e.ExpiringRedisKeysEventListener : Key [key24] Expired
2023-08-09T11:54:34.750-07:00  INFO 54010 --- [   scheduling-1] i.v.s.d.r.p.c.d.RedisKeyValueGenerator   : KEY [key26] VALUE [59893cac-65f6-4eb8-bf09-f49162293d9f] with EXPIRATION [PT1S]
2023-08-09T11:54:34.831-07:00  WARN 54010 --- [nerContainer-24] d.r.p.c.e.ExpiringRedisKeysEventListener : Key [key25] Expired
2023-08-09T11:54:35.752-07:00  INFO 54010 --- [   scheduling-1] i.v.s.d.r.p.c.d.RedisKeyValueGenerator   : KEY [key27] VALUE [d73813cb-69e0-459d-a399-2a3e190fe426] with EXPIRATION [PT1S]
2023-08-09T11:54:35.840-07:00  WARN 54010 --- [nerContainer-25] d.r.p.c.e.ExpiringRedisKeysEventListener : Key [key26] Expired
2023-08-09T11:54:36.752-07:00  INFO 54010 --- [   scheduling-1] i.v.s.d.r.p.c.d.RedisKeyValueGenerator   : KEY [key28] VALUE [8dd02626-9c9b-4857-8260-da3590725eeb] with EXPIRATION [PT1S]
2023-08-09T11:54:36.852-07:00  WARN 54010 --- [nerContainer-26] d.r.p.c.e.ExpiringRedisKeysEventListener : Key [key27] Expired
2023-08-09T11:54:37.757-07:00  INFO 54010 --- [   scheduling-1] i.v.s.d.r.p.c.d.RedisKeyValueGenerator   : KEY [key29] VALUE [fa83d2d6-b2c7-48a8-b865-609209a50a4a] with EXPIRATION [PT1S]
2023-08-09T11:54:37.759-07:00  WARN 54010 --- [nerContainer-27] d.r.p.c.e.ExpiringRedisKeysEventListener : Key [key28] Expired
2023-08-09T11:54:38.757-07:00  INFO 54010 --- [   scheduling-1] i.v.s.d.r.p.c.d.RedisKeyValueGenerator   : KEY [key30] VALUE [b6b5b90d-0d5c-46c7-9cfb-51931a485868] with EXPIRATION [PT1S]
2023-08-09T11:54:38.767-07:00  WARN 54010 --- [nerContainer-28] d.r.p.c.e.ExpiringRedisKeysEventListener : Key [key29] Expired
2023-08-09T11:54:39.755-07:00  INFO 54010 --- [   scheduling-1] i.v.s.d.r.p.c.d.RedisKeyValueGenerator   : KEY [key31] VALUE [78af8414-57d4-46a6-81f5-af892fe39f61] with EXPIRATION [PT1S]
2023-08-09T11:54:39.774-07:00  WARN 54010 --- [nerContainer-29] d.r.p.c.e.ExpiringRedisKeysEventListener : Key [key30] Expired

Please note, this application log is precisely what I would expect to happen.

Feel free to give my example/test from the spring-data-redis-experiments module a try as well, and then compare with your application.

I also recommend you to explicitly pass the modified ("custom") redis.conf to the Redis server on start, as I have done above.

[Lvbuqing]

Many thanks to jxblum and mp911de for their help.
In this test, I used this Redis: https://github.com/microsoftarchive/redis/releases/tag/win-3.0.504
, is running directly on Windows, and the Redis-server operating environment is not Linux, which caused me to configure the properties of redis.conf, but it still does not take effect after restarting. I guess it is a version problem. I reinstalled Redis on Linux, and configured: notify-keyspace-events EA, and found that after restarting, I can continue to notify, I apologize again, it is my problem that delayed everyone's precious time

[jxblum]

Thank you for confirming, @Lvbuqing. I am happy you uncovered the underlying problem. Environment issues tend to be very allusive exactly like this.

I will close this ticket. However, if you find any related problems or other issues, feel free to file a new issue ticket.

Ultimately, I think it was a mistake in Spring Data Redis to ever allow the notify-keyspace-events to be set to any value other than empty, thereby enabling notifications. As such, I am going to strongly recommend we change such default settings to be opt-in, rather than opt-out, to avoid issues (and confusion) coming from the framework. Development-time settings should not be the default setting just because they are convenient while development.

Wishing you all the best.

[jxblum]

See #2670 and the corresponding PR, #2671.

[Jagden]

I solved it in the application by using the following code it will restart the listening phase and apply the psubscribe commands to the Redis connection once a connection was broken / terminated with Redis.

@Slf4j
@Component
@RequiredArgsConstructor
public class RedisSubscriberWatchdog {
    private boolean firstTime = false;
    private final RedisMessageListenerContainer redisMessageListenerContainer;

    @Scheduled(fixedDelay = 1000)
    public void check () {
        if (redisMessageListenerContainer.isListening()) {
            firstTime = true;
        }

        if (!redisMessageListenerContainer.isListening() && firstTime) {
            log.info("RedisSubscriberWatchdog identified that redis listener is down, restarting it.");

            redisMessageListenerContainer.stop(() -> {
                log.info("RedisSubscriberWatchdog stopped redis listener, restarting it.");
                try {
                    redisMessageListenerContainer.start();
                    log.info("RedisSubscriberWatchdog restarted redis listener.");
                } catch (Exception e) {
                    log.error("Failed to restart redis listener {}", e.getMessage());
                }
            });
        }
    }
}