search

hazelcast / hazelcast-jet

Distributed Stream and Batch Processing
https://jet-start.sh
Other
1.11k stars 205 forks source link

com.hazelcast.jet.pipeline.SourceBuilder_TopologyChangeTest.test_restartJob_nodeTerminated #3021

Open olukas opened 3 years ago

olukas commented 3 years ago

master (commit 4eb9c6bb3aac6b2c827e07c346237f6bc8f5db1b)

Failed on Oracle JDK 11: http://jenkins.hazelcast.com/job/jet-oss-master-oracle-jdk11/370/testReport/junit/com.hazelcast.jet.pipeline/SourceBuilder_TopologyChangeTest/test_restartJob_nodeTerminated/

Stacktrace:

java.lang.AssertionError: No snapshot produced
    at org.junit.Assert.fail(Assert.java:89)
    at org.junit.Assert.assertTrue(Assert.java:42)
    at com.hazelcast.jet.core.JetTestSupport.lambda$waitForFirstSnapshot$3(JetTestSupport.java:257)
    at com.hazelcast.test.HazelcastTestSupport.assertTrueEventually(HazelcastTestSupport.java:1247)
    at com.hazelcast.test.HazelcastTestSupport.assertTrueEventually(HazelcastTestSupport.java:1264)
    at com.hazelcast.jet.core.JetTestSupport.waitForFirstSnapshot(JetTestSupport.java:254)
    at com.hazelcast.jet.pipeline.SourceBuilder_TopologyChangeTest.testTopologyChange(SourceBuilder_TopologyChangeTest.java:114)
    at com.hazelcast.jet.pipeline.SourceBuilder_TopologyChangeTest.test_restartJob_nodeTerminated(SourceBuilder_TopologyChangeTest.java:58)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.base/java.lang.reflect.Method.invoke(Method.java:566)
    at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java: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:115)
    at com.hazelcast.test.FailOnTimeoutStatement$CallableStatement.call(FailOnTimeoutStatement.java:107)
    at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
    at java.base/java.lang.Thread.run(Thread.java:834)

Standard output:

Started Running Test: test_restartJob_nodeTerminated
2021-04-08 19:47:09,614 [ INFO] [test_restartJob_nodeTerminated] [c.h.i.m.i.MetricsConfigHelper]: [LOCAL] [jet] [4.5-SNAPSHOT] Overridden metrics configuration with system property 'hazelcast.metrics.collection.frequency'='1' -> 'MetricsConfig.collectionFrequencySeconds'='1'
2021-04-08 19:47:09,619 [ INFO] [test_restartJob_nodeTerminated] [c.h.system]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Hazelcast Jet 4.5-SNAPSHOT (20210408 - 4eb9c6b) starting at [127.0.0.1]:5701
2021-04-08 19:47:09,619 [ INFO] [test_restartJob_nodeTerminated] [c.h.system]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Based on Hazelcast IMDG version: 4.2.0 (20210324 - 405cfd1)
2021-04-08 19:47:09,619 [ INFO] [test_restartJob_nodeTerminated] [c.h.system]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Cluster name: jet
2021-04-08 19:47:09,619 [ INFO] [test_restartJob_nodeTerminated] [c.h.system]: [127.0.0.1]:5701 [jet] [4.5-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-04-08 19:47:09,619 [ INFO] [test_restartJob_nodeTerminated] [c.h.system]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Copyright (c) 2008-2021, Hazelcast, Inc. All Rights Reserved.
2021-04-08 19:47:09,632 [ INFO] [test_restartJob_nodeTerminated] [c.h.i.m.i.MetricsConfigHelper]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Collecting debug metrics and sending to diagnostics is enabled
2021-04-08 19:47:09,742 [ WARN] [test_restartJob_nodeTerminated] [c.h.c.CPSubsystem]: [127.0.0.1]:5701 [jet] [4.5-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-04-08 19:47:10,092 [ INFO] [test_restartJob_nodeTerminated] [c.h.j.i.JetService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Setting number of cooperative threads and default parallelism to 72
2021-04-08 19:47:10,910 [ INFO] [test_restartJob_nodeTerminated] [c.h.i.d.Diagnostics]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Diagnostics disabled. To enable add -Dhazelcast.diagnostics.enabled=true to the JVM arguments.
2021-04-08 19:47:10,910 [ INFO] [test_restartJob_nodeTerminated] [c.h.c.LifecycleService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] [127.0.0.1]:5701 is STARTING
2021-04-08 19:47:10,923 [ INFO] [test_restartJob_nodeTerminated] [c.h.i.c.ClusterService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] 

Members {size:1, ver:1} [
    Member [127.0.0.1]:5701 - 61cdd91d-92bd-4e65-b6cd-e9309484be50 this
]

2021-04-08 19:47:10,982 [ INFO] [test_restartJob_nodeTerminated] [c.h.c.LifecycleService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] [127.0.0.1]:5701 is STARTED
2021-04-08 19:47:10,983 [ INFO] [test_restartJob_nodeTerminated] [c.h.i.m.i.MetricsConfigHelper]: [LOCAL] [jet] [4.5-SNAPSHOT] Overridden metrics configuration with system property 'hazelcast.metrics.collection.frequency'='1' -> 'MetricsConfig.collectionFrequencySeconds'='1'
2021-04-08 19:47:10,984 [ INFO] [test_restartJob_nodeTerminated] [c.h.system]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Hazelcast Jet 4.5-SNAPSHOT (20210408 - 4eb9c6b) starting at [127.0.0.1]:5702
2021-04-08 19:47:10,984 [ INFO] [test_restartJob_nodeTerminated] [c.h.system]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Based on Hazelcast IMDG version: 4.2.0 (20210324 - 405cfd1)
2021-04-08 19:47:10,984 [ INFO] [test_restartJob_nodeTerminated] [c.h.system]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Cluster name: jet
2021-04-08 19:47:10,984 [ INFO] [test_restartJob_nodeTerminated] [c.h.system]: [127.0.0.1]:5702 [jet] [4.5-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-04-08 19:47:10,984 [ INFO] [test_restartJob_nodeTerminated] [c.h.system]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Copyright (c) 2008-2021, Hazelcast, Inc. All Rights Reserved.
2021-04-08 19:47:11,033 [ INFO] [test_restartJob_nodeTerminated] [c.h.i.m.i.MetricsConfigHelper]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Collecting debug metrics and sending to diagnostics is enabled
2021-04-08 19:47:11,071 [DEBUG] [hz.zealous_fermat.cached.thread-10] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Not starting jobs because partitions are not yet initialized.
2021-04-08 19:47:11,162 [ WARN] [test_restartJob_nodeTerminated] [c.h.c.CPSubsystem]: [127.0.0.1]:5702 [jet] [4.5-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-04-08 19:47:11,172 [DEBUG] [hz.zealous_fermat.cached.thread-7] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Not starting jobs because partitions are not yet initialized.
2021-04-08 19:47:11,273 [DEBUG] [hz.zealous_fermat.cached.thread-11] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Not starting jobs because partitions are not yet initialized.
2021-04-08 19:47:11,374 [DEBUG] [hz.zealous_fermat.cached.thread-11] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Not starting jobs because partitions are not yet initialized.
2021-04-08 19:47:11,467 [ INFO] [test_restartJob_nodeTerminated] [c.h.j.i.JetService]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Setting number of cooperative threads and default parallelism to 72
2021-04-08 19:47:11,475 [DEBUG] [hz.zealous_fermat.cached.thread-11] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Not starting jobs because partitions are not yet initialized.
2021-04-08 19:47:11,578 [DEBUG] [hz.zealous_fermat.cached.thread-11] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Not starting jobs because partitions are not yet initialized.
2021-04-08 19:47:11,686 [DEBUG] [hz.zealous_fermat.cached.thread-11] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Not starting jobs because partitions are not yet initialized.
2021-04-08 19:47:11,786 [DEBUG] [hz.zealous_fermat.cached.thread-11] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Not starting jobs because partitions are not yet initialized.
2021-04-08 19:47:11,889 [DEBUG] [hz.zealous_fermat.cached.thread-7] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Not starting jobs because partitions are not yet initialized.
2021-04-08 19:47:11,924 [DEBUG] [hz.zealous_fermat.cached.thread-7] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Not starting jobs because partitions are not yet initialized.
2021-04-08 19:47:11,989 [DEBUG] [hz.zealous_fermat.cached.thread-7] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Not starting jobs because partitions are not yet initialized.
2021-04-08 19:47:12,080 [ INFO] [test_restartJob_nodeTerminated] [c.h.i.d.Diagnostics]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Diagnostics disabled. To enable add -Dhazelcast.diagnostics.enabled=true to the JVM arguments.
2021-04-08 19:47:12,080 [ INFO] [test_restartJob_nodeTerminated] [c.h.c.LifecycleService]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [127.0.0.1]:5702 is STARTING
2021-04-08 19:47:12,081 [ INFO] [test_restartJob_nodeTerminated] [c.h.t.m.MockServer]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Created connection to endpoint: [127.0.0.1]:5701, connection: MockConnection{localEndpoint=[127.0.0.1]:5702, remoteEndpoint=[127.0.0.1]:5701, alive=true}
2021-04-08 19:47:12,089 [ INFO] [hz.zealous_fermat.generic-operation.thread-0] [c.h.t.m.MockServer]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Created connection to endpoint: [127.0.0.1]:5702, connection: MockConnection{localEndpoint=[127.0.0.1]:5701, remoteEndpoint=[127.0.0.1]:5702, alive=true}
2021-04-08 19:47:12,091 [DEBUG] [hz.zealous_fermat.cached.thread-7] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Not starting jobs because partitions are not yet initialized.
2021-04-08 19:47:12,136 [ INFO] [hz.zealous_fermat.generic-operation.thread-0] [c.h.i.c.ClusterService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] 

Members {size:2, ver:2} [
    Member [127.0.0.1]:5701 - 61cdd91d-92bd-4e65-b6cd-e9309484be50 this
    Member [127.0.0.1]:5702 - 5ae77878-297a-4d22-ae4f-1060e0853c93
]

2021-04-08 19:47:12,195 [DEBUG] [hz.zealous_fermat.cached.thread-11] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Not starting jobs because partitions are not yet initialized.
2021-04-08 19:47:12,226 [ INFO] [hz.magical_fermat.generic-operation.thread-7] [c.h.i.c.ClusterService]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] 

Members {size:2, ver:2} [
    Member [127.0.0.1]:5701 - 61cdd91d-92bd-4e65-b6cd-e9309484be50
    Member [127.0.0.1]:5702 - 5ae77878-297a-4d22-ae4f-1060e0853c93 this
]

2021-04-08 19:47:12,296 [DEBUG] [hz.zealous_fermat.cached.thread-3] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Not starting jobs because partitions are not yet initialized.
2021-04-08 19:47:12,396 [DEBUG] [hz.zealous_fermat.cached.thread-3] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Not starting jobs because partitions are not yet initialized.
2021-04-08 19:47:12,497 [DEBUG] [hz.zealous_fermat.cached.thread-3] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Not starting jobs because partitions are not yet initialized.
2021-04-08 19:47:12,598 [DEBUG] [hz.zealous_fermat.cached.thread-3] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Not starting jobs because partitions are not yet initialized.
2021-04-08 19:47:12,621 [ INFO] [test_restartJob_nodeTerminated] [c.h.c.LifecycleService]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [127.0.0.1]:5702 is STARTED
2021-04-08 19:47:12,625 [ INFO] [hz.zealous_fermat.cached.thread-3] [c.h.i.p.i.PartitionStateManager]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Initializing cluster partition table arrangement...
2021-04-08 19:47:12,700 [DEBUG] [hz.zealous_fermat.cached.thread-3] [c.h.j.i.p.Planner]: Watermarks in the pipeline will be throttled to 100
2021-04-08 19:47:12,731 [ INFO] [hz.zealous_fermat.cached.thread-3] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Starting job 0601-006a-1b80-0001 based on submit request
2021-04-08 19:47:12,794 [ INFO] [hz.zealous_fermat.cached.thread-3] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Didn't find any snapshot to restore for job '0601-006a-1b80-0001', execution 0601-006a-1b81-0001
2021-04-08 19:47:12,794 [ INFO] [hz.zealous_fermat.cached.thread-3] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Start executing job '0601-006a-1b80-0001', execution 0601-006a-1b81-0001, execution graph in DOT format:
digraph DAG {
    "src" [localParallelism=1];
    "sliding-window-prepare" [localParallelism=72];
    "sliding-window" [localParallelism=1];
    "listSink(result-349848b7-4762-4b05-a1d3-532afebcd2ac)" [localParallelism=1];
    "src" -> "sliding-window-prepare" [queueSize=1024];
    subgraph cluster_0 {
        "sliding-window-prepare" -> "sliding-window" [label="distributed-partitioned", queueSize=1024];
    }
    "sliding-window" -> "listSink(result-349848b7-4762-4b05-a1d3-532afebcd2ac)" [queueSize=1024];
}
HINT: You can use graphviz or http://viz-js.com to visualize the printed graph.
2021-04-08 19:47:12,794 [DEBUG] [hz.zealous_fermat.cached.thread-3] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Building execution plan for job '0601-006a-1b80-0001', execution 0601-006a-1b81-0001
2021-04-08 19:47:12,795 [DEBUG] [hz.zealous_fermat.cached.thread-3] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Built execution plans for job '0601-006a-1b80-0001', execution 0601-006a-1b81-0001
2021-04-08 19:47:12,806 [DEBUG] [hz.zealous_fermat.cached.thread-3] [c.h.j.i.o.InitExecutionOperation]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Initializing execution plan for job 0601-006a-1b80-0001, execution 0601-006a-1b81-0001 from [127.0.0.1]:5701
2021-04-08 19:47:12,809 [DEBUG] [hz.zealous_fermat.cached.thread-6] [c.h.j.i.JobRepository]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Job cleanup took 21ms
2021-04-08 19:47:12,836 [ INFO] [hz.zealous_fermat.cached.thread-3] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Execution plan for jobId=0601-006a-1b80-0001, jobName='0601-006a-1b80-0001', executionId=0601-006a-1b81-0001 initialized
2021-04-08 19:47:12,839 [DEBUG] [hz.magical_fermat.generic-operation.thread-18] [c.h.j.i.o.InitExecutionOperation]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Initializing execution plan for job 0601-006a-1b80-0001, execution 0601-006a-1b81-0001 from [127.0.0.1]:5701
2021-04-08 19:47:12,851 [ INFO] [hz.magical_fermat.generic-operation.thread-18] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Execution plan for jobId=0601-006a-1b80-0001, jobName='0601-006a-1b80-0001', executionId=0601-006a-1b81-0001 initialized
2021-04-08 19:47:12,852 [DEBUG] [hz.zealous_fermat.cached.thread-3] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Init of job '0601-006a-1b80-0001', execution 0601-006a-1b81-0001 was successful
2021-04-08 19:47:12,852 [DEBUG] [hz.zealous_fermat.cached.thread-3] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Executing job '0601-006a-1b80-0001', execution 0601-006a-1b81-0001
2021-04-08 19:47:12,852 [ INFO] [hz.zealous_fermat.cached.thread-3] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Start execution of job '0601-006a-1b80-0001', execution 0601-006a-1b81-0001 from coordinator [127.0.0.1]:5701
2021-04-08 19:47:13,089 [DEBUG] [hz.zealous_fermat.cached.thread-3] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] job '0601-006a-1b80-0001', execution 0601-006a-1b81-0001 snapshot is scheduled in 500ms
2021-04-08 19:47:13,089 [ INFO] [hz.magical_fermat.generic-operation.thread-19] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Start execution of job '0601-006a-1b80-0001', execution 0601-006a-1b81-0001 from coordinator [127.0.0.1]:5701
2021-04-08 19:47:13,170 [DEBUG] [hz.zealous_fermat.cached.thread-3] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Not scaling up job '0601-006a-1b80-0001', execution 0601-006a-1b81-0001: not running or already running on all members
2021-04-08 19:47:14,023 [DEBUG] [hz.zealous_fermat.cached.thread-55] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Starting snapshot 0 for job '0601-006a-1b80-0001', execution 0601-006a-1b81-0001, flags: terminal=no,export=no, writing to: null
2021-04-08 19:47:14,024 [DEBUG] [hz.zealous_fermat.cached.thread-55] [c.h.j.i.e.ExecutionContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Starting snapshot 0 phase 1 for job '0601-006a-1b80-0001', execution 0601-006a-1b81-0001 on member
2021-04-08 19:47:14,024 [DEBUG] [hz.magical_fermat.generic-operation.thread-21] [c.h.j.i.e.ExecutionContext]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Starting snapshot 0 phase 1 for job '0601-006a-1b80-0001', execution 0601-006a-1b81-0001 on member
Will save 934 to snapshot
2021-04-08 19:47:14,036 [DEBUG] [hz.zealous_fermat.jet.cooperative.thread-0] [c.h.j.i.u.AsyncSnapshotWriterImpl]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Stats for src: keys=1, chunks=1, bytes=170
2021-04-08 19:47:14,086 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:00.000, end=00:00:00.100, value='100', isEarly=false} (eventTime=00:00:00.099)
2021-04-08 19:47:14,086 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:00.100, end=00:00:00.200, value='100', isEarly=false} (eventTime=00:00:00.199)
2021-04-08 19:47:14,086 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:00.200, end=00:00:00.300, value='100', isEarly=false} (eventTime=00:00:00.299)
2021-04-08 19:47:14,086 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:00.300, end=00:00:00.400, value='100', isEarly=false} (eventTime=00:00:00.399)
2021-04-08 19:47:14,086 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:00.400, end=00:00:00.500, value='100', isEarly=false} (eventTime=00:00:00.499)
2021-04-08 19:47:14,086 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:00.500, end=00:00:00.600, value='100', isEarly=false} (eventTime=00:00:00.599)
2021-04-08 19:47:14,086 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:00.600, end=00:00:00.700, value='100', isEarly=false} (eventTime=00:00:00.699)
2021-04-08 19:47:14,086 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:00.700}
2021-04-08 19:47:14,087 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:00.700, end=00:00:00.800, value='100', isEarly=false} (eventTime=00:00:00.799)
2021-04-08 19:47:14,087 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:00.800}
2021-04-08 19:47:14,087 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:00.800, end=00:00:00.900, value='100', isEarly=false} (eventTime=00:00:00.899)
2021-04-08 19:47:14,087 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:00.900}
2021-04-08 19:47:14,092 [DEBUG] [hz.zealous_fermat.jet.cooperative.thread-1] [c.h.j.i.u.AsyncSnapshotWriterImpl]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Stats for sliding-window-prepare: keys=0, chunks=0, bytes=0
2021-04-08 19:47:14,093 [ INFO] [hz.zealous_fermat.jet.cooperative.thread-4] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#0] Output to ordinal 0: Watermark{ts=00:00:00.900}
2021-04-08 19:47:14,242 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:00.900, end=00:00:01.000, value='100', isEarly=false} (eventTime=00:00:00.999)
2021-04-08 19:47:14,243 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:01.000}
2021-04-08 19:47:14,263 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:01.000, end=00:00:01.100, value='100', isEarly=false} (eventTime=00:00:01.099)
2021-04-08 19:47:14,263 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:01.100}
2021-04-08 19:47:14,271 [DEBUG] [hz.magical_fermat.jet.cooperative.thread-4] [c.h.j.i.u.AsyncSnapshotWriterImpl]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Stats for sliding-window: keys=2, chunks=2, bytes=216
2021-04-08 19:47:14,284 [DEBUG] [hz.magical_fermat.jet.cooperative.thread-6] [c.h.j.i.u.AsyncSnapshotWriterImpl]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Stats for listSink(result-349848b7-4762-4b05-a1d3-532afebcd2ac): keys=0, chunks=0, bytes=0
2021-04-08 19:47:14,538 [DEBUG] [hz.magical_fermat.jet.cooperative.thread-6] [c.h.j.i.o.SnapshotPhase1Operation]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Snapshot 0 phase 1 for job '0601-006a-1b80-0001', execution 0601-006a-1b81-0001 finished successfully on member
2021-04-08 19:47:14,646 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:01.100, end=00:00:01.200, value='100', isEarly=false} (eventTime=00:00:01.199)
2021-04-08 19:47:14,646 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:01.200}
2021-04-08 19:47:14,646 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:01.200, end=00:00:01.300, value='100', isEarly=false} (eventTime=00:00:01.299)
2021-04-08 19:47:14,646 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:01.300}
2021-04-08 19:47:14,646 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:01.300, end=00:00:01.400, value='100', isEarly=false} (eventTime=00:00:01.399)
2021-04-08 19:47:14,646 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:01.400}
2021-04-08 19:47:14,646 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:01.400, end=00:00:01.500, value='100', isEarly=false} (eventTime=00:00:01.499)
2021-04-08 19:47:14,646 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:01.500}
2021-04-08 19:47:14,711 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:01.500, end=00:00:01.600, value='100', isEarly=false} (eventTime=00:00:01.599)
2021-04-08 19:47:14,711 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:01.600}
2021-04-08 19:47:14,812 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:01.600, end=00:00:01.700, value='100', isEarly=false} (eventTime=00:00:01.699)
2021-04-08 19:47:14,812 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:01.700}
2021-04-08 19:47:14,909 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:01.700, end=00:00:01.800, value='100', isEarly=false} (eventTime=00:00:01.799)
2021-04-08 19:47:14,909 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:01.800}
2021-04-08 19:47:15,017 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:01.800, end=00:00:01.900, value='100', isEarly=false} (eventTime=00:00:01.899)
2021-04-08 19:47:15,018 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:01.900}
2021-04-08 19:47:15,103 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:01.900, end=00:00:02.000, value='100', isEarly=false} (eventTime=00:00:01.999)
2021-04-08 19:47:15,103 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:02.000}
2021-04-08 19:47:15,201 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:02.000, end=00:00:02.100, value='100', isEarly=false} (eventTime=00:00:02.099)
2021-04-08 19:47:15,201 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:02.100}
2021-04-08 19:47:15,298 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:02.100, end=00:00:02.200, value='100', isEarly=false} (eventTime=00:00:02.199)
2021-04-08 19:47:15,298 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:02.200}
2021-04-08 19:47:15,398 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:02.200, end=00:00:02.300, value='100', isEarly=false} (eventTime=00:00:02.299)
2021-04-08 19:47:15,398 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:02.300}
2021-04-08 19:47:15,498 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:02.300, end=00:00:02.400, value='100', isEarly=false} (eventTime=00:00:02.399)
2021-04-08 19:47:15,498 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:02.400}
2021-04-08 19:47:15,602 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:02.400, end=00:00:02.500, value='100', isEarly=false} (eventTime=00:00:02.499)
2021-04-08 19:47:15,602 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:02.500}
2021-04-08 19:47:15,697 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:02.500, end=00:00:02.600, value='100', isEarly=false} (eventTime=00:00:02.599)
2021-04-08 19:47:15,697 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:02.600}
2021-04-08 19:47:15,805 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:02.600, end=00:00:02.700, value='100', isEarly=false} (eventTime=00:00:02.699)
2021-04-08 19:47:15,805 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:02.700}
2021-04-08 19:47:15,895 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:02.700, end=00:00:02.800, value='100', isEarly=false} (eventTime=00:00:02.799)
2021-04-08 19:47:15,895 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:02.800}
2021-04-08 19:47:16,119 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:02.800, end=00:00:02.900, value='100', isEarly=false} (eventTime=00:00:02.899)
2021-04-08 19:47:16,119 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:02.900}
2021-04-08 19:47:16,119 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:02.900, end=00:00:03.000, value='100', isEarly=false} (eventTime=00:00:02.999)
2021-04-08 19:47:16,119 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:03.000}
2021-04-08 19:47:16,194 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:03.000, end=00:00:03.100, value='100', isEarly=false} (eventTime=00:00:03.099)
2021-04-08 19:47:16,194 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:03.100}
2021-04-08 19:47:16,301 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:03.100, end=00:00:03.200, value='100', isEarly=false} (eventTime=00:00:03.199)
2021-04-08 19:47:16,301 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:03.200}
2021-04-08 19:47:16,412 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:03.200, end=00:00:03.300, value='100', isEarly=false} (eventTime=00:00:03.299)
2021-04-08 19:47:16,412 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:03.300}
2021-04-08 19:47:16,521 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:03.300, end=00:00:03.400, value='100', isEarly=false} (eventTime=00:00:03.399)
2021-04-08 19:47:16,521 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:03.400}
2021-04-08 19:47:16,616 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:03.400, end=00:00:03.500, value='100', isEarly=false} (eventTime=00:00:03.499)
2021-04-08 19:47:16,616 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:03.500}
2021-04-08 19:47:16,715 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:03.500, end=00:00:03.600, value='100', isEarly=false} (eventTime=00:00:03.599)
2021-04-08 19:47:16,716 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:03.600}
2021-04-08 19:47:16,807 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:03.600, end=00:00:03.700, value='100', isEarly=false} (eventTime=00:00:03.699)
2021-04-08 19:47:16,807 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:03.700}
2021-04-08 19:47:16,907 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:03.700, end=00:00:03.800, value='100', isEarly=false} (eventTime=00:00:03.799)
2021-04-08 19:47:16,907 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:03.800}
2021-04-08 19:47:17,002 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:03.800, end=00:00:03.900, value='100', isEarly=false} (eventTime=00:00:03.899)
2021-04-08 19:47:17,002 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:03.900}
2021-04-08 19:47:17,098 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:03.900, end=00:00:04.000, value='100', isEarly=false} (eventTime=00:00:03.999)
2021-04-08 19:47:17,098 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:04.000}
2021-04-08 19:47:17,206 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:04.000, end=00:00:04.100, value='100', isEarly=false} (eventTime=00:00:04.099)
2021-04-08 19:47:17,206 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:04.100}
2021-04-08 19:47:17,319 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:04.100, end=00:00:04.200, value='100', isEarly=false} (eventTime=00:00:04.199)
2021-04-08 19:47:17,319 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:04.200}
2021-04-08 19:47:17,399 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:04.200, end=00:00:04.300, value='100', isEarly=false} (eventTime=00:00:04.299)
2021-04-08 19:47:17,399 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:04.300}
2021-04-08 19:47:17,502 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:04.300, end=00:00:04.400, value='100', isEarly=false} (eventTime=00:00:04.399)
2021-04-08 19:47:17,502 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:04.400}
2021-04-08 19:47:17,661 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:04.400, end=00:00:04.500, value='100', isEarly=false} (eventTime=00:00:04.499)
2021-04-08 19:47:17,662 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:04.500}
2021-04-08 19:47:17,712 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:04.500, end=00:00:04.600, value='100', isEarly=false} (eventTime=00:00:04.599)
2021-04-08 19:47:17,712 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:04.600}
2021-04-08 19:47:17,803 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:04.600, end=00:00:04.700, value='100', isEarly=false} (eventTime=00:00:04.699)
2021-04-08 19:47:17,803 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:04.700}
2021-04-08 19:47:17,909 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:04.700, end=00:00:04.800, value='100', isEarly=false} (eventTime=00:00:04.799)
2021-04-08 19:47:17,909 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:04.800}
2021-04-08 19:47:17,911 [DEBUG] [hz.zealous_fermat.cached.thread-49] [c.h.j.i.JobRepository]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Job cleanup took 39ms
2021-04-08 19:47:18,010 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:04.800, end=00:00:04.900, value='100', isEarly=false} (eventTime=00:00:04.899)
2021-04-08 19:47:18,010 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:04.900}
2021-04-08 19:47:18,121 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:04.900, end=00:00:05.000, value='100', isEarly=false} (eventTime=00:00:04.999)
2021-04-08 19:47:18,121 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:05.000}
2021-04-08 19:47:18,233 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:05.000, end=00:00:05.100, value='100', isEarly=false} (eventTime=00:00:05.099)
2021-04-08 19:47:18,233 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:05.100}
2021-04-08 19:47:18,360 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:05.100, end=00:00:05.200, value='100', isEarly=false} (eventTime=00:00:05.199)
2021-04-08 19:47:18,360 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:05.200}
2021-04-08 19:47:18,418 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:05.200, end=00:00:05.300, value='100', isEarly=false} (eventTime=00:00:05.299)
2021-04-08 19:47:18,418 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:05.300}
2021-04-08 19:47:18,507 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:05.300, end=00:00:05.400, value='100', isEarly=false} (eventTime=00:00:05.399)
2021-04-08 19:47:18,507 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:05.400}
2021-04-08 19:47:18,614 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:05.400, end=00:00:05.500, value='100', isEarly=false} (eventTime=00:00:05.499)
2021-04-08 19:47:18,614 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:05.500}
2021-04-08 19:47:18,700 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:05.500, end=00:00:05.600, value='100', isEarly=false} (eventTime=00:00:05.599)
2021-04-08 19:47:18,700 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:05.600}
2021-04-08 19:47:18,807 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:05.600, end=00:00:05.700, value='100', isEarly=false} (eventTime=00:00:05.699)
2021-04-08 19:47:18,807 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:05.700}
2021-04-08 19:47:18,898 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:05.700, end=00:00:05.800, value='100', isEarly=false} (eventTime=00:00:05.799)
2021-04-08 19:47:18,898 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:05.800}
2021-04-08 19:47:19,008 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:05.800, end=00:00:05.900, value='100', isEarly=false} (eventTime=00:00:05.899)
2021-04-08 19:47:19,008 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:05.900}
2021-04-08 19:47:19,108 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:05.900, end=00:00:06.000, value='100', isEarly=false} (eventTime=00:00:05.999)
2021-04-08 19:47:19,108 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:06.000}
2021-04-08 19:47:19,205 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:06.000, end=00:00:06.100, value='100', isEarly=false} (eventTime=00:00:06.099)
2021-04-08 19:47:19,205 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:06.100}
2021-04-08 19:47:19,303 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:06.100, end=00:00:06.200, value='100', isEarly=false} (eventTime=00:00:06.199)
2021-04-08 19:47:19,304 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:06.200}
2021-04-08 19:47:19,414 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:06.200, end=00:00:06.300, value='100', isEarly=false} (eventTime=00:00:06.299)
2021-04-08 19:47:19,414 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:06.300}
2021-04-08 19:47:19,513 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:06.300, end=00:00:06.400, value='100', isEarly=false} (eventTime=00:00:06.399)
2021-04-08 19:47:19,513 [ INFO] [hz.magical_fermat.jet.cooperative.t
...[truncated 3555 chars]...
-window#1] Output to ordinal 0: WindowResult{start=00:00:07.000, end=00:00:07.100, value='100', isEarly=false} (eventTime=00:00:07.099)
2021-04-08 19:47:20,205 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:07.100}
2021-04-08 19:47:20,297 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:07.100, end=00:00:07.200, value='100', isEarly=false} (eventTime=00:00:07.199)
2021-04-08 19:47:20,297 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:07.200}
2021-04-08 19:47:20,428 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:07.200, end=00:00:07.300, value='100', isEarly=false} (eventTime=00:00:07.299)
2021-04-08 19:47:20,428 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:07.300}
2021-04-08 19:47:20,519 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:07.300, end=00:00:07.400, value='100', isEarly=false} (eventTime=00:00:07.399)
2021-04-08 19:47:20,519 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:07.400}
2021-04-08 19:47:20,633 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:07.400, end=00:00:07.500, value='100', isEarly=false} (eventTime=00:00:07.499)
2021-04-08 19:47:20,633 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:07.500}
2021-04-08 19:47:20,734 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:07.500, end=00:00:07.600, value='100', isEarly=false} (eventTime=00:00:07.599)
2021-04-08 19:47:20,735 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:07.600}
2021-04-08 19:47:20,829 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:07.600, end=00:00:07.700, value='100', isEarly=false} (eventTime=00:00:07.699)
2021-04-08 19:47:20,829 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:07.700}
2021-04-08 19:47:20,930 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:07.700, end=00:00:07.800, value='100', isEarly=false} (eventTime=00:00:07.799)
2021-04-08 19:47:20,930 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:07.800}
2021-04-08 19:47:21,033 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:07.800, end=00:00:07.900, value='100', isEarly=false} (eventTime=00:00:07.899)
2021-04-08 19:47:21,033 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:07.900}
2021-04-08 19:47:21,134 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:07.900, end=00:00:08.000, value='100', isEarly=false} (eventTime=00:00:07.999)
2021-04-08 19:47:21,134 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:08.000}
2021-04-08 19:47:21,239 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:08.000, end=00:00:08.100, value='100', isEarly=false} (eventTime=00:00:08.099)
2021-04-08 19:47:21,239 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:08.100}
2021-04-08 19:47:21,335 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:08.100, end=00:00:08.200, value='100', isEarly=false} (eventTime=00:00:08.199)
2021-04-08 19:47:21,335 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:08.200}
2021-04-08 19:47:21,432 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:08.200, end=00:00:08.300, value='100', isEarly=false} (eventTime=00:00:08.299)
2021-04-08 19:47:21,432 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:08.300}
2021-04-08 19:47:21,531 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:08.300, end=00:00:08.400, value='100', isEarly=false} (eventTime=00:00:08.399)
2021-04-08 19:47:21,531 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:08.400}
2021-04-08 19:47:21,668 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:08.400, end=00:00:08.500, value='100', isEarly=false} (eventTime=00:00:08.499)
2021-04-08 19:47:21,668 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:08.500}
2021-04-08 19:47:21,731 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:08.500, end=00:00:08.600, value='100', isEarly=false} (eventTime=00:00:08.599)
2021-04-08 19:47:21,731 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:08.600}
2021-04-08 19:47:21,831 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:08.600, end=00:00:08.700, value='100', isEarly=false} (eventTime=00:00:08.699)
2021-04-08 19:47:21,831 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:08.700}
2021-04-08 19:47:21,987 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:08.700, end=00:00:08.800, value='100', isEarly=false} (eventTime=00:00:08.799)
2021-04-08 19:47:21,987 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:08.800}
2021-04-08 19:47:22,064 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:08.800, end=00:00:08.900, value='100', isEarly=false} (eventTime=00:00:08.899)
2021-04-08 19:47:22,064 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:08.900}
2021-04-08 19:47:22,144 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:08.900, end=00:00:09.000, value='100', isEarly=false} (eventTime=00:00:08.999)
2021-04-08 19:47:22,144 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:09.000}
2021-04-08 19:47:22,208 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:09.000, end=00:00:09.100, value='100', isEarly=false} (eventTime=00:00:09.099)
2021-04-08 19:47:22,208 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:09.100}
2021-04-08 19:47:22,327 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:09.100, end=00:00:09.200, value='100', isEarly=false} (eventTime=00:00:09.199)
2021-04-08 19:47:22,327 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:09.200}
2021-04-08 19:47:22,459 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:09.200, end=00:00:09.300, value='100', isEarly=false} (eventTime=00:00:09.299)
2021-04-08 19:47:22,459 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:09.300}
2021-04-08 19:47:22,524 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:09.300, end=00:00:09.400, value='100', isEarly=false} (eventTime=00:00:09.399)
2021-04-08 19:47:22,524 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:09.400}
2021-04-08 19:47:22,611 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:09.400, end=00:00:09.500, value='100', isEarly=false} (eventTime=00:00:09.499)
2021-04-08 19:47:22,611 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:09.500}
2021-04-08 19:47:22,795 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:09.500, end=00:00:09.600, value='100', isEarly=false} (eventTime=00:00:09.599)
2021-04-08 19:47:22,795 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:09.600}
2021-04-08 19:47:22,894 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:09.600, end=00:00:09.700, value='100', isEarly=false} (eventTime=00:00:09.699)
2021-04-08 19:47:22,894 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:09.700}
2021-04-08 19:47:22,925 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:09.700, end=00:00:09.800, value='100', isEarly=false} (eventTime=00:00:09.799)
2021-04-08 19:47:22,925 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:09.800}
2021-04-08 19:47:22,945 [DEBUG] [hz.zealous_fermat.cached.thread-50] [c.h.j.i.JobRepository]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Job cleanup took 12ms
2021-04-08 19:47:23,092 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:09.800, end=00:00:09.900, value='100', isEarly=false} (eventTime=00:00:09.899)
2021-04-08 19:47:23,092 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:09.900}
2021-04-08 19:47:23,196 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:09.900, end=00:00:10.000, value='100', isEarly=false} (eventTime=00:00:09.999)
2021-04-08 19:47:23,196 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:10.000}
2021-04-08 19:47:23,216 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:10.000, end=00:00:10.100, value='100', isEarly=false} (eventTime=00:00:10.099)
2021-04-08 19:47:23,216 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:10.100}
2021-04-08 19:47:23,316 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:10.100, end=00:00:10.200, value='100', isEarly=false} (eventTime=00:00:10.199)
2021-04-08 19:47:23,316 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:10.200}
2021-04-08 19:47:23,439 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:10.200, end=00:00:10.300, value='100', isEarly=false} (eventTime=00:00:10.299)
2021-04-08 19:47:23,439 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:10.300}
2021-04-08 19:47:23,592 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:10.300, end=00:00:10.400, value='100', isEarly=false} (eventTime=00:00:10.399)
2021-04-08 19:47:23,592 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:10.400}
2021-04-08 19:47:23,671 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:10.400, end=00:00:10.500, value='100', isEarly=false} (eventTime=00:00:10.499)
2021-04-08 19:47:23,671 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:10.500}
2021-04-08 19:47:23,710 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:10.500, end=00:00:10.600, value='100', isEarly=false} (eventTime=00:00:10.599)
2021-04-08 19:47:23,710 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:10.600}
2021-04-08 19:47:23,893 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:10.600, end=00:00:10.700, value='100', isEarly=false} (eventTime=00:00:10.699)
2021-04-08 19:47:23,893 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:10.700}
2021-04-08 19:47:24,004 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:10.700, end=00:00:10.800, value='100', isEarly=false} (eventTime=00:00:10.799)
2021-04-08 19:47:24,004 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:10.800}
2021-04-08 19:47:24,092 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:10.800, end=00:00:10.900, value='100', isEarly=false} (eventTime=00:00:10.899)
2021-04-08 19:47:24,093 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:10.900}
2021-04-08 19:47:24,156 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:10.900, end=00:00:11.000, value='100', isEarly=false} (eventTime=00:00:10.999)
2021-04-08 19:47:24,157 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:11.000}
2021-04-08 19:47:24,244 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: WindowResult{start=00:00:11.000, end=00:00:11.100, value='100', isEarly=false} (eventTime=00:00:11.099)
2021-04-08 19:47:24,244 [ INFO] [hz.magical_fermat.jet.cooperative.thread-5] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#1] Output to ordinal 0: Watermark{ts=00:00:11.100}
2021-04-08 19:47:24,665 [ INFO] [Time-limited test] [c.h.j.c.JetTestSupport]: Terminating instanceFactory in JetTestSupport.@After
2021-04-08 19:47:24,666 [ INFO] [Thread-198] [c.h.c.LifecycleService]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [127.0.0.1]:5702 is SHUTTING_DOWN
2021-04-08 19:47:24,667 [ WARN] [Thread-198] [c.h.i.i.Node]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Terminating forcefully...
2021-04-08 19:47:24,667 [ INFO] [Thread-198] [c.h.i.i.Node]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Shutting down connection manager...
2021-04-08 19:47:24,667 [ INFO] [Thread-198] [c.h.t.m.MockServer]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Removed connection to endpoint: [127.0.0.1]:5702, connection: MockConnection{localEndpoint=[127.0.0.1]:5701, remoteEndpoint=[127.0.0.1]:5702, alive=false}
2021-04-08 19:47:24,667 [ INFO] [Thread-198] [c.h.t.m.MockServer]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Removed connection to endpoint: [127.0.0.1]:5701, connection: MockConnection{localEndpoint=[127.0.0.1]:5702, remoteEndpoint=[127.0.0.1]:5701, alive=false}
2021-04-08 19:47:24,667 [ INFO] [Thread-198] [c.h.i.c.i.MembershipManager]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Removing Member [127.0.0.1]:5702 - 5ae77878-297a-4d22-ae4f-1060e0853c93
2021-04-08 19:47:24,667 [ INFO] [Thread-198] [c.h.i.c.ClusterService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] 

Members {size:1, ver:3} [
    Member [127.0.0.1]:5701 - 61cdd91d-92bd-4e65-b6cd-e9309484be50 this
]

2021-04-08 19:47:24,668 [ INFO] [Thread-198] [c.h.i.i.Node]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Shutting down node engine...
2021-04-08 19:47:24,688 [ WARN] [hz.zealous_fermat.async.thread-1] [c.h.j.i.o.SnapshotPhase1Operation]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Snapshot 0 phase 1 for job '0601-006a-1b80-0001', execution 0601-006a-1b81-0001 finished with an error on member: java.util.concurrent.CancellationException: execution cancelled
2021-04-08 19:47:24,689 [ERROR] [ForkJoinPool.commonPool-worker-235] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] job '0601-006a-1b80-0001', execution 0601-006a-1b81-0001: some TerminateExecutionOperation invocations failed, execution might remain stuck: [MemberInfo{address=[127.0.0.1]:5701, uuid=61cdd91d-92bd-4e65-b6cd-e9309484be50, liteMember=false, memberListJoinVersion=1}=null, MemberInfo{address=[127.0.0.1]:5702, uuid=5ae77878-297a-4d22-ae4f-1060e0853c93, liteMember=false, memberListJoinVersion=2}=com.hazelcast.spi.exception.TargetNotMemberException: Not Member! target: [127.0.0.1]:5702, partitionId: -1, operation: com.hazelcast.jet.impl.operation.TerminateExecutionOperation, service: hz:impl:jetService]
2021-04-08 19:47:24,719 [ WARN] [hz.magical_fermat.jet.cooperative.thread-7] [c.h.j.i.e.TaskletExecutionService]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Exception in ReceiverTasklet
com.hazelcast.jet.RestartableException: The member was reconnected: [127.0.0.1]:5701
    at com.hazelcast.jet.impl.execution.ReceiverTasklet.call(ReceiverTasklet.java:150) ~[classes/:?]
    at com.hazelcast.jet.impl.execution.TaskletExecutionService$CooperativeWorker.runTasklet(TaskletExecutionService.java:367) ~[classes/:?]
    at java.util.concurrent.CopyOnWriteArrayList.forEach(CopyOnWriteArrayList.java:803) [?:?]
    at com.hazelcast.jet.impl.execution.TaskletExecutionService$CooperativeWorker.run(TaskletExecutionService.java:347) [classes/:?]
    at java.lang.Thread.run(Thread.java:834) [?:?]
2021-04-08 19:47:24,725 [DEBUG] [hz.magical_fermat.jet.cooperative.thread-6] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Execution of job '0601-006a-1b80-0001', execution 0601-006a-1b81-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
    at java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:331) ~[?:?]
    at java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:346) ~[?:?]
    at java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:632) ~[?:?]
    at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:506) ~[?:?]
    at java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:2088) ~[?:?]
    at com.hazelcast.jet.impl.util.NonCompletableFuture.internalCompleteExceptionally(NonCompletableFuture.java:59) ~[classes/:?]
    at com.hazelcast.jet.impl.execution.TaskletExecutionService$ExecutionTracker.taskletDone(TaskletExecutionService.java:468) ~[classes/:?]
    at com.hazelcast.jet.impl.execution.TaskletExecutionService$CooperativeWorker.dismissTasklet(TaskletExecutionService.java:399) ~[classes/:?]
    at com.hazelcast.jet.impl.execution.TaskletExecutionService$CooperativeWorker.runTasklet(TaskletExecutionService.java:385) ~[classes/:?]
    at java.util.concurrent.CopyOnWriteArrayList.forEach(CopyOnWriteArrayList.java:803) [?:?]
    at com.hazelcast.jet.impl.execution.TaskletExecutionService$CooperativeWorker.run(TaskletExecutionService.java:347) [classes/:?]
    at java.lang.Thread.run(Thread.java:834) [?:?]
Caused by: com.hazelcast.jet.JetException: Exception in ReceiverTasklet: com.hazelcast.jet.RestartableException: The member was reconnected: [127.0.0.1]:5701
    at com.hazelcast.jet.impl.execution.TaskletExecutionService$CooperativeWorker.runTasklet(TaskletExecutionService.java:379) ~[classes/:?]
    ... 3 more
Caused by: com.hazelcast.jet.RestartableException: The member was reconnected: [127.0.0.1]:5701
    at com.hazelcast.jet.impl.execution.ReceiverTasklet.call(ReceiverTasklet.java:150) ~[classes/:?]
    at com.hazelcast.jet.impl.execution.TaskletExecutionService$CooperativeWorker.runTasklet(TaskletExecutionService.java:367) ~[classes/:?]
    ... 3 more
2021-04-08 19:47:24,766 [ INFO] [hz.zealous_fermat.cached.thread-52] [c.h.i.p.InternalPartitionService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Remaining migration tasks: 1. (repartitionTime=Thu Jan 01 00:00:00 UTC 1970, plannedMigrations=0, completedMigrations=0, remainingMigrations=0, totalCompletedMigrations=0, elapsedMigrationOperationTime=0ms, totalElapsedMigrationOperationTime=0ms, elapsedDestinationCommitTime=0ms, totalElapsedDestinationCommitTime=0ms, elapsedMigrationTime=0ms, totalElapsedMigrationTime=0ms)
2021-04-08 19:47:24,766 [ INFO] [hz.zealous_fermat.cached.thread-48] [c.h.t.TransactionManagerService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Committing/rolling-back live transactions of [127.0.0.1]:5702, UUID: 5ae77878-297a-4d22-ae4f-1060e0853c93
2021-04-08 19:47:24,767 [DEBUG] [hz.zealous_fermat.cached.thread-48] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Completing job '0601-006a-1b80-0001', execution 0601-006a-1b81-0001 locally. Reason: Member [127.0.0.1]:5702 left the cluster
2021-04-08 19:47:24,767 [DEBUG] [hz.zealous_fermat.cached.thread-48] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Completed execution of job '0601-006a-1b80-0001', execution 0601-006a-1b81-0001
2021-04-08 19:47:24,759 [DEBUG] [hz.zealous_fermat.jet.cooperative.thread-5] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Execution of job '0601-006a-1b80-0001', execution 0601-006a-1b81-0001 completed with failure
java.util.concurrent.CompletionException: java.util.concurrent.CancellationException
    at java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:331) ~[?:?]
    at java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:346) ~[?:?]
    at java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:632) ~[?:?]
    at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:506) ~[?:?]
    at java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:2088) ~[?:?]
    at com.hazelcast.jet.impl.util.NonCompletableFuture.internalCompleteExceptionally(NonCompletableFuture.java:59) ~[classes/:?]
    at com.hazelcast.jet.impl.execution.TaskletExecutionService$ExecutionTracker.taskletDone(TaskletExecutionService.java:468) ~[classes/:?]
    at com.hazelcast.jet.impl.execution.TaskletExecutionService$CooperativeWorker.dismissTasklet(TaskletExecutionService.java:399) ~[classes/:?]
    at com.hazelcast.jet.impl.execution.TaskletExecutionService$CooperativeWorker.runTasklet(TaskletExecutionService.java:385) ~[classes/:?]
    at java.util.concurrent.CopyOnWriteArrayList.forEach(CopyOnWriteArrayList.java:803) [?:?]
    at com.hazelcast.jet.impl.execution.TaskletExecutionService$CooperativeWorker.run(TaskletExecutionService.java:347) [classes/:?]
    at java.lang.Thread.run(Thread.java:834) [?:?]
Caused by: java.util.concurrent.CancellationException
    at java.util.concurrent.CompletableFuture.cancel(CompletableFuture.java:2396) ~[?:?]
    at com.hazelcast.jet.impl.execution.ExecutionContext.terminateExecution(ExecutionContext.java:233) ~[classes/:?]
    at com.hazelcast.jet.impl.operation.TerminateExecutionOperation.run(TerminateExecutionOperation.java:61) ~[classes/:?]
    at com.hazelcast.spi.impl.operationservice.Operation.call(Operation.java:189) ~[hazelcast-4.2.jar:4.2]
    at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.call(OperationRunnerImpl.java:272) ~[hazelcast-4.2.jar:4.2]
    at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:248) ~[hazelcast-4.2.jar:4.2]
    at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:213) ~[hazelcast-4.2.jar:4.2]
    at com.hazelcast.spi.impl.operationexecutor.impl.OperationExecutorImpl.run(OperationExecutorImpl.java:411) ~[hazelcast-4.2.jar:4.2]
    at com.hazelcast.spi.impl.operationexecutor.impl.OperationExecutorImpl.runOrExecute(OperationExecutorImpl.java:438) ~[hazelcast-4.2.jar:4.2]
    at com.hazelcast.spi.impl.operationservice.impl.Invocation.doInvokeLocal(Invocation.java:600) ~[hazelcast-4.2.jar:4.2]
    at com.hazelcast.spi.impl.operationservice.impl.Invocation.doInvoke(Invocation.java:579) ~[hazelcast-4.2.jar:4.2]
    at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke0(Invocation.java:540) ~[hazelcast-4.2.jar:4.2]
    at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke(Invocation.java:240) ~[hazelcast-4.2.jar:4.2]
    at com.hazelcast.spi.impl.operationservice.impl.InvocationBuilderImpl.invoke(InvocationBuilderImpl.java:59) ~[hazelcast-4.2.jar:4.2]
    at com.hazelcast.jet.impl.MasterContext.invokeOnParticipant(MasterContext.java:264) ~[classes/:?]
    at com.hazelcast.jet.impl.MasterContext.invokeOnParticipants(MasterContext.java:247) ~[classes/:?]
    at com.hazelcast.jet.impl.MasterJobContext.lambda$cancelExecutionInvocations$16(MasterJobContext.java:601) ~[classes/:?]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) ~[?:?]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[?:?]
    at java.lang.Thread.run(Thread.java:834) ~[?:?]
    at com.hazelcast.internal.util.executor.HazelcastManagedThread.executeRun(HazelcastManagedThread.java:76) ~[hazelcast-4.2.jar:4.2]
    at com.hazelcast.internal.util.executor.HazelcastManagedThread.run(HazelcastManagedThread.java:102) ~[hazelcast-4.2.jar:4.2]
2021-04-08 19:47:24,768 [DEBUG] [ForkJoinPool.commonPool-worker-149] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Execution of job '0601-006a-1b80-0001', execution 0601-006a-1b81-0001 has failures: [[127.0.0.1]:5701=java.util.concurrent.CancellationException, [127.0.0.1]:5702=com.hazelcast.core.MemberLeftException: Member [127.0.0.1]:5702 - 5ae77878-297a-4d22-ae4f-1060e0853c93 has left cluster!]
2021-04-08 19:47:24,769 [DEBUG] [hz.zealous_fermat.cached.thread-48] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Sending CompleteExecutionOperation for job '0601-006a-1b80-0001', execution 0601-006a-1b81-0001
2021-04-08 19:47:24,769 [DEBUG] [hz.zealous_fermat.cached.thread-48] [c.h.j.i.o.CompleteExecutionOperation]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Completing execution 0601-006a-1b81-0001 from caller [127.0.0.1]:5701, error=com.hazelcast.jet.core.TopologyChangedException: Causes from members: [[127.0.0.1]:5701=java.util.concurrent.CancellationException, [127.0.0.1]:5702=com.hazelcast.core.MemberLeftException: Member [127.0.0.1]:5702 - 5ae77878-297a-4d22-ae4f-1060e0853c93 has left cluster!]
2021-04-08 19:47:24,769 [DEBUG] [hz.zealous_fermat.cached.thread-48] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Execution 0601-006a-1b81-0001 not found for completion
2021-04-08 19:47:24,769 [ERROR] [ForkJoinPool.commonPool-worker-149] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] job '0601-006a-1b80-0001', execution 0601-006a-1b81-0001: some CompleteExecutionOperation invocations failed, execution resources might leak: [MemberInfo{address=[127.0.0.1]:5701, uuid=61cdd91d-92bd-4e65-b6cd-e9309484be50, liteMember=false, memberListJoinVersion=1}=null @ 1617911244769, MemberInfo{address=[127.0.0.1]:5702, uuid=5ae77878-297a-4d22-ae4f-1060e0853c93, liteMember=false, memberListJoinVersion=2}=com.hazelcast.spi.exception.TargetNotMemberException: Not Member! target: [127.0.0.1]:5702, partitionId: -1, operation: com.hazelcast.jet.impl.operation.CompleteExecutionOperation, service: hz:impl:jetService]
2021-04-08 19:47:24,845 [DEBUG] [Thread-198] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Completing job '0601-006a-1b80-0001', execution 0601-006a-1b81-0001 locally. Reason: Node is shutting down
2021-04-08 19:47:24,845 [DEBUG] [Thread-198] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Completed execution of job '0601-006a-1b80-0001', execution 0601-006a-1b81-0001
2021-04-08 19:47:24,976 [DEBUG] [hz.zealous_fermat.cached.thread-50] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Snapshot 0 phase 1 for job '0601-006a-1b80-0001', execution 0601-006a-1b81-0001 completed with status FAILURE in 10905ms, 386 bytes, 3 keys in 3 chunks, stored in '__jet.snapshot.0601-006a-1b80-0001.0', proceeding to phase 2
2021-04-08 19:47:24,976 [ WARN] [hz.zealous_fermat.cached.thread-50] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] job '0601-006a-1b80-0001', execution 0601-006a-1b81-0001 snapshot 0 phase 1 failed on some member(s), one of the failures: java.util.concurrent.CancellationException: execution cancelled
2021-04-08 19:47:25,359 [ INFO] [Thread-198] [c.h.i.i.NodeExtension]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Destroying node NodeExtension.
2021-04-08 19:47:25,375 [ INFO] [hz.zealous_fermat.migration] [c.h.i.p.i.MigrationManager]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Partition balance is ok, no need to repartition.
2021-04-08 19:47:25,377 [DEBUG] [hz.zealous_fermat.cached.thread-50] [c.h.j.i.JobRepository]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Cleared snapshot data map __jet.snapshot.0601-006a-1b80-0001.0
2021-04-08 19:47:25,377 [ERROR] [hz.zealous_fermat.cached.thread-50] [c.h.j.i.o.SnapshotPhase2Operation]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] job 0601-006a-1b80-0001, execution 0601-006a-1b81-0001 not found for coordinator [127.0.0.1]:5701 for 'SnapshotPhase2Operation'
com.hazelcast.jet.core.TopologyChangedException: job 0601-006a-1b80-0001, execution 0601-006a-1b81-0001 not found for coordinator [127.0.0.1]:5701 for 'SnapshotPhase2Operation'
    at com.hazelcast.jet.impl.JobExecutionService.assertExecutionContext(JobExecutionService.java:326) ~[classes/:?]
    at com.hazelcast.jet.impl.operation.SnapshotPhase2Operation.doRun(SnapshotPhase2Operation.java:50) ~[classes/:?]
    at com.hazelcast.jet.impl.operation.AsyncOperation.run(AsyncOperation.java:53) ~[classes/:?]
    at com.hazelcast.spi.impl.operationservice.Operation.call(Operation.java:189) ~[hazelcast-4.2.jar:4.2]
    at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.call(OperationRunnerImpl.java:272) ~[hazelcast-4.2.jar:4.2]
    at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:248) ~[hazelcast-4.2.jar:4.2]
    at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:213) ~[hazelcast-4.2.jar:4.2]
    at com.hazelcast.spi.impl.operationexecutor.impl.OperationExecutorImpl.run(OperationExecutorImpl.java:411) ~[hazelcast-4.2.jar:4.2]
    at com.hazelcast.spi.impl.operationexecutor.impl.OperationExecutorImpl.runOrExecute(OperationExecutorImpl.java:438) ~[hazelcast-4.2.jar:4.2]
    at com.hazelcast.spi.impl.operationservice.impl.Invocation.doInvokeLocal(Invocation.java:600) ~[hazelcast-4.2.jar:4.2]
    at com.hazelcast.spi.impl.operationservice.impl.Invocation.doInvoke(Invocation.java:579) ~[hazelcast-4.2.jar:4.2]
    at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke0(Invocation.java:540) ~[hazelcast-4.2.jar:4.2]
    at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke(Invocation.java:240) ~[hazelcast-4.2.jar:4.2]
    at com.hazelcast.spi.impl.operationservice.impl.InvocationBuilderImpl.invoke(InvocationBuilderImpl.java:59) ~[hazelcast-4.2.jar:4.2]
    at com.hazelcast.jet.impl.MasterContext.invokeOnParticipant(MasterContext.java:264) ~[classes/:?]
    at com.hazelcast.jet.impl.MasterContext.invokeOnParticipants(MasterContext.java:247) ~[classes/:?]
    at com.hazelcast.jet.impl.MasterSnapshotContext.lambda$onSnapshotPhase1Complete$5(MasterSnapshotContext.java:277) ~[classes/:?]
    at com.hazelcast.jet.impl.JobCoordinationService.lambda$submitToCoordinatorThread$46(JobCoordinationService.java:1039) ~[classes/:?]
    at com.hazelcast.jet.impl.JobCoordinationService.lambda$submitToCoordinatorThread$47(JobCoordinationService.java:1060) ~[classes/:?]
    at com.hazelcast.internal.util.executor.CompletableFutureTask.run(CompletableFutureTask.java:64) [hazelcast-4.2.jar:4.2]
    at com.hazelcast.internal.util.executor.CachedExecutorServiceDelegate$Worker.run(CachedExecutorServiceDelegate.java:217) [hazelcast-4.2.jar:4.2]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
    at java.lang.Thread.run(Thread.java:834) [?:?]
    at com.hazelcast.internal.util.executor.HazelcastManagedThread.executeRun(HazelcastManagedThread.java:76) [hazelcast-4.2.jar:4.2]
    at com.hazelcast.internal.util.executor.HazelcastManagedThread.run(HazelcastManagedThread.java:102) [hazelcast-4.2.jar:4.2]
2021-04-08 19:47:25,383 [DEBUG] [hz.zealous_fermat.cached.thread-51] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Scheduling restart on master for job 0601-006a-1b80-0001
2021-04-08 19:47:25,404 [ INFO] [Thread-198] [c.h.i.i.Node]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Hazelcast Shutdown is completed in 737 ms.
2021-04-08 19:47:25,404 [ INFO] [Thread-198] [c.h.c.LifecycleService]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [127.0.0.1]:5702 is SHUTDOWN
2021-04-08 19:47:25,404 [ INFO] [Thread-198] [c.h.c.LifecycleService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] [127.0.0.1]:5701 is SHUTTING_DOWN
2021-04-08 19:47:25,405 [ WARN] [Thread-198] [c.h.i.i.Node]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Terminating forcefully...
2021-04-08 19:47:25,405 [ INFO] [Thread-198] [c.h.i.i.Node]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Shutting down connection manager...
2021-04-08 19:47:25,405 [ INFO] [Thread-198] [c.h.i.i.Node]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Shutting down node engine...
2021-04-08 19:47:25,378 [ WARN] [hz.zealous_fermat.cached.thread-64] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] SnapshotPhase2Operation for snapshot 0 in job '0601-006a-1b80-0001', execution 0601-006a-1b81-0001 failed on member: MemberInfo{address=[127.0.0.1]:5701, uuid=61cdd91d-92bd-4e65-b6cd-e9309484be50, liteMember=false, memberListJoinVersion=1}=com.hazelcast.jet.core.TopologyChangedException: job 0601-006a-1b80-0001, execution 0601-006a-1b81-0001 not found for coordinator [127.0.0.1]:5701 for 'SnapshotPhase2Operation'
com.hazelcast.jet.core.TopologyChangedException: job 0601-006a-1b80-0001, execution 0601-006a-1b81-0001 not found for coordinator [127.0.0.1]:5701 for 'SnapshotPhase2Operation'
    at com.hazelcast.jet.impl.JobExecutionService.assertExecutionContext(JobExecutionService.java:326) ~[classes/:?]
    at com.hazelcast.jet.impl.operation.SnapshotPhase2Operation.doRun(SnapshotPhase2Operation.java:50) ~[classes/:?]
    at com.hazelcast.jet.impl.operation.AsyncOperation.run(AsyncOperation.java:53) ~[classes/:?]
    at com.hazelcast.spi.impl.operationservice.Operation.call(Operation.java:189) ~[hazelcast-4.2.jar:4.2]
    at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.call(OperationRunnerImpl.java:272) ~[hazelcast-4.2.jar:4.2]
    at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:248) ~[hazelcast-4.2.jar:4.2]
    at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:213) ~[hazelcast-4.2.jar:4.2]
    at com.hazelcast.spi.impl.operationexecutor.impl.OperationExecutorImpl.run(OperationExecutorImpl.java:411) ~[hazelcast-4.2.jar:4.2]
    at com.hazelcast.spi.impl.operationexecutor.impl.OperationExecutorImpl.runOrExecute(OperationExecutorImpl.java:438) ~[hazelcast-4.2.jar:4.2]
    at com.hazelcast.spi.impl.operationservice.impl.Invocation.doInvokeLocal(Invocation.java:600) ~[hazelcast-4.2.jar:4.2]
    at com.hazelcast.spi.impl.operationservice.impl.Invocation.doInvoke(Invocation.java:579) ~[hazelcast-4.2.jar:4.2]
    at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke0(Invocation.java:540) ~[hazelcast-4.2.jar:4.2]
    at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke(Invocation.java:240) ~[hazelcast-4.2.jar:4.2]
    at com.hazelcast.spi.impl.operationservice.impl.InvocationBuilderImpl.invoke(InvocationBuilderImpl.java:59) ~[hazelcast-4.2.jar:4.2]
    at com.hazelcast.jet.impl.MasterContext.invokeOnParticipant(MasterContext.java:264) ~[classes/:?]
    at com.hazelcast.jet.impl.MasterContext.invokeOnParticipants(MasterContext.java:247) ~[classes/:?]
    at com.hazelcast.jet.impl.MasterSnapshotContext.lambda$onSnapshotPhase1Complete$5(MasterSnapshotContext.java:277) ~[classes/:?]
    at com.hazelcast.jet.impl.JobCoordinationService.lambda$submitToCoordinatorThread$46(JobCoordinationService.java:1039) ~[classes/:?]
    at com.hazelcast.jet.impl.JobCoordinationService.lambda$submitToCoordinatorThread$47(JobCoordinationService.java:1060) ~[classes/:?]
    at com.hazelcast.internal.util.executor.CompletableFutureTask.run(CompletableFutureTask.java:64) [hazelcast-4.2.jar:4.2]
    at com.hazelcast.internal.util.executor.CachedExecutorServiceDelegate$Worker.run(CachedExecutorServiceDelegate.java:217) [hazelcast-4.2.jar:4.2]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
    at java.lang.Thread.run(Thread.java:834) [?:?]
    at com.hazelcast.internal.util.executor.HazelcastManagedThread.executeRun(HazelcastManagedThread.java:76) [hazelcast-4.2.jar:4.2]
    at com.hazelcast.internal.util.executor.HazelcastManagedThread.run(HazelcastManagedThread.java:102) [hazelcast-4.2.jar:4.2]
2021-04-08 19:47:25,406 [ WARN] [hz.zealous_fermat.cached.thread-64] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] SnapshotPhase2Operation for snapshot 0 in job '0601-006a-1b80-0001', execution 0601-006a-1b81-0001 failed on member: MemberInfo{address=[127.0.0.1]:5702, uuid=5ae77878-297a-4d22-ae4f-1060e0853c93, liteMember=false, memberListJoinVersion=2}=com.hazelcast.spi.exception.TargetNotMemberException: Not Member! target: [127.0.0.1]:5702, partitionId: -1, operation: com.hazelcast.jet.impl.operation.SnapshotPhase2Operation, service: hz:impl:jetService
com.hazelcast.spi.exception.TargetNotMemberException: Not Member! target: [127.0.0.1]:5702, partitionId: -1, operation: com.hazelcast.jet.impl.operation.SnapshotPhase2Operation, service: hz:impl:jetService
    at com.hazelcast.spi.impl.operationservice.impl.Invocation.initInvocationTarget(Invocation.java:290) ~[hazelcast-4.2.jar:4.2]
    at com.hazelcast.spi.impl.operationservice.impl.Invocation.doInvoke(Invocation.java:562) ~[hazelcast-4.2.jar:4.2]
    at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke0(Invocation.java:540) ~[hazelcast-4.2.jar:4.2]
    at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke(Invocation.java:240) ~[hazelcast-4.2.jar:4.2]
    at com.hazelcast.spi.impl.operationservice.impl.InvocationBuilderImpl.invoke(InvocationBuilderImpl.java:59) ~[hazelcast-4.2.jar:4.2]
    at com.hazelcast.jet.impl.MasterContext.invokeOnParticipant(MasterContext.java:264) ~[classes/:?]
    at com.hazelcast.jet.impl.MasterContext.invokeOnParticipants(MasterContext.java:247) ~[classes/:?]
    at com.hazelcast.jet.impl.MasterSnapshotContext.lambda$onSnapshotPhase1Complete$5(MasterSnapshotContext.java:277) ~[classes/:?]
    at com.hazelcast.jet.impl.JobCoordinationService.lambda$submitToCoordinatorThread$46(JobCoordinationService.java:1039) ~[classes/:?]
    at com.hazelcast.jet.impl.JobCoordinationService.lambda$submitToCoordinatorThread$47(JobCoordinationService.java:1060) ~[classes/:?]
    at com.hazelcast.internal.util.executor.CompletableFutureTask.run(CompletableFutureTask.java:64) [hazelcast-4.2.jar:4.2]
    at com.hazelcast.internal.util.executor.CachedExecutorServiceDelegate$Worker.run(CachedExecutorServiceDelegate.java:217) [hazelcast-4.2.jar:4.2]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
    at java.lang.Thread.run(Thread.java:834) [?:?]
    at com.hazelcast.internal.util.executor.HazelcastManagedThread.executeRun(HazelcastManagedThread.java:76) [hazelcast-4.2.jar:4.2]
    at com.hazelcast.internal.util.executor.HazelcastManagedThread.run(HazelcastManagedThread.java:102) [hazelcast-4.2.jar:4.2]
2021-04-08 19:47:25,417 [DEBUG] [hz.zealous_fermat.cached.thread-64] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] job '0601-006a-1b80-0001', execution 0601-006a-1b81-0001 snapshot is scheduled in 500ms
2021-04-08 19:47:25,417 [DEBUG] [hz.zealous_fermat.cached.thread-64] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Snapshot 0 for job '0601-006a-1b80-0001', execution 0601-006a-1b81-0001 completed in 11633ms, status=failure: java.util.concurrent.CancellationException: execution cancelled
2021-04-08 19:47:25,417 [DEBUG] [hz.zealous_fermat.cached.thread-64] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Not beginning snapshot, job '0601-006a-1b80-0001', execution 0601-006a-1b81-0001 is not RUNNING, but NOT_RUNNING
2021-04-08 19:47:25,668 [ INFO] [Thread-198] [c.h.i.i.NodeExtension]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Destroying node NodeExtension.
2021-04-08 19:47:25,669 [ INFO] [Thread-198] [c.h.i.i.Node]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Hazelcast Shutdown is completed in 264 ms.
2021-04-08 19:47:25,669 [ INFO] [Thread-198] [c.h.c.LifecycleService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] [127.0.0.1]:5701 is SHUTDOWN
BuildInfo right after test_restartJob_nodeTerminated(com.hazelcast.jet.pipeline.SourceBuilder_TopologyChangeTest): BuildInfo{version='4.2', build='20210324', buildNumber=20210324, revision=405cfd1, enterprise=false, serializationVersion=1, jet=JetBuildInfo{version='4.5-SNAPSHOT', build='20210408', revision='4eb9c6b'}}
Hiccups measured while running test 'test_restartJob_nodeTerminated(com.hazelcast.jet.pipeline.SourceBuilder_TopologyChangeTest):'
19:47:05, accumulated pauses: 611 ms, max pause: 91 ms, pauses over 1000 ms: 0
19:47:10, accumulated pauses: 2065 ms, max pause: 438 ms, pauses over 1000 ms: 0
19:47:15, accumulated pauses: 661 ms, max pause: 15 ms, pauses over 1000 ms: 0
19:47:20, accumulated pauses: 1377 ms, max pause: 298 ms, pauses over 1000 ms: 0
19:47:25, accumulated pauses: 94 ms, max pause: 28 ms, pauses over 1000 ms: 0
gurbuzali commented 3 years ago

Looks like the snapshot is stuck at phase 1

Snaphot 0 is started at 19:47:14,023, it prints the log from the test too Will save 934 to snapshot

2021-04-08 19:47:14,023 [DEBUG] [hz.zealous_fermat.cached.thread-55] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Starting snapshot 0 for job '0601-006a-1b80-0001', execution 0601-006a-1b81-0001, flags: terminal=no,export=no, writing to: null
2021-04-08 19:47:14,024 [DEBUG] [hz.zealous_fermat.cached.thread-55] [c.h.j.i.e.ExecutionContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Starting snapshot 0 phase 1 for job '0601-006a-1b80-0001', execution 0601-006a-1b81-0001 on member
2021-04-08 19:47:14,024 [DEBUG] [hz.magical_fermat.generic-operation.thread-21] [c.h.j.i.e.ExecutionContext]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Starting snapshot 0 phase 1 for job '0601-006a-1b80-0001', execution 0601-006a-1b81-0001 on member
Will save 934 to snapshot

At 19:47:14,538 second member declares that it finished phase 1

2021-04-08 19:47:14,538 [DEBUG] [hz.magical_fermat.jet.cooperative.thread-6] [c.h.j.i.o.SnapshotPhase1Operation]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Snapshot 0 phase 1 for job '0601-006a-1b80-0001', execution 0601-006a-1b81-0001 finished successfully on member

after 10 seconds, assertion times out and test fails. only then we see this log

2021-04-08 19:47:24,688 [ WARN] [hz.zealous_fermat.async.thread-1] [c.h.j.i.o.SnapshotPhase1Operation]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Snapshot 0 phase 1 for job '0601-006a-1b80-0001', execution 0601-006a-1b81-0001 finished with an error on member: java.util.concurrent.CancellationException: execution cancelled
gurbuzali commented 3 years ago

see also https://github.com/hazelcast/hazelcast-jet/issues/2643

ufukyilmaz commented 3 years ago

We discussed this issue with Viliam and our findings are: Member at 5701 got stuck in Snapshot 0 phase 1. It saved the state of src and sliding-window-prepare and then somehow it got stuck. It should save state for sliding-window and listSink, but it didn't.

Looking at the snapshot process in 5702, everything looks normal there. Since the source stage is not distributed, it runs only on single member, apparently 5701 in this test. So, snapshot phase 1 for src and sliding-window-prepare completed immediately on 5702. Member 5702 saved state only for sliding-window (the second stage of sliding window) and listSink and completed the snapshot phase 1 successfully.

Considering this log below, sliding window (second stage of sliding window) at member 5701 run on hz.zealous_fermat.jet.cooperative.thread-4. 

2021-04-08 19:47:14,093 [ INFO] [hz.zealous_fermat.jet.cooperative.thread-4] [c.h.j.i.p.SlidingWindowP]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] [0601-006a-1b80-0001/sliding-window#0] Output to ordinal 0: Watermark{ts=00:00:00.900}

When we checked the thread dump for this thread, we did not encounter any problems. Actually, this thread appears to be idle in the thread dump.