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

DistSyncTxL1FuncTest.testGetBlockingAnotherGetCacheEntry random failures

    XMLWordPrintable

Details

    Description

      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:

      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/:?]

      The lingering L1WriteSynchronizer also fails the next test (usually testGetBlockingAnotherGetWithMiss).

      Attachments

        Activity

          People

            dberinde@redhat.com Dan Berindei (Inactive)
            dberinde@redhat.com Dan Berindei (Inactive)
            Votes:
            0 Vote for this issue
            Watchers:
            1 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved: