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

ClusterExpirationFunctionalTest.testWriteExpiredEntry random failures

    Details

      Description

      21:20:48,799 TRACE (testng-Test:[]) [InvocationContextInterceptor] Invoked with command PutKeyValueCommand{key=key, value=value, flags=[], commandInvocationId=CommandInvocation:Test-NodeA:15530, putIfAbsent=true, valueMatcher=MATCH_EXPECTED, metadata=EmbeddedExpirableMetadata{version=null, lifespan=1000, maxIdle=-1}, successful=true, topologyId=-1} and InvocationContext [SingleKeyNonTxInvocationContext{isLocked=false, key=null, cacheEntry=null, origin=null, lockOwner=CommandInvocation:Test-NodeA:15530}]
      21:20:48,800 TRACE (jgroups-5,Test-NodeA:[]) [TriangleDistributionInterceptor] Command CommandInvocation:Test-NodeA:15530 send to backup owner [Test-NodeB].
      21:20:48,800 TRACE (jgroups-5,Test-NodeA:[]) [TriangleDistributionInterceptor] Command CommandInvocation:Test-NodeA:15530 got sequence 56 for segment 99
      21:20:48,801 TRACE (jgroups-6,Test-NodeB:[]) [TriangleOrderManager] Receiver old topology. Current sequence (27:56), command sequence (27:56)
      21:20:48,802 TRACE (remote-thread-Test-NodeB-p15169-t1:[]) [ClusterExpirationManager] Submitting expiration removal for key: key which is maxIdle: false of: 1000
      21:20:48,802 TRACE (remote-thread-Test-NodeB-p15169-t1:[]) [CommandAckCollector] Created new collector for 15533. BackupOwners=[Test-NodeB]
      21:20:48,802 TRACE (remote-thread-Test-NodeB-p15169-t1:[]) [JGroupsTransport] Test-NodeB sending single request 48 to Test-NodeA: SingleRpcCommand{cacheName='defaultcache', command=RemoveExpiredCommand{key=key, value=value, lifespan=1000, maxIde=false}}
      21:20:48,803 TRACE (remote-thread-Test-NodeA-p15163-t3:[]) [TriangleDistributionInterceptor] Command CommandInvocation:Test-NodeB:15533 got sequence 57 for segment 99
      21:20:48,804 TRACE (jgroups-5,Test-NodeB:[]) [CommandAckCollector] Pending backup acks: [Test-NodeB]
      21:20:48,804 TRACE (jgroups-6,Test-NodeB:[]) [TriangleOrderAction] Checking if next for segment 99 and sequence 57
      21:20:48,804 TRACE (jgroups-6,Test-NodeB:[]) [TriangleOrderManager] Receiver old topology. Current sequence (27:56), command sequence (27:57)
      21:20:48,804 TRACE (Controller-remote-thread-Test-NodeB:[]) [TriangleOrderManager] Receiver old topology. Current sequence (27:56), command sequence (27:57)
      21:20:48,804 TRACE (Controller-remote-thread-Test-NodeB:[]) [BlockingTaskAwareExecutorServiceImpl] Tasks to be executed=0, still pending=~1
      21:21:03,801 ERROR (timeout-thread-Test-NodeA-p15164-t1:[]) [InvocationContextInterceptor] ISPN000136: Error executing command PutKeyValueCommand on Cache 'defaultcache', writing keys [key]
      org.infinispan.util.concurrent.TimeoutException: ISPN000427: Timeout after 15 seconds waiting for acks. Id=15530
      21:21:03,805 ERROR (testng-Test:[]) [TestSuiteProgress] Test failed: org.infinispan.expiration.impl.ClusterExpirationFunctionalTest.testWriteExpiredEntry[DIST_SYNC, tx=false, storageType=OBJECT]
      org.infinispan.util.concurrent.TimeoutException: ISPN000427: Timeout after 15 seconds waiting for acks. Id=15530
      	at org.infinispan.interceptors.impl.AsyncInterceptorChainImpl.invoke(AsyncInterceptorChainImpl.java:255) ~[classes/:?]
      	at org.infinispan.cache.impl.InvocationHelper.doInvoke(InvocationHelper.java:296) ~[classes/:?]
      	at org.infinispan.cache.impl.InvocationHelper.invoke(InvocationHelper.java:100) ~[classes/:?]
      	at org.infinispan.cache.impl.InvocationHelper.invoke(InvocationHelper.java:82) ~[classes/:?]
      	at org.infinispan.cache.impl.CacheImpl.putIfAbsent(CacheImpl.java:1331) ~[classes/:?]
      	at org.infinispan.cache.impl.CacheImpl.putIfAbsent(CacheImpl.java:1325) ~[classes/:?]
      	at org.infinispan.cache.impl.CacheImpl.putIfAbsent(CacheImpl.java:1321) ~[classes/:?]
      	at org.infinispan.cache.impl.CacheImpl.putIfAbsent(CacheImpl.java:232) ~[classes/:?]
      	at org.infinispan.cache.impl.AbstractDelegatingCache.putIfAbsent(AbstractDelegatingCache.java:127) ~[classes/:?]
      	at org.infinispan.cache.impl.EncoderCache.putIfAbsent(EncoderCache.java:215) ~[classes/:?]
      	at org.infinispan.expiration.impl.ClusterExpirationFunctionalTest.testWriteExpiredEntry(ClusterExpirationFunctionalTest.java:374) ~[test-classes/:?]
      	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
      	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
      	at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
      	at java.lang.reflect.Method.invoke(Method.java:566) ~[?:?]
      	at org.testng.internal.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:124) ~[testng-6.14.3.jar:?]
      	at org.testng.internal.MethodInvocationHelper$1.runTestMethod(MethodInvocationHelper.java:230) ~[testng-6.14.3.jar:?]
      	at org.infinispan.commons.test.TestNGLongTestsHook.run(TestNGLongTestsHook.java:24) ~[infinispan-commons-test-11.0.0-SNAPSHOT.jar:11.0.0-SNAPSHOT]
      	at org.testng.internal.MethodInvocationHelper.invokeHookable(MethodInvocationHelper.java:242) ~[testng-6.14.3.jar:?]
      	at org.testng.internal.Invoker.invokeMethod(Invoker.java:579) [testng-6.14.3.jar:?]
      	at org.testng.internal.Invoker.invokeTestMethod(Invoker.java:719) [testng-6.14.3.jar:?]
      	at org.testng.internal.Invoker.invokeTestMethods(Invoker.java:989) [testng-6.14.3.jar:?]
      	at org.testng.internal.TestMethodWorker.invokeTestMethods(TestMethodWorker.java:125) [testng-6.14.3.jar:?]
      	at org.testng.internal.TestMethodWorker.run(TestMethodWorker.java:109) [testng-6.14.3.jar:?]
      	at org.testng.TestRunner.privateRun(TestRunner.java:648) [testng-6.14.3.jar:?]
      	at org.testng.TestRunner.run(TestRunner.java:505) [testng-6.14.3.jar:?]
      	at org.testng.SuiteRunner.runTest(SuiteRunner.java:455) [testng-6.14.3.jar:?]
      	at org.testng.SuiteRunner.access$000(SuiteRunner.java:40) [testng-6.14.3.jar:?]
      	at org.testng.SuiteRunner$SuiteWorker.run(SuiteRunner.java:489) [testng-6.14.3.jar:?]
      	at org.testng.internal.thread.ThreadUtil$1.call(ThreadUtil.java:52) [testng-6.14.3.jar:?]
      	at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
      	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
      	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
      	at java.lang.Thread.run(Thread.java:834) [?:?]
      Caused by: org.infinispan.util.concurrent.TimeoutException: ISPN000427: Timeout after 15 seconds waiting for acks. Id=15530
      	at org.infinispan.util.concurrent.CommandAckCollector.createTimeoutException(CommandAckCollector.java:222) ~[classes/:?]
      	at org.infinispan.util.concurrent.CommandAckCollector.access$700(CommandAckCollector.java:58) ~[classes/:?]
      	at org.infinispan.util.concurrent.CommandAckCollector$BaseCollector.call(CommandAckCollector.java:275) ~[classes/:?]
      	at org.infinispan.util.concurrent.CommandAckCollector$BaseCollector.call(CommandAckCollector.java:255) ~[classes/:?]
      	at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
      	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
      	... 3 more
      	Suppressed: org.infinispan.util.logging.TraceException
      		at org.infinispan.interceptors.impl.SimpleAsyncInvocationStage.get(SimpleAsyncInvocationStage.java:39) ~[classes/:?]
      		at org.infinispan.interceptors.impl.AsyncInterceptorChainImpl.invoke(AsyncInterceptorChainImpl.java:246) ~[classes/:?]
      		at org.infinispan.cache.impl.InvocationHelper.doInvoke(InvocationHelper.java:296) ~[classes/:?]
      		at org.infinispan.cache.impl.InvocationHelper.invoke(InvocationHelper.java:100) ~[classes/:?]
      		at org.infinispan.cache.impl.InvocationHelper.invoke(InvocationHelper.java:82) ~[classes/:?]
      		at org.infinispan.cache.impl.CacheImpl.putIfAbsent(CacheImpl.java:1331) ~[classes/:?]
      		at org.infinispan.cache.impl.CacheImpl.putIfAbsent(CacheImpl.java:1325) ~[classes/:?]
      		at org.infinispan.cache.impl.CacheImpl.putIfAbsent(CacheImpl.java:1321) ~[classes/:?]
      		at org.infinispan.cache.impl.CacheImpl.putIfAbsent(CacheImpl.java:232) ~[classes/:?]
      		at org.infinispan.cache.impl.AbstractDelegatingCache.putIfAbsent(AbstractDelegatingCache.java:127) ~[classes/:?]
      		at org.infinispan.cache.impl.EncoderCache.putIfAbsent(EncoderCache.java:215) ~[classes/:?]
      		at org.infinispan.expiration.impl.ClusterExpirationFunctionalTest.testWriteExpiredEntry(ClusterExpirationFunctionalTest.java:374) ~[test-classes/:?]
      		at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
      		at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
      		at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
      		at java.lang.reflect.Method.invoke(Method.java:566) ~[?:?]
      		at org.testng.internal.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:124) ~[testng-6.14.3.jar:?]
      		at org.testng.internal.MethodInvocationHelper$1.runTestMethod(MethodInvocationHelper.java:230) ~[testng-6.14.3.jar:?]
      		at org.infinispan.commons.test.TestNGLongTestsHook.run(TestNGLongTestsHook.java:24) ~[infinispan-commons-test-11.0.0-SNAPSHOT.jar:11.0.0-SNAPSHOT]
      		at org.testng.internal.MethodInvocationHelper.invokeHookable(MethodInvocationHelper.java:242) ~[testng-6.14.3.jar:?]
      		at org.testng.internal.Invoker.invokeMethod(Invoker.java:579) [testng-6.14.3.jar:?]
      		at org.testng.internal.Invoker.invokeTestMethod(Invoker.java:719) [testng-6.14.3.jar:?]
      		at org.testng.internal.Invoker.invokeTestMethods(Invoker.java:989) [testng-6.14.3.jar:?]
      		at org.testng.internal.TestMethodWorker.invokeTestMethods(TestMethodWorker.java:125) [testng-6.14.3.jar:?]
      		at org.testng.internal.TestMethodWorker.run(TestMethodWorker.java:109) [testng-6.14.3.jar:?]
      		at org.testng.TestRunner.privateRun(TestRunner.java:648) [testng-6.14.3.jar:?]
      		at org.testng.TestRunner.run(TestRunner.java:505) [testng-6.14.3.jar:?]
      		at org.testng.SuiteRunner.runTest(SuiteRunner.java:455) [testng-6.14.3.jar:?]
      		at org.testng.SuiteRunner.access$000(SuiteRunner.java:40) [testng-6.14.3.jar:?]
      		at org.testng.SuiteRunner$SuiteWorker.run(SuiteRunner.java:489) [testng-6.14.3.jar:?]
      		at org.testng.internal.thread.ThreadUtil$1.call(ThreadUtil.java:52) [testng-6.14.3.jar:?]
      		at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
      		at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
      		at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
      		at java.lang.Thread.run(Thread.java:834) [?:?]
      

      Looks like a deadlock: the RemoveExpiredCommand can't run on backup B because the sequence number is still 56 (the seqno of the PutKeyValueCommand).

        Gliffy Diagrams

          Attachments

            Activity

              People

              • Assignee:
                william.burns Will Burns
                Reporter:
                dan.berindei Dan Berindei
              • Votes:
                0 Vote for this issue
                Watchers:
                2 Start watching this issue

                Dates

                • Created:
                  Updated: