Uploaded image for project: 'Infinispan'
  1. Infinispan
  2. ISPN-15626

Hot Rod client tries to schedule operation twice

XMLWordPrintable

      During ISPN-14832, we identified operations could be enqueued while a channel was released, causing an operation not to execute. This has a chance of causing an operation to be scheduled twice.

       

      After we enqueue an operation, we recheck the pool to see if a channel is available. If this second check succeeds AND another channel is released to the pool, we end scheduling the same operation for execution twice.

       

      Some tests in CI show this problem:

      https://ci.infinispan.org/job/Infinispan/job/main/1476/testReport/org.infinispan.client.hotrod.near/AvoidStaleNearCacheReadsTest/testAvoidStaleReadsAfterReplacemaxEntries__20__bloomFilter__true__Flaky_Test_/

       

      And locally:

      [OK:  1261, KO:     1, SKIP:     0] Test failed: org.infinispan.client.hotrod.near.AvoidStaleNearCacheReadsTest.testAvoidStaleReadsAfterPutAllmaxEntries\=20, bloomFilter\=true
      org.infinispan.client.hotrod.exceptions.TransportException:: java.lang.AssertionError: PutAllOperation{(default), flags=6, connection=127.0.0.1/127.0.0.1:46385} is trying to override a timeout: 81387086
      	at org.infinispan.client.hotrod.impl.Util.rewrap(Util.java:87)
      	at org.infinispan.client.hotrod.impl.Util.await(Util.java:58)
      	at org.infinispan.client.hotrod.impl.RemoteCacheSupport.putAll(RemoteCacheSupport.java:48)
      	at org.infinispan.client.hotrod.impl.RemoteCacheSupport.putAll(RemoteCacheSupport.java:38)
      	at org.infinispan.client.hotrod.near.AvoidStaleNearCacheReadsTest.lambda$testAvoidStaleReadsAfterPutAll$1(AvoidStaleNearCacheReadsTest.java:99)
      	at org.infinispan.client.hotrod.near.AvoidStaleNearCacheReadsTest.lambda$repeated$5(AvoidStaleNearCacheReadsTest.java:137)
      	at java.base/java.util.stream.Streams$RangeIntSpliterator.forEachRemaining(Streams.java:104)
      	at java.base/java.util.stream.IntPipeline$Head.forEach(IntPipeline.java:617)
      	at org.infinispan.client.hotrod.near.AvoidStaleNearCacheReadsTest.repeated(AvoidStaleNearCacheReadsTest.java:136)
      	at org.infinispan.client.hotrod.near.AvoidStaleNearCacheReadsTest.testAvoidStaleReadsAfterPutAll(AvoidStaleNearCacheReadsTest.java:95)
      	at java.base/java.lang.reflect.Method.invoke(Method.java:568)
      	at org.testng.internal.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:124)
      	at org.testng.internal.MethodInvocationHelper$1.runTestMethod(MethodInvocationHelper.java:230)
      	at org.infinispan.commons.test.TestNGLongTestsHook.run(TestNGLongTestsHook.java:24)
      	at org.testng.internal.MethodInvocationHelper.invokeHookable(MethodInvocationHelper.java:242)
      	at org.testng.internal.Invoker.invokeMethod(Invoker.java:579)
      	at org.testng.internal.Invoker.invokeTestMethod(Invoker.java:719)
      	at org.testng.internal.Invoker.invokeTestMethods(Invoker.java:989)
      	at org.testng.internal.TestMethodWorker.invokeTestMethods(TestMethodWorker.java:125)
      	at org.testng.internal.TestMethodWorker.run(TestMethodWorker.java:109)
      	at org.testng.TestRunner.privateRun(TestRunner.java:648)
      	at org.testng.TestRunner.run(TestRunner.java:505)
      	at org.testng.SuiteRunner.runTest(SuiteRunner.java:455)
      	at org.testng.SuiteRunner.access$000(SuiteRunner.java:40)
      	at org.testng.SuiteRunner$SuiteWorker.run(SuiteRunner.java:489)
      	at org.testng.internal.thread.ThreadUtil$1.call(ThreadUtil.java:52)
      	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
      	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
      	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
      	at java.base/java.lang.Thread.run(Thread.java:833)
      Caused by: java.lang.AssertionError: PutAllOperation{(default), flags=6, connection=127.0.0.1/127.0.0.1:46385} is trying to override a timeout: 81387086
      	at org.infinispan.client.hotrod.impl.operations.HotRodOperation.scheduleTimeout(HotRodOperation.java:169)
      	at org.infinispan.client.hotrod.impl.transport.netty.HeaderDecoder.registerOperation(HeaderDecoder.java:83)
      	at org.infinispan.client.hotrod.impl.operations.HotRodOperation.scheduleRead(HotRodOperation.java:90)
      	at org.infinispan.client.hotrod.impl.operations.StatsAffectingRetryingOperation.scheduleRead(StatsAffectingRetryingOperation.java:35)
      	at org.infinispan.client.hotrod.impl.operations.PutAllOperation.executeOperation(PutAllOperation.java:57)
      	at org.infinispan.client.hotrod.impl.operations.RetryOnFailureOperation.invoke(RetryOnFailureOperation.java:78)
      	at org.infinispan.client.hotrod.impl.transport.netty.ChannelPool.activateChannel(ChannelPool.java:319)
      	at org.infinispan.client.hotrod.impl.transport.netty.ChannelPool.executeDirectlyIfPossible(ChannelPool.java:126)
      	at org.infinispan.client.hotrod.impl.transport.netty.ChannelPool.acquire(ChannelPool.java:93)
      	at org.infinispan.client.hotrod.impl.transport.netty.ChannelFactory.fetchChannelAndInvoke(ChannelFactory.java:327)
      	at org.infinispan.client.hotrod.impl.transport.netty.ChannelFactory.fetchChannelAndInvoke(ChannelFactory.java:322)
      	at org.infinispan.client.hotrod.impl.transport.netty.ChannelFactory.fetchChannelAndInvoke(ChannelFactory.java:305)
      	at org.infinispan.client.hotrod.impl.transport.netty.ChannelFactory.fetchChannelAndInvoke(ChannelFactory.java:281)
      	at org.infinispan.client.hotrod.impl.transport.netty.ChannelFactory.fetchChannelAndInvoke(ChannelFactory.java:367)
      	at org.infinispan.client.hotrod.impl.operations.PutAllOperation.fetchChannelAndInvoke(PutAllOperation.java:79)
      	at org.infinispan.client.hotrod.impl.operations.RetryOnFailureOperation.execute(RetryOnFailureOperation.java:63)
      	at org.infinispan.client.hotrod.impl.operations.ParallelHotRodOperation.execute(ParallelHotRodOperation.java:40)
      	at org.infinispan.client.hotrod.impl.RemoteCacheImpl.putAllAsync(RemoteCacheImpl.java:273)
      	at org.infinispan.client.hotrod.impl.DelegatingRemoteCache.putAllAsync(DelegatingRemoteCache.java:50)
      	at org.infinispan.client.hotrod.impl.InvalidatedNearRemoteCache.putAllAsync(InvalidatedNearRemoteCache.java:144)
      	... 28 more
      

      With some changes to capture who first instantiated the timeout:

      java.lang.RuntimeException: PutAllOperation{(default), flags=6, connection=127.0.0.1/127.0.0.1:46385} registered timeout: 81387086
      	at org.infinispan.client.hotrod.impl.operations.HotRodOperation.scheduleTimeout(HotRodOperation.java:172)
      	at org.infinispan.client.hotrod.impl.transport.netty.HeaderDecoder.registerOperation(HeaderDecoder.java:83)
      	at org.infinispan.client.hotrod.impl.operations.HotRodOperation.scheduleRead(HotRodOperation.java:90)
      	at org.infinispan.client.hotrod.impl.operations.StatsAffectingRetryingOperation.scheduleRead(StatsAffectingRetryingOperation.java:35)
      	at org.infinispan.client.hotrod.impl.operations.PutAllOperation.executeOperation(PutAllOperation.java:57)
      	at org.infinispan.client.hotrod.impl.operations.RetryOnFailureOperation.invoke(RetryOnFailureOperation.java:78)
      	at org.infinispan.client.hotrod.impl.transport.netty.ChannelPool.lambda$activateChannel$1(ChannelPool.java:311)
      	at io.netty.util.concurrent.AbstractEventExecutor.runTask(AbstractEventExecutor.java:173)
      	at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:166)
      	at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:470)
      	at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:413)
      	at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)
      	at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
      	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
      	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
      	at java.base/java.lang.Thread.run(Thread.java:833)
      

       

            rh-ee-jbolina Jose Bolina
            rh-ee-jbolina Jose Bolina
            Votes:
            0 Vote for this issue
            Watchers:
            1 Start watching this issue

              Created:
              Updated:
              Resolved: