ClusterExpirationFunctionalTest.testWriteExpiredEntry random failures --------------------------------------------------------------------- Key: ISPN-11422 URL: https://issues.redhat.com/browse/ISPN-11422 Project: Infinispan Issue Type: Bug Components: Core, Test Suite Affects Versions: 11.0.0.Alpha2 Reporter: Dan Berindei Assignee: Will Burns Priority: Major Labels: testsuite_stability Fix For: 11.0.0.Final Attachments: ISPN-11367_default_configuration_20200301-2115_ClusterExpirationFunctionalTest-infinispan-core.log.gz {noformat} 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) [?:?] {noformat} Looks like a deadlock: the {{RemoveExpiredCommand}} can't run on backup B because the sequence number is still 56 (the seqno of the {{PutKeyValueCommand}}).