JedisException that seems to be out of application direct control

[Anand-Tableau]

Hello, we are seeing this exception after we upgraded from Jedis 2.9.0 to Jedis 3.6.0
The callstack seems to originate from commons-pool2 eviction timer that seems to be out of our direct control, is that timer managed by Jedis ?
I will be looking up how commons-pool2 is supposed to work, but is JedisFactory.destroyObject supposed to return the object to the pool when the pool itself is invoking destroy object for an evicted/destroyed object ?
Our testing suggests that this is not causing any issue in terms of functionality, but it is generating a lot of noise in log and will overwhelm splunk if we deployed it to production. If this is an issue in Jedis, is there some way of suppressing this warning without waiting for a patch from Jedis ?

Call stack is further below.

Thank you,
Anand

2021-07-21 06:59:59.599 +0000 (,,,,,,) commons-pool-evictor-thread : WARN redis.clients.jedis.JedisFactory - Error while close redis.clients.jedis.exceptions.JedisException: Could not return the broken resource to the pool at redis.clients.jedis.util.Pool.returnBrokenResourceObject(Pool.java:116) ~[jedis-3.6.0.jar:?] at redis.clients.jedis.util.Pool.returnBrokenResource(Pool.java:98) ~[jedis-3.6.0.jar:?] at redis.clients.jedis.JedisPool.returnResource(JedisPool.java:378) ~[jedis-3.6.0.jar:?] at redis.clients.jedis.JedisPool.returnResource(JedisPool.java:15) ~[jedis-3.6.0.jar:?] at redis.clients.jedis.Jedis.close(Jedis.java:3957) ~[jedis-3.6.0.jar:?] at redis.clients.jedis.JedisFactory.destroyObject(JedisFactory.java:166) [jedis-3.6.0.jar:?] at org.apache.commons.pool2.PooledObjectFactory.destroyObject(PooledObjectFactory.java:126) [commons-pool2-2.9.0.jar:2.9.0] at org.apache.commons.pool2.impl.GenericObjectPool.destroy(GenericObjectPool.java:958) [commons-pool2-2.9.0.jar:2.9.0] at org.apache.commons.pool2.impl.GenericObjectPool.evict(GenericObjectPool.java:797) [commons-pool2-2.9.0.jar:2.9.0] at org.apache.commons.pool2.impl.BaseGenericObjectPool$Evictor.run(BaseGenericObjectPool.java:1160) [commons-pool2-2.9.0.jar:2.9.0] at org.apache.commons.pool2.impl.EvictionTimer$WeakRunner.run(EvictionTimer.java:213) [commons-pool2-2.9.0.jar:2.9.0] at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [?:?] at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) [?:?] at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) [?:?] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?] at java.lang.Thread.run(Thread.java:829) [?:?] Caused by: java.lang.IllegalStateException: Invalidated object not currently part of this pool at org.apache.commons.pool2.impl.GenericObjectPool.invalidateObject(GenericObjectPool.java:642) ~[commons-pool2-2.9.0.jar:2.9.0] at org.apache.commons.pool2.impl.GenericObjectPool.invalidateObject(GenericObjectPool.java:620) ~[commons-pool2-2.9.0.jar:2.9.0] at redis.clients.jedis.util.Pool.returnBrokenResourceObject(Pool.java:114) ~[jedis-3.6.0.jar:?] ... 16 more


[sazzad16]

is that timer managed by Jedis ?

No

s JedisFactory.destroyObject supposed to return the object to the pool ... ?

No

If this is an issue in Jedis

This is not an issue in Jedis. It used to swallow many internal exceptions. Some of those exceptions are now logged upon users' requests.

is there some way of suppressing this warning

Set the logging level of redis.clients.jedis package to ERROR or above.

[Anand-Tableau]

Thanks @sazzad16 , you mentioned that JedisFactory.destroyObject is not supposed to return the object to the pool.
But in code I see destroyObject calling close which in turn tries to return the object to the pool.
https://github.com/redis/jedis/blob/3.6/src/main/java/redis/clients/jedis/JedisFactory.java#L166

  @Override
  public void destroyObject(PooledObject pooledJedis) throws Exception {
    final BinaryJedis jedis = pooledJedis.getObject();
    if (jedis.isConnected()) {
      try {
        // need a proper test, probably with mock
        if (!jedis.isBroken()) {
          jedis.quit();
        }
      } catch (Exception e) {
        logger.warn("Error while QUIT", e);
      }
      try {
        jedis.close();
      } catch (Exception e) {
        logger.warn("Error while close", e);
      }
    }
  }

[Anand-Tableau]

Hello, I am attaching some callstacks from debugger to indicate why this would be an issue Jedis.
Callstack1 from debugger shows JedisFactory looking to return the object to the pool.
Note the pool instance GenericObjectPool@24451 and it wants to fetch the object from allObjects variable on line 637.

Looking at what happened before in the callstack, here is the object pool calling the factory to destroy the object.
Notice that the object pool instance matches, but the pool already removed the object from allObjects variable on line 956.
JedisFactory.destroyObject is called by commons-pool when evicting objects, and is called after evicting the object from the pool.

Hence JedisFactory.destroyObject should not try to return the object to the pool.
May need some thinking here to manage the expectation for destroyObject being called by the pool vs. client app of Jedis calling JedisFactory.destroyObject

[yangbodong22011]

@Anand-Tableau Thank you for your detailed reply.
it seems we change disconnect to close in this PR.
But what I am still curious about is: the type of Jedis we call is BinaryJedis, but why the Jedis.close() is still executed.

[Anand-Tableau]

Thanks @yangbodong22011, that was helpful. They are indeed different objects.

This article helped us fix the issue by moving over from the older pattern of explicitly returning the resource to simply calling close via try().
https://stackoverflow.com/questions/17082163/jedis-when-to-use-returnbrokenresource

A related question, version 2.9.0 had deprecated returnResource and returnBrokenResource. But they are not deprecated in version 3.6.0 of jedis. Could these API be marked as deprecated again to help other users of Jedis follow the right pattern ?

Regards,
Anand

[sazzad16]

@Anand-Tableau It'd great if could create an issue. This may trigger discussion and PR.

[SoberChina]

I have the same problem