ClusterExecutor submitConsumer can complete before local thread completes ------------------------------------------------------------------------- Key: ISPN-6351 URL: https://issues.jboss.org/browse/ISPN-6351 Project: Infinispan Issue Type: Bug Components: Distributed Execution and Map/Reduce Affects Versions: 8.2.0.Final Reporter: William Burns Assignee: William Burns Fix For: 8.2.1.Final, 9.0.0.Alpha1 The ClusterExecutor test can fail spuriously. Below is the trace output. {code} 10:36:07,855 INFO (testng-ClusterExecutorTest:) [UnitTestTestNGListener] Test suite progress: tests succeeded: 236, failed: 0, skipped: 0. 10:36:07,855 INFO (testng-ClusterExecutorTest:) [UnitTestTestNGListener] Starting test testExecutorTriConsumer(org.infinispan.manager.ClusterExecutorTest) 10:36:07,857 DEBUG (testng-ClusterExecutorTest:) [ServiceFinder] No service impls found: ModuleLifecycle 10:36:07,857 DEBUG (testng-ClusterExecutorTest:) [ServiceFinder] Loading service impl: CoreTestMetadataFileFinder 10:36:07,861 DEBUG (testng-ClusterExecutorTest:) [ServiceFinder] Loading service impl: TestModuleCommandExtensions 10:36:07,861 DEBUG (testng-ClusterExecutorTest:) [ModuleProperties] Loading module command extension SPI class: org.infinispan.remoting.rpc.TestModuleCommandExtensions@50408d95 10:36:07,865 INFO (testng-ClusterExecutorTest:) [JGroupsTransport] ISPN000078: Starting JGroups channel ISPN 10:36:07,870 DEBUG (testng-ClusterExecutorTest:) [Configurator] set property TCP_NIO2.diagnostics_addr to default value /224.0.75.75 10:36:07,871 TRACE (testng-ClusterExecutorTest:) [NAKACK2] null: set max_xmit_req_size from 0 to 247600 10:36:07,871 TRACE (testng-ClusterExecutorTest:) [UNICAST3] null: set max_xmit_req_size from 0 to 247600 10:36:07,871 TRACE (testng-ClusterExecutorTest:) [MessageDispatcher] setting local_addr (null) to NodeV-57636 10:36:07,871 TRACE (testng-ClusterExecutorTest:) [STABLE] NodeV-57636: stable task started 10:36:07,871 TRACE (testng-ClusterExecutorTest:) [TEST_PING] Discovery.stopped=false 10:36:07,872 DEBUG (testng-ClusterExecutorTest:) [GMS] address=NodeV-57636, cluster=ISPN, physical address=127.0.0.1:9000 10:36:07,872 TRACE (testng-ClusterExecutorTest:) [TEST_PING] Discoveries for DiscoveryKey{clusterName='ISPN', testName='org.infinispan.manager.ClusterExecutorTest'} are : {} 10:36:07,872 TRACE (testng-ClusterExecutorTest:) [TEST_PING] Add discovery for NodeV-57636 to cache. The cache now contains: {NodeV-57636=TEST_PING@NodeV-57636} 10:36:07,872 TRACE (testng-ClusterExecutorTest:) [TEST_PING] Skipping sending discovery to self 10:36:07,872 TRACE (testng-ClusterExecutorTest:) [GMS] NodeV-57636: no members discovered after 0 ms: creating cluster as first member 10:36:07,872 DEBUG (testng-ClusterExecutorTest:) [NAKACK2] [NodeV-57636 setDigest()] existing digest: [] new digest: NodeV-57636: [0 (0)] resulting digest: NodeV-57636: [0 (0)] 10:36:07,872 DEBUG (testng-ClusterExecutorTest:) [GMS] NodeV-57636: installing view [NodeV-57636|0] (1) [NodeV-57636] 10:36:07,872 DEBUG (testng-ClusterExecutorTest:) [STABLE] resuming message garbage collection 10:36:07,872 TRACE (testng-ClusterExecutorTest:) [STABLE] NodeV-57636: reset digest to NodeV-57636: [-1] 10:36:07,872 TRACE (testng-ClusterExecutorTest:) [TOA] Handle view [NodeV-57636|0] (1) [NodeV-57636] 10:36:07,872 TRACE (testng-ClusterExecutorTest:) [MFC] new membership: [NodeV-57636] 10:36:07,872 DEBUG (testng-ClusterExecutorTest:) [JGroupsTransport] New view accepted: [NodeV-57636|0] (1) [NodeV-57636] 10:36:07,872 INFO (testng-ClusterExecutorTest:) [JGroupsTransport] ISPN000094: Received new cluster view for channel ISPN: [NodeV-57636|0] (1) [NodeV-57636] 10:36:07,872 TRACE (testng-ClusterExecutorTest:) [STABLE] NodeV-57636: reset digest to NodeV-57636: [-1] 10:36:07,872 DEBUG (testng-ClusterExecutorTest:) [STABLE] resuming message garbage collection 10:36:07,872 DEBUG (testng-ClusterExecutorTest:) [GMS] NodeV-57636: created cluster (first member). My view is [NodeV-57636|0], impl is org.jgroups.protocols.pbcast.CoordGmsImpl 10:36:07,872 INFO (testng-ClusterExecutorTest:) [JGroupsTransport] ISPN000079: Channel ISPN local address is NodeV-57636, physical addresses are [127.0.0.1:9000] 10:36:07,872 TRACE (testng-ClusterExecutorTest:) [JGroupsTransport] Waiting on view 0 being accepted 10:36:07,872 TRACE (testng-ClusterExecutorTest:) [SemaphoreCompletionService] New task submitted, tasks in queue 1, available permits 1 10:36:07,872 TRACE (testng-ClusterExecutorTest:) [LocalTopologyManagerImpl] Starting LocalTopologyManager on NodeV-57636 10:36:07,872 TRACE (transport-thread-NodeV-p1249-t1:) [SemaphoreCompletionService] Task started, tasks in queue 0, available permits 0 10:36:07,872 DEBUG (testng-ClusterExecutorTest:) [DefaultCacheManager] Started cache manager ISPN on NodeV 10:36:07,872 TRACE (transport-thread-NodeV-p1249-t1:) [ClusterTopologyManagerImpl] Received new cluster view: 0, isCoordinator = true, old status = INITIALIZING 10:36:07,872 DEBUG (transport-thread-NodeV-p1249-t1:) [ClusterTopologyManagerImpl] Recovering cluster status for view 0 10:36:07,872 TRACE (transport-thread-NodeV-p1249-t1:) [JGroupsTransport] dests=null, command=CacheTopologyControlCommand{cache=null, type=GET_STATUS, sender=NodeV-57636, joinInfo=null, topologyId=0, rebalanceId=0, currentCH=null, pendingCH=null, availabilityMode=null, actualMembers=null, throwable=null, viewId=0}, mode=SYNCHRONOUS, timeout=240000 10:36:07,873 TRACE (transport-thread-NodeV-p1249-t1:) [ClusterTopologyManagerImpl] Attempting to execute command on self: CacheTopologyControlCommand{cache=null, type=GET_STATUS, sender=NodeV-57636, joinInfo=null, topologyId=0, rebalanceId=0, currentCH=null, pendingCH=null, availabilityMode=null, actualMembers=null, throwable=null, viewId=0} 10:36:07,873 TRACE (transport-thread-NodeV-p1249-t1:) [JGroupsTransport] Waiting on view 0 being accepted 10:36:07,873 DEBUG (transport-thread-NodeV-p1249-t1:) [LocalTopologyManagerImpl] Sending cluster status response for view 0 10:36:07,873 DEBUG (transport-thread-NodeV-p1249-t1:) [ClusterTopologyManagerImpl] Got 1 status responses. members are [NodeV-57636] 10:36:07,873 TRACE (transport-thread-NodeV-p1249-t1:) [ClusterTopologyManagerImpl] Updating cluster members for all the caches. New list is [NodeV-57636] 10:36:07,873 TRACE (transport-thread-NodeV-p1249-t1:) [JGroupsTransport] dests=null, command=CacheTopologyControlCommand{cache=null, type=POLICY_GET_STATUS, sender=NodeV-57636, joinInfo=null, topologyId=0, rebalanceId=0, currentCH=null, pendingCH=null, availabilityMode=null, actualMembers=null, throwable=null, viewId=-1}, mode=SYNCHRONOUS, timeout=240000 10:36:07,873 TRACE (transport-thread-NodeV-p1249-t1:) [SemaphoreCompletionService] Task finished, tasks in queue 0, available permits 0 10:36:07,874 DEBUG (testng-ClusterExecutorTest:) [ServiceFinder] No service impls found: ModuleLifecycle 10:36:07,874 DEBUG (testng-ClusterExecutorTest:) [ServiceFinder] Loading service impl: CoreTestMetadataFileFinder 10:36:07,878 DEBUG (testng-ClusterExecutorTest:) [ServiceFinder] Loading service impl: TestModuleCommandExtensions 10:36:07,878 DEBUG (testng-ClusterExecutorTest:) [ModuleProperties] Loading module command extension SPI class: org.infinispan.remoting.rpc.TestModuleCommandExtensions@7dd5c371 10:36:07,880 INFO (testng-ClusterExecutorTest:) [JGroupsTransport] ISPN000078: Starting JGroups channel ISPN 10:36:07,888 DEBUG (testng-ClusterExecutorTest:) [Configurator] set property TCP_NIO2.diagnostics_addr to default value /224.0.75.75 10:36:07,889 TRACE (testng-ClusterExecutorTest:) [NAKACK2] null: set max_xmit_req_size from 0 to 247600 10:36:07,889 TRACE (testng-ClusterExecutorTest:) [UNICAST3] null: set max_xmit_req_size from 0 to 247600 10:36:07,889 TRACE (testng-ClusterExecutorTest:) [MessageDispatcher] setting local_addr (null) to NodeW-53871 10:36:07,889 TRACE (testng-ClusterExecutorTest:) [STABLE] NodeW-53871: stable task started 10:36:07,889 TRACE (testng-ClusterExecutorTest:) [TEST_PING] Discovery.stopped=false 10:36:07,890 DEBUG (testng-ClusterExecutorTest:) [GMS] address=NodeW-53871, cluster=ISPN, physical address=127.0.0.1:9001 10:36:07,890 TRACE (testng-ClusterExecutorTest:) [TEST_PING] Discoveries for DiscoveryKey{clusterName='ISPN', testName='org.infinispan.manager.ClusterExecutorTest'} are : {NodeV-57636=TEST_PING@NodeV-57636} 10:36:07,890 TRACE (testng-ClusterExecutorTest:) [TEST_PING] Add discovery for NodeW-53871 to cache. The cache now contains: {NodeV-57636=TEST_PING@NodeV-57636, NodeW-53871=TEST_PING@NodeW-53871} 10:36:07,890 TRACE (testng-ClusterExecutorTest:) [TEST_PING] Map NodeV-57636 with physical address 127.0.0.1:9000 in TEST_PING@NodeW-53871 10:36:07,890 TRACE (testng-ClusterExecutorTest:) [TEST_PING] Map NodeW-53871 with physical address 127.0.0.1:9001 in TEST_PING@NodeV-57636 10:36:07,890 TRACE (testng-ClusterExecutorTest:) [TEST_PING] Returning ping rsp: NodeV-57636, name=NodeV-57636, addr=127.0.0.1:9000, coord 10:36:07,890 TRACE (testng-ClusterExecutorTest:) [TEST_PING] Skipping sending discovery to self 10:36:07,890 TRACE (testng-ClusterExecutorTest:) [GMS] NodeW-53871: discovery took 0 ms, members: 1 rsps (1 coords) [done] 10:36:07,890 DEBUG (testng-ClusterExecutorTest:) [GMS] NodeW-53871: sending JOIN(NodeW-53871) to NodeV-57636 10:36:07,890 TRACE (testng-ClusterExecutorTest:) [UNICAST3] NodeW-53871: created sender window for NodeV-57636 (conn-id=0) 10:36:07,890 TRACE (testng-ClusterExecutorTest:) [UNICAST3] NodeW-53871 --> DATA(NodeV-57636: #1, conn_id=0, first) 10:36:07,890 TRACE (testng-ClusterExecutorTest:) [TCP_NIO2] NodeW-53871: sending msg to NodeV-57636, src=NodeW-53871, headers are GMS: GmsHeader[JOIN_REQ]: mbr=NodeW-53871, UNICAST3: DATA, seqno=1, first, TP: [cluster_name=ISPN] 10:36:07,915 TRACE (Timer-2,NodeW-53871:) [TCP_NIO2] NodeW-53871: sending 1 msgs (83 bytes (0.27% of max_bundle_size) to 1 dests(s): [ISPN:NodeV-57636] 10:36:07,915 TRACE (Timer-2,NodeW-53871:) [TCP_NIO2] dest=127.0.0.1:9000 (86 bytes) 10:36:07,915 TRACE (Timer-2,NodeW-53871:) [TCP_NIO2] 127.0.0.1:9001: connecting to 127.0.0.1:9000 10:36:07,917 TRACE (INT-1,NodeV-57636:) [TCP_NIO2] NodeV-57636: received [dst: NodeV-57636, src: NodeW-53871 (3 headers), size=0 bytes, flags=OOB|INTERNAL], headers are GMS: GmsHeader[JOIN_REQ]: mbr=NodeW-53871, UNICAST3: DATA, seqno=1, first, TP: [cluster_name=ISPN] 10:36:07,917 TRACE (INT-1,NodeV-57636:) [UNICAST3] NodeV-57636 <-- DATA(NodeW-53871: #1, conn_id=0, first) 10:36:07,917 TRACE (INT-1,NodeV-57636:) [UNICAST3] NodeV-57636: created receiver window for NodeW-53871 at seqno=#1 for conn-id=0 10:36:07,917 TRACE (INT-1,NodeV-57636:) [UNICAST3] NodeV-57636: delivering NodeW-53871#1 10:36:07,978 TRACE (ViewHandler,NodeV-57636:) [GMS] NodeV-57636: joiners=[NodeW-53871], suspected=[], leaving=[], new view: [NodeV-57636|1] (2) [NodeV-57636, NodeW-53871] 10:36:07,978 DEBUG (ViewHandler,NodeV-57636:) [STABLE] suspending message garbage collection 10:36:07,978 DEBUG (ViewHandler,NodeV-57636:) [STABLE] NodeV-57636: resume task started, max_suspend_time=33000 10:36:07,978 TRACE (ViewHandler,NodeV-57636:) [GMS] NodeV-57636: mcasting view [NodeV-57636|1] (2) [NodeV-57636, NodeW-53871] (2 mbrs) 10:36:07,978 TRACE (ViewHandler,NodeV-57636:) [NAKACK2] NodeV-57636: sending NodeV-57636#1 10:36:07,978 TRACE (ViewHandler,NodeV-57636:) [TCP_NIO2] NodeV-57636: sending msg to null, src=NodeV-57636, headers are GMS: GmsHeader[VIEW], NAKACK2: [MSG, seqno=1], TP: [cluster_name=ISPN] 10:36:07,978 TRACE (ViewHandler,NodeV-57636:) [TCP_NIO2] NodeV-57636: looping back message [dst: <null>, src: NodeV-57636 (3 headers), size=57 bytes] 10:36:07,978 TRACE (Incoming-1,NodeV-57636:) [TCP_NIO2] NodeV-57636: received [dst: <null>, src: NodeV-57636 (3 headers), size=57 bytes], headers are GMS: GmsHeader[VIEW], NAKACK2: [MSG, seqno=1], TP: [cluster_name=ISPN] 10:36:07,978 TRACE (Incoming-1,NodeV-57636:) [NAKACK2] NodeV-57636: received NodeV-57636#1 10:36:07,978 TRACE (Incoming-1,NodeV-57636:) [NAKACK2] NodeV-57636: delivering NodeV-57636#1-1 (1 messages) 10:36:07,979 TRACE (Incoming-1,NodeV-57636:) [GMS] NodeV-57636: received full view: [NodeV-57636|1] (2) [NodeV-57636, NodeW-53871] 10:36:07,979 DEBUG (Incoming-1,NodeV-57636:) [GMS] NodeV-57636: installing view [NodeV-57636|1] (2) [NodeV-57636, NodeW-53871] 10:36:07,979 TRACE (Incoming-1,NodeV-57636:) [STABLE] NodeV-57636: reset digest to NodeV-57636: [-1], NodeW-53871: [-1] 10:36:07,979 TRACE (Incoming-1,NodeV-57636:) [TOA] Handle view [NodeV-57636|1] (2) [NodeV-57636, NodeW-53871] 10:36:07,979 TRACE (Incoming-1,NodeV-57636:) [MFC] new membership: [NodeV-57636, NodeW-53871] 10:36:07,979 DEBUG (Incoming-1,NodeV-57636:) [JGroupsTransport] New view accepted: [NodeV-57636|1] (2) [NodeV-57636, NodeW-53871] 10:36:07,979 DEBUG (Incoming-1,NodeV-57636:) [JGroupsTransport] Joined: [NodeW-53871], Left: [] 10:36:07,979 INFO (Incoming-1,NodeV-57636:) [JGroupsTransport] ISPN000094: Received new cluster view for channel ISPN: [NodeV-57636|1] (2) [NodeV-57636, NodeW-53871] 10:36:07,979 TRACE (Incoming-1,NodeV-57636:) [SemaphoreCompletionService] New task submitted, tasks in queue 1, available permits 1 10:36:07,979 TRACE (transport-thread-NodeV-p1249-t2:) [SemaphoreCompletionService] Task started, tasks in queue 0, available permits 0 10:36:07,979 TRACE (transport-thread-NodeV-p1249-t2:) [ClusterTopologyManagerImpl] Received new cluster view: 1, isCoordinator = true, old status = COORDINATOR 10:36:07,979 TRACE (transport-thread-NodeV-p1249-t2:) [ClusterTopologyManagerImpl] Updating cluster members for all the caches. New list is [NodeV-57636, NodeW-53871] 10:36:07,979 TRACE (transport-thread-NodeV-p1249-t2:) [JGroupsTransport] dests=null, command=CacheTopologyControlCommand{cache=null, type=POLICY_GET_STATUS, sender=NodeV-57636, joinInfo=null, topologyId=0, rebalanceId=0, currentCH=null, pendingCH=null, availabilityMode=null, actualMembers=null, throwable=null, viewId=-1}, mode=SYNCHRONOUS, timeout=240000 10:36:07,979 TRACE (transport-thread-NodeV-p1249-t2:) [CommandAwareRpcDispatcher] Replication task sending CacheTopologyControlCommand{cache=null, type=POLICY_GET_STATUS, sender=NodeV-57636, joinInfo=null, topologyId=0, rebalanceId=0, currentCH=null, pendingCH=null, availabilityMode=null, actualMembers=null, throwable=null, viewId=-1} to single recipient NodeW-53871 with response mode GET_ALL 10:36:07,979 TRACE (transport-thread-NodeV-p1249-t2:) [RequestCorrelator] NodeV-57636: invoking unicast RPC [req-id=1546] on NodeW-53871 10:36:07,979 TRACE (Incoming-1,NodeV-57636:) [UNICAST3] NodeV-57636: created sender window for NodeV-57636 (conn-id=0) 10:36:07,979 TRACE (transport-thread-NodeV-p1249-t2:) [UNICAST3] NodeV-57636: created sender window for NodeW-53871 (conn-id=1) 10:36:07,979 TRACE (Incoming-1,NodeV-57636:) [UNICAST3] NodeV-57636 --> DATA(NodeV-57636: #1, conn_id=0, first) 10:36:07,979 TRACE (transport-thread-NodeV-p1249-t2:) [UNICAST3] NodeV-57636 --> DATA(NodeW-53871: #1, conn_id=1, first) 10:36:07,979 TRACE (Incoming-1,NodeV-57636:) [TCP_NIO2] NodeV-57636: sending msg to NodeV-57636, src=NodeV-57636, headers are GMS: GmsHeader[VIEW_ACK], UNICAST3: DATA, seqno=1, first, TP: [cluster_name=ISPN] 10:36:07,979 TRACE (transport-thread-NodeV-p1249-t2:) [TCP_NIO2] NodeV-57636: sending msg to NodeW-53871, src=NodeV-57636, headers are RequestCorrelator: corr_id=200, type=REQ, req_id=1546, rsp_expected=true, UNICAST3: DATA, seqno=1, conn_id=1, first, TP: [cluster_name=ISPN] 10:36:07,979 TRACE (Incoming-1,NodeV-57636:) [TCP_NIO2] NodeV-57636: looping back message [dst: NodeV-57636, src: NodeV-57636 (3 headers), size=0 bytes, flags=OOB|INTERNAL] 10:36:07,979 TRACE (transport-thread-NodeV-p1249-t2:) [TCP_NIO2] dest=127.0.0.1:9001 (87 bytes) 10:36:07,980 TRACE (INT-2,NodeV-57636:) [TCP_NIO2] NodeV-57636: received [dst: NodeV-57636, src: NodeV-57636 (3 headers), size=0 bytes, flags=OOB|INTERNAL], headers are GMS: GmsHeader[VIEW_ACK], UNICAST3: DATA, seqno=1, first, TP: [cluster_name=ISPN] 10:36:07,980 TRACE (INT-2,NodeV-57636:) [UNICAST3] NodeV-57636 <-- DATA(NodeV-57636: #1, conn_id=0, first) 10:36:07,980 TRACE (INT-2,NodeV-57636:) [UNICAST3] NodeV-57636: delivering NodeV-57636#1 10:36:07,981 TRACE (ViewHandler,NodeV-57636:) [GMS] NodeV-57636: got all ACKs (1) from members for view [NodeV-57636|1] 10:36:07,981 TRACE (ViewHandler,NodeV-57636:) [UNICAST3] NodeV-57636 --> DATA(NodeW-53871: #2, conn_id=1) 10:36:07,981 TRACE (ViewHandler,NodeV-57636:) [TCP_NIO2] NodeV-57636: sending msg to NodeW-53871, src=NodeV-57636, headers are GMS: GmsHeader[JOIN_RSP], UNICAST3: DATA, seqno=2, conn_id=1, TP: [cluster_name=ISPN] 10:36:07,982 TRACE (OOB-1,NodeW-53871:) [TCP_NIO2] NodeW-53871: received [dst: NodeW-53871, src: NodeV-57636 (3 headers), size=11 bytes, flags=OOB|DONT_BUNDLE|NO_TOTAL_ORDER], headers are RequestCorrelator: corr_id=200, type=REQ, req_id=1546, rsp_expected=true, UNICAST3: DATA, seqno=1, conn_id=1, first, TP: [cluster_name=ISPN] 10:36:07,982 TRACE (OOB-1,NodeW-53871:) [UNICAST3] NodeW-53871 <-- DATA(NodeV-57636: #1, conn_id=1, first) 10:36:07,987 TRACE (OOB-1,NodeW-53871:) [UNICAST3] NodeW-53871: created receiver window for NodeV-57636 at seqno=#1 for conn-id=1 10:36:07,987 TRACE (OOB-1,NodeW-53871:) [UNICAST3] NodeW-53871: delivering NodeV-57636#1 10:36:07,987 TRACE (OOB-1,NodeW-53871:) [RequestCorrelator] calling (org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher) with request 1546 10:36:07,988 TRACE (OOB-1,NodeW-53871:) [GlobalInboundInvocationHandler] Attempting to execute non-CacheRpcCommand: CacheTopologyControlCommand{cache=null, type=POLICY_GET_STATUS, sender=null, joinInfo=null, topologyId=0, rebalanceId=0, currentCH=null, pendingCH=null, availabilityMode=null, actualMembers=null, throwable=null, viewId=0} [sender=NodeV-57636] 10:36:07,995 TRACE (OOB-1,NodeW-53871:) [BlockingTaskAwareExecutorServiceImpl] Added a new task directly: 0 task(s) are waiting 10:36:07,998 TRACE (Timer-2,NodeV-57636:) [TCP_NIO2] NodeV-57636: sending 2 msgs (240 bytes (0.77% of max_bundle_size) to 2 dests(s): [ISPN:NodeW-53871, ISPN] 10:36:07,999 TRACE (Timer-2,NodeV-57636:) [TCP_NIO2] dest=127.0.0.1:9001 (135 bytes) 10:36:07,999 TRACE (Timer-2,NodeV-57636:) [TCP_NIO2] dest=127.0.0.1:9001 (111 bytes) 10:36:07,999 TRACE (INT-1,NodeW-53871:) [TCP_NIO2] NodeW-53871: received [dst: NodeW-53871, src: NodeV-57636 (3 headers), size=61 bytes, flags=OOB|INTERNAL], headers are GMS: GmsHeader[JOIN_RSP], UNICAST3: DATA, seqno=2, conn_id=1, TP: [cluster_name=ISPN] 10:36:07,999 TRACE (INT-1,NodeW-53871:) [UNICAST3] NodeW-53871 <-- DATA(NodeV-57636: #2, conn_id=1) 10:36:07,999 TRACE (INT-1,NodeW-53871:) [UNICAST3] NodeW-53871: delivering NodeV-57636#2 10:36:07,999 DEBUG (testng-ClusterExecutorTest:) [NAKACK2] [NodeW-53871 setDigest()] existing digest: [] new digest: NodeV-57636: [0 (0)], NodeW-53871: [0 (0)] resulting digest: NodeV-57636: [0 (0)], NodeW-53871: [0 (0)] 10:36:07,999 DEBUG (testng-ClusterExecutorTest:) [GMS] NodeW-53871: installing view [NodeV-57636|1] (2) [NodeV-57636, NodeW-53871] 10:36:07,999 TRACE (testng-ClusterExecutorTest:) [STABLE] NodeW-53871: reset digest to NodeV-57636: [-1], NodeW-53871: [-1] 10:36:07,999 TRACE (testng-ClusterExecutorTest:) [TOA] Handle view [NodeV-57636|1] (2) [NodeV-57636, NodeW-53871] 10:36:07,999 TRACE (testng-ClusterExecutorTest:) [MFC] new membership: [NodeV-57636, NodeW-53871] 10:36:07,999 DEBUG (testng-ClusterExecutorTest:) [JGroupsTransport] New view accepted: [NodeV-57636|1] (2) [NodeV-57636, NodeW-53871] 10:36:07,999 INFO (testng-ClusterExecutorTest:) [JGroupsTransport] ISPN000094: Received new cluster view for channel ISPN: [NodeV-57636|1] (2) [NodeV-57636, NodeW-53871] 10:36:08,000 TRACE (testng-ClusterExecutorTest:) [UNICAST3] NodeW-53871 --> DATA(NodeV-57636: #2, conn_id=0) 10:36:08,000 TRACE (testng-ClusterExecutorTest:) [TCP_NIO2] NodeW-53871: sending msg to NodeV-57636, src=NodeW-53871, headers are GMS: GmsHeader[VIEW_ACK], UNICAST3: DATA, seqno=2, TP: [cluster_name=ISPN] 10:36:08,000 INFO (testng-ClusterExecutorTest:) [JGroupsTransport] ISPN000079: Channel ISPN local address is NodeW-53871, physical addresses are [127.0.0.1:9001] 10:36:08,000 TRACE (testng-ClusterExecutorTest:) [JGroupsTransport] Waiting on view 0 being accepted 10:36:08,000 TRACE (testng-ClusterExecutorTest:) [SemaphoreCompletionService] New task submitted, tasks in queue 1, available permits 1 10:36:08,009 TRACE (testng-ClusterExecutorTest:) [JGroupsTransport] dests=[NodeV-57636], command=CacheTopologyControlCommand{cache=null, type=POLICY_GET_STATUS, sender=NodeW-53871, joinInfo=null, topologyId=0, rebalanceId=0, currentCH=null, pendingCH=null, availabilityMode=null, actualMembers=null, throwable=null, viewId=-1}, mode=SYNCHRONOUS, timeout=240000 10:36:08,009 TRACE (testng-ClusterExecutorTest:) [CommandAwareRpcDispatcher] Replication task sending CacheTopologyControlCommand{cache=null, type=POLICY_GET_STATUS, sender=NodeW-53871, joinInfo=null, topologyId=0, rebalanceId=0, currentCH=null, pendingCH=null, availabilityMode=null, actualMembers=null, throwable=null, viewId=-1} to single recipient NodeV-57636 with response mode GET_ALL 10:36:08,009 TRACE (testng-ClusterExecutorTest:) [RequestCorrelator] NodeW-53871: invoking unicast RPC [req-id=1558] on NodeV-57636 10:36:08,009 TRACE (testng-ClusterExecutorTest:) [UNICAST3] NodeW-53871 --> DATA(NodeV-57636: #3, conn_id=0) 10:36:08,009 TRACE (testng-ClusterExecutorTest:) [TCP_NIO2] NodeW-53871: sending msg to NodeV-57636, src=NodeW-53871, headers are RequestCorrelator: corr_id=200, type=REQ, req_id=1558, rsp_expected=true, UNICAST3: DATA, seqno=3, TP: [cluster_name=ISPN] 10:36:08,009 TRACE (testng-ClusterExecutorTest:) [TCP_NIO2] dest=127.0.0.1:9000 (87 bytes) 10:36:08,009 TRACE (OOB-1,NodeV-57636:) [TCP_NIO2] NodeV-57636: received [dst: NodeV-57636, src: NodeW-53871 (3 headers), size=11 bytes, flags=OOB|DONT_BUNDLE|NO_TOTAL_ORDER], headers are RequestCorrelator: corr_id=200, type=REQ, req_id=1558, rsp_expected=true, UNICAST3: DATA, seqno=3, TP: [cluster_name=ISPN] 10:36:08,009 TRACE (OOB-1,NodeV-57636:) [UNICAST3] NodeV-57636 <-- DATA(NodeW-53871: #3, conn_id=0) 10:36:08,009 TRACE (OOB-1,NodeV-57636:) [UNICAST3] NodeV-57636: delivering NodeW-53871#3 10:36:08,009 TRACE (OOB-1,NodeV-57636:) [RequestCorrelator] calling (org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher) with request 1558 10:36:08,009 TRACE (OOB-1,NodeV-57636:) [GlobalInboundInvocationHandler] Attempting to execute non-CacheRpcCommand: CacheTopologyControlCommand{cache=null, type=POLICY_GET_STATUS, sender=null, joinInfo=null, topologyId=0, rebalanceId=0, currentCH=null, pendingCH=null, availabilityMode=null, actualMembers=null, throwable=null, viewId=0} [sender=NodeW-53871] 10:36:08,010 TRACE (Incoming-1,NodeW-53871:) [TCP_NIO2] NodeW-53871: received [dst: <null>, src: NodeV-57636 (3 headers), size=57 bytes], headers are GMS: GmsHeader[VIEW], NAKACK2: [MSG, seqno=1], TP: [cluster_name=ISPN] 10:36:08,010 TRACE (Incoming-1,NodeW-53871:) [NAKACK2] NodeW-53871: received NodeV-57636#1 10:36:08,010 TRACE (Incoming-1,NodeW-53871:) [NAKACK2] NodeW-53871: delivering NodeV-57636#1-1 (1 messages) 10:36:08,010 TRACE (transport-thread-NodeW-p1259-t1:) [SemaphoreCompletionService] Task started, tasks in queue 0, available permits 0 10:36:08,010 TRACE (transport-thread-NodeW-p1259-t1:) [ClusterTopologyManagerImpl] Received new cluster view: 1, isCoordinator = false, old status = INITIALIZING 10:36:08,010 TRACE (transport-thread-NodeW-p1259-t1:) [SemaphoreCompletionService] Task finished, tasks in queue 0, available permits 0 10:36:08,011 TRACE (OOB-1,NodeV-57636:) [BlockingTaskAwareExecutorServiceImpl] Added a new task directly: 0 task(s) are waiting 10:36:08,012 TRACE (remote-thread-NodeV-p1247-t1:) [CommandAwareRpcDispatcher] About to send back response SuccessfulResponse{responseValue=true} for command CacheTopologyControlCommand{cache=null, type=POLICY_GET_STATUS, sender=null, joinInfo=null, topologyId=0, rebalanceId=0, currentCH=null, pendingCH=null, availabilityMode=null, actualMembers=null, throwable=null, viewId=0} 10:36:08,012 TRACE (remote-thread-NodeV-p1247-t1:) [RequestCorrelator] sending rsp for 1558 to NodeW-53871 10:36:08,012 TRACE (remote-thread-NodeV-p1247-t1:) [UNICAST3] NodeV-57636 --> DATA(NodeW-53871: #3, conn_id=1) 10:36:08,012 TRACE (remote-thread-NodeV-p1247-t1:) [TCP_NIO2] NodeV-57636: sending msg to NodeW-53871, src=NodeV-57636, headers are RequestCorrelator: corr_id=200, type=RSP, req_id=1558, rsp_expected=true, UNICAST3: DATA, seqno=3, conn_id=1, TP: [cluster_name=ISPN] 10:36:08,012 TRACE (remote-thread-NodeV-p1247-t1:) [TCP_NIO2] dest=127.0.0.1:9001 (83 bytes) 10:36:08,013 TRACE (OOB-1,NodeW-53871:) [TCP_NIO2] NodeW-53871: received [dst: NodeW-53871, src: NodeV-57636 (3 headers), size=7 bytes, flags=OOB|DONT_BUNDLE|NO_TOTAL_ORDER], headers are RequestCorrelator: corr_id=200, type=RSP, req_id=1558, rsp_expected=true, UNICAST3: DATA, seqno=3, conn_id=1, TP: [cluster_name=ISPN] 10:36:08,013 TRACE (OOB-1,NodeW-53871:) [UNICAST3] NodeW-53871 <-- DATA(NodeV-57636: #3, conn_id=1) 10:36:08,013 TRACE (OOB-1,NodeW-53871:) [UNICAST3] NodeW-53871: delivering NodeV-57636#3 10:36:08,013 TRACE (OOB-1,NodeW-53871:) [JGroupsTransport] Response: sender=NodeV-57636, retval=SuccessfulResponse{responseValue=true} , received=true, suspected=false 10:36:08,013 TRACE (testng-ClusterExecutorTest:) [LocalTopologyManagerImpl] Starting LocalTopologyManager on NodeW-53871 10:36:08,013 DEBUG (testng-ClusterExecutorTest:) [DefaultCacheManager] Started cache manager ISPN on NodeW 10:36:08,013 TRACE (remote-thread-NodeW-p1257-t1:) [CommandAwareRpcDispatcher] About to send back response SuccessfulResponse{responseValue=true} for command CacheTopologyControlCommand{cache=null, type=POLICY_GET_STATUS, sender=null, joinInfo=null, topologyId=0, rebalanceId=0, currentCH=null, pendingCH=null, availabilityMode=null, actualMembers=null, throwable=null, viewId=0} 10:36:08,013 TRACE (remote-thread-NodeW-p1257-t1:) [RequestCorrelator] sending rsp for 1546 to NodeV-57636 10:36:08,013 TRACE (remote-thread-NodeW-p1257-t1:) [UNICAST3] NodeW-53871 --> DATA(NodeV-57636: #4, conn_id=0) 10:36:08,013 TRACE (remote-thread-NodeW-p1257-t1:) [TCP_NIO2] NodeW-53871: sending msg to NodeV-57636, src=NodeW-53871, headers are RequestCorrelator: corr_id=200, type=RSP, req_id=1546, rsp_expected=true, UNICAST3: DATA, seqno=4, TP: [cluster_name=ISPN] 10:36:08,013 TRACE (remote-thread-NodeW-p1257-t1:) [TCP_NIO2] dest=127.0.0.1:9000 (83 bytes) 10:36:08,014 TRACE (OOB-1,NodeV-57636:) [TCP_NIO2] NodeV-57636: received [dst: NodeV-57636, src: NodeW-53871 (3 headers), size=7 bytes, flags=OOB|DONT_BUNDLE|NO_TOTAL_ORDER], headers are RequestCorrelator: corr_id=200, type=RSP, req_id=1546, rsp_expected=true, UNICAST3: DATA, seqno=4, TP: [cluster_name=ISPN] 10:36:08,014 TRACE (OOB-1,NodeV-57636:) [UNICAST3] NodeV-57636 <-- DATA(NodeW-53871: #4, conn_id=0) 10:36:08,014 TRACE (OOB-1,NodeV-57636:) [UNICAST3] NodeV-57636: delivering NodeW-53871#4 10:36:08,014 TRACE (OOB-1,NodeV-57636:) [JGroupsTransport] Response: sender=NodeW-53871, retval=SuccessfulResponse{responseValue=true} , received=true, suspected=false 10:36:08,014 TRACE (transport-thread-NodeV-p1249-t2:) [SemaphoreCompletionService] Task finished, tasks in queue 0, available permits 0 10:36:08,015 TRACE (testng-ClusterExecutorTest:) [ClusterExecutorImpl] Submitting callable to local node on executor thread! - Usually remote command thread pool 10:36:08,015 TRACE (testng-ClusterExecutorTest:) [BlockingTaskAwareExecutorServiceImpl] Added a new task directly: 0 task(s) are waiting 10:36:08,015 TRACE (testng-ClusterExecutorTest:) [ClusterExecutorImpl] Submitting consumer to single remote node - JGroups Address NodeW-53871 10:36:08,015 TRACE (testng-ClusterExecutorTest:) [CommandAwareRpcDispatcher] Replication task sending org.infinispan.manager.impl.ReplicableCommandManagerFunction@187af934 to single recipient NodeW-53871 with response mode GET_ALL 10:36:08,016 TRACE (testng-ClusterExecutorTest:) [RequestCorrelator] NodeV-57636: invoking unicast RPC [req-id=1562] on NodeW-53871 10:36:08,016 TRACE (testng-ClusterExecutorTest:) [UNICAST3] NodeV-57636 --> DATA(NodeW-53871: #4, conn_id=1) 10:36:08,016 TRACE (testng-ClusterExecutorTest:) [TCP_NIO2] NodeV-57636: sending msg to NodeW-53871, src=NodeV-57636, headers are RequestCorrelator: corr_id=200, type=REQ, req_id=1562, rsp_expected=true, UNICAST3: DATA, seqno=4, conn_id=1, TP: [cluster_name=ISPN] 10:36:08,016 TRACE (testng-ClusterExecutorTest:) [TCP_NIO2] dest=127.0.0.1:9001 (731 bytes) 10:36:08,017 TRACE (OOB-1,NodeW-53871:) [TCP_NIO2] NodeW-53871: received [dst: NodeW-53871, src: NodeV-57636 (3 headers), size=655 bytes, flags=OOB|DONT_BUNDLE|NO_TOTAL_ORDER], headers are RequestCorrelator: corr_id=200, type=REQ, req_id=1562, rsp_expected=true, UNICAST3: DATA, seqno=4, conn_id=1, TP: [cluster_name=ISPN] 10:36:08,017 TRACE (OOB-1,NodeW-53871:) [UNICAST3] NodeW-53871 <-- DATA(NodeV-57636: #4, conn_id=1) 10:36:08,017 TRACE (OOB-1,NodeW-53871:) [UNICAST3] NodeW-53871: delivering NodeV-57636#4 10:36:08,017 TRACE (OOB-1,NodeW-53871:) [RequestCorrelator] calling (org.infinispan.remoting.transport.jgroups.CommandAwareRpcDispatcher) with request 1562 10:36:08,017 TRACE (OOB-1,NodeW-53871:) [GlobalInboundInvocationHandler] Attempting to execute non-CacheRpcCommand: org.infinispan.manager.impl.ReplicableCommandManagerFunction@42c891df [sender=NodeV-57636] 10:36:08,018 TRACE (OOB-1,NodeW-53871:) [BlockingTaskAwareExecutorServiceImpl] Added a new task directly: 0 task(s) are waiting 10:36:08,018 TRACE (remote-thread-NodeW-p1257-t2:) [CommandAwareRpcDispatcher] About to send back response SuccessfulResponse{responseValue=NodeW-53871} for command org.infinispan.manager.impl.ReplicableCommandManagerFunction@42c891df 10:36:08,019 TRACE (remote-thread-NodeW-p1257-t2:) [RequestCorrelator] sending rsp for 1562 to NodeV-57636 10:36:08,019 TRACE (remote-thread-NodeW-p1257-t2:) [UNICAST3] NodeW-53871 --> DATA(NodeV-57636: #5, conn_id=0) 10:36:08,019 TRACE (remote-thread-NodeW-p1257-t2:) [TCP_NIO2] NodeW-53871: sending msg to NodeV-57636, src=NodeW-53871, headers are RequestCorrelator: corr_id=200, type=RSP, req_id=1562, rsp_expected=true, UNICAST3: DATA, seqno=5, TP: [cluster_name=ISPN] 10:36:08,019 TRACE (remote-thread-NodeW-p1257-t2:) [TCP_NIO2] dest=127.0.0.1:9000 (102 bytes) 10:36:08,019 TRACE (OOB-1,NodeV-57636:) [TCP_NIO2] NodeV-57636: received [dst: NodeV-57636, src: NodeW-53871 (3 headers), size=26 bytes, flags=OOB|DONT_BUNDLE|NO_TOTAL_ORDER], headers are RequestCorrelator: corr_id=200, type=RSP, req_id=1562, rsp_expected=true, UNICAST3: DATA, seqno=5, TP: [cluster_name=ISPN] 10:36:08,019 TRACE (OOB-1,NodeV-57636:) [UNICAST3] NodeV-57636 <-- DATA(NodeW-53871: #5, conn_id=0) 10:36:08,019 TRACE (OOB-1,NodeV-57636:) [UNICAST3] NodeV-57636: delivering NodeW-53871#5 10:36:08,020 TRACE (Timer-3,NodeW-53871:) [TCP_NIO2] NodeW-53871: sending 1 msgs (67 bytes (0.22% of max_bundle_size) to 1 dests(s): [ISPN:NodeV-57636] 10:36:08,020 TRACE (Timer-3,NodeW-53871:) [TCP_NIO2] dest=127.0.0.1:9000 (70 bytes) 10:36:08,022 DEBUG (testng-ClusterExecutorTest:) [DefaultCacheManager] Stopping cache manager ISPN on NodeW-53871 10:36:08,022 TRACE (testng-ClusterExecutorTest:) [DefaultCacheManager] Cache stop order: [] 10:36:08,022 TRACE (INT-1,NodeV-57636:) [TCP_NIO2] NodeV-57636: received [dst: NodeV-57636, src: NodeW-53871 (3 headers), size=0 bytes, flags=OOB|INTERNAL], headers are GMS: GmsHeader[VIEW_ACK], UNICAST3: DATA, seqno=2, TP: [cluster_name=ISPN] 10:36:08,022 TRACE (INT-1,NodeV-57636:) [UNICAST3] NodeV-57636 <-- DATA(NodeW-53871: #2, conn_id=0) 10:36:08,026 TRACE (INT-1,NodeV-57636:) [UNICAST3] NodeV-57636: delivering NodeW-53871#2 10:36:08,026 TRACE (ViewHandler,NodeV-57636:) [GMS] NodeV-57636: got all ACKs (1) from joiners for view [NodeV-57636|1] 10:36:08,026 TRACE (ViewHandler,NodeV-57636:) [STABLE] NodeV-57636: reset digest to NodeV-57636: [-1], NodeW-53871: [-1] 10:36:08,026 DEBUG (ViewHandler,NodeV-57636:) [STABLE] resuming message garbage collection 10:36:08,030 TRACE (testng-ClusterExecutorTest:) [LocalTopologyManagerImpl] Stopping LocalTopologyManager on NodeW-53871 10:36:08,030 INFO (testng-ClusterExecutorTest:) [JGroupsTransport] ISPN000080: Disconnecting JGroups channel ISPN 10:36:08,030 TRACE (testng-ClusterExecutorTest:) [GMS] Handling disconnect event 10:36:08,030 TRACE (testng-ClusterExecutorTest:) [GMS] Handling leave as participant, leaver = NodeW-53871, coord = NodeV-57636 10:36:08,030 TRACE (testng-ClusterExecutorTest:) [GMS] NodeW-53871: sending LEAVE request to NodeV-57636 10:36:08,030 TRACE (testng-ClusterExecutorTest:) [UNICAST3] NodeW-53871 --> DATA(NodeV-57636: #6, conn_id=0) 10:36:08,030 TRACE (testng-ClusterExecutorTest:) [TCP_NIO2] NodeW-53871: sending msg to NodeV-57636, src=NodeW-53871, headers are GMS: GmsHeader[LEAVE_REQ]: mbr=NodeW-53871, UNICAST3: DATA, seqno=6, TP: [cluster_name=ISPN] 10:36:08,050 TRACE (Timer-2,NodeW-53871:) [TCP_NIO2] NodeW-53871: sending 1 msgs (83 bytes (0.27% of max_bundle_size) to 1 dests(s): [ISPN:NodeV-57636] 10:36:08,050 TRACE (Timer-2,NodeW-53871:) [TCP_NIO2] dest=127.0.0.1:9000 (86 bytes) 10:36:08,050 TRACE (OOB-1,NodeV-57636:) [TCP_NIO2] NodeV-57636: received [dst: NodeV-57636, src: NodeW-53871 (3 headers), size=0 bytes, flags=OOB], headers are GMS: GmsHeader[LEAVE_REQ]: mbr=NodeW-53871, UNICAST3: DATA, seqno=6, TP: [cluster_name=ISPN] 10:36:08,050 TRACE (OOB-1,NodeV-57636:) [UNICAST3] NodeV-57636 <-- DATA(NodeW-53871: #6, conn_id=0) 10:36:08,050 TRACE (OOB-1,NodeV-57636:) [UNICAST3] NodeV-57636: delivering NodeW-53871#6 10:36:08,075 TRACE (ViewHandler,NodeV-57636:) [GMS] NodeV-57636: joiners=[], suspected=[], leaving=[NodeW-53871], new view: [NodeV-57636|2] (1) [NodeV-57636] 10:36:08,075 TRACE (ViewHandler,NodeV-57636:) [GMS] NodeV-57636: sending LEAVE response to NodeW-53871 10:36:08,075 TRACE (ViewHandler,NodeV-57636:) [TCP_NIO2] NodeV-57636: sending msg to NodeW-53871, src=NodeV-57636, headers are GMS: GmsHeader[LEAVE_RSP], TP: [cluster_name=ISPN] 10:36:08,075 TRACE (ViewHandler,NodeV-57636:) [GMS] NodeV-57636: mcasting view [NodeV-57636|2] (1) [NodeV-57636] (1 mbrs) 10:36:08,076 TRACE (ViewHandler,NodeV-57636:) [NAKACK2] NodeV-57636: sending NodeV-57636#2 10:36:08,076 TRACE (ViewHandler,NodeV-57636:) [TCP_NIO2] NodeV-57636: sending msg to null, src=NodeV-57636, headers are GMS: GmsHeader[VIEW], NAKACK2: [MSG, seqno=2], TP: [cluster_name=ISPN] 10:36:08,076 TRACE (ViewHandler,NodeV-57636:) [TCP_NIO2] NodeV-57636: looping back message [dst: <null>, src: NodeV-57636 (3 headers), size=61 bytes] 10:36:08,080 TRACE (Incoming-1,NodeV-57636:) [TCP_NIO2] NodeV-57636: received [dst: <null>, src: NodeV-57636 (3 headers), size=61 bytes], headers are GMS: GmsHeader[VIEW], NAKACK2: [MSG, seqno=2], TP: [cluster_name=ISPN] 10:36:08,079 TRACE (NioConnection.Reader [127.0.0.1:9000],NodeW-53871:) [TCP_NIO2] 127.0.0.1:9001: removed connection to 127.0.0.1:9000 10:36:08,080 TRACE (Incoming-1,NodeV-57636:) [NAKACK2] NodeV-57636: received NodeV-57636#2 10:36:08,080 TRACE (Incoming-1,NodeV-57636:) [NAKACK2] NodeV-57636: delivering NodeV-57636#2-2 (1 messages) 10:36:08,080 TRACE (Incoming-1,NodeV-57636:) [GMS] NodeV-57636: received delta view [NodeV-57636|2], ref-view=[NodeV-57636|1], left=[NodeW-53871] 10:36:08,082 DEBUG (Incoming-1,NodeV-57636:) [GMS] NodeV-57636: installing view [NodeV-57636|2] (1) [NodeV-57636] 10:36:08,082 TRACE (Incoming-1,NodeV-57636:) [UNICAST3] NodeV-57636: closing connections of non members [NodeW-53871] 10:36:08,082 DEBUG (Incoming-1,NodeV-57636:) [NAKACK2] NodeV-57636: removed NodeW-53871 from xmit_table (not member anymore) 10:36:08,082 TRACE (Incoming-1,NodeV-57636:) [STABLE] NodeV-57636: reset digest to NodeV-57636: [-1] 10:36:08,082 TRACE (Incoming-1,NodeV-57636:) [TOA] Handle view [NodeV-57636|2] (1) [NodeV-57636] 10:36:08,082 TRACE (Incoming-1,NodeV-57636:) [MFC] new membership: [NodeV-57636] 10:36:08,082 TRACE (Incoming-1,NodeV-57636:) [FRAG2] NodeV-57636: removed NodeW-53871 from fragmentation table 10:36:08,082 DEBUG (Incoming-1,NodeV-57636:) [JGroupsTransport] New view accepted: [NodeV-57636|2] (1) [NodeV-57636] 10:36:08,082 DEBUG (Incoming-1,NodeV-57636:) [JGroupsTransport] Joined: [], Left: [NodeW-53871] 10:36:08,082 INFO (Incoming-1,NodeV-57636:) [JGroupsTransport] ISPN000094: Received new cluster view for channel ISPN: [NodeV-57636|2] (1) [NodeV-57636] 10:36:08,082 TRACE (Incoming-1,NodeV-57636:) [SemaphoreCompletionService] New task submitted, tasks in queue 1, available permits 1 10:36:08,085 TRACE (Incoming-1,NodeV-57636:) [UNICAST3] NodeV-57636 --> DATA(NodeV-57636: #2, conn_id=0) 10:36:08,085 TRACE (Incoming-1,NodeV-57636:) [TCP_NIO2] NodeV-57636: sending msg to NodeV-57636, src=NodeV-57636, headers are GMS: GmsHeader[VIEW_ACK], UNICAST3: DATA, seqno=2, TP: [cluster_name=ISPN] 10:36:08,085 TRACE (Incoming-1,NodeV-57636:) [TCP_NIO2] NodeV-57636: looping back message [dst: NodeV-57636, src: NodeV-57636 (3 headers), size=0 bytes, flags=OOB|INTERNAL] 10:36:08,085 TRACE (transport-thread-NodeV-p1249-t3:) [SemaphoreCompletionService] Task started, tasks in queue 0, available permits 0 10:36:08,085 TRACE (transport-thread-NodeV-p1249-t3:) [ClusterTopologyManagerImpl] Received new cluster view: 2, isCoordinator = true, old status = COORDINATOR 10:36:08,085 TRACE (transport-thread-NodeV-p1249-t3:) [ClusterTopologyManagerImpl] Updating cluster members for all the caches. New list is [NodeV-57636] 10:36:08,085 TRACE (INT-2,NodeV-57636:) [TCP_NIO2] NodeV-57636: received [dst: NodeV-57636, src: NodeV-57636 (3 headers), size=0 bytes, flags=OOB|INTERNAL], headers are GMS: GmsHeader[VIEW_ACK], UNICAST3: DATA, seqno=2, TP: [cluster_name=ISPN] 10:36:08,085 TRACE (transport-thread-NodeV-p1249-t3:) [JGroupsTransport] dests=null, command=CacheTopologyControlCommand{cache=null, type=POLICY_GET_STATUS, sender=NodeV-57636, joinInfo=null, topologyId=0, rebalanceId=0, currentCH=null, pendingCH=null, availabilityMode=null, actualMembers=null, throwable=null, viewId=-1}, mode=SYNCHRONOUS, timeout=240000 10:36:08,085 TRACE (INT-2,NodeV-57636:) [UNICAST3] NodeV-57636 <-- DATA(NodeV-57636: #2, conn_id=0) 10:36:08,085 TRACE (INT-2,NodeV-57636:) [UNICAST3] NodeV-57636: delivering NodeV-57636#2 10:36:08,085 TRACE (transport-thread-NodeV-p1249-t3:) [SemaphoreCompletionService] Task finished, tasks in queue 0, available permits 0 10:36:08,085 TRACE (ViewHandler,NodeV-57636:) [GMS] NodeV-57636: got all ACKs (1) from members for view [NodeV-57636|2] 10:36:08,096 TRACE (Timer-2,NodeV-57636:) [TCP_NIO2] NodeV-57636: sending 2 msgs (169 bytes (0.55% of max_bundle_size) to 2 dests(s): [ISPN:NodeW-53871, ISPN] 10:36:08,096 TRACE (Timer-2,NodeV-57636:) [TCP_NIO2] dest=127.0.0.1:9001 (60 bytes) 10:36:08,096 TRACE (Timer-2,NodeV-57636:) [TCP_NIO2] 127.0.0.1:9000: connecting to 127.0.0.1:9001 10:36:08,107 TRACE (INT-2,NodeW-53871:) [TCP_NIO2] NodeW-53871: received [dst: NodeW-53871, src: NodeV-57636 (2 headers), size=0 bytes, flags=OOB|NO_RELIABILITY|INTERNAL], headers are GMS: GmsHeader[LEAVE_RSP], TP: [cluster_name=ISPN] 10:36:08,107 TRACE (testng-ClusterExecutorTest:) [GMS] NodeW-53871: got LEAVE response from NodeV-57636 10:36:08,107 TRACE (NioConnection.Reader [127.0.0.1:9001],NodeV-57636:) [TCP_NIO2] 127.0.0.1:9000: removed connection to 127.0.0.1:9001 10:36:08,108 TRACE (testng-ClusterExecutorTest:) [UNICAST3] NodeW-53871 --> ACK(NodeV-57636: #4) 10:36:08,108 TRACE (testng-ClusterExecutorTest:) [TCP_NIO2] NodeW-53871: sending msg to NodeV-57636, src=NodeW-53871, headers are UNICAST3: ACK, seqno=4, conn_id=1, ts=1, TP: [cluster_name=ISPN] 10:36:08,108 DEBUG (testng-ClusterExecutorTest:) [TEST_PING] Stop discovery for NodeW-53871 10:36:08,108 DEBUG (testng-ClusterExecutorTest:) [TCP_NIO2] closing sockets and stopping threads 10:36:08,108 INFO (testng-ClusterExecutorTest:) [JGroupsTransport] ISPN000082: Stopping the RpcDispatcher for channel ISPN 10:36:08,109 DEBUG (testng-ClusterExecutorTest:) [DefaultCacheManager] Stopping cache manager ISPN on NodeV-57636 10:36:08,109 TRACE (testng-ClusterExecutorTest:) [DefaultCacheManager] Cache stop order: [] 10:36:08,113 TRACE (testng-ClusterExecutorTest:) [LocalTopologyManagerImpl] Stopping LocalTopologyManager on NodeV-57636 10:36:08,113 INFO (testng-ClusterExecutorTest:) [JGroupsTransport] ISPN000080: Disconnecting JGroups channel ISPN 10:36:08,113 TRACE (testng-ClusterExecutorTest:) [GMS] Handling disconnect event 10:36:08,113 TRACE (testng-ClusterExecutorTest:) [GMS] Handling leave as coord, leaver = NodeV-57636 10:36:08,114 TRACE (testng-ClusterExecutorTest:) [UNICAST3] NodeV-57636 --> ACK(NodeW-53871: #6) 10:36:08,114 TRACE (testng-ClusterExecutorTest:) [TCP_NIO2] NodeV-57636: sending msg to NodeW-53871, src=NodeV-57636, headers are UNICAST3: ACK, seqno=6, ts=1, TP: [cluster_name=ISPN] 10:36:08,114 DEBUG (testng-ClusterExecutorTest:) [TEST_PING] Stop discovery for NodeV-57636 10:36:08,114 DEBUG (testng-ClusterExecutorTest:) [TCP_NIO2] closing sockets and stopping threads 10:36:08,114 INFO (testng-ClusterExecutorTest:) [JGroupsTransport] ISPN000082: Stopping the RpcDispatcher for channel ISPN 10:36:08,116 ERROR (testng-ClusterExecutorTest:) [UnitTestTestNGListener] Test testExecutorTriConsumer(org.infinispan.manager.ClusterExecutorTest) failed. java.lang.AssertionError: expected:<2> but was:<1> at org.testng.AssertJUnit.fail(AssertJUnit.java:59) ~[testng-6.8.8.jar:?] at org.testng.AssertJUnit.failNotEquals(AssertJUnit.java:364) ~[testng-6.8.8.jar:?] at org.testng.AssertJUnit.assertEquals(AssertJUnit.java:80) ~[testng-6.8.8.jar:?] at org.testng.AssertJUnit.assertEquals(AssertJUnit.java:245) ~[testng-6.8.8.jar:?] at org.testng.AssertJUnit.assertEquals(AssertJUnit.java:252) ~[testng-6.8.8.jar:?] at org.infinispan.manager.ClusterExecutorTest$11.call(ClusterExecutorTest.java:222) ~[test-classes/:?] at org.infinispan.test.TestingUtil.withCacheManagers(TestingUtil.java:1353) ~[test-classes/:?] at org.infinispan.manager.ClusterExecutorTest.testExecutorTriConsumer(ClusterExecutorTest.java:201) ~[test-classes/:?] at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.8.0_74] at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:1.8.0_74] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_74] at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_74] at org.testng.internal.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:84) ~[testng-6.8.8.jar:?] at org.testng.internal.Invoker.invokeMethod(Invoker.java:714) [testng-6.8.8.jar:?] at org.testng.internal.Invoker.invokeTestMethod(Invoker.java:901) [testng-6.8.8.jar:?] at org.testng.internal.Invoker.invokeTestMethods(Invoker.java:1231) [testng-6.8.8.jar:?] at org.testng.internal.TestMethodWorker.invokeTestMethods(TestMethodWorker.java:127) [testng-6.8.8.jar:?] at org.testng.internal.TestMethodWorker.run(TestMethodWorker.java:111) [testng-6.8.8.jar:?] at org.testng.TestRunner.privateRun(TestRunner.java:767) [testng-6.8.8.jar:?] at org.testng.TestRunner.run(TestRunner.java:617) [testng-6.8.8.jar:?] at org.testng.SuiteRunner.runTest(SuiteRunner.java:348) [testng-6.8.8.jar:?] at org.testng.SuiteRunner.access$000(SuiteRunner.java:38) [testng-6.8.8.jar:?] at org.testng.SuiteRunner$SuiteWorker.run(SuiteRunner.java:382) [testng-6.8.8.jar:?] at org.testng.internal.thread.ThreadUtil$2.call(ThreadUtil.java:64) [testng-6.8.8.jar:?] at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_74] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [?:1.8.0_74] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:1.8.0_74] at java.lang.Thread.run(Thread.java:745) [?:1.8.0_74] {code}