EvictionWithPassivationAndConcurrentOperationsTest.testEvictionDuringWriteWithConcurrentRead random failures ------------------------------------------------------------------------------------------------------------ Key: ISPN-11598 URL: https://issues.redhat.com/browse/ISPN-11598 Project: Infinispan Issue Type: Bug Components: Core, Test Suite Affects Versions: 11.0.0.Dev03, 12.0.0.Final Reporter: Dan Berindei Assignee: Dan Berindei Priority: Major Labels: testsuite_stability Fix For: 12.1.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. {noformat} 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 {noformat} ^ put(evicted-key) is blocked {noformat} 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 {noformat} ^ put(other-key) is not blocked here {noformat} 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 {noformat} ^ put(other-key) blocks in the checkpoint {noformat} 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) {noformat} ^ put(other-key) is unblocked, put(evicted-key) stays blocked {noformat} 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/:?] {noformat}