search

hazelcast / hazelcast-jet

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

com.hazelcast.jet.cdc.postgres.PostgresCdcIntegrationTest.stressTest_exactlyOnce_gracefulRestart #2889

Closed olukas closed 3 years ago

olukas commented 3 years ago

master (commit 43b3ac2f55f1a02e225dac07a269ab7237963850)

Failed on Oracle JDK 8: http://jenkins.hazelcast.com/job/jet-oss-master-nightly-oracle-jdk8/404/testReport/junit/com.hazelcast.jet.cdc.postgres/PostgresCdcIntegrationTest/stressTest_exactlyOnce_gracefulRestart/

Stacktrace:

java.lang.AssertionError: jobId=05be-635f-7880-0001 expected:<RUNNING> but was:<FAILED>
    at org.junit.Assert.fail(Assert.java:89)
    at org.junit.Assert.failNotEquals(Assert.java:835)
    at org.junit.Assert.assertEquals(Assert.java:120)
    at com.hazelcast.jet.core.JetTestSupport.lambda$assertJobStatusEventually$1(JetTestSupport.java:199)
    at com.hazelcast.test.HazelcastTestSupport.assertTrueEventually(HazelcastTestSupport.java:1248)
    at com.hazelcast.test.HazelcastTestSupport.assertTrueEventually(HazelcastTestSupport.java:1265)
    at com.hazelcast.jet.core.JetTestSupport.assertJobStatusEventually(JetTestSupport.java:198)
    at com.hazelcast.jet.core.JetTestSupport.assertJobStatusEventually(JetTestSupport.java:153)
    at com.hazelcast.jet.cdc.postgres.PostgresCdcIntegrationTest.stressTest_exactlyOnce(PostgresCdcIntegrationTest.java:195)
    at com.hazelcast.jet.cdc.postgres.PostgresCdcIntegrationTest.stressTest_exactlyOnce_gracefulRestart(PostgresCdcIntegrationTest.java:160)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:59)
    at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
    at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:56)
    at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
    at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
    at org.testcontainers.containers.FailureDetectingExternalResource$1.evaluate(FailureDetectingExternalResource.java:30)
    at org.junit.rules.TestWatcher$1.evaluate(TestWatcher.java:61)
    at com.hazelcast.test.DumpBuildInfoOnFailureRule$1.evaluate(DumpBuildInfoOnFailureRule.java:37)
    at com.hazelcast.test.jitter.JitterRule$1.evaluate(JitterRule.java:104)
    at com.hazelcast.test.metrics.MetricsRule$1.evaluate(MetricsRule.java:62)
    at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
    at org.junit.runners.BlockJUnit4ClassRunner$1.evaluate(BlockJUnit4ClassRunner.java:100)
    at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:366)
    at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:103)
    at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:63)
    at org.junit.runners.ParentRunner$4.run(ParentRunner.java:331)
    at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:79)
    at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:329)
    at org.junit.runners.ParentRunner.access$100(ParentRunner.java:66)
    at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:293)
    at org.junit.internal.runners.statements.FailOnTimeout$CallableStatement.call(FailOnTimeout.java:288)
    at org.junit.internal.runners.statements.FailOnTimeout$CallableStatement.call(FailOnTimeout.java:282)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.lang.Thread.run(Thread.java:748)

Standard output:

2021-02-16 02:01:15,640 [ INFO] [Time-limited test] [d.3]]: Creating container for image: debezium/example-postgres:1.3
2021-02-16 02:01:16,044 [ INFO] [Time-limited test] [d.3]]: Starting container with ID: aeaa528ee129ab1bd1b8f43fc8fa007c565cab1ebef7ea6c9446fa616790f890
2021-02-16 02:01:16,629 [ INFO] [Time-limited test] [d.3]]: Container debezium/example-postgres:1.3 is starting: aeaa528ee129ab1bd1b8f43fc8fa007c565cab1ebef7ea6c9446fa616790f890
2021-02-16 02:01:19,435 [ INFO] [Time-limited test] [d.3]]: Container debezium/example-postgres:1.3 started in PT3.796S
2021-02-16 02:01:19,437 [ INFO] [Time-limited test] [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-02-16 02:01:19,439 [ INFO] [Time-limited test] [c.h.system]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Hazelcast Jet 4.5-SNAPSHOT (20210216 - 43b3ac2) starting at [127.0.0.1]:5701
2021-02-16 02:01:19,439 [ INFO] [Time-limited test] [c.h.system]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Based on Hazelcast IMDG version: 4.1.1 (20201222 - 27af558)
2021-02-16 02:01:19,439 [ INFO] [Time-limited test] [c.h.system]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Cluster name: jet
2021-02-16 02:01:19,439 [ INFO] [Time-limited test] [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-02-16 02:01:19,439 [ INFO] [Time-limited test] [c.h.system]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Copyright (c) 2008-2021, Hazelcast, Inc. All Rights Reserved.
2021-02-16 02:01:19,444 [ INFO] [Time-limited test] [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-02-16 02:01:19,456 [ WARN] [Time-limited test] [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-02-16 02:01:19,473 [ INFO] [Time-limited test] [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-02-16 02:01:19,495 [ INFO] [Time-limited test] [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-02-16 02:01:19,496 [ INFO] [Time-limited test] [c.h.c.LifecycleService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] [127.0.0.1]:5701 is STARTING
2021-02-16 02:01:19,497 [ INFO] [Time-limited test] [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 - 9e77d632-e41d-4bff-8049-3a81f2db79c9 this
]

2021-02-16 02:01:19,503 [ INFO] [Time-limited test] [c.h.c.LifecycleService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] [127.0.0.1]:5701 is STARTED
2021-02-16 02:01:19,503 [DEBUG] [hz.frosty_almeida.cached.thread-2] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Not starting jobs because partitions are not yet initialized.
2021-02-16 02:01:19,504 [ INFO] [Time-limited test] [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-02-16 02:01:19,506 [ INFO] [Time-limited test] [c.h.system]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Hazelcast Jet 4.5-SNAPSHOT (20210216 - 43b3ac2) starting at [127.0.0.1]:5702
2021-02-16 02:01:19,506 [ INFO] [Time-limited test] [c.h.system]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Based on Hazelcast IMDG version: 4.1.1 (20201222 - 27af558)
2021-02-16 02:01:19,506 [ INFO] [Time-limited test] [c.h.system]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Cluster name: jet
2021-02-16 02:01:19,506 [ INFO] [Time-limited test] [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-02-16 02:01:19,506 [ INFO] [Time-limited test] [c.h.system]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Copyright (c) 2008-2021, Hazelcast, Inc. All Rights Reserved.
2021-02-16 02:01:19,514 [ INFO] [Time-limited test] [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-02-16 02:01:19,524 [ WARN] [Time-limited test] [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-02-16 02:01:19,566 [ INFO] [Time-limited test] [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-02-16 02:01:19,596 [ INFO] [Time-limited test] [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-02-16 02:01:19,596 [ INFO] [Time-limited test] [c.h.c.LifecycleService]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [127.0.0.1]:5702 is STARTING
2021-02-16 02:01:19,597 [ INFO] [Time-limited test] [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-02-16 02:01:19,598 [ INFO] [hz.frosty_almeida.priority-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-02-16 02:01:19,600 [ INFO] [hz.frosty_almeida.priority-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 - 9e77d632-e41d-4bff-8049-3a81f2db79c9 this
    Member [127.0.0.1]:5702 - 2b8ca85c-d39a-4439-a545-a17e8052dc10
]

2021-02-16 02:01:19,604 [DEBUG] [hz.frosty_almeida.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-02-16 02:01:19,703 [ INFO] [hz.condescending_almeida.priority-generic-operation.thread-0] [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 - 9e77d632-e41d-4bff-8049-3a81f2db79c9
    Member [127.0.0.1]:5702 - 2b8ca85c-d39a-4439-a545-a17e8052dc10 this
]

2021-02-16 02:01:19,704 [DEBUG] [hz.frosty_almeida.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-02-16 02:01:19,805 [DEBUG] [hz.frosty_almeida.cached.thread-1] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Not starting jobs because partitions are not yet initialized.
2021-02-16 02:01:19,905 [DEBUG] [hz.frosty_almeida.cached.thread-1] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Not starting jobs because partitions are not yet initialized.
2021-02-16 02:01:20,006 [DEBUG] [hz.frosty_almeida.cached.thread-6] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Not starting jobs because partitions are not yet initialized.
2021-02-16 02:01:20,098 [ INFO] [Time-limited test] [c.h.c.LifecycleService]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [127.0.0.1]:5702 is STARTED
2021-02-16 02:01:20,100 [ INFO] [hz.frosty_almeida.cached.thread-6] [c.h.i.p.i.PartitionStateManager]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Initializing cluster partition table arrangement...
2021-02-16 02:01:20,122 [DEBUG] [hz.frosty_almeida.cached.thread-6] [c.h.j.i.p.Planner]: Watermarks in the pipeline will be throttled to 1
2021-02-16 02:01:20,125 [ INFO] [hz.frosty_almeida.cached.thread-6] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Starting job 05be-635f-7880-0001 based on submit request
2021-02-16 02:01:20,148 [DEBUG] [hz.frosty_almeida.cached.thread-6] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Not starting jobs because partition replication is not in safe state, but in REPLICA_NOT_SYNC
2021-02-16 02:01:20,148 [DEBUG] [hz.frosty_almeida.cached.thread-6] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Rescheduling restart of '05be-635f-7880-0001': cluster is not safe
2021-02-16 02:01:20,149 [DEBUG] [hz.frosty_almeida.cached.thread-6] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Scheduling restart on master for job 05be-635f-7880-0001
2021-02-16 02:01:20,153 [DEBUG] [hz.frosty_almeida.cached.thread-1] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Not starting jobs because partition replication is not in safe state, but in REPLICA_NOT_SYNC
2021-02-16 02:01:20,271 [DEBUG] [hz.frosty_almeida.cached.thread-1] [c.h.j.i.JobRepository]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Job cleanup took 9ms
2021-02-16 02:01:22,165 [ INFO] [hz.frosty_almeida.cached.thread-4] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Didn't find any snapshot to restore for job '05be-635f-7880-0001', execution 05be-635f-7881-0001
2021-02-16 02:01:22,165 [ INFO] [hz.frosty_almeida.cached.thread-4] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Start executing job '05be-635f-7880-0001', execution 05be-635f-7881-0001, execution graph in DOT format:
digraph DAG {
    "customers" [localParallelism=1];
    "filter_timestamps" [localParallelism=1];
    "map-stateful-keyed" [localParallelism=1];
    "mapSink(results)" [localParallelism=1];
    "customers" -> "filter_timestamps" [queueSize=1024];
    "filter_timestamps" -> "map-stateful-keyed" [label="distributed-partitioned", queueSize=1024];
    "map-stateful-keyed" -> "mapSink(results)" [label="partitioned", queueSize=1024];
}
HINT: You can use graphviz or http://viz-js.com to visualize the printed graph.
2021-02-16 02:01:22,165 [DEBUG] [hz.frosty_almeida.cached.thread-4] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Building execution plan for job '05be-635f-7880-0001', execution 05be-635f-7881-0001
2021-02-16 02:01:22,166 [DEBUG] [hz.frosty_almeida.cached.thread-4] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Built execution plans for job '05be-635f-7880-0001', execution 05be-635f-7881-0001
2021-02-16 02:01:22,167 [DEBUG] [hz.frosty_almeida.cached.thread-4] [c.h.j.i.o.InitExecutionOperation]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Initializing execution plan for job 05be-635f-7880-0001, execution 05be-635f-7881-0001 from [127.0.0.1]:5701
2021-02-16 02:01:22,172 [ INFO] [hz.frosty_almeida.cached.thread-4] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Execution plan for jobId=05be-635f-7880-0001, jobName='05be-635f-7880-0001', executionId=05be-635f-7881-0001 initialized
2021-02-16 02:01:22,173 [DEBUG] [hz.condescending_almeida.generic-operation.thread-15] [c.h.j.i.o.InitExecutionOperation]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Initializing execution plan for job 05be-635f-7880-0001, execution 05be-635f-7881-0001 from [127.0.0.1]:5701
2021-02-16 02:01:22,180 [ INFO] [hz.condescending_almeida.generic-operation.thread-15] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Execution plan for jobId=05be-635f-7880-0001, jobName='05be-635f-7880-0001', executionId=05be-635f-7881-0001 initialized
2021-02-16 02:01:22,181 [DEBUG] [hz.frosty_almeida.cached.thread-5] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Init of job '05be-635f-7880-0001', execution 05be-635f-7881-0001 was successful
2021-02-16 02:01:22,181 [DEBUG] [hz.frosty_almeida.cached.thread-5] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Executing job '05be-635f-7880-0001', execution 05be-635f-7881-0001
2021-02-16 02:01:22,181 [ INFO] [hz.frosty_almeida.cached.thread-5] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Start execution of job '05be-635f-7880-0001', execution 05be-635f-7881-0001 from coordinator [127.0.0.1]:5701
2021-02-16 02:01:22,187 [DEBUG] [hz.frosty_almeida.cached.thread-5] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] job '05be-635f-7880-0001', execution 05be-635f-7881-0001 snapshot is scheduled in 100ms
2021-02-16 02:01:22,187 [ INFO] [hz.condescending_almeida.generic-operation.thread-16] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Start execution of job '05be-635f-7880-0001', execution 05be-635f-7881-0001 from coordinator [127.0.0.1]:5701
2021-02-16 02:01:22,189 [ INFO] [hz.condescending_almeida.jet.blocking.thread-0] [c.h.j.c.i.ChangeRecordCdcSourceP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [05be-635f-7880-0001/customers#0] customers has 'retry strategy' set to 'max attempts = -1, interval function = IntervalFunction (constant of 1000ms)'
2021-02-16 02:01:22,189 [ INFO] [hz.condescending_almeida.jet.blocking.thread-0] [c.h.j.c.i.ChangeRecordCdcSourceP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [05be-635f-7880-0001/customers#0] customers has 'clear state on reconnect' set to 'false'
2021-02-16 02:01:22,190 [ INFO] [hz.condescending_almeida.jet.blocking.thread-0] [i.d.c.c.BaseSourceTask]: Starting PostgresConnectorTask with configuration:
2021-02-16 02:01:22,190 [ INFO] [hz.condescending_almeida.jet.blocking.thread-0] [i.d.c.c.BaseSourceTask]:    reconnect.behavior = max attempts = -1, interval function = IntervalFunction (constant of 1000ms)
2021-02-16 02:01:22,190 [ INFO] [hz.condescending_almeida.jet.blocking.thread-0] [i.d.c.c.BaseSourceTask]:    connector.class = io.debezium.connector.postgresql.PostgresConnector
2021-02-16 02:01:22,190 [ INFO] [hz.condescending_almeida.jet.blocking.thread-0] [i.d.c.c.BaseSourceTask]:    db.specific.extra.fields = schema
2021-02-16 02:01:22,190 [ INFO] [hz.condescending_almeida.jet.blocking.thread-0] [i.d.c.c.BaseSourceTask]:    database.user = postgres
2021-02-16 02:01:22,190 [ INFO] [hz.condescending_almeida.jet.blocking.thread-0] [i.d.c.c.BaseSourceTask]:    database.dbname = postgres
2021-02-16 02:01:22,190 [ INFO] [hz.condescending_almeida.jet.blocking.thread-0] [i.d.c.c.BaseSourceTask]:    slot.name = debezium
2021-02-16 02:01:22,190 [ INFO] [hz.condescending_almeida.jet.blocking.thread-0] [i.d.c.c.BaseSourceTask]:    database.server.name = fe9be6c9-2bf4-4c0a-a643-25bd40ec2143
2021-02-16 02:01:22,190 [ INFO] [hz.condescending_almeida.jet.blocking.thread-0] [i.d.c.c.BaseSourceTask]:    sequence.extractor.class = com.hazelcast.jet.cdc.postgres.impl.PostgresSequenceExtractor
2021-02-16 02:01:22,190 [ INFO] [hz.condescending_almeida.jet.blocking.thread-0] [i.d.c.c.BaseSourceTask]:    commit.period = 9223372036854775807
2021-02-16 02:01:22,190 [ INFO] [hz.condescending_almeida.jet.blocking.thread-0] [i.d.c.c.BaseSourceTask]:    database.port = 56707
2021-02-16 02:01:22,190 [ INFO] [hz.condescending_almeida.jet.blocking.thread-0] [i.d.c.c.BaseSourceTask]:    table.whitelist = inventory.customers
2021-02-16 02:01:22,190 [ INFO] [hz.condescending_almeida.jet.blocking.thread-0] [i.d.c.c.BaseSourceTask]:    tombstones.on.delete = false
2021-02-16 02:01:22,190 [ INFO] [hz.condescending_almeida.jet.blocking.thread-0] [i.d.c.c.BaseSourceTask]:    database.hostname = 172.17.0.1
2021-02-16 02:01:22,190 [ INFO] [hz.condescending_almeida.jet.blocking.thread-0] [i.d.c.c.BaseSourceTask]:    database.password = ********
2021-02-16 02:01:22,190 [ INFO] [hz.condescending_almeida.jet.blocking.thread-0] [i.d.c.c.BaseSourceTask]:    name = customers
2021-02-16 02:01:22,190 [ INFO] [hz.condescending_almeida.jet.blocking.thread-0] [i.d.c.c.BaseSourceTask]:    snapshot.mode = exported
2021-02-16 02:01:22,190 [ INFO] [hz.condescending_almeida.jet.blocking.thread-0] [i.d.c.c.BaseSourceTask]:    database.history = com.hazelcast.jet.cdc.impl.CdcSourceP$DatabaseHistoryImpl
2021-02-16 02:01:22,234 [ INFO] [hz.condescending_almeida.jet.blocking.thread-0] [i.d.c.p.PostgresConnectorTask]: user 'postgres' connected to database 'postgres' on PostgreSQL 11.10 (Debian 11.10-1.pgdg90+1) on x86_64-pc-linux-gnu, compiled by gcc (Debian 6.3.0-18+deb9u1) 6.3.0 20170516, 64-bit with roles:
    role 'pg_read_all_settings' [superuser: false, replication: false, inherit: true, create role: false, create db: false, can log in: false]
    role 'pg_stat_scan_tables' [superuser: false, replication: false, inherit: true, create role: false, create db: false, can log in: false]
    role 'pg_write_server_files' [superuser: false, replication: false, inherit: true, create role: false, create db: false, can log in: false]
    role 'pg_monitor' [superuser: false, replication: false, inherit: true, create role: false, create db: false, can log in: false]
    role 'pg_read_server_files' [superuser: false, replication: false, inherit: true, create role: false, create db: false, can log in: false]
    role 'pg_execute_server_program' [superuser: false, replication: false, inherit: true, create role: false, create db: false, can log in: false]
    role 'pg_read_all_stats' [superuser: false, replication: false, inherit: true, create role: false, create db: false, can log in: false]
    role 'pg_signal_backend' [superuser: false, replication: false, inherit: true, create role: false, create db: false, can log in: false]
    role 'postgres' [superuser: true, replication: true, inherit: true, create role: true, create db: true, can log in: true]
2021-02-16 02:01:22,236 [ INFO] [hz.condescending_almeida.jet.blocking.thread-0] [i.d.c.p.c.PostgresConnection]: Obtained valid replication slot ReplicationSlot [active=false, latestFlushedLsn=null, catalogXmin=null]
2021-02-16 02:01:22,236 [ INFO] [hz.condescending_almeida.jet.blocking.thread-0] [i.d.c.p.PostgresConnectorTask]: No previous offset found
2021-02-16 02:01:22,236 [ INFO] [hz.condescending_almeida.jet.blocking.thread-0] [i.d.c.p.s.ExportedSnapshotter]: Taking exported snapshot for new datasource
2021-02-16 02:01:22,241 [ INFO] [hz.condescending_almeida.jet.blocking.thread-0] [i.d.c.p.c.PostgresReplicationConnection]: Creating replication slot with command CREATE_REPLICATION_SLOT debezium  LOGICAL decoderbufs
2021-02-16 02:01:22,243 [ INFO] [hz.condescending_almeida.jet.blocking.thread-0] [i.d.u.Threads]: Requested thread factory for connector PostgresConnector, id = fe9be6c9-2bf4-4c0a-a643-25bd40ec2143 named = change-event-source-coordinator
2021-02-16 02:01:22,243 [ INFO] [hz.condescending_almeida.jet.blocking.thread-0] [i.d.u.Threads]: Creating thread debezium-postgresconnector-fe9be6c9-2bf4-4c0a-a643-25bd40ec2143-change-event-source-coordinator
2021-02-16 02:01:22,244 [ INFO] [debezium-postgresconnector-fe9be6c9-2bf4-4c0a-a643-25bd40ec2143-change-event-source-coordinator] [i.d.p.ChangeEventSourceCoordinator]: Metrics registered
2021-02-16 02:01:22,244 [ INFO] [debezium-postgresconnector-fe9be6c9-2bf4-4c0a-a643-25bd40ec2143-change-event-source-coordinator] [i.d.p.ChangeEventSourceCoordinator]: Context created
2021-02-16 02:01:22,244 [ INFO] [debezium-postgresconnector-fe9be6c9-2bf4-4c0a-a643-25bd40ec2143-change-event-source-coordinator] [i.d.c.p.s.ExportedSnapshotter]: Taking exported snapshot for new datasource
2021-02-16 02:01:22,244 [ INFO] [debezium-postgresconnector-fe9be6c9-2bf4-4c0a-a643-25bd40ec2143-change-event-source-coordinator] [i.d.c.p.PostgresSnapshotChangeEventSource]: According to the connector configuration data will be snapshotted
2021-02-16 02:01:22,244 [ INFO] [debezium-postgresconnector-fe9be6c9-2bf4-4c0a-a643-25bd40ec2143-change-event-source-coordinator] [i.d.r.RelationalSnapshotChangeEventSource]: Snapshot step 1 - Preparing
2021-02-16 02:01:22,246 [ INFO] [debezium-postgresconnector-fe9be6c9-2bf4-4c0a-a643-25bd40ec2143-change-event-source-coordinator] [i.d.c.p.PostgresSnapshotChangeEventSource]: Setting isolation level
2021-02-16 02:01:22,246 [ INFO] [debezium-postgresconnector-fe9be6c9-2bf4-4c0a-a643-25bd40ec2143-change-event-source-coordinator] [i.d.c.p.PostgresSnapshotChangeEventSource]: Opening transaction with statement SET TRANSACTION ISOLATION LEVEL REPEATABLE READ; 
SET TRANSACTION SNAPSHOT '00000005-00000002-1';
2021-02-16 02:01:22,302 [DEBUG] [hz.frosty_almeida.cached.thread-5] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Starting snapshot 0 for job '05be-635f-7880-0001', execution 05be-635f-7881-0001, flags: terminal=no,export=no, writing to: null
2021-02-16 02:01:22,302 [DEBUG] [hz.frosty_almeida.cached.thread-5] [c.h.j.i.e.ExecutionContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Starting snapshot 0 phase 1 for job '05be-635f-7880-0001', execution 05be-635f-7881-0001 on member
2021-02-16 02:01:22,302 [DEBUG] [hz.condescending_almeida.generic-operation.thread-18] [c.h.j.i.e.ExecutionContext]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Starting snapshot 0 phase 1 for job '05be-635f-7880-0001', execution 05be-635f-7881-0001 on member
2021-02-16 02:01:22,320 [ WARN] [debezium-postgresconnector-fe9be6c9-2bf4-4c0a-a643-25bd40ec2143-change-event-source-coordinator] [i.d.c.p.PostgresSchema]: The Kafka Connect schema name 'fe9be6c9-2bf4-4c0a-a643-25bd40ec2143.inventory.customers.Value' is not a valid Avro schema name, so replacing with 'fe9be6c9_2bf4_4c0a_a643_25bd40ec2143.inventory.customers.Value'
2021-02-16 02:01:22,320 [ WARN] [debezium-postgresconnector-fe9be6c9-2bf4-4c0a-a643-25bd40ec2143-change-event-source-coordinator] [i.d.c.p.PostgresSchema]: The Kafka Connect schema name 'fe9be6c9-2bf4-4c0a-a643-25bd40ec2143.inventory.customers.Key' is not a valid Avro schema name, so replacing with 'fe9be6c9_2bf4_4c0a_a643_25bd40ec2143.inventory.customers.Key'
2021-02-16 02:01:22,321 [ WARN] [debezium-postgresconnector-fe9be6c9-2bf4-4c0a-a643-25bd40ec2143-change-event-source-coordinator] [i.d.c.p.PostgresSchema]: The Kafka Connect schema name 'fe9be6c9-2bf4-4c0a-a643-25bd40ec2143.inventory.customers.Envelope' is not a valid Avro schema name, so replacing with 'fe9be6c9_2bf4_4c0a_a643_25bd40ec2143.inventory.customers.Envelope'
2021-02-16 02:01:22,321 [ INFO] [debezium-postgresconnector-fe9be6c9-2bf4-4c0a-a643-25bd40ec2143-change-event-source-coordinator] [i.d.r.RelationalSnapshotChangeEventSource]: Snapshot step 2 - Determining captured tables
2021-02-16 02:01:22,323 [ INFO] [debezium-postgresconnector-fe9be6c9-2bf4-4c0a-a643-25bd40ec2143-change-event-source-coordinator] [i.d.r.RelationalSnapshotChangeEventSource]: Snapshot step 3 - Locking captured tables
2021-02-16 02:01:22,323 [ INFO] [debezium-postgresconnector-fe9be6c9-2bf4-4c0a-a643-25bd40ec2143-change-event-source-coordinator] [i.d.c.p.PostgresSnapshotChangeEventSource]: Step 2: skipping locking each table in an exported snapshot
2021-02-16 02:01:22,323 [ INFO] [debezium-postgresconnector-fe9be6c9-2bf4-4c0a-a643-25bd40ec2143-change-event-source-coordinator] [i.d.r.RelationalSnapshotChangeEventSource]: Snapshot step 4 - Determining snapshot offset
2021-02-16 02:01:22,323 [ INFO] [debezium-postgresconnector-fe9be6c9-2bf4-4c0a-a643-25bd40ec2143-change-event-source-coordinator] [i.d.c.p.PostgresSnapshotChangeEventSource]: Read xlogStart at 'LSN{0/203EE80}' from transaction '596'
2021-02-16 02:01:22,323 [ INFO] [debezium-postgresconnector-fe9be6c9-2bf4-4c0a-a643-25bd40ec2143-change-event-source-coordinator] [i.d.c.p.PostgresSnapshotChangeEventSource]: Creating initial offset context
2021-02-16 02:01:22,324 [ INFO] [debezium-postgresconnector-fe9be6c9-2bf4-4c0a-a643-25bd40ec2143-change-event-source-coordinator] [i.d.c.p.PostgresSnapshotChangeEventSource]: Read xlogStart at 'LSN{0/203EE80}' from transaction '596'
2021-02-16 02:01:22,324 [ INFO] [debezium-postgresconnector-fe9be6c9-2bf4-4c0a-a643-25bd40ec2143-change-event-source-coordinator] [i.d.r.RelationalSnapshotChangeEventSource]: Snapshot step 5 - Reading structure of captured tables
2021-02-16 02:01:22,324 [ INFO] [debezium-postgresconnector-fe9be6c9-2bf4-4c0a-a643-25bd40ec2143-change-event-source-coordinator] [i.d.c.p.PostgresSnapshotChangeEventSource]: Reading structure of schema 'postgres'
2021-02-16 02:01:22,365 [ INFO] [debezium-postgresconnector-fe9be6c9-2bf4-4c0a-a643-25bd40ec2143-change-event-source-coordinator] [i.d.r.RelationalSnapshotChangeEventSource]: Snapshot step 6 - Persisting schema history
2021-02-16 02:01:22,365 [ INFO] [debezium-postgresconnector-fe9be6c9-2bf4-4c0a-a643-25bd40ec2143-change-event-source-coordinator] [i.d.r.RelationalSnapshotChangeEventSource]: Snapshot step 7 - Snapshotting data
2021-02-16 02:01:22,365 [ INFO] [debezium-postgresconnector-fe9be6c9-2bf4-4c0a-a643-25bd40ec2143-change-event-source-coordinator] [i.d.r.RelationalSnapshotChangeEventSource]:   Exporting data from table 'inventory.customers'
2021-02-16 02:01:22,365 [ INFO] [debezium-postgresconnector-fe9be6c9-2bf4-4c0a-a643-25bd40ec2143-change-event-source-coordinator] [i.d.r.RelationalSnapshotChangeEventSource]:   For table 'inventory.customers' using select statement: 'select * from "inventory"."customers"'
2021-02-16 02:01:22,369 [ INFO] [debezium-postgresconnector-fe9be6c9-2bf4-4c0a-a643-25bd40ec2143-change-event-source-coordinator] [i.d.r.RelationalSnapshotChangeEventSource]:   Finished exporting 4 records for table 'inventory.customers'; total duration '00:00:00.003'
2021-02-16 02:01:22,369 [ INFO] [debezium-postgresconnector-fe9be6c9-2bf4-4c0a-a643-25bd40ec2143-change-event-source-coordinator] [i.d.p.s.AbstractSnapshotChangeEventSource]: Snapshot - Final stage
2021-02-16 02:01:22,369 [ INFO] [debezium-postgresconnector-fe9be6c9-2bf4-4c0a-a643-25bd40ec2143-change-event-source-coordinator] [i.d.p.ChangeEventSourceCoordinator]: Snapshot ended with SnapshotResult [status=COMPLETED, offset=PostgresOffsetContext [sourceInfoSchema=Schema{io.debezium.connector.postgresql.Source:STRUCT}, sourceInfo=source_info[server='fe9be6c9-2bf4-4c0a-a643-25bd40ec2143'db='postgres', lsn=LSN{0/203EE80}, txId=596, timestamp=2021-02-16T02:01:22.368Z, snapshot=FALSE, schema=inventory, table=customers], partition={server=fe9be6c9-2bf4-4c0a-a643-25bd40ec2143}, lastSnapshotRecord=true, lastCompletelyProcessedLsn=null, lastCommitLsn=null, transactionContext=TransactionContext [currentTransactionId=null, perTableEventCount={}, totalEventCount=0]]]
2021-02-16 02:01:22,369 [ INFO] [debezium-postgresconnector-fe9be6c9-2bf4-4c0a-a643-25bd40ec2143-change-event-source-coordinator] [i.d.p.m.StreamingChangeEventSourceMetrics]: Connected metrics set to 'true'
2021-02-16 02:01:22,369 [ INFO] [debezium-postgresconnector-fe9be6c9-2bf4-4c0a-a643-25bd40ec2143-change-event-source-coordinator] [i.d.p.ChangeEventSourceCoordinator]: Starting streaming
2021-02-16 02:01:22,369 [ INFO] [debezium-postgresconnector-fe9be6c9-2bf4-4c0a-a643-25bd40ec2143-change-event-source-coordinator] [i.d.c.p.PostgresStreamingChangeEventSource]: Retrieved latest position from stored offset 'LSN{0/203EE80}'
2021-02-16 02:01:22,369 [ INFO] [debezium-postgresconnector-fe9be6c9-2bf4-4c0a-a643-25bd40ec2143-change-event-source-coordinator] [i.d.c.p.c.WalPositionLocator]: Looking for WAL restart position for last commit LSN 'null' and last change LSN 'LSN{0/203EE80}'
2021-02-16 02:01:22,377 [ INFO] [debezium-postgresconnector-fe9be6c9-2bf4-4c0a-a643-25bd40ec2143-change-event-source-coordinator] [i.d.c.p.c.PostgresConnection]: Obtained valid replication slot ReplicationSlot [active=false, latestFlushedLsn=LSN{0/203EE80}, catalogXmin=596]
2021-02-16 02:01:22,420 [ INFO] [debezium-postgresconnector-fe9be6c9-2bf4-4c0a-a643-25bd40ec2143-change-event-source-coordinator] [i.d.c.p.PostgresSchema]: REPLICA IDENTITY for 'inventory.customers' is 'FULL'; UPDATE AND DELETE events will contain the previous values of all the columns
2021-02-16 02:01:22,421 [ INFO] [debezium-postgresconnector-fe9be6c9-2bf4-4c0a-a643-25bd40ec2143-change-event-source-coordinator] [i.d.c.p.PostgresStreamingChangeEventSource]: Searching for WAL resume position
2021-02-16 02:01:22,744 [DEBUG] [hz.condescending_almeida.jet.cooperative.thread-0] [c.h.j.i.u.AsyncSnapshotWriterImpl]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Stats for customers: keys=1, chunks=1, bytes=330
2021-02-16 02:01:22,744 [DEBUG] [hz.condescending_almeida.jet.cooperative.thread-1] [c.h.j.i.u.AsyncSnapshotWriterImpl]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Stats for filter_timestamps: keys=0, chunks=0, bytes=0
2021-02-16 02:01:22,745 [DEBUG] [hz.condescending_almeida.jet.cooperative.thread-4] [c.h.j.i.u.AsyncSnapshotWriterImpl]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Stats for map-stateful-keyed: keys=4, chunks=4, bytes=310
2021-02-16 02:01:22,745 [DEBUG] [hz.frosty_almeida.jet.cooperative.thread-5] [c.h.j.i.u.AsyncSnapshotWriterImpl]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Stats for map-stateful-keyed: keys=2, chunks=2, bytes=212
2021-02-16 02:01:22,746 [DEBUG] [hz.condescending_almeida.jet.cooperative.thread-6] [c.h.j.i.u.AsyncSnapshotWriterImpl]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Stats for mapSink(results): keys=0, chunks=0, bytes=0
2021-02-16 02:01:22,746 [DEBUG] [hz.condescending_almeida.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 '05be-635f-7880-0001', execution 05be-635f-7881-0001 finished successfully on member
2021-02-16 02:01:22,747 [DEBUG] [hz.frosty_almeida.jet.cooperative.thread-7] [c.h.j.i.u.AsyncSnapshotWriterImpl]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Stats for mapSink(results): keys=0, chunks=0, bytes=0
2021-02-16 02:01:22,748 [DEBUG] [hz.frosty_almeida.jet.cooperative.thread-7] [c.h.j.i.o.SnapshotPhase1Operation]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Snapshot 0 phase 1 for job '05be-635f-7880-0001', execution 05be-635f-7881-0001 finished successfully on member
2021-02-16 02:01:22,750 [DEBUG] [hz.frosty_almeida.cached.thread-5] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Snapshot 0 phase 1 for job '05be-635f-7880-0001', execution 05be-635f-7881-0001 completed with status SUCCESS in 462ms, 852 bytes, 7 keys in 7 chunks, stored in '__jet.snapshot.05be-635f-7880-0001.0', proceeding to phase 2
2021-02-16 02:01:22,764 [DEBUG] [hz.frosty_almeida.cached.thread-5] [c.h.j.i.JobRepository]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Cleared snapshot data map __jet.snapshot.05be-635f-7880-0001.1
2021-02-16 02:01:22,764 [DEBUG] [hz.frosty_almeida.cached.thread-5] [c.h.j.i.e.ExecutionContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Starting snapshot 0 phase 2 for job '05be-635f-7880-0001', execution 05be-635f-7881-0001 on member
2021-02-16 02:01:22,765 [DEBUG] [hz.frosty_almeida.jet.cooperative.thread-8] [c.h.j.i.o.SnapshotPhase2Operation]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Snapshot 0 phase 2 for job '05be-635f-7880-0001', execution 05be-635f-7881-0001 finished successfully on member
2021-02-16 02:01:22,765 [DEBUG] [hz.condescending_almeida.generic-operation.thread-23] [c.h.j.i.e.ExecutionContext]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Starting snapshot 0 phase 2 for job '05be-635f-7880-0001', execution 05be-635f-7881-0001 on member
2021-02-16 02:01:22,772 [DEBUG] [hz.condescending_almeida.jet.cooperative.thread-7] [c.h.j.i.o.SnapshotPhase2Operation]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Snapshot 0 phase 2 for job '05be-635f-7880-0001', execution 05be-635f-7881-0001 finished successfully on member
2021-02-16 02:01:22,772 [DEBUG] [hz.frosty_almeida.cached.thread-5] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] job '05be-635f-7880-0001', execution 05be-635f-7881-0001 snapshot is scheduled in 100ms
2021-02-16 02:01:22,772 [DEBUG] [hz.frosty_almeida.cached.thread-5] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Snapshot 0 for job '05be-635f-7880-0001', execution 05be-635f-7881-0001 completed in 485ms, status=success
2021-02-16 02:01:22,875 [DEBUG] [hz.frosty_almeida.cached.thread-10] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Starting snapshot 1 for job '05be-635f-7880-0001', execution 05be-635f-7881-0001, flags: terminal=no,export=no, writing to: null
2021-02-16 02:01:22,876 [DEBUG] [hz.frosty_almeida.cached.thread-10] [c.h.j.i.e.ExecutionContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Starting snapshot 1 phase 1 for job '05be-635f-7880-0001', execution 05be-635f-7881-0001 on member
2021-02-16 02:01:22,876 [DEBUG] [hz.condescending_almeida.generic-operation.thread-25] [c.h.j.i.e.ExecutionContext]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Starting snapshot 1 phase 1 for job '05be-635f-7880-0001', execution 05be-635f-7881-0001 on member
2021-02-16 02:01:23,744 [DEBUG] [hz.condescending_almeida.jet.cooperative.thread-0] [c.h.j.i.u.AsyncSnapshotWriterImpl]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Stats for customers: keys=1, chunks=1, bytes=330
2021-02-16 02:01:23,744 [DEBUG] [hz.condescending_almeida.jet.cooperative.thread-1] [c.h.j.i.u.AsyncSnapshotWriterImpl]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Stats for filter_timestamps: keys=0, chunks=0, bytes=0
2021-02-16 02:01:23,745 [DEBUG] [hz.condescending_almeida.jet.cooperative.thread-4] [c.h.j.i.u.AsyncSnapshotWriterImpl]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Stats for map-stateful-keyed: keys=4, chunks=4, bytes=310
2021-02-16 02:01:23,745 [DEBUG] [hz.condescending_almeida.jet.cooperative.thread-6] [c.h.j.i.u.AsyncSnapshotWriterImpl]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Stats for mapSink(results): keys=0, chunks=0, bytes=0
2021-02-16 02:01:23,745 [DEBUG] [hz.frosty_almeida.jet.cooperative.thread-7] [c.h.j.i.u.AsyncSnapshotWriterImpl]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Stats for mapSink(results): keys=0, chunks=0, bytes=0
2021-02-16 02:01:23,745 [DEBUG] [hz.condescending_almeida.jet.cooperative.thread-6] [c.h.j.i.o.SnapshotPhase1Operation]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Snapshot 1 phase 1 for job '05be-635f-7880-0001', execution 05be-635f-7881-0001 finished successfully on member
2021-02-16 02:01:23,745 [DEBUG] [hz.frosty_almeida.jet.cooperative.thread-5] [c.h.j.i.u.AsyncSnapshotWriterImpl]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Stats for map-stateful-keyed: keys=2, chunks=2, bytes=212
2021-02-16 02:01:23,747 [DEBUG] [hz.frosty_almeida.jet.cooperative.thread-5] [c.h.j.i.o.SnapshotPhase1Operation]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Snapshot 1 phase 1 for job '05be-635f-7880-0001', execution 05be-635f-7881-0001 finished successfully on member
2021-02-16 02:01:23,747 [DEBUG] [hz.frosty_almeida.cached.thread-6] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Snapshot 1 phase 1 for job '05be-635f-7880-0001', execution 05be-635f-7881-0001 completed with status SUCCESS in 874ms, 852 bytes, 7 keys in 7 chunks, stored in '__jet.snapshot.05be-635f-7880-0001.1', proceeding to phase 2
2021-02-16 02:01:23,752 [DEBUG] [hz.frosty_almeida.cached.thread-6] [c.h.j.i.JobRepository]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Cleared snapshot data map __jet.snapshot.05be-635f-7880-0001.0
2021-02-16 02:01:23,752 [DEBUG] [hz.frosty_almeida.cached.thread-6] [c.h.j.i.e.ExecutionContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Starting snapshot 1 phase 2 for job '05be-635f-7880-0001', execution 05be-635f-7881-0001 on member
2021-02-16 02:01:23,755 [DEBUG] [hz.frosty_almeida.jet.cooperative.thread-8] [c.h.j.i.o.SnapshotPhase2Operation]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Snapshot 1 phase 2 for job '05be-635f-7880-0001', execution 05be-635f-7881-0001 finished successfully on member
2021-02-16 02:01:23,752 [DEBUG] [hz.condescending_almeida.generic-operation.thread-28] [c.h.j.i.e.ExecutionContext]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Starting snapshot 1 phase 2 for job '05be-635f-7880-0001', execution 05be-635f-7881-0001 on member
2021-02-16 02:01:23,761 [DEBUG] [hz.condescending_almeida.jet.blocking.thread-0] [c.h.j.i.o.SnapshotPhase2Operation]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Snapshot 1 phase 2 for job '05be-635f-7880-0001', execution 05be-635f-7881-0001 finished successfully on member
2021-02-16 02:01:23,762 [DEBUG] [hz.frosty_almeida.cached.thread-6] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] job '05be-635f-7880-0001', execution 05be-635f-7881-0001 snapshot is scheduled in 100ms
2021-02-16 02:01:23,762 [DEBUG] [hz.frosty_almeida.cached.thread-6] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Snapshot 1 for job '05be-635f-7880-0001', execution 05be-635f-7881-0001 completed in 889ms, status=success
2021-02-16 02:01:23,869 [DEBUG] [hz.frosty_almeida.cached.thread-6] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Starting snapshot 2 for job '05be-635f-7880-0001', execution 05be-635f-7881-0001, flags: terminal=no,export=no, writing to: null
2021-02-16 02:01:23,869 [DEBUG] [hz.frosty_almeida.cached.thread-6] [c.h.j.i.e.ExecutionContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Starting snapshot 2 phase 1 for job '05be-635f-7880-0001', execution 05be-635f-7881-0001 on member
2021-02-16 02:01:23,869 [DEBUG] [hz.condescending_almeida.generic-operation.thread-30] [c.h.j.i.e.ExecutionContext]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Starting snapshot 2 phase 1 for job '05be-635f-7880-0001', execution 05be-635f-7881-0001 on member
2021-02-16 02:01:23,947 [ INFO] [Time-limited test] [c.h.j.c.JetTestSupport]: Next snapshot found after 1002 ms (id=1, previous id=0)
2021-02-16 02:01:23,955 [DEBUG] [Time-limited test] [c.h.j.Job]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Sending RESTART_GRACEFUL request for job 05be-635f-7880-0001 (name ??)
2021-02-16 02:01:23,955 [DEBUG] [hz.frosty_almeida.cached.thread-6] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Not beginning snapshot since one is already in progress job '05be-635f-7880-0001', execution 05be-635f-7881-0001
2021-02-16 02:01:24,446 [ INFO] [debezium-postgresconnector-fe9be6c9-2bf4-4c0a-a643-25bd40ec2143-change-event-source-coordinator] [i.d.c.p.c.WalPositionLocator]: First LSN 'LSN{0/2044CA0}' received
2021-02-16 02:01:24,446 [ INFO] [debezium-postgresconnector-fe9be6c9-2bf4-4c0a-a643-25bd40ec2143-change-event-source-coordinator] [i.d.c.p.PostgresStreamingChangeEventSource]: WAL resume position 'LSN{0/2044CA0}' discovered
2021-02-16 02:01:24,463 [ INFO] [debezium-postgresconnector-fe9be6c9-2bf4-4c0a-a643-25bd40ec2143-change-event-source-coordinator] [i.d.c.p.PostgresStreamingChangeEventSource]: Processing messages
2021-02-16 02:01:24,463 [ INFO] [debezium-postgresconnector-fe9be6c9-2bf4-4c0a-a643-25bd40ec2143-change-event-source-coordinator] [i.d.c.p.c.WalPositionLocator]: Message with LSN 'LSN{0/2044CA0}' arrived, switching off the filtering
2021-02-16 02:01:24,744 [DEBUG] [hz.condescending_almeida.jet.cooperative.thread-0] [c.h.j.i.u.AsyncSnapshotWriterImpl]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Stats for customers: keys=1, chunks=1, bytes=330
2021-02-16 02:01:24,744 [DEBUG] [hz.condescending_almeida.jet.cooperative.thread-1] [c.h.j.i.u.AsyncSnapshotWriterImpl]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Stats for filter_timestamps: keys=0, chunks=0, bytes=0
2021-02-16 02:01:24,745 [DEBUG] [hz.condescending_almeida.jet.cooperative.thread-6] [c.h.j.i.u.AsyncSnapshotWriterImpl]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Stats for mapSink(results): keys=0, chunks=0, bytes=0
2021-02-16 02:01:24,745 [DEBUG] [hz.condescending_almeida.jet.cooperative.thread-4] [c.h.j.i.u.AsyncSnapshotWriterImpl]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Stats for map-stateful-keyed: keys=4, chunks=4, bytes=310
2021-02-16 02:01:24,745 [DEBUG] [hz.frosty_almeida.jet.cooperative.thread-5] [c.h.j.i.u.AsyncSnapshotWriterImpl]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Stats for map-stateful-keyed: keys=2, chunks=2, bytes=212
2021-02-16 02:01:24,745 [DEBUG] [hz.condescending_almeida.jet.cooperative.thread-4] [c.h.j.i.o.SnapshotPhase1Operation]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Snapshot 2 phase 1 for job '05be-635f-7880-0001', execution 05be-635f-7881-0001 finished successfully on member
2021-02-16 02:01:24,745 [DEBUG] [hz.frosty_almeida.jet.cooperative.thread-7] [c.h.j.i.u.AsyncSnapshotWriterImpl]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Stats for mapSink(results): keys=0, chunks=0, bytes=0
2021-02-16 02:01:24,745 [DEBUG] [hz.frosty_almeida.jet.cooperative.thread-7] [c.h.j.i.o.SnapshotPhase1Operation]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Snapshot 2 phase 1 for job '05be-635f-7880-0001', execution 05be-635f-7881-0001 finished successfully on member
2021-02-16 02:01:24,746 [DEBUG] [hz.frosty_almeida.cached.thread-10] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Snapshot 2 phase 1 for job '05be-635f-7880-0001', execution 05be-635f-7881-0001 completed with status SUCCESS in 884ms, 852 bytes, 7 keys in 7 chunks, stored in '__jet.snapshot.05be-635f-7880-0001.0', proceeding to phase 2
2021-02-16 02:01:24,749 [DEBUG] [hz.frosty_almeida.cached.thread-10] [c.h.j.i.JobRepository]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Cleared snapshot data map __jet.snapshot.05be-635f-7880-0001.1
2021-02-16 02:01:24,749 [DEBUG] [hz.frosty_almeida.cached.thread-10] [c.h.j.i.e.ExecutionContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Starting snapshot 2 phase 2 for job '05be-635f-7880-0001', execution 05be-635f-7881-0001 on member
2021-02-16 02:01:24,749 [DEBUG] [hz.condescending_almeida.generic-operation.thread-33] [c.h.j.i.e.ExecutionContext]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Starting snapshot 2 phase 2 for job '05be-635f-7880-0001', execution 05be-635f-7881-0001 on member
2021-02-16 02:01:24,749 [DEBUG] [hz.frosty_almeida.jet.cooperative.thread-6] [c.h.j.i.o.SnapshotPhase2Operation]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Snapshot 2 phase 2 for job '05be-635f-7880-0001', execution 05be-635f-7881-0001 finished successfully on member
2021-02-16 02:01:24,750 [DEBUG] [hz.condescending_almeida.jet.blocking.thread-0] [c.h.j.i.o.SnapshotPhase2Operation]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Snapshot 2 phase 2 for job '05be-635f-7880-0001', execution 05be-635f-7881-0001 finished successfully on member
2021-02-16 02:01:24,751 [DEBUG] [hz.frosty_almeida.cached.thread-10] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] job '05be-635f-7880-0001', execution 05be-635f-7881-0001 snapshot is scheduled in 100ms
2021-02-16 02:01:24,751 [DEBUG] [hz.frosty_almeida.cached.thread-10] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Snapshot 2 for job '05be-635f-7880-0001', execution 05be-635f-7881-0001 completed in 889ms, status=success
2021-02-16 02:01:24,758 [DEBUG] [hz.frosty_almeida.cached.thread-10] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Starting snapshot 3 for job '05be-635f-7880-0001', execution 05be-635f-7881-0001, flags: terminal=yes,export=no, writing to: null
2021-02-16 02:01:24,758 [DEBUG] [hz.frosty_almeida.cached.thread-10] [c.h.j.i.e.ExecutionContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Starting snapshot 3 phase 1 for job '05be-635f-7880-0001', execution 05be-635f-7881-0001 on member
2021-02-16 02:01:24,758 [DEBUG] [hz.condescending_almeida.generic-operation.thread-35] [c.h.j.i.e.ExecutionContext]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Starting snapshot 3 phase 1 for job '05be-635f-7880-0001', execution 05be-635f-7881-0001 on member
2021-02-16 02:01:24,852 [DEBUG] [hz.frosty_almeida.cached.thread-10] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Not beginning snapshot since one is already in progress job '05be-635f-7880-0001', execution 05be-635f-7881-0001
2021-02-16 02:01:25,245 [DEBUG] [hz.condescending_almeida.jet.cooperative.thread-1] [c.h.j.i.u.AsyncSnapshotWriterImpl]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Stats for filter_timestamps: keys=0, chunks=0, bytes=0
2021-02-16 02:01:25,246 [DEBUG] [hz.condescending_almeida.jet.cooperative.thread-0] [c.h.j.i.u.AsyncSnapshotWriterImpl]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Stats for customers: keys=1, chunks=1, bytes=360
2021-02-16 02:01:25,246 [DEBUG] [hz.condescending_almeida.jet.cooperative.thread-4] [c.h.j.i.u.AsyncSnapshotWriterImpl]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Stats for map-stateful-keyed: keys=4, chunks=4, bytes=310
2021-02-16 02:01:25,246 [DEBUG] [hz.frosty_almeida.jet.cooperative.thread-5] [c.h.j.i.u.AsyncSnapshotWriterImpl]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Stats for map-stateful-keyed: keys=2, chunks=2, bytes=212
2021-02-16 02:01:25,247 [DEBUG] [hz.frosty_almeida.jet.cooperative.thread-7] [c.h.j.i.u.AsyncSnapshotWriterImpl]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Stats for mapSink(results): keys=0, chunks=0, bytes=0
2021-02-16 02:01:25,248 [DEBUG] [hz.frosty_almeida.jet.cooperative.thread-7] [c.h.j.i.o.SnapshotPhase1Operation]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Snapshot 3 phase 1 for job '05be-635f-7880-0001', execution 05be-635f-7881-0001 finished successfully on member
2021-02-16 02:01:25,251 [DEBUG] [hz.condescending_almeida.jet.cooperative.thread-6] [c.h.j.i.u.AsyncSnapshotWriterImpl]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Stats for mapSink(results): keys=0, chunks=0, bytes=0
2021-02-16 02:01:25,251 [DEBUG] [hz.condescending_almeida.jet.cooperative.thread-6] [c.h.j.i.o.SnapshotPhase1Operation]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Snapshot 3 phase 1 for job '05be-635f-7880-0001', execution 05be-635f-7881-0001 finished successfully on member
2021-02-16 02:01:25,252 [DEBUG] [hz.frosty_almeida.cached.thread-9] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Snapshot 3 phase 1 for job '05be-635f-7880-0001', execution 05be-635f-7881-0001 completed with status SUCCESS in 500ms, 882 bytes, 7 keys in 7 chunks, stored in '__jet.snapshot.05be-635f-7880-0001.1', proceeding to phase 2
2021-02-16 02:01:25,256 [DEBUG] [hz.frosty_almeida.cached.thread-9] [c.h.j.i.JobRepository]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Cleared snapshot data map __jet.snapshot.05be-635f-7880-0001.0
2021-02-16 02:01:25,256 [DEBUG] [hz.frosty_almeida.cached.thread-9] [c.h.j.i.e.ExecutionContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Starting snapshot 3 phase 2 for job '05be-635f-7880-0001', execution 05be-635f-7881-0001 on member
2021-02-16 02:01:25,256 [DEBUG] [hz.condescending_almeida.generic-operation.thread-1] [c.h.j.i.e.ExecutionContext]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Starting snapshot 3 phase 2 for job '05be-635f-7880-0001', execution 05be-635f-7881-0001 on member
2021-02-16 02:01:25,256 [DEBUG] [hz.frosty_almeida.jet.cooperative.thread-6] [c.h.j.i.o.SnapshotPhase2Operation]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Snapshot 3 phase 2 for job '05be-635f-7880-0001', execution 05be-635f-7881-0001 finished successfully on member
2021-02-16 02:01:25,257 [DEBUG] [hz.condescending_almeida.jet.blocking.thread-0] [c.h.j.i.o.SnapshotPhase2Operation]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Snapshot 3 phase 2 for job '05be-635f-7880-0001', execution 05be-635f-7881-0001 finished successfully on member
2021-02-16 02:01:25,257 [ INFO] [hz.condescending_almeida.jet.blocking.thread-0] [i.d.c.c.BaseSourceTask]: Stopping down connector
2021-02-16 02:01:25,257 [DEBUG] [hz.frosty_almeida.cached.thread-9] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Snapshot 3 for job '05be-635f-7880-0001', execution 05be-635f-7881-0001 completed in 506ms, status=success
2021-02-16 02:01:25,257 [DEBUG] [hz.frosty_almeida.cached.thread-9] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Not beginning snapshot since terminal snapshot is already completed job '05be-635f-7880-0001', execution 05be-635f-7881-0001
2021-02-16 02:01:25,257 [DEBUG] [hz.frosty_almeida.jet.cooperative.thread-9] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Execution of job '05be-635f-7880-0001', execution 05be-635f-7881-0001 completed with failure
java.util.concurrent.CompletionException: com.hazelcast.jet.impl.exception.TerminatedWithSnapshotException
    at java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:273) ~[?:1.8.0_251]
    at java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:280) ~[?:1.8.0_251]
    at java.util.concurrent.CompletableFuture.uniApply(CompletableFuture.java:618) ~[?:1.8.0_251]
    at java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:591) ~[?:1.8.0_251]
    at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:488) ~[?:1.8.0_251]
    at java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:1975) ~[?:1.8.0_251]
    at com.hazelcast.jet.impl.util.NonCompletableFuture.internalComplete(NonCompletableFuture.java:55) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.execution.TaskletExecutionService$ExecutionTracker.taskletDone(TaskletExecutionService.java:459) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.execution.TaskletExecutionService$CooperativeWorker.dismissTasklet(TaskletExecutionService.java:392) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.execution.TaskletExecutionService$CooperativeWorker.runTasklet(TaskletExecutionService.java:368) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at java.util.concurrent.CopyOnWriteArrayList.forEach(CopyOnWriteArrayList.java:891) [?:1.8.0_251]
    at com.hazelcast.jet.impl.execution.TaskletExecutionService$CooperativeWorker.run(TaskletExecutionService.java:346) [hazelcast-jet-4.5-SNAPS
...[truncated 228177 chars]...
16 02:01:35,464 [DEBUG] [hz.condescending_almeida.jet.blocking.thread-0] [c.h.j.i.o.SnapshotPhase2Operation]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Snapshot 16 phase 2 for job '05be-635f-7880-0001', execution 05be-635f-7888-0001 finished successfully on member
2021-02-16 02:01:35,464 [DEBUG] [hz.frosty_almeida.jet.cooperative.thread-5] [c.h.j.i.o.SnapshotPhase2Operation]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Snapshot 16 phase 2 for job '05be-635f-7880-0001', execution 05be-635f-7888-0001 finished successfully on member
2021-02-16 02:01:35,464 [ INFO] [hz.condescending_almeida.jet.blocking.thread-0] [i.d.c.c.BaseSourceTask]: Stopping down connector
2021-02-16 02:01:35,465 [DEBUG] [hz.frosty_almeida.cached.thread-50] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Snapshot 16 for job '05be-635f-7880-0001', execution 05be-635f-7888-0001 completed in 1001ms, status=success
2021-02-16 02:01:35,465 [DEBUG] [hz.frosty_almeida.cached.thread-50] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Not beginning snapshot since terminal snapshot is already completed job '05be-635f-7880-0001', execution 05be-635f-7888-0001
2021-02-16 02:01:35,465 [DEBUG] [hz.frosty_almeida.jet.cooperative.thread-4] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Execution of job '05be-635f-7880-0001', execution 05be-635f-7888-0001 completed with failure
java.util.concurrent.CompletionException: com.hazelcast.jet.impl.exception.TerminatedWithSnapshotException
    at java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:273) ~[?:1.8.0_251]
    at java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:280) ~[?:1.8.0_251]
    at java.util.concurrent.CompletableFuture.uniApply(CompletableFuture.java:618) ~[?:1.8.0_251]
    at java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:591) ~[?:1.8.0_251]
    at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:488) ~[?:1.8.0_251]
    at java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:1975) ~[?:1.8.0_251]
    at com.hazelcast.jet.impl.util.NonCompletableFuture.internalComplete(NonCompletableFuture.java:55) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.execution.TaskletExecutionService$ExecutionTracker.taskletDone(TaskletExecutionService.java:459) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.execution.TaskletExecutionService$CooperativeWorker.dismissTasklet(TaskletExecutionService.java:392) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.execution.TaskletExecutionService$CooperativeWorker.runTasklet(TaskletExecutionService.java:368) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at java.util.concurrent.CopyOnWriteArrayList.forEach(CopyOnWriteArrayList.java:891) [?:1.8.0_251]
    at com.hazelcast.jet.impl.execution.TaskletExecutionService$CooperativeWorker.run(TaskletExecutionService.java:346) [hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at java.lang.Thread.run(Thread.java:748) [?:1.8.0_251]
Caused by: com.hazelcast.jet.impl.exception.TerminatedWithSnapshotException
    at com.hazelcast.jet.impl.execution.ExecutionContext.lambda$beginExecution$0(ExecutionContext.java:173) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at java.util.concurrent.CompletableFuture.uniApply(CompletableFuture.java:616) ~[?:1.8.0_251]
    ... 10 more
2021-02-16 02:01:35,594 [ INFO] [debezium-postgresconnector-fe9be6c9-2bf4-4c0a-a643-25bd40ec2143-change-event-source-coordinator] [i.d.p.ChangeEventSourceCoordinator]: Finished streaming
2021-02-16 02:01:35,594 [ INFO] [debezium-postgresconnector-fe9be6c9-2bf4-4c0a-a643-25bd40ec2143-change-event-source-coordinator] [i.d.p.m.StreamingChangeEventSourceMetrics]: Connected metrics set to 'false'
2021-02-16 02:01:35,597 [DEBUG] [hz.condescending_almeida.jet.blocking.thread-0] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Execution of job '05be-635f-7880-0001', execution 05be-635f-7888-0001 completed with failure
java.util.concurrent.CompletionException: com.hazelcast.jet.impl.exception.TerminatedWithSnapshotException
    at java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:273) ~[?:1.8.0_251]
    at java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:280) ~[?:1.8.0_251]
    at java.util.concurrent.CompletableFuture.uniApply(CompletableFuture.java:618) ~[?:1.8.0_251]
    at java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:591) ~[?:1.8.0_251]
    at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:488) [?:1.8.0_251]
    at java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:1975) [?:1.8.0_251]
    at com.hazelcast.jet.impl.util.NonCompletableFuture.internalComplete(NonCompletableFuture.java:55) [hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.execution.TaskletExecutionService$ExecutionTracker.taskletDone(TaskletExecutionService.java:459) [hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.execution.TaskletExecutionService$BlockingWorker.run(TaskletExecutionService.java:309) [hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_251]
    at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_251]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_251]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_251]
    at java.lang.Thread.run(Thread.java:748) [?:1.8.0_251]
Caused by: com.hazelcast.jet.impl.exception.TerminatedWithSnapshotException
    at com.hazelcast.jet.impl.execution.ExecutionContext.lambda$beginExecution$0(ExecutionContext.java:173) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at java.util.concurrent.CompletableFuture.uniApply(CompletableFuture.java:616) ~[?:1.8.0_251]
    ... 11 more
2021-02-16 02:01:35,597 [DEBUG] [ForkJoinPool.commonPool-worker-73] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Execution of job '05be-635f-7880-0001', execution 05be-635f-7888-0001 has failures: [[127.0.0.1]:5701=com.hazelcast.jet.impl.exception.TerminatedWithSnapshotException, [127.0.0.1]:5702=com.hazelcast.jet.impl.exception.TerminatedWithSnapshotException]
2021-02-16 02:01:35,598 [DEBUG] [ForkJoinPool.commonPool-worker-73] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Execution of job '05be-635f-7880-0001', execution 05be-635f-7888-0001 terminated after a terminal snapshot
2021-02-16 02:01:35,598 [DEBUG] [hz.frosty_almeida.cached.thread-20] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Sending CompleteExecutionOperation for job '05be-635f-7880-0001', execution 05be-635f-7888-0001
2021-02-16 02:01:35,598 [DEBUG] [hz.frosty_almeida.cached.thread-20] [c.h.j.i.o.CompleteExecutionOperation]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Completing execution 05be-635f-7888-0001 from caller [127.0.0.1]:5701, error=com.hazelcast.jet.impl.exception.JobTerminateRequestedException: RESTART_GRACEFUL
2021-02-16 02:01:35,598 [DEBUG] [hz.frosty_almeida.cached.thread-20] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Completed execution of job '05be-635f-7880-0001', execution 05be-635f-7888-0001
2021-02-16 02:01:35,599 [DEBUG] [hz.condescending_almeida.generic-operation.thread-22] [c.h.j.i.o.CompleteExecutionOperation]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Completing execution 05be-635f-7888-0001 from caller [127.0.0.1]:5701, error=com.hazelcast.jet.impl.exception.JobTerminateRequestedException: RESTART_GRACEFUL
2021-02-16 02:01:35,599 [DEBUG] [hz.condescending_almeida.generic-operation.thread-22] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Completed execution of job '05be-635f-7880-0001', execution 05be-635f-7888-0001
2021-02-16 02:01:35,612 [ INFO] [hz.frosty_almeida.cached.thread-20] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] About to restore the state of job '05be-635f-7880-0001', execution 05be-635f-7889-0001 from snapshot 16, mapName = __jet.snapshot.05be-635f-7880-0001.0
2021-02-16 02:01:35,612 [ INFO] [hz.frosty_almeida.cached.thread-20] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Start executing job '05be-635f-7880-0001', execution 05be-635f-7889-0001, execution graph in DOT format:
digraph DAG {
    "customers" [localParallelism=1];
    "filter_timestamps" [localParallelism=1];
    "map-stateful-keyed" [localParallelism=1];
    "mapSink(results)" [localParallelism=1];
    "customers" -> "filter_timestamps" [queueSize=1024];
    "filter_timestamps" -> "map-stateful-keyed" [label="distributed-partitioned", queueSize=1024];
    "map-stateful-keyed" -> "mapSink(results)" [label="partitioned", queueSize=1024];
}
HINT: You can use graphviz or http://viz-js.com to visualize the printed graph.
2021-02-16 02:01:35,612 [DEBUG] [hz.frosty_almeida.cached.thread-20] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Building execution plan for job '05be-635f-7880-0001', execution 05be-635f-7889-0001
2021-02-16 02:01:35,613 [DEBUG] [hz.frosty_almeida.cached.thread-20] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Built execution plans for job '05be-635f-7880-0001', execution 05be-635f-7889-0001
2021-02-16 02:01:35,614 [DEBUG] [hz.frosty_almeida.cached.thread-20] [c.h.j.i.o.InitExecutionOperation]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Initializing execution plan for job 05be-635f-7880-0001, execution 05be-635f-7889-0001 from [127.0.0.1]:5701
2021-02-16 02:01:35,620 [ INFO] [hz.frosty_almeida.cached.thread-20] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Execution plan for jobId=05be-635f-7880-0001, jobName='05be-635f-7880-0001', executionId=05be-635f-7889-0001 initialized
2021-02-16 02:01:35,621 [DEBUG] [hz.condescending_almeida.generic-operation.thread-24] [c.h.j.i.o.InitExecutionOperation]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Initializing execution plan for job 05be-635f-7880-0001, execution 05be-635f-7889-0001 from [127.0.0.1]:5701
2021-02-16 02:01:35,627 [ INFO] [hz.condescending_almeida.generic-operation.thread-24] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Execution plan for jobId=05be-635f-7880-0001, jobName='05be-635f-7880-0001', executionId=05be-635f-7889-0001 initialized
2021-02-16 02:01:35,627 [DEBUG] [hz.frosty_almeida.cached.thread-20] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Init of job '05be-635f-7880-0001', execution 05be-635f-7889-0001 was successful
2021-02-16 02:01:35,627 [DEBUG] [hz.frosty_almeida.cached.thread-20] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Executing job '05be-635f-7880-0001', execution 05be-635f-7889-0001
2021-02-16 02:01:35,627 [ INFO] [hz.frosty_almeida.cached.thread-20] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Start execution of job '05be-635f-7880-0001', execution 05be-635f-7889-0001 from coordinator [127.0.0.1]:5701
2021-02-16 02:01:35,630 [DEBUG] [hz.frosty_almeida.cached.thread-20] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] job '05be-635f-7880-0001', execution 05be-635f-7889-0001 snapshot is scheduled in 100ms
2021-02-16 02:01:35,631 [ INFO] [hz.condescending_almeida.generic-operation.thread-25] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Start execution of job '05be-635f-7880-0001', execution 05be-635f-7889-0001 from coordinator [127.0.0.1]:5701
2021-02-16 02:01:35,634 [ INFO] [hz.condescending_almeida.jet.blocking.thread-0] [c.h.j.c.i.ChangeRecordCdcSourceP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [05be-635f-7880-0001/customers#0] customers has 'retry strategy' set to 'max attempts = -1, interval function = IntervalFunction (constant of 1000ms)'
2021-02-16 02:01:35,634 [ INFO] [hz.condescending_almeida.jet.blocking.thread-0] [c.h.j.c.i.ChangeRecordCdcSourceP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [05be-635f-7880-0001/customers#0] customers has 'clear state on reconnect' set to 'false'
2021-02-16 02:01:35,636 [DEBUG] [Time-limited test] [c.h.j.Job]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Sending RESTART_GRACEFUL request for job 05be-635f-7880-0001 (name ??)
2021-02-16 02:01:35,639 [DEBUG] [hz.frosty_almeida.cached.thread-5] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Starting snapshot 17 for job '05be-635f-7880-0001', execution 05be-635f-7889-0001, flags: terminal=yes,export=no, writing to: null
2021-02-16 02:01:35,639 [DEBUG] [hz.frosty_almeida.cached.thread-5] [c.h.j.i.e.ExecutionContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Starting snapshot 17 phase 1 for job '05be-635f-7880-0001', execution 05be-635f-7889-0001 on member
2021-02-16 02:01:35,639 [ INFO] [hz.frosty_almeida.cached.thread-5] [c.h.j.i.e.SnapshotContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Snapshot 17 for job '05be-635f-7880-0001', execution 05be-635f-7889-0001 is postponed until all higher priority vertices are completed (number of such vertices = 1)
2021-02-16 02:01:35,639 [ INFO] [hz.frosty_almeida.jet.cooperative.thread-15] [c.h.j.i.e.SnapshotContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Postponed snapshot 17 for job '05be-635f-7880-0001', execution 05be-635f-7889-0001 started
2021-02-16 02:01:35,639 [DEBUG] [hz.condescending_almeida.generic-operation.thread-26] [c.h.j.i.e.ExecutionContext]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Starting snapshot 17 phase 1 for job '05be-635f-7880-0001', execution 05be-635f-7889-0001 on member
2021-02-16 02:01:35,640 [DEBUG] [hz.frosty_almeida.jet.cooperative.thread-22] [c.h.j.i.u.AsyncSnapshotWriterImpl]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Stats for filter_timestamps: keys=0, chunks=0, bytes=0
2021-02-16 02:01:35,640 [DEBUG] [hz.frosty_almeida.jet.cooperative.thread-20] [c.h.j.i.u.AsyncSnapshotWriterImpl]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Stats for customers: keys=0, chunks=0, bytes=0
2021-02-16 02:01:35,640 [DEBUG] [hz.condescending_almeida.jet.cooperative.thread-13] [c.h.j.i.u.AsyncSnapshotWriterImpl]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Stats for filter_timestamps: keys=0, chunks=0, bytes=0
2021-02-16 02:01:35,640 [DEBUG] [hz.condescending_almeida.jet.cooperative.thread-12] [c.h.j.i.u.AsyncSnapshotWriterImpl]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Stats for customers: keys=1, chunks=1, bytes=360
2021-02-16 02:01:35,641 [DEBUG] [hz.condescending_almeida.jet.cooperative.thread-16] [c.h.j.i.u.AsyncSnapshotWriterImpl]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Stats for map-stateful-keyed: keys=4, chunks=4, bytes=310
2021-02-16 02:01:35,642 [DEBUG] [hz.condescending_almeida.jet.cooperative.thread-18] [c.h.j.i.u.AsyncSnapshotWriterImpl]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Stats for mapSink(results): keys=0, chunks=0, bytes=0
2021-02-16 02:01:35,642 [DEBUG] [hz.condescending_almeida.jet.cooperative.thread-18] [c.h.j.i.o.SnapshotPhase1Operation]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Snapshot 17 phase 1 for job '05be-635f-7880-0001', execution 05be-635f-7889-0001 finished successfully on member
2021-02-16 02:01:35,646 [DEBUG] [hz.frosty_almeida.jet.cooperative.thread-25] [c.h.j.i.u.AsyncSnapshotWriterImpl]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Stats for map-stateful-keyed: keys=2, chunks=2, bytes=212
2021-02-16 02:01:35,646 [DEBUG] [hz.frosty_almeida.jet.cooperative.thread-27] [c.h.j.i.u.AsyncSnapshotWriterImpl]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Stats for mapSink(results): keys=0, chunks=0, bytes=0
2021-02-16 02:01:35,646 [DEBUG] [hz.frosty_almeida.jet.cooperative.thread-25] [c.h.j.i.o.SnapshotPhase1Operation]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Snapshot 17 phase 1 for job '05be-635f-7880-0001', execution 05be-635f-7889-0001 finished successfully on member
2021-02-16 02:01:35,647 [DEBUG] [hz.frosty_almeida.cached.thread-11] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Snapshot 17 phase 1 for job '05be-635f-7880-0001', execution 05be-635f-7889-0001 completed with status SUCCESS in 9ms, 882 bytes, 7 keys in 7 chunks, stored in '__jet.snapshot.05be-635f-7880-0001.1', proceeding to phase 2
2021-02-16 02:01:35,649 [DEBUG] [hz.frosty_almeida.cached.thread-11] [c.h.j.i.JobRepository]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Cleared snapshot data map __jet.snapshot.05be-635f-7880-0001.0
2021-02-16 02:01:35,649 [DEBUG] [hz.frosty_almeida.cached.thread-11] [c.h.j.i.e.ExecutionContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Starting snapshot 17 phase 2 for job '05be-635f-7880-0001', execution 05be-635f-7889-0001 on member
2021-02-16 02:01:35,649 [DEBUG] [hz.condescending_almeida.generic-operation.thread-29] [c.h.j.i.e.ExecutionContext]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Starting snapshot 17 phase 2 for job '05be-635f-7880-0001', execution 05be-635f-7889-0001 on member
2021-02-16 02:01:35,649 [DEBUG] [hz.frosty_almeida.jet.cooperative.thread-26] [c.h.j.i.o.SnapshotPhase2Operation]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Snapshot 17 phase 2 for job '05be-635f-7880-0001', execution 05be-635f-7889-0001 finished successfully on member
2021-02-16 02:01:35,651 [DEBUG] [hz.frosty_almeida.jet.cooperative.thread-31] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Execution of job '05be-635f-7880-0001', execution 05be-635f-7889-0001 completed with failure
java.util.concurrent.CompletionException: com.hazelcast.jet.impl.exception.TerminatedWithSnapshotException
    at java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:273) ~[?:1.8.0_251]
    at java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:280) ~[?:1.8.0_251]
    at java.util.concurrent.CompletableFuture.uniApply(CompletableFuture.java:618) ~[?:1.8.0_251]
    at java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:591) ~[?:1.8.0_251]
    at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:488) ~[?:1.8.0_251]
    at java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:1975) ~[?:1.8.0_251]
    at com.hazelcast.jet.impl.util.NonCompletableFuture.internalComplete(NonCompletableFuture.java:55) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.execution.TaskletExecutionService$ExecutionTracker.taskletDone(TaskletExecutionService.java:459) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.execution.TaskletExecutionService$CooperativeWorker.dismissTasklet(TaskletExecutionService.java:392) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.execution.TaskletExecutionService$CooperativeWorker.runTasklet(TaskletExecutionService.java:368) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at java.util.concurrent.CopyOnWriteArrayList.forEach(CopyOnWriteArrayList.java:891) [?:1.8.0_251]
    at com.hazelcast.jet.impl.execution.TaskletExecutionService$CooperativeWorker.run(TaskletExecutionService.java:346) [hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at java.lang.Thread.run(Thread.java:748) [?:1.8.0_251]
Caused by: com.hazelcast.jet.impl.exception.TerminatedWithSnapshotException
    at com.hazelcast.jet.impl.execution.ExecutionContext.lambda$beginExecution$0(ExecutionContext.java:173) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at java.util.concurrent.CompletableFuture.uniApply(CompletableFuture.java:616) ~[?:1.8.0_251]
    ... 10 more
2021-02-16 02:01:35,652 [ WARN] [hz.condescending_almeida.jet.blocking.thread-0] [c.h.j.i.e.TaskletExecutionService]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Exception in ProcessorTasklet{05be-635f-7880-0001/customers#0}
java.lang.NullPointerException: null
    at com.hazelcast.jet.cdc.impl.CdcSourceP.snapshotCommitFinish(CdcSourceP.java:292) ~[hazelcast-jet-cdc-debezium-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.execution.ProcessorTasklet.stateMachineStep(ProcessorTasklet.java:343) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.execution.ProcessorTasklet.stateMachineStep(ProcessorTasklet.java:367) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.execution.ProcessorTasklet.call(ProcessorTasklet.java:247) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.execution.TaskletExecutionService$BlockingWorker.run(TaskletExecutionService.java:293) [hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_251]
    at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_251]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_251]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_251]
    at java.lang.Thread.run(Thread.java:748) [?:1.8.0_251]
2021-02-16 02:01:35,653 [DEBUG] [hz.condescending_almeida.jet.cooperative.thread-12] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Execution of job '05be-635f-7880-0001', execution 05be-635f-7889-0001 completed with failure
java.util.concurrent.CompletionException: com.hazelcast.jet.JetException: Exception in ProcessorTasklet{05be-635f-7880-0001/customers#0}: java.lang.NullPointerException
    at java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:292) ~[?:1.8.0_251]
    at java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:308) ~[?:1.8.0_251]
    at java.util.concurrent.CompletableFuture.uniApply(CompletableFuture.java:607) ~[?:1.8.0_251]
    at java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:591) ~[?:1.8.0_251]
    at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:488) ~[?:1.8.0_251]
    at java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:1990) ~[?:1.8.0_251]
    at com.hazelcast.jet.impl.util.NonCompletableFuture.internalCompleteExceptionally(NonCompletableFuture.java:59) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.execution.TaskletExecutionService$ExecutionTracker.taskletDone(TaskletExecutionService.java:461) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.execution.TaskletExecutionService$CooperativeWorker.dismissTasklet(TaskletExecutionService.java:392) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.execution.TaskletExecutionService$CooperativeWorker.runTasklet(TaskletExecutionService.java:378) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at java.util.concurrent.CopyOnWriteArrayList.forEach(CopyOnWriteArrayList.java:891) [?:1.8.0_251]
    at com.hazelcast.jet.impl.execution.TaskletExecutionService$CooperativeWorker.run(TaskletExecutionService.java:346) [hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at java.lang.Thread.run(Thread.java:748) [?:1.8.0_251]
Caused by: com.hazelcast.jet.JetException: Exception in ProcessorTasklet{05be-635f-7880-0001/customers#0}: java.lang.NullPointerException
    at com.hazelcast.jet.impl.execution.TaskletExecutionService$BlockingWorker.run(TaskletExecutionService.java:304) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) ~[?:1.8.0_251]
    at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[?:1.8.0_251]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) ~[?:1.8.0_251]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) ~[?:1.8.0_251]
    ... 1 more
Caused by: java.lang.NullPointerException
    at com.hazelcast.jet.cdc.impl.CdcSourceP.snapshotCommitFinish(CdcSourceP.java:292) ~[hazelcast-jet-cdc-debezium-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.execution.ProcessorTasklet.stateMachineStep(ProcessorTasklet.java:343) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.execution.ProcessorTasklet.stateMachineStep(ProcessorTasklet.java:367) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.execution.ProcessorTasklet.call(ProcessorTasklet.java:247) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.execution.TaskletExecutionService$BlockingWorker.run(TaskletExecutionService.java:293) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) ~[?:1.8.0_251]
    at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[?:1.8.0_251]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) ~[?:1.8.0_251]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) ~[?:1.8.0_251]
    ... 1 more
2021-02-16 02:01:35,659 [DEBUG] [ForkJoinPool.commonPool-worker-29] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Execution of job '05be-635f-7880-0001', execution 05be-635f-7889-0001 has failures: [[127.0.0.1]:5701=com.hazelcast.jet.impl.exception.TerminatedWithSnapshotException, [127.0.0.1]:5702=com.hazelcast.jet.JetException: Exception in ProcessorTasklet{05be-635f-7880-0001/customers#0}: java.lang.NullPointerException]
2021-02-16 02:01:35,659 [DEBUG] [hz.condescending_almeida.generic-operation.thread-30] [c.h.j.i.o.SnapshotPhase2Operation]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Snapshot 17 phase 2 for job '05be-635f-7880-0001', execution 05be-635f-7889-0001 finished successfully on member
2021-02-16 02:01:35,659 [DEBUG] [hz.frosty_almeida.cached.thread-66] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Sending CompleteExecutionOperation for job '05be-635f-7880-0001', execution 05be-635f-7889-0001
2021-02-16 02:01:35,659 [DEBUG] [hz.frosty_almeida.cached.thread-66] [c.h.j.i.o.CompleteExecutionOperation]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Completing execution 05be-635f-7889-0001 from caller [127.0.0.1]:5701, error=com.hazelcast.jet.JetException: Exception in ProcessorTasklet{05be-635f-7880-0001/customers#0}: java.lang.NullPointerException
2021-02-16 02:01:35,659 [DEBUG] [hz.frosty_almeida.cached.thread-50] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Snapshot 17 for job '05be-635f-7880-0001', execution 05be-635f-7889-0001 completed in 22ms, status=success
2021-02-16 02:01:35,660 [DEBUG] [hz.frosty_almeida.cached.thread-50] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Not beginning snapshot since terminal snapshot is already completed job '05be-635f-7880-0001', execution 05be-635f-7889-0001
2021-02-16 02:01:35,660 [DEBUG] [hz.frosty_almeida.cached.thread-66] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Completed execution of job '05be-635f-7880-0001', execution 05be-635f-7889-0001
2021-02-16 02:01:35,662 [DEBUG] [hz.condescending_almeida.generic-operation.thread-31] [c.h.j.i.o.CompleteExecutionOperation]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Completing execution 05be-635f-7889-0001 from caller [127.0.0.1]:5701, error=com.hazelcast.jet.JetException: Exception in ProcessorTasklet{05be-635f-7880-0001/customers#0}: java.lang.NullPointerException
2021-02-16 02:01:35,662 [DEBUG] [hz.condescending_almeida.generic-operation.thread-31] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Completed execution of job '05be-635f-7880-0001', execution 05be-635f-7889-0001
2021-02-16 02:01:35,662 [ERROR] [hz.frosty_almeida.cached.thread-66] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Execution of job '05be-635f-7880-0001', execution 05be-635f-7889-0001 failed
    Start time: 2021-02-16T02:01:35.599
    Duration: 00:00:00.063
    To see additional job metrics enable JobConfig.storeMetricsAfterJobCompletion
com.hazelcast.jet.JetException: Exception in ProcessorTasklet{05be-635f-7880-0001/customers#0}: java.lang.NullPointerException
    at com.hazelcast.jet.impl.execution.TaskletExecutionService$BlockingWorker.run(TaskletExecutionService.java:304) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) ~[?:1.8.0_251]
    at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[?:1.8.0_251]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) ~[?:1.8.0_251]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) ~[?:1.8.0_251]
    at java.lang.Thread.run(Thread.java:748) ~[?:1.8.0_251]
Caused by: java.lang.NullPointerException
    at com.hazelcast.jet.cdc.impl.CdcSourceP.snapshotCommitFinish(CdcSourceP.java:292) ~[hazelcast-jet-cdc-debezium-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.execution.ProcessorTasklet.stateMachineStep(ProcessorTasklet.java:343) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.execution.ProcessorTasklet.stateMachineStep(ProcessorTasklet.java:367) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.execution.ProcessorTasklet.call(ProcessorTasklet.java:247) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.execution.TaskletExecutionService$BlockingWorker.run(TaskletExecutionService.java:293) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    ... 5 more
2021-02-16 02:01:35,664 [DEBUG] [hz.frosty_almeida.cached.thread-66] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] job '05be-635f-7880-0001', execution 05be-635f-7889-0001 is completed
2021-02-16 02:01:35,730 [DEBUG] [hz.frosty_almeida.cached.thread-66] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Not beginning snapshot, job '05be-635f-7880-0001', execution 05be-635f-7889-0001 is not RUNNING, but FAILED
2021-02-16 02:01:39,508 [ INFO] [hz.frosty_almeida.HealthMonitor] [c.h.i.d.HealthMonitor]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] processors=72, physical.memory.total=377.6G, physical.memory.free=61.2G, swap.space.total=4.0G, swap.space.free=4.0G, heap.memory.used=332.5M, heap.memory.free=650.0M, heap.memory.total=982.5M, heap.memory.max=982.5M, heap.memory.used/total=33.84%, heap.memory.used/max=33.84%, minor.gc.count=19, minor.gc.time=973ms, major.gc.count=3, major.gc.time=423ms, load.process=0.00%, load.system=50.00%, load.systemAverage=154.02, thread.count=734, thread.peakCount=751, cluster.timeDiff=0, event.q.size=0, executor.q.async.size=0, executor.q.client.size=0, executor.q.client.query.size=0, executor.q.client.blocking.size=0, executor.q.query.size=0, executor.q.scheduled.size=0, executor.q.io.size=0, executor.q.system.size=0, executor.q.operations.size=0, executor.q.priorityOperation.size=0, operations.completed.count=15936, executor.q.mapLoad.size=0, executor.q.mapLoadAllKeys.size=0, executor.q.cluster.size=0, executor.q.response.size=0, operations.running.count=0, operations.pending.invocations.percentage=0.00%, operations.pending.invocations.count=0, proxy.count=9, clientEndpoint.count=0, connection.active.count=0, client.connection.count=0, connection.count=0
2021-02-16 02:01:40,379 [DEBUG] [hz.frosty_almeida.cached.thread-5] [c.h.j.i.JobRepository]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Deleting snapshot data map '__jet.snapshot.05be-635f-7880-0001.1' because job already finished
2021-02-16 02:01:40,391 [DEBUG] [hz.frosty_almeida.cached.thread-5] [c.h.j.i.JobRepository]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Deleting snapshot data map '__jet.snapshot.05be-635f-7880-0001.0' because job already finished
2021-02-16 02:01:40,405 [DEBUG] [hz.frosty_almeida.cached.thread-5] [c.h.j.i.JobRepository]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Job cleanup took 26ms
2021-02-16 02:01:45,410 [DEBUG] [hz.frosty_almeida.cached.thread-66] [c.h.j.i.JobRepository]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Job cleanup took 1ms
2021-02-16 02:01:50,423 [DEBUG] [hz.frosty_almeida.cached.thread-12] [c.h.j.i.JobRepository]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Job cleanup took 1ms
2021-02-16 02:01:55,429 [DEBUG] [hz.frosty_almeida.cached.thread-50] [c.h.j.i.JobRepository]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Job cleanup took 1ms
2021-02-16 02:01:59,511 [ INFO] [hz.frosty_almeida.HealthMonitor] [c.h.i.d.HealthMonitor]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] processors=72, physical.memory.total=377.6G, physical.memory.free=60.5G, swap.space.total=4.0G, swap.space.free=4.0G, heap.memory.used=258.1M, heap.memory.free=724.4M, heap.memory.total=982.5M, heap.memory.max=982.5M, heap.memory.used/total=26.27%, heap.memory.used/max=26.27%, minor.gc.count=20, minor.gc.time=1034ms, major.gc.count=3, major.gc.time=423ms, load.process=0.00%, load.system=75.00%, load.systemAverage=136.75, thread.count=734, thread.peakCount=751, cluster.timeDiff=0, event.q.size=0, executor.q.async.size=0, executor.q.client.size=0, executor.q.client.query.size=0, executor.q.client.blocking.size=0, executor.q.query.size=0, executor.q.scheduled.size=0, executor.q.io.size=0, executor.q.system.size=0, executor.q.operations.size=0, executor.q.priorityOperation.size=0, operations.completed.count=19945, executor.q.mapLoad.size=0, executor.q.mapLoadAllKeys.size=0, executor.q.cluster.size=0, executor.q.response.size=0, operations.running.count=0, operations.pending.invocations.percentage=0.00%, operations.pending.invocations.count=0, proxy.count=7, clientEndpoint.count=0, connection.active.count=0, client.connection.count=0, connection.count=0
2021-02-16 02:02:00,106 [ INFO] [hz.condescending_almeida.HealthMonitor] [c.h.i.d.HealthMonitor]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] processors=72, physical.memory.total=377.6G, physical.memory.free=59.8G, swap.space.total=4.0G, swap.space.free=4.0G, heap.memory.used=266.3M, heap.memory.free=716.2M, heap.memory.total=982.5M, heap.memory.max=982.5M, heap.memory.used/total=27.10%, heap.memory.used/max=27.10%, minor.gc.count=20, minor.gc.time=1034ms, major.gc.count=3, major.gc.time=423ms, load.process=0.00%, load.system=85.71%, load.systemAverage=136.75, thread.count=734, thread.peakCount=751, cluster.timeDiff=0, event.q.size=0, executor.q.async.size=0, executor.q.client.size=0, executor.q.client.query.size=0, executor.q.client.blocking.size=0, executor.q.query.size=0, executor.q.scheduled.size=0, executor.q.io.size=0, executor.q.system.size=0, executor.q.operations.size=0, executor.q.priorityOperation.size=0, operations.completed.count=22766, executor.q.mapLoad.size=0, executor.q.mapLoadAllKeys.size=0, executor.q.cluster.size=0, executor.q.response.size=0, operations.running.count=0, operations.pending.invocations.percentage=0.00%, operations.pending.invocations.count=0, proxy.count=7, clientEndpoint.count=0, connection.active.count=0, client.connection.count=0, connection.count=0
2021-02-16 02:02:00,462 [DEBUG] [hz.frosty_almeida.cached.thread-4] [c.h.j.i.JobRepository]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Job cleanup took 5ms
2021-02-16 02:02:05,485 [DEBUG] [hz.frosty_almeida.cached.thread-50] [c.h.j.i.JobRepository]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Job cleanup took 8ms
2021-02-16 02:02:10,537 [DEBUG] [hz.frosty_almeida.cached.thread-42] [c.h.j.i.JobRepository]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Job cleanup took 23ms
2021-02-16 02:02:15,591 [DEBUG] [hz.frosty_almeida.cached.thread-7] [c.h.j.i.JobRepository]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Job cleanup took 14ms
2021-02-16 02:02:19,516 [ INFO] [hz.frosty_almeida.HealthMonitor] [c.h.i.d.HealthMonitor]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] processors=72, physical.memory.total=377.6G, physical.memory.free=59.7G, swap.space.total=4.0G, swap.space.free=4.0G, heap.memory.used=187.4M, heap.memory.free=756.6M, heap.memory.total=944.0M, heap.memory.max=944.0M, heap.memory.used/total=19.85%, heap.memory.used/max=19.85%, minor.gc.count=21, minor.gc.time=1093ms, major.gc.count=3, major.gc.time=423ms, load.process=0.00%, load.system=86.67%, load.systemAverage=186.36, thread.count=732, thread.peakCount=751, cluster.timeDiff=0, event.q.size=0, executor.q.async.size=0, executor.q.client.size=0, executor.q.client.query.size=0, executor.q.client.blocking.size=0, executor.q.query.size=0, executor.q.scheduled.size=0, executor.q.io.size=0, executor.q.system.size=0, executor.q.operations.size=0, executor.q.priorityOperation.size=0, operations.completed.count=23412, executor.q.mapLoad.size=0, executor.q.mapLoadAllKeys.size=0, executor.q.cluster.size=0, executor.q.response.size=0, operations.running.count=0, operations.pending.invocations.percentage=0.00%, operations.pending.invocations.count=0, proxy.count=7, clientEndpoint.count=0, connection.active.count=0, client.connection.count=0, connection.count=0
2021-02-16 02:02:20,110 [ INFO] [hz.condescending_almeida.HealthMonitor] [c.h.i.d.HealthMonitor]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] processors=72, physical.memory.total=377.6G, physical.memory.free=60.2G, swap.space.total=4.0G, swap.space.free=4.0G, heap.memory.used=195.5M, heap.memory.free=748.5M, heap.memory.total=944.0M, heap.memory.max=944.0M, heap.memory.used/total=20.71%, heap.memory.used/max=20.71%, minor.gc.count=21, minor.gc.time=1093ms, major.gc.count=3, major.gc.time=423ms, load.process=0.00%, load.system=76.92%, load.systemAverage=186.36, thread.count=732, thread.peakCount=751, cluster.timeDiff=-2, event.q.size=0, executor.q.async.size=0, executor.q.client.size=0, executor.q.client.query.size=0, executor.q.client.blocking.size=0, executor.q.query.size=0, executor.q.scheduled.size=0, executor.q.io.size=0, executor.q.system.size=0, executor.q.operations.size=0, executor.q.priorityOperation.size=0, operations.completed.count=26795, executor.q.mapLoad.size=0, executor.q.mapLoadAllKeys.size=0, executor.q.cluster.size=0, executor.q.response.size=0, operations.running.count=0, operations.pending.invocations.percentage=0.00%, operations.pending.invocations.count=0, proxy.count=7, clientEndpoint.count=0, connection.active.count=0, client.connection.count=0, connection.count=0
2021-02-16 02:02:20,611 [DEBUG] [hz.frosty_almeida.cached.thread-5] [c.h.j.i.JobRepository]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Job cleanup took 3ms
2021-02-16 02:02:25,615 [DEBUG] [hz.frosty_almeida.cached.thread-35] [c.h.j.i.JobRepository]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Job cleanup took 1ms
2021-02-16 02:02:30,620 [DEBUG] [hz.frosty_almeida.cached.thread-4] [c.h.j.i.JobRepository]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Job cleanup took 1ms
2021-02-16 02:02:35,625 [DEBUG] [hz.frosty_almeida.cached.thread-4] [c.h.j.i.JobRepository]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Job cleanup took 1ms
2021-02-16 02:02:40,662 [DEBUG] [hz.frosty_almeida.cached.thread-37] [c.h.j.i.JobRepository]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Job cleanup took 18ms
2021-02-16 02:02:45,666 [DEBUG] [hz.frosty_almeida.cached.thread-35] [c.h.j.i.JobRepository]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Job cleanup took 1ms
2021-02-16 02:02:50,686 [DEBUG] [hz.frosty_almeida.cached.thread-35] [c.h.j.i.JobRepository]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Job cleanup took 10ms
2021-02-16 02:02:55,692 [DEBUG] [hz.frosty_almeida.cached.thread-50] [c.h.j.i.JobRepository]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Job cleanup took 3ms
2021-02-16 02:03:00,709 [DEBUG] [hz.frosty_almeida.cached.thread-66] [c.h.j.i.JobRepository]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Job cleanup took 4ms
2021-02-16 02:03:05,712 [DEBUG] [hz.frosty_almeida.cached.thread-55] [c.h.j.i.JobRepository]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Job cleanup took 0ms
2021-02-16 02:03:10,715 [DEBUG] [hz.frosty_almeida.cached.thread-42] [c.h.j.i.JobRepository]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Job cleanup took 1ms
2021-02-16 02:03:15,721 [DEBUG] [hz.frosty_almeida.cached.thread-5] [c.h.j.i.JobRepository]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Job cleanup took 1ms
2021-02-16 02:03:20,734 [DEBUG] [hz.frosty_almeida.cached.thread-50] [c.h.j.i.JobRepository]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Job cleanup took 2ms
2021-02-16 02:03:25,738 [DEBUG] [hz.frosty_almeida.cached.thread-47] [c.h.j.i.JobRepository]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Job cleanup took 1ms
2021-02-16 02:03:30,756 [DEBUG] [hz.frosty_almeida.cached.thread-11] [c.h.j.i.JobRepository]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Job cleanup took 7ms
2021-02-16 02:03:35,765 [ INFO] [Time-limited test] [c.h.j.c.JetTestSupport]: Terminating instanceFactory in JetTestSupport.@After
2021-02-16 02:03:35,767 [ INFO] [Thread-17] [c.h.c.LifecycleService]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [127.0.0.1]:5702 is SHUTTING_DOWN
2021-02-16 02:03:35,769 [ WARN] [Thread-17] [c.h.i.i.Node]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Terminating forcefully...
2021-02-16 02:03:35,769 [ INFO] [Thread-17] [c.h.i.i.Node]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Shutting down connection manager...
2021-02-16 02:03:35,796 [ INFO] [Thread-17] [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-02-16 02:03:35,796 [ INFO] [Thread-17] [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-02-16 02:03:35,796 [ INFO] [Thread-17] [c.h.i.c.i.MembershipManager]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Removing Member [127.0.0.1]:5702 - 2b8ca85c-d39a-4439-a545-a17e8052dc10
2021-02-16 02:03:35,797 [ INFO] [Thread-17] [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 - 9e77d632-e41d-4bff-8049-3a81f2db79c9 this
]

2021-02-16 02:03:35,816 [ INFO] [Thread-17] [c.h.i.i.Node]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Shutting down node engine...
2021-02-16 02:03:35,804 [ INFO] [hz.frosty_almeida.cached.thread-11] [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: 2b8ca85c-d39a-4439-a545-a17e8052dc10
2021-02-16 02:03:36,511 [ INFO] [Thread-17] [c.h.i.i.NodeExtension]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Destroying node NodeExtension.
2021-02-16 02:03:36,517 [ INFO] [Thread-17] [c.h.i.i.Node]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Hazelcast Shutdown is completed in 748 ms.
2021-02-16 02:03:36,517 [ INFO] [Thread-17] [c.h.c.LifecycleService]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [127.0.0.1]:5702 is SHUTDOWN
2021-02-16 02:03:36,517 [ INFO] [Thread-17] [c.h.c.LifecycleService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] [127.0.0.1]:5701 is SHUTTING_DOWN
2021-02-16 02:03:36,518 [ WARN] [Thread-17] [c.h.i.i.Node]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Terminating forcefully...
2021-02-16 02:03:36,518 [ INFO] [Thread-17] [c.h.i.i.Node]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Shutting down connection manager...
2021-02-16 02:03:36,521 [ INFO] [Thread-17] [c.h.i.i.Node]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Shutting down node engine...
2021-02-16 02:03:36,810 [ WARN] [hz.frosty_almeida.partition-operation.thread-15] [c.h.s.i.o.i.Invocation]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Future.complete(Object) on completed future. Request: Invocation{op=com.hazelcast.spi.impl.operationservice.impl.operations.PartitionIteratingOperation{serviceName='hz:impl:mapService', identityHash=791556380, partitionId=-1, replicaIndex=0, callId=-8712, invocationTime=1613441016673 (2021-02-16 02:03:36.673), waitTimeout=-1, callTimeout=60000, operationFactory=com.hazelcast.map.impl.operation.SizeOperationFactory@37dcc461}, tryCount=10, tryPauseMillis=300, invokeCount=1, callTimeoutMillis=60000, firstInvocationTimeMs=1613441016672, firstInvocationTime='2021-02-16 02:03:36.672', lastHeartbeatMillis=0, lastHeartbeatTime='1970-01-01 00:00:00.000', target=[127.0.0.1]:5701, pendingResponse={VOID}, backupsAcksExpected=-1, backupsAcksReceived=0, connection=null}, current value: ExceptionalResult{cause=com.hazelcast.core.HazelcastInstanceNotActiveException: Hazelcast instance is not active!}, offered value: com.hazelcast.spi.impl.operationservice.impl.operations.PartitionIteratingOperation$PartitionResponse@72de4cfe
java.lang.Exception: null
    at com.hazelcast.spi.impl.AbstractInvocationFuture.warnIfSuspiciousDoubleCompletion(AbstractInvocationFuture.java:1208) [hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.AbstractInvocationFuture.complete0(AbstractInvocationFuture.java:1185) [hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.AbstractInvocationFuture.complete(AbstractInvocationFuture.java:1174) [hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.Invocation.complete(Invocation.java:675) [hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.Invocation.sendResponse(Invocation.java:239) [hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.Offload$OffloadedOperationResponseHandler.sendResponse(Offload.java:166) [hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.Operation.sendResponse(Operation.java:470) [hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.operations.PartitionIteratingOperation$OperationResponseHandlerImpl.sendResponse(PartitionIteratingOperation.java:270) [hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.operations.PartitionIteratingOperation$OperationResponseHandlerImpl.sendResponse(PartitionIteratingOperation.java:258) [hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.Operation.sendResponse(Operation.java:470) [hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.call(OperationRunnerImpl.java:266) [hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:237) [hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:213) [hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationexecutor.impl.OperationThread.process(OperationThread.java:160) [hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationexecutor.impl.OperationThread.process(OperationThread.java:190) [hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationexecutor.impl.OperationThread.process(OperationThread.java:144) [hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationexecutor.impl.OperationThread.executeRun(OperationThread.java:123) [hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.internal.util.executor.HazelcastManagedThread.run(HazelcastManagedThread.java:102) [hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
2021-02-16 02:03:37,092 [ INFO] [Thread-17] [c.h.i.i.NodeExtension]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Destroying node NodeExtension.
2021-02-16 02:03:37,093 [ INFO] [Thread-17] [c.h.i.i.Node]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Hazelcast Shutdown is completed in 575 ms.
2021-02-16 02:03:37,094 [ INFO] [Thread-17] [c.h.c.LifecycleService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] [127.0.0.1]:5701 is SHUTDOWN
BuildInfo right after stressTest_exactlyOnce_gracefulRestart(com.hazelcast.jet.cdc.postgres.PostgresCdcIntegrationTest): BuildInfo{version='4.1.1', build='20201222', buildNumber=20201222, revision=27af558, enterprise=false, serializationVersion=1, jet=JetBuildInfo{version='4.5-SNAPSHOT', build='20210216', revision='43b3ac2'}}
Hiccups measured while running test 'stressTest_exactlyOnce_gracefulRestart(com.hazelcast.jet.cdc.postgres.PostgresCdcIntegrationTest):'
02:01:15, accumulated pauses: 131 ms, max pause: 12 ms, pauses over 1000 ms: 0
02:01:20, accumulated pauses: 79 ms, max pause: 5 ms, pauses over 1000 ms: 0
02:01:25, accumulated pauses: 203 ms, max pause: 52 ms, pauses over 1000 ms: 0
02:01:30, accumulated pauses: 207 ms, max pause: 90 ms, pauses over 1000 ms: 0
02:01:35, accumulated pauses: 53 ms, max pause: 4 ms, pauses over 1000 ms: 0
02:01:40, accumulated pauses: 169 ms, max pause: 66 ms, pauses over 1000 ms: 0
02:01:45, accumulated pauses: 53 ms, max pause: 7 ms, pauses over 1000 ms: 0
02:01:50, accumulated pauses: 247 ms, max pause: 54 ms, pauses over 1000 ms: 0
02:01:55, accumulated pauses: 168 ms, max pause: 10 ms, pauses over 1000 ms: 0
02:02:00, accumulated pauses: 185 ms, max pause: 17 ms, pauses over 1000 ms: 0
02:02:05, accumulated pauses: 263 ms, max pause: 60 ms, pauses over 1000 ms: 0
02:02:10, accumulated pauses: 179 ms, max pause: 9 ms, pauses over 1000 ms: 0
02:02:15, accumulated pauses: 168 ms, max pause: 8 ms, pauses over 1000 ms: 0
02:02:20, accumulated pauses: 171 ms, max pause: 9 ms, pauses over 1000 ms: 0
02:02:25, accumulated pauses: 29 ms, max pause: 1 ms, pauses over 1000 ms: 0
02:02:30, accumulated pauses: 28 ms, max pause: 2 ms, pauses over 1000 ms: 0
02:02:35, accumulated pauses: 71 ms, max pause: 30 ms, pauses over 1000 ms: 0
02:02:40, accumulated pauses: 76 ms, max pause: 7 ms, pauses over 1000 ms: 0
02:02:45, accumulated pauses: 22 ms, max pause: 0 ms, pauses over 1000 ms: 0
02:02:50, accumulated pauses: 71 ms, max pause: 10 ms, pauses over 1000 ms: 0
02:02:55, accumulated pauses: 92 ms, max pause: 16 ms, pauses over 1000 ms: 0
02:03:00, accumulated pauses: 59 ms, max pause: 9 ms, pauses over 1000 ms: 0
02:03:05, accumulated pauses: 33 ms, max pause: 2 ms, pauses over 1000 ms: 0
02:03:10, accumulated pauses: 43 ms, max pause: 5 ms, pauses over 1000 ms: 0
02:03:15, accumulated pauses: 108 ms, max pause: 8 ms, pauses over 1000 ms: 0
02:03:20, accumulated pauses: 43 ms, max pause: 3 ms, pauses over 1000 ms: 0
02:03:25, accumulated pauses: 66 ms, max pause: 7 ms, pauses over 1000 ms: 0
02:03:30, accumulated pauses: 289 ms, max pause: 26 ms, pauses over 1000 ms: 0
02:03:35, accumulated pauses: 316 ms, max pause: 41 ms, pauses over 1000 ms: 0
olukas commented 3 years ago

Failed again: http://jenkins.hazelcast.com/job/jet-oss-master-nightly-oracle-jdk8/415/testReport/junit/com.hazelcast.jet.cdc.postgres/PostgresCdcIntegrationTest/stressTest_exactlyOnce_gracefulRestart/

olukas commented 3 years ago

Failed again: http://jenkins.hazelcast.com/job/jet-oss-master-nightly-oracle-jdk11/46/testReport/junit/com.hazelcast.jet.cdc.postgres/PostgresCdcIntegrationTest/stressTest_exactlyOnce_gracefulRestart/