-
Bug
-
Resolution: Done
-
Major
-
11.0.0.Dev03, 12.0.0.Final
According to the code comments, the test is supposed to block the put(evicted-key) operation before releasing the orderer, but because of operationCheckPoint.trigger(Mocks.BEFORE_RELEASE) it only blocks after releasing the orderer. This means the eviction triggered by put(other-key) and the activation triggered later by get(evicted-key) are not blocked.
All three operations eventually call operationCheckPoint.awaitStrict(Mocks.BEFORE_RELEASE). The test triggers that event twice, so it unblocks put(evicted-key) and one of put(other-key)/get(evicted-key). The two unblocked operations then compete for a single Mocks.AFTER_RELEASE event.
If put(evicted-key) receives the Mocks.AFTER_RELEASE event, the test passes, because the other operations can finish without waiting for the activation/passivation to finish. (It just needs to be queued in )
Because CheckPoint doesn't guarantee waiters receive events in the queueing order, either put(other-key, "value", or get(evicted-key) could receive the AFTER_RELEASE event from put(evicted-key, "value"), making it time out.
19:53:59,795 TRACE (ForkThread-1,Test:[]) [InvocationContextInterceptor] Invoked with command PutKeyValueCommand{key=evicted-key, value=value, flags=[SKIP_CACHE_LOAD], commandInvocationId=CommandInvocation:<local>:37070, putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{version=null, lifespan=-1, maxIdle=-1}, successful=true, topologyId=-1} and InvocationContext [SingleKeyNonTxInvocationContext{isLocked=false, key=null, cacheEntry=null, origin=null, lockOwner=CommandInvocation:<local>:37070}]
19:53:59,807 TRACE (non-blocking-thread-Test-NodeK-p23146-t1:[]) [DataOperationOrderer] Ordered future java.util.concurrent.CompletableFuture@76d1e6bc[Not completed] is completed for key evicted-key from op WRITE
19:53:59,811 TRACE (non-blocking-thread-Test-NodeK-p23146-t1:[]) [CheckPoint] Waiting for event post_released * 1
^ put(evicted-key) is blocked
19:53:59,807 TRACE (testng-Test:[]) [InvocationContextInterceptor] Invoked with command PutKeyValueCommand{key=other-key, value=other-value, flags=[], commandInvocationId=CommandInvocation:<local>:37073, putIfAbsent=false, valueMatcher=MATCH_ALWAYS, metadata=EmbeddedExpirableMetadata{version=null, lifespan=-1, maxIdle=-1}, successful=true, topologyId=-1} and InvocationContext [SingleKeyNonTxInvocationContext{isLocked=false, key=null, cacheEntry=null, origin=null, lockOwner=CommandInvocation:<local>:37073}]
19:53:59,816 TRACE (non-blocking-thread-Test-NodeK-p23146-t2:[]) [AbstractInternalDataContainer] Store other-key=ImmortalCacheEntry{key=other-key, value=other-value, internalMetadata=null} in container
19:53:59,817 TRACE (non-blocking-thread-Test-NodeK-p23146-t2:[]) [DataOperationOrderer] Ordering upcoming future java.util.concurrent.CompletableFuture@32541e18[Not completed] for key evicted-key to run after null
^ put(other-key) is not blocked here
19:53:59,818 TRACE (non-blocking-thread-Test-NodeK-p23146-t2:[]) [PassivationManagerImpl] Passivating entry evicted-key 19:53:59,818 TRACE (non-blocking-thread-Test-NodeK-p23146-t2:[]) [PersistenceManagerImpl] Writing to all stores for id 67588 19:53:59,841 TRACE (non-blocking-thread-Test-NodeK-p23146-t3:[]) [CompletionStages] Continuing execution of id 67588 19:53:59,844 TRACE (non-blocking-thread-Test-NodeK-p23146-t3:[]) [CheckPoint] Waiting for event pre_released * 1
^ put(other-key) blocks in the checkpoint
19:53:59,956 TRACE (testng-Test:[]) [CheckPoint] Triggering event pre_released * 1 (available = 1, total = 2) 19:53:59,956 TRACE (testng-Test:[]) [CheckPoint] Triggering event post_released * 1 (available = 1, total = 1) 19:53:59,956 TRACE (non-blocking-thread-Test-NodeK-p23146-t3:[]) [CheckPoint] Received event pre_released * 1 (available = 0, total = 2)
^ put(other-key) is unblocked, put(evicted-key) stays blocked
19:54:09,998 ERROR (testng-Test:[]) [TestSuiteProgress] Test failed: org.infinispan.eviction.impl.EvictionWithPassivationAndConcurrentOperationsTest.testEvictionDuringWriteWithConcurrentRead java.util.concurrent.TimeoutException: null at java.util.concurrent.FutureTask.get(FutureTask.java:204) ~[?:?] at org.infinispan.eviction.impl.EvictionWithPassivationAndConcurrentOperationsTest.testEvictionDuringWriteWithConcurrentRead(EvictionWithPassivationAndConcurrentOperationsTest.java:99) ~[test-classes/:?]