hazelcast-jet com.hazelcast.jet.core.MemberReconnectionStressTest.test

com.hazelcast.jet.core.MemberReconnectionStressTest.test

Open olukas opened this issue 4 years ago • 6 comments

master (commit c2ed87549018247916e194728b54d19ce5baea48)

Failed on nightly run: http://jenkins.hazelcast.com/job/jet-oss-master-nightly/266/testReport/junit/com.hazelcast.jet.core/MemberReconnectionStressTest/test/

Stacktrace:

java.lang.AssertionError: jobCount didn't increment for 30 seconds
	at org.junit.Assert.fail(Assert.java:88)
	at com.hazelcast.jet.core.MemberReconnectionStressTest.test(MemberReconnectionStressTest.java:118)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
	at com.hazelcast.test.FailOnTimeoutStatement$CallableStatement.call(FailOnTimeoutStatement.java:114)
	at com.hazelcast.test.FailOnTimeoutStatement$CallableStatement.call(FailOnTimeoutStatement.java:106)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	at java.lang.Thread.run(Thread.java:748)

Standard output:

se partitions are not yet initialized.
2020-09-30 23:28:44,069 [DEBUG] [hz.unruffled_moser.cached.thread-1] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Not starting jobs because partitions are not yet initialized.
2020-09-30 23:28:44,169 [DEBUG] [hz.unruffled_moser.cached.thread-1] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Not starting jobs because partitions are not yet initialized.
2020-09-30 23:28:44,269 [DEBUG] [hz.unruffled_moser.cached.thread-1] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Not starting jobs because partitions are not yet initialized.
2020-09-30 23:28:44,369 [DEBUG] [hz.unruffled_moser.cached.thread-1] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Not starting jobs because partitions are not yet initialized.
2020-09-30 23:28:44,470 [DEBUG] [hz.unruffled_moser.cached.thread-1] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Not starting jobs because partitions are not yet initialized.
2020-09-30 23:28:44,488 [ INFO] [hz.unruffled_moser.priority-generic-operation.thread-0] [c.h.i.c.ClusterService]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] 

Members {size:2, ver:2} [
	Member [127.0.0.1]:5701 - e487092b-9b7d-4c5c-ac9f-67a2db8bd515 this
	Member [127.0.0.1]:5702 - ddac6c6e-b5aa-4c60-bd7f-4521e04a0b4e
]

2020-09-30 23:28:44,489 [ INFO] [hz.festive_moser.priority-generic-operation.thread-0] [c.h.i.c.ClusterService]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] 

Members {size:2, ver:2} [
	Member [127.0.0.1]:5701 - e487092b-9b7d-4c5c-ac9f-67a2db8bd515
	Member [127.0.0.1]:5702 - ddac6c6e-b5aa-4c60-bd7f-4521e04a0b4e this
]

2020-09-30 23:28:44,570 [DEBUG] [hz.unruffled_moser.cached.thread-5] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Not starting jobs because partitions are not yet initialized.
2020-09-30 23:28:44,670 [DEBUG] [hz.unruffled_moser.cached.thread-5] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Not starting jobs because partitions are not yet initialized.
2020-09-30 23:28:44,770 [DEBUG] [hz.unruffled_moser.cached.thread-5] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Not starting jobs because partitions are not yet initialized.
2020-09-30 23:28:44,870 [DEBUG] [hz.unruffled_moser.cached.thread-5] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Not starting jobs because partitions are not yet initialized.
2020-09-30 23:28:44,970 [DEBUG] [hz.unruffled_moser.cached.thread-5] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Not starting jobs because partitions are not yet initialized.
2020-09-30 23:28:45,070 [DEBUG] [hz.unruffled_moser.cached.thread-5] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Not starting jobs because partitions are not yet initialized.
2020-09-30 23:28:45,170 [DEBUG] [hz.unruffled_moser.cached.thread-5] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Not starting jobs because partitions are not yet initialized.
2020-09-30 23:28:45,270 [DEBUG] [hz.unruffled_moser.cached.thread-5] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Not starting jobs because partitions are not yet initialized.
2020-09-30 23:28:45,371 [DEBUG] [hz.unruffled_moser.cached.thread-5] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Not starting jobs because partitions are not yet initialized.
2020-09-30 23:28:45,471 [DEBUG] [hz.unruffled_moser.cached.thread-5] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Not starting jobs because partitions are not yet initialized.
2020-09-30 23:28:45,488 [ INFO] [test] [c.h.c.LifecycleService]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] [127.0.0.1]:5702 is STARTED
2020-09-30 23:28:45,488 [ INFO] [test] [c.h.j.c.MemberReconnectionStressTest]: Starting 
2020-09-30 23:28:45,489 [ WARN] [Thread-51] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Connection[id=1, /127.0.0.1:5701->/127.0.0.1:53684, qualifier=null, endpoint=[127.0.0.1]:5702, alive=false, connectionType=MEMBER] closed. Reason: test
java.lang.Exception: test failure
	at com.hazelcast.jet.core.MemberReconnectionStressTest.lambda$test$0(MemberReconnectionStressTest.java:84) ~[test-classes/:?]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_251]
2020-09-30 23:28:45,492 [ INFO] [Thread-51] [c.h.j.c.MemberReconnectionStressTest]: connection closed
2020-09-30 23:28:45,493 [ INFO] [hz.unruffled_moser.cached.thread-5] [c.h.i.n.t.TcpIpConnector]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5702, timeout: 10000, bind-any: true
2020-09-30 23:28:45,493 [ INFO] [hz.festive_moser.IO.thread-in-0] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Connection[id=1, /0.0.0.0:53684->/127.0.0.1:5701, qualifier=null, endpoint=[127.0.0.1]:5701, alive=false, connectionType=MEMBER] closed. Reason: Connection closed by the other side
2020-09-30 23:28:45,494 [ INFO] [hz.festive_moser.cached.thread-6] [c.h.i.n.t.TcpIpConnector]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2020-09-30 23:28:45,495 [ INFO] [hz.unruffled_moser.IO.thread-in-2] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Initialized new cluster connection between /127.0.0.1:5701 and /127.0.0.1:54637
2020-09-30 23:28:45,495 [ INFO] [hz.festive_moser.IO.thread-in-1] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Initialized new cluster connection between /0.0.0.0:54637 and /127.0.0.1:5701
2020-09-30 23:28:45,499 [ INFO] [hz.festive_moser.IO.thread-in-2] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Initialized new cluster connection between /127.0.0.1:5702 and /127.0.0.1:56162
2020-09-30 23:28:45,500 [ INFO] [hz.unruffled_moser.IO.thread-in-1] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Initialized new cluster connection between /0.0.0.0:56162 and /127.0.0.1:5702
2020-09-30 23:28:45,500 [ INFO] [hz.unruffled_moser.cached.thread-5] [c.h.i.p.i.PartitionStateManager]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Initializing cluster partition table arrangement...
2020-09-30 23:28:45,505 [ INFO] [hz.unruffled_moser.cached.thread-5] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Starting job 050c-950d-6d40-0001 based on submit request
2020-09-30 23:28:45,508 [ INFO] [hz.unruffled_moser.cached.thread-5] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Didn't find any snapshot to restore for job '050c-950d-6d40-0001', execution 050c-950d-6d41-0001
2020-09-30 23:28:45,508 [ INFO] [hz.unruffled_moser.cached.thread-5] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Start executing job '050c-950d-6d40-0001', execution 050c-950d-6d41-0001, execution graph in DOT format:
digraph DAG {
	"v1" [localParallelism=2];
	"v2" [localParallelism=2];
	"v1" -> "v2" [label="distributed", queueSize=1024];
}
HINT: You can use graphviz or http://viz-js.com to visualize the printed graph.
2020-09-30 23:28:45,508 [DEBUG] [hz.unruffled_moser.cached.thread-5] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Building execution plan for job '050c-950d-6d40-0001', execution 050c-950d-6d41-0001
2020-09-30 23:28:45,508 [DEBUG] [hz.unruffled_moser.cached.thread-5] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Built execution plans for job '050c-950d-6d40-0001', execution 050c-950d-6d41-0001
2020-09-30 23:28:45,509 [DEBUG] [hz.festive_moser.generic-operation.thread-5] [c.h.j.i.o.InitExecutionOperation]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Initializing execution plan for job 050c-950d-6d40-0001, execution 050c-950d-6d41-0001 from [127.0.0.1]:5701
2020-09-30 23:28:45,509 [DEBUG] [hz.unruffled_moser.cached.thread-5] [c.h.j.i.o.InitExecutionOperation]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Initializing execution plan for job 050c-950d-6d40-0001, execution 050c-950d-6d41-0001 from [127.0.0.1]:5701
2020-09-30 23:28:45,511 [ INFO] [hz.unruffled_moser.cached.thread-5] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Execution plan for jobId=050c-950d-6d40-0001, jobName='050c-950d-6d40-0001', executionId=050c-950d-6d41-0001 initialized
2020-09-30 23:28:45,511 [ INFO] [hz.festive_moser.generic-operation.thread-5] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Execution plan for jobId=050c-950d-6d40-0001, jobName='050c-950d-6d40-0001', executionId=050c-950d-6d41-0001 initialized
2020-09-30 23:28:45,511 [DEBUG] [hz.unruffled_moser.cached.thread-5] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Init of job '050c-950d-6d40-0001', execution 050c-950d-6d41-0001 was successful
2020-09-30 23:28:45,511 [DEBUG] [hz.unruffled_moser.cached.thread-5] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Executing job '050c-950d-6d40-0001', execution 050c-950d-6d41-0001
2020-09-30 23:28:45,511 [ INFO] [hz.unruffled_moser.cached.thread-5] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Start execution of job '050c-950d-6d40-0001', execution 050c-950d-6d41-0001 from coordinator [127.0.0.1]:5701
2020-09-30 23:28:45,511 [ INFO] [hz.festive_moser.generic-operation.thread-6] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Start execution of job '050c-950d-6d40-0001', execution 050c-950d-6d41-0001 from coordinator [127.0.0.1]:5701
2020-09-30 23:28:45,513 [DEBUG] [hz.unruffled_moser.jet.cooperative.thread-2] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Execution of job '050c-950d-6d40-0001', execution 050c-950d-6d41-0001 completed
2020-09-30 23:28:45,513 [DEBUG] [hz.festive_moser.jet.cooperative.thread-2] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Execution of job '050c-950d-6d40-0001', execution 050c-950d-6d41-0001 completed
2020-09-30 23:28:45,513 [DEBUG] [ForkJoinPool.commonPool-worker-89] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Execution of job '050c-950d-6d40-0001', execution 050c-950d-6d41-0001 was successful
2020-09-30 23:28:45,513 [DEBUG] [hz.unruffled_moser.cached.thread-5] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Sending CompleteExecutionOperation for job '050c-950d-6d40-0001', execution 050c-950d-6d41-0001
2020-09-30 23:28:45,513 [DEBUG] [hz.unruffled_moser.cached.thread-5] [c.h.j.i.o.CompleteExecutionOperation]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Completing execution 050c-950d-6d41-0001 from caller [127.0.0.1]:5701, error=null
2020-09-30 23:28:45,513 [DEBUG] [hz.unruffled_moser.cached.thread-5] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Completed execution of job '050c-950d-6d40-0001', execution 050c-950d-6d41-0001
2020-09-30 23:28:45,513 [DEBUG] [hz.festive_moser.generic-operation.thread-7] [c.h.j.i.o.CompleteExecutionOperation]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Completing execution 050c-950d-6d41-0001 from caller [127.0.0.1]:5701, error=null
2020-09-30 23:28:45,513 [DEBUG] [hz.festive_moser.generic-operation.thread-7] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Completed execution of job '050c-950d-6d40-0001', execution 050c-950d-6d41-0001
2020-09-30 23:28:45,514 [ INFO] [hz.unruffled_moser.cached.thread-5] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Execution of job '050c-950d-6d40-0001', execution 050c-950d-6d41-0001 completed successfully
	Start time: 2020-09-30T23:28:45.506
	Duration: 7 ms
	To see additional job metrics enable JobConfig.storeMetricsAfterJobCompletion
2020-09-30 23:28:45,514 [DEBUG] [hz.unruffled_moser.cached.thread-5] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] job '050c-950d-6d40-0001', execution 050c-950d-6d41-0001 is completed
2020-09-30 23:28:45,514 [ INFO] [Thread-52] [c.h.j.c.MemberReconnectionStressTest]: job completed
2020-09-30 23:28:45,516 [ INFO] [hz.unruffled_moser.cached.thread-3] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Starting job 050c-950d-6d42-0001 based on submit request
2020-09-30 23:28:45,517 [ INFO] [hz.unruffled_moser.cached.thread-3] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Didn't find any snapshot to restore for job '050c-950d-6d42-0001', execution 050c-950d-6d43-0001
2020-09-30 23:28:45,517 [ INFO] [hz.unruffled_moser.cached.thread-3] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Start executing job '050c-950d-6d42-0001', execution 050c-950d-6d43-0001, execution graph in DOT format:
digraph DAG {
	"v1" [localParallelism=2];
	"v2" [localParallelism=2];
	"v1" -> "v2" [label="distributed", queueSize=1024];
}
HINT: You can use graphviz or http://viz-js.com to visualize the printed graph.
2020-09-30 23:28:45,517 [DEBUG] [hz.unruffled_moser.cached.thread-3] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Building execution plan for job '050c-950d-6d42-0001', execution 050c-950d-6d43-0001
2020-09-30 23:28:45,517 [DEBUG] [hz.unruffled_moser.cached.thread-3] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Built execution plans for job '050c-950d-6d42-0001', execution 050c-950d-6d43-0001
2020-09-30 23:28:45,517 [DEBUG] [hz.festive_moser.generic-operation.thread-8] [c.h.j.i.o.InitExecutionOperation]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Initializing execution plan for job 050c-950d-6d42-0001, execution 050c-950d-6d43-0001 from [127.0.0.1]:5701
2020-09-30 23:28:45,517 [DEBUG] [hz.unruffled_moser.cached.thread-3] [c.h.j.i.o.InitExecutionOperation]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Initializing execution plan for job 050c-950d-6d42-0001, execution 050c-950d-6d43-0001 from [127.0.0.1]:5701
2020-09-30 23:28:45,518 [ INFO] [hz.unruffled_moser.cached.thread-3] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Execution plan for jobId=050c-950d-6d42-0001, jobName='050c-950d-6d42-0001', executionId=050c-950d-6d43-0001 initialized
2020-09-30 23:28:45,519 [ INFO] [hz.festive_moser.generic-operation.thread-8] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Execution plan for jobId=050c-950d-6d42-0001, jobName='050c-950d-6d42-0001', executionId=050c-950d-6d43-0001 initialized
2020-09-30 23:28:45,519 [DEBUG] [hz.unruffled_moser.cached.thread-3] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Init of job '050c-950d-6d42-0001', execution 050c-950d-6d43-0001 was successful
2020-09-30 23:28:45,519 [DEBUG] [hz.unruffled_moser.cached.thread-3] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Executing job '050c-950d-6d42-0001', execution 050c-950d-6d43-0001
2020-09-30 23:28:45,519 [ INFO] [hz.unruffled_moser.cached.thread-3] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Start execution of job '050c-950d-6d42-0001', execution 050c-950d-6d43-0001 from coordinator [127.0.0.1]:5701
2020-09-30 23:28:45,519 [ INFO] [hz.festive_moser.generic-operation.thread-9] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Start execution of job '050c-950d-6d42-0001', execution 050c-950d-6d43-0001 from coordinator [127.0.0.1]:5701
2020-09-30 23:28:45,521 [DEBUG] [hz.unruffled_moser.jet.cooperative.thread-6] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Execution of job '050c-950d-6d42-0001', execution 050c-950d-6d43-0001 completed
2020-09-30 23:28:45,521 [DEBUG] [hz.festive_moser.jet.cooperative.thread-6] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Execution of job '050c-950d-6d42-0001', execution 050c-950d-6d43-0001 completed
2020-09-30 23:28:45,521 [DEBUG] [ForkJoinPool.commonPool-worker-107] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Execution of job '050c-950d-6d42-0001', execution 050c-950d-6d43-0001 was successful
2020-09-30 23:28:45,521 [DEBUG] [hz.unruffled_moser.cached.thread-3] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Sending CompleteExecutionOperation for job '050c-950d-6d42-0001', execution 050c-950d-6d43-0001
2020-09-30 23:28:45,521 [DEBUG] [hz.unruffled_moser.cached.thread-3] [c.h.j.i.o.CompleteExecutionOperation]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Completing execution 050c-950d-6d43-0001 from caller [127.0.0.1]:5701, error=null
2020-09-30 23:28:45,521 [DEBUG] [hz.unruffled_moser.cached.thread-3] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Completed execution of job '050c-950d-6d42-0001', execution 050c-950d-6d43-0001
2020-09-30 23:28:45,521 [DEBUG] [hz.festive_moser.generic-operation.thread-10] [c.h.j.i.o.CompleteExecutionOperation]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Completing execution 050c-950d-6d43-0001 from caller [127.0.0.1]:5701, error=null
2020-09-30 23:28:45,521 [DEBUG] [hz.festive_moser.generic-operation.thread-10] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Completed execution of job '050c-950d-6d42-0001', execution 050c-950d-6d43-0001
2020-09-30 23:28:45,521 [ INFO] [hz.unruffled_moser.cached.thread-3] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Execution of job '050c-950d-6d42-0001', execution 050c-950d-6d43-0001 completed successfully
	Start time: 2020-09-30T23:28:45.516
	Duration: 5 ms
	To see additional job metrics enable JobConfig.storeMetricsAfterJobCompletion
2020-09-30 23:28:45,522 [DEBUG] [hz.unruffled_moser.cached.thread-3] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] job '050c-950d-6d42-0001', execution 050c-950d-6d43-0001 is completed
2020-09-30 23:28:45,522 [ INFO] [Thread-52] [c.h.j.c.MemberReconnectionStressTest]: job completed
2020-09-30 23:28:45,523 [ INFO] [hz.unruffled_moser.cached.thread-1] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Starting job 050c-950d-6d44-0001 based on submit request
2020-09-30 23:28:45,525 [ INFO] [hz.unruffled_moser.cached.thread-1] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Didn't find any snapshot to restore for job '050c-950d-6d44-0001', execution 050c-950d-6d45-0001
2020-09-30 23:28:45,525 [ INFO] [hz.unruffled_moser.cached.thread-1] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Start executing job '050c-950d-6d44-0001', execution 050c-950d-6d45-0001, execution graph in DOT format:
digraph DAG {
	"v1" [localParallelism=2];
	"v2" [localParallelism=2];
	"v1" -> "v2" [label="distributed", queueSize=1024];
}
HINT: You can use graphviz or http://viz-js.com to visualize the printed graph.
2020-09-30 23:28:45,525 [DEBUG] [hz.unruffled_moser.cached.thread-1] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Building execution plan for job '050c-950d-6d44-0001', execution 050c-950d-6d45-0001
2020-09-30 23:28:45,525 [DEBUG] [hz.unruffled_moser.cached.thread-1] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Built execution plans for job '050c-950d-6d44-0001', execution 050c-950d-6d45-0001
2020-09-30 23:28:45,525 [DEBUG] [hz.festive_moser.generic-operation.thread-11] [c.h.j.i.o.InitExecutionOperation]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Initializing execution plan for job 050c-950d-6d44-0001, execution 050c-950d-6d45-0001 from [127.0.0.1]:5701
2020-09-30 23:28:45,526 [DEBUG] [hz.unruffled_moser.cached.thread-1] [c.h.j.i.o.InitExecutionOperation]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Initializing execution plan for job 050c-950d-6d44-0001, execution 050c-950d-6d45-0001 from [127.0.0.1]:5701
2020-09-30 23:28:45,526 [ INFO] [hz.unruffled_moser.cached.thread-1] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Execution plan for jobId=050c-950d-6d44-0001, jobName='050c-950d-6d44-0001', executionId=050c-950d-6d45-0001 initialized
2020-09-30 23:28:45,529 [ INFO] [hz.festive_moser.generic-operation.thread-11] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Execution plan for jobId=050c-950d-6d44-0001, jobName='050c-950d-6d44-0001', executionId=050c-950d-6d45-0001 initialized
2020-09-30 23:28:45,529 [DEBUG] [hz.unruffled_moser.cached.thread-1] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Init of job '050c-950d-6d44-0001', execution 050c-950d-6d45-0001 was successful
2020-09-30 23:28:45,529 [DEBUG] [hz.unruffled_moser.cached.thread-1] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Executing job '050c-950d-6d44-0001', execution 050c-950d-6d45-0001
2020-09-30 23:28:45,529 [ INFO] [hz.unruffled_moser.cached.thread-1] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Start execution of job '050c-950d-6d44-0001', execution 050c-950d-6d45-0001 from coordinator [127.0.0.1]:5701
2020-09-30 23:28:45,529 [ INFO] [hz.festive_moser.generic-operation.thread-12] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Start execution of job '050c-950d-6d44-0001', execution 050c-950d-6d45-0001 from coordinator [127.0.0.1]:5701
2020-09-30 23:28:45,531 [DEBUG] [hz.unruffled_moser.jet.cooperative.thread-10] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Execution of job '050c-950d-6d44-0001', execution 050c-950d-6d45-0001 completed
2020-09-30 23:28:45,531 [DEBUG] [hz.festive_moser.jet.cooperative.thread-10] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Execution of job '050c-950d-6d44-0001', execution 050c-950d-6d45-0001 completed
2020-09-30 23:28:45,532 [DEBUG] [ForkJoinPool.commonPool-worker-106] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Execution of job '050c-950d-6d44-0001', execution 050c-950d-6d45-0001 was successful
2020-09-30 23:28:45,532 [DEBUG] [hz.unruffled_moser.cached.thread-1] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Sending CompleteExecutionOperation for job '050c-950d-6d44-0001', execution 050c-950d-6d45-0001
2020-09-30 23:28:45,532 [DEBUG] [hz.unruffled_moser.cached.thread-1] [c.h.j.i.o.CompleteExecutionOperation]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Completing execution 050c-950d-6d45-0001 from caller [127.0.0.1]:5701, error=null
2020-09-30 23:28:45,532 [DEBUG] [hz.unruffled_moser.cached.thread-1] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Completed execution of job '050c-950d-6d44-0001', execution 050c-950d-6d45-0001
2020-09-30 23:28:45,532 [DEBUG] [hz.festive_moser.generic-operation.thread-13] [c.h.j.i.o.CompleteExecutionOperation]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Completing execution 050c-950d-6d45-0001 from caller [127.0.0.1]:5701, error=null
2020-09-30 23:28:45,532 [DEBUG] [hz.festive_moser.generic-operation.thread-13] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Completed execution of job '050c-950d-6d44-0001', execution 050c-950d-6d45-0001
2020-09-30 23:28:45,532 [ INFO] [hz.unruffled_moser.cached.thread-1] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Execution of job '050c-950d-6d44-0001', execution 050c-950d-6d45-0001 completed successfully
	Start time: 2020-09-30T23:28:45.523
	Duration: 9 ms
	To see additional job metrics enable JobConfig.storeMetricsAfterJobCompletion
2020-09-30 23:28:45,533 [DEBUG] [hz.unruffled_moser.cached.thread-1] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] job '050c-950d-6d44-0001', execution 050c-950d-6d45-0001 is completed
2020-09-30 23:28:45,533 [ INFO] [Thread-52] [c.h.j.c.MemberReconnectionStressTest]: job completed
2020-09-30 23:28:45,534 [ INFO] [hz.unruffled_moser.cached.thread-5] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Starting job 050c-950d-6d46-0001 based on submit request
2020-09-30 23:28:45,535 [ INFO] [hz.unruffled_moser.cached.thread-5] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Didn't find any snapshot to restore for job '050c-950d-6d46-0001', execution 050c-950d-6d47-0001
2020-09-30 23:28:45,535 [ INFO] [hz.unruffled_moser.cached.thread-5] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Start executing job '050c-950d-6d46-0001', execution 050c-950d-6d47-0001, execution graph in DOT format:
digraph DAG {
	"v1" [localParallelism=2];
	"v2" [localParallelism=2];
	"v1" -> "v2" [label="distributed", queueSize=1024];
}
HINT: You can use graphviz or http://viz-js.com to visualize the printed graph.
2020-09-30 23:28:45,535 [DEBUG] [hz.unruffled_moser.cached.thread-5] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Building execution plan for job '050c-950d-6d46-0001', execution 050c-950d-6d47-0001
2020-09-30 23:28:45,535 [DEBUG] [hz.unruffled_moser.cached.thread-5] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Built execution plans for job '050c-950d-6d46-0001', execution 050c-950d-6d47-0001
2020-09-30 23:28:45,535 [DEBUG] [hz.festive_moser.generic-operation.thread-14] [c.h.j.i.o.InitExecutionOperation]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Initializing execution plan for job 050c-950d-6d46-0001, execution 050c-950d-6d47-0001 from [127.0.0.1]:5701
2020-09-30 23:28:45,535 [DEBUG] [hz.unruffled_moser.cached.thread-5] [c.h.j.i.o.InitExecutionOperation]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Initializing execution plan for job 050c-950d-6d46-0001, execution 050c-950d-6d47-0001 from [127.0.0.1]:5701
2020-09-30 23:28:45,536 [ INFO] [hz.unruffled_moser.cached.thread-5] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Execution plan for jobId=050c-950d-6d46-0001, jobName='050c-950d-6d46-0001', executionId=050c-950d-6d47-0001 initialized
2020-09-30 23:28:45,536 [ INFO] [hz.festive_moser.generic-operation.thread-14] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Execution plan for jobId=050c-950d-6d46-0001, jobName='050c-950d-6d46-0001', executionId=050c-950d-6d47-0001 initialized
2020-09-30 23:28:45,536 [DEBUG] [hz.unruffled_moser.cached.thread-5] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Init of job '050c-950d-6d46-0001', execution 050c-950d-6d47-0001 was successful
2020-09-30 23:28:45,536 [DEBUG] [hz.unruffled_moser.cached.thread-5] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Executing job '050c-950d-6d46-0001', execution 050c-950d-6d47-0001
2020-09-30 23:28:45,536 [ INFO] [hz.unruffled_moser.cached.thread-5] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Start execution of job '050c-950d-6d46-0001', execution 050c-950d-6d47-0001 from coordinator [127.0.0.1]:5701
2020-09-30 23:28:45,537 [ INFO] [hz.festive_moser.generic-operation.thread-15] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Start execution of job '050c-950d-6d46-0001', execution 050c-950d-6d47-0001 from coordinator [127.0.0.1]:5701
2020-09-30 23:28:45,538 [DEBUG] [hz.unruffled_moser.jet.cooperative.thread-14] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Execution of job '050c-950d-6d46-0001', execution 050c-950d-6d47-0001 completed
2020-09-30 23:28:45,539 [DEBUG] [hz.festive_moser.jet.cooperative.thread-14] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Execution of job '050c-950d-6d46-0001', execution 050c-950d-6d47-0001 completed
2020-09-30 23:28:45,539 [DEBUG] [ForkJoinPool.commonPool-worker-18] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Execution of job '050c-950d-6d46-0001', execution 050c-950d-6d47-0001 was successful
2020-09-30 23:28:45,539 [DEBUG] [hz.unruffled_moser.cached.thread-5] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Sending CompleteExecutionOperation for job '050c-950d-6d46-0001', execution 050c-950d-6d47-0001
2020-09-30 23:28:45,539 [DEBUG] [hz.unruffled_moser.cached.thread-5] [c.h.j.i.o.CompleteExecutionOperation]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Completing execution 050c-950d-6d47-0001 from caller [127.0.0.1]:5701, error=null
2020-09-30 23:28:45,539 [DEBUG] [hz.unruffled_moser.cached.thread-5] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Completed execution of job '050c-950d-6d46-0001', execution 050c-950d-6d47-0001
2020-09-30 23:28:45,539 [DEBUG] [hz.festive_moser.generic-operation.thread-16] [c.h.j.i.o.CompleteExecutionOperation]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Completing execution 050c-950d-6d47-0001 from caller [127.0.0.1]:5701, error=null
2020-09-30 23:28:45,539 [DEBUG] [hz.festive_moser.generic-operation.thread-16] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Completed execution of job '050c-950d-6d46-0001', execution 050c-950d-6d47-0001
2020-09-30 23:28:45,540 [ INFO] [hz.unruffled_moser.cached.thread-5] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Execution of job '050c-950d-6d46-0001', execution 050c-950d-6d47-0001 completed successfully
	Start time: 2020-09-30T23:28:45.534
	Duration: 6 ms
	To see additional job metrics enable JobConfig.storeMetricsAfterJobCompletion
2020-09-30 23:28:45,540 [DEBUG] [hz.unruffled_moser.cached.thread-5] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] job '050c-950d-6d46-0001', execution 050c-950d-6d47-0001 is completed
2020-09-30 23:28:45,540 [ INFO] [Thread-52] [c.h.j.c.MemberReconnectionStressTest]: job completed
2020-09-30 23:28:45,541 [ INFO] [hz.unruffled_moser.cached.thread-6] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Starting job 050c-950d-6d48-0001 based on submit request
2020-09-30 23:28:45,543 [ INFO] [hz.unruffled_moser.cached.thread-6] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Didn't find any snapshot to restore for job '050c-950d-6d48-0001', execution 050c-950d-6d49-0001
2020-09-30 23:28:45,543 [ INFO] [hz.unruffled_moser.cached.thread-6] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Start executing job '050c-950d-6d48-0001', execution 050c-950d-6d49-0001, execution graph in DOT format:
digraph DAG {
	"v1" [localParallelism=2];
	"v2" [localParallelism=2];
	"v1" -> "v2" [label="distributed", queueSize=1024];
}
HINT: You can use graphviz or http://viz-js.com to visualize the printed graph.
2020-09-30 23:28:45,543 [DEBUG] [hz.unruffled_moser.cached.thread-6] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Building execution plan for job '050c-950d-6d48-0001', execution 050c-950d-6d49-0001
2020-09-30 23:28:45,543 [DEBUG] [hz.unruffled_moser.cached.thread-6] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Built execution plans for job '050c-950d-6d48-0001', execution 050c-950d-6d49-0001
2020-09-30 23:28:45,544 [DEBUG] [hz.unruffled_moser.cached.thread-6] [c.h.j.i.o.InitExecutionOperation]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Initializing execution plan for job 050c-950d-6d48-0001, execution 050c-950d-6d49-0001 from [127.0.0.1]:5701
2020-09-30 23:28:45,544 [DEBUG] [hz.festive_moser.generic-operation.thread-17] [c.h.j.i.o.InitExecutionOperation]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Initializing execution plan for job 050c-950d-6d48-0001, execution 050c-950d-6d49-0001 from [127.0.0.1]:5701
2020-09-30 23:28:45,545 [ INFO] [hz.unruffled_moser.cached.thread-6] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Execution plan for jobId=050c-950d-6d48-0001, jobName='050c-950d-6d48-0001', executionId=050c-950d-6d49-0001 initialized
2020-09-30 23:28:45,547 [ INFO] [hz.festive_moser.generic-operation.thread-17] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Execution plan for jobId=050c-950d-6d48-0001, jobName='050c-950d-6d48-0001', executionId=050c-950d-6d49-0001 initialized
2020-09-30 23:28:45,547 [DEBUG] [hz.unruffled_moser.cached.thread-6] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Init of job '050c-950d-6d48-0001', execution 050c-950d-6d49-0001 was successful
2020-09-30 23:28:45,547 [DEBUG] [hz.unruffled_moser.cac
...[truncated 2983195 chars]...
tween /0.0.0.0:43942 and /127.0.0.1:5702
2020-09-30 23:29:52,777 [ WARN] [Thread-51] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Connection[id=227, /0.0.0.0:43942->/127.0.0.1:5702, qualifier=null, endpoint=[127.0.0.1]:5702, alive=false, connectionType=MEMBER] closed. Reason: test
java.lang.Exception: test failure
	at com.hazelcast.jet.core.MemberReconnectionStressTest.lambda$test$0(MemberReconnectionStressTest.java:84) ~[test-classes/:?]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_251]
2020-09-30 23:29:52,777 [ INFO] [hz.festive_moser.IO.thread-in-2] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Connection[id=227, /127.0.0.1:5702->/127.0.0.1:43942, qualifier=null, endpoint=[127.0.0.1]:5701, alive=false, connectionType=MEMBER] closed. Reason: Connection closed by the other side
2020-09-30 23:29:52,777 [ INFO] [Thread-51] [c.h.j.c.MemberReconnectionStressTest]: connection closed
2020-09-30 23:29:52,777 [ INFO] [hz.unruffled_moser.cached.thread-11] [c.h.i.n.t.TcpIpConnector]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5702, timeout: 10000, bind-any: true
2020-09-30 23:29:52,778 [ INFO] [hz.festive_moser.IO.thread-in-3] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Initialized new cluster connection between /127.0.0.1:5702 and /127.0.0.1:56004
2020-09-30 23:29:52,778 [ INFO] [hz.unruffled_moser.IO.thread-in-3] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Initialized new cluster connection between /0.0.0.0:56004 and /127.0.0.1:5702
2020-09-30 23:29:53,077 [ WARN] [Thread-51] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Connection[id=228, /0.0.0.0:56004->/127.0.0.1:5702, qualifier=null, endpoint=[127.0.0.1]:5702, alive=false, connectionType=MEMBER] closed. Reason: test
java.lang.Exception: test failure
	at com.hazelcast.jet.core.MemberReconnectionStressTest.lambda$test$0(MemberReconnectionStressTest.java:84) ~[test-classes/:?]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_251]
2020-09-30 23:29:53,077 [ INFO] [Thread-51] [c.h.j.c.MemberReconnectionStressTest]: connection closed
2020-09-30 23:29:53,077 [ INFO] [hz.festive_moser.IO.thread-in-3] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Connection[id=228, /127.0.0.1:5702->/127.0.0.1:56004, qualifier=null, endpoint=[127.0.0.1]:5701, alive=false, connectionType=MEMBER] closed. Reason: Connection closed by the other side
2020-09-30 23:29:53,078 [ INFO] [hz.unruffled_moser.cached.thread-1] [c.h.i.n.t.TcpIpConnector]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5702, timeout: 10000, bind-any: true
2020-09-30 23:29:53,078 [ INFO] [hz.festive_moser.IO.thread-in-0] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Initialized new cluster connection between /127.0.0.1:5702 and /127.0.0.1:59046
2020-09-30 23:29:53,078 [ INFO] [hz.unruffled_moser.IO.thread-in-0] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Initialized new cluster connection between /0.0.0.0:59046 and /127.0.0.1:5702
2020-09-30 23:29:53,378 [ WARN] [Thread-51] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Connection[id=229, /0.0.0.0:59046->/127.0.0.1:5702, qualifier=null, endpoint=[127.0.0.1]:5702, alive=false, connectionType=MEMBER] closed. Reason: test
java.lang.Exception: test failure
	at com.hazelcast.jet.core.MemberReconnectionStressTest.lambda$test$0(MemberReconnectionStressTest.java:84) ~[test-classes/:?]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_251]
2020-09-30 23:29:53,378 [ INFO] [hz.festive_moser.IO.thread-in-0] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Connection[id=229, /127.0.0.1:5702->/127.0.0.1:59046, qualifier=null, endpoint=[127.0.0.1]:5701, alive=false, connectionType=MEMBER] closed. Reason: Connection closed by the other side
2020-09-30 23:29:53,378 [ INFO] [Thread-51] [c.h.j.c.MemberReconnectionStressTest]: connection closed
2020-09-30 23:29:53,378 [ INFO] [hz.unruffled_moser.cached.thread-1] [c.h.i.n.t.TcpIpConnector]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5702, timeout: 10000, bind-any: true
2020-09-30 23:29:53,378 [ INFO] [hz.festive_moser.IO.thread-in-1] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Initialized new cluster connection between /127.0.0.1:5702 and /127.0.0.1:37251
2020-09-30 23:29:53,378 [ INFO] [hz.unruffled_moser.IO.thread-in-1] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Initialized new cluster connection between /0.0.0.0:37251 and /127.0.0.1:5702
2020-09-30 23:29:53,678 [ WARN] [Thread-51] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Connection[id=230, /0.0.0.0:37251->/127.0.0.1:5702, qualifier=null, endpoint=[127.0.0.1]:5702, alive=false, connectionType=MEMBER] closed. Reason: test
java.lang.Exception: test failure
	at com.hazelcast.jet.core.MemberReconnectionStressTest.lambda$test$0(MemberReconnectionStressTest.java:84) ~[test-classes/:?]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_251]
2020-09-30 23:29:53,678 [ INFO] [hz.festive_moser.IO.thread-in-1] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Connection[id=230, /127.0.0.1:5702->/127.0.0.1:37251, qualifier=null, endpoint=[127.0.0.1]:5701, alive=false, connectionType=MEMBER] closed. Reason: Connection closed by the other side
2020-09-30 23:29:53,678 [ INFO] [Thread-51] [c.h.j.c.MemberReconnectionStressTest]: connection closed
2020-09-30 23:29:53,678 [ INFO] [hz.unruffled_moser.cached.thread-8] [c.h.i.n.t.TcpIpConnector]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5702, timeout: 10000, bind-any: true
2020-09-30 23:29:53,679 [ INFO] [hz.festive_moser.IO.thread-in-2] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Initialized new cluster connection between /127.0.0.1:5702 and /127.0.0.1:42860
2020-09-30 23:29:53,679 [ INFO] [hz.unruffled_moser.IO.thread-in-2] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Initialized new cluster connection between /0.0.0.0:42860 and /127.0.0.1:5702
2020-09-30 23:29:53,978 [ WARN] [Thread-51] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Connection[id=231, /0.0.0.0:42860->/127.0.0.1:5702, qualifier=null, endpoint=[127.0.0.1]:5702, alive=false, connectionType=MEMBER] closed. Reason: test
java.lang.Exception: test failure
	at com.hazelcast.jet.core.MemberReconnectionStressTest.lambda$test$0(MemberReconnectionStressTest.java:84) ~[test-classes/:?]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_251]
2020-09-30 23:29:53,978 [ INFO] [hz.festive_moser.IO.thread-in-2] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Connection[id=231, /127.0.0.1:5702->/127.0.0.1:42860, qualifier=null, endpoint=[127.0.0.1]:5701, alive=false, connectionType=MEMBER] closed. Reason: Connection closed by the other side
2020-09-30 23:29:53,978 [ INFO] [Thread-51] [c.h.j.c.MemberReconnectionStressTest]: connection closed
2020-09-30 23:29:53,979 [ INFO] [hz.unruffled_moser.cached.thread-8] [c.h.i.n.t.TcpIpConnector]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5702, timeout: 10000, bind-any: true
2020-09-30 23:29:53,979 [ INFO] [hz.festive_moser.IO.thread-in-3] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Initialized new cluster connection between /127.0.0.1:5702 and /127.0.0.1:40064
2020-09-30 23:29:53,979 [ INFO] [hz.unruffled_moser.IO.thread-in-3] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Initialized new cluster connection between /127.0.0.1:40064 and /127.0.0.1:5702
2020-09-30 23:29:54,278 [ WARN] [Thread-51] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Connection[id=232, /127.0.0.1:40064->/127.0.0.1:5702, qualifier=null, endpoint=[127.0.0.1]:5702, alive=false, connectionType=MEMBER] closed. Reason: test
java.lang.Exception: test failure
	at com.hazelcast.jet.core.MemberReconnectionStressTest.lambda$test$0(MemberReconnectionStressTest.java:84) ~[test-classes/:?]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_251]
2020-09-30 23:29:54,279 [ INFO] [hz.festive_moser.IO.thread-in-3] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Connection[id=232, /127.0.0.1:5702->/127.0.0.1:40064, qualifier=null, endpoint=[127.0.0.1]:5701, alive=false, connectionType=MEMBER] closed. Reason: Connection closed by the other side
2020-09-30 23:29:54,279 [ INFO] [Thread-51] [c.h.j.c.MemberReconnectionStressTest]: connection closed
2020-09-30 23:29:54,279 [ INFO] [hz.unruffled_moser.cached.thread-11] [c.h.i.n.t.TcpIpConnector]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5702, timeout: 10000, bind-any: true
2020-09-30 23:29:54,279 [ INFO] [hz.festive_moser.IO.thread-in-0] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Initialized new cluster connection between /127.0.0.1:5702 and /127.0.0.1:43383
2020-09-30 23:29:54,279 [ INFO] [hz.unruffled_moser.IO.thread-in-0] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Initialized new cluster connection between /0.0.0.0:43383 and /127.0.0.1:5702
2020-09-30 23:29:54,579 [ WARN] [Thread-51] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Connection[id=233, /0.0.0.0:43383->/127.0.0.1:5702, qualifier=null, endpoint=[127.0.0.1]:5702, alive=false, connectionType=MEMBER] closed. Reason: test
java.lang.Exception: test failure
	at com.hazelcast.jet.core.MemberReconnectionStressTest.lambda$test$0(MemberReconnectionStressTest.java:84) ~[test-classes/:?]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_251]
2020-09-30 23:29:54,579 [ INFO] [Thread-51] [c.h.j.c.MemberReconnectionStressTest]: connection closed
2020-09-30 23:29:54,579 [ INFO] [hz.festive_moser.IO.thread-in-0] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Connection[id=233, /127.0.0.1:5702->/127.0.0.1:43383, qualifier=null, endpoint=[127.0.0.1]:5701, alive=false, connectionType=MEMBER] closed. Reason: Connection closed by the other side
2020-09-30 23:29:54,579 [ INFO] [hz.unruffled_moser.cached.thread-10] [c.h.i.n.t.TcpIpConnector]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5702, timeout: 10000, bind-any: true
2020-09-30 23:29:54,579 [ INFO] [hz.festive_moser.IO.thread-in-1] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Initialized new cluster connection between /127.0.0.1:5702 and /127.0.0.1:56267
2020-09-30 23:29:54,580 [ INFO] [hz.unruffled_moser.IO.thread-in-1] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Initialized new cluster connection between /0.0.0.0:56267 and /127.0.0.1:5702
2020-09-30 23:29:54,879 [ WARN] [Thread-51] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Connection[id=234, /0.0.0.0:56267->/127.0.0.1:5702, qualifier=null, endpoint=[127.0.0.1]:5702, alive=false, connectionType=MEMBER] closed. Reason: test
java.lang.Exception: test failure
	at com.hazelcast.jet.core.MemberReconnectionStressTest.lambda$test$0(MemberReconnectionStressTest.java:84) ~[test-classes/:?]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_251]
2020-09-30 23:29:54,879 [ INFO] [hz.festive_moser.IO.thread-in-1] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Connection[id=234, /127.0.0.1:5702->/127.0.0.1:56267, qualifier=null, endpoint=[127.0.0.1]:5701, alive=false, connectionType=MEMBER] closed. Reason: Connection closed by the other side
2020-09-30 23:29:54,879 [ INFO] [Thread-51] [c.h.j.c.MemberReconnectionStressTest]: connection closed
2020-09-30 23:29:54,879 [ INFO] [hz.unruffled_moser.cached.thread-10] [c.h.i.n.t.TcpIpConnector]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5702, timeout: 10000, bind-any: true
2020-09-30 23:29:54,880 [ INFO] [hz.festive_moser.IO.thread-in-2] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Initialized new cluster connection between /127.0.0.1:5702 and /127.0.0.1:47822
2020-09-30 23:29:54,880 [ INFO] [hz.unruffled_moser.IO.thread-in-2] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Initialized new cluster connection between /127.0.0.1:47822 and /127.0.0.1:5702
2020-09-30 23:29:55,179 [ WARN] [Thread-51] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Connection[id=235, /127.0.0.1:47822->/127.0.0.1:5702, qualifier=null, endpoint=[127.0.0.1]:5702, alive=false, connectionType=MEMBER] closed. Reason: test
java.lang.Exception: test failure
	at com.hazelcast.jet.core.MemberReconnectionStressTest.lambda$test$0(MemberReconnectionStressTest.java:84) ~[test-classes/:?]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_251]
2020-09-30 23:29:55,179 [ INFO] [Thread-51] [c.h.j.c.MemberReconnectionStressTest]: connection closed
2020-09-30 23:29:55,179 [ INFO] [hz.festive_moser.IO.thread-in-2] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Connection[id=235, /127.0.0.1:5702->/127.0.0.1:47822, qualifier=null, endpoint=[127.0.0.1]:5701, alive=false, connectionType=MEMBER] closed. Reason: Connection closed by the other side
2020-09-30 23:29:55,179 [ INFO] [hz.unruffled_moser.cached.thread-13] [c.h.i.n.t.TcpIpConnector]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5702, timeout: 10000, bind-any: true
2020-09-30 23:29:55,180 [ INFO] [hz.festive_moser.IO.thread-in-3] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Initialized new cluster connection between /127.0.0.1:5702 and /127.0.0.1:54540
2020-09-30 23:29:55,180 [ INFO] [hz.unruffled_moser.IO.thread-in-3] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Initialized new cluster connection between /127.0.0.1:54540 and /127.0.0.1:5702
2020-09-30 23:29:55,479 [ WARN] [Thread-51] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Connection[id=236, /127.0.0.1:54540->/127.0.0.1:5702, qualifier=null, endpoint=[127.0.0.1]:5702, alive=false, connectionType=MEMBER] closed. Reason: test
java.lang.Exception: test failure
	at com.hazelcast.jet.core.MemberReconnectionStressTest.lambda$test$0(MemberReconnectionStressTest.java:84) ~[test-classes/:?]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_251]
2020-09-30 23:29:55,480 [ INFO] [Thread-51] [c.h.j.c.MemberReconnectionStressTest]: connection closed
2020-09-30 23:29:55,480 [ INFO] [hz.festive_moser.IO.thread-in-3] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Connection[id=236, /127.0.0.1:5702->/127.0.0.1:54540, qualifier=null, endpoint=[127.0.0.1]:5701, alive=false, connectionType=MEMBER] closed. Reason: Connection closed by the other side
2020-09-30 23:29:55,480 [ INFO] [hz.unruffled_moser.cached.thread-13] [c.h.i.n.t.TcpIpConnector]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5702, timeout: 10000, bind-any: true
2020-09-30 23:29:55,480 [ INFO] [hz.festive_moser.IO.thread-in-0] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Initialized new cluster connection between /127.0.0.1:5702 and /127.0.0.1:38526
2020-09-30 23:29:55,480 [ INFO] [hz.unruffled_moser.IO.thread-in-0] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Initialized new cluster connection between /0.0.0.0:38526 and /127.0.0.1:5702
2020-09-30 23:29:55,780 [ WARN] [Thread-51] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Connection[id=237, /0.0.0.0:38526->/127.0.0.1:5702, qualifier=null, endpoint=[127.0.0.1]:5702, alive=false, connectionType=MEMBER] closed. Reason: test
java.lang.Exception: test failure
	at com.hazelcast.jet.core.MemberReconnectionStressTest.lambda$test$0(MemberReconnectionStressTest.java:84) ~[test-classes/:?]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_251]
2020-09-30 23:29:55,780 [ INFO] [hz.festive_moser.IO.thread-in-0] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Connection[id=237, /127.0.0.1:5702->/127.0.0.1:38526, qualifier=null, endpoint=[127.0.0.1]:5701, alive=false, connectionType=MEMBER] closed. Reason: Connection closed by the other side
2020-09-30 23:29:55,780 [ INFO] [Thread-51] [c.h.j.c.MemberReconnectionStressTest]: connection closed
2020-09-30 23:29:55,780 [ INFO] [hz.unruffled_moser.cached.thread-1] [c.h.i.n.t.TcpIpConnector]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5702, timeout: 10000, bind-any: true
2020-09-30 23:29:55,780 [ INFO] [hz.festive_moser.IO.thread-in-1] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Initialized new cluster connection between /127.0.0.1:5702 and /127.0.0.1:50519
2020-09-30 23:29:55,780 [ INFO] [hz.unruffled_moser.IO.thread-in-1] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Initialized new cluster connection between /0.0.0.0:50519 and /127.0.0.1:5702
2020-09-30 23:29:55,793 [DEBUG] [hz.unruffled_moser.cached.thread-1] [c.h.j.i.JobRepository]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Job cleanup took 0ms
2020-09-30 23:29:56,080 [ WARN] [Thread-51] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Connection[id=238, /0.0.0.0:50519->/127.0.0.1:5702, qualifier=null, endpoint=[127.0.0.1]:5702, alive=false, connectionType=MEMBER] closed. Reason: test
java.lang.Exception: test failure
	at com.hazelcast.jet.core.MemberReconnectionStressTest.lambda$test$0(MemberReconnectionStressTest.java:84) ~[test-classes/:?]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_251]
2020-09-30 23:29:56,080 [ INFO] [Thread-51] [c.h.j.c.MemberReconnectionStressTest]: connection closed
2020-09-30 23:29:56,080 [ INFO] [hz.festive_moser.IO.thread-in-1] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Connection[id=238, /127.0.0.1:5702->/127.0.0.1:50519, qualifier=null, endpoint=[127.0.0.1]:5701, alive=false, connectionType=MEMBER] closed. Reason: Connection closed by the other side
2020-09-30 23:29:56,080 [ INFO] [hz.unruffled_moser.cached.thread-10] [c.h.i.n.t.TcpIpConnector]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5702, timeout: 10000, bind-any: true
2020-09-30 23:29:56,081 [ INFO] [hz.festive_moser.IO.thread-in-2] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Initialized new cluster connection between /127.0.0.1:5702 and /127.0.0.1:51481
2020-09-30 23:29:56,081 [ INFO] [hz.unruffled_moser.IO.thread-in-2] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Initialized new cluster connection between /0.0.0.0:51481 and /127.0.0.1:5702
2020-09-30 23:29:56,380 [ WARN] [Thread-51] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Connection[id=239, /0.0.0.0:51481->/127.0.0.1:5702, qualifier=null, endpoint=[127.0.0.1]:5702, alive=false, connectionType=MEMBER] closed. Reason: test
java.lang.Exception: test failure
	at com.hazelcast.jet.core.MemberReconnectionStressTest.lambda$test$0(MemberReconnectionStressTest.java:84) ~[test-classes/:?]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_251]
2020-09-30 23:29:56,380 [ INFO] [hz.festive_moser.IO.thread-in-2] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Connection[id=239, /127.0.0.1:5702->/127.0.0.1:51481, qualifier=null, endpoint=[127.0.0.1]:5701, alive=false, connectionType=MEMBER] closed. Reason: Connection closed by the other side
2020-09-30 23:29:56,380 [ INFO] [Thread-51] [c.h.j.c.MemberReconnectionStressTest]: connection closed
2020-09-30 23:29:56,381 [ INFO] [hz.unruffled_moser.cached.thread-10] [c.h.i.n.t.TcpIpConnector]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5702, timeout: 10000, bind-any: true
2020-09-30 23:29:56,381 [ INFO] [hz.festive_moser.IO.thread-in-3] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Initialized new cluster connection between /127.0.0.1:5702 and /127.0.0.1:53293
2020-09-30 23:29:56,381 [ INFO] [hz.unruffled_moser.IO.thread-in-3] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Initialized new cluster connection between /127.0.0.1:53293 and /127.0.0.1:5702
2020-09-30 23:29:56,681 [ WARN] [Thread-51] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Connection[id=240, /127.0.0.1:53293->/127.0.0.1:5702, qualifier=null, endpoint=[127.0.0.1]:5702, alive=false, connectionType=MEMBER] closed. Reason: test
java.lang.Exception: test failure
	at com.hazelcast.jet.core.MemberReconnectionStressTest.lambda$test$0(MemberReconnectionStressTest.java:84) ~[test-classes/:?]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_251]
2020-09-30 23:29:56,681 [ INFO] [hz.festive_moser.IO.thread-in-3] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Connection[id=240, /127.0.0.1:5702->/127.0.0.1:53293, qualifier=null, endpoint=[127.0.0.1]:5701, alive=false, connectionType=MEMBER] closed. Reason: Connection closed by the other side
2020-09-30 23:29:56,681 [ INFO] [Thread-51] [c.h.j.c.MemberReconnectionStressTest]: connection closed
2020-09-30 23:29:56,681 [ INFO] [hz.unruffled_moser.cached.thread-8] [c.h.i.n.t.TcpIpConnector]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5702, timeout: 10000, bind-any: true
2020-09-30 23:29:56,681 [ INFO] [hz.festive_moser.IO.thread-in-0] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Initialized new cluster connection between /127.0.0.1:5702 and /127.0.0.1:49330
2020-09-30 23:29:56,682 [ INFO] [hz.unruffled_moser.IO.thread-in-0] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Initialized new cluster connection between /127.0.0.1:49330 and /127.0.0.1:5702
2020-09-30 23:29:56,981 [ WARN] [Thread-51] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Connection[id=241, /127.0.0.1:49330->/127.0.0.1:5702, qualifier=null, endpoint=[127.0.0.1]:5702, alive=false, connectionType=MEMBER] closed. Reason: test
java.lang.Exception: test failure
	at com.hazelcast.jet.core.MemberReconnectionStressTest.lambda$test$0(MemberReconnectionStressTest.java:84) ~[test-classes/:?]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_251]
2020-09-30 23:29:56,981 [ INFO] [hz.festive_moser.IO.thread-in-0] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Connection[id=241, /127.0.0.1:5702->/127.0.0.1:49330, qualifier=null, endpoint=[127.0.0.1]:5701, alive=false, connectionType=MEMBER] closed. Reason: Connection closed by the other side
2020-09-30 23:29:56,981 [ INFO] [Thread-51] [c.h.j.c.MemberReconnectionStressTest]: connection closed
2020-09-30 23:29:56,981 [ INFO] [hz.unruffled_moser.cached.thread-8] [c.h.i.n.t.TcpIpConnector]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5702, timeout: 10000, bind-any: true
2020-09-30 23:29:56,981 [ INFO] [hz.festive_moser.IO.thread-in-1] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Initialized new cluster connection between /127.0.0.1:5702 and /127.0.0.1:44000
2020-09-30 23:29:56,982 [ INFO] [hz.unruffled_moser.IO.thread-in-1] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Initialized new cluster connection between /0.0.0.0:44000 and /127.0.0.1:5702
2020-09-30 23:29:57,281 [ WARN] [Thread-51] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Connection[id=242, /0.0.0.0:44000->/127.0.0.1:5702, qualifier=null, endpoint=[127.0.0.1]:5702, alive=false, connectionType=MEMBER] closed. Reason: test
java.lang.Exception: test failure
	at com.hazelcast.jet.core.MemberReconnectionStressTest.lambda$test$0(MemberReconnectionStressTest.java:84) ~[test-classes/:?]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_251]
2020-09-30 23:29:57,281 [ INFO] [Thread-51] [c.h.j.c.MemberReconnectionStressTest]: connection closed
2020-09-30 23:29:57,281 [ INFO] [hz.festive_moser.IO.thread-in-1] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Connection[id=242, /127.0.0.1:5702->/127.0.0.1:44000, qualifier=null, endpoint=[127.0.0.1]:5701, alive=false, connectionType=MEMBER] closed. Reason: Connection closed by the other side
2020-09-30 23:29:57,281 [ INFO] [hz.unruffled_moser.cached.thread-13] [c.h.i.n.t.TcpIpConnector]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5702, timeout: 10000, bind-any: true
2020-09-30 23:29:57,282 [ INFO] [hz.festive_moser.IO.thread-in-2] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Initialized new cluster connection between /127.0.0.1:5702 and /127.0.0.1:37218
2020-09-30 23:29:57,282 [ INFO] [hz.unruffled_moser.IO.thread-in-2] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Initialized new cluster connection between /0.0.0.0:37218 and /127.0.0.1:5702
2020-09-30 23:29:57,581 [ WARN] [Thread-51] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Connection[id=243, /0.0.0.0:37218->/127.0.0.1:5702, qualifier=null, endpoint=[127.0.0.1]:5702, alive=false, connectionType=MEMBER] closed. Reason: test
java.lang.Exception: test failure
	at com.hazelcast.jet.core.MemberReconnectionStressTest.lambda$test$0(MemberReconnectionStressTest.java:84) ~[test-classes/:?]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_251]
2020-09-30 23:29:57,581 [ INFO] [Thread-51] [c.h.j.c.MemberReconnectionStressTest]: connection closed
2020-09-30 23:29:57,581 [ INFO] [hz.festive_moser.IO.thread-in-2] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Connection[id=243, /127.0.0.1:5702->/127.0.0.1:37218, qualifier=null, endpoint=[127.0.0.1]:5701, alive=false, connectionType=MEMBER] closed. Reason: Connection closed by the other side
2020-09-30 23:29:57,581 [ INFO] [hz.unruffled_moser.cached.thread-1] [c.h.i.n.t.TcpIpConnector]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5702, timeout: 10000, bind-any: true
2020-09-30 23:29:57,582 [ INFO] [hz.festive_moser.IO.thread-in-3] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Initialized new cluster connection between /127.0.0.1:5702 and /127.0.0.1:51331
2020-09-30 23:29:57,582 [ INFO] [hz.unruffled_moser.IO.thread-in-3] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Initialized new cluster connection between /0.0.0.0:51331 and /127.0.0.1:5702
2020-09-30 23:29:57,906 [ WARN] [Thread-51] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Connection[id=244, /0.0.0.0:51331->/127.0.0.1:5702, qualifier=null, endpoint=[127.0.0.1]:5702, alive=false, connectionType=MEMBER] closed. Reason: test
java.lang.Exception: test failure
	at com.hazelcast.jet.core.MemberReconnectionStressTest.lambda$test$0(MemberReconnectionStressTest.java:84) ~[test-classes/:?]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_251]
2020-09-30 23:29:57,906 [ INFO] [hz.festive_moser.IO.thread-in-3] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Connection[id=244, /127.0.0.1:5702->/127.0.0.1:51331, qualifier=null, endpoint=[127.0.0.1]:5701, alive=false, connectionType=MEMBER] closed. Reason: Connection closed by the other side
2020-09-30 23:29:57,906 [ INFO] [Thread-51] [c.h.j.c.MemberReconnectionStressTest]: connection closed
2020-09-30 23:29:57,907 [ INFO] [hz.unruffled_moser.cached.thread-12] [c.h.i.n.t.TcpIpConnector]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5702, timeout: 10000, bind-any: true
2020-09-30 23:29:57,907 [ INFO] [hz.festive_moser.IO.thread-in-0] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Initialized new cluster connection between /127.0.0.1:5702 and /127.0.0.1:42396
2020-09-30 23:29:57,907 [ INFO] [hz.unruffled_moser.IO.thread-in-0] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Initialized new cluster connection between /0.0.0.0:42396 and /127.0.0.1:5702
2020-09-30 23:29:57,985 [ INFO] [Time-limited test] [c.h.c.LifecycleService]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] [127.0.0.1]:5702 is SHUTTING_DOWN
2020-09-30 23:29:57,988 [ INFO] [hz.unruffled_moser.priority-generic-operation.thread-0] [c.h.i.p.i.MigrationManager]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Shutdown request of Member [127.0.0.1]:5702 - ddac6c6e-b5aa-4c60-bd7f-4521e04a0b4e is handled
2020-09-30 23:29:58,014 [ INFO] [hz.unruffled_moser.migration] [c.h.i.p.i.MigrationManager]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Repartitioning cluster data. Migration tasks count: 135
2020-09-30 23:29:58,177 [ INFO] [Time-limited test] [c.h.i.i.Node]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Shutting down multicast service...
2020-09-30 23:29:58,178 [ INFO] [Time-limited test] [c.h.i.i.Node]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Shutting down connection manager...
2020-09-30 23:29:58,181 [ INFO] [Time-limited test] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Connection[id=4, /127.0.0.1:5702->/127.0.0.1:56148, qualifier=null, endpoint=[127.0.0.1]:5701, alive=false, connectionType=MEMBER] closed. Reason: EndpointManager is stopping
2020-09-30 23:29:58,182 [ INFO] [Time-limited test] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Connection[id=3, /127.0.0.1:5702->/127.0.0.1:56162, qualifier=null, endpoint=[127.0.0.1]:5701, alive=false, connectionType=MEMBER] closed. Reason: EndpointManager is stopping
2020-09-30 23:29:58,182 [ INFO] [Time-limited test] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Connection[id=245, /127.0.0.1:5702->/127.0.0.1:42396, qualifier=null, endpoint=[127.0.0.1]:5701, alive=false, connectionType=MEMBER] closed. Reason: EndpointManager is stopping
2020-09-30 23:29:58,184 [ INFO] [Time-limited test] [c.h.i.i.Node]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Shutting down node engine...
2020-09-30 23:29:58,184 [ INFO] [hz.unruffled_moser.IO.thread-in-3] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Connection[id=4, /0.0.0.0:56148->/127.0.0.1:5702, qualifier=null, endpoint=[127.0.0.1]:5702, alive=false, connectionType=MEMBER] closed. Reason: Connection closed by the other side
2020-09-30 23:29:58,185 [ INFO] [hz.unruffled_moser.IO.thread-in-0] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Connection[id=245, /0.0.0.0:42396->/127.0.0.1:5702, qualifier=null, endpoint=[127.0.0.1]:5702, alive=false, connectionType=MEMBER] closed. Reason: Connection closed by the other side
2020-09-30 23:29:58,185 [ INFO] [hz.unruffled_moser.IO.thread-in-1] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Connection[id=3, /0.0.0.0:56162->/127.0.0.1:5702, qualifier=null, endpoint=[127.0.0.1]:5702, alive=false, connectionType=MEMBER] closed. Reason: Connection closed by the other side
2020-09-30 23:29:58,185 [ INFO] [hz.unruffled_moser.cached.thread-8] [c.h.i.n.t.TcpIpConnector]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5702, timeout: 10000, bind-any: true
2020-09-30 23:29:58,185 [ INFO] [hz.unruffled_moser.cached.thread-12] [c.h.i.n.t.TcpIpConnector]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5702, timeout: 10000, bind-any: true
2020-09-30 23:29:58,189 [ INFO] [hz.unruffled_moser.cached.thread-12] [c.h.i.n.t.TcpIpConnector]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5702. Reason: SocketException[Connection refused to address /127.0.0.1:5702]
2020-09-30 23:29:58,189 [ INFO] [hz.unruffled_moser.cached.thread-8] [c.h.i.n.t.TcpIpConnector]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5702. Reason: SocketException[Connection refused to address /127.0.0.1:5702]
2020-09-30 23:29:58,187 [DEBUG] [hz.festive_moser.jet.cooperative.thread-10] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Execution of job '050c-9518-9c9e-0001', execution 050c-9518-9c9f-0001 completed with failure
java.util.concurrent.CompletionException: java.util.concurrent.CancellationException
	at java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:292) ~[?:1.8.0_251]
	at java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:308) ~[?:1.8.0_251]
	at java.util.concurrent.CompletableFuture.uniApply(CompletableFuture.java:607) ~[?:1.8.0_251]
	at java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:591) ~[?:1.8.0_251]
	at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:488) ~[?:1.8.0_251]
	at java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:1990) ~[?:1.8.0_251]
	at com.hazelcast.jet.impl.util.NonCompletableFuture.internalCompleteExceptionally(NonCompletableFuture.java:59) ~[classes/:?]
	at com.hazelcast.jet.impl.execution.TaskletExecutionService$ExecutionTracker.taskletDone(TaskletExecutionService.java:461) ~[classes/:?]
	at com.hazelcast.jet.impl.execution.TaskletExecutionService$CooperativeWorker.dismissTasklet(TaskletExecutionService.java:392) ~[classes/:?]
	at com.hazelcast.jet.impl.execution.TaskletExecutionService$CooperativeWorker.runTasklet(TaskletExecutionService.java:378) ~[classes/:?]
	at java.util.concurrent.CopyOnWriteArrayList.forEach(CopyOnWriteArrayList.java:891) [?:1.8.0_251]
	at com.hazelcast.jet.impl.execution.TaskletExecutionService$CooperativeWorker.run(TaskletExecutionService.java:346) [classes/:?]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_251]
Caused by: java.util.concurrent.CancellationException
	at java.util.concurrent.CompletableFuture.cancel(CompletableFuture.java:2276) ~[?:1.8.0_251]
	at com.hazelcast.jet.impl.execution.ExecutionContext.terminateExecution(ExecutionContext.java:233) ~[classes/:?]
	at com.hazelcast.jet.impl.JobExecutionService.cancelAndComplete(JobExecutionService.java:183) ~[classes/:?]
	at com.hazelcast.jet.impl.JobExecutionService.lambda$cancelAllExecutions$4(JobExecutionService.java:157) ~[classes/:?]
	at java.util.concurrent.ConcurrentHashMap$ValuesView.forEach(ConcurrentHashMap.java:4707) ~[?:1.8.0_251]
	at com.hazelcast.jet.impl.JobExecutionService.cancelAllExecutions(JobExecutionService.java:153) ~[classes/:?]
	at com.hazelcast.jet.impl.JobExecutionService.shutdown(JobExecutionService.java:142) ~[classes/:?]
	at com.hazelcast.jet.impl.JetService.shutdown(JetService.java:167) ~[classes/:?]
	at com.hazelcast.spi.impl.servicemanager.impl.ServiceManagerImpl.shutdownService(ServiceManagerImpl.java:307) ~[hazelcast-4.0.3.jar:4.0.3]
	at com.hazelcast.spi.impl.servicemanager.impl.ServiceManagerImpl.shutdown(ServiceManagerImpl.java:298) ~[hazelcast-4.0.3.jar:4.0.3]
	at com.hazelcast.spi.impl.NodeEngineImpl.shutdown(NodeEngineImpl.java:494) ~[hazelcast-4.0.3.jar:4.0.3]
	at com.hazelcast.instance.impl.Node.shutdownServices(Node.java:584) ~[hazelcast-4.0.3.jar:4.0.3]
	at com.hazelcast.instance.impl.Node.shutdown(Node.java:519) ~[hazelcast-4.0.3.jar:4.0.3]
	at com.hazelcast.instance.impl.LifecycleServiceImpl.shutdown(LifecycleServiceImpl.java:101) ~[hazelcast-4.0.3.jar:4.0.3]
	at com.hazelcast.instance.impl.LifecycleServiceImpl.shutdown(LifecycleServiceImpl.java:84) ~[hazelcast-4.0.3.jar:4.0.3]
	at com.hazelcast.instance.impl.HazelcastInstanceFactory.shutdownAll(HazelcastInstanceFactory.java:300) ~[hazelcast-4.0.3.jar:4.0.3]
	at com.hazelcast.instance.impl.HazelcastInstanceFactory.shutdownAll(HazelcastInstanceFactory.java:274) ~[hazelcast-4.0.3.jar:4.0.3]
	at com.hazelcast.core.Hazelcast.shutdownAll(Hazelcast.java:40) ~[hazelcast-4.0.3.jar:4.0.3]
	at com.hazelcast.jet.Jet.shutdownAll(Jet.java:237) ~[classes/:?]
	at com.hazelcast.jet.core.MemberReconnectionStressTest.after(MemberReconnectionStressTest.java:50) ~[test-classes/:?]
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.8.0_251]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:1.8.0_251]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_251]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_251]
	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50) ~[junit-4.12.jar:4.12]
	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12) ~[junit-4.12.jar:4.12]
	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47) ~[junit-4.12.jar:4.12]
	at com.hazelcast.test.AbstractHazelcastClassRunner$ThreadDumpAwareRunAfters.evaluate(AbstractHazelcastClassRunner.java:404) ~[hazelcast-4.0.3-tests.jar:4.0.3]
	at com.hazelcast.test.DumpBuildInfoOnFailureRule$1.evaluate(DumpBuildInfoOnFailureRule.java:37) ~[hazelcast-4.0.3-tests.jar:4.0.3]
	at com.hazelcast.test.jitter.JitterRule$1.evaluate(JitterRule.java:104) ~[hazelcast-4.0.3-tests.jar:4.0.3]
	at com.hazelcast.test.metrics.MetricsRule$1.evaluate(MetricsRule.java:62) ~[hazelcast-4.0.3-tests.jar:4.0.3]
	at org.junit.rules.RunRules.evaluate(RunRules.java:20) ~[junit-4.12.jar:4.12]
	at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325) ~[junit-4.12.jar:4.12]
	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78) ~[junit-4.12.jar:4.12]
	at com.hazelcast.test.HazelcastSerialClassRunner.runChild(HazelcastSerialClassRunner.java:50) ~[hazelcast-4.0.3-tests.jar:4.0.3]
	at com.hazelcast.test.HazelcastSerialClassRunner.runChild(HazelcastSerialClassRunner.java:29) ~[hazelcast-4.0.3-tests.jar:4.0.3]
	at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290) ~[junit-4.12.jar:4.12]
	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71) ~[junit-4.12.jar:4.12]
	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288) ~[junit-4.12.jar:4.12]
	at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58) ~[junit-4.12.jar:4.12]
	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268) ~[junit-4.12.jar:4.12]
	at com.hazelcast.test.AbstractHazelcastClassRunner$1.evaluate(AbstractHazelcastClassRunner.java:301) ~[hazelcast-4.0.3-tests.jar:4.0.3]
	at org.junit.internal.runners.statements.FailOnTimeout$CallableStatement.call(FailOnTimeout.java:298) ~[junit-4.12.jar:4.12]
	at org.junit.internal.runners.statements.FailOnTimeout$CallableStatement.call(FailOnTimeout.java:292) ~[junit-4.12.jar:4.12]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[?:1.8.0_251]
	... 1 more
2020-09-30 23:29:58,190 [ WARN] [hz.festive_moser.jet.cooperative.thread-10] [c.h.s.i.o.i.OutboundResponseHandler]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Cannot send response: java.util.concurrent.CancellationException to [127.0.0.1]:5701. com.hazelcast.jet.impl.operation.StartExecutionOperation{serviceName='hz:impl:jetService', identityHash=234429781, partitionId=-1, replicaIndex=0, callId=61786, invocationTime=1601508537211 (2020-09-30 23:28:57.211), waitTimeout=-1, callTimeout=2000}
2020-09-30 23:29:58,190 [DEBUG] [hz.festive_moser.jet.cooperative.thread-10] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Completing job '050c-9518-9c9e-0001', execution 050c-9518-9c9f-0001 locally. Reason: Node is shutting down
2020-09-30 23:29:58,191 [DEBUG] [hz.festive_moser.jet.cooperative.thread-10] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Completed execution of job '050c-9518-9c9e-0001', execution 050c-9518-9c9f-0001
2020-09-30 23:29:58,203 [ INFO] [Time-limited test] [c.h.i.i.NodeExtension]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Destroying node NodeExtension.
2020-09-30 23:29:58,204 [ INFO] [Time-limited test] [c.h.i.i.Node]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Hazelcast Shutdown is completed in 217 ms.
2020-09-30 23:29:58,204 [ INFO] [Time-limited test] [c.h.c.LifecycleService]: [127.0.0.1]:5702 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] [127.0.0.1]:5702 is SHUTDOWN
2020-09-30 23:29:58,204 [ INFO] [Time-limited test] [c.h.c.LifecycleService]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] [127.0.0.1]:5701 is SHUTTING_DOWN
2020-09-30 23:29:58,206 [ INFO] [hz.unruffled_moser.cached.thread-8] [c.h.i.p.i.MigrationManager]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Shutdown request of Member [127.0.0.1]:5701 - e487092b-9b7d-4c5c-ac9f-67a2db8bd515 this is handled
2020-09-30 23:29:58,206 [ INFO] [Time-limited test] [c.h.i.i.Node]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Shutting down multicast service...
2020-09-30 23:29:58,206 [ INFO] [hz.unruffled_moser.cached.thread-10] [c.h.i.n.t.TcpIpConnector]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5702, timeout: 10000, bind-any: true
2020-09-30 23:29:58,206 [ INFO] [Time-limited test] [c.h.i.i.Node]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Shutting down connection manager...
2020-09-30 23:29:58,208 [ INFO] [hz.unruffled_moser.cached.thread-10] [c.h.i.n.t.TcpIpConnector]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5702. Reason: SocketException[Connection refused to address /127.0.0.1:5702]
2020-09-30 23:29:58,208 [ INFO] [hz.unruffled_moser.cached.thread-10] [c.h.i.c.i.MulticastJoiner]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] [127.0.0.1]:5702 is added to the blacklist.
2020-09-30 23:29:58,208 [ INFO] [Time-limited test] [c.h.i.i.Node]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Shutting down node engine...
2020-09-30 23:29:58,210 [DEBUG] [Time-limited test] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Completing job '050c-9518-9c9e-0001', execution 050c-9518-9c9f-0001 locally. Reason: Node is shutting down
2020-09-30 23:29:58,210 [DEBUG] [Time-limited test] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Completed execution of job '050c-9518-9c9e-0001', execution 050c-9518-9c9f-0001
2020-09-30 23:29:58,213 [DEBUG] [ForkJoinPool.commonPool-worker-61] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Execution of job '050c-9518-9c9e-0001', execution 050c-9518-9c9f-0001 has failures: [[127.0.0.1]:5702=com.hazelcast.core.HazelcastInstanceNotActiveException: Hazelcast instance is not active!]
2020-09-30 23:29:58,213 [DEBUG] [hz.unruffled_moser.cached.thread-10] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Sending CompleteExecutionOperation for job '050c-9518-9c9e-0001', execution 050c-9518-9c9f-0001
2020-09-30 23:29:58,214 [ERROR] [ForkJoinPool.commonPool-worker-61] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] job '050c-9518-9c9e-0001', execution 050c-9518-9c9f-0001: some TerminateExecutionOperation invocations failed, execution might remain stuck: [MemberInfo{address=[127.0.0.1]:5702, uuid=ddac6c6e-b5aa-4c60-bd7f-4521e04a0b4e, liteMember=false, memberListJoinVersion=2}=com.hazelcast.core.HazelcastInstanceNotActiveException: Hazelcast instance is not active!, MemberInfo{address=[127.0.0.1]:5701, uuid=e487092b-9b7d-4c5c-ac9f-67a2db8bd515, liteMember=false, memberListJoinVersion=1}=com.hazelcast.core.HazelcastInstanceNotActiveException: Hazelcast instance is not active!]
2020-09-30 23:29:58,214 [ERROR] [ForkJoinPool.commonPool-worker-16] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] job '050c-9518-9c9e-0001', execution 050c-9518-9c9f-0001: some CompleteExecutionOperation invocations failed, execution resources might leak: [MemberInfo{address=[127.0.0.1]:5702, uuid=ddac6c6e-b5aa-4c60-bd7f-4521e04a0b4e, liteMember=false, memberListJoinVersion=2}=com.hazelcast.core.HazelcastInstanceNotActiveException: Hazelcast instance is not active!, MemberInfo{address=[127.0.0.1]:5701, uuid=e487092b-9b7d-4c5c-ac9f-67a2db8bd515, liteMember=false, memberListJoinVersion=1}=com.hazelcast.core.HazelcastInstanceNotActiveException: Hazelcast instance is not active!]
2020-09-30 23:29:58,214 [DEBUG] [hz.unruffled_moser.cached.thread-10] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Scheduling restart on master for job 050c-9518-9c9e-0001
2020-09-30 23:29:58,222 [ INFO] [Time-limited test] [c.h.i.i.NodeExtension]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Destroying node NodeExtension.
2020-09-30 23:29:58,222 [ INFO] [Time-limited test] [c.h.i.i.Node]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] Hazelcast Shutdown is completed in 16 ms.
2020-09-30 23:29:58,223 [ INFO] [Time-limited test] [c.h.c.LifecycleService]: [127.0.0.1]:5701 [3fcd810d-269a-488a-8069-1552c80aeaa5] [4.4-SNAPSHOT] [127.0.0.1]:5701 is SHUTDOWN
BuildInfo right after test(com.hazelcast.jet.core.MemberReconnectionStressTest): BuildInfo{version='4.0.3', build='20200921', buildNumber=20200921, revision=59ae831, enterprise=false, serializationVersion=1, jet=JetBuildInfo{version='4.4-SNAPSHOT', build='20200930', revision='c2ed875'}}
Hiccups measured while running test 'test(com.hazelcast.jet.core.MemberReconnectionStressTest):'
23:28:35, accumulated pauses: 27 ms, max pause: 0 ms, pauses over 1000 ms: 0
23:28:40, accumulated pauses: 26 ms, max pause: 2 ms, pauses over 1000 ms: 0
23:28:45, accumulated pauses: 25 ms, max pause: 1 ms, pauses over 1000 ms: 0
23:28:50, accumulated pauses: 61 ms, max pause: 19 ms, pauses over 1000 ms: 0
23:28:55, accumulated pauses: 22 ms, max pause: 0 ms, pauses over 1000 ms: 0
23:29:00, accumulated pauses: 23 ms, max pause: 0 ms, pauses over 1000 ms: 0
23:29:05, accumulated pauses: 30 ms, max pause: 1 ms, pauses over 1000 ms: 0
23:29:10, accumulated pauses: 42 ms, max pause: 8 ms, pauses over 1000 ms: 0
23:29:15, accumulated pauses: 26 ms, max pause: 2 ms, pauses over 1000 ms: 0
23:29:20, accumulated pauses: 27 ms, max pause: 2 ms, pauses over 1000 ms: 0
23:29:25, accumulated pauses: 52 ms, max pause: 25 ms, pauses over 1000 ms: 0
23:29:30, accumulated pauses: 22 ms, max pause: 0 ms, pauses over 1000 ms: 0
23:29:35, accumulated pauses: 22 ms, max pause: 0 ms, pauses over 1000 ms: 0
23:29:40, accumulated pauses: 22 ms, max pause: 0 ms, pauses over 1000 ms: 0
23:29:45, accumulated pauses: 23 ms, max pause: 0 ms, pauses over 1000 ms: 0
23:29:50, accumulated pauses: 22 ms, max pause: 0 ms, pauses over 1000 ms: 0
23:29:55, accumulated pauses: 164 ms, max pause: 140 ms, pauses over 1000 ms: 0

Oct 13 '20 12:10 olukas

It started to fail quite often, another fail is for example here: http://jenkins.hazelcast.com/job/jet-oss-master-sonar-nightly/658/testReport/junit/com.hazelcast.jet.core/MemberReconnectionStressTest/test/

Oct 23 '20 16:10 olukas

In the run from the Oct 23 the logged events were this:

2020-10-23 13:21:19,675 [DEBUG] [hz.boring_hellman.cached.thread-13] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [1ec5ecfd-48b0-4fdf-962a-3e09a8dc53a6] [4.4-SNAPSHOT] Executing job '0529-a68f-6da9-0001', execution 0529-a68f-6daa-0001
2020-10-23 13:21:19,675 [ INFO] [hz.boring_hellman.cached.thread-13] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [1ec5ecfd-48b0-4fdf-962a-3e09a8dc53a6] [4.4-SNAPSHOT] Start execution of job '0529-a68f-6da9-0001', execution 0529-a68f-6daa-0001 from coordinator [127.0.0.1]:5701
2020-10-23 13:21:19,675 [ INFO] [hz.focused_hellman.generic-operation.thread-1] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5702 [1ec5ecfd-48b0-4fdf-962a-3e09a8dc53a6] [4.4-SNAPSHOT] Start execution of job '0529-a68f-6da9-0001', execution 0529-a68f-6daa-0001 from coordinator [127.0.0.1]:5701
2020-10-23 13:21:19,675 [ WARN] [Thread-1225] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5701 [1ec5ecfd-48b0-4fdf-962a-3e09a8dc53a6] [4.4-SNAPSHOT] Connection[id=241, /127.0.0.1:60243->/127.0.0.1:5702, qualifier=null, endpoint=[127.0.0.1]:5702, alive=false, connectionType=MEMBER] closed. Reason: test
java.lang.Exception: test failure
	at com.hazelcast.jet.core.MemberReconnectionStressTest.lambda$test$0(MemberReconnectionStressTest.java:84) ~[test-classes/:?]
	at java.lang.Thread.run(Thread.java:834) [?:?]
2020-10-23 13:21:19,675 [ INFO] [hz.focused_hellman.IO.thread-in-0] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5702 [1ec5ecfd-48b0-4fdf-962a-3e09a8dc53a6] [4.4-SNAPSHOT] Connection[id=241, /127.0.0.1:5702->/127.0.0.1:60243, qualifier=null, endpoint=[127.0.0.1]:5701, alive=false, connectionType=MEMBER] closed. Reason: Connection closed by the other side
2020-10-23 13:21:19,675 [ INFO] [Thread-1225] [c.h.j.c.MemberReconnectionStressTest]: connection closed
2020-10-23 13:21:19,676 [ INFO] [hz.boring_hellman.cached.thread-3] [c.h.i.n.t.TcpIpConnector]: [127.0.0.1]:5701 [1ec5ecfd-48b0-4fdf-962a-3e09a8dc53a6] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5702, timeout: 10000, bind-any: true
2020-10-23 13:21:19,676 [ INFO] [hz.focused_hellman.IO.thread-in-1] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5702 [1ec5ecfd-48b0-4fdf-962a-3e09a8dc53a6] [4.4-SNAPSHOT] Initialized new cluster connection between /127.0.0.1:5702 and /127.0.0.1:57847
2020-10-23 13:21:19,676 [ INFO] [hz.boring_hellman.IO.thread-in-1] [c.h.i.n.t.TcpIpConnection]: [127.0.0.1]:5701 [1ec5ecfd-48b0-4fdf-962a-3e09a8dc53a6] [4.4-SNAPSHOT] Initialized new cluster connection between /127.0.0.1:57847 and /127.0.0.1:5702
2020-10-23 13:21:19,677 [DEBUG] [hz.boring_hellman.jet.cooperative.thread-46] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [1ec5ecfd-48b0-4fdf-962a-3e09a8dc53a6] [4.4-SNAPSHOT] Execution of job '0529-a68f-6da9-0001', execution 0529-a68f-6daa-0001 completed

That is, the master sent the StartExecutionOp, both member received it, started the execution. 0ms later the connection was dropped. 2ms later member1 completed the execution. bit member2 didn't. 48.5 seconds later member1 (the master) completed the job because the node was shutting down. 20 ms later, member 2 logged:

2020-10-23 13:22:08,138 [DEBUG] [hz.focused_hellman.jet.blocking.thread-3] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5702 [1ec5ecfd-48b0-4fdf-962a-3e09a8dc53a6] [4.4-SNAPSHOT] Execution of job '0529-a68f-6da9-0001', execution 0529-a68f-6daa-0001 completed with failure
java.util.concurrent.CompletionException: com.hazelcast.jet.JetException: Exception in ReceiverTasklet: com.hazelcast.jet.RestartableException: The member was reconnected: [127.0.0.1]:5701

So it seems the ReceiverTasklet was running, but didn't detect the connection change. A the end of the day I had one failure locally, which greatly increases the chances of fixing the issue. I'll continue tomorrow.

Nov 30 '20 16:11 viliam-durina

Fixed one cause in #2722, see description there. But I observed different causes too, I expect more failures in the future.

Dec 01 '20 15:12 viliam-durina

Reopening, it failed again on nightly build with Oracle JDK 8: http://jenkins.hazelcast.com/job/jet-oss-master-nightly-oracle-jdk8/369/testReport/junit/com.hazelcast.jet.core/MemberReconnectionStressTest/test/

Stacktrace:

java.lang.AssertionError: jobCount didn't increment for 30 seconds
	at org.junit.Assert.fail(Assert.java:89)
	at com.hazelcast.jet.core.MemberReconnectionStressTest.test(MemberReconnectionStressTest.java:118)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:59)
	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:56)
	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
	at com.hazelcast.test.FailOnTimeoutStatement$CallableStatement.call(FailOnTimeoutStatement.java:114)
	at com.hazelcast.test.FailOnTimeoutStatement$CallableStatement.call(FailOnTimeoutStatement.java:106)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	at java.lang.Thread.run(Thread.java:748)

Standard output:

2021-01-12 01:45:14,187 [ INFO] [test] [c.h.i.m.i.MetricsConfigHelper]: [LOCAL] [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Overridden metrics configuration with system property 'hazelcast.metrics.collection.frequency'='1' -> 'MetricsConfig.collectionFrequencySeconds'='1'
2021-01-12 01:45:14,191 [ INFO] [test] [c.h.system]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Hazelcast Jet 4.4-SNAPSHOT (20210112 - 2d6bcac) starting at [127.0.0.1]:5701
2021-01-12 01:45:14,191 [ INFO] [test] [c.h.system]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Based on Hazelcast IMDG version: 4.1.1 (20201222 - 27af558)
2021-01-12 01:45:14,191 [ INFO] [test] [c.h.system]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Cluster name: 2557e9dc-121a-4358-969d-64d904f70fb5
2021-01-12 01:45:14,191 [ INFO] [test] [c.h.system]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] 
	o   o   o   o---o o---o o     o---o   o   o---o o-o-o        o o---o o-o-o
	|   |  / \     /  |     |     |      / \  |       |          | |       |
	o---o o---o   o   o-o   |     o     o---o o---o   |          | o-o     |
	|   | |   |  /    |     |     |     |   |     |   |      \   | |       |
	o   o o   o o---o o---o o---o o---o o   o o---o   o       o--o o---o   o
2021-01-12 01:45:14,191 [ INFO] [test] [c.h.system]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Copyright (c) 2008-2020, Hazelcast, Inc. All Rights Reserved.
2021-01-12 01:45:14,195 [ INFO] [test] [c.h.i.m.i.MetricsConfigHelper]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Collecting debug metrics and sending to diagnostics is enabled
2021-01-12 01:45:14,201 [ INFO] [test] [c.h.s.d.i.DiscoveryService]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] No discovery strategy is applicable for auto-detection
2021-01-12 01:45:14,202 [ WARN] [test] [c.h.i.i.Node]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Hazelcast is bound to 127.0.0.1 and loop-back mode is disabled in the configuration. This could cause multicast auto-discovery issues and render it unable to work. Check your network connectivity, try to enable the loopback mode and/or force -Djava.net.preferIPv4Stack=true on your JVM.
2021-01-12 01:45:14,202 [ INFO] [test] [c.h.i.i.Node]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Using Multicast discovery
2021-01-12 01:45:14,202 [ WARN] [test] [c.h.c.CPSubsystem]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] CP Subsystem is not enabled. CP data structures will operate in UNSAFE mode! Please note that UNSAFE mode will not provide strong consistency guarantees.
2021-01-12 01:45:14,207 [ INFO] [test] [c.h.j.i.e.TaskletExecutionService]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Creating idler with jet.idle.cooperative.min.microseconds=25?s,jet.idle.cooperative.max.microseconds=500?s
2021-01-12 01:45:14,207 [ INFO] [test] [c.h.j.i.e.TaskletExecutionService]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Creating idler with jet.idle.noncooperative.min.microseconds=25?s,jet.idle.noncooperative.max.microseconds=5000?s
2021-01-12 01:45:14,212 [ INFO] [test] [c.h.j.i.JetService]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Setting number of cooperative threads and default parallelism to 72
2021-01-12 01:45:14,222 [ INFO] [test] [c.h.i.d.Diagnostics]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Diagnostics disabled. To enable add -Dhazelcast.diagnostics.enabled=true to the JVM arguments.
2021-01-12 01:45:14,222 [ INFO] [test] [c.h.c.LifecycleService]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] [127.0.0.1]:5701 is STARTING
2021-01-12 01:45:16,716 [ INFO] [test] [c.h.i.c.ClusterService]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] 

Members {size:1, ver:1} [
	Member [127.0.0.1]:5701 - 3fb9bfa6-908c-409f-8625-d7c1ff21b83b this
]

2021-01-12 01:45:16,716 [DEBUG] [hz.infallible_turing.cached.thread-5] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Not starting jobs because partitions are not yet initialized.
2021-01-12 01:45:16,716 [ INFO] [test] [c.h.c.LifecycleService]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] [127.0.0.1]:5701 is STARTED
2021-01-12 01:45:16,717 [ INFO] [test] [c.h.i.m.i.MetricsConfigHelper]: [LOCAL] [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Overridden metrics configuration with system property 'hazelcast.metrics.collection.frequency'='1' -> 'MetricsConfig.collectionFrequencySeconds'='1'
2021-01-12 01:45:16,718 [ INFO] [test] [c.h.system]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Hazelcast Jet 4.4-SNAPSHOT (20210112 - 2d6bcac) starting at [127.0.0.1]:5702
2021-01-12 01:45:16,718 [ INFO] [test] [c.h.system]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Based on Hazelcast IMDG version: 4.1.1 (20201222 - 27af558)
2021-01-12 01:45:16,718 [ INFO] [test] [c.h.system]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Cluster name: 2557e9dc-121a-4358-969d-64d904f70fb5
2021-01-12 01:45:16,718 [ INFO] [test] [c.h.system]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] 
	o   o   o   o---o o---o o     o---o   o   o---o o-o-o        o o---o o-o-o
	|   |  / \     /  |     |     |      / \  |       |          | |       |
	o---o o---o   o   o-o   |     o     o---o o---o   |          | o-o     |
	|   | |   |  /    |     |     |     |   |     |   |      \   | |       |
	o   o o   o o---o o---o o---o o---o o   o o---o   o       o--o o---o   o
2021-01-12 01:45:16,718 [ INFO] [test] [c.h.system]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Copyright (c) 2008-2020, Hazelcast, Inc. All Rights Reserved.
2021-01-12 01:45:16,721 [ INFO] [test] [c.h.i.m.i.MetricsConfigHelper]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Collecting debug metrics and sending to diagnostics is enabled
2021-01-12 01:45:16,725 [ INFO] [test] [c.h.s.d.i.DiscoveryService]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] No discovery strategy is applicable for auto-detection
2021-01-12 01:45:16,726 [ WARN] [test] [c.h.i.i.Node]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Hazelcast is bound to 127.0.0.1 and loop-back mode is disabled in the configuration. This could cause multicast auto-discovery issues and render it unable to work. Check your network connectivity, try to enable the loopback mode and/or force -Djava.net.preferIPv4Stack=true on your JVM.
2021-01-12 01:45:16,726 [ INFO] [test] [c.h.i.i.Node]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Using Multicast discovery
2021-01-12 01:45:16,726 [ WARN] [test] [c.h.c.CPSubsystem]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] CP Subsystem is not enabled. CP data structures will operate in UNSAFE mode! Please note that UNSAFE mode will not provide strong consistency guarantees.
2021-01-12 01:45:16,730 [ INFO] [test] [c.h.j.i.e.TaskletExecutionService]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Creating idler with jet.idle.cooperative.min.microseconds=25?s,jet.idle.cooperative.max.microseconds=500?s
2021-01-12 01:45:16,730 [ INFO] [test] [c.h.j.i.e.TaskletExecutionService]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Creating idler with jet.idle.noncooperative.min.microseconds=25?s,jet.idle.noncooperative.max.microseconds=5000?s
2021-01-12 01:45:16,735 [ INFO] [test] [c.h.j.i.JetService]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Setting number of cooperative threads and default parallelism to 72
2021-01-12 01:45:16,747 [ INFO] [test] [c.h.i.d.Diagnostics]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Diagnostics disabled. To enable add -Dhazelcast.diagnostics.enabled=true to the JVM arguments.
2021-01-12 01:45:16,747 [ INFO] [test] [c.h.c.LifecycleService]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] [127.0.0.1]:5702 is STARTING
2021-01-12 01:45:16,816 [DEBUG] [hz.infallible_turing.cached.thread-5] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Not starting jobs because partitions are not yet initialized.
2021-01-12 01:45:16,849 [ INFO] [test] [c.h.i.c.i.MulticastJoiner]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Trying to join to discovered node: [127.0.0.1]:5701
2021-01-12 01:45:16,853 [ INFO] [hz.infallible_turing.IO.thread-in-0] [c.h.i.s.t.TcpServerConnection]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Initialized new cluster connection between /127.0.0.1:5701 and /127.0.0.1:39810
2021-01-12 01:45:16,854 [ INFO] [hz.vigorous_turing.IO.thread-in-0] [c.h.i.s.t.TcpServerConnection]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Initialized new cluster connection between /0.0.0.0:39810 and /127.0.0.1:5701
2021-01-12 01:45:16,917 [DEBUG] [hz.infallible_turing.cached.thread-5] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Not starting jobs because partitions are not yet initialized.
2021-01-12 01:45:17,017 [DEBUG] [hz.infallible_turing.cached.thread-5] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Not starting jobs because partitions are not yet initialized.
2021-01-12 01:45:17,117 [DEBUG] [hz.infallible_turing.cached.thread-5] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Not starting jobs because partitions are not yet initialized.
2021-01-12 01:45:17,217 [DEBUG] [hz.infallible_turing.cached.thread-5] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Not starting jobs because partitions are not yet initialized.
2021-01-12 01:45:17,317 [DEBUG] [hz.infallible_turing.cached.thread-5] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Not starting jobs because partitions are not yet initialized.
2021-01-12 01:45:17,417 [DEBUG] [hz.infallible_turing.cached.thread-5] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Not starting jobs because partitions are not yet initialized.
2021-01-12 01:45:17,517 [DEBUG] [hz.infallible_turing.cached.thread-5] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Not starting jobs because partitions are not yet initialized.
2021-01-12 01:45:17,617 [DEBUG] [hz.infallible_turing.cached.thread-5] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Not starting jobs because partitions are not yet initialized.
2021-01-12 01:45:17,718 [DEBUG] [hz.infallible_turing.cached.thread-6] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Not starting jobs because partitions are not yet initialized.
2021-01-12 01:45:17,818 [DEBUG] [hz.infallible_turing.cached.thread-6] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Not starting jobs because partitions are not yet initialized.
2021-01-12 01:45:17,918 [DEBUG] [hz.infallible_turing.cached.thread-6] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Not starting jobs because partitions are not yet initialized.
2021-01-12 01:45:18,018 [DEBUG] [hz.infallible_turing.cached.thread-6] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Not starting jobs because partitions are not yet initialized.
2021-01-12 01:45:18,118 [DEBUG] [hz.infallible_turing.cached.thread-6] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Not starting jobs because partitions are not yet initialized.
2021-01-12 01:45:18,218 [DEBUG] [hz.infallible_turing.cached.thread-6] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Not starting jobs because partitions are not yet initialized.
2021-01-12 01:45:18,318 [DEBUG] [hz.infallible_turing.cached.thread-6] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Not starting jobs because partitions are not yet initialized.
2021-01-12 01:45:18,418 [DEBUG] [hz.infallible_turing.cached.thread-6] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Not starting jobs because partitions are not yet initialized.
2021-01-12 01:45:18,518 [DEBUG] [hz.infallible_turing.cached.thread-6] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Not starting jobs because partitions are not yet initialized.
2021-01-12 01:45:18,619 [DEBUG] [hz.infallible_turing.cached.thread-6] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Not starting jobs because partitions are not yet initialized.
2021-01-12 01:45:18,719 [DEBUG] [hz.infallible_turing.cached.thread-1] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Not starting jobs because partitions are not yet initialized.
2021-01-12 01:45:18,819 [DEBUG] [hz.infallible_turing.cached.thread-1] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Not starting jobs because partitions are not yet initialized.
2021-01-12 01:45:18,854 [ INFO] [hz.infallible_turing.priority-generic-operation.thread-0] [c.h.i.c.ClusterService]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] 

Members {size:2, ver:2} [
	Member [127.0.0.1]:5701 - 3fb9bfa6-908c-409f-8625-d7c1ff21b83b this
	Member [127.0.0.1]:5702 - bdb6555f-a375-4302-a04f-45fe633480ba
]

2021-01-12 01:45:18,855 [ INFO] [hz.vigorous_turing.priority-generic-operation.thread-0] [c.h.i.c.ClusterService]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] 

Members {size:2, ver:2} [
	Member [127.0.0.1]:5701 - 3fb9bfa6-908c-409f-8625-d7c1ff21b83b
	Member [127.0.0.1]:5702 - bdb6555f-a375-4302-a04f-45fe633480ba this
]

2021-01-12 01:45:18,919 [DEBUG] [hz.infallible_turing.cached.thread-5] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Not starting jobs because partitions are not yet initialized.
2021-01-12 01:45:19,019 [DEBUG] [hz.infallible_turing.cached.thread-5] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Not starting jobs because partitions are not yet initialized.
2021-01-12 01:45:19,119 [DEBUG] [hz.infallible_turing.cached.thread-5] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Not starting jobs because partitions are not yet initialized.
2021-01-12 01:45:19,219 [DEBUG] [hz.infallible_turing.cached.thread-5] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Not starting jobs because partitions are not yet initialized.
2021-01-12 01:45:19,319 [DEBUG] [hz.infallible_turing.cached.thread-5] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Not starting jobs because partitions are not yet initialized.
2021-01-12 01:45:19,419 [DEBUG] [hz.infallible_turing.cached.thread-5] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Not starting jobs because partitions are not yet initialized.
2021-01-12 01:45:19,519 [DEBUG] [hz.infallible_turing.cached.thread-5] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Not starting jobs because partitions are not yet initialized.
2021-01-12 01:45:19,620 [DEBUG] [hz.infallible_turing.cached.thread-5] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Not starting jobs because partitions are not yet initialized.
2021-01-12 01:45:19,720 [DEBUG] [hz.infallible_turing.cached.thread-2] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Not starting jobs because partitions are not yet initialized.
2021-01-12 01:45:19,820 [DEBUG] [hz.infallible_turing.cached.thread-2] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Not starting jobs because partitions are not yet initialized.
2021-01-12 01:45:19,859 [ INFO] [test] [c.h.c.LifecycleService]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] [127.0.0.1]:5702 is STARTED
2021-01-12 01:45:19,859 [ INFO] [test] [c.h.j.c.MemberReconnectionStressTest]: Instances started
2021-01-12 01:45:19,863 [ INFO] [hz.infallible_turing.cached.thread-2] [c.h.i.p.i.PartitionStateManager]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Initializing cluster partition table arrangement...
2021-01-12 01:45:19,865 [ WARN] [Thread-40] [c.h.i.s.t.TcpServerConnection]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connection[id=1, /127.0.0.1:5701->/127.0.0.1:39810, qualifier=null, endpoint=[127.0.0.1]:5702, alive=false, connectionType=MEMBER, planeIndex=0] closed. Reason: test
java.lang.Exception: test failure
	at com.hazelcast.jet.core.MemberReconnectionStressTest.lambda$test$0(MemberReconnectionStressTest.java:84) ~[test-classes/:?]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_251]
2021-01-12 01:45:19,868 [ INFO] [Thread-40] [c.h.j.c.MemberReconnectionStressTest]: connection closed
2021-01-12 01:45:19,869 [ INFO] [hz.vigorous_turing.IO.thread-in-0] [c.h.i.s.t.TcpServerConnection]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connection[id=1, /0.0.0.0:39810->/127.0.0.1:5701, qualifier=null, endpoint=[127.0.0.1]:5701, alive=false, connectionType=MEMBER, planeIndex=0] closed. Reason: Connection closed by the other side
2021-01-12 01:45:19,870 [ INFO] [hz.vigorous_turing.cached.thread-3] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:45:19,870 [ INFO] [hz.infallible_turing.IO.thread-in-1] [c.h.i.s.t.TcpServerConnection]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Initialized new cluster connection between /127.0.0.1:5701 and /127.0.0.1:45271
2021-01-12 01:45:19,870 [ INFO] [hz.vigorous_turing.IO.thread-in-1] [c.h.i.s.t.TcpServerConnection]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Initialized new cluster connection between /0.0.0.0:45271 and /127.0.0.1:5701
2021-01-12 01:45:19,871 [ INFO] [hz.infallible_turing.cached.thread-5] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5702, timeout: 10000, bind-any: true
2021-01-12 01:45:19,874 [ INFO] [hz.vigorous_turing.IO.thread-in-2] [c.h.i.s.t.TcpServerConnection]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Initialized new cluster connection between /127.0.0.1:5702 and /127.0.0.1:37218
2021-01-12 01:45:19,874 [ INFO] [hz.infallible_turing.IO.thread-in-2] [c.h.i.s.t.TcpServerConnection]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Initialized new cluster connection between /0.0.0.0:37218 and /127.0.0.1:5702
2021-01-12 01:45:19,926 [DEBUG] [hz.infallible_turing.cached.thread-5] [c.h.j.i.JobRepository]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Job cleanup took 1ms
2021-01-12 01:45:19,972 [ INFO] [hz.infallible_turing.cached.thread-2] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Starting job 0591-5010-bd40-0001 based on submit request
2021-01-12 01:45:19,974 [ INFO] [hz.infallible_turing.cached.thread-2] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Didn't find any snapshot to restore for job '0591-5010-bd40-0001', execution 0591-5010-bd41-0001
2021-01-12 01:45:19,974 [ INFO] [hz.infallible_turing.cached.thread-2] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Start executing job '0591-5010-bd40-0001', execution 0591-5010-bd41-0001, execution graph in DOT format:
digraph DAG {
	"v1" [localParallelism=2];
	"v2" [localParallelism=2];
	"v1" -> "v2" [label="distributed", queueSize=1024];
}
HINT: You can use graphviz or http://viz-js.com to visualize the printed graph.
2021-01-12 01:45:19,974 [DEBUG] [hz.infallible_turing.cached.thread-2] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Building execution plan for job '0591-5010-bd40-0001', execution 0591-5010-bd41-0001
2021-01-12 01:45:19,975 [DEBUG] [hz.infallible_turing.cached.thread-2] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Built execution plans for job '0591-5010-bd40-0001', execution 0591-5010-bd41-0001
2021-01-12 01:45:19,976 [DEBUG] [hz.infallible_turing.cached.thread-2] [c.h.j.i.o.InitExecutionOperation]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Initializing execution plan for job 0591-5010-bd40-0001, execution 0591-5010-bd41-0001 from [127.0.0.1]:5701
2021-01-12 01:45:19,978 [ INFO] [hz.infallible_turing.cached.thread-2] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Execution plan for jobId=0591-5010-bd40-0001, jobName='0591-5010-bd40-0001', executionId=0591-5010-bd41-0001 initialized
2021-01-12 01:45:19,978 [DEBUG] [hz.vigorous_turing.generic-operation.thread-8] [c.h.j.i.o.InitExecutionOperation]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Initializing execution plan for job 0591-5010-bd40-0001, execution 0591-5010-bd41-0001 from [127.0.0.1]:5701
2021-01-12 01:45:19,979 [ INFO] [hz.vigorous_turing.generic-operation.thread-8] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Execution plan for jobId=0591-5010-bd40-0001, jobName='0591-5010-bd40-0001', executionId=0591-5010-bd41-0001 initialized
2021-01-12 01:45:19,979 [DEBUG] [hz.infallible_turing.cached.thread-2] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Init of job '0591-5010-bd40-0001', execution 0591-5010-bd41-0001 was successful
2021-01-12 01:45:19,979 [DEBUG] [hz.infallible_turing.cached.thread-2] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Executing job '0591-5010-bd40-0001', execution 0591-5010-bd41-0001
2021-01-12 01:45:19,979 [ INFO] [hz.infallible_turing.cached.thread-2] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Start execution of job '0591-5010-bd40-0001', execution 0591-5010-bd41-0001 from coordinator [127.0.0.1]:5701
2021-01-12 01:45:19,980 [ INFO] [hz.vigorous_turing.generic-operation.thread-9] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Start execution of job '0591-5010-bd40-0001', execution 0591-5010-bd41-0001 from coordinator [127.0.0.1]:5701
2021-01-12 01:45:19,981 [DEBUG] [hz.vigorous_turing.jet.cooperative.thread-1] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Execution of job '0591-5010-bd40-0001', execution 0591-5010-bd41-0001 completed
2021-01-12 01:45:19,982 [DEBUG] [hz.infallible_turing.jet.cooperative.thread-2] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Execution of job '0591-5010-bd40-0001', execution 0591-5010-bd41-0001 completed
2021-01-12 01:45:19,982 [DEBUG] [ForkJoinPool.commonPool-worker-75] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Execution of job '0591-5010-bd40-0001', execution 0591-5010-bd41-0001 was successful
2021-01-12 01:45:19,982 [DEBUG] [hz.infallible_turing.cached.thread-2] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Sending CompleteExecutionOperation for job '0591-5010-bd40-0001', execution 0591-5010-bd41-0001
2021-01-12 01:45:19,982 [DEBUG] [hz.infallible_turing.cached.thread-2] [c.h.j.i.o.CompleteExecutionOperation]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Completing execution 0591-5010-bd41-0001 from caller [127.0.0.1]:5701, error=null
2021-01-12 01:45:19,983 [DEBUG] [hz.infallible_turing.cached.thread-2] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Completed execution of job '0591-5010-bd40-0001', execution 0591-5010-bd41-0001
2021-01-12 01:45:19,983 [DEBUG] [hz.vigorous_turing.generic-operation.thread-10] [c.h.j.i.o.CompleteExecutionOperation]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Completing execution 0591-5010-bd41-0001 from caller [127.0.0.1]:5701, error=null
2021-01-12 01:45:19,983 [DEBUG] [hz.vigorous_turing.generic-operation.thread-10] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Completed execution of job '0591-5010-bd40-0001', execution 0591-5010-bd41-0001
2021-01-12 01:45:19,983 [ INFO] [hz.infallible_turing.cached.thread-2] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Execution of job '0591-5010-bd40-0001', execution 0591-5010-bd41-0001 completed successfully
	Start time: 2021-01-12T01:45:19.973
	Duration: 00:00:00.010
	To see additional job metrics enable JobConfig.storeMetricsAfterJobCompletion
2021-01-12 01:45:19,983 [DEBUG] [hz.infallible_turing.cached.thread-2] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] job '0591-5010-bd40-0001', execution 0591-5010-bd41-0001 is completed
2021-01-12 01:45:19,984 [ INFO] [Thread-41] [c.h.j.c.MemberReconnectionStressTest]: job completed
2021-01-12 01:45:19,985 [ INFO] [hz.infallible_turing.cached.thread-4] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Starting job 0591-5010-bd42-0001 based on submit request
2021-01-12 01:45:19,986 [ INFO] [hz.infallible_turing.cached.thread-4] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Didn't find any snapshot to restore for job '0591-5010-bd42-0001', execution 0591-5010-bd43-0001
2021-01-12 01:45:19,986 [ INFO] [hz.infallible_turing.cached.thread-4] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Start executing job '0591-5010-bd42-0001', execution 0591-5010-bd43-0001, execution graph in DOT format:
digraph DAG {
	"v1" [localParallelism=2];
	"v2" [localParallelism=2];
	"v1" -> "v2" [label="distributed", queueSize=1024];
}
HINT: You can use graphviz or http://viz-js.com to visualize the printed graph.
2021-01-12 01:45:19,986 [DEBUG] [hz.infallible_turing.cached.thread-4] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Building execution plan for job '0591-5010-bd42-0001', execution 0591-5010-bd43-0001
2021-01-12 01:45:19,986 [DEBUG] [hz.infallible_turing.cached.thread-4] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Built execution plans for job '0591-5010-bd42-0001', execution 0591-5010-bd43-0001
2021-01-12 01:45:19,986 [DEBUG] [hz.infallible_turing.cached.thread-4] [c.h.j.i.o.InitExecutionOperation]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Initializing execution plan for job 0591-5010-bd42-0001, execution 0591-5010-bd43-0001 from [127.0.0.1]:5701
2021-01-12 01:45:19,987 [ INFO] [hz.infallible_turing.cached.thread-4] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Execution plan for jobId=0591-5010-bd42-0001, jobName='0591-5010-bd42-0001', executionId=0591-5010-bd43-0001 initialized
2021-01-12 01:45:19,988 [DEBUG] [hz.vigorous_turing.generic-operation.thread-11] [c.h.j.i.o.InitExecutionOperation]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Initializing execution plan for job 0591-5010-bd42-0001, execution 0591-5010-bd43-0001 from [127.0.0.1]:5701
2021-01-12 01:45:19,988 [ INFO] [hz.vigorous_turing.generic-operation.thread-11] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Execution plan for jobId=0591-5010-bd42-0001, jobName='0591-5010-bd42-0001', executionId=0591-5010-bd43-0001 initialized
2021-01-12 01:45:19,989 [DEBUG] [hz.infallible_turing.cached.thread-4] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Init of job '0591-5010-bd42-0001', execution 0591-5010-bd43-0001 was successful
2021-01-12 01:45:19,989 [DEBUG] [hz.infallible_turing.cached.thread-4] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Executing job '0591-5010-bd42-0001', execution 0591-5010-bd43-0001
2021-01-12 01:45:19,989 [ INFO] [hz.infallible_turing.cached.thread-4] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Start execution of job '0591-5010-bd42-0001', execution 0591-5010-bd43-0001 from coordinator [127.0.0.1]:5701
2021-01-12 01:45:19,989 [ INFO] [hz.vigorous_turing.generic-operation.thread-12] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Start execution of job '0591-5010-bd42-0001', execution 0591-5010-bd43-0001 from coordinator [127.0.0.1]:5701
2021-01-12 01:45:19,990 [DEBUG] [hz.vigorous_turing.jet.cooperative.thread-6] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Execution of job '0591-5010-bd42-0001', execution 0591-5010-bd43-0001 completed
2021-01-12 01:45:19,991 [DEBUG] [hz.infallible_turing.jet.cooperative.thread-6] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Execution of job '0591-5010-bd42-0001', execution 0591-5010-bd43-0001 completed
2021-01-12 01:45:19,991 [DEBUG] [ForkJoinPool.commonPool-worker-47] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Execution of job '0591-5010-bd42-0001', execution 0591-5010-bd43-0001 was successful
2021-01-12 01:45:19,991 [DEBUG] [hz.infallible_turing.cached.thread-4] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Sending CompleteExecutionOperation for job '0591-5010-bd42-0001', execution 0591-5010-bd43-0001
2021-01-12 01:45:19,991 [DEBUG] [hz.infallible_turing.cached.thread-4] [c.h.j.i.o.CompleteExecutionOperation]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Completing execution 0591-5010-bd43-0001 from caller [127.0.0.1]:5701, error=null
2021-01-12 01:45:19,991 [DEBUG] [hz.infallible_turing.cached.thread-4] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Completed execution of job '0591-5010-bd42-0001', execution 0591-5010-bd43-0001
2021-01-12 01:45:19,991 [DEBUG] [hz.vigorous_turing.generic-operation.thread-13] [c.h.j.i.o.CompleteExecutionOperation]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Completing execution 0591-5010-bd43-0001 from caller [127.0.0.1]:5701, error=null
2021-01-12 01:45:19,991 [DEBUG] [hz.vigorous_turing.generic-operation.thread-13] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Completed execution of job '0591-5010-bd42-0001', execution 0591-5010-bd43-0001
2021-01-12 01:45:19,992 [ INFO] [hz.infallible_turing.cached.thread-2] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Execution of job '0591-5010-bd42-0001', execution 0591-5010-bd43-0001 completed successfully
	Start time: 2021-01-12T01:45:19.985
	Duration: 00:00:00.007
	To see additional job metrics enable JobConfig.storeMetricsAfterJobCompletion
2021-01-12 01:45:19,992 [DEBUG] [hz.infallible_turing.cached.thread-2] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] job '0591-5010-bd42-0001', execution 0591-5010-bd43-0001 is completed
2021-01-12 01:45:19,992 [ INFO] [Thread-41] [c.h.j.c.MemberReconnectionStressTest]: job completed
2021-01-12 01:45:19,993 [ INFO] [hz.infallible_turing.cached.thread-4] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Starting job 0591-5010-bd44-0001 based on submit request
2021-01-12 01:45:19,994 [ INFO] [hz.infallible_turing.cached.thread-4] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Didn't find any snapshot to restore for job '0591-5010-bd44-0001', execution 0591-5010-bd45-0001
2021-01-12 01:45:19,994 [ INFO] [hz.infallible_turing.cached.thread-4] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Start executing job '0591-5010-bd44-0001', execution 0591-5010-bd45-0001, execution graph in DOT format:
digraph DAG {
	"v1" [localParallelism=2];
	"v2" [localParallelism=2];
	"v1" -> "v2" [label="distributed", queueSize=1024];
}
HINT: You can use graphviz or http://viz-js.com to visualize the printed graph.
2021-01-12 01:45:19,994 [DEBUG] [hz.infallible_turing.cached.thread-4] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Building execution plan for job '0591-5010-bd44-0001', execution 0591-5010-bd45-0001
2021-01-12 01:45:19,994 [DEBUG] [hz.infallible_turing.cached.thread-4] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Built execution plans for job '0591-5010-bd44-0001', execution 0591-5010-bd45-0001
2021-01-12 01:45:19,994 [DEBUG] [hz.infallible_turing.cached.thread-4] [c.h.j.i.o.InitExecutionOperation]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Initializing execution plan for job 0591-5010-bd44-0001, execution 0591-5010-bd45-0001 from [127.0.0.1]:5701
2021-01-12 01:45:19,995 [ INFO] [hz.infallible_turing.cached.thread-4] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Execution plan for jobId=0591-5010-bd44-0001, jobName='0591-5010-bd44-0001', executionId=0591-5010-bd45-0001 initialized
2021-01-12 01:45:19,995 [DEBUG] [hz.vigorous_turing.generic-operation.thread-14] [c.h.j.i.o.InitExecutionOperation]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Initializing execution plan for job 0591-5010-bd44-0001, execution 0591-5010-bd45-0001 from [127.0.0.1]:5701
2021-01-12 01:45:19,996 [ INFO] [hz.vigorous_turing.generic-operation.thread-14] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Execution plan for jobId=0591-5010-bd44-0001, jobName='0591-5010-bd44-0001', executionId=0591-5010-bd45-0001 initialized
2021-01-12 01:45:19,996 [DEBUG] [hz.infallible_turing.cached.thread-4] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Init of job '0591-5010-bd44-0001', execution 0591-5010-bd45-0001 was successful
2021-01-12 01:45:19,996 [DEBUG] [hz.infallible_turing.cached.thread-4] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Executing job '0591-5010-bd44-0001', execution 0591-5010-bd45-0001
2021-01-12 01:45:19,996 [ INFO] [hz.infallible_turing.cached.thread-4] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Start execution of job '0591-5010-bd44-0001', execution 0591-5010-bd45-0001 from coordinator [127.0.0.1]:5701
2021-01-12 01:45:19,997 [ INFO] [hz.vigorous_turing.generic-operation.thread-15] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Start execution of job '0591-5010-bd44-0001', execution 0591-5010-bd45-0001 from coordinator [127.0.0.1]:5701
2021-01-12 01:45:19,998 [DEBUG] [hz.vigorous_turing.jet.cooperative.thread-10] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Execution of job '0591-5010-bd44-0001', execution 0591-5010-bd45-0001 completed
2021-01-12 01:45:19,998 [DEBUG] [hz.infallible_turing.jet.cooperative.thread-10] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Execution of job '0591-5010-bd44-0001', execution 0591-5010-bd45-0001 completed
2021-01-12 01:45:19,998 [DEBUG] [ForkJoinPool.commonPool-worker-86] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Execution of job '0591-5010-bd44-0001', execution 0591-5010-bd45-0001 was successful
2021-01-12 01:45:19,999 [DEBUG] [hz.infallible_turing.cached.thread-4] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Sending CompleteExecutionOperation for job '0591-5010-bd44-0001', execution 0591-5010-bd45-0001
2021-01-12 01:45:19,999 [DEBUG] [hz.infallible_turing.cached.thread-4] [c.h.j.i.o.CompleteExecutionOperation]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Completing execution 0591-5010-bd45-0001 from caller [127.0.0.1]:5701, error=null
2021-01-12 01:45:19,999 [DEBUG] [hz.infallible_turing.cached.thread-4] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Completed execution of job '0591-5010-bd44-0001', execution 0591-5010-bd45-0001
2021-01-12 01:45:19,999 [DEBUG] [hz.vigorous_turing.generic-operation.thread-16] [c.h.j.i.o.CompleteExecutionOperation]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Completing execution 0591-5010-bd45-0001 from caller [127.0.0.1]:5701, error=null
2021-01-12 01:45:19,999 [DEBUG] [hz.vigorous_turing.generic-operation.thread-16] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Completed execution of job '0591-5010-bd44-0001', execution 0591-5010-bd45-0001
2021-01-12 01:45:19,999 [ INFO] [hz.infallible_turing.cached.thread-4] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Execution of job '0591-5010-bd44-0001', execution 0591-5010-bd45-0001 completed successfully
	Start time: 2021-01-12T01:45:19.993
	Duration: 00:00:00.006
	To see additional job metrics enable JobConfig.storeMetricsAfterJobCompletion
2021-01-12 01:45:19,999 [DEBUG] [hz.infallible_turing.cached.thread-4] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] job '0591-5010-bd44-0001', execution 0591-5010-bd45-0001 is completed
2021-01-12 01:45:19,999 [ INFO] [Thread-41] [c.h.j.c.MemberReconnectionStressTest]: job completed
2021-01-12 01:45:20,000 [ INFO] [hz.infallible_turing.cached.thread-6] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Starting job 0591-5010-bd46-0001 based on submit request
2021-01-12 01:45:20,002 [ INFO] [hz.infallible_turing.cached.thread-6] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Didn't find any snapshot to restore for job '0591-5010-bd46-0001', execution 0591-5010-bd47-0001
2021-01-12 01:45:20,002 [ INFO] [hz.infallible_turing.cached.thread-6] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Start executing job '0591-5010-bd46-0001', execution 0591-5010-bd47-0001, execution graph in DOT format:
digraph DAG {
	"v1" [localParallelism=2];
	"v2" [localParallelism=2];
	"v1" -> "v2" [label="distributed", queueSize=1024];
}
HINT: You can use graphviz or http://viz-js.com to visualize the printed graph.
2021-01-12 01:45:20,002 [DEBUG] [hz.infallible_turing.cached.thread-6] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Building execution plan for job '0591-5010-bd46-0001', execution 0591-5010-bd47-0001
2021-01-12 01:45:20,002 [DEBUG] [hz.infallible_turing.cached.thread-6] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Built execution plans for job '0591-5010-bd46-0001', execution 0591-5010-bd47-0001
2021-01-12 01:45:20,002 [DEBUG] [hz.infallible_turing.cached.thread-6] [c.h.j.i.o.InitExecutionOperation]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Initializing execution plan for job 0591-5010-bd46-0001, execution 0591-5010-bd47-0001 from [127.0.0.1]:5701
2021-01-12 01:45:20,003 [ INFO] [hz.infallible_turing.cached.thread-6] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Execution plan for jobId=0591-5010-bd46-0001, jobName='0591-5010-bd46-0001', executionId=0591-5010-bd47-0001 initialized
2021-01-12 01:45:20,003 [DEBUG] [hz.vigorous_turing.generic-operation.thread-17] [c.h.j.i.o.InitExecutionOperation]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Initializing execution plan for job 0591-5010-bd46-0001, execution 0591-5010-bd47-0001 from [127.0.0.1]:5701
2021-01-12 01:45:20,004 [ INFO] [hz.vigorous_turing.generic-operation.thread-17] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Execution plan for jobId=0591-5010-bd46-0001, jobName='0591-5010-bd46-0001', executionId=0591-5010-bd47-0001 initialized
2021-01-12 01:45:20,004 [DEBUG] [hz.infallible_turing.cached.thread-6] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Init of job '0591-5010-bd46-0001', execution 0591-5010-bd47-0001 was successful
2021-01-12 01:45:20,004 [DEBUG] [hz.infallible_turing.cached.thread-6] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Executing job '0591-5010-bd46-0001', execution 0591-5010-bd47-0001
2021-01-12 01:45:20,004 [ INFO] [hz.infallible_turing.cached.thread-6] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Start execution of job '0591-5010-bd46-0001', execution 0591-5010-bd47-0001 from coordinator [127.0.0.1]:5701
2021-01-12 01:45:20,005 [ INFO] [hz.vigorous_turing.generic-operation.thread-18] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Start execution of job '0591-5010-bd46-0001', execution 0591-5010-bd47-0001 from coordinator [127.0.0.1]:5701
2021-01-12 01:45:20,006 [DEBUG] [hz.vigorous_turing.jet.cooperative.thread-14] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Execution of job '0591-5010-bd46-0001', execution 0591-5010-bd47-0001 completed
2021-01-12 01:45:20,007 [DEBUG] [hz.infallible_turing.jet.cooperative.thread-14] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Execution of job '0591-5010-bd46-0001', execution 0591-5010-bd47-0001 completed
2021-01-12 01:45:20,007 [DEBUG] [ForkJoinPool.commonPool-worker-62] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Execution of job '0591-5010-bd46-0001', execution 0591-5010-bd47-0001 was successful
2021-01-12 01:45:20,007 [DEBUG] [hz.infallible_turing.cached.thread-6] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Sending CompleteExecutionOperation for job '0591-5010-bd46-0001', execution 0591-5010-bd47-0001
2021-01-12 01:45:20,007 [DEBUG] [hz.infallible_turing.cached.thread-6] [c.h.j.i.o.CompleteExecutionOperation]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Completing execution 0591-5010-bd47-0001 from caller [127.0.0.1]:5701, error=null
2021-01-12 01:45:20,007 [DEBUG] [hz.infallible_turing.cached.thread-6] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Completed execution of job '0591-5010-bd46-0001', execution 0591-5010-bd47-0001
2021-01-12 01:45:20,007 [DEBUG] [hz.vigorous_turing.generic-operation.thread-19] [c.h.j.i.o.CompleteExecutionOperation]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Completing execution 0591-5010-bd47-0001 from caller [127.0.0.1]:5701, error=null
2021-01-12 01:45:20,007 [DEBUG] [hz.vigorous_turing.generic-operation.thread-19] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Completed execution of job '0591-5010-bd46-0001', execution 0591-5010-bd47-0001
2021-01-12 01:45:20,007 [ INFO] [hz.infallible_turing.cached.thread-6] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Execution of job '0591-5010-bd46-0001', execution 0591-5010-bd47-0001 completed successfully
	Start time: 2021-01-12T01:45:20
	Duration: 00:00:00.007
	To see additional job metrics enable JobConfig.storeMetricsAfterJobCompletion
2021-01-12 01:45:20,007 [DEBUG] [hz.infallible_turing.cached.thread-6] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] job '0591-5010-bd46-0001', execution 0591-5010-bd47-0001 is completed
2021-01-12 01:45:20,008 [ INFO] [Thread-41] [c.h.j.c.MemberReconnectionStressTest]: job completed
2021-01-12 01:45:20,008 [ INFO] [hz.infallible_turing.cached.thread-5] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Starting job 0591-5010-bd48-0001 based on submit request
2021-01-12 01:45:20,010 [ INFO] [hz.infallible_turing.cached.thread-5] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Didn't find any snapshot to restore for job '0591-5010-bd48-0001', execution 0591-5010-bd49-0001
2021-01-12 01:45:20,010 [ INFO] [hz.infallible_turing.cached.thread-5] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Start executing job '0591-5010-bd48-0001', execution 0591-5010-bd49-0001, execution graph in DOT format:
digraph DAG {
	"v1" [localParallelism=2];
	"v2" [localParallelism=2];
	"v1" -> "v2" [label="distributed", queueSize=1024];
}
HINT: You can use graphviz or http://viz-js.com to visualize the printed graph.
2021-01-12 01:45:20,010 [DEBUG] [hz.infallible_turing.cached.thread-5] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Building execution plan for job '0591-5010-bd48-0001', execution 0591-5010-bd49-0001
2021-01-12 01:45:20,010 [DEBUG] [hz.infallible_turing.cached.thread-5] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Built execution plans for job '0591-5010-bd48-0001', execution 0591-5010-bd49-0001
2021-01-12 01:45:20,010 [DEBUG] [hz.infallible_turing.cached.thread-5] [c.h.j.i.o.InitExecutionOperation]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Initializing execution plan for job 0591-5010-bd48-0001, execution 0591-5010-bd49-0001 from [127.0.0.1]:5701
2021-01-12 01:45:20,010 [ INFO] [hz.infallible_turing.cached.thread-5] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Execution plan for jobId=0591-5010-bd48-0001, jobName='0591-5010-bd48-0001', executionId=0591-5010-bd49-0001 initialized
2021-01-12 01:45:20,011 [DEBUG] [hz.vigorous_turing.generic-operation.thread-20] [c.h.j.i.o.InitExecutionOperation]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Initializing execution plan for job 0591-5010-bd48-0001, execution 0591-5010-bd49-0001 from [127.0.0.1]:5701
2021-01-12 01:45:20,012 [ INFO] [hz.vigorous_turing.generic-operation.thread-20] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Execution plan for jobId=0591-5010-bd48-0001, jobName='0591-5010-bd48-0001', executionId=0591-5010-bd49-0001 initialized
2021-01-12 01:45:20,012 [DEBUG] [hz.infallible_turing.cached.thread-5] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Init of job '0591-5010-bd48-0001', execution 0591-5010-bd49-0001 was successful
2021-01-12 01:45:20,012 [DEBUG] [hz.infallible_turing.cached.thread-5] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Executing job '0591-5010-bd48-0001', execution 0591-5010-bd49-0001
2021-01-12 01:45:20,012 [ INFO] [hz.infallible_turing.cached.thread-5] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Start execution of job '0591-5010-bd48
...[truncated 8769324 chars]...
b5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,395 [ INFO] [hz.vigorous_turing.cached.thread-8] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,395 [ INFO] [hz.vigorous_turing.cached.thread-8] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,395 [ INFO] [hz.vigorous_turing.cached.thread-8] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,395 [ INFO] [hz.vigorous_turing.cached.thread-8] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,395 [ INFO] [hz.vigorous_turing.cached.thread-5] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,396 [ INFO] [hz.vigorous_turing.cached.thread-5] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,396 [ INFO] [hz.vigorous_turing.cached.thread-17] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,396 [ INFO] [hz.vigorous_turing.cached.thread-17] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,396 [ INFO] [hz.vigorous_turing.cached.thread-6] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,396 [ INFO] [hz.vigorous_turing.cached.thread-6] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,396 [ INFO] [hz.vigorous_turing.cached.thread-5] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,396 [ INFO] [hz.vigorous_turing.cached.thread-5] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,396 [ INFO] [hz.vigorous_turing.cached.thread-17] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,396 [ INFO] [hz.vigorous_turing.cached.thread-17] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,397 [ INFO] [hz.vigorous_turing.cached.thread-10] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,397 [ INFO] [hz.vigorous_turing.cached.thread-10] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,397 [ INFO] [hz.vigorous_turing.cached.thread-10] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,397 [ INFO] [hz.vigorous_turing.cached.thread-10] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,397 [ INFO] [hz.vigorous_turing.cached.thread-10] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,397 [ INFO] [hz.vigorous_turing.cached.thread-10] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,397 [ INFO] [hz.vigorous_turing.cached.thread-16] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,397 [ INFO] [hz.vigorous_turing.cached.thread-16] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,398 [ INFO] [hz.vigorous_turing.cached.thread-5] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,398 [ INFO] [hz.vigorous_turing.cached.thread-5] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,398 [ INFO] [hz.vigorous_turing.cached.thread-7] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,398 [ INFO] [hz.vigorous_turing.cached.thread-7] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,398 [ INFO] [hz.vigorous_turing.cached.thread-16] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,398 [ INFO] [hz.vigorous_turing.cached.thread-16] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,398 [ INFO] [hz.vigorous_turing.cached.thread-13] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,398 [ INFO] [hz.vigorous_turing.cached.thread-13] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,399 [ INFO] [hz.vigorous_turing.cached.thread-15] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,399 [ INFO] [hz.vigorous_turing.cached.thread-15] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,399 [ INFO] [hz.vigorous_turing.cached.thread-3] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,399 [ INFO] [hz.vigorous_turing.cached.thread-3] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,399 [ INFO] [hz.vigorous_turing.cached.thread-7] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,399 [ INFO] [hz.vigorous_turing.cached.thread-7] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,399 [ INFO] [hz.vigorous_turing.cached.thread-7] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,399 [ INFO] [hz.vigorous_turing.cached.thread-7] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,399 [ INFO] [hz.vigorous_turing.cached.thread-3] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,400 [ INFO] [hz.vigorous_turing.cached.thread-3] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,400 [ INFO] [hz.vigorous_turing.cached.thread-17] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,400 [ INFO] [hz.vigorous_turing.cached.thread-17] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,400 [ INFO] [hz.vigorous_turing.cached.thread-6] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,400 [ INFO] [hz.vigorous_turing.cached.thread-6] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,400 [ INFO] [hz.vigorous_turing.cached.thread-11] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,400 [ INFO] [hz.vigorous_turing.cached.thread-11] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,400 [ INFO] [hz.vigorous_turing.cached.thread-2] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,400 [ INFO] [hz.vigorous_turing.cached.thread-2] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,401 [ INFO] [hz.vigorous_turing.cached.thread-7] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,401 [ INFO] [hz.vigorous_turing.cached.thread-7] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,401 [ INFO] [hz.vigorous_turing.cached.thread-15] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,401 [ INFO] [hz.vigorous_turing.cached.thread-15] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,401 [ INFO] [hz.vigorous_turing.cached.thread-10] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,401 [ INFO] [hz.vigorous_turing.cached.thread-10] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,401 [ INFO] [hz.vigorous_turing.cached.thread-6] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,401 [ INFO] [hz.vigorous_turing.cached.thread-6] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,401 [ INFO] [hz.vigorous_turing.cached.thread-17] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,402 [ INFO] [hz.vigorous_turing.cached.thread-17] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,402 [ INFO] [hz.vigorous_turing.cached.thread-4] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,402 [ INFO] [hz.vigorous_turing.cached.thread-4] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,402 [ INFO] [hz.vigorous_turing.cached.thread-7] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,402 [ INFO] [hz.vigorous_turing.cached.thread-7] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,405 [ INFO] [hz.vigorous_turing.cached.thread-16] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,405 [ INFO] [hz.vigorous_turing.cached.thread-16] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,429 [ INFO] [hz.vigorous_turing.cached.thread-16] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,429 [ INFO] [hz.vigorous_turing.cached.thread-16] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,465 [ INFO] [hz.vigorous_turing.cached.thread-16] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,466 [ INFO] [hz.vigorous_turing.cached.thread-16] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,466 [ INFO] [hz.vigorous_turing.cached.thread-7] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,466 [ INFO] [hz.vigorous_turing.cached.thread-7] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,466 [ INFO] [hz.vigorous_turing.cached.thread-17] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,467 [ INFO] [hz.vigorous_turing.cached.thread-17] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,467 [ INFO] [hz.vigorous_turing.cached.thread-7] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,467 [ INFO] [hz.vigorous_turing.cached.thread-7] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,468 [ INFO] [hz.vigorous_turing.cached.thread-9] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,468 [ INFO] [hz.vigorous_turing.cached.thread-9] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,468 [ INFO] [hz.vigorous_turing.cached.thread-17] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,468 [ INFO] [hz.vigorous_turing.cached.thread-17] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,468 [ INFO] [hz.vigorous_turing.cached.thread-16] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,468 [ INFO] [hz.vigorous_turing.cached.thread-16] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,469 [ INFO] [hz.vigorous_turing.cached.thread-15] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,469 [ INFO] [hz.vigorous_turing.cached.thread-15] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,469 [ INFO] [hz.vigorous_turing.cached.thread-11] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,469 [ INFO] [hz.vigorous_turing.cached.thread-11] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,469 [ INFO] [hz.vigorous_turing.cached.thread-7] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,470 [ INFO] [hz.vigorous_turing.cached.thread-7] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,470 [ INFO] [hz.vigorous_turing.cached.thread-2] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,470 [ INFO] [hz.vigorous_turing.cached.thread-2] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,470 [ INFO] [hz.vigorous_turing.cached.thread-8] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,470 [ INFO] [hz.vigorous_turing.cached.thread-8] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,470 [ INFO] [hz.vigorous_turing.cached.thread-13] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,470 [ INFO] [hz.vigorous_turing.cached.thread-13] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,482 [ INFO] [hz.vigorous_turing.cached.thread-13] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,482 [ INFO] [hz.vigorous_turing.cached.thread-13] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,483 [ INFO] [hz.vigorous_turing.cached.thread-13] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,484 [ INFO] [hz.vigorous_turing.cached.thread-13] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,484 [ INFO] [hz.vigorous_turing.cached.thread-5] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,484 [ INFO] [hz.vigorous_turing.cached.thread-5] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,484 [ INFO] [hz.vigorous_turing.cached.thread-11] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,484 [ INFO] [hz.vigorous_turing.cached.thread-11] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,484 [ INFO] [hz.vigorous_turing.cached.thread-10] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,484 [ INFO] [hz.vigorous_turing.cached.thread-10] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,485 [ INFO] [hz.vigorous_turing.cached.thread-13] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,485 [ INFO] [hz.vigorous_turing.cached.thread-13] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,485 [ INFO] [hz.vigorous_turing.cached.thread-17] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,485 [ INFO] [hz.vigorous_turing.cached.thread-17] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,485 [ INFO] [hz.vigorous_turing.cached.thread-11] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,485 [ INFO] [hz.vigorous_turing.cached.thread-11] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,486 [ INFO] [hz.vigorous_turing.cached.thread-8] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,486 [ INFO] [hz.vigorous_turing.cached.thread-8] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,486 [ INFO] [hz.vigorous_turing.cached.thread-13] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,486 [ INFO] [hz.vigorous_turing.cached.thread-13] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,486 [ INFO] [hz.vigorous_turing.cached.thread-9] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,486 [ INFO] [hz.vigorous_turing.cached.thread-9] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,486 [ INFO] [hz.vigorous_turing.cached.thread-10] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,486 [ INFO] [hz.vigorous_turing.cached.thread-10] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,487 [ INFO] [hz.vigorous_turing.cached.thread-4] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,487 [ INFO] [hz.vigorous_turing.cached.thread-4] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,487 [ INFO] [hz.vigorous_turing.cached.thread-13] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,487 [ INFO] [hz.vigorous_turing.cached.thread-13] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,487 [ INFO] [hz.vigorous_turing.cached.thread-7] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,487 [ INFO] [hz.vigorous_turing.cached.thread-7] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,487 [ INFO] [hz.vigorous_turing.cached.thread-8] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,487 [ INFO] [hz.vigorous_turing.cached.thread-8] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,488 [ INFO] [hz.vigorous_turing.cached.thread-6] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,488 [ INFO] [hz.vigorous_turing.cached.thread-6] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,488 [ INFO] [hz.vigorous_turing.cached.thread-13] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,488 [ INFO] [hz.vigorous_turing.cached.thread-13] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,488 [ INFO] [hz.vigorous_turing.cached.thread-7] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,488 [ INFO] [hz.vigorous_turing.cached.thread-7] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,489 [ INFO] [hz.vigorous_turing.cached.thread-8] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,489 [ INFO] [hz.vigorous_turing.cached.thread-8] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,489 [ INFO] [hz.vigorous_turing.cached.thread-6] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,489 [ INFO] [hz.vigorous_turing.cached.thread-6] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,489 [ INFO] [hz.vigorous_turing.cached.thread-9] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,489 [ INFO] [hz.vigorous_turing.cached.thread-9] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,490 [ INFO] [hz.vigorous_turing.cached.thread-8] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,490 [ INFO] [hz.vigorous_turing.cached.thread-8] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,490 [ INFO] [hz.vigorous_turing.cached.thread-17] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,490 [ INFO] [hz.vigorous_turing.cached.thread-17] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,490 [ INFO] [hz.vigorous_turing.cached.thread-11] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,490 [ INFO] [hz.vigorous_turing.cached.thread-11] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,490 [ INFO] [hz.vigorous_turing.cached.thread-9] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,490 [ INFO] [hz.vigorous_turing.cached.thread-9] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,491 [ INFO] [hz.vigorous_turing.cached.thread-5] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,491 [ INFO] [hz.vigorous_turing.cached.thread-5] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,491 [ INFO] [hz.vigorous_turing.cached.thread-10] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,491 [ INFO] [hz.vigorous_turing.cached.thread-10] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,491 [ INFO] [hz.vigorous_turing.cached.thread-15] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,491 [ INFO] [hz.vigorous_turing.cached.thread-15] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,491 [ INFO] [hz.vigorous_turing.cached.thread-13] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,491 [ INFO] [hz.vigorous_turing.cached.thread-13] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,492 [ INFO] [hz.vigorous_turing.cached.thread-3] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,492 [ INFO] [hz.vigorous_turing.cached.thread-3] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,492 [ INFO] [hz.vigorous_turing.cached.thread-17] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,492 [ INFO] [hz.vigorous_turing.cached.thread-17] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,492 [ INFO] [hz.vigorous_turing.cached.thread-5] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,493 [ INFO] [hz.vigorous_turing.cached.thread-5] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,493 [ INFO] [hz.vigorous_turing.cached.thread-3] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:38,493 [ INFO] [hz.vigorous_turing.cached.thread-3] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:38,493 [ INFO] [hz.vigorous_turing.cached.thread-2] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Connecting to /127.0.0.1:5701, timeout: 10000, bind-any: true
2021-01-12 01:47:39,296 [ INFO] [hz.vigorous_turing.cached.thread-12] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:39,296 [ WARN] [hz.vigorous_turing.cached.thread-12] [c.h.i.s.t.TcpServerConnectionErrorHandler]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Removing connection to endpoint [127.0.0.1]:5701 Cause => java.net.SocketException {Connection refused to address /127.0.0.1:5701}, Error-Count: 5
2021-01-12 01:47:39,297 [ WARN] [hz.vigorous_turing.cached.thread-12] [c.h.i.c.i.MembershipManager]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Member [127.0.0.1]:5701 - 3fb9bfa6-908c-409f-8625-d7c1ff21b83b is suspected to be dead for reason: No connection
2021-01-12 01:47:39,297 [ INFO] [hz.vigorous_turing.cached.thread-12] [c.h.i.c.i.MembershipManager]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Starting mastership claim process...
2021-01-12 01:47:39,297 [ INFO] [hz.vigorous_turing.cached.thread-12] [c.h.i.c.i.MembershipManager]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Local MembersView{version=2, members=[MemberInfo{address=[127.0.0.1]:5701, uuid=3fb9bfa6-908c-409f-8625-d7c1ff21b83b, liteMember=false, memberListJoinVersion=1}, MemberInfo{address=[127.0.0.1]:5702, uuid=bdb6555f-a375-4302-a04f-45fe633480ba, liteMember=false, memberListJoinVersion=2}]} with suspected members: [Member [127.0.0.1]:5701 - 3fb9bfa6-908c-409f-8625-d7c1ff21b83b] and initial addresses to ask: []
2021-01-12 01:47:39,300 [ INFO] [hz.vigorous_turing.cached.thread-6] [c.h.i.c.ClusterService]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] 

Members {size:1, ver:3} [
	Member [127.0.0.1]:5702 - bdb6555f-a375-4302-a04f-45fe633480ba this
]

2021-01-12 01:47:39,300 [ INFO] [hz.vigorous_turing.cached.thread-6] [c.h.i.c.i.MembershipManager]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Mastership is claimed with: MembersView{version=3, members=[MemberInfo{address=[127.0.0.1]:5702, uuid=bdb6555f-a375-4302-a04f-45fe633480ba, liteMember=false, memberListJoinVersion=2}]}
2021-01-12 01:47:39,302 [ INFO] [hz.vigorous_turing.migration] [c.h.i.p.InternalPartitionService]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Fetching partition tables from cluster to determine the most recent one... Local stamp: -5124984796201632246
2021-01-12 01:47:39,302 [ INFO] [hz.vigorous_turing.migration] [c.h.i.p.InternalPartitionService]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Most recent partition table is determined.
2021-01-12 01:47:39,302 [ INFO] [hz.vigorous_turing.migration] [c.h.i.p.InternalPartitionService]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Applying the most recent of partition state...
2021-01-12 01:47:39,305 [ INFO] [hz.vigorous_turing.cached.thread-14] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: SocketException[Connection refused to address /127.0.0.1:5701]
2021-01-12 01:47:39,315 [ INFO] [hz.vigorous_turing.migration] [c.h.i.p.i.MigrationManager]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Partition balance is ok, no need to repartition.
2021-01-12 01:47:39,329 [ INFO] [hz.vigorous_turing.cached.thread-1] [c.h.i.p.i.MigrationManager]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Shutdown request of Member [127.0.0.1]:5702 - bdb6555f-a375-4302-a04f-45fe633480ba this is handled
2021-01-12 01:47:39,329 [ INFO] [Time-limited test] [c.h.i.i.Node]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Shutting down multicast service...
2021-01-12 01:47:39,330 [ INFO] [Time-limited test] [c.h.i.i.Node]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Shutting down connection manager...
2021-01-12 01:47:39,332 [ INFO] [hz.vigorous_turing.cached.thread-14] [c.h.i.c.i.MulticastJoiner]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] [127.0.0.1]:5701 is added to the blacklist.
2021-01-12 01:47:39,333 [ INFO] [hz.vigorous_turing.cached.thread-2] [c.h.i.s.t.TcpServerConnector]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Could not connect to: /127.0.0.1:5701. Reason: ClosedChannelException[null]
2021-01-12 01:47:39,333 [ INFO] [hz.vigorous_turing.cached.thread-2] [c.h.i.c.i.MulticastJoiner]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] [127.0.0.1]:5701 is added to the blacklist.
2021-01-12 01:47:39,334 [ INFO] [Time-limited test] [c.h.i.i.Node]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Shutting down node engine...
2021-01-12 01:47:39,352 [ INFO] [Time-limited test] [c.h.i.i.NodeExtension]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Destroying node NodeExtension.
2021-01-12 01:47:39,352 [ INFO] [Time-limited test] [c.h.i.i.Node]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] Hazelcast Shutdown is completed in 1024 ms.
2021-01-12 01:47:39,352 [ INFO] [Time-limited test] [c.h.c.LifecycleService]: [127.0.0.1]:5702 [2557e9dc-121a-4358-969d-64d904f70fb5] [4.4-SNAPSHOT] [127.0.0.1]:5702 is SHUTDOWN
BuildInfo right after test(com.hazelcast.jet.core.MemberReconnectionStressTest): BuildInfo{version='4.1.1', build='20201222', buildNumber=20201222, revision=27af558, enterprise=false, serializationVersion=1, jet=JetBuildInfo{version='4.4-SNAPSHOT', build='20210112', revision='2d6bcac'}}
Hiccups measured while running test 'test(com.hazelcast.jet.core.MemberReconnectionStressTest):'
01:45:10, accumulated pauses: 239 ms, max pause: 22 ms, pauses over 1000 ms: 0
01:45:15, accumulated pauses: 24 ms, max pause: 1 ms, pauses over 1000 ms: 0
01:45:20, accumulated pauses: 37 ms, max pause: 8 ms, pauses over 1000 ms: 0
01:45:25, accumulated pauses: 45 ms, max pause: 12 ms, pauses over 1000 ms: 0
01:45:30, accumulated pauses: 29 ms, max pause: 2 ms, pauses over 1000 ms: 0
01:45:35, accumulated pauses: 41 ms, max pause: 8 ms, pauses over 1000 ms: 0
01:45:40, accumulated pauses: 53 ms, max pause: 11 ms, pauses over 1000 ms: 0
01:45:45, accumulated pauses: 47 ms, max pause: 16 ms, pauses over 1000 ms: 0
01:45:50, accumulated pauses: 48 ms, max pause: 8 ms, pauses over 1000 ms: 0
01:45:55, accumulated pauses: 40 ms, max pause: 14 ms, pauses over 1000 ms: 0
01:46:00, accumulated pauses: 35 ms, max pause: 3 ms, pauses over 1000 ms: 0
01:46:05, accumulated pauses: 56 ms, max pause: 19 ms, pauses over 1000 ms: 0
01:46:10, accumulated pauses: 83 ms, max pause: 20 ms, pauses over 1000 ms: 0
01:46:15, accumulated pauses: 42 ms, max pause: 13 ms, pauses over 1000 ms: 0
01:46:20, accumulated pauses: 43 ms, max pause: 17 ms, pauses over 1000 ms: 0
01:46:25, accumulated pauses: 49 ms, max pause: 23 ms, pauses over 1000 ms: 0
01:46:30, accumulated pauses: 52 ms, max pause: 23 ms, pauses over 1000 ms: 0
01:46:35, accumulated pauses: 82 ms, max pause: 27 ms, pauses over 1000 ms: 0
01:46:40, accumulated pauses: 41 ms, max pause: 15 ms, pauses over 1000 ms: 0
01:46:45, accumulated pauses: 48 ms, max pause: 17 ms, pauses over 1000 ms: 0
01:46:50, accumulated pauses: 43 ms, max pause: 9 ms, pauses over 1000 ms: 0
01:46:55, accumulated pauses: 31 ms, max pause: 4 ms, pauses over 1000 ms: 0
01:47:00, accumulated pauses: 52 ms, max pause: 24 ms, pauses over 1000 ms: 0
01:47:05, accumulated pauses: 47 ms, max pause: 19 ms, pauses over 1000 ms: 0
01:47:10, accumulated pauses: 38 ms, max pause: 12 ms, pauses over 1000 ms: 0
01:47:15, accumulated pauses: 49 ms, max pause: 13 ms, pauses over 1000 ms: 0
01:47:20, accumulated pauses: 57 ms, max pause: 15 ms, pauses over 1000 ms: 0
01:47:25, accumulated pauses: 67 ms, max pause: 16 ms, pauses over 1000 ms: 0
01:47:30, accumulated pauses: 46 ms, max pause: 18 ms, pauses over 1000 ms: 0
01:47:35, accumulated pauses: 283 ms, max pause: 221 ms, pauses over 1000 ms: 0

Jan 12 '21 07:01 olukas

This happens also on 4.3-maintenance branch.

Mar 08 '21 09:03 olukas

From the logs we see several Not starting jobs because partition replication is not in safe state, but in REPLICA_NOT_SYNC logs. After this log job coordination service reschedules the job. This is normal and eventually the state of the partition replication turns to SAFE and jobs are started.

We see first such log at 01:45:24,230 10 seconds after test started, partition replication heals shortly (in 2 seconds) and test continues. Second log at 01:45:31,219, again 2 seconds later partition replication heals and test continues. Third log is at 01:46:04,217 again 2 seconds later partition replication heals and test continues.

Next log is at 01:46:15,185 and it never heals, thus the submitted job is scheduled continuesly but never can start.

I think the root cause of the failure is the partition replication state

Mar 24 '21 11:03 gurbuzali

hazelcast-jet hazelcast-jet copied to clipboard

com.hazelcast.jet.core.MemberReconnectionStressTest.test

hazelcast-jet
hazelcast-jet copied to clipboard