[JBoss JIRA] (ISPN-5507) Transactions committed immediately before cache stop can block shutdown
by Sebastian Łaskawiec (JIRA)
[ https://issues.jboss.org/browse/ISPN-5507?page=com.atlassian.jira.plugin.... ]
Sebastian Łaskawiec closed ISPN-5507.
-------------------------------------
> Transactions committed immediately before cache stop can block shutdown
> -----------------------------------------------------------------------
>
> Key: ISPN-5507
> URL: https://issues.jboss.org/browse/ISPN-5507
> Project: Infinispan
> Issue Type: Bug
> Components: Core, Test Suite - Core
> Affects Versions: 7.2.1.Final, 8.0.0.Alpha1
> Reporter: Dan Berindei
> Assignee: Dan Berindei
> Priority: Blocker
> Labels: testsuite_stability
> Fix For: 8.2.1.Final, 9.0.0.Alpha1
>
>
> This is causing random failures in {{DistributedEntryRetrieverTxTest.verifyNodeLeavesBeforeGettingData}}.
> The test inserts some values into the cache, starts an iteration, and then kills one of the nodes. In rare instances, the killed cache only receives the TxCompletionCommand for one of the writes after it started the shutdown, and ignores it. That leaves the remote tx on-going, and {{TransactionTable.shutDownGracefully()}} blocks for 30 seconds - causing a {{TimeoutException}} elsewhere in the test.
> {noformat}
> 10:52:18,129 TRACE (remote-thread-NodeAM-p12133-t6:) [CommandAwareRpcDispatcher] About to send back response SuccessfulResponse{responseValue=null} for command CommitCommand {gtx=GlobalTransaction:<NodeAL-45757>:22325:remote, cacheName='org.infinispan.iteration.DistributedEntryRetrieverTxTest', topologyId=4}
> 10:52:18,129 TRACE (testng-DistributedEntryRetrieverTxTest:) [JGroupsTransport] dests=[NodeAM-45518, NodeAL-45757], command=TxCompletionNotificationCommand{ xid=null, internalId=0, topologyId=4, gtx=GlobalTransaction:<NodeAL-45757>:22325:local, cacheName=org.infinispan.iteration.DistributedEntryRetrieverTxTest} , mode=ASYNCHRONOUS, timeout=15000
> 10:52:18,133 DEBUG (testng-DistributedEntryRetrieverTxTest:) [CacheImpl] Stopping cache org.infinispan.iteration.DistributedEntryRetrieverTxTest on NodeAM-45518
> 10:52:18,133 TRACE (OOB-2,NodeAM-45518:) [GlobalInboundInvocationHandler] Attempting to execute CacheRpcCommand: TxCompletionNotificationCommand{ xid=null, internalId=0, topologyId=4, gtx=GlobalTransaction:<NodeAL-45757>:22325:local, cacheName=org.infinispan.iteration.DistributedEntryRetrieverTxTest} [sender=NodeAL-45757]
> 10:52:18,133 TRACE (OOB-2,NodeAM-45518:) [GlobalInboundInvocationHandler] Silently ignoring that org.infinispan.iteration.DistributedEntryRetrieverTxTest cache is not defined
> 10:52:18,133 DEBUG (testng-DistributedEntryRetrieverTxTest:) [TransactionTable] Wait for on-going transactions to finish for 30 seconds.
> 10:52:48,139 WARN (testng-DistributedEntryRetrieverTxTest:) [TransactionTable] ISPN000100: Stopping, but there are 0 local transactions and 1 remote transactions that did not finish in time.
> 10:52:48,386 ERROR (testng-DistributedEntryRetrieverTxTest:) [UnitTestTestNGListener] Test verifyNodeLeavesBeforeGettingData(org.infinispan.iteration.DistributedEntryRetrieverTxTest) failed.
> java.lang.IllegalStateException: Thread already timed out waiting for event pre_send_response_released
> at org.infinispan.test.fwk.CheckPoint.trigger(CheckPoint.java:131)
> at org.infinispan.test.fwk.CheckPoint.trigger(CheckPoint.java:116)
> at org.infinispan.iteration.DistributedEntryRetrieverTest.verifyNodeLeavesBeforeGettingData(DistributedEntryRetrieverTest.java:105)
> {noformat}
--
This message was sent by Atlassian JIRA
(v6.4.11#64026)
8 years, 1 month
[JBoss JIRA] (ISPN-3037) Failing test: MixedModeTest.testMixedMode:72 NullPointer
by Sebastian Łaskawiec (JIRA)
[ https://issues.jboss.org/browse/ISPN-3037?page=com.atlassian.jira.plugin.... ]
Sebastian Łaskawiec closed ISPN-3037.
-------------------------------------
> Failing test: MixedModeTest.testMixedMode:72 NullPointer
> --------------------------------------------------------
>
> Key: ISPN-3037
> URL: https://issues.jboss.org/browse/ISPN-3037
> Project: Infinispan
> Issue Type: Bug
> Components: Test Suite - Core
> Affects Versions: 8.2.0.Final
> Reporter: Sanne Grinovero
> Assignee: Dan Berindei
> Labels: testsuite_stability
> Fix For: 8.2.1.Final, 9.0.0.Alpha1, 9.0.0.Final
>
>
> ~~~~~~~~~~~~~~~~~~~~~~~~~ ENVIRONMENT INFO ~~~~~~~~~~~~~~~~~~~~~~~~~~
> jgroups.bind_addr = 127.0.0.1
> java.runtime.version = 1.6.0_43-b01
> java.runtime.name =Java(TM) SE Runtime Environment
> java.vm.version = 20.14-b01
> java.vm.vendor = Sun Microsystems Inc.
> os.name = Linux
> os.version = 3.8.8-202.fc18.x86_64
> sun.arch.data.model = 64
> sun.cpu.endian = little
> protocol.stack = null
> infinispan.test.jgroups.protocol = tcp
> infinispan.unsafe.allow_jdk8_chm = true
> java.net.preferIPv4Stack = true
> java.net.preferIPv6Stack = null
> log4.configuration = null
> MAVEN_OPTS = null
> ~~~~~~~~~~~~~~~~~~~~~~~~~ ENVIRONMENT INFO ~~~~~~~~~~~~~~~~~~~~~~~~~~
> Tests run: 2911, Failures: 1, Errors: 0, Skipped: 0, Time elapsed: 212.448 sec <<< FAILURE!
> testMixedMode(org.infinispan.api.MixedModeTest) Time elapsed: 0.03 sec <<< FAILURE!
> java.lang.NullPointerException
> at org.infinispan.api.MixedModeTest.testMixedMode(MixedModeTest.java:72)
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
> at java.lang.reflect.Method.invoke(Method.java:597)
> at org.testng.internal.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:80)
> at org.testng.internal.Invoker.invokeMethod(Invoker.java:714)
> at org.testng.internal.Invoker.invokeTestMethod(Invoker.java:901)
> at org.testng.internal.Invoker.invokeTestMethods(Invoker.java:1231)
> at org.testng.internal.TestMethodWorker.invokeTestMethods(TestMethodWorker.java:127)
> at org.testng.internal.TestMethodWorker.run(TestMethodWorker.java:111)
> at org.testng.TestRunner.privateRun(TestRunner.java:767)
> at org.testng.TestRunner.run(TestRunner.java:617)
> at org.testng.SuiteRunner.runTest(SuiteRunner.java:334)
> at org.testng.SuiteRunner.access$000(SuiteRunner.java:37)
> at org.testng.SuiteRunner$SuiteWorker.run(SuiteRunner.java:368)
> at org.testng.internal.thread.ThreadUtil$2.call(ThreadUtil.java:64)
> at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
> at java.util.concurrent.FutureTask.run(FutureTask.java:138)
> at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:895)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:918)
> at java.lang.Thread.run(Thread.java:662)
> Results :
> Failed tests:
> MixedModeTest.testMixedMode:72 NullPointer
> Tests run: 2911, Failures: 1, Errors: 0, Skipped: 0
--
This message was sent by Atlassian JIRA
(v6.4.11#64026)
8 years, 1 month
[JBoss JIRA] (ISPN-6351) ClusterExecutor submitConsumer can complete before local thread completes
by Sebastian Łaskawiec (JIRA)
[ https://issues.jboss.org/browse/ISPN-6351?page=com.atlassian.jira.plugin.... ]
Sebastian Łaskawiec closed ISPN-6351.
-------------------------------------
> ClusterExecutor submitConsumer can complete before local thread completes
> -------------------------------------------------------------------------
>
> Key: ISPN-6351
> URL: https://issues.jboss.org/browse/ISPN-6351
> Project: Infinispan
> Issue Type: Bug
> Components: Distributed Execution and Map/Reduce
> Affects Versions: 8.2.0.Final
> Reporter: William Burns
> Assignee: William Burns
> Fix For: 8.2.1.Final, 9.0.0.Alpha1
>
>
> The ClusterExecutor test can fail spuriously. Below is the trace output.
> {code}
> 10:36:07,855 INFO (testng-ClusterExecutorTest:) [UnitTestTestNGListener] Test suite progress: tests succeeded: 236, failed: 0, skipped: 0.
> 10:36:07,855 INFO (testng-ClusterExecutorTest:) [UnitTestTestNGListener] Starting test testExecutorTriConsumer(org.infinispan.manager.ClusterExecutorTest)
> 10:36:07,857 DEBUG (testng-ClusterExecutorTest:) [ServiceFinder] No service impls found: ModuleLifecycle
> 10:36:07,857 DEBUG (testng-ClusterExecutorTest:) [ServiceFinder] Loading service impl: CoreTestMetadataFileFinder
> 10:36:07,861 DEBUG (testng-ClusterExecutorTest:) [ServiceFinder] Loading service impl: TestModuleCommandExtensions
> 10:36:07,861 DEBUG (testng-ClusterExecutorTest:) [ModuleProperties] Loading module command extension SPI class: org.infinispan.remoting.rpc.TestModuleCommandExtensions@50408d95
> 10:36:07,865 INFO (testng-ClusterExecutorTest:) [JGroupsTransport] ISPN000078: Starting JGroups channel ISPN
> 10:36:07,870 DEBUG (testng-ClusterExecutorTest:) [Configurator] set property TCP_NIO2.diagnostics_addr to default value /224.0.75.75
> 10:36:07,871 TRACE (testng-ClusterExecutorTest:) [NAKACK2] null: set max_xmit_req_size from 0 to 247600
> 10:36:07,871 TRACE (testng-ClusterExecutorTest:) [UNICAST3] null: set max_xmit_req_size from 0 to 247600
> 10:36:07,871 TRACE (testng-ClusterExecutorTest:) [MessageDispatcher] setting local_addr (null) to NodeV-57636
> 10:36:07,871 TRACE (testng-ClusterExecutorTest:) [STABLE] NodeV-57636: stable task started
> 10:36:07,871 TRACE (testng-ClusterExecutorTest:) [TEST_PING] Discovery.stopped=false
> 10:36:07,872 DEBUG (testng-ClusterExecutorTest:) [GMS] address=NodeV-57636, cluster=ISPN, physical address=127.0.0.1:9000
> 10:36:07,872 TRACE (testng-ClusterExecutorTest:) [TEST_PING] Discoveries for DiscoveryKey{clusterName='ISPN', testName='org.infinispan.manager.ClusterExecutorTest'} are : {}
> 10:36:07,872 TRACE (testng-ClusterExecutorTest:) [TEST_PING] Add discovery for NodeV-57636 to cache. The cache now contains: {NodeV-57636=TEST_PING@NodeV-57636}
> 10:36:07,872 TRACE (testng-ClusterExecutorTest:) [TEST_PING] Skipping sending discovery to self
> 10:36:07,872 TRACE (testng-ClusterExecutorTest:) [GMS] NodeV-57636: no members discovered after 0 ms: creating cluster as first member
> 10:36:07,872 DEBUG (testng-ClusterExecutorTest:) [NAKACK2]
> [NodeV-57636 setDigest()]
> existing digest: []
> new digest: NodeV-57636: [0 (0)]
> resulting digest: NodeV-57636: [0 (0)]
> 10:36:07,872 DEBUG (testng-ClusterExecutorTest:) [GMS] NodeV-57636: installing view [NodeV-57636|0] (1) [NodeV-57636]
> 10:36:07,872 DEBUG (testng-ClusterExecutorTest:) [STABLE] resuming message garbage collection
> 10:36:07,872 TRACE (testng-ClusterExecutorTest:) [STABLE] NodeV-57636: reset digest to NodeV-57636: [-1]
> 10:36:07,872 TRACE (testng-ClusterExecutorTest:) [TOA] Handle view [NodeV-57636|0] (1) [NodeV-57636]
> 10:36:07,872 TRACE (testng-ClusterExecutorTest:) [MFC] new membership: [NodeV-57636]
> 10:36:07,872 DEBUG (testng-ClusterExecutorTest:) [JGroupsTransport] New view accepted: [NodeV-57636|0] (1) [NodeV-57636]
> 10:36:07,872 INFO (testng-ClusterExecutorTest:) [JGroupsTransport] ISPN000094: Received new cluster view for channel ISPN: [NodeV-57636|0] (1) [NodeV-57636]
> 10:36:07,872 TRACE (testng-ClusterExecutorTest:) [STABLE] NodeV-57636: reset digest to NodeV-57636: [-1]
> 10:36:07,872 DEBUG (testng-ClusterExecutorTest:) [STABLE] resuming message garbage collection
> 10:36:07,872 DEBUG (testng-ClusterExecutorTest:) [GMS] NodeV-57636: created cluster (first member). My view is [NodeV-57636|0], impl is org.jgroups.protocols.pbcast.CoordGmsImpl
> 10:36:07,872 INFO (testng-ClusterExecutorTest:) [JGroupsTransport] ISPN000079: Channel ISPN local address is NodeV-57636, physical addresses are [127.0.0.1:9000]
> 10:36:07,872 TRACE (testng-ClusterExecutorTest:) [JGroupsTransport] Waiting on view 0 being accepted
> 10:36:07,872 TRACE (testng-ClusterExecutorTest:) [SemaphoreCompletionService] New task submitted, tasks in queue 1, available permits 1
> 10:36:07,872 TRACE (testng-ClusterExecutorTest:) [LocalTopologyManagerImpl] Starting LocalTopologyManager on NodeV-57636
> 10:36:07,872 TRACE (transport-thread-NodeV-p1249-t1:) [SemaphoreCompletionService] Task started, tasks in queue 0, available permits 0
> 10:36:07,872 DEBUG (testng-ClusterExecutorTest:) [DefaultCacheManager] Started cache manager ISPN on NodeV
> 10:36:07,872 TRACE (transport-thread-NodeV-p1249-t1:) [ClusterTopologyManagerImpl] Received new cluster view: 0, isCoordinator = true, old status = INITIALIZING
> 10:36:07,872 DEBUG (transport-thread-NodeV-p1249-t1:) [ClusterTopologyManagerImpl] Recovering cluster status for view 0
> 10:36:07,872 TRACE (transport-thread-NodeV-p1249-t1:) [JGroupsTransport] dests=null, command=CacheTopologyControlCommand{cache=null, type=GET_STATUS, sender=NodeV-57636, joinInfo=null, topologyId=0, rebalanceId=0, currentCH=null, pendingCH=null, availabilityMode=null, actualMembers=null, throwable=null, viewId=0}, mode=SYNCHRONOUS, timeout=240000
> 10:36:07,873 TRACE (transport-thread-NodeV-p1249-t1:) [ClusterTopologyManagerImpl] Attempting to execute command on self: CacheTopologyControlCommand{cache=null, type=GET_STATUS, sender=NodeV-57636, joinInfo=null, topologyId=0, rebalanceId=0, currentCH=null, pendingCH=null, availabilityMode=null, actualMembers=null, throwable=null, viewId=0}
> 10:36:07,873 TRACE (transport-thread-NodeV-p1249-t1:) [JGroupsTransport] Waiting on view 0 being accepted
> 10:36:07,873 DEBUG (transport-thread-NodeV-p1249-t1:) [LocalTopologyManagerImpl] Sending cluster status response for view 0
> 10:36:07,873 DEBUG (transport-thread-NodeV-p1249-t1:) [ClusterTopologyManagerImpl] Got 1 status responses. members are [NodeV-57636]
> 10:36:07,873 TRACE (transport-thread-NodeV-p1249-t1:) [ClusterTopologyManagerImpl] Updating cluster members for all the caches. New list is [NodeV-57636]
> 10:36:07,873 TRACE (transport-thread-NodeV-p1249-t1:) [JGroupsTransport] dests=null, command=CacheTopologyControlCommand{cache=null, type=POLICY_GET_STATUS, sender=NodeV-57636, joinInfo=null, topologyId=0, rebalanceId=0, currentCH=null, pendingCH=null, availabilityMode=null, actualMembers=null, throwable=null, viewId=-1}, mode=SYNCHRONOUS, timeout=240000
> 10:36:07,873 TRACE (transport-thread-NodeV-p1249-t1:) [SemaphoreCompletionService] Task finished, tasks in queue 0, available permits 0
> 10:36:07,874 DEBUG (testng-ClusterExecutorTest:) [ServiceFinder] No service impls found: ModuleLifecycle
> 10:36:07,874 DEBUG (testng-ClusterExecutorTest:) [ServiceFinder] Loading service impl: CoreTestMetadataFileFinder
> 10:36:07,878 DEBUG (testng-ClusterExecutorTest:) [ServiceFinder] Loading service impl: TestModuleCommandExtensions
> 10:36:07,878 DEBUG (testng-ClusterExecutorTest:) [ModuleProperties] Loading module command extension SPI class: org.infinispan.remoting.rpc.TestModuleCommandExtensions@7dd5c371
> 10:36:07,880 INFO (testng-ClusterExecutorTest:) [JGroupsTransport] ISPN000078: Starting JGroups channel ISPN
> 10:36:07,888 DEBUG (testng-ClusterExecutorTest:) [Configurator] set property TCP_NIO2.diagnostics_addr to default value /224.0.75.75
> 10:36:07,889 TRACE (testng-ClusterExecutorTest:) [NAKACK2] null: set max_xmit_req_size from 0 to 247600
> 10:36:07,889 TRACE (testng-ClusterExecutorTest:) [UNICAST3] null: set max_xmit_req_size from 0 to 247600
> 10:36:07,889 TRACE (testng-ClusterExecutorTest:) [MessageDispatcher] setting local_addr (null) to NodeW-53871
> 10:36:07,889 TRACE (testng-ClusterExecutorTest:) [STABLE] NodeW-53871: stable task started
> 10:36:07,889 TRACE (testng-ClusterExecutorTest:) [TEST_PING] Discovery.stopped=false
> 10:36:07,890 DEBUG (testng-ClusterExecutorTest:) [GMS] address=NodeW-53871, cluster=ISPN, physical address=127.0.0.1:9001
> 10:36:07,890 TRACE (testng-ClusterExecutorTest:) [TEST_PING] Discoveries for DiscoveryKey{clusterName='ISPN', testName='org.infinispan.manager.ClusterExecutorTest'} are : {NodeV-57636=TEST_PING@NodeV-57636}
> 10:36:07,890 TRACE (testng-ClusterExecutorTest:) [TEST_PING] Add discovery for NodeW-53871 to cache. The cache now contains: {NodeV-57636=TEST_PING@NodeV-57636, NodeW-53871=TEST_PING@NodeW-53871}
> 10:36:07,890 TRACE (testng-ClusterExecutorTest:) [TEST_PING] Map NodeV-57636 with physical address 127.0.0.1:9000 in TEST_PING@NodeW-53871
> 10:36:07,890 TRACE (testng-ClusterExecutorTest:) [TEST_PING] Map NodeW-53871 with physical address 127.0.0.1:9001 in TEST_PING@NodeV-57636
> 10:36:07,890 TRACE (testng-ClusterExecutorTest:) [TEST_PING] Returning ping rsp: NodeV-57636, name=NodeV-57636, addr=127.0.0.1:9000, coord
> 10:36:07,890 TRACE (testng-ClusterExecutorTest:) [TEST_PING] Skipping sending discovery to self
> 10:36:07,890 TRACE (testng-ClusterExecutorTest:) [GMS] NodeW-53871: discovery took 0 ms, members: 1 rsps (1 coords) [done]
> 10:36:07,890 DEBUG (testng-ClusterExecutorTest:) [GMS] NodeW-53871: sending JOIN(NodeW-53871) to NodeV-57636
> 10:36:07,890 TRACE (testng-ClusterExecutorTest:) [UNICAST3] NodeW-53871: created sender window for NodeV-57636 (conn-id=0)
> 10:36:07,890 TRACE (testng-ClusterExecutorTest:) [UNICAST3] NodeW-53871 --> DATA(NodeV-57636: #1, conn_id=0, first)
> 10:36:07,890 TRACE (testng-ClusterExecutorTest:) [TCP_NIO2] NodeW-53871: sending msg to NodeV-57636, src=NodeW-53871, headers are GMS: GmsHeader[JOIN_REQ]: mbr=NodeW-53871, UNICAST3: DATA, seqno=1, first, TP: [cluster_name=ISPN]
> 10:36:07,915 TRACE (Timer-2,NodeW-53871:) [TCP_NIO2] NodeW-53871: sending 1 msgs (83 bytes (0.27% of max_bundle_size) to 1 dests(s): [ISPN:NodeV-57636]
> 10:36:07,915 TRACE (Timer-2,NodeW-53871:) [TCP_NIO2] dest=127.0.0.1:9000 (86 bytes)
> 10:36:07,915 TRACE (Timer-2,NodeW-53871:) [TCP_NIO2] 127.0.0.1:9001: connecting to 127.0.0.1:9000
> 10:36:07,917 TRACE (INT-1,NodeV-57636:) [TCP_NIO2] NodeV-57636: received [dst: NodeV-57636, src: NodeW-53871 (3 headers), size=0 bytes, flags=OOB|INTERNAL], headers are GMS: GmsHeader[JOIN_REQ]: mbr=NodeW-53871, UNICAST3: DATA, seqno=1, first, TP: [cluster_name=ISPN]
> 10:36:07,917 TRACE (INT-1,NodeV-57636:) [UNICAST3] NodeV-57636 <-- DATA(NodeW-53871: #1, conn_id=0, first)
> 10:36:07,917 TRACE (INT-1,NodeV-57636:) [UNICAST3] NodeV-57636: created receiver window for NodeW-53871 at seqno=#1 for conn-id=0
> 10:36:07,917 TRACE (INT-1,NodeV-57636:) [UNICAST3] NodeV-57636: delivering NodeW-53871#1
> 10:36:07,978 TRACE (ViewHandler,NodeV-57636:) [GMS] NodeV-57636: joiners=[NodeW-53871], suspected=[], leaving=[], new view: [NodeV-57636|1] (2) [NodeV-57636, NodeW-53871]
> 10:36:07,978 DEBUG (ViewHandler,NodeV-57636:) [STABLE] suspending message garbage collection
> 10:36:07,978 DEBUG (ViewHandler,NodeV-57636:) [STABLE] NodeV-57636: resume task started, max_suspend_time=33000
> 10:36:07,978 TRACE (ViewHandler,NodeV-57636:) [GMS] NodeV-57636: mcasting view [NodeV-57636|1] (2) [NodeV-57636, NodeW-53871] (2 mbrs)
> 10:36:07,978 TRACE (ViewHandler,NodeV-57636:) [NAKACK2] NodeV-57636: sending NodeV-57636#1
> 10:36:07,978 TRACE (ViewHandler,NodeV-57636:) [TCP_NIO2] NodeV-57636: sending msg to null, src=NodeV-57636, headers are GMS: GmsHeader[VIEW], NAKACK2: [MSG, seqno=1], TP: [cluster_name=ISPN]
> 10:36:07,978 TRACE (ViewHandler,NodeV-57636:) [TCP_NIO2] NodeV-57636: looping back message [dst: <null>, src: NodeV-57636 (3 headers), size=57 bytes]
> 10:36:07,978 TRACE (Incoming-1,NodeV-57636:) [TCP_NIO2] NodeV-57636: received [dst: <null>, src: NodeV-57636 (3 headers), size=57 bytes], headers are GMS: GmsHeader[VIEW], NAKACK2: [MSG, seqno=1], TP: [cluster_name=ISPN]
> 10:36:07,978 TRACE (Incoming-1,NodeV-57636:) [NAKACK2] NodeV-57636: received NodeV-57636#1
> 10:36:07,978 TRACE (Incoming-1,NodeV-57636:) [NAKACK2] NodeV-57636: delivering NodeV-57636#1-1 (1 messages)
> 10:36:07,979 TRACE (Incoming-1,NodeV-57636:) [GMS] NodeV-57636: received full view: [NodeV-57636|1] (2) [NodeV-57636, NodeW-53871]
> 10:36:07,979 DEBUG (Incoming-1,NodeV-57636:) [GMS] NodeV-57636: installing view [NodeV-57636|1] (2) [NodeV-57636, NodeW-53871]
> 10:36:07,979 TRACE (Incoming-1,NodeV-57636:) [STABLE] NodeV-57636: reset digest to NodeV-57636: [-1], NodeW-53871: [-1]
> 10:36:07,979 TRACE (Incoming-1,NodeV-57636:) [TOA] Handle view [NodeV-57636|1] (2) [NodeV-57636, NodeW-53871]
> 10:36:07,979 TRACE (Incoming-1,NodeV-57636:) [MFC] new membership: [NodeV-57636, NodeW-53871]
> 10:36:07,979 DEBUG (Incoming-1,NodeV-57636:) [JGroupsTransport] New view accepted: [NodeV-57636|1] (2) [NodeV-57636, NodeW-53871]
> 10:36:07,979 DEBUG (Incoming-1,NodeV-57636:) [JGroupsTransport] Joined: [NodeW-53871], Left: []
> 10:36:07,979 INFO (Incoming-1,NodeV-57636:) [JGroupsTransport] ISPN000094: Received new cluster view for channel ISPN: [NodeV-57636|1] (2) [NodeV-57636, NodeW-53871]
> 10:36:07,979 TRACE (Incoming-1,NodeV-57636:) [SemaphoreCompletionService] New task submitted, tasks in queue 1, available permits 1
> 10:36:07,979 TRACE (transport-thread-NodeV-p1249-t2:) [SemaphoreCompletionService] Task started, tasks in queue 0, available permits 0
> 10:36:07,979 TRACE (transport-thread-NodeV-p1249-t2:) [ClusterTopologyManagerImpl] Received new cluster view: 1, isCoordinator = true, old status = COORDINATOR
> 10:36:07,979 TRACE (transport-thread-NodeV-p1249-t2:) [ClusterTopologyManagerImpl] Updating cluster members for all the caches. New list is [NodeV-57636, NodeW-53871]
> 10:36:07,979 TRACE (transport-thread-NodeV-p1249-t2:) [JGroupsTransport] dests=null, command=CacheTopologyControlCommand{cache=null, type=POLICY_GET_STATUS, sender=NodeV-57636, joinInfo=null, topologyId=0, rebalanceId=0, currentCH=null, pendingCH=null, availabilityMode=null, actualMembers=null, throwable=null, viewId=-1}, mode=SYNCHRONOUS, timeout=240000
> 10:36:07,979 TRACE (transport-thread-NodeV-p1249-t2:) [CommandAwareRpcDispatcher] Replication task sending CacheTopologyControlCommand{cache=null, type=POLICY_GET_STATUS, sender=NodeV-57636, joinInfo=null, topologyId=0, rebalanceId=0, currentCH=null, pendingCH=null, availabilityMode=null, actualMembers=null, throwable=null, viewId=-1} to single recipient NodeW-53871 with response mode GET_ALL
> 10:36:07,979 TRACE (transport-thread-NodeV-p1249-t2:) [RequestCorrelator] NodeV-57636: invoking unicast RPC [req-id=1546] on NodeW-53871
> 10:36:07,979 TRACE (Incoming-1,NodeV-57636:) [UNICAST3] NodeV-57636: created sender window for NodeV-57636 (conn-id=0)
> 10:36:07,979 TRACE (transport-thread-NodeV-p1249-t2:) [UNICAST3] NodeV-57636: created sender window for NodeW-53871 (conn-id=1)
> 10:36:07,979 TRACE (Incoming-1,NodeV-57636:) [UNICAST3] NodeV-57636 --> DATA(NodeV-57636: #1, conn_id=0, first)
> 10:36:07,979 TRACE (transport-thread-NodeV-p1249-t2:) [UNICAST3] NodeV-57636 --> DATA(NodeW-53871: #1, conn_id=1, first)
> 10:36:07,979 TRACE (Incoming-1,NodeV-57636:) [TCP_NIO2] NodeV-57636: sending msg to NodeV-57636, src=NodeV-57636, headers are GMS: GmsHeader[VIEW_ACK], UNICAST3: DATA, seqno=1, first, TP: [cluster_name=ISPN]
> 10:36:07,979 TRACE (transport-thread-NodeV-p1249-t2:) [TCP_NIO2] NodeV-57636: sending msg to NodeW-53871, src=NodeV-57636, headers are RequestCorrelator: corr_id=200, type=REQ, req_id=1546, rsp_expected=true, UNICAST3: DATA, seqno=1, conn_id=1, first, TP: [cluster_name=ISPN]
> 10:36:07,979 TRACE (Incoming-1,NodeV-57636:) [TCP_NIO2] NodeV-57636: looping back message [dst: NodeV-57636, src: NodeV-57636 (3 headers), size=0 bytes, flags=OOB|INTERNAL]
> 10:36:07,979 TRACE (transport-thread-NodeV-p1249-t2:) [TCP_NIO2] dest=127.0.0.1:9001 (87 bytes)
> 10:36:07,980 TRACE (INT-2,NodeV-57636:) [TCP_NIO2] NodeV-57636: received [dst: NodeV-57636, src: NodeV-57636 (3 headers), size=0 bytes, flags=OOB|INTERNAL], headers are GMS: GmsHeader[VIEW_ACK], UNICAST3: DATA, seqno=1, first, TP: [cluster_name=ISPN]
> 10:36:07,980 TRACE (INT-2,NodeV-57636:) [UNICAST3] NodeV-57636 <-- DATA(NodeV-57636: #1, conn_id=0, first)
> 10:36:07,980 TRACE (INT-2,NodeV-57636:) [UNICAST3] NodeV-57636: delivering NodeV-57636#1
> 10:36:07,981 TRACE (ViewHandler,NodeV-57636:) [GMS] NodeV-57636: got all ACKs (1) from members for view [NodeV-57636|1]
> 10:36:07,981 TRACE (ViewHandler,NodeV-57636:) [UNICAST3] NodeV-57636 --> DATA(NodeW-53871: #2, conn_id=1)
> 10:36:07,981 TRACE (ViewHandler,NodeV-57636:) [TCP_NIO2] NodeV-57636: sending msg to NodeW-53871, src=NodeV-57636, headers are GMS: GmsHeader[JOIN_RSP], UNICAST3: DATA, seqno=2, conn_id=1, TP: [cluster_name=ISPN]
> 10:36:07,982 TRACE (OOB-1,NodeW-53871:) [TCP_NIO2] NodeW-53871: received [dst: NodeW-53871, src: NodeV-57636 (3 headers), size=11 bytes, flags=OOB|DONT_BUNDLE|NO_TOTAL_ORDER], headers are RequestCorrelator: corr_id=200, type=REQ, req_id=1546, rsp_expected=true, UNICAST3: DATA, seqno=1, conn_id=1, first, TP: [cluster_name=ISPN]
> 10:36:07,982 TRACE (OOB-1,NodeW-53871:) [UNICAST3] NodeW-53871 <-- DATA(NodeV-57636: #1, conn_id=1, first)
> 10:36:07,987 TRACE (OOB-1,NodeW-53871:) [UNICAST3] NodeW-53871: created receiver window for NodeV-57636 at seqno=#1 for conn-id=1
> 10:36:07,987 TRACE (OOB-1,NodeW-53871:) [UNICAST3] NodeW-53871: delivering NodeV-57636#1
> 10:36:07,987 TRACE (OOB-1,NodeW-53871:) [RequestCorrelator] calling (org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher) with request 1546
> 10:36:07,988 TRACE (OOB-1,NodeW-53871:) [GlobalInboundInvocationHandler] Attempting to execute non-CacheRpcCommand: CacheTopologyControlCommand{cache=null, type=POLICY_GET_STATUS, sender=null, joinInfo=null, topologyId=0, rebalanceId=0, currentCH=null, pendingCH=null, availabilityMode=null, actualMembers=null, throwable=null, viewId=0} [sender=NodeV-57636]
> 10:36:07,995 TRACE (OOB-1,NodeW-53871:) [BlockingTaskAwareExecutorServiceImpl] Added a new task directly: 0 task(s) are waiting
> 10:36:07,998 TRACE (Timer-2,NodeV-57636:) [TCP_NIO2] NodeV-57636: sending 2 msgs (240 bytes (0.77% of max_bundle_size) to 2 dests(s): [ISPN:NodeW-53871, ISPN]
> 10:36:07,999 TRACE (Timer-2,NodeV-57636:) [TCP_NIO2] dest=127.0.0.1:9001 (135 bytes)
> 10:36:07,999 TRACE (Timer-2,NodeV-57636:) [TCP_NIO2] dest=127.0.0.1:9001 (111 bytes)
> 10:36:07,999 TRACE (INT-1,NodeW-53871:) [TCP_NIO2] NodeW-53871: received [dst: NodeW-53871, src: NodeV-57636 (3 headers), size=61 bytes, flags=OOB|INTERNAL], headers are GMS: GmsHeader[JOIN_RSP], UNICAST3: DATA, seqno=2, conn_id=1, TP: [cluster_name=ISPN]
> 10:36:07,999 TRACE (INT-1,NodeW-53871:) [UNICAST3] NodeW-53871 <-- DATA(NodeV-57636: #2, conn_id=1)
> 10:36:07,999 TRACE (INT-1,NodeW-53871:) [UNICAST3] NodeW-53871: delivering NodeV-57636#2
> 10:36:07,999 DEBUG (testng-ClusterExecutorTest:) [NAKACK2]
> [NodeW-53871 setDigest()]
> existing digest: []
> new digest: NodeV-57636: [0 (0)], NodeW-53871: [0 (0)]
> resulting digest: NodeV-57636: [0 (0)], NodeW-53871: [0 (0)]
> 10:36:07,999 DEBUG (testng-ClusterExecutorTest:) [GMS] NodeW-53871: installing view [NodeV-57636|1] (2) [NodeV-57636, NodeW-53871]
> 10:36:07,999 TRACE (testng-ClusterExecutorTest:) [STABLE] NodeW-53871: reset digest to NodeV-57636: [-1], NodeW-53871: [-1]
> 10:36:07,999 TRACE (testng-ClusterExecutorTest:) [TOA] Handle view [NodeV-57636|1] (2) [NodeV-57636, NodeW-53871]
> 10:36:07,999 TRACE (testng-ClusterExecutorTest:) [MFC] new membership: [NodeV-57636, NodeW-53871]
> 10:36:07,999 DEBUG (testng-ClusterExecutorTest:) [JGroupsTransport] New view accepted: [NodeV-57636|1] (2) [NodeV-57636, NodeW-53871]
> 10:36:07,999 INFO (testng-ClusterExecutorTest:) [JGroupsTransport] ISPN000094: Received new cluster view for channel ISPN: [NodeV-57636|1] (2) [NodeV-57636, NodeW-53871]
> 10:36:08,000 TRACE (testng-ClusterExecutorTest:) [UNICAST3] NodeW-53871 --> DATA(NodeV-57636: #2, conn_id=0)
> 10:36:08,000 TRACE (testng-ClusterExecutorTest:) [TCP_NIO2] NodeW-53871: sending msg to NodeV-57636, src=NodeW-53871, headers are GMS: GmsHeader[VIEW_ACK], UNICAST3: DATA, seqno=2, TP: [cluster_name=ISPN]
> 10:36:08,000 INFO (testng-ClusterExecutorTest:) [JGroupsTransport] ISPN000079: Channel ISPN local address is NodeW-53871, physical addresses are [127.0.0.1:9001]
> 10:36:08,000 TRACE (testng-ClusterExecutorTest:) [JGroupsTransport] Waiting on view 0 being accepted
> 10:36:08,000 TRACE (testng-ClusterExecutorTest:) [SemaphoreCompletionService] New task submitted, tasks in queue 1, available permits 1
> 10:36:08,009 TRACE (testng-ClusterExecutorTest:) [JGroupsTransport] dests=[NodeV-57636], command=CacheTopologyControlCommand{cache=null, type=POLICY_GET_STATUS, sender=NodeW-53871, joinInfo=null, topologyId=0, rebalanceId=0, currentCH=null, pendingCH=null, availabilityMode=null, actualMembers=null, throwable=null, viewId=-1}, mode=SYNCHRONOUS, timeout=240000
> 10:36:08,009 TRACE (testng-ClusterExecutorTest:) [CommandAwareRpcDispatcher] Replication task sending CacheTopologyControlCommand{cache=null, type=POLICY_GET_STATUS, sender=NodeW-53871, joinInfo=null, topologyId=0, rebalanceId=0, currentCH=null, pendingCH=null, availabilityMode=null, actualMembers=null, throwable=null, viewId=-1} to single recipient NodeV-57636 with response mode GET_ALL
> 10:36:08,009 TRACE (testng-ClusterExecutorTest:) [RequestCorrelator] NodeW-53871: invoking unicast RPC [req-id=1558] on NodeV-57636
> 10:36:08,009 TRACE (testng-ClusterExecutorTest:) [UNICAST3] NodeW-53871 --> DATA(NodeV-57636: #3, conn_id=0)
> 10:36:08,009 TRACE (testng-ClusterExecutorTest:) [TCP_NIO2] NodeW-53871: sending msg to NodeV-57636, src=NodeW-53871, headers are RequestCorrelator: corr_id=200, type=REQ, req_id=1558, rsp_expected=true, UNICAST3: DATA, seqno=3, TP: [cluster_name=ISPN]
> 10:36:08,009 TRACE (testng-ClusterExecutorTest:) [TCP_NIO2] dest=127.0.0.1:9000 (87 bytes)
> 10:36:08,009 TRACE (OOB-1,NodeV-57636:) [TCP_NIO2] NodeV-57636: received [dst: NodeV-57636, src: NodeW-53871 (3 headers), size=11 bytes, flags=OOB|DONT_BUNDLE|NO_TOTAL_ORDER], headers are RequestCorrelator: corr_id=200, type=REQ, req_id=1558, rsp_expected=true, UNICAST3: DATA, seqno=3, TP: [cluster_name=ISPN]
> 10:36:08,009 TRACE (OOB-1,NodeV-57636:) [UNICAST3] NodeV-57636 <-- DATA(NodeW-53871: #3, conn_id=0)
> 10:36:08,009 TRACE (OOB-1,NodeV-57636:) [UNICAST3] NodeV-57636: delivering NodeW-53871#3
> 10:36:08,009 TRACE (OOB-1,NodeV-57636:) [RequestCorrelator] calling (org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher) with request 1558
> 10:36:08,009 TRACE (OOB-1,NodeV-57636:) [GlobalInboundInvocationHandler] Attempting to execute non-CacheRpcCommand: CacheTopologyControlCommand{cache=null, type=POLICY_GET_STATUS, sender=null, joinInfo=null, topologyId=0, rebalanceId=0, currentCH=null, pendingCH=null, availabilityMode=null, actualMembers=null, throwable=null, viewId=0} [sender=NodeW-53871]
> 10:36:08,010 TRACE (Incoming-1,NodeW-53871:) [TCP_NIO2] NodeW-53871: received [dst: <null>, src: NodeV-57636 (3 headers), size=57 bytes], headers are GMS: GmsHeader[VIEW], NAKACK2: [MSG, seqno=1], TP: [cluster_name=ISPN]
> 10:36:08,010 TRACE (Incoming-1,NodeW-53871:) [NAKACK2] NodeW-53871: received NodeV-57636#1
> 10:36:08,010 TRACE (Incoming-1,NodeW-53871:) [NAKACK2] NodeW-53871: delivering NodeV-57636#1-1 (1 messages)
> 10:36:08,010 TRACE (transport-thread-NodeW-p1259-t1:) [SemaphoreCompletionService] Task started, tasks in queue 0, available permits 0
> 10:36:08,010 TRACE (transport-thread-NodeW-p1259-t1:) [ClusterTopologyManagerImpl] Received new cluster view: 1, isCoordinator = false, old status = INITIALIZING
> 10:36:08,010 TRACE (transport-thread-NodeW-p1259-t1:) [SemaphoreCompletionService] Task finished, tasks in queue 0, available permits 0
> 10:36:08,011 TRACE (OOB-1,NodeV-57636:) [BlockingTaskAwareExecutorServiceImpl] Added a new task directly: 0 task(s) are waiting
> 10:36:08,012 TRACE (remote-thread-NodeV-p1247-t1:) [CommandAwareRpcDispatcher] About to send back response SuccessfulResponse{responseValue=true} for command CacheTopologyControlCommand{cache=null, type=POLICY_GET_STATUS, sender=null, joinInfo=null, topologyId=0, rebalanceId=0, currentCH=null, pendingCH=null, availabilityMode=null, actualMembers=null, throwable=null, viewId=0}
> 10:36:08,012 TRACE (remote-thread-NodeV-p1247-t1:) [RequestCorrelator] sending rsp for 1558 to NodeW-53871
> 10:36:08,012 TRACE (remote-thread-NodeV-p1247-t1:) [UNICAST3] NodeV-57636 --> DATA(NodeW-53871: #3, conn_id=1)
> 10:36:08,012 TRACE (remote-thread-NodeV-p1247-t1:) [TCP_NIO2] NodeV-57636: sending msg to NodeW-53871, src=NodeV-57636, headers are RequestCorrelator: corr_id=200, type=RSP, req_id=1558, rsp_expected=true, UNICAST3: DATA, seqno=3, conn_id=1, TP: [cluster_name=ISPN]
> 10:36:08,012 TRACE (remote-thread-NodeV-p1247-t1:) [TCP_NIO2] dest=127.0.0.1:9001 (83 bytes)
> 10:36:08,013 TRACE (OOB-1,NodeW-53871:) [TCP_NIO2] NodeW-53871: received [dst: NodeW-53871, src: NodeV-57636 (3 headers), size=7 bytes, flags=OOB|DONT_BUNDLE|NO_TOTAL_ORDER], headers are RequestCorrelator: corr_id=200, type=RSP, req_id=1558, rsp_expected=true, UNICAST3: DATA, seqno=3, conn_id=1, TP: [cluster_name=ISPN]
> 10:36:08,013 TRACE (OOB-1,NodeW-53871:) [UNICAST3] NodeW-53871 <-- DATA(NodeV-57636: #3, conn_id=1)
> 10:36:08,013 TRACE (OOB-1,NodeW-53871:) [UNICAST3] NodeW-53871: delivering NodeV-57636#3
> 10:36:08,013 TRACE (OOB-1,NodeW-53871:) [JGroupsTransport] Response: sender=NodeV-57636, retval=SuccessfulResponse{responseValue=true} , received=true, suspected=false
> 10:36:08,013 TRACE (testng-ClusterExecutorTest:) [LocalTopologyManagerImpl] Starting LocalTopologyManager on NodeW-53871
> 10:36:08,013 DEBUG (testng-ClusterExecutorTest:) [DefaultCacheManager] Started cache manager ISPN on NodeW
> 10:36:08,013 TRACE (remote-thread-NodeW-p1257-t1:) [CommandAwareRpcDispatcher] About to send back response SuccessfulResponse{responseValue=true} for command CacheTopologyControlCommand{cache=null, type=POLICY_GET_STATUS, sender=null, joinInfo=null, topologyId=0, rebalanceId=0, currentCH=null, pendingCH=null, availabilityMode=null, actualMembers=null, throwable=null, viewId=0}
> 10:36:08,013 TRACE (remote-thread-NodeW-p1257-t1:) [RequestCorrelator] sending rsp for 1546 to NodeV-57636
> 10:36:08,013 TRACE (remote-thread-NodeW-p1257-t1:) [UNICAST3] NodeW-53871 --> DATA(NodeV-57636: #4, conn_id=0)
> 10:36:08,013 TRACE (remote-thread-NodeW-p1257-t1:) [TCP_NIO2] NodeW-53871: sending msg to NodeV-57636, src=NodeW-53871, headers are RequestCorrelator: corr_id=200, type=RSP, req_id=1546, rsp_expected=true, UNICAST3: DATA, seqno=4, TP: [cluster_name=ISPN]
> 10:36:08,013 TRACE (remote-thread-NodeW-p1257-t1:) [TCP_NIO2] dest=127.0.0.1:9000 (83 bytes)
> 10:36:08,014 TRACE (OOB-1,NodeV-57636:) [TCP_NIO2] NodeV-57636: received [dst: NodeV-57636, src: NodeW-53871 (3 headers), size=7 bytes, flags=OOB|DONT_BUNDLE|NO_TOTAL_ORDER], headers are RequestCorrelator: corr_id=200, type=RSP, req_id=1546, rsp_expected=true, UNICAST3: DATA, seqno=4, TP: [cluster_name=ISPN]
> 10:36:08,014 TRACE (OOB-1,NodeV-57636:) [UNICAST3] NodeV-57636 <-- DATA(NodeW-53871: #4, conn_id=0)
> 10:36:08,014 TRACE (OOB-1,NodeV-57636:) [UNICAST3] NodeV-57636: delivering NodeW-53871#4
> 10:36:08,014 TRACE (OOB-1,NodeV-57636:) [JGroupsTransport] Response: sender=NodeW-53871, retval=SuccessfulResponse{responseValue=true} , received=true, suspected=false
> 10:36:08,014 TRACE (transport-thread-NodeV-p1249-t2:) [SemaphoreCompletionService] Task finished, tasks in queue 0, available permits 0
> 10:36:08,015 TRACE (testng-ClusterExecutorTest:) [ClusterExecutorImpl] Submitting callable to local node on executor thread! - Usually remote command thread pool
> 10:36:08,015 TRACE (testng-ClusterExecutorTest:) [BlockingTaskAwareExecutorServiceImpl] Added a new task directly: 0 task(s) are waiting
> 10:36:08,015 TRACE (testng-ClusterExecutorTest:) [ClusterExecutorImpl] Submitting consumer to single remote node - JGroups Address NodeW-53871
> 10:36:08,015 TRACE (testng-ClusterExecutorTest:) [CommandAwareRpcDispatcher] Replication task sending org.infinispan.manager.impl.ReplicableCommandManagerFunction@187af934 to single recipient NodeW-53871 with response mode GET_ALL
> 10:36:08,016 TRACE (testng-ClusterExecutorTest:) [RequestCorrelator] NodeV-57636: invoking unicast RPC [req-id=1562] on NodeW-53871
> 10:36:08,016 TRACE (testng-ClusterExecutorTest:) [UNICAST3] NodeV-57636 --> DATA(NodeW-53871: #4, conn_id=1)
> 10:36:08,016 TRACE (testng-ClusterExecutorTest:) [TCP_NIO2] NodeV-57636: sending msg to NodeW-53871, src=NodeV-57636, headers are RequestCorrelator: corr_id=200, type=REQ, req_id=1562, rsp_expected=true, UNICAST3: DATA, seqno=4, conn_id=1, TP: [cluster_name=ISPN]
> 10:36:08,016 TRACE (testng-ClusterExecutorTest:) [TCP_NIO2] dest=127.0.0.1:9001 (731 bytes)
> 10:36:08,017 TRACE (OOB-1,NodeW-53871:) [TCP_NIO2] NodeW-53871: received [dst: NodeW-53871, src: NodeV-57636 (3 headers), size=655 bytes, flags=OOB|DONT_BUNDLE|NO_TOTAL_ORDER], headers are RequestCorrelator: corr_id=200, type=REQ, req_id=1562, rsp_expected=true, UNICAST3: DATA, seqno=4, conn_id=1, TP: [cluster_name=ISPN]
> 10:36:08,017 TRACE (OOB-1,NodeW-53871:) [UNICAST3] NodeW-53871 <-- DATA(NodeV-57636: #4, conn_id=1)
> 10:36:08,017 TRACE (OOB-1,NodeW-53871:) [UNICAST3] NodeW-53871: delivering NodeV-57636#4
> 10:36:08,017 TRACE (OOB-1,NodeW-53871:) [RequestCorrelator] calling (org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher) with request 1562
> 10:36:08,017 TRACE (OOB-1,NodeW-53871:) [GlobalInboundInvocationHandler] Attempting to execute non-CacheRpcCommand: org.infinispan.manager.impl.ReplicableCommandManagerFunction@42c891df [sender=NodeV-57636]
> 10:36:08,018 TRACE (OOB-1,NodeW-53871:) [BlockingTaskAwareExecutorServiceImpl] Added a new task directly: 0 task(s) are waiting
> 10:36:08,018 TRACE (remote-thread-NodeW-p1257-t2:) [CommandAwareRpcDispatcher] About to send back response SuccessfulResponse{responseValue=NodeW-53871} for command org.infinispan.manager.impl.ReplicableCommandManagerFunction@42c891df
> 10:36:08,019 TRACE (remote-thread-NodeW-p1257-t2:) [RequestCorrelator] sending rsp for 1562 to NodeV-57636
> 10:36:08,019 TRACE (remote-thread-NodeW-p1257-t2:) [UNICAST3] NodeW-53871 --> DATA(NodeV-57636: #5, conn_id=0)
> 10:36:08,019 TRACE (remote-thread-NodeW-p1257-t2:) [TCP_NIO2] NodeW-53871: sending msg to NodeV-57636, src=NodeW-53871, headers are RequestCorrelator: corr_id=200, type=RSP, req_id=1562, rsp_expected=true, UNICAST3: DATA, seqno=5, TP: [cluster_name=ISPN]
> 10:36:08,019 TRACE (remote-thread-NodeW-p1257-t2:) [TCP_NIO2] dest=127.0.0.1:9000 (102 bytes)
> 10:36:08,019 TRACE (OOB-1,NodeV-57636:) [TCP_NIO2] NodeV-57636: received [dst: NodeV-57636, src: NodeW-53871 (3 headers), size=26 bytes, flags=OOB|DONT_BUNDLE|NO_TOTAL_ORDER], headers are RequestCorrelator: corr_id=200, type=RSP, req_id=1562, rsp_expected=true, UNICAST3: DATA, seqno=5, TP: [cluster_name=ISPN]
> 10:36:08,019 TRACE (OOB-1,NodeV-57636:) [UNICAST3] NodeV-57636 <-- DATA(NodeW-53871: #5, conn_id=0)
> 10:36:08,019 TRACE (OOB-1,NodeV-57636:) [UNICAST3] NodeV-57636: delivering NodeW-53871#5
> 10:36:08,020 TRACE (Timer-3,NodeW-53871:) [TCP_NIO2] NodeW-53871: sending 1 msgs (67 bytes (0.22% of max_bundle_size) to 1 dests(s): [ISPN:NodeV-57636]
> 10:36:08,020 TRACE (Timer-3,NodeW-53871:) [TCP_NIO2] dest=127.0.0.1:9000 (70 bytes)
> 10:36:08,022 DEBUG (testng-ClusterExecutorTest:) [DefaultCacheManager] Stopping cache manager ISPN on NodeW-53871
> 10:36:08,022 TRACE (testng-ClusterExecutorTest:) [DefaultCacheManager] Cache stop order: []
> 10:36:08,022 TRACE (INT-1,NodeV-57636:) [TCP_NIO2] NodeV-57636: received [dst: NodeV-57636, src: NodeW-53871 (3 headers), size=0 bytes, flags=OOB|INTERNAL], headers are GMS: GmsHeader[VIEW_ACK], UNICAST3: DATA, seqno=2, TP: [cluster_name=ISPN]
> 10:36:08,022 TRACE (INT-1,NodeV-57636:) [UNICAST3] NodeV-57636 <-- DATA(NodeW-53871: #2, conn_id=0)
> 10:36:08,026 TRACE (INT-1,NodeV-57636:) [UNICAST3] NodeV-57636: delivering NodeW-53871#2
> 10:36:08,026 TRACE (ViewHandler,NodeV-57636:) [GMS] NodeV-57636: got all ACKs (1) from joiners for view [NodeV-57636|1]
> 10:36:08,026 TRACE (ViewHandler,NodeV-57636:) [STABLE] NodeV-57636: reset digest to NodeV-57636: [-1], NodeW-53871: [-1]
> 10:36:08,026 DEBUG (ViewHandler,NodeV-57636:) [STABLE] resuming message garbage collection
> 10:36:08,030 TRACE (testng-ClusterExecutorTest:) [LocalTopologyManagerImpl] Stopping LocalTopologyManager on NodeW-53871
> 10:36:08,030 INFO (testng-ClusterExecutorTest:) [JGroupsTransport] ISPN000080: Disconnecting JGroups channel ISPN
> 10:36:08,030 TRACE (testng-ClusterExecutorTest:) [GMS] Handling disconnect event
> 10:36:08,030 TRACE (testng-ClusterExecutorTest:) [GMS] Handling leave as participant, leaver = NodeW-53871, coord = NodeV-57636
> 10:36:08,030 TRACE (testng-ClusterExecutorTest:) [GMS] NodeW-53871: sending LEAVE request to NodeV-57636
> 10:36:08,030 TRACE (testng-ClusterExecutorTest:) [UNICAST3] NodeW-53871 --> DATA(NodeV-57636: #6, conn_id=0)
> 10:36:08,030 TRACE (testng-ClusterExecutorTest:) [TCP_NIO2] NodeW-53871: sending msg to NodeV-57636, src=NodeW-53871, headers are GMS: GmsHeader[LEAVE_REQ]: mbr=NodeW-53871, UNICAST3: DATA, seqno=6, TP: [cluster_name=ISPN]
> 10:36:08,050 TRACE (Timer-2,NodeW-53871:) [TCP_NIO2] NodeW-53871: sending 1 msgs (83 bytes (0.27% of max_bundle_size) to 1 dests(s): [ISPN:NodeV-57636]
> 10:36:08,050 TRACE (Timer-2,NodeW-53871:) [TCP_NIO2] dest=127.0.0.1:9000 (86 bytes)
> 10:36:08,050 TRACE (OOB-1,NodeV-57636:) [TCP_NIO2] NodeV-57636: received [dst: NodeV-57636, src: NodeW-53871 (3 headers), size=0 bytes, flags=OOB], headers are GMS: GmsHeader[LEAVE_REQ]: mbr=NodeW-53871, UNICAST3: DATA, seqno=6, TP: [cluster_name=ISPN]
> 10:36:08,050 TRACE (OOB-1,NodeV-57636:) [UNICAST3] NodeV-57636 <-- DATA(NodeW-53871: #6, conn_id=0)
> 10:36:08,050 TRACE (OOB-1,NodeV-57636:) [UNICAST3] NodeV-57636: delivering NodeW-53871#6
> 10:36:08,075 TRACE (ViewHandler,NodeV-57636:) [GMS] NodeV-57636: joiners=[], suspected=[], leaving=[NodeW-53871], new view: [NodeV-57636|2] (1) [NodeV-57636]
> 10:36:08,075 TRACE (ViewHandler,NodeV-57636:) [GMS] NodeV-57636: sending LEAVE response to NodeW-53871
> 10:36:08,075 TRACE (ViewHandler,NodeV-57636:) [TCP_NIO2] NodeV-57636: sending msg to NodeW-53871, src=NodeV-57636, headers are GMS: GmsHeader[LEAVE_RSP], TP: [cluster_name=ISPN]
> 10:36:08,075 TRACE (ViewHandler,NodeV-57636:) [GMS] NodeV-57636: mcasting view [NodeV-57636|2] (1) [NodeV-57636] (1 mbrs)
> 10:36:08,076 TRACE (ViewHandler,NodeV-57636:) [NAKACK2] NodeV-57636: sending NodeV-57636#2
> 10:36:08,076 TRACE (ViewHandler,NodeV-57636:) [TCP_NIO2] NodeV-57636: sending msg to null, src=NodeV-57636, headers are GMS: GmsHeader[VIEW], NAKACK2: [MSG, seqno=2], TP: [cluster_name=ISPN]
> 10:36:08,076 TRACE (ViewHandler,NodeV-57636:) [TCP_NIO2] NodeV-57636: looping back message [dst: <null>, src: NodeV-57636 (3 headers), size=61 bytes]
> 10:36:08,080 TRACE (Incoming-1,NodeV-57636:) [TCP_NIO2] NodeV-57636: received [dst: <null>, src: NodeV-57636 (3 headers), size=61 bytes], headers are GMS: GmsHeader[VIEW], NAKACK2: [MSG, seqno=2], TP: [cluster_name=ISPN]
> 10:36:08,079 TRACE (NioConnection.Reader [127.0.0.1:9000],NodeW-53871:) [TCP_NIO2] 127.0.0.1:9001: removed connection to 127.0.0.1:9000
> 10:36:08,080 TRACE (Incoming-1,NodeV-57636:) [NAKACK2] NodeV-57636: received NodeV-57636#2
> 10:36:08,080 TRACE (Incoming-1,NodeV-57636:) [NAKACK2] NodeV-57636: delivering NodeV-57636#2-2 (1 messages)
> 10:36:08,080 TRACE (Incoming-1,NodeV-57636:) [GMS] NodeV-57636: received delta view [NodeV-57636|2], ref-view=[NodeV-57636|1], left=[NodeW-53871]
> 10:36:08,082 DEBUG (Incoming-1,NodeV-57636:) [GMS] NodeV-57636: installing view [NodeV-57636|2] (1) [NodeV-57636]
> 10:36:08,082 TRACE (Incoming-1,NodeV-57636:) [UNICAST3] NodeV-57636: closing connections of non members [NodeW-53871]
> 10:36:08,082 DEBUG (Incoming-1,NodeV-57636:) [NAKACK2] NodeV-57636: removed NodeW-53871 from xmit_table (not member anymore)
> 10:36:08,082 TRACE (Incoming-1,NodeV-57636:) [STABLE] NodeV-57636: reset digest to NodeV-57636: [-1]
> 10:36:08,082 TRACE (Incoming-1,NodeV-57636:) [TOA] Handle view [NodeV-57636|2] (1) [NodeV-57636]
> 10:36:08,082 TRACE (Incoming-1,NodeV-57636:) [MFC] new membership: [NodeV-57636]
> 10:36:08,082 TRACE (Incoming-1,NodeV-57636:) [FRAG2] NodeV-57636: removed NodeW-53871 from fragmentation table
> 10:36:08,082 DEBUG (Incoming-1,NodeV-57636:) [JGroupsTransport] New view accepted: [NodeV-57636|2] (1) [NodeV-57636]
> 10:36:08,082 DEBUG (Incoming-1,NodeV-57636:) [JGroupsTransport] Joined: [], Left: [NodeW-53871]
> 10:36:08,082 INFO (Incoming-1,NodeV-57636:) [JGroupsTransport] ISPN000094: Received new cluster view for channel ISPN: [NodeV-57636|2] (1) [NodeV-57636]
> 10:36:08,082 TRACE (Incoming-1,NodeV-57636:) [SemaphoreCompletionService] New task submitted, tasks in queue 1, available permits 1
> 10:36:08,085 TRACE (Incoming-1,NodeV-57636:) [UNICAST3] NodeV-57636 --> DATA(NodeV-57636: #2, conn_id=0)
> 10:36:08,085 TRACE (Incoming-1,NodeV-57636:) [TCP_NIO2] NodeV-57636: sending msg to NodeV-57636, src=NodeV-57636, headers are GMS: GmsHeader[VIEW_ACK], UNICAST3: DATA, seqno=2, TP: [cluster_name=ISPN]
> 10:36:08,085 TRACE (Incoming-1,NodeV-57636:) [TCP_NIO2] NodeV-57636: looping back message [dst: NodeV-57636, src: NodeV-57636 (3 headers), size=0 bytes, flags=OOB|INTERNAL]
> 10:36:08,085 TRACE (transport-thread-NodeV-p1249-t3:) [SemaphoreCompletionService] Task started, tasks in queue 0, available permits 0
> 10:36:08,085 TRACE (transport-thread-NodeV-p1249-t3:) [ClusterTopologyManagerImpl] Received new cluster view: 2, isCoordinator = true, old status = COORDINATOR
> 10:36:08,085 TRACE (transport-thread-NodeV-p1249-t3:) [ClusterTopologyManagerImpl] Updating cluster members for all the caches. New list is [NodeV-57636]
> 10:36:08,085 TRACE (INT-2,NodeV-57636:) [TCP_NIO2] NodeV-57636: received [dst: NodeV-57636, src: NodeV-57636 (3 headers), size=0 bytes, flags=OOB|INTERNAL], headers are GMS: GmsHeader[VIEW_ACK], UNICAST3: DATA, seqno=2, TP: [cluster_name=ISPN]
> 10:36:08,085 TRACE (transport-thread-NodeV-p1249-t3:) [JGroupsTransport] dests=null, command=CacheTopologyControlCommand{cache=null, type=POLICY_GET_STATUS, sender=NodeV-57636, joinInfo=null, topologyId=0, rebalanceId=0, currentCH=null, pendingCH=null, availabilityMode=null, actualMembers=null, throwable=null, viewId=-1}, mode=SYNCHRONOUS, timeout=240000
> 10:36:08,085 TRACE (INT-2,NodeV-57636:) [UNICAST3] NodeV-57636 <-- DATA(NodeV-57636: #2, conn_id=0)
> 10:36:08,085 TRACE (INT-2,NodeV-57636:) [UNICAST3] NodeV-57636: delivering NodeV-57636#2
> 10:36:08,085 TRACE (transport-thread-NodeV-p1249-t3:) [SemaphoreCompletionService] Task finished, tasks in queue 0, available permits 0
> 10:36:08,085 TRACE (ViewHandler,NodeV-57636:) [GMS] NodeV-57636: got all ACKs (1) from members for view [NodeV-57636|2]
> 10:36:08,096 TRACE (Timer-2,NodeV-57636:) [TCP_NIO2] NodeV-57636: sending 2 msgs (169 bytes (0.55% of max_bundle_size) to 2 dests(s): [ISPN:NodeW-53871, ISPN]
> 10:36:08,096 TRACE (Timer-2,NodeV-57636:) [TCP_NIO2] dest=127.0.0.1:9001 (60 bytes)
> 10:36:08,096 TRACE (Timer-2,NodeV-57636:) [TCP_NIO2] 127.0.0.1:9000: connecting to 127.0.0.1:9001
> 10:36:08,107 TRACE (INT-2,NodeW-53871:) [TCP_NIO2] NodeW-53871: received [dst: NodeW-53871, src: NodeV-57636 (2 headers), size=0 bytes, flags=OOB|NO_RELIABILITY|INTERNAL], headers are GMS: GmsHeader[LEAVE_RSP], TP: [cluster_name=ISPN]
> 10:36:08,107 TRACE (testng-ClusterExecutorTest:) [GMS] NodeW-53871: got LEAVE response from NodeV-57636
> 10:36:08,107 TRACE (NioConnection.Reader [127.0.0.1:9001],NodeV-57636:) [TCP_NIO2] 127.0.0.1:9000: removed connection to 127.0.0.1:9001
> 10:36:08,108 TRACE (testng-ClusterExecutorTest:) [UNICAST3] NodeW-53871 --> ACK(NodeV-57636: #4)
> 10:36:08,108 TRACE (testng-ClusterExecutorTest:) [TCP_NIO2] NodeW-53871: sending msg to NodeV-57636, src=NodeW-53871, headers are UNICAST3: ACK, seqno=4, conn_id=1, ts=1, TP: [cluster_name=ISPN]
> 10:36:08,108 DEBUG (testng-ClusterExecutorTest:) [TEST_PING] Stop discovery for NodeW-53871
> 10:36:08,108 DEBUG (testng-ClusterExecutorTest:) [TCP_NIO2] closing sockets and stopping threads
> 10:36:08,108 INFO (testng-ClusterExecutorTest:) [JGroupsTransport] ISPN000082: Stopping the RpcDispatcher for channel ISPN
> 10:36:08,109 DEBUG (testng-ClusterExecutorTest:) [DefaultCacheManager] Stopping cache manager ISPN on NodeV-57636
> 10:36:08,109 TRACE (testng-ClusterExecutorTest:) [DefaultCacheManager] Cache stop order: []
> 10:36:08,113 TRACE (testng-ClusterExecutorTest:) [LocalTopologyManagerImpl] Stopping LocalTopologyManager on NodeV-57636
> 10:36:08,113 INFO (testng-ClusterExecutorTest:) [JGroupsTransport] ISPN000080: Disconnecting JGroups channel ISPN
> 10:36:08,113 TRACE (testng-ClusterExecutorTest:) [GMS] Handling disconnect event
> 10:36:08,113 TRACE (testng-ClusterExecutorTest:) [GMS] Handling leave as coord, leaver = NodeV-57636
> 10:36:08,114 TRACE (testng-ClusterExecutorTest:) [UNICAST3] NodeV-57636 --> ACK(NodeW-53871: #6)
> 10:36:08,114 TRACE (testng-ClusterExecutorTest:) [TCP_NIO2] NodeV-57636: sending msg to NodeW-53871, src=NodeV-57636, headers are UNICAST3: ACK, seqno=6, ts=1, TP: [cluster_name=ISPN]
> 10:36:08,114 DEBUG (testng-ClusterExecutorTest:) [TEST_PING] Stop discovery for NodeV-57636
> 10:36:08,114 DEBUG (testng-ClusterExecutorTest:) [TCP_NIO2] closing sockets and stopping threads
> 10:36:08,114 INFO (testng-ClusterExecutorTest:) [JGroupsTransport] ISPN000082: Stopping the RpcDispatcher for channel ISPN
> 10:36:08,116 ERROR (testng-ClusterExecutorTest:) [UnitTestTestNGListener] Test testExecutorTriConsumer(org.infinispan.manager.ClusterExecutorTest) failed.
> java.lang.AssertionError: expected:<2> but was:<1>
> at org.testng.AssertJUnit.fail(AssertJUnit.java:59) ~[testng-6.8.8.jar:?]
> at org.testng.AssertJUnit.failNotEquals(AssertJUnit.java:364) ~[testng-6.8.8.jar:?]
> at org.testng.AssertJUnit.assertEquals(AssertJUnit.java:80) ~[testng-6.8.8.jar:?]
> at org.testng.AssertJUnit.assertEquals(AssertJUnit.java:245) ~[testng-6.8.8.jar:?]
> at org.testng.AssertJUnit.assertEquals(AssertJUnit.java:252) ~[testng-6.8.8.jar:?]
> at org.infinispan.manager.ClusterExecutorTest$11.call(ClusterExecutorTest.java:222) ~[test-classes/:?]
> at org.infinispan.test.TestingUtil.withCacheManagers(TestingUtil.java:1353) ~[test-classes/:?]
> at org.infinispan.manager.ClusterExecutorTest.testExecutorTriConsumer(ClusterExecutorTest.java:201) ~[test-classes/:?]
> at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.8.0_74]
> at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:1.8.0_74]
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_74]
> at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_74]
> at org.testng.internal.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:84) ~[testng-6.8.8.jar:?]
> at org.testng.internal.Invoker.invokeMethod(Invoker.java:714) [testng-6.8.8.jar:?]
> at org.testng.internal.Invoker.invokeTestMethod(Invoker.java:901) [testng-6.8.8.jar:?]
> at org.testng.internal.Invoker.invokeTestMethods(Invoker.java:1231) [testng-6.8.8.jar:?]
> at org.testng.internal.TestMethodWorker.invokeTestMethods(TestMethodWorker.java:127) [testng-6.8.8.jar:?]
> at org.testng.internal.TestMethodWorker.run(TestMethodWorker.java:111) [testng-6.8.8.jar:?]
> at org.testng.TestRunner.privateRun(TestRunner.java:767) [testng-6.8.8.jar:?]
> at org.testng.TestRunner.run(TestRunner.java:617) [testng-6.8.8.jar:?]
> at org.testng.SuiteRunner.runTest(SuiteRunner.java:348) [testng-6.8.8.jar:?]
> at org.testng.SuiteRunner.access$000(SuiteRunner.java:38) [testng-6.8.8.jar:?]
> at org.testng.SuiteRunner$SuiteWorker.run(SuiteRunner.java:382) [testng-6.8.8.jar:?]
> at org.testng.internal.thread.ThreadUtil$2.call(ThreadUtil.java:64) [testng-6.8.8.jar:?]
> at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_74]
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [?:1.8.0_74]
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:1.8.0_74]
> at java.lang.Thread.run(Thread.java:745) [?:1.8.0_74]
> {code}
--
This message was sent by Atlassian JIRA
(v6.4.11#64026)
8 years, 1 month
[JBoss JIRA] (ISPN-6399) Timeout updating the JGroups view after killing one node
by Sebastian Łaskawiec (JIRA)
[ https://issues.jboss.org/browse/ISPN-6399?page=com.atlassian.jira.plugin.... ]
Sebastian Łaskawiec closed ISPN-6399.
-------------------------------------
> Timeout updating the JGroups view after killing one node
> --------------------------------------------------------
>
> Key: ISPN-6399
> URL: https://issues.jboss.org/browse/ISPN-6399
> Project: Infinispan
> Issue Type: Bug
> Components: Test Suite - Core
> Affects Versions: 8.2.0.Final
> Reporter: Dan Berindei
> Assignee: Dan Berindei
> Fix For: 8.2.1.Final, 9.0.0.Alpha1, 9.0.0.Final
>
>
> {{GMS}} can sometimes delay the processing of a join/leave request because of JGRP-2028.
> Joiners retry automatically after {{GMS.join_timeout}}, so it's not that bad. Leavers, however, don't resend their leave requests, so the delay can be worse.
> Normally, the FD/FD_ALL/FD_SOCK protocols would wake up the ViewHandler thread. But we remove the FD* protocols from the stack in most of our tests, unless the test uses {{DISCARD}}. That means the leave request can be delayed until another node leaves:
> {noformat}
> 16:35:56,247 TRACE (testng-ClusterListenerDistAddListenerTest:) [GMS] NodeB-8309: sending LEAVE request to NodeA-45395
> 16:35:56,268 TRACE (OOB-1,NodeA-45395:) [TCP_NIO2] NodeA-45395: received [dst: NodeA-45395, src: NodeB-8309 (3 headers), size=0 bytes, flags=OOB], headers are GMS: GmsHeader[LEAVE_REQ]: mbr=NodeB-8309, UNICAST3: DATA, seqno=22, TP: [cluster_name=ISPN]
> 16:35:56,268 TRACE (OOB-1,NodeA-45395:) [UNICAST3] NodeA-45395: delivering NodeB-8309#22
> 16:36:07,263 ERROR (testng-ClusterListenerDistAddListenerTest:) [UnitTestTestNGListener] Test testMemberJoinsAndRetrievesClusterListenersButMainListenerNodeDiesBeforeInstalled(org.infinispan.notifications.cachelistener.cluster.ClusterListenerDistAddListenerTest) failed.
> org.infinispan.util.concurrent.TimeoutException: Timed out before caches had complete views. Expected 3 members in each view. Views are as follows: [[NodeA-45395|3] (4) [NodeA-45395, NodeB-8309, NodeC-53222, NodeD-55165], [NodeA-45395|3] (4) [NodeA-45395, NodeB-8309, NodeC-53222, NodeD-55165], [NodeA-45395|3] (4) [NodeA-45395, NodeB-8309, NodeC-53222, NodeD-55165]]
> 16:37:07,341 TRACE (testng-ClusterListenerDistAddListenerTest:) [GMS] NodeD-55165: sending LEAVE request to NodeA-45395
> 16:37:07,361 TRACE (OOB-4,NodeA-45395:) [TCP_NIO2] NodeA-45395: received [dst: NodeA-45395, src: NodeD-55165 (3 headers), size=0 bytes, flags=OOB], headers are GMS: GmsHeader[LEAVE_REQ]: mbr=NodeD-55165, UNICAST3: DATA, seqno=21, TP: [cluster_name=ISPN]
> 16:37:07,361 TRACE (OOB-4,NodeA-45395:) [UNICAST3] NodeA-45395: delivering NodeD-55165#21
> 16:37:07,361 TRACE (ViewHandler,NodeA-45395:) [GMS] NodeA-45395: joiners=[], suspected=[], leaving=[NodeB-8309], new view: [NodeA-45395|4] (3) [NodeA-45395, NodeC-53222, NodeD-55165]
> {noformat}
> {{FD_ALL}} is pretty cheap: it just sends a message every second, without opening any new sockets. So I think we should enable it by default, and only enable {{FD_SOCK}} with {{TransportFlags.withFD(true)}}.
--
This message was sent by Atlassian JIRA
(v6.4.11#64026)
8 years, 1 month
[JBoss JIRA] (ISPN-6304) NPE during ClearCommand
by Sebastian Łaskawiec (JIRA)
[ https://issues.jboss.org/browse/ISPN-6304?page=com.atlassian.jira.plugin.... ]
Sebastian Łaskawiec updated ISPN-6304:
--------------------------------------
Fix Version/s: (was: 8.2.1.Final)
> NPE during ClearCommand
> -----------------------
>
> Key: ISPN-6304
> URL: https://issues.jboss.org/browse/ISPN-6304
> Project: Infinispan
> Issue Type: Bug
> Components: Core
> Affects Versions: 8.2.0.CR1, 8.2.0.Final, 8.1.2.Final
> Reporter: Gustavo Fernandes
> Assignee: Dan Berindei
> Fix For: 9.0.0.Alpha1
>
>
> The logs can be seen on https://travis-ci.org/infinispan/infinispan-hadoop/builds/113090728
> The NPE happens intermittently.
> {code}
> 0:52:28,139 ERROR [org.infinispan.interceptors.InvocationContextInterceptor] (HotRodServerWorker-7-1) ISPN000136: Error executing command ClearCommand, writing keys []: org.infinispan.remoting.RemoteException: ISPN000217: Received exception from node1, see cause for remote stack trace
> at org.infinispan.remoting.transport.AbstractTransport.checkResponse(AbstractTransport.java:44)
> at org.infinispan.remoting.transport.jgroups.JGroupsTransport.checkRsp(JGroupsTransport.java:796)
> at org.infinispan.remoting.transport.jgroups.JGroupsTransport.lambda$invokeRemotelyAsync$83(JGroupsTransport.java:633)
> at org.infinispan.remoting.transport.jgroups.JGroupsTransport$$Lambda$46/308539050.apply(Unknown Source)
> at java.util.concurrent.CompletableFuture$ThenApply.run(CompletableFuture.java:717)
> at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:193)
> at java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:2345)
> at org.infinispan.remoting.transport.jgroups.SingleResponseFuture.futureDone(SingleResponseFuture.java:30)
> at org.jgroups.blocks.Request.checkCompletion(Request.java:162)
> at org.jgroups.blocks.UnicastRequest.receiveResponse(UnicastRequest.java:81)
> at org.jgroups.blocks.RequestCorrelator.receiveMessage(RequestCorrelator.java:373)
> at org.jgroups.blocks.RequestCorrelator.receive(RequestCorrelator.java:237)
> at org.jgroups.blocks.MessageDispatcher$ProtocolAdapter.up(MessageDispatcher.java:695)
> at org.jgroups.JChannel.up(JChannel.java:738)
> at org.jgroups.fork.ForkProtocolStack.up(ForkProtocolStack.java:120)
> at org.jgroups.stack.Protocol.up(Protocol.java:379)
> at org.jgroups.protocols.FORK.up(FORK.java:114)
> at org.jgroups.protocols.FRAG2.up(FRAG2.java:165)
> at org.jgroups.protocols.FlowControl.up(FlowControl.java:392)
> at org.jgroups.protocols.FlowControl.up(FlowControl.java:381)
> at org.jgroups.protocols.pbcast.GMS.up(GMS.java:1043)
> at org.jgroups.protocols.pbcast.STABLE.up(STABLE.java:234)
> at org.jgroups.protocols.UNICAST3.deliverMessage(UNICAST3.java:1064)
> at org.jgroups.protocols.UNICAST3.handleDataReceived(UNICAST3.java:779)
> at org.jgroups.protocols.UNICAST3.up(UNICAST3.java:426)
> at org.jgroups.protocols.pbcast.NAKACK2.up(NAKACK2.java:652)
> at org.jgroups.protocols.VERIFY_SUSPECT.up(VERIFY_SUSPECT.java:155)
> at org.jgroups.protocols.FD_ALL.up(FD_ALL.java:200)
> at org.jgroups.protocols.FD_SOCK.up(FD_SOCK.java:310)
> at org.jgroups.protocols.MERGE3.up(MERGE3.java:285)
> at org.jgroups.protocols.Discovery.up(Discovery.java:296)
> at org.jgroups.protocols.TP.passMessageUp(TP.java:1590)
> at org.jgroups.protocols.TP$SingleMessageHandler.run(TP.java:1802)
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
> at java.lang.Thread.run(Thread.java:745)
> Caused by: org.infinispan.commons.CacheException: java.lang.NullPointerException
> at org.infinispan.remoting.inboundhandler.GlobalInboundInvocationHandler.handleFromCluster(GlobalInboundInvocationHandler.java:89)
> at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.executeCommandFromLocalCluster(CommandAwareRpcDispatcher.java:196)
> at org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher.handle(CommandAwareRpcDispatcher.java:166)
> at org.jgroups.blocks.RequestCorrelator.handleRequest(RequestCorrelator.java:402)
> at org.jgroups.blocks.RequestCorrelator.receiveMessage(RequestCorrelator.java:352)
> ... 25 more
> Caused by: java.lang.NullPointerException
> at org.infinispan.remoting.inboundhandler.GlobalInboundInvocationHandler.handleCacheRpcCommand(GlobalInboundInvocationHandler.java:126)
> at org.infinispan.remoting.inboundhandler.GlobalInboundInvocationHandler.handleFromCluster(GlobalInboundInvocationHandler.java:75)
> ... 29 more
> {code}
--
This message was sent by Atlassian JIRA
(v6.4.11#64026)
8 years, 1 month
[JBoss JIRA] (ISPN-6421) Instantiation of cache based on template should not modify template
by Sebastian Łaskawiec (JIRA)
[ https://issues.jboss.org/browse/ISPN-6421?page=com.atlassian.jira.plugin.... ]
Sebastian Łaskawiec updated ISPN-6421:
--------------------------------------
Fix Version/s: (was: 8.2.1.Final)
> Instantiation of cache based on template should not modify template
> -------------------------------------------------------------------
>
> Key: ISPN-6421
> URL: https://issues.jboss.org/browse/ISPN-6421
> Project: Infinispan
> Issue Type: Bug
> Components: Console
> Affects Versions: 8.2.0.Final
> Reporter: Tristan Tarrant
> Assignee: Vladimir Blagojevic
> Fix For: 9.0.0.Alpha1, 9.0.0.Final
>
>
> In cache add, instiating a cache A based on template T should not modify T but should create a configuration A under configurations=CONFIGURATIONS with the "template" attribute set to false and the "configuration" attribute set to T and then a cache A with "configuration" A.
--
This message was sent by Atlassian JIRA
(v6.4.11#64026)
8 years, 1 month