[ISPN-11422] ClusterExpirationFunctionalTest.testWriteExpiredEntry random failures

Type: Bug
Resolution: Obsolete
Priority: Major
Fix Version/s: 12.1.12.Final
Affects Version/s: 11.0.0.Alpha2
Component/s: Core, Test Suite
Labels:
- testsuite_stability

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).

- - Sort By Name
  - Sort By Date
  - Ascending
  - Descending
  - Thumbnails
  - List
  - Download All

ISPN-11367_default_configuration_20200301-2115_ClusterExpirationFunctionalTest-infinispan-core.log.gz
11.99 MB
2020/03/04 8:56 AM

Tristan Tarrant added a comment - 2024/11/27 2:36 PM

Infinispan issue tracking has been migrated to GitHub issues: https://github.com/infinispan/infinispan/issues
If you still want this issue to be worked on, create a new issue on GitHub and link this issue.

Tristan Tarrant added a comment - 2024/11/27 2:36 PM Infinispan issue tracking has been migrated to GitHub issues: https://github.com/infinispan/infinispan/issues If you still want this issue to be worked on, create a new issue on GitHub and link this issue.

Dan Berindei (Inactive) added a comment - 2020/04/02 12:07 PM

Finishing the get operation only after the RemoveExpiredCommand finished sounds good to me, but I'd like to know more details about why the pending RemoveExpiredCommand cannot finish.

Dan Berindei (Inactive) added a comment - 2020/04/02 12:07 PM Finishing the get operation only after the RemoveExpiredCommand finished sounds good to me, but I'd like to know more details about why the pending RemoveExpiredCommand cannot finish.

Will Burns added a comment - 2020/04/02 9:01 AM

We may also want to rethink making get wait for the remove expired to complete. It should be infrequent that a read for expired entry is actually triggered in most cases (hopefully). At least before the reaper removes it.

Will Burns added a comment - 2020/04/02 9:01 AM We may also want to rethink making get wait for the remove expired to complete. It should be infrequent that a read for expired entry is actually triggered in most cases (hopefully). At least before the reaper removes it.

Will Burns added a comment - 2020/03/31 1:13 PM - edited

Okay looking closer, this is caused by sending a write command to a key that is expired, but the primary owner didn't see it expired but the backup does.

~~This can be caused by a few different things including time mismatch in clocks~~. However the offending one in this code is that there is a pending remove expired still running from a prior get via `expiring` map in `ExpirationManagerImpl`.

Will Burns added a comment - 2020/03/31 1:13 PM - edited Okay looking closer, this is caused by sending a write command to a key that is expired, but the primary owner didn't see it expired but the backup does. This can be caused by a few different things including time mismatch in clocks . However the offending one in this code is that there is a pending remove expired still running from a prior get via `expiring` map in `ExpirationManagerImpl`.

Details

Description

Attachments

Attachments

Easy Agile Planning Poker

Activity

Collapse comment: Tristan Tarrant added a comment - 2024/11/27 2:36 PM

Expand comment: Tristan Tarrant added a comment - 2024/11/27 2:36 PM

Collapse comment: Dan Berindei (Inactive) added a comment - 2020/04/02 12:07 PM

Expand comment: Dan Berindei (Inactive) added a comment - 2020/04/02 12:07 PM

Collapse comment: Will Burns added a comment - 2020/04/02 9:01 AM

Expand comment: Will Burns added a comment - 2020/04/02 9:01 AM

Collapse comment: Will Burns added a comment - 2020/03/31 1:13 PM, Edited by Will Burns - 2020/04/02 9:07 AM

Expand comment: Will Burns added a comment - 2020/03/31 1:13 PM, Edited by Will Burns - 2020/04/02 9:07 AM

People

Dates

PagerDuty