Error while validating pooled Java object (java.util.ArrayList cannot be cast to [B)

[kchristidis]

(I am creating a new issue about this, as suggested.)

Dependencies

• spring-data-redis: 2.7.2
• jedis: 3.9.0 (but this also happens with 3.8.0)
• commons-pool2: 2.11.1

Configuration settings

• spring.redis.jedis.pool.max-active=60
• spring.redis.jedis.pool.max-idle=60
• spring.redis.jedis.pool.min-idle=10

What my code does

public void scan(RedisClusterNode redisClusterNode, RedisClusterConnection redisClusterConnection, int scanLimit) { // scanLimit = 50
    ScanOptions scanOptions = ScanOptions.scanOptions().count(scanLimit).build();
    try (Cursor<byte[]> cursor = redisClusterConnection.scan(redisClusterNode, scanOptions)) {
      do {
        cursor.next();
      } while (cursor.hasNext());
    }
  }

This is how I set the redisClusterNode and redisClousterConnection fields before I pass them to the function:

RedisConnection redisConnection = Objects.requireNonNull(stringRedisTemplate.getConnectionFactory()).getConnection();
if (redisConnection instanceof RedisClusterConnection) {
    RedisClusterConnection redisClusterConnection = Objects.requireNonNull(stringRedisTemplate.getConnectionFactory()).getClusterConnection();
    Iterable<RedisClusterNode> redisClusterNodes = redisClusterConnection.clusterGetNodes();
    StreamSupport.stream(redisClusterNodes.spliterator(), false).forEach(
        (redisClusterNode) -> { scan(redisClusterNode, redisClusterConnection, scanLimit);}
    );
} else {
// ...      
}

How things fail

Shortly after I invoke this method, I will get the following:

[redis.clients.jedis.JedisFactory] [commons-pool-evictor] ERROR - <<JedisFactory>> Error while validating pooled Jedis object.
java.lang.ClassCastException: java.util.ArrayList cannot be cast to [B
	at redis.clients.jedis.Connection.getStatusCodeReply(Connection.java:270) ~[jedis-3.8.0.jar:?]
	at redis.clients.jedis.BinaryJedis.ping(BinaryJedis.java:384) ~[jedis-3.8.0.jar:?]
	at redis.clients.jedis.JedisFactory.validateObject(JedisFactory.java:214) ~[jedis-3.8.0.jar:?]
	at org.apache.commons.pool2.impl.GenericObjectPool.evict(GenericObjectPool.java:745) ~[commons-pool2-2.11.1.jar:2.11.1]
	at org.apache.commons.pool2.impl.BaseGenericObjectPool$Evictor.run(BaseGenericObjectPool.java:160) ~[commons-pool2-2.11.1.jar:2.11.1]
	at org.apache.commons.pool2.impl.EvictionTimer$WeakRunner.run(EvictionTimer.java:113) ~[commons-pool2-2.11.1.jar:2.11.1]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) ~[?:1.8.0_362]
	at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) ~[?:1.8.0_362]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) ~[?:1.8.0_362]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) ~[?:1.8.0_362]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) ~[?:1.8.0_362]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) ~[?:1.8.0_362]
	at java.lang.Thread.run(Thread.java:750) ~[?:1.8.0_362]

The timing of this exception differs. Sometimes it shows up right away, sometimes it takes a few seconds (and iterations of the cursor).

Note that the size of the shard is big: ~90M keys.

Things I've tried successfully

1. Running against a much smaller cluster (each shard with hundreds of keys)

Things I've tried without success

1. Running with only one thread active in the pool.
2. Running with an unlimited number of idle threads in the pool.
3. Setting scanLimit to 1.

@mp911de suggested the following:

It sounds as if a cluster node connection was in use by two processes. I suggest monitoring JedisCluster's node connection pool (JedisClusterInfoCache.nodes) while your SCAN is in progress. The node in the ConnectionPool should remain acquired while your scan cursor remains open.

I've enabled breakpoints across the JedisClusterInfoCache class, and only see this method accessed by the thread that performs the scan. Then the commons-pool-evictor thread will kick in, and the exception above will surface.

So I'm afraid I'm still stuck here. Thanks in advance for any pointer you may have for me.

[kchristidis]

One more thing I've tried:

spring.redis.jedis.pool.enabled=false

Same failure.

[jxblum]

After reading through both Issue tickets, #2382 and now this one, #2517, I am unclear (and uncertain, yet?) how Spring Data Redis is the cause of this issue in this case.

DISCLAIMER: I am still learning about Redis in general, and Spring Data Redis in particular, especially the internals of both along with their behaviors, configurations and so on, so please forgive my ignorance here.

While it is possible Spring Data Redis is not properly taking into account some interaction in this case, on the surface, the issue appears to be Jedis driver related, and maybe something specifically to do with Jedis's use and/or configuration of Apache Commons Pool?

Some possible questions and ideas/thoughts:

1. Does your (transitive) dependency between Jedis and Apache Commons [Pool] align for certain? (Also see #5 below)

Of course, your reference to (commons-pool2: 2.11.1) and the Stack Trace seem to confirm this.

When I see Exceptions of the nature ClassCastExceptions, especially casting from java.util.ArrayList to [B (byte array) in this case, or ClassNotFoundExceptions / NoClassDefFoundErrors, or NoSuchMethodErrors, etc, I immediately suspect there may be an API incompatibility present.

<FLUFF>

As I am sure you are well aware, this often happens when projects declare and use the same transitive dependencies, either directly or indirectly, as other dependencies the project also declares and depends on. Your project depends on Jedis, which depends on Apache Commons Pool. Does your project directly depend on Apache Commons Pool in some other capacity? Does your project perhaps indirectly depend on Apache Commons Pool, such as through another Apache project (e.g. DBCP) that also depends on Apache Commons Pool?

Symbolically, this can be represented as, given project A, and dependencies [ B, C, D], you can run into conflicts in the following situation: A -> B -> D and A -> C -> D'. When B and C's shared transitive dependency on D does not align, then conflicts can occur.

</FLUFF>

To confirm, it does appear Spring Boot manages the Apache Commons Pool dependencies, and specifically commons-pool2, set to 2.11.1.

NOTE: I selected Spring Boot version 2.7.8 based on the start.spring.io URL posted in Issue #2382. I also noticed Gradle was selected, so just be careful there, :).

Additionally, Jedis 3.8.0 uses the same commons-pool2 dependency. Spring Boot pulls in Spring Data BOM 2021.2.7. Spring Data BOM 2021.2.7 declares Spring Data Redis 2.7.7. Spring Data Redis 2.7.7 declares Jedis version 3.8.0.

While everything appears to align correctly (based on the description above), I'd run mvn dependency:tree in your project and search for all instances of commons-pool2 to make sure they point to 2.11.1 consistently.

2. Have you tried with the Lettuce driver? I'd be curious if Lettuce has the same issue.

3. Similarly, I 'd also be curious if the same issue happened using the Jedis driver API directly without Spring Data Redis. I suspect it might.

4. It is not surprising that, "The timing of this exception differs. Sometimes it shows up right away, sometimes it takes a few seconds (and iterations of the cursor).".

After all, the ClassCastException is being thrown from an asynchronous operation in the commons-pool-evictor Thread, when apparently, it is trying to do the following:

at org.apache.commons.pool2.impl.GenericObjectPool.evict(GenericObjectPool.java:745) ~[commons-pool2-2.11.1.jar:2.11.1]
at org.apache.commons.pool2.impl.BaseGenericObjectPool$Evictor.run(BaseGenericObjectPool.java:160) ~[commons-pool2-2.11.1.jar:2.11.1]

That is, run a (scheduled) eviction.

at org.apache.commons.pool2.impl.EvictionTimer$WeakRunner.run(EvictionTimer.java:113) ~[commons-pool2-2.11.1.jar:2.11.1]

It seems Jedis goes on to verify that the (pooled) connection is still valid (??) and perhaps still in use (suggesting some timeout for inactivity?).

at redis.clients.jedis.Connection.getStatusCodeReply(Connection.java:270) ~[jedis-3.8.0.jar:?]
at redis.clients.jedis.BinaryJedis.ping(BinaryJedis.java:384) ~[jedis-3.8.0.jar:?]
at redis.clients.jedis.JedisFactory.validateObject(JedisFactory.java:214) ~[jedis-3.8.0.jar:?]

Following this call stack, I see:

• From the JedisFactory.validateObject(:PooledObject<Jedis>) call...

• To the BinaryJedis.ping() call ... (even the name is quite revealing in this case)

• Then to the Connection.getStatusCodeReply() call...

On line 270, why did readProtocolWithCheckingBroken() (from the the Redis server (cluster node)?) seemingly return an ArrayList here, when the response is clearly expected to be a byte[]?

Let's see...

• Next, into the Connection.readProtocolWithCheckingBroken() call...

• Ok, then... Protocol.read(:redis.clients.jedis.util.RedisInputStream) and finally, Protocol.process(:RedisInputStream).

I suspect we are supposed to be getting back this.

Was it not the + byte? Was it one of the other bytes? What was it?

This leads me to suspect...

5. Are you certain your Redis (cluster) server version is correctly aligned with your Jedis driver version (3.8.0)?

In many databases (I come from VMware GemFire/Apache Geode) newer client drivers cannot always talk to older servers, but older clients can typically talk to newer servers (with reduced capabilities, of course). This is likely because the (binary, on-the-wire) protocol, changes.

Finally...

AFAICK, Spring Data Redis is not affecting the binary protocols of the Redis client drivers, e.g. Jedis, or even Lettuce, in any particular way.

Additionally, given this is an interaction with the pooled connections (Thread) using the Jedis driver to assess the health (e.g. status, liveness, availability) of the cluster nodes (Redis servers), then it seems unlikely this is a Spring Data Redis issue to begin with, and the manifestation of this error occurring during the SCAN is simply a coincidence, and in fact, could possibly happen with any other reasonably lengthy command as well.

6. I'd also look at other factors like the configuration of the JedisConnectionFactory, and the produced JedisConnection instances themselves, as they both have quite a few configuration options available.

There could we be other factors to consider here as well, such as network issues.

7. Is this happening in all environments?

Food for thought to kickstart more discussion.

Given the intermittent nature of this issue, I think it will be very difficult to track down the underly problem if there is not simple, reliable example to reproduce this problem.

[jxblum]

Regarding your comment concerning setting the spring.redis.jedis.pool.enabled property to false, I would certainly verify this setting was applied correctly, too.

[kchristidis]

the issue appears to be Jedis driver related, and maybe something specifically to do with Jedis's use and/or configuration of Apache Commons Pool?

I think you're hitting the nail on the head with this one. This does seem to be a Jedis issue, and I will close this ticket here.

Before I do so, let me respond to some of your comments:

1. Dependencies align and I am indeed working with 2.11.1.
2. Lettuce works without issues — was just wrapping up this experiment, and was actually coming here to update the issue with this finding.
3. I'm running Redis 6.2.5. I cannot find a compatibility page anywhere?
4. Yes. I can reproduce this failure deterministically.

[chen-jie]

@kchristidis I'm facing same issue like yours. Did you find a way out of this ?

[shiranyosef1]

I'm facing the same issue with jedis, is there a known solution? @mp911de

[kchristidis]

@kchristidis I'm facing same issue like yours. Did you find a way out of this ?

Sorry for the super-late reply. I solved this by switching to Lettuce.