[JBoss JIRA] (ISPN-11422) ClusterExpirationFunctionalTest.testWriteExpiredEntry random failures
by Will Burns (Jira)
[ https://issues.redhat.com/browse/ISPN-11422?page=com.atlassian.jira.plugi... ]
Will Burns edited comment on ISPN-11422 at 4/2/20 9:07 AM:
-----------------------------------------------------------
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`.
was (Author: william.burns):
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`.
> 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}}).
--
This message was sent by Atlassian Jira
(v7.13.8#713008)
6 years
[JBoss JIRA] (ISPN-11422) ClusterExpirationFunctionalTest.testWriteExpiredEntry random failures
by Will Burns (Jira)
[ https://issues.redhat.com/browse/ISPN-11422?page=com.atlassian.jira.plugi... ]
Will Burns edited comment on ISPN-11422 at 4/2/20 9:03 AM:
-----------------------------------------------------------
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`.
was (Author: william.burns):
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.
> 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}}).
--
This message was sent by Atlassian Jira
(v7.13.8#713008)
6 years
[JBoss JIRA] (ISPN-11422) ClusterExpirationFunctionalTest.testWriteExpiredEntry random failures
by Will Burns (Jira)
[ https://issues.redhat.com/browse/ISPN-11422?page=com.atlassian.jira.plugi... ]
Will Burns commented on ISPN-11422:
-----------------------------------
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.
> 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}}).
--
This message was sent by Atlassian Jira
(v7.13.8#713008)
6 years
[JBoss JIRA] (ISPN-10804) JCache tck-runner does not run interception tests
by Dan Berindei (Jira)
[ https://issues.redhat.com/browse/ISPN-10804?page=com.atlassian.jira.plugi... ]
Dan Berindei reopened ISPN-10804:
---------------------------------
I broke the interception tests again when I split the TCK modules (ISPN-11139)
> JCache tck-runner does not run interception tests
> -------------------------------------------------
>
> Key: ISPN-10804
> URL: https://issues.redhat.com/browse/ISPN-10804
> Project: Infinispan
> Issue Type: Bug
> Components: JCache, Test Suite
> Affects Versions: 9.4.16.Final, 10.0.0.CR3
> Reporter: Dan Berindei
> Assignee: Dan Berindei
> Priority: Major
> Fix For: 11.0.0.Alpha1
>
>
> Initially I thought the only way to make the interception TCK tests run was to add a {{@Priority}} annotation, which is not a good idea because even our tests expect to be able to switch between the managed or the managed interceptors.
> But it turns out if we revert ISPN-10721 and unpack the TCK tests in our build output directory, we can override {{beans.xml}} and make the interception tests run.
--
This message was sent by Atlassian Jira
(v7.13.8#713008)
6 years
[JBoss JIRA] (ISPN-11585) Use JavaSerializationMarshaller in jcache TCK modules
by Dan Berindei (Jira)
Dan Berindei created ISPN-11585:
-----------------------------------
Summary: Use JavaSerializationMarshaller in jcache TCK modules
Key: ISPN-11585
URL: https://issues.redhat.com/browse/ISPN-11585
Project: Infinispan
Issue Type: Task
Components: JCache
Affects Versions: 11.0.0.Dev03
Reporter: Dan Berindei
Assignee: Dan Berindei
Fix For: 11.0.0.Dev04
We should run the JSR-107 TCK with the java serialization marshaller, not with the protostream marshaller, to ensure that Infinispan is usable as a JCache implementation with minimal application code changes.
--
This message was sent by Atlassian Jira
(v7.13.8#713008)
6 years
[JBoss JIRA] (ISPN-11584) Functional Commands don't propagate DataConversion correctly
by Gustavo Fernandes (Jira)
[ https://issues.redhat.com/browse/ISPN-11584?page=com.atlassian.jira.plugi... ]
Gustavo Fernandes updated ISPN-11584:
-------------------------------------
Description: EncoderCache operations such as merge, compute, and every other that rely on Functional Commands end up losing the DataConversion, since it uses the CacheImpl's DataConversion instead of the EncoderCache's DataConversion (was: Encoder cache operations such as merge, compute, and every other that rely upon Functional Command end up looking DataConversion, since it uses the CacheImpl. DataConversion instead of the EncoderCache's Data Conversion)
> Functional Commands don't propagate DataConversion correctly
> ------------------------------------------------------------
>
> Key: ISPN-11584
> URL: https://issues.redhat.com/browse/ISPN-11584
> Project: Infinispan
> Issue Type: Enhancement
> Components: Core
> Affects Versions: 11.0.0.Dev03
> Reporter: Gustavo Fernandes
> Assignee: Gustavo Fernandes
> Priority: Major
>
> EncoderCache operations such as merge, compute, and every other that rely on Functional Commands end up losing the DataConversion, since it uses the CacheImpl's DataConversion instead of the EncoderCache's DataConversion
--
This message was sent by Atlassian Jira
(v7.13.8#713008)
6 years
[JBoss JIRA] (ISPN-11584) Functional Commands don't propagate DataConversion correctly
by Gustavo Fernandes (Jira)
Gustavo Fernandes created ISPN-11584:
----------------------------------------
Summary: Functional Commands don't propagate DataConversion correctly
Key: ISPN-11584
URL: https://issues.redhat.com/browse/ISPN-11584
Project: Infinispan
Issue Type: Enhancement
Components: Core
Affects Versions: 11.0.0.Dev03
Reporter: Gustavo Fernandes
Assignee: Gustavo Fernandes
Encoder cache operations such as merge, compute, and every other that rely upon Functional Command end up looking DataConversion, since it uses the CacheImpl. DataConversion instead of the EncoderCache's Data Conversion
--
This message was sent by Atlassian Jira
(v7.13.8#713008)
6 years
[JBoss JIRA] (ISPN-9351) nodes did not join to cluster because of timeoutException
by Dan Berindei (Jira)
[ https://issues.redhat.com/browse/ISPN-9351?page=com.atlassian.jira.plugin... ]
Dan Berindei resolved ISPN-9351.
--------------------------------
Resolution: Explained
[~staho] sorry we couldn't be more helpful at the time. I checked the configuration file and I noticed that you have {{UDP.max_bundle_size="64K"}} and you don't set a bundler, so you're using the default {{transfer-queue}} bundler. {{FRAG3.frag_size="1200"}} doesn't help, because messages are fragmented in {{FRAG3}} and then they're batched back together in the bundler.
In general we recommend using the default JGroups configuration files shipped with Infinispan and modifying them as little as possible. In our {{default-jgroups-udp.xml}}, we have {{UDP.max_bundle_size="8500"}}, {{UDP.bundler="no-bundler"}}, and {{FRAG3.frag_size="8000"}}. We set at those defaults exactly because some networks have problems with UDP packets bigger than 9000 bytes (the size of a jumbo Ethernet frame).
The logs seem to confirm that the cluster status responses, which are big messages, are sent by all 14 nodes but are not received by the coordinator.
{noformat}
2018-01-15 06:48:45,072 DEBUG [transport-thread-0045f36a-2860-4107-810a-d087224c9105-p4-t19] (DelegatingBasicLogger.java:384) - Recovering cluster status for view 20
2018-01-15 06:48:45,101 DEBUG [transport-thread-0045f36a-2860-4107-810a-d087224c9105-p4-t19] (DelegatingBasicLogger.java:384) - Sending cluster status response for view 20
2018-01-15 06:48:45,126 DEBUG [remote-thread-0105f36a-2860-4107-810a-d087224c9105-p2-t22] (DelegatingBasicLogger.java:384) - Sending cluster status response for view 20
2018-01-15 06:48:45,127 DEBUG [remote-thread-0035f36a-2860-4107-810a-d087224c9105-p2-t17] (DelegatingBasicLogger.java:384) - Sending cluster status response for view 20
2018-01-15 06:48:45,128 DEBUG [remote-thread-0055f36a-2860-4107-810a-d087224c9105-p2-t19] (DelegatingBasicLogger.java:384) - Sending cluster status response for view 20
2018-01-15 06:48:45,128 DEBUG [remote-thread-0155f36a-2860-4107-810a-d087224c9105-p2-t21] (DelegatingBasicLogger.java:384) - Sending cluster status response for view 20
2018-01-15 06:48:45,129 DEBUG [remote-thread-0025f36a-2860-4107-810a-d087224c9105-p2-t32] (DelegatingBasicLogger.java:384) - Sending cluster status response for view 20
2018-01-15 06:48:45,129 DEBUG [remote-thread-0085f36a-2860-4107-810a-d087224c9105-p2-t29] (DelegatingBasicLogger.java:384) - Sending cluster status response for view 20
2018-01-15 06:48:45,129 DEBUG [remote-thread-0135f36a-2860-4107-810a-d087224c9105-p2-t16] (DelegatingBasicLogger.java:384) - Sending cluster status response for view 20
2018-01-15 06:48:45,129 DEBUG [remote-thread-0145f36a-2860-4107-810a-d087224c9105-p2-t17] (DelegatingBasicLogger.java:384) - Sending cluster status response for view 20
2018-01-15 06:48:45,130 DEBUG [remote-thread-0095f36a-2860-4107-810a-d087224c9105-p2-t10] (DelegatingBasicLogger.java:384) - Sending cluster status response for view 20
2018-01-15 06:48:45,130 DEBUG [remote-thread-0125f36a-2860-4107-810a-d087224c9105-p2-t15] (DelegatingBasicLogger.java:384) - Sending cluster status response for view 20
2018-01-15 06:48:45,131 DEBUG [remote-thread-0065f36a-2860-4107-810a-d087224c9105-p2-t10] (DelegatingBasicLogger.java:384) - Sending cluster status response for view 20
2018-01-15 06:48:45,131 DEBUG [remote-thread-0075f36a-2860-4107-810a-d087224c9105-p2-t2] (DelegatingBasicLogger.java:384) - Sending cluster status response for view 20
2018-01-15 06:48:45,131 DEBUG [remote-thread-0115f36a-2860-4107-810a-d087224c9105-p2-t25] (DelegatingBasicLogger.java:384) - Sending cluster status response for view 20
2018-01-15 06:49:33,107 DEBUG [transport-thread-0045f36a-2860-4107-810a-d087224c9105-p4-t19] (ClusterTopologyManagerImpl.java:456) - Timed out waiting for cluster status responses, trying again
{noformat}
> nodes did not join to cluster because of timeoutException
> ---------------------------------------------------------
>
> Key: ISPN-9351
> URL: https://issues.redhat.com/browse/ISPN-9351
> Project: Infinispan
> Issue Type: Bug
> Reporter: Robert Cernak
> Priority: Major
> Attachments: 15nodesTryingToJoin1ClusterHowever5DidNotJoin .zip, Rebooting14ControllrsOf15InCloud.zip
>
>
> I was trying to connect 15nodes to 1 cluster, however nodes did not join.
> In logs, all nodes mostly had 2 kinds of exceptions, all caused by TimeoutException:
> 1:
> {noformat}
> 2018-07-03 07:35:31,670 DEBUG [Camel (camel-1) thread #0 - seda://systemInitializer] (LocalTopologyManagerImpl.java:169) - Error sending join request for cache org.infinispan.CONFIG to coordinator
> org.infinispan.util.concurrent.TimeoutException: ISPN000476: Timed out waiting for responses for request 2 from 0125f36a-2860-4107-810a-d087224c9105-21637
> following by next exception 1 second after...
> 2018-07-03 07:35:31,968 INFO [Camel (camel-1) thread #0 - seda://systemInitializer] (JGroupsTransport.java:702) - ISPN000080: Disconnecting JGroups channel cloud11-15
> 2018-07-03 07:35:32,262 DEBUG [Camel (camel-1) thread #0 - seda://systemInitializer] (DefaultCacheManager.java:709) - Stopping cache manager cloud11-15 on null
> 2018-07-03 07:35:32,273 WARN [Camel (camel-1) thread #0 - seda://systemInitializer] (DefaultCacheManager.java:736) - ISPN000189: While stopping a cache or cache manager, one of its components failed to stop
> java.util.concurrent.CompletionException: org.infinispan.commons.CacheException: Unable to invoke method public void org.infinispan.statetransfer.StateTransferManagerImpl.start() throws java.lang.Exception on object of type StateTransferManagerImpl
> at java.util.concurrent.CompletableFuture.reportJoin(Unknown Source) ~[?:1.8.0_131]
> at java.util.concurrent.CompletableFuture.join(Unknown Source) ~[?:1.8.0_131]
> at org.infinispan.manager.DefaultCacheManager.terminate(DefaultCacheManager.java:688) ~[infinispan-embedded-9.3.0.Final.jar:9.3.0.Final]
> at org.infinispan.manager.DefaultCacheManager.stopCaches(DefaultCacheManager.java:734) [infinispan-embedded-9.3.0.Final.jar:9.3.0.Final]
> at org.infinispan.manager.DefaultCacheManager.stop(DefaultCacheManager.java:711) [infinispan-embedded-9.3.0.Final.jar:9.3.0.Final]
> Caused by: org.infinispan.util.concurrent.TimeoutException: ISPN000476: Timed out waiting for responses for request 2 from 0125f36a-2860-4107-810a-d087224c9105-21637
> {noformat}
> 2:
> {noformat}
> 2018-07-03 09:12:55,788 WARN [Camel (camel-1) thread #2 - seda://northboundProvider] (TransactionImpl.java:429) - ISPN000927: exception while committing
> javax.transaction.xa.XAException: null
> at org.infinispan.transaction.impl.TransactionCoordinator.rollback(TransactionCoordinator.java:180) ~[infinispan-embedded-9.3.0.Final.jar:9.3.0.Final]
> at org.infinispan.transaction.xa.XaTransactionTable.rollback(XaTransactionTable.java:137) ~[infinispan-embedded-9.3.0.Final.jar:9.3.0.Final]
> at org.infinispan.transaction.xa.TransactionXaAdapter.rollback(TransactionXaAdapter.java:76) ~[infinispan-embedded-9.3.0.Final.jar:9.3.0.Final]
> at org.infinispan.commons.tx.TransactionImpl.finishResource(TransactionImpl.java:424) [infinispan-embedded-9.3.0.Final.jar:9.3.0.Final]
> at org.infinispan.commons.tx.TransactionImpl.rollbackResources(TransactionImpl.java:477) [infinispan-embedded-9.3.0.Final.jar:9.3.0.Final]
> at org.infinispan.commons.tx.TransactionImpl.runCommit(TransactionImpl.java:332) [infinispan-embedded-9.3.0.Final.jar:9.3.0.Final]
> at org.infinispan.commons.tx.TransactionImpl.rollback(TransactionImpl.java:132) [infinispan-embedded-9.3.0.Final.jar:9.3.0.Final]
> at org.infinispan.commons.tx.TransactionManagerImpl.rollback(TransactionManagerImpl.java:80) [infinispan-embedded-9.3.0.Final.jar:9.3.0.Final]
> at org.infinispan.cache.impl.CacheImpl.tryRollback(CacheImpl.java:1801) [infinispan-embedded-9.3.0.Final.jar:9.3.0.Final]
> at org.infinispan.cache.impl.CacheImpl.executeCommandWithInjectedTx(CacheImpl.java:1731) [infinispan-embedded-9.3.0.Final.jar:9.3.0.Final]
> at org.infinispan.cache.impl.CacheImpl.executeCommandAndCommitIfNeeded(CacheImpl.java:1707) [infinispan-embedded-9.3.0.Final.jar:9.3.0.Final]
> at org.infinispan.cache.impl.CacheImpl.put(CacheImpl.java:1370) [infinispan-embedded-9.3.0.Final.jar:9.3.0.Final]
> at org.infinispan.cache.impl.DecoratedCache.put(DecoratedCache.java:655) [infinispan-embedded-9.3.0.Final.jar:9.3.0.Final]
> at org.infinispan.cache.impl.DecoratedCache.put(DecoratedCache.java:544) [infinispan-embedded-9.3.0.Final.jar:9.3.0.Final]
> at org.infinispan.cache.impl.AbstractDelegatingCache.put(AbstractDelegatingCache.java:358) [infinispan-embedded-9.3.0.Final.jar:9.3.0.Final]
> at org.infinispan.cache.impl.EncoderCache.put(EncoderCache.java:674) [infinispan-embedded-9.3.0.Final.jar:9.3.0.Final]
> .....
> Caused by: org.infinispan.util.concurrent.TimeoutException: ISPN000476: Timed out waiting for responses for request 1043 from 0075f36a-2860-4107-810a-d087224c9105-32070
> {noformat}
> in attached zip including
> -infinispan logs from all nodes
> -cluster config
> -jgroups health status csv files from nodes(comma separated, time in csv is 2hours before time in logs)
--
This message was sent by Atlassian Jira
(v7.13.8#713008)
6 years