DistSyncTxL1FuncTest.testGetBlockingAnotherGetCacheEntry random failures ------------------------------------------------------------------------ Key: ISPN-8742 URL: https://issues.jboss.org/browse/ISPN-8742 Project: Infinispan Issue Type: Bug Components: Test Suite - Core Affects Versions: 9.2.0.CR1 Reporter: Dan Berindei Assignee: Dan Berindei Labels: testsuite_stability Fix For: 9.2.0.CR2 getAsync() doesn't always run interceptor callbacks on a separate thread. The remote get can finish before the calling thread calls thenAccept(), especially when the test suite is limited to a single CPU. When that happens, the test thread cannot unblock the callback and the operation eventually times out: {noformat} 17:58:40,510 TRACE (jgroups-7,Test-NodeA-4165:[]) [JGroupsTransport] Test-NodeA-4165 received response for request 15 from Test-NodeC-55903: SuccessfulResponse(MetadataImmortalCacheValue {value=first-put, metadata=EmbeddedExpirableMetadata{lifespan=-1, maxIdle=-1, version=SimpleClusteredVersion{topologyId=13, version=1}}}) 17:58:40,511 TRACE (testng-Test:[]) [CheckPoint] Triggering event pre_acquire_shared_topology_lock_invoked * 1 (available = 1, total = 1) 17:58:40,511 TRACE (testng-Test:[]) [CheckPoint] Waiting for event pre_acquire_shared_topology_lock_released * 1 17:58:50,511 ERROR (testng-Test:[]) [CheckPoint] Timed out waiting for event pre_acquire_shared_topology_lock_released * 1 (available = 0, total = 0 17:58:50,512 ERROR (testng-Test:[]) [InvocationContextInterceptor] ISPN000136: Error executing command GetKeyValueCommand, writing keys [] java.util.concurrent.TimeoutException: Timed out waiting for event pre_acquire_shared_topology_lock_released at org.infinispan.test.fwk.CheckPoint.awaitStrict(CheckPoint.java:44) ~[test-classes/:?] at org.infinispan.test.fwk.CheckPoint.awaitStrict(CheckPoint.java:34) ~[test-classes/:?] at org.infinispan.distribution.BaseDistSyncL1Test.lambda$waitUntilAboutToAcquireLock$20(BaseDistSyncL1Test.java:554) ~[test-classes/:?] at org.mockito.internal.stubbing.StubbedInvocationMatcher.answer(StubbedInvocationMatcher.java:35) ~[mockito-core-2.7.21.jar:?] at org.mockito.internal.handler.MockHandlerImpl.handle(MockHandlerImpl.java:95) ~[mockito-core-2.7.21.jar:?] at org.mockito.internal.handler.NullResultGuardian.handle(NullResultGuardian.java:32) ~[mockito-core-2.7.21.jar:?] at org.mockito.internal.handler.InvocationNotifierHandler.handle(InvocationNotifierHandler.java:36) ~[mockito-core-2.7.21.jar:?] at org.mockito.internal.creation.bytebuddy.MockMethodInterceptor.doIntercept(MockMethodInterceptor.java:57) ~[mockito-core-2.7.21.jar:?] at org.mockito.internal.creation.bytebuddy.MockMethodInterceptor.doIntercept(MockMethodInterceptor.java:43) ~[mockito-core-2.7.21.jar:?] at org.mockito.internal.creation.bytebuddy.MockMethodInterceptor$DispatcherDefaultingToRealMethod.interceptAbstract(MockMethodInterceptor.java:137) ~[mockito-core-2.7.21.jar:?] at org.infinispan.statetransfer.StateTransferLock$MockitoMock$827961965.acquireSharedTopologyLock(Unknown Source) ~[classes/:?] at org.infinispan.interceptors.distribution.L1WriteSynchronizer.runL1UpdateIfPossible(L1WriteSynchronizer.java:176) ~[classes/:?] at org.infinispan.distribution.impl.L1ManagerImpl.remoteValueFound(L1ManagerImpl.java:196) ~[classes/:?] at org.infinispan.interceptors.distribution.BaseDistributionInterceptor.lambda$remoteGet$1(BaseDistributionInterceptor.java:197) ~[classes/:?] at java.util.concurrent.CompletableFuture.uniAccept(CompletableFuture.java:656) ~[?:1.8.0_152] at java.util.concurrent.CompletableFuture.uniAcceptStage(CompletableFuture.java:669) ~[?:1.8.0_152] at java.util.concurrent.CompletableFuture.thenAccept(CompletableFuture.java:1997) ~[?:1.8.0_152] at java.util.concurrent.CompletableFuture.thenAccept(CompletableFuture.java:110) ~[?:1.8.0_152] at org.infinispan.interceptors.distribution.BaseDistributionInterceptor.remoteGet(BaseDistributionInterceptor.java:184) ~[classes/:?] at org.infinispan.interceptors.distribution.TxDistributionInterceptor.remoteGet(TxDistributionInterceptor.java:553) ~[classes/:?] at org.infinispan.interceptors.distribution.BaseDistributionInterceptor.handleMissingEntryOnLocalRead(BaseDistributionInterceptor.java:796) ~[classes/:?] at org.infinispan.interceptors.distribution.BaseDistributionInterceptor.onEntryMiss(BaseDistributionInterceptor.java:791) ~[classes/:?] at org.infinispan.interceptors.distribution.BaseDistributionInterceptor.visitGetCommand(BaseDistributionInterceptor.java:786) ~[classes/:?] at org.infinispan.interceptors.distribution.BaseDistributionInterceptor.visitGetKeyValueCommand(BaseDistributionInterceptor.java:803) ~[classes/:?] at org.infinispan.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:38) ~[classes/:?] at org.infinispan.interceptors.BaseAsyncInterceptor.invokeNextAndFinally(BaseAsyncInterceptor.java:150) ~[classes/:?] at org.infinispan.interceptors.distribution.L1NonTxInterceptor.performL1Lookup(L1NonTxInterceptor.java:155) ~[classes/:?] at org.infinispan.interceptors.distribution.L1NonTxInterceptor.performCommandWithL1WriteIfAble(L1NonTxInterceptor.java:130) ~[classes/:?] at org.infinispan.interceptors.distribution.L1NonTxInterceptor.visitDataReadCommand(L1NonTxInterceptor.java:121) ~[classes/:?] at org.infinispan.interceptors.distribution.L1NonTxInterceptor.visitGetKeyValueCommand(L1NonTxInterceptor.java:110) ~[classes/:?] at org.infinispan.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:38) ~[classes/:?] at org.infinispan.interceptors.BaseAsyncInterceptor.invokeNextThenAccept(BaseAsyncInterceptor.java:98) ~[classes/:?] at org.infinispan.interceptors.impl.EntryWrappingInterceptor.visitDataReadCommand(EntryWrappingInterceptor.java:201) ~[classes/:?] at org.infinispan.interceptors.impl.EntryWrappingInterceptor.visitGetKeyValueCommand(EntryWrappingInterceptor.java:189) ~[classes/:?] at org.infinispan.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:38) ~[classes/:?] at org.infinispan.interceptors.BaseAsyncInterceptor.invokeNext(BaseAsyncInterceptor.java:54) ~[classes/:?] at org.infinispan.interceptors.DDAsyncInterceptor.handleDefault(DDAsyncInterceptor.java:54) ~[classes/:?] at org.infinispan.interceptors.DDAsyncInterceptor.visitGetKeyValueCommand(DDAsyncInterceptor.java:106) ~[classes/:?] at org.infinispan.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:38) ~[classes/:?] at org.infinispan.interceptors.BaseAsyncInterceptor.invokeNext(BaseAsyncInterceptor.java:54) ~[classes/:?] at org.infinispan.interceptors.DDAsyncInterceptor.handleDefault(DDAsyncInterceptor.java:54) ~[classes/:?] at org.infinispan.interceptors.DDAsyncInterceptor.visitGetKeyValueCommand(DDAsyncInterceptor.java:106) ~[classes/:?] at org.infinispan.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:38) ~[classes/:?] at org.infinispan.interceptors.BaseAsyncInterceptor.invokeNext(BaseAsyncInterceptor.java:54) ~[classes/:?] at org.infinispan.interceptors.locking.OptimisticLockingInterceptor.visitDataReadCommand(OptimisticLockingInterceptor.java:53) ~[classes/:?] at org.infinispan.interceptors.locking.AbstractLockingInterceptor.visitGetKeyValueCommand(AbstractLockingInterceptor.java:105) ~[classes/:?] at org.infinispan.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:38) ~[classes/:?] at org.infinispan.interceptors.BaseAsyncInterceptor.invokeNext(BaseAsyncInterceptor.java:54) ~[classes/:?] at org.infinispan.interceptors.impl.TxInterceptor.visitGetKeyValueCommand(TxInterceptor.java:360) ~[classes/:?] at org.infinispan.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:38) ~[classes/:?] at org.infinispan.interceptors.BaseAsyncInterceptor.invokeNext(BaseAsyncInterceptor.java:54) ~[classes/:?] at org.infinispan.statetransfer.TransactionSynchronizerInterceptor.visitCommand(TransactionSynchronizerInterceptor.java:41) ~[classes/:?] at org.infinispan.interceptors.BaseAsyncInterceptor.invokeNextAndHandle(BaseAsyncInterceptor.java:185) ~[classes/:?] at org.infinispan.interceptors.impl.BaseStateTransferInterceptor.handleReadCommand(BaseStateTransferInterceptor.java:187) ~[classes/:?] at org.infinispan.interceptors.impl.BaseStateTransferInterceptor.visitGetKeyValueCommand(BaseStateTransferInterceptor.java:170) ~[classes/:?] at org.infinispan.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:38) ~[classes/:?] at org.infinispan.interceptors.BaseAsyncInterceptor.invokeNext(BaseAsyncInterceptor.java:54) ~[classes/:?] at org.infinispan.interceptors.impl.CacheMgmtInterceptor.visitDataReadCommand(CacheMgmtInterceptor.java:103) ~[classes/:?] at org.infinispan.interceptors.impl.CacheMgmtInterceptor.visitGetKeyValueCommand(CacheMgmtInterceptor.java:92) ~[classes/:?] at org.infinispan.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:38) ~[classes/:?] at org.infinispan.interceptors.BaseAsyncInterceptor.invokeNextAndExceptionally(BaseAsyncInterceptor.java:123) [classes/:?] at org.infinispan.interceptors.impl.InvocationContextInterceptor.visitCommand(InvocationContextInterceptor.java:90) [classes/:?] at org.infinispan.interceptors.BaseAsyncInterceptor.invokeNext(BaseAsyncInterceptor.java:56) [classes/:?] at org.infinispan.interceptors.impl.BatchingInterceptor.handleDefault(BatchingInterceptor.java:53) [classes/:?] at org.infinispan.interceptors.DDAsyncInterceptor.visitGetKeyValueCommand(DDAsyncInterceptor.java:106) [classes/:?] at org.infinispan.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:38) [classes/:?] at org.infinispan.interceptors.BaseAsyncInterceptor.invokeNext(BaseAsyncInterceptor.java:54) [classes/:?] at org.infinispan.interceptors.DDAsyncInterceptor.handleDefault(DDAsyncInterceptor.java:54) [classes/:?] at org.infinispan.interceptors.DDAsyncInterceptor.visitGetKeyValueCommand(DDAsyncInterceptor.java:106) [classes/:?] at org.infinispan.commands.read.GetKeyValueCommand.acceptVisitor(GetKeyValueCommand.java:38) [classes/:?] at org.infinispan.interceptors.DDAsyncInterceptor.visitCommand(DDAsyncInterceptor.java:50) [classes/:?] at org.infinispan.interceptors.impl.AsyncInterceptorChainImpl.invokeAsync(AsyncInterceptorChainImpl.java:234) [classes/:?] at org.infinispan.cache.impl.CacheImpl.getAsync(CacheImpl.java:1591) [classes/:?] at org.infinispan.cache.impl.CacheImpl.getAsync(CacheImpl.java:1584) [classes/:?] at org.infinispan.cache.impl.AbstractDelegatingCache.getAsync(AbstractDelegatingCache.java:467) [classes/:?] at org.infinispan.cache.impl.EncoderCache.getAsync(EncoderCache.java:915) [classes/:?] at org.infinispan.distribution.BaseDistSyncL1Test.testGetBlockingAnotherGetCacheEntry(BaseDistSyncL1Test.java:515) [test-classes/:?] {noformat} The lingering {{L1WriteSynchronizer}} also fails the next test (usually {{testGetBlockingAnotherGetWithMiss}}).