[JBoss JIRA] (ISPN-6353) REST service fails to start during remote query server integration tests
by Adrian Nistor (JIRA)
[ https://issues.jboss.org/browse/ISPN-6353?page=com.atlassian.jira.plugin.... ]
Adrian Nistor updated ISPN-6353:
--------------------------------
Status: Open (was: New)
> REST service fails to start during remote query server integration tests
> ------------------------------------------------------------------------
>
> Key: ISPN-6353
> URL: https://issues.jboss.org/browse/ISPN-6353
> Project: Infinispan
> Issue Type: Bug
> Affects Versions: 8.1.0.Final
> Reporter: Adrian Nistor
> Assignee: Adrian Nistor
> Fix For: 9.0.0.Final, 9.0.0.Alpha1, 8.1.3.Final, 8.2.1.Final
>
>
> Errors are logged, REST service fails to start due to classloading problems of InfinispanIndexManager. This happens because the rest cache is not defined in the configuration so it gets created automatically based on the default config which happens to be an indexed cache, using InfinispanIndexManager, which is not normally available to the REST service. The tests do not fail.
--
This message was sent by Atlassian JIRA
(v6.4.11#64026)
10 years, 1 month
- 1
- 0
[JBoss JIRA] (ISPN-6353) REST service fails to start during remote query server integration tests
by Adrian Nistor (JIRA)
[ https://issues.jboss.org/browse/ISPN-6353?page=com.atlassian.jira.plugin.... ]
Adrian Nistor updated ISPN-6353:
--------------------------------
Fix Version/s: 9.0.0.Final
9.0.0.Alpha1
8.1.3.Final
8.2.1.Final
> REST service fails to start during remote query server integration tests
> ------------------------------------------------------------------------
>
> Key: ISPN-6353
> URL: https://issues.jboss.org/browse/ISPN-6353
> Project: Infinispan
> Issue Type: Bug
> Affects Versions: 8.1.0.Final
> Reporter: Adrian Nistor
> Assignee: Adrian Nistor
> Fix For: 9.0.0.Final, 9.0.0.Alpha1, 8.1.3.Final, 8.2.1.Final
>
>
> Errors are logged, REST service fails to start due to classloading problems of InfinispanIndexManager. This happens because the rest cache is not defined in the configuration so it gets created automatically based on the default config which happens to be an indexed cache, using InfinispanIndexManager, which is not normally available to the REST service. The tests do not fail.
--
This message was sent by Atlassian JIRA
(v6.4.11#64026)
10 years, 1 month
- 1
- 0
[JBoss JIRA] (ISPN-6353) REST service fails to start during remote query server integration tests
by Adrian Nistor (JIRA)
[ https://issues.jboss.org/browse/ISPN-6353?page=com.atlassian.jira.plugin.... ]
Work on ISPN-6353 started by Adrian Nistor.
-------------------------------------------
> REST service fails to start during remote query server integration tests
> ------------------------------------------------------------------------
>
> Key: ISPN-6353
> URL: https://issues.jboss.org/browse/ISPN-6353
> Project: Infinispan
> Issue Type: Bug
> Affects Versions: 8.1.0.Final
> Reporter: Adrian Nistor
> Assignee: Adrian Nistor
> Fix For: 9.0.0.Final, 9.0.0.Alpha1, 8.1.3.Final, 8.2.1.Final
>
>
> Errors are logged, REST service fails to start due to classloading problems of InfinispanIndexManager. This happens because the rest cache is not defined in the configuration so it gets created automatically based on the default config which happens to be an indexed cache, using InfinispanIndexManager, which is not normally available to the REST service. The tests do not fail.
--
This message was sent by Atlassian JIRA
(v6.4.11#64026)
10 years, 1 month
- 1
- 0
[JBoss JIRA] (ISPN-6352) ClusterExecutor.submitConsumer swallows exceptions thrown by the consumer
by Dan Berindei (JIRA)
Dan Berindei created ISPN-6352:
----------------------------------
Summary: ClusterExecutor.submitConsumer swallows exceptions thrown by the consumer
Key: ISPN-6352
URL: https://issues.jboss.org/browse/ISPN-6352
Project: Infinispan
Issue Type: Bug
Components: Core
Affects Versions: 8.2.0.Final
Reporter: Dan Berindei
Fix For: 9.0.0.Final, 8.2.1.Final
When the remote/local function throws an exception, the {{TriConsumer}} receives the exception as a parameter and can handle it. When the {{TriConsumer}} throws an exception, however, that exception is hidden from the caller.
--
This message was sent by Atlassian JIRA
(v6.4.11#64026)
10 years, 1 month
- 1
- 0
[JBoss JIRA] (ISPN-6352) ClusterExecutor.submitConsumer swallows exceptions thrown by the consumer
by Dan Berindei (JIRA)
[ https://issues.jboss.org/browse/ISPN-6352?page=com.atlassian.jira.plugin.... ]
Dan Berindei reassigned ISPN-6352:
----------------------------------
Assignee: William Burns
> ClusterExecutor.submitConsumer swallows exceptions thrown by the consumer
> -------------------------------------------------------------------------
>
> Key: ISPN-6352
> URL: https://issues.jboss.org/browse/ISPN-6352
> Project: Infinispan
> Issue Type: Bug
> Components: Core
> Affects Versions: 8.2.0.Final
> Reporter: Dan Berindei
> Assignee: William Burns
> Fix For: 9.0.0.Final, 8.2.1.Final
>
>
> When the remote/local function throws an exception, the {{TriConsumer}} receives the exception as a parameter and can handle it. When the {{TriConsumer}} throws an exception, however, that exception is hidden from the caller.
--
This message was sent by Atlassian JIRA
(v6.4.11#64026)
10 years, 1 month
- 1
- 0
[JBoss JIRA] (ISPN-6351) ClusterExecutor submitConsumer can complete before local thread completes
by William Burns (JIRA)
[ https://issues.jboss.org/browse/ISPN-6351?page=com.atlassian.jira.plugin.... ]
William Burns updated ISPN-6351:
--------------------------------
Status: Open (was: New)
> 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: 9.0.0.Alpha1, 8.2.1.Final
>
>
> 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)
10 years, 1 month
- 1
- 0
[JBoss JIRA] (ISPN-6351) ClusterExecutor submitConsumer can complete before local thread completes
by William Burns (JIRA)
[ https://issues.jboss.org/browse/ISPN-6351?page=com.atlassian.jira.plugin.... ]
William Burns updated ISPN-6351:
--------------------------------
Status: Pull Request Sent (was: Open)
Git Pull Request: https://github.com/infinispan/infinispan/pull/4101
> 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: 9.0.0.Alpha1, 8.2.1.Final
>
>
> 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)
10 years, 1 month
- 1
- 0
[JBoss JIRA] (ISPN-6351) ClusterExecutor submitConsumer can complete before local thread completes
by William Burns (JIRA)
William Burns created ISPN-6351:
-----------------------------------
Summary: 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: 9.0.0.Alpha1, 8.2.1.Final
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)
10 years, 1 month
- 1
- 0
[JBoss JIRA] (ISPRK-20) Update to Infinispan 8.2.0.Final
by Gustavo Fernandes (JIRA)
Gustavo Fernandes created ISPRK-20:
--------------------------------------
Summary: Update to Infinispan 8.2.0.Final
Key: ISPRK-20
URL: https://issues.jboss.org/browse/ISPRK-20
Project: Infinispan Spark
Issue Type: Bug
Reporter: Gustavo Fernandes
--
This message was sent by Atlassian JIRA
(v6.4.11#64026)
10 years, 1 month
- 1
- 0
[JBoss JIRA] (ISPRK-20) Update to Infinispan 8.2.0.Final
by Gustavo Fernandes (JIRA)
[ https://issues.jboss.org/browse/ISPRK-20?page=com.atlassian.jira.plugin.s... ]
Gustavo Fernandes updated ISPRK-20:
-----------------------------------
Issue Type: Component Upgrade (was: Bug)
> Update to Infinispan 8.2.0.Final
> --------------------------------
>
> Key: ISPRK-20
> URL: https://issues.jboss.org/browse/ISPRK-20
> Project: Infinispan Spark
> Issue Type: Component Upgrade
> Reporter: Gustavo Fernandes
>
--
This message was sent by Atlassian JIRA
(v6.4.11#64026)
10 years, 1 month
- 1
- 0