[infinispan-issues] [JBoss JIRA] (ISPN-11172) GracefulShutdownRestartIT fails
Dan Berindei (Jira)
issues at jboss.org
Fri Jan 24 11:36:40 EST 2020
[ https://issues.redhat.com/browse/ISPN-11172?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13956367#comment-13956367 ]
Dan Berindei commented on ISPN-11172:
-------------------------------------
I found an exception in the container output:
{noformat}
18:15:05,923 WARN (jgroups-8,05ea2c1c87a5-30319) [CLUSTER] ISPN000071: Caught exception when handling command CacheTopologyControlCommand{cache=___script_cache, type=SHUTDOWN_REQUEST, sender=null, joinInfo=null, topologyId=0, rebalanceId=0, currentCH=null, pendingCH=null, availabilityMode=null, phase=null, actualMembers=null, throwable=null, viewId=0} org.infinispan.remoting.RemoteException: ISPN000217: Received exception from 05ea2c1c87a5-30319, see cause for remote stack trace
at org.infinispan.remoting.transport.ResponseCollectors.wrapRemoteException(ResponseCollectors.java:25)
at org.infinispan.remoting.transport.impl.VoidResponseCollector.addException(VoidResponseCollector.java:46)
at org.infinispan.remoting.transport.impl.VoidResponseCollector.addException(VoidResponseCollector.java:18)
at org.infinispan.remoting.transport.ValidResponseCollector.addResponse(ValidResponseCollector.java:29)
at org.infinispan.topology.TopologyManagementHelper.lambda$addLocalResult$2(TopologyManagementHelper.java:135)
at java.base/java.util.concurrent.CompletableFuture.uniHandle(CompletableFuture.java:930)
at java.base/java.util.concurrent.CompletableFuture.uniHandleStage(CompletableFuture.java:946)
at java.base/java.util.concurrent.CompletableFuture.handle(CompletableFuture.java:2266)
at org.infinispan.topology.TopologyManagementHelper.lambda$addLocalResult$3(TopologyManagementHelper.java:131)
at java.base/java.util.concurrent.CompletableFuture$UniCompose.tryFire(CompletableFuture.java:1072)
at java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:506)
at java.base/java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:2073)
at org.infinispan.remoting.transport.AbstractRequest.complete(AbstractRequest.java:67)
at org.infinispan.remoting.transport.impl.MultiTargetRequest.onResponse(MultiTargetRequest.java:104)
at org.infinispan.remoting.transport.impl.RequestRepository.addResponse(RequestRepository.java:52)
at org.infinispan.remoting.transport.jgroups.JGroupsTransport.processResponse(JGroupsTransport.java:1411)
at org.infinispan.remoting.transport.jgroups.JGroupsTransport.processMessage(JGroupsTransport.java:1314)
at org.infinispan.remoting.transport.jgroups.JGroupsTransport.access$300(JGroupsTransport.java:129)
at org.infinispan.remoting.transport.jgroups.JGroupsTransport$ChannelCallbacks.up(JGroupsTransport.java:1459)
at org.jgroups.JChannel.up(JChannel.java:775)
at org.jgroups.stack.ProtocolStack.up(ProtocolStack.java:920)
at org.jgroups.protocols.FlowControl.up(FlowControl.java:338)
at org.jgroups.protocols.FlowControl.up(FlowControl.java:338)
at org.jgroups.protocols.tom.TOA.up(TOA.java:119)
at org.jgroups.protocols.pbcast.GMS.up(GMS.java:859)
at org.jgroups.protocols.pbcast.STABLE.up(STABLE.java:243)
at org.jgroups.protocols.UNICAST3.deliverMessage(UNICAST3.java:1049)
at org.jgroups.protocols.UNICAST3.addMessage(UNICAST3.java:772)
at org.jgroups.protocols.UNICAST3.handleDataReceived(UNICAST3.java:753)
at org.jgroups.protocols.UNICAST3.up(UNICAST3.java:405)
at org.jgroups.protocols.pbcast.NAKACK2.up(NAKACK2.java:592)
at org.jgroups.protocols.VERIFY_SUSPECT.up(VERIFY_SUSPECT.java:132)
at org.jgroups.protocols.FD_ALL.up(FD_ALL.java:205)
at org.jgroups.protocols.FD_SOCK.up(FD_SOCK.java:254)
at org.jgroups.protocols.MERGE3.up(MERGE3.java:285)
at org.jgroups.protocols.Discovery.up(Discovery.java:300)
at org.jgroups.protocols.TP.passMessageUp(TP.java:1367)
at org.jgroups.util.SubmitToThreadPool$SingleMessageHandler.run(SubmitToThreadPool.java:89)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
at java.base/java.lang.Thread.run(Thread.java:834)
Caused by: org.infinispan.remoting.RemoteException: ISPN000217: Received exception from 05ea2c1c87a5-30319, see cause for remote stack trace
at org.infinispan.topology.TopologyManagementHelper.makeResponse(TopologyManagementHelper.java:144)
at org.infinispan.topology.TopologyManagementHelper.lambda$addLocalResult$2(TopologyManagementHelper.java:132)
... 36 more
Caused by: java.lang.NullPointerException
at org.infinispan.topology.LocalTopologyManagerImpl.handleCacheShutdown(LocalTopologyManagerImpl.java:743)
at org.infinispan.topology.CacheTopologyControlCommand.doPerform(CacheTopologyControlCommand.java:189)
at org.infinispan.topology.CacheTopologyControlCommand.invokeAsync(CacheTopologyControlCommand.java:160)
at org.infinispan.topology.TopologyManagementHelper.executeOnClusterSync(TopologyManagementHelper.java:54)
at org.infinispan.topology.ClusterTopologyManagerImpl.broadcastShutdownCache(ClusterTopologyManagerImpl.java:734)
at org.infinispan.topology.ClusterCacheStatus.shutdownCache(ClusterCacheStatus.java:951)
at org.infinispan.topology.ClusterTopologyManagerImpl.handleShutdownRequest(ClusterTopologyManagerImpl.java:749)
at org.infinispan.topology.CacheTopologyControlCommand.doPerform(CacheTopologyControlCommand.java:174)
at org.infinispan.topology.CacheTopologyControlCommand.invokeAsync(CacheTopologyControlCommand.java:160)
at org.infinispan.remoting.inboundhandler.GlobalInboundInvocationHandler$ReplicableCommandRunner.run(GlobalInboundInvocationHandler.java:160)
at org.infinispan.util.concurrent.BlockingTaskAwareExecutorServiceImpl$RunnableWrapper.run(BlockingTaskAwareExecutorServiceImpl.java:215)
... 3 more
{noformat}
We need to do more to ensure that any remote commands processed during shutdown return a {{CacheNotFoundResponse}} instead of throwing random exceptions.
> GracefulShutdownRestartIT fails
> -------------------------------
>
> Key: ISPN-11172
> URL: https://issues.redhat.com/browse/ISPN-11172
> Project: Infinispan
> Issue Type: Bug
> Affects Versions: 10.1.0.Final
> Reporter: Tristan Tarrant
> Assignee: Tristan Tarrant
> Priority: Major
>
> {noformat}
> Error Message
> Cluster did not shutdown within timeout
> Stacktrace
> java.lang.AssertionError: Cluster did not shutdown within timeout
> at org.infinispan.commons.util.Eventually.lambda$eventually$0(Eventually.java:33)
> at org.infinispan.commons.util.Eventually.eventually(Eventually.java:25)
> at org.infinispan.commons.util.Eventually.eventually(Eventually.java:33)
> at org.infinispan.server.resilience.GracefulShutdownRestartIT.testGracefulShutdownRestart(GracefulShutdownRestartIT.java:50)
> at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
> at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.base/java.lang.reflect.Method.invoke(Method.java:566)
> at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
> at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
> at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
> at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
> at org.infinispan.server.test.InfinispanServerTestMethodRule$1.evaluate(InfinispanServerTestMethodRule.java:69)
> at org.junit.rules.RunRules.evaluate(RunRules.java:20)
> at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
> at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
> at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
> at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
> at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
> at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
> at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
> at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
> at org.infinispan.server.test.InfinispanServerRule$1.evaluate(InfinispanServerRule.java:90)
> at org.junit.rules.RunRules.evaluate(RunRules.java:20)
> at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
> at org.junit.runners.Suite.runChild(Suite.java:128)
> at org.junit.runners.Suite.runChild(Suite.java:27)
> at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
> at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
> at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
> at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
> at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
> at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
> at org.apache.maven.surefire.junitcore.JUnitCore.run(JUnitCore.java:55)
> at org.apache.maven.surefire.junitcore.JUnitCoreWrapper.createRequestAndRun(JUnitCoreWrapper.java:137)
> at org.apache.maven.surefire.junitcore.JUnitCoreWrapper.executeEager(JUnitCoreWrapper.java:107)
> at org.apache.maven.surefire.junitcore.JUnitCoreWrapper.execute(JUnitCoreWrapper.java:83)
> at org.apache.maven.surefire.junitcore.JUnitCoreWrapper.execute(JUnitCoreWrapper.java:75)
> at org.apache.maven.surefire.junitcore.JUnitCoreProvider.invoke(JUnitCoreProvider.java:158)
> at org.apache.maven.surefire.booter.ForkedBooter.invokeProviderInSameClassLoader(ForkedBooter.java:384)
> at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:345)
> at org.apache.maven.surefire.booter.ForkedBooter.execute(ForkedBooter.java:126)
> at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:418)
> Standard Output
> [OK: 131, KO: 0, SKIP: 0] Test starting: GracefulShutdownRestartIT.testGracefulShutdownRestart
> [0] STDOUT: 12:36:05,513 WARN (async-thread--p2-t6) [CONFIG] ISPN000564: Configured store 'SingleFileStore' is segmented and may use a large number of file descriptors[m
> [0] STDOUT: 12:36:05,514 WARN (async-thread--p2-t6) [CONFIG] ISPN000149: Fetch persistent state and purge on startup are both disabled, cache may contain stale entries on startup[m
> [0] STDOUT: 12:36:05,515 WARN (async-thread--p2-t6) [CONFIG] ISPN000149: Fetch persistent state and purge on startup are both disabled, cache may contain stale entries on startup[m
> [1] STDOUT: 12:36:05,558 WARN (remote-thread--p3-t2) [CONFIG] ISPN000564: Configured store 'SingleFileStore' is segmented and may use a large number of file descriptors[m
> [1] STDOUT: 12:36:05,560 WARN (remote-thread--p3-t2) [CONFIG] ISPN000149: Fetch persistent state and purge on startup are both disabled, cache may contain stale entries on startup[m
> [1] STDOUT: 12:36:05,562 WARN (remote-thread--p3-t2) [CONFIG] ISPN000149: Fetch persistent state and purge on startup are both disabled, cache may contain stale entries on startup[m
> [0] STDOUT: 12:36:05,771 WARN (jgroups-13,06978f4151c0-63390) [CONFIG] ISPN000149: Fetch persistent state and purge on startup are both disabled, cache may contain stale entries on startup[m
> [0] STDOUT: 12:36:05,776 WARN (jgroups-13,06978f4151c0-63390) [CONFIG] ISPN000149: Fetch persistent state and purge on startup are both disabled, cache may contain stale entries on startup[m
> [0] STDOUT: 12:36:05,883 INFO (transport-thread--p5-t7) [CLUSTER] [Context=C3F31F9D169B25D0C68FE5A26A6600FFA0E2E3F4]ISPN100002: Starting rebalance with members [63781b79183e-43839, 06978f4151c0-63390], phase READ_OLD_WRITE_ALL, topology id 2[m
> [0] STDOUT: 12:36:05,963 INFO (remote-thread--p3-t1) [CLUSTER] [Context=C3F31F9D169B25D0C68FE5A26A6600FFA0E2E3F4]ISPN100009: Advancing to rebalance phase READ_ALL_WRITE_ALL, topology id 3[m
> [0] STDOUT: 12:36:05,978 INFO (remote-thread--p3-t1) [CLUSTER] [Context=C3F31F9D169B25D0C68FE5A26A6600FFA0E2E3F4]ISPN100009: Advancing to rebalance phase READ_NEW_WRITE_ALL, topology id 4[m
> [0] STDOUT: 12:36:05,985 INFO (async-thread--p2-t17) [CLUSTER] [Context=C3F31F9D169B25D0C68FE5A26A6600FFA0E2E3F4]ISPN100010: Finished rebalance with members [63781b79183e-43839, 06978f4151c0-63390], topology id 5[m
> [0] STDERR: WARNING: An illegal reflective access operation has occurred
> [0] STDERR: WARNING: Illegal reflective access by protostream.com.google.protobuf.UnsafeUtil (file:/opt/infinispan/lib/protostream-4.3.1.Final.jar) to field java.nio.Buffer.address
> [0] STDERR: WARNING: Please consider reporting this to the maintainers of protostream.com.google.protobuf.UnsafeUtil
> [0] STDERR: WARNING: Use --illegal-access=warn to enable warnings of further illegal reflective access operations
> [0] STDERR: WARNING: All illegal access operations will be denied in a future release
> [1] STDERR: WARNING: An illegal reflective access operation has occurred
> [1] STDERR: WARNING: Illegal reflective access by protostream.com.google.protobuf.UnsafeUtil (file:/opt/infinispan/lib/protostream-4.3.1.Final.jar) to field java.nio.Buffer.address
> [1] STDERR: WARNING: Please consider reporting this to the maintainers of protostream.com.google.protobuf.UnsafeUtil
> [1] STDERR: WARNING: Use --illegal-access=warn to enable warnings of further illegal reflective access operations
> [1] STDERR: WARNING: All illegal access operations will be denied in a future release
> [0] STDOUT: 12:36:06,811 INFO (SINGLE_PORT-ServerIO-8-2) [CLUSTER] [Context=___protobuf_metadata]ISPN100008: Updating cache members list [63781b79183e-43839], topology id 6[m
> [0] STDOUT: 12:36:06,860 INFO (SINGLE_PORT-ServerIO-8-2) [CLUSTER] [Context=C3F31F9D169B25D0C68FE5A26A6600FFA0E2E3F4]ISPN100008: Updating cache members list [63781b79183e-43839], topology id 6[m
> [0] STDOUT: 12:36:06,898 INFO (SINGLE_PORT-ServerIO-8-2) [CLUSTER] [Context=memcachedCache]ISPN100008: Updating cache members list [63781b79183e-43839], topology id 6[m
> [1] STDOUT: 12:36:06,904 WARN (remote-thread--p3-t2) [CLUSTER] ISPN000071: Caught exception when handling command CacheTopologyControlCommand{cache=___script_cache, type=SHUTDOWN_PERFORM, sender=null, joinInfo=null, topologyId=0, rebalanceId=0, currentCH=null, pendingCH=null, availabilityMode=null, phase=null, actualMembers=null, throwable=null, viewId=0} java.lang.NullPointerException
> [1] STDOUT: at org.infinispan.topology.LocalTopologyManagerImpl.handleCacheShutdown(LocalTopologyManagerImpl.java:743)
> [1] STDOUT: at org.infinispan.topology.CacheTopologyControlCommand.doPerform(CacheTopologyControlCommand.java:189)
> [1] STDOUT: at org.infinispan.topology.CacheTopologyControlCommand.invokeAsync(CacheTopologyControlCommand.java:160)
> [1] STDOUT: at org.infinispan.remoting.inboundhandler.GlobalInboundInvocationHandler$ReplicableCommandRunner.run(GlobalInboundInvocationHandler.java:160)
> [1] STDOUT: at org.infinispan.util.concurrent.BlockingTaskAwareExecutorServiceImpl$RunnableWrapper.run(BlockingTaskAwareExecutorServiceImpl.java:215)
> [1] STDOUT: at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
> [1] STDOUT: at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
> [1] STDOUT: at java.base/java.lang.Thread.run(Thread.java:834)
> [1] STDOUT: [m
> {noformat}
--
This message was sent by Atlassian Jira
(v7.13.8#713008)
More information about the infinispan-issues
mailing list