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) [?:?]