hazelcast / hazelcast-jet

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

com.hazelcast.jet.cdc.postgres.PostgresCdcIntegrationTest.stressTest_exactlyOnce_forcefulRestart #3022

Open olukas opened 3 years ago

olukas commented 3 years ago

master (commit 8e7c2995ec2c9d47a2057f018c85c89ef5cac609)

Failed on OpenJDK 8: http://jenkins.hazelcast.com/view/Jet%20-%20Compatibility/job/jet-oss-master-nightly-zulu-jdk8/48/testReport/com.hazelcast.jet.cdc.postgres/PostgresCdcIntegrationTest/stressTest_exactlyOnce_forcefulRestart/

Stacktrace:

java.lang.AssertionError: expected:<1004> but was:<4>
    at org.junit.Assert.fail(Assert.java:89)
    at org.junit.Assert.failNotEquals(Assert.java:835)
    at org.junit.Assert.assertEquals(Assert.java:647)
    at org.junit.Assert.assertEquals(Assert.java:633)
    at com.hazelcast.jet.cdc.AbstractCdcIntegrationTest.assertMatch(AbstractCdcIntegrationTest.java:65)
    at com.hazelcast.jet.cdc.postgres.PostgresCdcIntegrationTest.lambda$stressTest_exactlyOnce$5(PostgresCdcIntegrationTest.java:216)
    at com.hazelcast.test.HazelcastTestSupport.assertTrueEventually(HazelcastTestSupport.java:1247)
    at com.hazelcast.test.HazelcastTestSupport.assertTrueEventually(HazelcastTestSupport.java:1349)
    at com.hazelcast.jet.cdc.postgres.PostgresCdcIntegrationTest.stressTest_exactlyOnce(PostgresCdcIntegrationTest.java:216)
    at com.hazelcast.jet.cdc.postgres.PostgresCdcIntegrationTest.stressTest_exactlyOnce_forcefulRestart(PostgresCdcIntegrationTest.java:153)
    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-04-06 06:27:12,295 [ INFO] [Time-limited test] [d.3]]: Creating container for image: debezium/example-postgres:1.3
2021-04-06 06:27:13,206 [ INFO] [Time-limited test] [d.3]]: Starting container with ID: 0b8ac6a9fabd6b2655c57fb9df7215bee15dc45f39fbb7faa25eef064a235156
2021-04-06 06:27:13,976 [ INFO] [Time-limited test] [d.3]]: Container debezium/example-postgres:1.3 is starting: 0b8ac6a9fabd6b2655c57fb9df7215bee15dc45f39fbb7faa25eef064a235156
2021-04-06 06:27:16,775 [ INFO] [Time-limited test] [d.3]]: Container debezium/example-postgres:1.3 started in PT4.48S
2021-04-06 06:27:16,781 [ 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-04-06 06:27:16,782 [ INFO] [Time-limited test] [c.h.system]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Hazelcast Jet 4.5-SNAPSHOT (20210406 - 8e7c299) starting at [127.0.0.1]:5701
2021-04-06 06:27:16,782 [ INFO] [Time-limited test] [c.h.system]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Based on Hazelcast IMDG version: 4.2.0 (20210312 - b4344f9)
2021-04-06 06:27:16,782 [ INFO] [Time-limited test] [c.h.system]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Cluster name: jet
2021-04-06 06:27:16,782 [ 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-04-06 06:27:16,782 [ 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-04-06 06:27:16,788 [ 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-04-06 06:27:16,798 [ 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-04-06 06:27:16,814 [ 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-04-06 06:27:16,838 [ 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-04-06 06:27:16,839 [ 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-04-06 06:27:16,839 [ 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 - 013460ae-b93b-4c6d-867c-2396a14941e7 this
]

2021-04-06 06:27:16,840 [ 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-04-06 06:27:16,840 [DEBUG] [hz.clever_meninsky.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-04-06 06:27:16,841 [ 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-04-06 06:27:16,842 [ INFO] [Time-limited test] [c.h.system]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Hazelcast Jet 4.5-SNAPSHOT (20210406 - 8e7c299) starting at [127.0.0.1]:5702
2021-04-06 06:27:16,842 [ INFO] [Time-limited test] [c.h.system]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Based on Hazelcast IMDG version: 4.2.0 (20210312 - b4344f9)
2021-04-06 06:27:16,842 [ INFO] [Time-limited test] [c.h.system]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Cluster name: jet
2021-04-06 06:27:16,842 [ 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-04-06 06:27:16,842 [ 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-04-06 06:27:16,844 [ INFO] [hz.clever_meninsky.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=42.7G, swap.space.total=4.0G, swap.space.free=3.7G, heap.memory.used=196.6M, heap.memory.free=775.4M, heap.memory.total=972.0M, heap.memory.max=972.0M, heap.memory.used/total=20.20%, heap.memory.used/max=20.20%, minor.gc.count=17, minor.gc.time=695ms, major.gc.count=3, major.gc.time=317ms, load.process=15.38%, load.system=66.67%, load.systemAverage=176.93, thread.count=284, thread.peakCount=604, 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=0, 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=6, clientEndpoint.count=0, connection.active.count=0, client.connection.count=0, connection.count=0
2021-04-06 06:27:16,845 [ 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-04-06 06:27:16,859 [ 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-04-06 06:27:16,913 [ 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-04-06 06:27:16,926 [ 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-04-06 06:27:16,926 [ 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-04-06 06:27:16,927 [ 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-04-06 06:27:16,930 [ INFO] [hz.clever_meninsky.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-04-06 06:27:16,931 [ INFO] [hz.clever_meninsky.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 - 013460ae-b93b-4c6d-867c-2396a14941e7 this
    Member [127.0.0.1]:5702 - 067792be-41ab-4077-859a-454476f6d48c
]

2021-04-06 06:27:16,940 [DEBUG] [hz.clever_meninsky.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-04-06 06:27:17,032 [ INFO] [hz.amazing_meninsky.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 - 013460ae-b93b-4c6d-867c-2396a14941e7
    Member [127.0.0.1]:5702 - 067792be-41ab-4077-859a-454476f6d48c this
]

2021-04-06 06:27:17,041 [DEBUG] [hz.clever_meninsky.cached.thread-5] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Not starting jobs because partitions are not yet initialized.
2021-04-06 06:27:17,141 [DEBUG] [hz.clever_meninsky.cached.thread-5] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Not starting jobs because partitions are not yet initialized.
2021-04-06 06:27:17,242 [DEBUG] [hz.clever_meninsky.cached.thread-5] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Not starting jobs because partitions are not yet initialized.
2021-04-06 06:27:17,342 [DEBUG] [hz.clever_meninsky.cached.thread-3] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Not starting jobs because partitions are not yet initialized.
2021-04-06 06:27:17,428 [ 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-04-06 06:27:17,430 [ INFO] [hz.clever_meninsky.cached.thread-3] [c.h.i.p.i.PartitionStateManager]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Initializing cluster partition table arrangement...
2021-04-06 06:27:17,441 [DEBUG] [hz.clever_meninsky.cached.thread-3] [c.h.j.i.p.Planner]: Watermarks in the pipeline will be throttled to 1
2021-04-06 06:27:17,451 [ INFO] [hz.clever_meninsky.cached.thread-3] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Starting job 05fd-b625-cd00-0001 based on submit request
2021-04-06 06:27:17,460 [DEBUG] [hz.clever_meninsky.cached.thread-5] [c.h.j.i.JobRepository]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Job cleanup took 4ms
2021-04-06 06:27:17,460 [ INFO] [hz.clever_meninsky.cached.thread-3] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Didn't find any snapshot to restore for job '05fd-b625-cd00-0001', execution 05fd-b625-cd01-0001
2021-04-06 06:27:17,460 [ INFO] [hz.clever_meninsky.cached.thread-3] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Start executing job '05fd-b625-cd00-0001', execution 05fd-b625-cd01-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-04-06 06:27:17,460 [DEBUG] [hz.clever_meninsky.cached.thread-3] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Building execution plan for job '05fd-b625-cd00-0001', execution 05fd-b625-cd01-0001
2021-04-06 06:27:17,461 [DEBUG] [hz.clever_meninsky.cached.thread-3] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Built execution plans for job '05fd-b625-cd00-0001', execution 05fd-b625-cd01-0001
2021-04-06 06:27:17,461 [DEBUG] [hz.clever_meninsky.cached.thread-3] [c.h.j.i.o.InitExecutionOperation]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Initializing execution plan for job 05fd-b625-cd00-0001, execution 05fd-b625-cd01-0001 from [127.0.0.1]:5701
2021-04-06 06:27:17,466 [ INFO] [hz.clever_meninsky.cached.thread-3] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Execution plan for jobId=05fd-b625-cd00-0001, jobName='05fd-b625-cd00-0001', executionId=05fd-b625-cd01-0001 initialized
2021-04-06 06:27:17,467 [DEBUG] [hz.amazing_meninsky.generic-operation.thread-17] [c.h.j.i.o.InitExecutionOperation]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Initializing execution plan for job 05fd-b625-cd00-0001, execution 05fd-b625-cd01-0001 from [127.0.0.1]:5701
2021-04-06 06:27:17,471 [ INFO] [hz.amazing_meninsky.generic-operation.thread-17] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Execution plan for jobId=05fd-b625-cd00-0001, jobName='05fd-b625-cd00-0001', executionId=05fd-b625-cd01-0001 initialized
2021-04-06 06:27:17,471 [DEBUG] [hz.clever_meninsky.cached.thread-3] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Init of job '05fd-b625-cd00-0001', execution 05fd-b625-cd01-0001 was successful
2021-04-06 06:27:17,471 [DEBUG] [hz.clever_meninsky.cached.thread-3] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Executing job '05fd-b625-cd00-0001', execution 05fd-b625-cd01-0001
2021-04-06 06:27:17,471 [ INFO] [hz.clever_meninsky.cached.thread-3] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Start execution of job '05fd-b625-cd00-0001', execution 05fd-b625-cd01-0001 from coordinator [127.0.0.1]:5701
2021-04-06 06:27:17,476 [DEBUG] [hz.clever_meninsky.cached.thread-3] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] job '05fd-b625-cd00-0001', execution 05fd-b625-cd01-0001 snapshot is scheduled in 100ms
2021-04-06 06:27:17,476 [ INFO] [hz.amazing_meninsky.generic-operation.thread-18] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Start execution of job '05fd-b625-cd00-0001', execution 05fd-b625-cd01-0001 from coordinator [127.0.0.1]:5701
2021-04-06 06:27:17,482 [ INFO] [hz.amazing_meninsky.jet.blocking.thread-0] [c.h.j.c.i.ChangeRecordCdcSourceP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [05fd-b625-cd00-0001/customers#0] customers has 'retry strategy' set to 'max attempts = -1, interval function = IntervalFunction (constant of 1000ms)'
2021-04-06 06:27:17,482 [ INFO] [hz.amazing_meninsky.jet.blocking.thread-0] [c.h.j.c.i.ChangeRecordCdcSourceP]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [05fd-b625-cd00-0001/customers#0] customers has 'clear state on reconnect' set to 'false'
2021-04-06 06:27:17,483 [ INFO] [hz.amazing_meninsky.jet.blocking.thread-0] [i.d.c.c.BaseSourceTask]: Starting PostgresConnectorTask with configuration:
2021-04-06 06:27:17,483 [ INFO] [hz.amazing_meninsky.jet.blocking.thread-0] [i.d.c.c.BaseSourceTask]:    reconnect.behavior = max attempts = -1, interval function = IntervalFunction (constant of 1000ms)
2021-04-06 06:27:17,483 [ INFO] [hz.amazing_meninsky.jet.blocking.thread-0] [i.d.c.c.BaseSourceTask]:    connector.class = io.debezium.connector.postgresql.PostgresConnector
2021-04-06 06:27:17,483 [ INFO] [hz.amazing_meninsky.jet.blocking.thread-0] [i.d.c.c.BaseSourceTask]:    db.specific.extra.fields = schema
2021-04-06 06:27:17,483 [ INFO] [hz.amazing_meninsky.jet.blocking.thread-0] [i.d.c.c.BaseSourceTask]:    database.user = postgres
2021-04-06 06:27:17,483 [ INFO] [hz.amazing_meninsky.jet.blocking.thread-0] [i.d.c.c.BaseSourceTask]:    database.dbname = postgres
2021-04-06 06:27:17,483 [ INFO] [hz.amazing_meninsky.jet.blocking.thread-0] [i.d.c.c.BaseSourceTask]:    slot.name = debezium
2021-04-06 06:27:17,483 [ INFO] [hz.amazing_meninsky.jet.blocking.thread-0] [i.d.c.c.BaseSourceTask]:    database.server.name = 142ee34a-11ad-4e44-b20a-c1d68bc833b2
2021-04-06 06:27:17,483 [ INFO] [hz.amazing_meninsky.jet.blocking.thread-0] [i.d.c.c.BaseSourceTask]:    sequence.extractor.class = com.hazelcast.jet.cdc.postgres.impl.PostgresSequenceExtractor
2021-04-06 06:27:17,483 [ INFO] [hz.amazing_meninsky.jet.blocking.thread-0] [i.d.c.c.BaseSourceTask]:    commit.period = 9223372036854775807
2021-04-06 06:27:17,483 [ INFO] [hz.amazing_meninsky.jet.blocking.thread-0] [i.d.c.c.BaseSourceTask]:    database.port = 58114
2021-04-06 06:27:17,483 [ INFO] [hz.amazing_meninsky.jet.blocking.thread-0] [i.d.c.c.BaseSourceTask]:    table.whitelist = inventory.customers
2021-04-06 06:27:17,483 [ INFO] [hz.amazing_meninsky.jet.blocking.thread-0] [i.d.c.c.BaseSourceTask]:    tombstones.on.delete = false
2021-04-06 06:27:17,483 [ INFO] [hz.amazing_meninsky.jet.blocking.thread-0] [i.d.c.c.BaseSourceTask]:    database.hostname = 172.17.0.1
2021-04-06 06:27:17,483 [ INFO] [hz.amazing_meninsky.jet.blocking.thread-0] [i.d.c.c.BaseSourceTask]:    database.password = ********
2021-04-06 06:27:17,483 [ INFO] [hz.amazing_meninsky.jet.blocking.thread-0] [i.d.c.c.BaseSourceTask]:    name = customers
2021-04-06 06:27:17,483 [ INFO] [hz.amazing_meninsky.jet.blocking.thread-0] [i.d.c.c.BaseSourceTask]:    snapshot.mode = exported
2021-04-06 06:27:17,483 [ INFO] [hz.amazing_meninsky.jet.blocking.thread-0] [i.d.c.c.BaseSourceTask]:    database.history = com.hazelcast.jet.cdc.impl.CdcSourceP$DatabaseHistoryImpl
2021-04-06 06:27:17,532 [ INFO] [hz.amazing_meninsky.jet.blocking.thread-0] [i.d.c.p.PostgresConnectorTask]: user 'postgres' connected to database 'postgres' on PostgreSQL 11.11 (Debian 11.11-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-04-06 06:27:17,534 [ INFO] [hz.amazing_meninsky.jet.blocking.thread-0] [i.d.c.p.c.PostgresConnection]: Obtained valid replication slot ReplicationSlot [active=false, latestFlushedLsn=null, catalogXmin=null]
2021-04-06 06:27:17,534 [ INFO] [hz.amazing_meninsky.jet.blocking.thread-0] [i.d.c.p.PostgresConnectorTask]: No previous offset found
2021-04-06 06:27:17,534 [ INFO] [hz.amazing_meninsky.jet.blocking.thread-0] [i.d.c.p.s.ExportedSnapshotter]: Taking exported snapshot for new datasource
2021-04-06 06:27:17,540 [ INFO] [hz.amazing_meninsky.jet.blocking.thread-0] [i.d.c.p.c.PostgresReplicationConnection]: Creating replication slot with command CREATE_REPLICATION_SLOT debezium  LOGICAL decoderbufs
2021-04-06 06:27:17,542 [ INFO] [hz.amazing_meninsky.jet.blocking.thread-0] [i.d.u.Threads]: Requested thread factory for connector PostgresConnector, id = 142ee34a-11ad-4e44-b20a-c1d68bc833b2 named = change-event-source-coordinator
2021-04-06 06:27:17,542 [ INFO] [hz.amazing_meninsky.jet.blocking.thread-0] [i.d.u.Threads]: Creating thread debezium-postgresconnector-142ee34a-11ad-4e44-b20a-c1d68bc833b2-change-event-source-coordinator
2021-04-06 06:27:17,543 [ INFO] [debezium-postgresconnector-142ee34a-11ad-4e44-b20a-c1d68bc833b2-change-event-source-coordinator] [i.d.p.ChangeEventSourceCoordinator]: Metrics registered
2021-04-06 06:27:17,543 [ INFO] [debezium-postgresconnector-142ee34a-11ad-4e44-b20a-c1d68bc833b2-change-event-source-coordinator] [i.d.p.ChangeEventSourceCoordinator]: Context created
2021-04-06 06:27:17,543 [ INFO] [debezium-postgresconnector-142ee34a-11ad-4e44-b20a-c1d68bc833b2-change-event-source-coordinator] [i.d.c.p.s.ExportedSnapshotter]: Taking exported snapshot for new datasource
2021-04-06 06:27:17,543 [ INFO] [debezium-postgresconnector-142ee34a-11ad-4e44-b20a-c1d68bc833b2-change-event-source-coordinator] [i.d.c.p.PostgresSnapshotChangeEventSource]: According to the connector configuration data will be snapshotted
2021-04-06 06:27:17,543 [ INFO] [debezium-postgresconnector-142ee34a-11ad-4e44-b20a-c1d68bc833b2-change-event-source-coordinator] [i.d.r.RelationalSnapshotChangeEventSource]: Snapshot step 1 - Preparing
2021-04-06 06:27:17,544 [ INFO] [debezium-postgresconnector-142ee34a-11ad-4e44-b20a-c1d68bc833b2-change-event-source-coordinator] [i.d.c.p.PostgresSnapshotChangeEventSource]: Setting isolation level
2021-04-06 06:27:17,544 [ INFO] [debezium-postgresconnector-142ee34a-11ad-4e44-b20a-c1d68bc833b2-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-04-06 06:27:17,592 [DEBUG] [hz.clever_meninsky.cached.thread-5] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Starting snapshot 0 for job '05fd-b625-cd00-0001', execution 05fd-b625-cd01-0001, flags: terminal=no,export=no, writing to: null
2021-04-06 06:27:17,592 [DEBUG] [hz.clever_meninsky.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 '05fd-b625-cd00-0001', execution 05fd-b625-cd01-0001 on member
2021-04-06 06:27:17,593 [DEBUG] [hz.amazing_meninsky.generic-operation.thread-19] [c.h.j.i.e.ExecutionContext]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Starting snapshot 0 phase 1 for job '05fd-b625-cd00-0001', execution 05fd-b625-cd01-0001 on member
2021-04-06 06:27:17,606 [ WARN] [debezium-postgresconnector-142ee34a-11ad-4e44-b20a-c1d68bc833b2-change-event-source-coordinator] [i.d.c.p.PostgresSchema]: The Kafka Connect schema name '142ee34a-11ad-4e44-b20a-c1d68bc833b2.inventory.customers.Value' is not a valid Avro schema name, so replacing with '_42ee34a_11ad_4e44_b20a_c1d68bc833b2.inventory.customers.Value'
2021-04-06 06:27:17,606 [ WARN] [debezium-postgresconnector-142ee34a-11ad-4e44-b20a-c1d68bc833b2-change-event-source-coordinator] [i.d.c.p.PostgresSchema]: The Kafka Connect schema name '142ee34a-11ad-4e44-b20a-c1d68bc833b2.inventory.customers.Key' is not a valid Avro schema name, so replacing with '_42ee34a_11ad_4e44_b20a_c1d68bc833b2.inventory.customers.Key'
2021-04-06 06:27:17,607 [ WARN] [debezium-postgresconnector-142ee34a-11ad-4e44-b20a-c1d68bc833b2-change-event-source-coordinator] [i.d.c.p.PostgresSchema]: The Kafka Connect schema name '142ee34a-11ad-4e44-b20a-c1d68bc833b2.inventory.customers.Envelope' is not a valid Avro schema name, so replacing with '_42ee34a_11ad_4e44_b20a_c1d68bc833b2.inventory.customers.Envelope'
2021-04-06 06:27:17,607 [ INFO] [debezium-postgresconnector-142ee34a-11ad-4e44-b20a-c1d68bc833b2-change-event-source-coordinator] [i.d.r.RelationalSnapshotChangeEventSource]: Snapshot step 2 - Determining captured tables
2021-04-06 06:27:17,609 [ INFO] [debezium-postgresconnector-142ee34a-11ad-4e44-b20a-c1d68bc833b2-change-event-source-coordinator] [i.d.r.RelationalSnapshotChangeEventSource]: Snapshot step 3 - Locking captured tables
2021-04-06 06:27:17,609 [ INFO] [debezium-postgresconnector-142ee34a-11ad-4e44-b20a-c1d68bc833b2-change-event-source-coordinator] [i.d.c.p.PostgresSnapshotChangeEventSource]: Step 2: skipping locking each table in an exported snapshot
2021-04-06 06:27:17,609 [ INFO] [debezium-postgresconnector-142ee34a-11ad-4e44-b20a-c1d68bc833b2-change-event-source-coordinator] [i.d.r.RelationalSnapshotChangeEventSource]: Snapshot step 4 - Determining snapshot offset
2021-04-06 06:27:17,609 [ INFO] [debezium-postgresconnector-142ee34a-11ad-4e44-b20a-c1d68bc833b2-change-event-source-coordinator] [i.d.c.p.PostgresSnapshotChangeEventSource]: Read xlogStart at 'LSN{0/2037088}' from transaction '596'
2021-04-06 06:27:17,609 [ INFO] [debezium-postgresconnector-142ee34a-11ad-4e44-b20a-c1d68bc833b2-change-event-source-coordinator] [i.d.c.p.PostgresSnapshotChangeEventSource]: Creating initial offset context
2021-04-06 06:27:17,610 [ INFO] [debezium-postgresconnector-142ee34a-11ad-4e44-b20a-c1d68bc833b2-change-event-source-coordinator] [i.d.c.p.PostgresSnapshotChangeEventSource]: Read xlogStart at 'LSN{0/2037088}' from transaction '596'
2021-04-06 06:27:17,610 [ INFO] [debezium-postgresconnector-142ee34a-11ad-4e44-b20a-c1d68bc833b2-change-event-source-coordinator] [i.d.r.RelationalSnapshotChangeEventSource]: Snapshot step 5 - Reading structure of captured tables
2021-04-06 06:27:17,610 [ INFO] [debezium-postgresconnector-142ee34a-11ad-4e44-b20a-c1d68bc833b2-change-event-source-coordinator] [i.d.c.p.PostgresSnapshotChangeEventSource]: Reading structure of schema 'postgres'
2021-04-06 06:27:17,642 [ INFO] [debezium-postgresconnector-142ee34a-11ad-4e44-b20a-c1d68bc833b2-change-event-source-coordinator] [i.d.r.RelationalSnapshotChangeEventSource]: Snapshot step 6 - Persisting schema history
2021-04-06 06:27:17,642 [ INFO] [debezium-postgresconnector-142ee34a-11ad-4e44-b20a-c1d68bc833b2-change-event-source-coordinator] [i.d.r.RelationalSnapshotChangeEventSource]: Snapshot step 7 - Snapshotting data
2021-04-06 06:27:17,642 [ INFO] [debezium-postgresconnector-142ee34a-11ad-4e44-b20a-c1d68bc833b2-change-event-source-coordinator] [i.d.r.RelationalSnapshotChangeEventSource]:   Exporting data from table 'inventory.customers'
2021-04-06 06:27:17,642 [ INFO] [debezium-postgresconnector-142ee34a-11ad-4e44-b20a-c1d68bc833b2-change-event-source-coordinator] [i.d.r.RelationalSnapshotChangeEventSource]:   For table 'inventory.customers' using select statement: 'select * from "inventory"."customers"'
2021-04-06 06:27:17,646 [ INFO] [debezium-postgresconnector-142ee34a-11ad-4e44-b20a-c1d68bc833b2-change-event-source-coordinator] [i.d.r.RelationalSnapshotChangeEventSource]:   Finished exporting 4 records for table 'inventory.customers'; total duration '00:00:00.004'
2021-04-06 06:27:17,647 [ INFO] [debezium-postgresconnector-142ee34a-11ad-4e44-b20a-c1d68bc833b2-change-event-source-coordinator] [i.d.p.s.AbstractSnapshotChangeEventSource]: Snapshot - Final stage
2021-04-06 06:27:17,647 [ INFO] [debezium-postgresconnector-142ee34a-11ad-4e44-b20a-c1d68bc833b2-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='142ee34a-11ad-4e44-b20a-c1d68bc833b2'db='postgres', lsn=LSN{0/2037088}, txId=596, timestamp=2021-04-06T06:27:17.646Z, snapshot=FALSE, schema=inventory, table=customers], partition={server=142ee34a-11ad-4e44-b20a-c1d68bc833b2}, lastSnapshotRecord=true, lastCompletelyProcessedLsn=null, lastCommitLsn=null, transactionContext=TransactionContext [currentTransactionId=null, perTableEventCount={}, totalEventCount=0]]]
2021-04-06 06:27:17,647 [ INFO] [debezium-postgresconnector-142ee34a-11ad-4e44-b20a-c1d68bc833b2-change-event-source-coordinator] [i.d.p.m.StreamingChangeEventSourceMetrics]: Connected metrics set to 'true'
2021-04-06 06:27:17,647 [ INFO] [debezium-postgresconnector-142ee34a-11ad-4e44-b20a-c1d68bc833b2-change-event-source-coordinator] [i.d.p.ChangeEventSourceCoordinator]: Starting streaming
2021-04-06 06:27:17,647 [ INFO] [debezium-postgresconnector-142ee34a-11ad-4e44-b20a-c1d68bc833b2-change-event-source-coordinator] [i.d.c.p.PostgresStreamingChangeEventSource]: Retrieved latest position from stored offset 'LSN{0/2037088}'
2021-04-06 06:27:17,647 [ INFO] [debezium-postgresconnector-142ee34a-11ad-4e44-b20a-c1d68bc833b2-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/2037088}'
2021-04-06 06:27:17,656 [ INFO] [debezium-postgresconnector-142ee34a-11ad-4e44-b20a-c1d68bc833b2-change-event-source-coordinator] [i.d.c.p.c.PostgresConnection]: Obtained valid replication slot ReplicationSlot [active=false, latestFlushedLsn=LSN{0/2037088}, catalogXmin=596]
2021-04-06 06:27:17,697 [ INFO] [debezium-postgresconnector-142ee34a-11ad-4e44-b20a-c1d68bc833b2-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-04-06 06:27:17,698 [ INFO] [debezium-postgresconnector-142ee34a-11ad-4e44-b20a-c1d68bc833b2-change-event-source-coordinator] [i.d.c.p.PostgresStreamingChangeEventSource]: Searching for WAL resume position
2021-04-06 06:27:18,043 [DEBUG] [hz.amazing_meninsky.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-04-06 06:27:18,043 [DEBUG] [hz.amazing_meninsky.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-04-06 06:27:18,046 [DEBUG] [hz.clever_meninsky.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-04-06 06:27:18,046 [DEBUG] [hz.amazing_meninsky.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-04-06 06:27:18,046 [DEBUG] [hz.amazing_meninsky.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-04-06 06:27:18,046 [DEBUG] [hz.amazing_meninsky.jet.cooperative.thread-4] [c.h.j.i.o.SnapshotPhase1Operation]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Snapshot 0 phase 1 for job '05fd-b625-cd00-0001', execution 05fd-b625-cd01-0001 finished successfully on member
2021-04-06 06:27:18,046 [DEBUG] [hz.clever_meninsky.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-04-06 06:27:18,047 [DEBUG] [hz.clever_meninsky.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 '05fd-b625-cd00-0001', execution 05fd-b625-cd01-0001 finished successfully on member
2021-04-06 06:27:18,048 [DEBUG] [hz.clever_meninsky.cached.thread-5] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Snapshot 0 phase 1 for job '05fd-b625-cd00-0001', execution 05fd-b625-cd01-0001 completed with status SUCCESS in 471ms, 852 bytes, 7 keys in 7 chunks, stored in '__jet.snapshot.05fd-b625-cd00-0001.0', proceeding to phase 2
2021-04-06 06:27:18,051 [DEBUG] [hz.clever_meninsky.cached.thread-5] [c.h.j.i.JobRepository]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Cleared snapshot data map __jet.snapshot.05fd-b625-cd00-0001.1
2021-04-06 06:27:18,051 [DEBUG] [hz.clever_meninsky.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 '05fd-b625-cd00-0001', execution 05fd-b625-cd01-0001 on member
2021-04-06 06:27:18,051 [DEBUG] [hz.clever_meninsky.jet.cooperative.thread-6] [c.h.j.i.o.SnapshotPhase2Operation]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Snapshot 0 phase 2 for job '05fd-b625-cd00-0001', execution 05fd-b625-cd01-0001 finished successfully on member
2021-04-06 06:27:18,052 [DEBUG] [hz.amazing_meninsky.generic-operation.thread-25] [c.h.j.i.e.ExecutionContext]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Starting snapshot 0 phase 2 for job '05fd-b625-cd00-0001', execution 05fd-b625-cd01-0001 on member
2021-04-06 06:27:18,054 [DEBUG] [hz.amazing_meninsky.jet.blocking.thread-0] [c.h.j.i.o.SnapshotPhase2Operation]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Snapshot 0 phase 2 for job '05fd-b625-cd00-0001', execution 05fd-b625-cd01-0001 finished successfully on member
2021-04-06 06:27:18,054 [DEBUG] [hz.clever_meninsky.cached.thread-5] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] job '05fd-b625-cd00-0001', execution 05fd-b625-cd01-0001 snapshot is scheduled in 100ms
2021-04-06 06:27:18,054 [DEBUG] [hz.clever_meninsky.cached.thread-5] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Snapshot 0 for job '05fd-b625-cd00-0001', execution 05fd-b625-cd01-0001 completed in 478ms, status=success
2021-04-06 06:27:18,160 [DEBUG] [hz.clever_meninsky.cached.thread-5] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Starting snapshot 1 for job '05fd-b625-cd00-0001', execution 05fd-b625-cd01-0001, flags: terminal=no,export=no, writing to: null
2021-04-06 06:27:18,160 [DEBUG] [hz.clever_meninsky.cached.thread-5] [c.h.j.i.e.ExecutionContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Starting snapshot 1 phase 1 for job '05fd-b625-cd00-0001', execution 05fd-b625-cd01-0001 on member
2021-04-06 06:27:18,160 [DEBUG] [hz.amazing_meninsky.generic-operation.thread-28] [c.h.j.i.e.ExecutionContext]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Starting snapshot 1 phase 1 for job '05fd-b625-cd00-0001', execution 05fd-b625-cd01-0001 on member
2021-04-06 06:27:19,043 [DEBUG] [hz.amazing_meninsky.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-04-06 06:27:19,043 [DEBUG] [hz.amazing_meninsky.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-04-06 06:27:19,044 [DEBUG] [hz.amazing_meninsky.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-04-06 06:27:19,044 [DEBUG] [hz.amazing_meninsky.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-04-06 06:27:19,045 [DEBUG] [hz.clever_meninsky.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-04-06 06:27:19,045 [DEBUG] [hz.amazing_meninsky.jet.cooperative.thread-0] [c.h.j.i.o.SnapshotPhase1Operation]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Snapshot 1 phase 1 for job '05fd-b625-cd00-0001', execution 05fd-b625-cd01-0001 finished successfully on member
2021-04-06 06:27:19,045 [DEBUG] [hz.clever_meninsky.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-04-06 06:27:19,046 [DEBUG] [hz.clever_meninsky.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 '05fd-b625-cd00-0001', execution 05fd-b625-cd01-0001 finished successfully on member
2021-04-06 06:27:19,050 [DEBUG] [hz.clever_meninsky.cached.thread-2] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Snapshot 1 phase 1 for job '05fd-b625-cd00-0001', execution 05fd-b625-cd01-0001 completed with status SUCCESS in 892ms, 852 bytes, 7 keys in 7 chunks, stored in '__jet.snapshot.05fd-b625-cd00-0001.1', proceeding to phase 2
2021-04-06 06:27:19,053 [DEBUG] [hz.clever_meninsky.cached.thread-2] [c.h.j.i.JobRepository]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Cleared snapshot data map __jet.snapshot.05fd-b625-cd00-0001.0
2021-04-06 06:27:19,053 [DEBUG] [hz.clever_meninsky.cached.thread-2] [c.h.j.i.e.ExecutionContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Starting snapshot 1 phase 2 for job '05fd-b625-cd00-0001', execution 05fd-b625-cd01-0001 on member
2021-04-06 06:27:19,053 [DEBUG] [hz.amazing_meninsky.generic-operation.thread-30] [c.h.j.i.e.ExecutionContext]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Starting snapshot 1 phase 2 for job '05fd-b625-cd00-0001', execution 05fd-b625-cd01-0001 on member
2021-04-06 06:27:19,054 [DEBUG] [hz.clever_meninsky.jet.cooperative.thread-6] [c.h.j.i.o.SnapshotPhase2Operation]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Snapshot 1 phase 2 for job '05fd-b625-cd00-0001', execution 05fd-b625-cd01-0001 finished successfully on member
2021-04-06 06:27:19,054 [DEBUG] [hz.amazing_meninsky.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 '05fd-b625-cd00-0001', execution 05fd-b625-cd01-0001 finished successfully on member
2021-04-06 06:27:19,054 [DEBUG] [hz.clever_meninsky.cached.thread-2] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] job '05fd-b625-cd00-0001', execution 05fd-b625-cd01-0001 snapshot is scheduled in 100ms
2021-04-06 06:27:19,054 [DEBUG] [hz.clever_meninsky.cached.thread-2] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Snapshot 1 for job '05fd-b625-cd00-0001', execution 05fd-b625-cd01-0001 completed in 899ms, status=success
2021-04-06 06:27:19,082 [ INFO] [Time-limited test] [c.h.j.c.JetTestSupport]: Next snapshot found after 1011 ms (id=1, previous id=0)
2021-04-06 06:27:19,093 [DEBUG] [Time-limited test] [c.h.j.Job]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Sending RESTART_FORCEFUL request for job 05fd-b625-cd00-0001 (name ??)
2021-04-06 06:27:19,094 [DEBUG] [hz.clever_meninsky.jet.cooperative.thread-9] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Execution of job '05fd-b625-cd00-0001', execution 05fd-b625-cd01-0001 completed with failure
java.util.concurrent.CompletionException: com.hazelcast.jet.impl.exception.JobTerminateRequestedException: RESTART_FORCEFUL
    at java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:292) ~[?:1.8.0_265]
    at java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:308) ~[?:1.8.0_265]
    at java.util.concurrent.CompletableFuture.uniApply(CompletableFuture.java:607) ~[?:1.8.0_265]
    at java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:591) ~[?:1.8.0_265]
    at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:488) ~[?:1.8.0_265]
    at java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:1990) ~[?:1.8.0_265]
    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:895) [?:1.8.0_265]
    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_265]
Caused by: com.hazelcast.jet.impl.exception.JobTerminateRequestedException: RESTART_FORCEFUL
    at com.hazelcast.jet.impl.execution.ExecutionContext.terminateExecution(ExecutionContext.java:235) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.operation.TerminateExecutionOperation.run(TerminateExecutionOperation.java:61) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.Operation.call(Operation.java:189) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.call(OperationRunnerImpl.java:272) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:248) ~[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.OperationExecutorImpl.run(OperationExecutorImpl.java:411) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationexecutor.impl.OperationExecutorImpl.runOrExecute(OperationExecutorImpl.java:438) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.Invocation.doInvokeLocal(Invocation.java:600) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.Invocation.doInvoke(Invocation.java:579) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke0(Invocation.java:540) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke(Invocation.java:240) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.InvocationBuilderImpl.invoke(InvocationBuilderImpl.java:59) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.MasterContext.invokeOnParticipant(MasterContext.java:264) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.MasterContext.invokeOnParticipants(MasterContext.java:247) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.MasterJobContext.lambda$cancelExecutionInvocations$16(MasterJobContext.java:598) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) ~[?:1.8.0_265]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) ~[?:1.8.0_265]
    at java.lang.Thread.run(Thread.java:748) ~[?:1.8.0_265]
    at com.hazelcast.internal.util.executor.HazelcastManagedThread.executeRun(HazelcastManagedThread.java:76) ~[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-04-06 06:27:19,163 [DEBUG] [hz.clever_meninsky.cached.thread-2] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Starting snapshot 2 for job '05fd-b625-cd00-0001', execution 05fd-b625-cd01-0001, flags: terminal=no,export=no, writing to: null
2021-04-06 06:27:19,163 [DEBUG] [hz.clever_meninsky.cached.thread-2] [c.h.j.i.e.ExecutionContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Starting snapshot 2 phase 1 for job '05fd-b625-cd00-0001', execution 05fd-b625-cd01-0001 on member
2021-04-06 06:27:19,163 [ERROR] [hz.clever_meninsky.cached.thread-2] [c.h.j.i.o.SnapshotPhase1Operation]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] null
java.util.concurrent.CancellationException: null
    at com.hazelcast.jet.impl.execution.ExecutionContext.beginSnapshotPhase1(ExecutionContext.java:253) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.operation.SnapshotPhase1Operation.doRun(SnapshotPhase1Operation.java:64) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.operation.AsyncOperation.run(AsyncOperation.java:53) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.Operation.call(Operation.java:189) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.call(OperationRunnerImpl.java:272) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:248) ~[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.OperationExecutorImpl.run(OperationExecutorImpl.java:411) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationexecutor.impl.OperationExecutorImpl.runOrExecute(OperationExecutorImpl.java:438) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.Invocation.doInvokeLocal(Invocation.java:600) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.Invocation.doInvoke(Invocation.java:579) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke0(Invocation.java:540) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke(Invocation.java:240) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.InvocationBuilderImpl.invoke(InvocationBuilderImpl.java:59) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.MasterContext.invokeOnParticipant(MasterContext.java:264) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.MasterContext.invokeOnParticipants(MasterContext.java:247) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.MasterSnapshotContext.lambda$tryBeginSnapshot$2(MasterSnapshotContext.java:173) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.JobCoordinationService.lambda$submitToCoordinatorThread$46(JobCoordinationService.java:1039) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.JobCoordinationService.lambda$submitToCoordinatorThread$47(JobCoordinationService.java:1060) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.internal.util.executor.CompletableFutureTask.run(CompletableFutureTask.java:64) [hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.internal.util.executor.CachedExecutorServiceDelegate$Worker.run(CachedExecutorServiceDelegate.java:217) [hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_265]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_265]
    at java.lang.Thread.run(Thread.java:748) [?:1.8.0_265]
    at com.hazelcast.internal.util.executor.HazelcastManagedThread.executeRun(HazelcastManagedThread.java:76) [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-04-06 06:27:19,164 [DEBUG] [hz.amazing_meninsky.generic-operation.thread-33] [c.h.j.i.e.ExecutionContext]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Starting snapshot 2 phase 1 for job '05fd-b625-cd00-0001', execution 05fd-b625-cd01-0001 on member
2021-04-06 06:27:19,164 [ERROR] [hz.amazing_meninsky.generic-operation.thread-33] [c.h.j.i.o.SnapshotPhase1Operation]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] null
java.util.concurrent.CancellationException: null
    at com.hazelcast.jet.impl.execution.ExecutionContext.beginSnapshotPhase1(ExecutionContext.java:253) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.operation.SnapshotPhase1Operation.doRun(SnapshotPhase1Operation.java:64) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.operation.AsyncOperation.run(AsyncOperation.java:53) [hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.Operation.call(Operation.java:189) [hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.call(OperationRunnerImpl.java:272) [hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:248) [hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:469) [hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationexecutor.impl.OperationThread.process(OperationThread.java:197) [hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationexecutor.impl.OperationThread.process(OperationThread.java:137) [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-04-06 06:27:19,167 [DEBUG] [hz.clever_meninsky.cached.thread-2] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Snapshot 2 phase 1 for job '05fd-b625-cd00-0001', execution 05fd-b625-cd01-0001 completed with status FAILURE in 11ms, 0 bytes, 0 keys in 0 chunks, stored in '__jet.snapshot.05fd-b625-cd00-0001.0', proceeding to phase 2
2021-04-06 06:27:19,167 [ WARN] [hz.clever_meninsky.cached.thread-2] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] job '05fd-b625-cd00-0001', execution 05fd-b625-cd01-0001 snapshot 2 phase 1 failed on some member(s), one of the failures: java.util.concurrent.CancellationException
2021-04-06 06:27:19,180 [DEBUG] [hz.clever_meninsky.cached.thread-2] [c.h.j.i.JobRepository]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Cleared snapshot data map __jet.snapshot.05fd-b625-cd00-0001.0
2021-04-06 06:27:19,180 [DEBUG] [hz.clever_meninsky.cached.thread-2] [c.h.j.i.e.ExecutionContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Starting snapshot 2 phase 2 for job '05fd-b6
...[truncated 5402619 chars]...
et-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke(Invocation.java:240) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.InvocationBuilderImpl.invoke(InvocationBuilderImpl.java:59) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.MasterContext.invokeOnParticipant(MasterContext.java:264) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.MasterContext.invokeOnParticipants(MasterContext.java:247) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.MasterSnapshotContext.lambda$tryBeginSnapshot$2(MasterSnapshotContext.java:173) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.JobCoordinationService.lambda$submitToCoordinatorThread$46(JobCoordinationService.java:1039) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.JobCoordinationService.lambda$submitToCoordinatorThread$47(JobCoordinationService.java:1060) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.internal.util.executor.CompletableFutureTask.run(CompletableFutureTask.java:64) [hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.internal.util.executor.CachedExecutorServiceDelegate$Worker.run(CachedExecutorServiceDelegate.java:217) [hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_265]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_265]
    at java.lang.Thread.run(Thread.java:748) [?:1.8.0_265]
    at com.hazelcast.internal.util.executor.HazelcastManagedThread.executeRun(HazelcastManagedThread.java:76) [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-04-06 06:29:26,969 [DEBUG] [hz.amazing_meninsky.generic-operation.thread-31] [c.h.j.i.e.ExecutionContext]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Starting snapshot 248 phase 1 for job '05fd-b625-cd00-0001', execution 05fd-b625-cd0b-0001 on member
2021-04-06 06:29:26,969 [ERROR] [hz.amazing_meninsky.generic-operation.thread-31] [c.h.j.i.o.SnapshotPhase1Operation]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] null
java.util.concurrent.CancellationException: null
    at com.hazelcast.jet.impl.execution.ExecutionContext.beginSnapshotPhase1(ExecutionContext.java:253) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.operation.SnapshotPhase1Operation.doRun(SnapshotPhase1Operation.java:64) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.operation.AsyncOperation.run(AsyncOperation.java:53) [hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.Operation.call(Operation.java:189) [hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.call(OperationRunnerImpl.java:272) [hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:248) [hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:469) [hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationexecutor.impl.OperationThread.process(OperationThread.java:197) [hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationexecutor.impl.OperationThread.process(OperationThread.java:137) [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-04-06 06:29:26,974 [DEBUG] [hz.clever_meninsky.cached.thread-46] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Snapshot 248 phase 1 for job '05fd-b625-cd00-0001', execution 05fd-b625-cd0b-0001 completed with status FAILURE in 10ms, 0 bytes, 0 keys in 0 chunks, stored in '__jet.snapshot.05fd-b625-cd00-0001.1', proceeding to phase 2
2021-04-06 06:29:26,974 [ WARN] [hz.clever_meninsky.cached.thread-46] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] job '05fd-b625-cd00-0001', execution 05fd-b625-cd0b-0001 snapshot 248 phase 1 failed on some member(s), one of the failures: java.util.concurrent.CancellationException
2021-04-06 06:29:26,984 [DEBUG] [hz.clever_meninsky.cached.thread-46] [c.h.j.i.JobRepository]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Cleared snapshot data map __jet.snapshot.05fd-b625-cd00-0001.1
2021-04-06 06:29:26,984 [DEBUG] [hz.clever_meninsky.cached.thread-46] [c.h.j.i.e.ExecutionContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Starting snapshot 248 phase 2 for job '05fd-b625-cd00-0001', execution 05fd-b625-cd0b-0001 on member
2021-04-06 06:29:26,984 [ERROR] [hz.clever_meninsky.cached.thread-46] [c.h.j.i.o.SnapshotPhase2Operation]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] null
java.util.concurrent.CancellationException: null
    at com.hazelcast.jet.impl.execution.ExecutionContext.beginSnapshotPhase2(ExecutionContext.java:271) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.operation.SnapshotPhase2Operation.doRun(SnapshotPhase2Operation.java:54) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.operation.AsyncOperation.run(AsyncOperation.java:53) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.Operation.call(Operation.java:189) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.call(OperationRunnerImpl.java:272) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:248) ~[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.OperationExecutorImpl.run(OperationExecutorImpl.java:411) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationexecutor.impl.OperationExecutorImpl.runOrExecute(OperationExecutorImpl.java:438) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.Invocation.doInvokeLocal(Invocation.java:600) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.Invocation.doInvoke(Invocation.java:579) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke0(Invocation.java:540) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke(Invocation.java:240) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.InvocationBuilderImpl.invoke(InvocationBuilderImpl.java:59) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.MasterContext.invokeOnParticipant(MasterContext.java:264) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.MasterContext.invokeOnParticipants(MasterContext.java:247) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.MasterSnapshotContext.lambda$onSnapshotPhase1Complete$5(MasterSnapshotContext.java:277) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.JobCoordinationService.lambda$submitToCoordinatorThread$46(JobCoordinationService.java:1039) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.JobCoordinationService.lambda$submitToCoordinatorThread$47(JobCoordinationService.java:1060) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.internal.util.executor.CompletableFutureTask.run(CompletableFutureTask.java:64) [hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.internal.util.executor.CachedExecutorServiceDelegate$Worker.run(CachedExecutorServiceDelegate.java:217) [hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_265]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_265]
    at java.lang.Thread.run(Thread.java:748) [?:1.8.0_265]
    at com.hazelcast.internal.util.executor.HazelcastManagedThread.executeRun(HazelcastManagedThread.java:76) [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-04-06 06:29:26,987 [DEBUG] [hz.amazing_meninsky.generic-operation.thread-33] [c.h.j.i.e.ExecutionContext]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Starting snapshot 248 phase 2 for job '05fd-b625-cd00-0001', execution 05fd-b625-cd0b-0001 on member
2021-04-06 06:29:26,987 [ERROR] [hz.amazing_meninsky.generic-operation.thread-33] [c.h.j.i.o.SnapshotPhase2Operation]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] null
java.util.concurrent.CancellationException: null
    at com.hazelcast.jet.impl.execution.ExecutionContext.beginSnapshotPhase2(ExecutionContext.java:271) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.operation.SnapshotPhase2Operation.doRun(SnapshotPhase2Operation.java:54) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.operation.AsyncOperation.run(AsyncOperation.java:53) [hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.Operation.call(Operation.java:189) [hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.call(OperationRunnerImpl.java:272) [hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:248) [hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:469) [hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationexecutor.impl.OperationThread.process(OperationThread.java:197) [hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationexecutor.impl.OperationThread.process(OperationThread.java:137) [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-04-06 06:29:26,989 [ WARN] [hz.clever_meninsky.cached.thread-60] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] SnapshotPhase2Operation for snapshot 248 in job '05fd-b625-cd00-0001', execution 05fd-b625-cd0b-0001 failed on member: MemberInfo{address=[127.0.0.1]:5701, uuid=013460ae-b93b-4c6d-867c-2396a14941e7, liteMember=false, memberListJoinVersion=1}=java.util.concurrent.CancellationException
java.util.concurrent.CancellationException: null
    at com.hazelcast.jet.impl.execution.ExecutionContext.beginSnapshotPhase2(ExecutionContext.java:271) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.operation.SnapshotPhase2Operation.doRun(SnapshotPhase2Operation.java:54) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.operation.AsyncOperation.run(AsyncOperation.java:53) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.Operation.call(Operation.java:189) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.call(OperationRunnerImpl.java:272) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:248) ~[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.OperationExecutorImpl.run(OperationExecutorImpl.java:411) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationexecutor.impl.OperationExecutorImpl.runOrExecute(OperationExecutorImpl.java:438) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.Invocation.doInvokeLocal(Invocation.java:600) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.Invocation.doInvoke(Invocation.java:579) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke0(Invocation.java:540) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke(Invocation.java:240) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.InvocationBuilderImpl.invoke(InvocationBuilderImpl.java:59) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.MasterContext.invokeOnParticipant(MasterContext.java:264) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.MasterContext.invokeOnParticipants(MasterContext.java:247) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.MasterSnapshotContext.lambda$onSnapshotPhase1Complete$5(MasterSnapshotContext.java:277) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.JobCoordinationService.lambda$submitToCoordinatorThread$46(JobCoordinationService.java:1039) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.JobCoordinationService.lambda$submitToCoordinatorThread$47(JobCoordinationService.java:1060) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.internal.util.executor.CompletableFutureTask.run(CompletableFutureTask.java:64) [hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.internal.util.executor.CachedExecutorServiceDelegate$Worker.run(CachedExecutorServiceDelegate.java:217) [hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_265]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_265]
    at java.lang.Thread.run(Thread.java:748) [?:1.8.0_265]
    at com.hazelcast.internal.util.executor.HazelcastManagedThread.executeRun(HazelcastManagedThread.java:76) [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-04-06 06:29:26,989 [ WARN] [hz.clever_meninsky.cached.thread-60] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] SnapshotPhase2Operation for snapshot 248 in job '05fd-b625-cd00-0001', execution 05fd-b625-cd0b-0001 failed on member: MemberInfo{address=[127.0.0.1]:5702, uuid=067792be-41ab-4077-859a-454476f6d48c, liteMember=false, memberListJoinVersion=2}=java.util.concurrent.CancellationException
java.util.concurrent.CancellationException: null
    at com.hazelcast.jet.impl.execution.ExecutionContext.beginSnapshotPhase2(ExecutionContext.java:271) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.operation.SnapshotPhase2Operation.doRun(SnapshotPhase2Operation.java:54) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.operation.AsyncOperation.run(AsyncOperation.java:53) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.Operation.call(Operation.java:189) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.call(OperationRunnerImpl.java:272) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:248) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:469) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationexecutor.impl.OperationThread.process(OperationThread.java:197) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationexecutor.impl.OperationThread.process(OperationThread.java:137) ~[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-04-06 06:29:26,989 [DEBUG] [hz.clever_meninsky.cached.thread-60] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] job '05fd-b625-cd00-0001', execution 05fd-b625-cd0b-0001 snapshot is scheduled in 100ms
2021-04-06 06:29:26,989 [DEBUG] [hz.clever_meninsky.cached.thread-60] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Snapshot 248 for job '05fd-b625-cd00-0001', execution 05fd-b625-cd0b-0001 completed in 29ms, status=failure: java.util.concurrent.CancellationException
2021-04-06 06:29:27,097 [DEBUG] [hz.clever_meninsky.cached.thread-60] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Starting snapshot 249 for job '05fd-b625-cd00-0001', execution 05fd-b625-cd0b-0001, flags: terminal=no,export=no, writing to: null
2021-04-06 06:29:27,097 [DEBUG] [hz.clever_meninsky.cached.thread-60] [c.h.j.i.e.ExecutionContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Starting snapshot 249 phase 1 for job '05fd-b625-cd00-0001', execution 05fd-b625-cd0b-0001 on member
2021-04-06 06:29:27,097 [ERROR] [hz.clever_meninsky.cached.thread-60] [c.h.j.i.o.SnapshotPhase1Operation]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] null
java.util.concurrent.CancellationException: null
    at com.hazelcast.jet.impl.execution.ExecutionContext.beginSnapshotPhase1(ExecutionContext.java:253) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.operation.SnapshotPhase1Operation.doRun(SnapshotPhase1Operation.java:64) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.operation.AsyncOperation.run(AsyncOperation.java:53) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.Operation.call(Operation.java:189) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.call(OperationRunnerImpl.java:272) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:248) ~[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.OperationExecutorImpl.run(OperationExecutorImpl.java:411) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationexecutor.impl.OperationExecutorImpl.runOrExecute(OperationExecutorImpl.java:438) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.Invocation.doInvokeLocal(Invocation.java:600) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.Invocation.doInvoke(Invocation.java:579) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke0(Invocation.java:540) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke(Invocation.java:240) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.InvocationBuilderImpl.invoke(InvocationBuilderImpl.java:59) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.MasterContext.invokeOnParticipant(MasterContext.java:264) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.MasterContext.invokeOnParticipants(MasterContext.java:247) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.MasterSnapshotContext.lambda$tryBeginSnapshot$2(MasterSnapshotContext.java:173) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.JobCoordinationService.lambda$submitToCoordinatorThread$46(JobCoordinationService.java:1039) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.JobCoordinationService.lambda$submitToCoordinatorThread$47(JobCoordinationService.java:1060) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.internal.util.executor.CompletableFutureTask.run(CompletableFutureTask.java:64) [hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.internal.util.executor.CachedExecutorServiceDelegate$Worker.run(CachedExecutorServiceDelegate.java:217) [hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_265]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_265]
    at java.lang.Thread.run(Thread.java:748) [?:1.8.0_265]
    at com.hazelcast.internal.util.executor.HazelcastManagedThread.executeRun(HazelcastManagedThread.java:76) [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-04-06 06:29:27,098 [DEBUG] [hz.amazing_meninsky.generic-operation.thread-1] [c.h.j.i.e.ExecutionContext]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Starting snapshot 249 phase 1 for job '05fd-b625-cd00-0001', execution 05fd-b625-cd0b-0001 on member
2021-04-06 06:29:27,098 [ERROR] [hz.amazing_meninsky.generic-operation.thread-1] [c.h.j.i.o.SnapshotPhase1Operation]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] null
java.util.concurrent.CancellationException: null
    at com.hazelcast.jet.impl.execution.ExecutionContext.beginSnapshotPhase1(ExecutionContext.java:253) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.operation.SnapshotPhase1Operation.doRun(SnapshotPhase1Operation.java:64) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.operation.AsyncOperation.run(AsyncOperation.java:53) [hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.Operation.call(Operation.java:189) [hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.call(OperationRunnerImpl.java:272) [hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:248) [hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:469) [hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationexecutor.impl.OperationThread.process(OperationThread.java:197) [hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationexecutor.impl.OperationThread.process(OperationThread.java:137) [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-04-06 06:29:27,103 [DEBUG] [hz.clever_meninsky.cached.thread-60] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Snapshot 249 phase 1 for job '05fd-b625-cd00-0001', execution 05fd-b625-cd0b-0001 completed with status FAILURE in 13ms, 0 bytes, 0 keys in 0 chunks, stored in '__jet.snapshot.05fd-b625-cd00-0001.1', proceeding to phase 2
2021-04-06 06:29:27,103 [ WARN] [hz.clever_meninsky.cached.thread-60] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] job '05fd-b625-cd00-0001', execution 05fd-b625-cd0b-0001 snapshot 249 phase 1 failed on some member(s), one of the failures: java.util.concurrent.CancellationException
2021-04-06 06:29:27,133 [DEBUG] [hz.clever_meninsky.cached.thread-60] [c.h.j.i.JobRepository]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Cleared snapshot data map __jet.snapshot.05fd-b625-cd00-0001.1
2021-04-06 06:29:27,133 [DEBUG] [hz.clever_meninsky.cached.thread-60] [c.h.j.i.e.ExecutionContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Starting snapshot 249 phase 2 for job '05fd-b625-cd00-0001', execution 05fd-b625-cd0b-0001 on member
2021-04-06 06:29:27,133 [ERROR] [hz.clever_meninsky.cached.thread-60] [c.h.j.i.o.SnapshotPhase2Operation]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] null
java.util.concurrent.CancellationException: null
    at com.hazelcast.jet.impl.execution.ExecutionContext.beginSnapshotPhase2(ExecutionContext.java:271) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.operation.SnapshotPhase2Operation.doRun(SnapshotPhase2Operation.java:54) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.operation.AsyncOperation.run(AsyncOperation.java:53) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.Operation.call(Operation.java:189) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.call(OperationRunnerImpl.java:272) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:248) ~[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.OperationExecutorImpl.run(OperationExecutorImpl.java:411) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationexecutor.impl.OperationExecutorImpl.runOrExecute(OperationExecutorImpl.java:438) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.Invocation.doInvokeLocal(Invocation.java:600) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.Invocation.doInvoke(Invocation.java:579) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke0(Invocation.java:540) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke(Invocation.java:240) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.InvocationBuilderImpl.invoke(InvocationBuilderImpl.java:59) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.MasterContext.invokeOnParticipant(MasterContext.java:264) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.MasterContext.invokeOnParticipants(MasterContext.java:247) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.MasterSnapshotContext.lambda$onSnapshotPhase1Complete$5(MasterSnapshotContext.java:277) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.JobCoordinationService.lambda$submitToCoordinatorThread$46(JobCoordinationService.java:1039) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.JobCoordinationService.lambda$submitToCoordinatorThread$47(JobCoordinationService.java:1060) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.internal.util.executor.CompletableFutureTask.run(CompletableFutureTask.java:64) [hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.internal.util.executor.CachedExecutorServiceDelegate$Worker.run(CachedExecutorServiceDelegate.java:217) [hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_265]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_265]
    at java.lang.Thread.run(Thread.java:748) [?:1.8.0_265]
    at com.hazelcast.internal.util.executor.HazelcastManagedThread.executeRun(HazelcastManagedThread.java:76) [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-04-06 06:29:27,135 [DEBUG] [hz.amazing_meninsky.generic-operation.thread-5] [c.h.j.i.e.ExecutionContext]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Starting snapshot 249 phase 2 for job '05fd-b625-cd00-0001', execution 05fd-b625-cd0b-0001 on member
2021-04-06 06:29:27,135 [ERROR] [hz.amazing_meninsky.generic-operation.thread-5] [c.h.j.i.o.SnapshotPhase2Operation]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] null
java.util.concurrent.CancellationException: null
    at com.hazelcast.jet.impl.execution.ExecutionContext.beginSnapshotPhase2(ExecutionContext.java:271) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.operation.SnapshotPhase2Operation.doRun(SnapshotPhase2Operation.java:54) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.operation.AsyncOperation.run(AsyncOperation.java:53) [hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.Operation.call(Operation.java:189) [hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.call(OperationRunnerImpl.java:272) [hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:248) [hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:469) [hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationexecutor.impl.OperationThread.process(OperationThread.java:197) [hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationexecutor.impl.OperationThread.process(OperationThread.java:137) [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-04-06 06:29:27,139 [ WARN] [hz.clever_meninsky.cached.thread-60] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] SnapshotPhase2Operation for snapshot 249 in job '05fd-b625-cd00-0001', execution 05fd-b625-cd0b-0001 failed on member: MemberInfo{address=[127.0.0.1]:5701, uuid=013460ae-b93b-4c6d-867c-2396a14941e7, liteMember=false, memberListJoinVersion=1}=java.util.concurrent.CancellationException
java.util.concurrent.CancellationException: null
    at com.hazelcast.jet.impl.execution.ExecutionContext.beginSnapshotPhase2(ExecutionContext.java:271) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.operation.SnapshotPhase2Operation.doRun(SnapshotPhase2Operation.java:54) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.operation.AsyncOperation.run(AsyncOperation.java:53) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.Operation.call(Operation.java:189) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.call(OperationRunnerImpl.java:272) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:248) ~[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.OperationExecutorImpl.run(OperationExecutorImpl.java:411) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationexecutor.impl.OperationExecutorImpl.runOrExecute(OperationExecutorImpl.java:438) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.Invocation.doInvokeLocal(Invocation.java:600) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.Invocation.doInvoke(Invocation.java:579) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke0(Invocation.java:540) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke(Invocation.java:240) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.InvocationBuilderImpl.invoke(InvocationBuilderImpl.java:59) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.MasterContext.invokeOnParticipant(MasterContext.java:264) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.MasterContext.invokeOnParticipants(MasterContext.java:247) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.MasterSnapshotContext.lambda$onSnapshotPhase1Complete$5(MasterSnapshotContext.java:277) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.JobCoordinationService.lambda$submitToCoordinatorThread$46(JobCoordinationService.java:1039) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.JobCoordinationService.lambda$submitToCoordinatorThread$47(JobCoordinationService.java:1060) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.internal.util.executor.CompletableFutureTask.run(CompletableFutureTask.java:64) [hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.internal.util.executor.CachedExecutorServiceDelegate$Worker.run(CachedExecutorServiceDelegate.java:217) [hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_265]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_265]
    at java.lang.Thread.run(Thread.java:748) [?:1.8.0_265]
    at com.hazelcast.internal.util.executor.HazelcastManagedThread.executeRun(HazelcastManagedThread.java:76) [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-04-06 06:29:27,140 [ WARN] [hz.clever_meninsky.cached.thread-60] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] SnapshotPhase2Operation for snapshot 249 in job '05fd-b625-cd00-0001', execution 05fd-b625-cd0b-0001 failed on member: MemberInfo{address=[127.0.0.1]:5702, uuid=067792be-41ab-4077-859a-454476f6d48c, liteMember=false, memberListJoinVersion=2}=java.util.concurrent.CancellationException
java.util.concurrent.CancellationException: null
    at com.hazelcast.jet.impl.execution.ExecutionContext.beginSnapshotPhase2(ExecutionContext.java:271) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.operation.SnapshotPhase2Operation.doRun(SnapshotPhase2Operation.java:54) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.operation.AsyncOperation.run(AsyncOperation.java:53) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.Operation.call(Operation.java:189) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.call(OperationRunnerImpl.java:272) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:248) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:469) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationexecutor.impl.OperationThread.process(OperationThread.java:197) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationexecutor.impl.OperationThread.process(OperationThread.java:137) ~[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-04-06 06:29:27,140 [DEBUG] [hz.clever_meninsky.cached.thread-60] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] job '05fd-b625-cd00-0001', execution 05fd-b625-cd0b-0001 snapshot is scheduled in 100ms
2021-04-06 06:29:27,140 [DEBUG] [hz.clever_meninsky.cached.thread-60] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Snapshot 249 for job '05fd-b625-cd00-0001', execution 05fd-b625-cd0b-0001 completed in 51ms, status=failure: java.util.concurrent.CancellationException
2021-04-06 06:29:27,209 [DEBUG] [hz.amazing_meninsky.jet.blocking.thread-1] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Execution of job '05fd-b625-cd00-0001', execution 05fd-b625-cd0b-0001 completed with failure
java.util.concurrent.CompletionException: com.hazelcast.jet.impl.exception.JobTerminateRequestedException: CANCEL_FORCEFUL
    at java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:292) ~[?:1.8.0_265]
    at java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:308) ~[?:1.8.0_265]
    at java.util.concurrent.CompletableFuture.uniApply(CompletableFuture.java:607) ~[?:1.8.0_265]
    at java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:591) ~[?:1.8.0_265]
    at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:488) [?:1.8.0_265]
    at java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:1990) [?:1.8.0_265]
    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$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_265]
    at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_265]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_265]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_265]
    at java.lang.Thread.run(Thread.java:748) [?:1.8.0_265]
Caused by: com.hazelcast.jet.impl.exception.JobTerminateRequestedException: CANCEL_FORCEFUL
    at com.hazelcast.jet.impl.execution.ExecutionContext.terminateExecution(ExecutionContext.java:235) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.jet.impl.operation.TerminateExecutionOperation.run(TerminateExecutionOperation.java:61) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.Operation.call(Operation.java:189) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.call(OperationRunnerImpl.java:272) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:248) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:469) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationexecutor.impl.OperationThread.process(OperationThread.java:197) ~[hazelcast-jet-4.5-SNAPSHOT.jar:4.5-SNAPSHOT]
    at com.hazelcast.spi.impl.operationexecutor.impl.OperationThread.process(OperationThread.java:137) ~[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-04-06 06:29:27,214 [DEBUG] [ForkJoinPool.commonPool-worker-49] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] job '05fd-b625-cd00-0001', execution 05fd-b625-cd0b-0001 to be cancelled after Execution
2021-04-06 06:29:27,214 [DEBUG] [hz.clever_meninsky.cached.thread-46] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Sending CompleteExecutionOperation for job '05fd-b625-cd00-0001', execution 05fd-b625-cd0b-0001
2021-04-06 06:29:27,214 [DEBUG] [hz.clever_meninsky.cached.thread-46] [c.h.j.i.o.CompleteExecutionOperation]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Completing execution 05fd-b625-cd0b-0001 from caller [127.0.0.1]:5701, error=java.util.concurrent.CancellationException
2021-04-06 06:29:27,215 [DEBUG] [hz.clever_meninsky.cached.thread-46] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Completed execution of job '05fd-b625-cd00-0001', execution 05fd-b625-cd0b-0001
2021-04-06 06:29:27,215 [DEBUG] [hz.amazing_meninsky.generic-operation.thread-3] [c.h.j.i.o.CompleteExecutionOperation]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Completing execution 05fd-b625-cd0b-0001 from caller [127.0.0.1]:5701, error=java.util.concurrent.CancellationException
2021-04-06 06:29:27,215 [ INFO] [hz.amazing_meninsky.generic-operation.thread-3] [i.d.c.c.BaseSourceTask]: Stopping down connector
2021-04-06 06:29:27,221 [DEBUG] [hz.amazing_meninsky.generic-operation.thread-3] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Completed execution of job '05fd-b625-cd00-0001', execution 05fd-b625-cd0b-0001
2021-04-06 06:29:27,222 [ INFO] [hz.clever_meninsky.cached.thread-46] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Execution of job '05fd-b625-cd00-0001', execution 05fd-b625-cd0b-0001 got terminated, reason=java.util.concurrent.CancellationException
    Start time: 2021-04-06T06:27:26.183
    Duration: 00:02:01.038
    To see additional job metrics enable JobConfig.storeMetricsAfterJobCompletion
2021-04-06 06:29:27,223 [DEBUG] [hz.clever_meninsky.cached.thread-46] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] job '05fd-b625-cd00-0001', execution 05fd-b625-cd0b-0001 is completed
2021-04-06 06:29:27,240 [DEBUG] [hz.clever_meninsky.cached.thread-60] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Not beginning snapshot, job '05fd-b625-cd00-0001', execution 05fd-b625-cd0b-0001 is not RUNNING, but FAILED
2021-04-06 06:29:27,395 [ INFO] [Time-limited test] [c.h.j.c.JetTestSupport]: Terminating instanceFactory in JetTestSupport.@After
2021-04-06 06:29:27,395 [ INFO] [Thread-47] [c.h.c.LifecycleService]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [127.0.0.1]:5702 is SHUTTING_DOWN
2021-04-06 06:29:27,396 [ WARN] [Thread-47] [c.h.i.i.Node]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Terminating forcefully...
2021-04-06 06:29:27,396 [ INFO] [Thread-47] [c.h.i.i.Node]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Shutting down connection manager...
2021-04-06 06:29:27,400 [ INFO] [Thread-47] [c.h.t.m.MockServer]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Removed connection to endpoint: [127.0.0.1]:5702, connection: MockConnection{localEndpoint=[127.0.0.1]:5701, remoteEndpoint=[127.0.0.1]:5702, alive=false}
2021-04-06 06:29:27,400 [ INFO] [Thread-47] [c.h.t.m.MockServer]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Removed connection to endpoint: [127.0.0.1]:5701, connection: MockConnection{localEndpoint=[127.0.0.1]:5702, remoteEndpoint=[127.0.0.1]:5701, alive=false}
2021-04-06 06:29:27,400 [ INFO] [Thread-47] [c.h.i.c.i.MembershipManager]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Removing Member [127.0.0.1]:5702 - 067792be-41ab-4077-859a-454476f6d48c
2021-04-06 06:29:27,401 [ INFO] [Thread-47] [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 - 013460ae-b93b-4c6d-867c-2396a14941e7 this
]

2021-04-06 06:29:27,407 [ INFO] [Thread-47] [c.h.i.i.Node]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Shutting down node engine...
2021-04-06 06:29:27,402 [ INFO] [hz.clever_meninsky.cached.thread-13] [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: 067792be-41ab-4077-859a-454476f6d48c
2021-04-06 06:29:27,677 [ INFO] [hz.clever_meninsky.migration] [c.h.i.p.i.MigrationManager]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Partition balance is ok, no need to repartition.
2021-04-06 06:29:27,759 [ INFO] [Thread-47] [c.h.i.i.NodeExtension]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Destroying node NodeExtension.
2021-04-06 06:29:27,761 [ INFO] [Thread-47] [c.h.i.i.Node]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] Hazelcast Shutdown is completed in 365 ms.
2021-04-06 06:29:27,761 [ INFO] [Thread-47] [c.h.c.LifecycleService]: [127.0.0.1]:5702 [jet] [4.5-SNAPSHOT] [127.0.0.1]:5702 is SHUTDOWN
2021-04-06 06:29:27,762 [ INFO] [Thread-47] [c.h.c.LifecycleService]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] [127.0.0.1]:5701 is SHUTTING_DOWN
2021-04-06 06:29:27,762 [ WARN] [Thread-47] [c.h.i.i.Node]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Terminating forcefully...
2021-04-06 06:29:27,762 [ INFO] [Thread-47] [c.h.i.i.Node]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Shutting down connection manager...
2021-04-06 06:29:27,763 [ INFO] [Thread-47] [c.h.i.i.Node]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Shutting down node engine...
2021-04-06 06:29:27,942 [ INFO] [Thread-47] [c.h.i.i.NodeExtension]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Destroying node NodeExtension.
2021-04-06 06:29:27,944 [ INFO] [Thread-47] [c.h.i.i.Node]: [127.0.0.1]:5701 [jet] [4.5-SNAPSHOT] Hazelcast Shutdown is completed in 182 ms.
2021-04-06 06:29:27,944 [ INFO] [Thread-47] [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_forcefulRestart(com.hazelcast.jet.cdc.postgres.PostgresCdcIntegrationTest): BuildInfo{version='4.2-SNAPSHOT', build='20210312', buildNumber=20210312, revision=b4344f9, enterprise=false, serializationVersion=1, jet=JetBuildInfo{version='4.5-SNAPSHOT', build='20210406', revision='8e7c299'}}
Hiccups measured while running test 'stressTest_exactlyOnce_forcefulRestart(com.hazelcast.jet.cdc.postgres.PostgresCdcIntegrationTest):'
06:27:10, accumulated pauses: 159 ms, max pause: 15 ms, pauses over 1000 ms: 0
06:27:15, accumulated pauses: 137 ms, max pause: 46 ms, pauses over 1000 ms: 0
06:27:20, accumulated pauses: 803 ms, max pause: 178 ms, pauses over 1000 ms: 0
06:27:25, accumulated pauses: 675 ms, max pause: 195 ms, pauses over 1000 ms: 0
06:27:30, accumulated pauses: 139 ms, max pause: 13 ms, pauses over 1000 ms: 0
06:27:35, accumulated pauses: 99 ms, max pause: 39 ms, pauses over 1000 ms: 0
06:27:40, accumulated pauses: 49 ms, max pause: 5 ms, pauses over 1000 ms: 0
06:27:45, accumulated pauses: 72 ms, max pause: 32 ms, pauses over 1000 ms: 0
06:27:50, accumulated pauses: 84 ms, max pause: 8 ms, pauses over 1000 ms: 0
06:27:55, accumulated pauses: 129 ms, max pause: 48 ms, pauses over 1000 ms: 0
06:28:00, accumulated pauses: 453 ms, max pause: 115 ms, pauses over 1000 ms: 0
06:28:05, accumulated pauses: 560 ms, max pause: 14 ms, pauses over 1000 ms: 0
06:28:10, accumulated pauses: 740 ms, max pause: 161 ms, pauses over 1000 ms: 0
06:28:15, accumulated pauses: 344 ms, max pause: 12 ms, pauses over 1000 ms: 0
06:28:20, accumulated pauses: 248 ms, max pause: 134 ms, pauses over 1000 ms: 0
06:28:25, accumulated pauses: 272 ms, max pause: 79 ms, pauses over 1000 ms: 0
06:28:30, accumulated pauses: 242 ms, max pause: 5 ms, pauses over 1000 ms: 0
06:28:35, accumulated pauses: 245 ms, max pause: 67 ms, pauses over 1000 ms: 0
06:28:40, accumulated pauses: 287 ms, max pause: 9 ms, pauses over 1000 ms: 0
06:28:45, accumulated pauses: 389 ms, max pause: 77 ms, pauses over 1000 ms: 0
06:28:50, accumulated pauses: 303 ms, max pause: 9 ms, pauses over 1000 ms: 0
06:28:55, accumulated pauses: 415 ms, max pause: 175 ms, pauses over 1000 ms: 0
06:29:00, accumulated pauses: 425 ms, max pause: 112 ms, pauses over 1000 ms: 0
06:29:05, accumulated pauses: 151 ms, max pause: 9 ms, pauses over 1000 ms: 0
06:29:10, accumulated pauses: 226 ms, max pause: 61 ms, pauses over 1000 ms: 0
06:29:15, accumulated pauses: 453 ms, max pause: 12 ms, pauses over 1000 ms: 0
06:29:20, accumulated pauses: 194 ms, max pause: 75 ms, pauses over 1000 ms: 0
06:29:25, accumulated pauses: 275 ms, max pause: 87 ms, pauses over 1000 ms: 0
06:29:30, accumulated pauses: 149 ms, max pause: 8 ms, pauses over 1000 ms: 0
06:29:35, accumulated pauses: 127 ms, max pause: 6 ms, pauses over 1000 ms: 0
06:29:40, accumulated pauses: 9 ms, max pause: 2 ms, pauses over 1000 ms: 0
olukas commented 3 years ago

Failed again on OpenJDK 8: http://jenkins.hazelcast.com/job/jet-oss-master-nightly-zulu-jdk8/50/testReport/

This time also com.hazelcast.jet.cdc.postgres.PostgresCdcWhiteBlackListIntegrationTest.blacklistColumn_sameTable has failed with:

java.lang.AssertionError: expected:<27> but was:<0>
    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 org.junit.Assert.assertEquals(Assert.java:146)
    at com.hazelcast.test.HazelcastTestSupport$9.run(HazelcastTestSupport.java:1016)
    at com.hazelcast.test.HazelcastTestSupport.assertTrueEventually(HazelcastTestSupport.java:1247)
    at com.hazelcast.test.HazelcastTestSupport.assertTrueEventually(HazelcastTestSupport.java:1349)
    at com.hazelcast.test.HazelcastTestSupport.assertEqualsEventually(HazelcastTestSupport.java:1013)
    at com.hazelcast.jet.cdc.postgres.PostgresCdcWhiteBlackListIntegrationTest.test(PostgresCdcWhiteBlackListIntegrationTest.java:242)
    at com.hazelcast.jet.cdc.postgres.PostgresCdcWhiteBlackListIntegrationTest.blacklistColumn_sameTable(PostgresCdcWhiteBlackListIntegrationTest.java:176)
    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.RunBefores.evaluate(RunBefores.java:26)
    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)