Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Test failures in WriteFilePTest test-failure #3044

Open
olukas opened this issue May 10, 2021 · 0 comments
Open

Test failures in WriteFilePTest test-failure #3044

olukas opened this issue May 10, 2021 · 0 comments
Labels
test-failure

Comments

@olukas
Copy link
Collaborator

olukas commented May 10, 2021

4.5-maintenance (commit 32b32b4)

Failed on Open JDK (Zulu) 15: http://jenkins.hazelcast.com/job/jet-oss-maintenance-zulu-jdk15/29/testReport/

Following tests failed:

  • com.hazelcast.jet.impl.connector.WriteFilePTest.stressTest_atLeastOnce_forceful
  • com.hazelcast.jet.impl.connector.WriteFilePTest.stressTest_exactlyOnce_forceful

It can be related to following issues:

Stacktrace for stressTest_atLeastOnce_forceful:

java.lang.AssertionError: some items are missing: {0=1, 1=1, 2=1, 3=1, 4=1, 5=1, 6=1, 7=1, 8=1, 9=1, 10=1, 11=1, 12=3, 13=3, 14=3, 15=3, 16=2, 17=2, 18=2, 19=2, 20=2, 21=2, 22=2, 23=2, 24=7, 25=7, 26=7, 27=6, 28=5, 29=5, 30=5, 31=3, 32=3, 33=3, 34=3, 35=3, 36=3, 37=2, 38=7, 39=7, 40=4, 41=4, 42=4, 43=3, 44=3, 45=3, 46=3, 47=3, 48=3, 49=3, 50=3, 51=3, 52=3, 53=2, 54=2, 55=1, 56=1, 57=1, 58=1, 59=4, 60=6, 61=8, 62=8, 63=7, 64=7, 65=8, 66=6, 67=6, 68=6, 69=6, 70=6, 71=5, 72=5, 73=5, 74=5, 75=5, 76=4, 77=5, 78=5, 79=4, 80=3, 81=3, 82=2, 83=2, 84=1, 85=1, 86=1, 87=1, 88=1, 89=1, 90=1, 91=1, 92=1, 93=1, 94=1, 95=2, 96=5, 97=6, 98=6, 99=6, 100=8, 101=10, 102=10, 103=8, 104=6, 105=6, 106=6, 107=6, 108=5, 109=5, 110=4, 111=2, 112=1, 113=2, 114=1, 115=1, 116=1, 117=1, 118=4, 119=4, 120=4, 121=5, 122=5, 123=4, 124=4, 125=3, 126=3, 127=3, 128=2, 129=2, 130=2, 131=1, 132=1, 133=1, 134=1, 135=1, 136=1, 137=1, 138=1, 139=2, 140=3, 141=3, 142=3, 143=5, 144=5, 145=4, 146=5, 147=6, 148=6, 149=5, 150=5, 151=5, 152=5, 153=4, 154=4, 155=3, 156=3, 157=2, 158=2, 159=2, 160=2, 161=2, 162=2, 163=1, 164=1, 165=1, 166=1, 167=1, 168=1, 169=1, 170=1, 171=1, 172=1, 173=2, 174=3, 175=7, 176=6, 177=5, 178=5, 179=5, 180=5, 181=5, 182=5, 183=5, 184=5, 185=4, 186=3, 187=3, 188=3, 189=3, 190=3, 191=3, 192=3, 193=3, 194=3, 195=3, 196=2, 197=3, 198=1, 199=1, 200=1, 201=1, 202=1, 203=1, 204=1, 205=1, 206=1, 207=1, 208=1, 209=1, 210=1, 211=1, 212=1, 213=1, 214=1, 215=1, 216=1, 217=1, 218=1, 219=1, 220=1, 221=1, 222=1, 223=1, 224=0, 225=0, 226=0, 227=0, 228=0, 229=0, 230=0, 231=0, 232=0, 233=0, 234=0, 235=0, 236=0, 237=0, 238=0, 239=0, 240=0, 241=0, 242=0, 243=0, 244=0, 245=0, 246=0, 247=0, 248=0, 249=0, 250=0, 251=0, 252=0, 253=0, 254=0, 255=0, 256=0, 257=0, 258=0, 259=0, 260=0, 261=0, 262=0, 263=0, 264=0, 265=0, 266=0, 267=0, 268=0, 269=0, 270=0, 271=0, 272=0, 273=0, 274=0, 275=0, 276=0, 277=0, 278=0, 279=0, 280=0, 281=0, 282=0, 283=0, 284=0, 285=0, 286=0, 287=0, 288=0, 289=0, 290=0, 291=0, 292=0, 293=0, 294=0, 295=0, 296=0, 297=0, 298=0, 299=0, 300=0, 301=0, 302=0, 303=0, 304=0, 305=0, 306=0, 307=0, 308=0, 309=0, 310=0, 311=0, 312=0, 313=0, 314=0, 315=0, 316=0, 317=0, 318=0, 319=0, 320=0, 321=0, 322=0, 323=0, 324=0, 325=0, 326=0, 327=0, 328=0, 329=0, 330=0, 331=0, 332=0, 333=0, 334=0, 335=0, 336=0, 337=0, 338=0, 339=0, 340=0, 341=0, 342=0, 343=0, 344=0, 345=0, 346=0, 347=0, 348=0, 349=0, 350=0, 351=0, 352=0, 353=0, 354=0, 355=0, 356=0, 357=0, 358=0, 359=0, 360=0, 361=0, 362=0, 363=0, 364=0, 365=0, 366=0, 367=0, 368=0, 369=0, 370=0, 371=0, 372=0, 373=0, 374=0, 375=0, 376=0, 377=0, 378=0, 379=0, 380=0, 381=0, 382=0, 383=0, 384=0, 385=0, 386=0, 387=0, 388=0, 389=0, 390=0, 391=0, 392=0, 393=0, 394=0, 395=0, 396=0, 397=0, 398=0, 399=0, 400=0, 401=0, 402=0, 403=0, 404=0, 405=0, 406=0, 407=0, 408=0, 409=0, 410=0, 411=0, 412=0, 413=0, 414=0, 415=0, 416=0, 417=0, 418=0, 419=0, 420=0, 421=0, 422=0, 423=0, 424=0, 425=0, 426=0, 427=0, 428=0, 429=0, 430=0, 431=0, 432=0, 433=0, 434=0, 435=0, 436=0, 437=0, 438=0, 439=0, 440=0, 441=0, 442=0, 443=0, 444=0, 445=0, 446=0, 447=0, 448=0, 449=0, 450=0, 451=0, 452=0, 453=0, 454=0, 455=0, 456=0, 457=0, 458=0, 459=0, 460=0, 461=0, 462=0, 463=0, 464=0, 465=0, 466=0, 467=0, 468=0, 469=0, 470=0, 471=0, 472=0, 473=0, 474=0, 475=0, 476=0, 477=0, 478=0, 479=0, 480=0, 481=0, 482=0, 483=0, 484=0, 485=0, 486=0, 487=0, 488=0, 489=0, 490=0, 491=0, 492=0, 493=0, 494=0, 495=0, 496=0, 497=0, 498=0, 499=0}
	at org.junit.Assert.fail(Assert.java:89)
	at org.junit.Assert.assertTrue(Assert.java:42)
	at com.hazelcast.jet.impl.connector.WriteFilePTest.checkFileContents(WriteFilePTest.java:450)
	at com.hazelcast.jet.impl.connector.WriteFilePTest.stressTest(WriteFilePTest.java:420)
	at com.hazelcast.jet.impl.connector.WriteFilePTest.stressTest_atLeastOnce_forceful(WriteFilePTest.java:371)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:64)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:564)
	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:59)
	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:56)
	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
	at com.hazelcast.test.FailOnTimeoutStatement$CallableStatement.call(FailOnTimeoutStatement.java:115)
	at com.hazelcast.test.FailOnTimeoutStatement$CallableStatement.call(FailOnTimeoutStatement.java:107)
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
	at java.base/java.lang.Thread.run(Thread.java:832)

Stacktrace for stressTest_exactlyOnce_forceful:

org.junit.ComparisonFailure: 
expected:<...
275
276
277
278
279[
280
281
282
283
284
285
286
287
288
289
290
291
292
293
294
295
296
297
298
299
300
301
302
303
304
305
306
307
308
309
310
311
312
313
314
315
316
317
318
319
320
321
322
323
324
325
326
327
328
329
330
331
332
333
334
335
336
337
338
339
340
341
342
343
344
345
346
347
348
349
350
351
352
353
354
355
356
357
358
359
360
361
362
363
364
365
366
367
368
369
370
371
372
373
374
375
376
377
378
379
380
381
382
383
384
385
386
387
388
389
390
391
392
393
394
395
396
397
398
399
400
401
402
403
404
405
406
407
408
409
410
411
412
413
414
415
416
417
418
419
420
421
422
423
424
425
426
427
428
429
430
431
432
433
434
435
436
437
438
439
440
441
442
443
444
445
446
447
448
449
450
451
452
453
454
455
456
457
458
459
460
461
462
463
464
465
466
467
468
469
470
471
472
473
474
475
476
477
478
479
480
481
482
483
484
485
486
487
488
489
490
491
492
493
494
495
496
497
498
499]> but was:<...
275
276
277
278
279[]>
	at org.junit.Assert.assertEquals(Assert.java:117)
	at org.junit.Assert.assertEquals(Assert.java:146)
	at com.hazelcast.jet.impl.connector.WriteFilePTest.checkFileContents(WriteFilePTest.java:444)
	at com.hazelcast.jet.impl.connector.WriteFilePTest.stressTest(WriteFilePTest.java:420)
	at com.hazelcast.jet.impl.connector.WriteFilePTest.stressTest_exactlyOnce_forceful(WriteFilePTest.java:366)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:64)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:564)
	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:59)
	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:56)
	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
	at com.hazelcast.test.FailOnTimeoutStatement$CallableStatement.call(FailOnTimeoutStatement.java:115)
	at com.hazelcast.test.FailOnTimeoutStatement$CallableStatement.call(FailOnTimeoutStatement.java:107)
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
	at java.base/java.lang.Thread.run(Thread.java:832)

Standard output for stressTest_atLeastOnce_forceful:

Started Running Test: stressTest_atLeastOnce_forceful
2021-05-09 15:32:54,192 [DEBUG] [hz.peaceful_booth.cached.thread-2] [c.h.j.i.p.Planner]: Watermarks in the pipeline will be throttled to 1000
2021-05-09 15:32:54,207 [ INFO] [hz.peaceful_booth.cached.thread-2] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Starting job 0628-af7d-f342-0001 based on submit request
2021-05-09 15:32:54,209 [ INFO] [hz.peaceful_booth.cached.thread-2] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Didn't find any snapshot to restore for job '0628-af7d-f342-0001', execution 0628-af7d-f343-0001
2021-05-09 15:32:54,209 [ INFO] [hz.peaceful_booth.cached.thread-2] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Start executing job '0628-af7d-f342-0001', execution 0628-af7d-f343-0001, execution graph in DOT format:
digraph DAG {
	"src" [localParallelism=1];
	"filesSink(/tmp/write-file-p14527133490174925014)" [localParallelism=2];
	"src" -> "filesSink(/tmp/write-file-p14527133490174925014)" [queueSize=1024];
}
HINT: You can use graphviz or http://viz-js.com to visualize the printed graph.
2021-05-09 15:32:54,209 [DEBUG] [hz.peaceful_booth.cached.thread-2] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Building execution plan for job '0628-af7d-f342-0001', execution 0628-af7d-f343-0001
2021-05-09 15:32:54,210 [DEBUG] [hz.peaceful_booth.cached.thread-2] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Built execution plans for job '0628-af7d-f342-0001', execution 0628-af7d-f343-0001
2021-05-09 15:32:54,210 [DEBUG] [hz.peaceful_booth.cached.thread-2] [c.h.j.i.o.InitExecutionOperation]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Initializing execution plan for job 0628-af7d-f342-0001, execution 0628-af7d-f343-0001 from [127.0.0.1]:5701
2021-05-09 15:32:54,216 [ INFO] [hz.peaceful_booth.cached.thread-2] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Execution plan for jobId=0628-af7d-f342-0001, jobName='0628-af7d-f342-0001', executionId=0628-af7d-f343-0001 initialized
2021-05-09 15:32:54,216 [DEBUG] [hz.peaceful_booth.cached.thread-7] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Init of job '0628-af7d-f342-0001', execution 0628-af7d-f343-0001 was successful
2021-05-09 15:32:54,216 [DEBUG] [hz.peaceful_booth.cached.thread-7] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Executing job '0628-af7d-f342-0001', execution 0628-af7d-f343-0001
2021-05-09 15:32:54,216 [ INFO] [hz.peaceful_booth.cached.thread-7] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Start execution of job '0628-af7d-f342-0001', execution 0628-af7d-f343-0001 from coordinator [127.0.0.1]:5701
2021-05-09 15:32:54,355 [DEBUG] [hz.peaceful_booth.cached.thread-7] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] job '0628-af7d-f342-0001', execution 0628-af7d-f343-0001 snapshot is scheduled in 50ms
2021-05-09 15:32:54,365 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-0] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-af7d-f342-0001/filesSink(/tmp/write-file-p14527133490174925014)#0] creating /tmp/write-file-p14527133490174925014/0
2021-05-09 15:32:54,366 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-2] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-af7d-f342-0001/filesSink(/tmp/write-file-p14527133490174925014)#1] creating /tmp/write-file-p14527133490174925014/1
2021-05-09 15:32:54,416 [DEBUG] [hz.peaceful_booth.cached.thread-7] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Starting snapshot 0 for job '0628-af7d-f342-0001', execution 0628-af7d-f343-0001, flags: terminal=no,export=no, writing to: null
2021-05-09 15:32:54,421 [DEBUG] [hz.peaceful_booth.cached.thread-7] [c.h.j.i.e.ExecutionContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Starting snapshot 0 phase 1 for job '0628-af7d-f342-0001', execution 0628-af7d-f343-0001 on member
2021-05-09 15:32:54,439 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-1] [c.h.j.i.c.ConvenientSourceP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-af7d-f342-0001/src#0] src vertex saved to snapshot: 12
2021-05-09 15:32:54,444 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-0] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-af7d-f342-0001/filesSink(/tmp/write-file-p14527133490174925014)#0] flush File{0}
2021-05-09 15:32:54,444 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-2] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-af7d-f342-0001/filesSink(/tmp/write-file-p14527133490174925014)#1] flush File{1}
2021-05-09 15:32:54,445 [DEBUG] [hz.peaceful_booth.jet.cooperative.thread-2] [c.h.j.i.u.AsyncSnapshotWriterImpl]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Stats for src: keys=1, chunks=1, bytes=37
2021-05-09 15:32:54,453 [DEBUG] [hz.peaceful_booth.jet.cooperative.thread-3] [c.h.j.i.u.AsyncSnapshotWriterImpl]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Stats for filesSink(/tmp/write-file-p14527133490174925014): keys=0, chunks=0, bytes=0
2021-05-09 15:32:54,453 [DEBUG] [hz.peaceful_booth.jet.cooperative.thread-3] [c.h.j.i.o.SnapshotPhase1Operation]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Snapshot 0 phase 1 for job '0628-af7d-f342-0001', execution 0628-af7d-f343-0001 finished successfully on member
2021-05-09 15:32:54,472 [DEBUG] [hz.peaceful_booth.cached.thread-7] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Snapshot 0 phase 1 for job '0628-af7d-f342-0001', execution 0628-af7d-f343-0001 completed with status SUCCESS in 62ms, 37 bytes, 1 keys in 1 chunks, stored in '__jet.snapshot.0628-af7d-f342-0001.0', proceeding to phase 2
2021-05-09 15:32:54,485 [DEBUG] [hz.peaceful_booth.cached.thread-7] [c.h.j.i.JobRepository]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Cleared snapshot data map __jet.snapshot.0628-af7d-f342-0001.1
2021-05-09 15:32:54,490 [DEBUG] [hz.peaceful_booth.cached.thread-7] [c.h.j.i.e.ExecutionContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Starting snapshot 0 phase 2 for job '0628-af7d-f342-0001', execution 0628-af7d-f343-0001 on member
2021-05-09 15:32:54,493 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-0] [c.h.j.i.o.SnapshotPhase2Operation]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Snapshot 0 phase 2 for job '0628-af7d-f342-0001', execution 0628-af7d-f343-0001 finished successfully on member
2021-05-09 15:32:54,495 [DEBUG] [hz.peaceful_booth.cached.thread-7] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] job '0628-af7d-f342-0001', execution 0628-af7d-f343-0001 snapshot is scheduled in 50ms
2021-05-09 15:32:54,496 [DEBUG] [hz.peaceful_booth.cached.thread-7] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Snapshot 0 for job '0628-af7d-f342-0001', execution 0628-af7d-f343-0001 completed in 88ms, status=success
2021-05-09 15:32:54,541 [DEBUG] [stressTest_atLeastOnce_forceful] [c.h.j.Job]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Sending RESTART_FORCEFUL request for job 0628-af7d-f342-0001 (name ??)
2021-05-09 15:32:54,561 [DEBUG] [hz.peaceful_booth.cached.thread-9] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Starting snapshot 1 for job '0628-af7d-f342-0001', execution 0628-af7d-f343-0001, flags: terminal=no,export=no, writing to: null
2021-05-09 15:32:54,561 [DEBUG] [hz.peaceful_booth.cached.thread-9] [c.h.j.i.e.ExecutionContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Starting snapshot 1 phase 1 for job '0628-af7d-f342-0001', execution 0628-af7d-f343-0001 on member
2021-05-09 15:32:54,564 [ WARN] [hz.peaceful_booth.async.thread-1] [c.h.j.i.o.SnapshotPhase1Operation]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Snapshot 1 phase 1 for job '0628-af7d-f342-0001', execution 0628-af7d-f343-0001 finished with an error on member: java.util.concurrent.CancellationException: execution cancelled
2021-05-09 15:32:54,564 [DEBUG] [hz.peaceful_booth.cached.thread-9] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Snapshot 1 phase 1 for job '0628-af7d-f342-0001', execution 0628-af7d-f343-0001 completed with status FAILURE in 15ms, 0 bytes, 0 keys in 0 chunks, stored in '__jet.snapshot.0628-af7d-f342-0001.1', proceeding to phase 2
2021-05-09 15:32:54,565 [ WARN] [hz.peaceful_booth.cached.thread-9] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] job '0628-af7d-f342-0001', execution 0628-af7d-f343-0001 snapshot 1 phase 1 failed on some member(s), one of the failures: java.util.concurrent.CancellationException: execution cancelled
2021-05-09 15:32:54,569 [DEBUG] [hz.peaceful_booth.jet.cooperative.thread-2] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Execution of job '0628-af7d-f342-0001', execution 0628-af7d-f343-0001 completed with failure
java.util.concurrent.CompletionException: com.hazelcast.jet.impl.exception.JobTerminateRequestedException: RESTART_FORCEFUL
	at java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:331) ~[?:?]
	at java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:346) ~[?:?]
	at java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:632) ~[?:?]
	at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:506) ~[?:?]
	at java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:2152) ~[?:?]
	at com.hazelcast.jet.impl.util.NonCompletableFuture.internalCompleteExceptionally(NonCompletableFuture.java:59) ~[classes/:?]
	at com.hazelcast.jet.impl.execution.TaskletExecutionService$ExecutionTracker.taskletDone(TaskletExecutionService.java:468) ~[classes/:?]
	at com.hazelcast.jet.impl.execution.TaskletExecutionService$CooperativeWorker.dismissTasklet(TaskletExecutionService.java:399) ~[classes/:?]
	at com.hazelcast.jet.impl.execution.TaskletExecutionService$CooperativeWorker.runTasklet(TaskletExecutionService.java:385) ~[classes/:?]
	at java.util.concurrent.CopyOnWriteArrayList.forEach(CopyOnWriteArrayList.java:807) [?:?]
	at com.hazelcast.jet.impl.execution.TaskletExecutionService$CooperativeWorker.run(TaskletExecutionService.java:347) [classes/:?]
	at java.lang.Thread.run(Thread.java:832) [?:?]
Caused by: com.hazelcast.jet.impl.exception.JobTerminateRequestedException: RESTART_FORCEFUL
	at com.hazelcast.jet.impl.execution.ExecutionContext.terminateExecution(ExecutionContext.java:235) ~[classes/:?]
	at com.hazelcast.jet.impl.operation.TerminateExecutionOperation.run(TerminateExecutionOperation.java:61) ~[classes/:?]
	at com.hazelcast.spi.impl.operationservice.Operation.call(Operation.java:189) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.call(OperationRunnerImpl.java:272) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:248) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:213) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationexecutor.impl.OperationExecutorImpl.run(OperationExecutorImpl.java:411) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationexecutor.impl.OperationExecutorImpl.runOrExecute(OperationExecutorImpl.java:438) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.doInvokeLocal(Invocation.java:600) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.doInvoke(Invocation.java:579) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke0(Invocation.java:540) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke(Invocation.java:240) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.InvocationBuilderImpl.invoke(InvocationBuilderImpl.java:59) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.jet.impl.MasterContext.invokeOnParticipant(MasterContext.java:264) ~[classes/:?]
	at com.hazelcast.jet.impl.MasterContext.invokeOnParticipants(MasterContext.java:247) ~[classes/:?]
	at com.hazelcast.jet.impl.MasterJobContext.lambda$cancelExecutionInvocations$16(MasterJobContext.java:601) ~[classes/:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130) ~[?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630) ~[?:?]
	at java.lang.Thread.run(Thread.java:832) ~[?:?]
	at com.hazelcast.internal.util.executor.HazelcastManagedThread.executeRun(HazelcastManagedThread.java:76) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.internal.util.executor.HazelcastManagedThread.run(HazelcastManagedThread.java:102) ~[hazelcast-4.2.jar:4.2]
2021-05-09 15:32:54,570 [DEBUG] [ForkJoinPool.commonPool-worker-31] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Execution of job '0628-af7d-f342-0001', execution 0628-af7d-f343-0001 has failures: [[127.0.0.1]:5701=com.hazelcast.jet.impl.exception.JobTerminateRequestedException: RESTART_FORCEFUL]
2021-05-09 15:32:54,570 [DEBUG] [hz.peaceful_booth.cached.thread-10] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Sending CompleteExecutionOperation for job '0628-af7d-f342-0001', execution 0628-af7d-f343-0001
2021-05-09 15:32:54,570 [DEBUG] [hz.peaceful_booth.cached.thread-10] [c.h.j.i.o.CompleteExecutionOperation]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Completing execution 0628-af7d-f343-0001 from caller [127.0.0.1]:5701, error=com.hazelcast.jet.impl.exception.JobTerminateRequestedException: RESTART_FORCEFUL
2021-05-09 15:32:54,571 [DEBUG] [hz.peaceful_booth.cached.thread-10] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-af7d-f342-0001/filesSink(/tmp/write-file-p14527133490174925014)#0] rollback File{0}
2021-05-09 15:32:54,571 [DEBUG] [hz.peaceful_booth.cached.thread-10] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-af7d-f342-0001/filesSink(/tmp/write-file-p14527133490174925014)#0] release File{0}
2021-05-09 15:32:54,571 [DEBUG] [hz.peaceful_booth.cached.thread-10] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-af7d-f342-0001/filesSink(/tmp/write-file-p14527133490174925014)#0] closing 0
2021-05-09 15:32:54,571 [DEBUG] [hz.peaceful_booth.cached.thread-10] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-af7d-f342-0001/filesSink(/tmp/write-file-p14527133490174925014)#1] rollback File{1}
2021-05-09 15:32:54,571 [DEBUG] [hz.peaceful_booth.cached.thread-10] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-af7d-f342-0001/filesSink(/tmp/write-file-p14527133490174925014)#1] release File{1}
2021-05-09 15:32:54,571 [DEBUG] [hz.peaceful_booth.cached.thread-10] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-af7d-f342-0001/filesSink(/tmp/write-file-p14527133490174925014)#1] closing 1
2021-05-09 15:32:54,571 [DEBUG] [hz.peaceful_booth.cached.thread-10] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Completed execution of job '0628-af7d-f342-0001', execution 0628-af7d-f343-0001
2021-05-09 15:32:54,588 [DEBUG] [hz.peaceful_booth.cached.thread-9] [c.h.j.i.JobRepository]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Cleared snapshot data map __jet.snapshot.0628-af7d-f342-0001.1
2021-05-09 15:32:54,588 [ERROR] [hz.peaceful_booth.cached.thread-9] [c.h.j.i.o.SnapshotPhase2Operation]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] job 0628-af7d-f342-0001, execution 0628-af7d-f343-0001 not found for coordinator [127.0.0.1]:5701 for 'SnapshotPhase2Operation'
com.hazelcast.jet.core.TopologyChangedException: job 0628-af7d-f342-0001, execution 0628-af7d-f343-0001 not found for coordinator [127.0.0.1]:5701 for 'SnapshotPhase2Operation'
	at com.hazelcast.jet.impl.JobExecutionService.assertExecutionContext(JobExecutionService.java:326) ~[classes/:?]
	at com.hazelcast.jet.impl.operation.SnapshotPhase2Operation.doRun(SnapshotPhase2Operation.java:50) ~[classes/:?]
	at com.hazelcast.jet.impl.operation.AsyncOperation.run(AsyncOperation.java:53) ~[classes/:?]
	at com.hazelcast.spi.impl.operationservice.Operation.call(Operation.java:189) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.call(OperationRunnerImpl.java:272) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:248) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:213) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationexecutor.impl.OperationExecutorImpl.run(OperationExecutorImpl.java:411) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationexecutor.impl.OperationExecutorImpl.runOrExecute(OperationExecutorImpl.java:438) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.doInvokeLocal(Invocation.java:600) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.doInvoke(Invocation.java:579) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke0(Invocation.java:540) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke(Invocation.java:240) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.InvocationBuilderImpl.invoke(InvocationBuilderImpl.java:59) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.jet.impl.MasterContext.invokeOnParticipant(MasterContext.java:264) ~[classes/:?]
	at com.hazelcast.jet.impl.MasterContext.invokeOnParticipants(MasterContext.java:247) ~[classes/:?]
	at com.hazelcast.jet.impl.MasterSnapshotContext.lambda$onSnapshotPhase1Complete$5(MasterSnapshotContext.java:277) ~[classes/:?]
	at com.hazelcast.jet.impl.JobCoordinationService.lambda$submitToCoordinatorThread$46(JobCoordinationService.java:1039) ~[classes/:?]
	at com.hazelcast.jet.impl.JobCoordinationService.lambda$submitToCoordinatorThread$47(JobCoordinationService.java:1060) ~[classes/:?]
	at com.hazelcast.internal.util.executor.CompletableFutureTask.run(CompletableFutureTask.java:64) [hazelcast-4.2.jar:4.2]
	at com.hazelcast.internal.util.executor.CachedExecutorServiceDelegate$Worker.run(CachedExecutorServiceDelegate.java:217) [hazelcast-4.2.jar:4.2]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630) [?:?]
	at java.lang.Thread.run(Thread.java:832) [?:?]
	at com.hazelcast.internal.util.executor.HazelcastManagedThread.executeRun(HazelcastManagedThread.java:76) [hazelcast-4.2.jar:4.2]
	at com.hazelcast.internal.util.executor.HazelcastManagedThread.run(HazelcastManagedThread.java:102) [hazelcast-4.2.jar:4.2]
2021-05-09 15:32:54,589 [ WARN] [hz.peaceful_booth.cached.thread-9] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] SnapshotPhase2Operation for snapshot 1 in job '0628-af7d-f342-0001', execution 0628-af7d-f343-0001 failed on member: MemberInfo{address=[127.0.0.1]:5701, uuid=e576beac-64f2-440a-b59d-d2c173094e1f, liteMember=false, memberListJoinVersion=1}=com.hazelcast.jet.core.TopologyChangedException: job 0628-af7d-f342-0001, execution 0628-af7d-f343-0001 not found for coordinator [127.0.0.1]:5701 for 'SnapshotPhase2Operation'
com.hazelcast.jet.core.TopologyChangedException: job 0628-af7d-f342-0001, execution 0628-af7d-f343-0001 not found for coordinator [127.0.0.1]:5701 for 'SnapshotPhase2Operation'
	at com.hazelcast.jet.impl.JobExecutionService.assertExecutionContext(JobExecutionService.java:326) ~[classes/:?]
	at com.hazelcast.jet.impl.operation.SnapshotPhase2Operation.doRun(SnapshotPhase2Operation.java:50) ~[classes/:?]
	at com.hazelcast.jet.impl.operation.AsyncOperation.run(AsyncOperation.java:53) ~[classes/:?]
	at com.hazelcast.spi.impl.operationservice.Operation.call(Operation.java:189) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.call(OperationRunnerImpl.java:272) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:248) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:213) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationexecutor.impl.OperationExecutorImpl.run(OperationExecutorImpl.java:411) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationexecutor.impl.OperationExecutorImpl.runOrExecute(OperationExecutorImpl.java:438) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.doInvokeLocal(Invocation.java:600) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.doInvoke(Invocation.java:579) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke0(Invocation.java:540) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke(Invocation.java:240) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.InvocationBuilderImpl.invoke(InvocationBuilderImpl.java:59) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.jet.impl.MasterContext.invokeOnParticipant(MasterContext.java:264) ~[classes/:?]
	at com.hazelcast.jet.impl.MasterContext.invokeOnParticipants(MasterContext.java:247) ~[classes/:?]
	at com.hazelcast.jet.impl.MasterSnapshotContext.lambda$onSnapshotPhase1Complete$5(MasterSnapshotContext.java:277) ~[classes/:?]
	at com.hazelcast.jet.impl.JobCoordinationService.lambda$submitToCoordinatorThread$46(JobCoordinationService.java:1039) ~[classes/:?]
	at com.hazelcast.jet.impl.JobCoordinationService.lambda$submitToCoordinatorThread$47(JobCoordinationService.java:1060) ~[classes/:?]
	at com.hazelcast.internal.util.executor.CompletableFutureTask.run(CompletableFutureTask.java:64) [hazelcast-4.2.jar:4.2]
	at com.hazelcast.internal.util.executor.CachedExecutorServiceDelegate$Worker.run(CachedExecutorServiceDelegate.java:217) [hazelcast-4.2.jar:4.2]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630) [?:?]
	at java.lang.Thread.run(Thread.java:832) [?:?]
	at com.hazelcast.internal.util.executor.HazelcastManagedThread.executeRun(HazelcastManagedThread.java:76) [hazelcast-4.2.jar:4.2]
	at com.hazelcast.internal.util.executor.HazelcastManagedThread.run(HazelcastManagedThread.java:102) [hazelcast-4.2.jar:4.2]
2021-05-09 15:32:54,615 [DEBUG] [hz.peaceful_booth.cached.thread-9] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Not completing terminalSnapshotFuture on job '0628-af7d-f342-0001', execution 0628-af7d-f344-0001, new execution already started, snapshot was for executionId=0628-af7d-f343-0001
2021-05-09 15:32:54,616 [ INFO] [hz.peaceful_booth.cached.thread-10] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] About to restore the state of job '0628-af7d-f342-0001', execution 0628-af7d-f344-0001 from snapshot 0, mapName = __jet.snapshot.0628-af7d-f342-0001.0
2021-05-09 15:32:54,637 [ INFO] [hz.peaceful_booth.cached.thread-10] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Start executing job '0628-af7d-f342-0001', execution 0628-af7d-f344-0001, execution graph in DOT format:
digraph DAG {
	"src" [localParallelism=1];
	"filesSink(/tmp/write-file-p14527133490174925014)" [localParallelism=2];
	"src" -> "filesSink(/tmp/write-file-p14527133490174925014)" [queueSize=1024];
}
HINT: You can use graphviz or http://viz-js.com to visualize the printed graph.
2021-05-09 15:32:54,637 [DEBUG] [hz.peaceful_booth.cached.thread-10] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Building execution plan for job '0628-af7d-f342-0001', execution 0628-af7d-f344-0001
2021-05-09 15:32:54,651 [DEBUG] [hz.peaceful_booth.cached.thread-10] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Built execution plans for job '0628-af7d-f342-0001', execution 0628-af7d-f344-0001
2021-05-09 15:32:54,655 [DEBUG] [hz.peaceful_booth.cached.thread-10] [c.h.j.i.o.InitExecutionOperation]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Initializing execution plan for job 0628-af7d-f342-0001, execution 0628-af7d-f344-0001 from [127.0.0.1]:5701
2021-05-09 15:32:54,845 [ INFO] [hz.peaceful_booth.cached.thread-10] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Execution plan for jobId=0628-af7d-f342-0001, jobName='0628-af7d-f342-0001', executionId=0628-af7d-f344-0001 initialized
2021-05-09 15:32:54,846 [DEBUG] [hz.peaceful_booth.cached.thread-5] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Init of job '0628-af7d-f342-0001', execution 0628-af7d-f344-0001 was successful
2021-05-09 15:32:54,846 [DEBUG] [hz.peaceful_booth.cached.thread-5] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Executing job '0628-af7d-f342-0001', execution 0628-af7d-f344-0001
2021-05-09 15:32:54,854 [ INFO] [hz.peaceful_booth.cached.thread-5] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Start execution of job '0628-af7d-f342-0001', execution 0628-af7d-f344-0001 from coordinator [127.0.0.1]:5701
2021-05-09 15:32:55,106 [DEBUG] [stressTest_atLeastOnce_forceful] [c.h.j.Job]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Sending RESTART_FORCEFUL request for job 0628-af7d-f342-0001 (name ??)
2021-05-09 15:32:55,117 [DEBUG] [hz.peaceful_booth.cached.thread-5] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] job '0628-af7d-f342-0001', execution 0628-af7d-f344-0001 snapshot is scheduled in 50ms
2021-05-09 15:32:55,477 [DEBUG] [hz.peaceful_booth.jet.cooperative.thread-50] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Execution of job '0628-af7d-f342-0001', execution 0628-af7d-f344-0001 completed with failure
java.util.concurrent.CompletionException: com.hazelcast.jet.impl.exception.JobTerminateRequestedException: RESTART_FORCEFUL
	at java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:331) ~[?:?]
	at java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:346) ~[?:?]
	at java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:632) ~[?:?]
	at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:506) ~[?:?]
	at java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:2152) ~[?:?]
	at com.hazelcast.jet.impl.util.NonCompletableFuture.internalCompleteExceptionally(NonCompletableFuture.java:59) ~[classes/:?]
	at com.hazelcast.jet.impl.execution.TaskletExecutionService$ExecutionTracker.taskletDone(TaskletExecutionService.java:468) ~[classes/:?]
	at com.hazelcast.jet.impl.execution.TaskletExecutionService$CooperativeWorker.dismissTasklet(TaskletExecutionService.java:399) ~[classes/:?]
	at com.hazelcast.jet.impl.execution.TaskletExecutionService$CooperativeWorker.runTasklet(TaskletExecutionService.java:385) ~[classes/:?]
	at java.util.concurrent.CopyOnWriteArrayList.forEach(CopyOnWriteArrayList.java:807) [?:?]
	at com.hazelcast.jet.impl.execution.TaskletExecutionService$CooperativeWorker.run(TaskletExecutionService.java:347) [classes/:?]
	at java.lang.Thread.run(Thread.java:832) [?:?]
Caused by: com.hazelcast.jet.impl.exception.JobTerminateRequestedException: RESTART_FORCEFUL
	at com.hazelcast.jet.impl.execution.ExecutionContext.terminateExecution(ExecutionContext.java:235) ~[classes/:?]
	at com.hazelcast.jet.impl.operation.TerminateExecutionOperation.run(TerminateExecutionOperation.java:61) ~[classes/:?]
	at com.hazelcast.spi.impl.operationservice.Operation.call(Operation.java:189) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.call(OperationRunnerImpl.java:272) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:248) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:213) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationexecutor.impl.OperationExecutorImpl.run(OperationExecutorImpl.java:411) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationexecutor.impl.OperationExecutorImpl.runOrExecute(OperationExecutorImpl.java:438) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.doInvokeLocal(Invocation.java:600) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.doInvoke(Invocation.java:579) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke0(Invocation.java:540) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke(Invocation.java:240) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.InvocationBuilderImpl.invoke(InvocationBuilderImpl.java:59) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.jet.impl.MasterContext.invokeOnParticipant(MasterContext.java:264) ~[classes/:?]
	at com.hazelcast.jet.impl.MasterContext.invokeOnParticipants(MasterContext.java:247) ~[classes/:?]
	at com.hazelcast.jet.impl.MasterJobContext.lambda$cancelExecutionInvocations$16(MasterJobContext.java:601) ~[classes/:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130) ~[?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630) ~[?:?]
	at java.lang.Thread.run(Thread.java:832) ~[?:?]
	at com.hazelcast.internal.util.executor.HazelcastManagedThread.executeRun(HazelcastManagedThread.java:76) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.internal.util.executor.HazelcastManagedThread.run(HazelcastManagedThread.java:102) ~[hazelcast-4.2.jar:4.2]
2021-05-09 15:32:55,478 [DEBUG] [ForkJoinPool.commonPool-worker-31] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Execution of job '0628-af7d-f342-0001', execution 0628-af7d-f344-0001 has failures: [[127.0.0.1]:5701=com.hazelcast.jet.impl.exception.JobTerminateRequestedException: RESTART_FORCEFUL]
2021-05-09 15:32:55,478 [DEBUG] [hz.peaceful_booth.cached.thread-42] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Sending CompleteExecutionOperation for job '0628-af7d-f342-0001', execution 0628-af7d-f344-0001
2021-05-09 15:32:55,479 [DEBUG] [hz.peaceful_booth.cached.thread-42] [c.h.j.i.o.CompleteExecutionOperation]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Completing execution 0628-af7d-f344-0001 from caller [127.0.0.1]:5701, error=com.hazelcast.jet.impl.exception.JobTerminateRequestedException: RESTART_FORCEFUL
2021-05-09 15:32:55,479 [DEBUG] [hz.peaceful_booth.cached.thread-42] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Completed execution of job '0628-af7d-f342-0001', execution 0628-af7d-f344-0001
2021-05-09 15:32:55,519 [DEBUG] [hz.peaceful_booth.cached.thread-46] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Starting snapshot 2 for job '0628-af7d-f342-0001', execution 0628-af7d-f345-0001, flags: terminal=no,export=no, writing to: null
2021-05-09 15:32:55,520 [ERROR] [hz.peaceful_booth.cached.thread-46] [c.h.j.i.o.SnapshotPhase1Operation]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] job 0628-af7d-f342-0001, execution 0628-af7d-f344-0001 not found for coordinator [127.0.0.1]:5701 for 'SnapshotPhase1Operation'
com.hazelcast.jet.core.TopologyChangedException: job 0628-af7d-f342-0001, execution 0628-af7d-f344-0001 not found for coordinator [127.0.0.1]:5701 for 'SnapshotPhase1Operation'
	at com.hazelcast.jet.impl.JobExecutionService.assertExecutionContext(JobExecutionService.java:326) ~[classes/:?]
	at com.hazelcast.jet.impl.operation.SnapshotPhase1Operation.doRun(SnapshotPhase1Operation.java:60) ~[classes/:?]
	at com.hazelcast.jet.impl.operation.AsyncOperation.run(AsyncOperation.java:53) ~[classes/:?]
	at com.hazelcast.spi.impl.operationservice.Operation.call(Operation.java:189) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.call(OperationRunnerImpl.java:272) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:248) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:213) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationexecutor.impl.OperationExecutorImpl.run(OperationExecutorImpl.java:411) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationexecutor.impl.OperationExecutorImpl.runOrExecute(OperationExecutorImpl.java:438) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.doInvokeLocal(Invocation.java:600) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.doInvoke(Invocation.java:579) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke0(Invocation.java:540) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke(Invocation.java:240) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.InvocationBuilderImpl.invoke(InvocationBuilderImpl.java:59) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.jet.impl.MasterContext.invokeOnParticipant(MasterContext.java:264) ~[classes/:?]
	at com.hazelcast.jet.impl.MasterContext.invokeOnParticipants(MasterContext.java:247) ~[classes/:?]
	at com.hazelcast.jet.impl.MasterSnapshotContext.lambda$tryBeginSnapshot$2(MasterSnapshotContext.java:173) ~[classes/:?]
	at com.hazelcast.jet.impl.JobCoordinationService.lambda$submitToCoordinatorThread$46(JobCoordinationService.java:1039) ~[classes/:?]
	at com.hazelcast.jet.impl.JobCoordinationService.lambda$submitToCoordinatorThread$47(JobCoordinationService.java:1060) ~[classes/:?]
	at com.hazelcast.internal.util.executor.CompletableFutureTask.run(CompletableFutureTask.java:64) [hazelcast-4.2.jar:4.2]
	at com.hazelcast.internal.util.executor.CachedExecutorServiceDelegate$Worker.run(CachedExecutorServiceDelegate.java:217) [hazelcast-4.2.jar:4.2]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630) [?:?]
	at java.lang.Thread.run(Thread.java:832) [?:?]
	at com.hazelcast.internal.util.executor.HazelcastManagedThread.executeRun(HazelcastManagedThread.java:76) [hazelcast-4.2.jar:4.2]
	at com.hazelcast.internal.util.executor.HazelcastManagedThread.run(HazelcastManagedThread.java:102) [hazelcast-4.2.jar:4.2]
2021-05-09 15:32:55,520 [DEBUG] [hz.peaceful_booth.cached.thread-48] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] job '0628-af7d-f342-0001', execution 0628-af7d-f345-0001: ignoring responses for snapshot 2 phase 1: the responses are from a different execution: 0628-af7d-f344-0001. Responses: [MemberInfo{address=[127.0.0.1]:5701, uuid=e576beac-64f2-440a-b59d-d2c173094e1f, liteMember=false, memberListJoinVersion=1}=com.hazelcast.jet.core.TopologyChangedException: job 0628-af7d-f342-0001, execution 0628-af7d-f344-0001 not found for coordinator [127.0.0.1]:5701 for 'SnapshotPhase1Operation']
2021-05-09 15:32:55,521 [ INFO] [hz.peaceful_booth.cached.thread-42] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] About to restore the state of job '0628-af7d-f342-0001', execution 0628-af7d-f345-0001 from snapshot 0, mapName = __jet.snapshot.0628-af7d-f342-0001.0
2021-05-09 15:32:55,521 [ INFO] [hz.peaceful_booth.cached.thread-42] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Start executing job '0628-af7d-f342-0001', execution 0628-af7d-f345-0001, execution graph in DOT format:
digraph DAG {
	"src" [localParallelism=1];
	"filesSink(/tmp/write-file-p14527133490174925014)" [localParallelism=2];
	"src" -> "filesSink(/tmp/write-file-p14527133490174925014)" [queueSize=1024];
}
HINT: You can use graphviz or http://viz-js.com to visualize the printed graph.
2021-05-09 15:32:55,521 [DEBUG] [hz.peaceful_booth.cached.thread-42] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Building execution plan for job '0628-af7d-f342-0001', execution 0628-af7d-f345-0001
2021-05-09 15:32:55,522 [DEBUG] [hz.peaceful_booth.cached.thread-42] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Built execution plans for job '0628-af7d-f342-0001', execution 0628-af7d-f345-0001
2021-05-09 15:32:55,523 [DEBUG] [hz.peaceful_booth.cached.thread-42] [c.h.j.i.o.InitExecutionOperation]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Initializing execution plan for job 0628-af7d-f342-0001, execution 0628-af7d-f345-0001 from [127.0.0.1]:5701
2021-05-09 15:32:55,581 [ INFO] [hz.peaceful_booth.cached.thread-42] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Execution plan for jobId=0628-af7d-f342-0001, jobName='0628-af7d-f342-0001', executionId=0628-af7d-f345-0001 initialized
2021-05-09 15:32:55,581 [DEBUG] [hz.peaceful_booth.cached.thread-47] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Init of job '0628-af7d-f342-0001', execution 0628-af7d-f345-0001 was successful
2021-05-09 15:32:55,582 [DEBUG] [hz.peaceful_booth.cached.thread-47] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Executing job '0628-af7d-f342-0001', execution 0628-af7d-f345-0001
2021-05-09 15:32:55,582 [ INFO] [hz.peaceful_booth.cached.thread-47] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Start execution of job '0628-af7d-f342-0001', execution 0628-af7d-f345-0001 from coordinator [127.0.0.1]:5701
2021-05-09 15:32:55,665 [DEBUG] [hz.peaceful_booth.cached.thread-47] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] job '0628-af7d-f342-0001', execution 0628-af7d-f345-0001 snapshot is scheduled in 50ms
2021-05-09 15:32:55,797 [DEBUG] [hz.peaceful_booth.cached.thread-66] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Starting snapshot 3 for job '0628-af7d-f342-0001', execution 0628-af7d-f345-0001, flags: terminal=no,export=no, writing to: null
2021-05-09 15:32:55,798 [DEBUG] [hz.peaceful_booth.cached.thread-66] [c.h.j.i.e.ExecutionContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Starting snapshot 3 phase 1 for job '0628-af7d-f342-0001', execution 0628-af7d-f345-0001 on member
2021-05-09 15:32:55,798 [ INFO] [hz.peaceful_booth.cached.thread-66] [c.h.j.i.e.SnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Snapshot 3 for job '0628-af7d-f342-0001', execution 0628-af7d-f345-0001 is postponed until all higher priority vertices are completed (number of such vertices = 2)
2021-05-09 15:32:55,809 [DEBUG] [stressTest_atLeastOnce_forceful] [c.h.j.Job]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Sending RESTART_FORCEFUL request for job 0628-af7d-f342-0001 (name ??)
2021-05-09 15:32:55,830 [ WARN] [hz.peaceful_booth.async.thread-3] [c.h.j.i.o.SnapshotPhase1Operation]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Snapshot 3 phase 1 for job '0628-af7d-f342-0001', execution 0628-af7d-f345-0001 finished with an error on member: java.util.concurrent.CancellationException: execution cancelled
2021-05-09 15:32:55,832 [DEBUG] [hz.peaceful_booth.cached.thread-68] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Snapshot 3 phase 1 for job '0628-af7d-f342-0001', execution 0628-af7d-f345-0001 completed with status FAILURE in 102ms, 0 bytes, 0 keys in 0 chunks, stored in '__jet.snapshot.0628-af7d-f342-0001.1', proceeding to phase 2
2021-05-09 15:32:55,832 [ WARN] [hz.peaceful_booth.cached.thread-68] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] job '0628-af7d-f342-0001', execution 0628-af7d-f345-0001 snapshot 3 phase 1 failed on some member(s), one of the failures: java.util.concurrent.CancellationException: execution cancelled
2021-05-09 15:32:55,843 [DEBUG] [hz.peaceful_booth.jet.cooperative.thread-53] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Execution of job '0628-af7d-f342-0001', execution 0628-af7d-f345-0001 completed with failure
java.util.concurrent.CompletionException: com.hazelcast.jet.impl.exception.JobTerminateRequestedException: RESTART_FORCEFUL
	at java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:331) ~[?:?]
	at java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:346) ~[?:?]
	at java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:632) ~[?:?]
	at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:506) ~[?:?]
	at java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:2152) ~[?:?]
	at com.hazelcast.jet.impl.util.NonCompletableFuture.internalCompleteExceptionally(NonCompletableFuture.java:59) ~[classes/:?]
	at com.hazelcast.jet.impl.execution.TaskletExecutionService$ExecutionTracker.taskletDone(TaskletExecutionService.java:468) ~[classes/:?]
	at com.hazelcast.jet.impl.execution.TaskletExecutionService$CooperativeWorker.dismissTasklet(TaskletExecutionService.java:399) ~[classes/:?]
	at com.hazelcast.jet.impl.execution.TaskletExecutionService$CooperativeWorker.runTasklet(TaskletExecutionService.java:385) ~[classes/:?]
	at java.util.concurrent.CopyOnWriteArrayList.forEach(CopyOnWriteArrayList.java:807) [?:?]
	at com.hazelcast.jet.impl.execution.TaskletExecutionService$CooperativeWorker.run(TaskletExecutionService.java:347) [classes/:?]
	at java.lang.Thread.run(Thread.java:832) [?:?]
Caused by: com.hazelcast.jet.impl.exception.JobTerminateRequestedException: RESTART_FORCEFUL
	at com.hazelcast.jet.impl.execution.ExecutionContext.terminateExecution(ExecutionContext.java:235) ~[classes/:?]
	at com.hazelcast.jet.impl.operation.TerminateExecutionOperation.run(TerminateExecutionOperation.java:61) ~[classes/:?]
	at com.hazelcast.spi.impl.operationservice.Operation.call(Operation.java:189) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.call(OperationRunnerImpl.java:272) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:248) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:213) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationexecutor.impl.OperationExecutorImpl.run(OperationExecutorImpl.java:411) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationexecutor.impl.OperationExecutorImpl.runOrExecute(OperationExecutorImpl.java:438) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.doInvokeLocal(Invocation.java:600) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.doInvoke(Invocation.java:579) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke0(Invocation.java:540) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke(Invocation.java:240) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.InvocationBuilderImpl.invoke(InvocationBuilderImpl.java:59) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.jet.impl.MasterContext.invokeOnParticipant(MasterContext.java:264) ~[classes/:?]
	at com.hazelcast.jet.impl.MasterContext.invokeOnParticipants(MasterContext.java:247) ~[classes/:?]
	at com.hazelcast.jet.impl.MasterJobContext.lambda$cancelExecutionInvocations$16(MasterJobContext.java:601) ~[classes/:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130) ~[?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630) ~[?:?]
	at java.lang.Thread.run(Thread.java:832) ~[?:?]
	at com.hazelcast.internal.util.executor.HazelcastManagedThread.executeRun(HazelcastManagedThread.java:76) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.internal.util.executor.HazelcastManagedThread.run(HazelcastManagedThread.java:102) ~[hazelcast-4.2.jar:4.2]
2021-05-09 15:32:55,844 [DEBUG] [ForkJoinPool.commonPool-worker-43] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Execution of job '0628-af7d-f342-0001', execution 0628-af7d-f345-0001 has failures: [[127.0.0.1]:5701=com.hazelcast.jet.impl.exception.JobTerminateRequestedException: RESTART_FORCEFUL]
2021-05-09 15:32:55,845 [DEBUG] [hz.peaceful_booth.cached.thread-72] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Sending CompleteExecutionOperation for job '0628-af7d-f342-0001', execution 0628-af7d-f345-0001
2021-05-09 15:32:55,845 [DEBUG] [hz.peaceful_booth.cached.thread-72] [c.h.j.i.o.CompleteExecutionOperation]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Completing execution 0628-af7d-f345-0001 from caller [127.0.0.1]:5701, error=com.hazelcast.jet.impl.exception.JobTerminateRequestedException: RESTART_FORCEFUL
2021-05-09 15:32:55,845 [DEBUG] [hz.peaceful_booth.cached.thread-72] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Completed execution of job '0628-af7d-f342-0001', execution 0628-af7d-f345-0001
2021-05-09 15:32:55,952 [DEBUG] [hz.peaceful_booth.cached.thread-68] [c.h.j.i.JobRepository]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Cleared snapshot data map __jet.snapshot.0628-af7d-f342-0001.1
2021-05-09 15:32:55,952 [ERROR] [hz.peaceful_booth.cached.thread-68] [c.h.j.i.o.SnapshotPhase2Operation]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] job 0628-af7d-f342-0001, execution 0628-af7d-f345-0001 not found for coordinator [127.0.0.1]:5701 for 'SnapshotPhase2Operation'
com.hazelcast.jet.core.TopologyChangedException: job 0628-af7d-f342-0001, execution 0628-af7d-f345-0001 not found for coordinator [127.0.0.1]:5701 for 'SnapshotPhase2Operation'
	at com.hazelcast.jet.impl.JobExecutionService.assertExecutionContext(JobExecutionService.java:326) ~[classes/:?]
	at com.hazelcast.jet.impl.operation.SnapshotPhase2Operation.doRun(SnapshotPhase2Operation.java:50) ~[classes/:?]
	at com.hazelcast.jet.impl.operation.AsyncOperation.run(AsyncOperation.java:53) ~[classes/:?]
	at com.hazelcast.spi.impl.operationservice.Operation.call(Operation.java:189) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.call(OperationRunnerImpl.java:272) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:248) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:213) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationexecutor.impl.OperationExecutorImpl.run(OperationExecutorImpl.java:411) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationexecutor.impl.OperationExecutorImpl.runOrExecute(OperationExecutorImpl.java:438) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.doInvokeLocal(Invocation.java:600) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.doInvoke(Invocation.java:579) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke0(Invocation.java:540) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke(Invocation.java:240) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.InvocationBuilderImpl.invoke(InvocationBuilderImpl.java:59) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.jet.impl.MasterContext.invokeOnParticipant(MasterContext.java:264) ~[classes/:?]
	at com.hazelcast.jet.impl.MasterContext.invokeOnParticipants(MasterContext.java:247) ~[classes/:?]
	at com.hazelcast.jet.impl.MasterSnapshotContext.lambda$onSnapshotPhase1Complete$5(MasterSnapshotContext.java:277) ~[classes/:?]
	at com.hazelcast.jet.impl.JobCoordinationService.lambda$submitToCoordinatorThread$46(JobCoordinationService.java:1039) ~[classes/:?]
	at com.hazelcast.jet.impl.JobCoordinationService.lambda$submitToCoordinatorThread$47(JobCoordinationService.java:1060) ~[classes/:?]
	at com.hazelcast.internal.util.executor.CompletableFutureTask.run(CompletableFutureTask.java:64) [hazelcast-4.2.jar:4.2]
	at com.hazelcast.internal.util.executor.CachedExecutorServiceDelegate$Worker.run(CachedExecutorServiceDelegate.java:217) [hazelcast-4.2.jar:4.2]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630) [?:?]
	at java.lang.Thread.run(Thread.java:832) [?:?]
	at com.hazelcast.internal.util.executor.HazelcastManagedThread.executeRun(HazelcastManagedThread.java:76) [hazelcast-4.2.jar:4.2]
	at com.hazelcast.internal.util.executor.HazelcastManagedThread.run(HazelcastManagedThread.java:102) [hazelcast-4.2.jar:4.2]
2021-05-09 15:32:55,953 [ WARN] [hz.peaceful_booth.cached.thread-68] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] SnapshotPhase2Operation for snapshot 3 in job '0628-af7d-f342-0001', execution 0628-af7d-f345-0001 failed on member: MemberInfo{address=[127.0.0.1]:5701, uuid=e576beac-64f2-440a-b59d-d2c173094e1f, liteMember=false, memberListJoinVersion=1}=com.hazelcast.jet.core.TopologyChangedException: job 0628-af7d-f342-0001, execution 0628-af7d-f345-0001 not found for coordinator [127.0.0.1]:5701 for 'SnapshotPhase2Operation'
com.hazelcast.jet.core.TopologyChangedException: job 0628-af7d-f342-0001, execution 0628-af7d-f345-0001 not found for coordinator [127.0.0.1]:5701 for 'SnapshotPhase2Operation'
	at com.hazelcast.jet.impl.JobExecutionService.assertExecutionContext(JobExecutionService.java:326) ~[classes/:?]
	at com.hazelcast.jet.impl.operation.SnapshotPhase2Operation.doRun(SnapshotPhase2Operation.jav
...[truncated 3276007 chars]...
 job '0628-af7d-f342-0001', execution 0628-af9e-4717-0001
2021-05-09 15:33:54,134 [DEBUG] [hz.peaceful_booth.cached.thread-65] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Built execution plans for job '0628-af7d-f342-0001', execution 0628-af9e-4717-0001
2021-05-09 15:33:54,135 [DEBUG] [hz.peaceful_booth.cached.thread-65] [c.h.j.i.o.InitExecutionOperation]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Initializing execution plan for job 0628-af7d-f342-0001, execution 0628-af9e-4717-0001 from [127.0.0.1]:5701
2021-05-09 15:33:54,139 [ INFO] [hz.peaceful_booth.cached.thread-65] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Execution plan for jobId=0628-af7d-f342-0001, jobName='0628-af7d-f342-0001', executionId=0628-af9e-4717-0001 initialized
2021-05-09 15:33:54,162 [DEBUG] [hz.peaceful_booth.cached.thread-65] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Not beginning snapshot, job '0628-af7d-f342-0001', execution 0628-af9e-4717-0001 is not RUNNING, but STARTING
2021-05-09 15:33:54,164 [DEBUG] [hz.peaceful_booth.cached.thread-22] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Init of job '0628-af7d-f342-0001', execution 0628-af9e-4717-0001 was successful
2021-05-09 15:33:54,164 [DEBUG] [hz.peaceful_booth.cached.thread-22] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Executing job '0628-af7d-f342-0001', execution 0628-af9e-4717-0001
2021-05-09 15:33:54,164 [ INFO] [hz.peaceful_booth.cached.thread-22] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Start execution of job '0628-af7d-f342-0001', execution 0628-af9e-4717-0001 from coordinator [127.0.0.1]:5701
2021-05-09 15:33:54,167 [DEBUG] [hz.peaceful_booth.cached.thread-22] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] job '0628-af7d-f342-0001', execution 0628-af9e-4717-0001 snapshot is scheduled in 50ms
2021-05-09 15:33:54,225 [DEBUG] [hz.peaceful_booth.cached.thread-19] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Starting snapshot 220 for job '0628-af7d-f342-0001', execution 0628-af9e-4717-0001, flags: terminal=no,export=no, writing to: null
2021-05-09 15:33:54,225 [DEBUG] [hz.peaceful_booth.cached.thread-19] [c.h.j.i.e.ExecutionContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Starting snapshot 220 phase 1 for job '0628-af7d-f342-0001', execution 0628-af9e-4717-0001 on member
2021-05-09 15:33:54,225 [ INFO] [hz.peaceful_booth.cached.thread-19] [c.h.j.i.e.SnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Snapshot 220 for job '0628-af7d-f342-0001', execution 0628-af9e-4717-0001 is postponed until all higher priority vertices are completed (number of such vertices = 2)
2021-05-09 15:33:54,225 [DEBUG] [hz.peaceful_booth.cached.thread-20] [c.h.j.i.JobRepository]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Job cleanup took 7ms
2021-05-09 15:33:54,269 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-1] [c.h.j.i.c.ConvenientSourceP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-af7d-f342-0001/src#0] src vertex restored from snapshot: 175
2021-05-09 15:33:54,274 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-3] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-af7d-f342-0001/filesSink(/tmp/write-file-p14527133490174925014)#0] creating /tmp/write-file-p14527133490174925014/0
2021-05-09 15:33:54,275 [ INFO] [hz.peaceful_booth.jet.cooperative.thread-57] [c.h.j.i.e.SnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Postponed snapshot 220 for job '0628-af7d-f342-0001', execution 0628-af9e-4717-0001 started
2021-05-09 15:33:54,279 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-1] [c.h.j.i.c.ConvenientSourceP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-af7d-f342-0001/src#0] src vertex saved to snapshot: 177
2021-05-09 15:33:54,281 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-3] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-af7d-f342-0001/filesSink(/tmp/write-file-p14527133490174925014)#0] flush File{0}
2021-05-09 15:33:54,283 [DEBUG] [hz.peaceful_booth.jet.cooperative.thread-58] [c.h.j.i.u.AsyncSnapshotWriterImpl]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Stats for src: keys=1, chunks=1, bytes=37
2021-05-09 15:33:54,286 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-2] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-af7d-f342-0001/filesSink(/tmp/write-file-p14527133490174925014)#1] creating /tmp/write-file-p14527133490174925014/1
2021-05-09 15:33:54,286 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-2] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-af7d-f342-0001/filesSink(/tmp/write-file-p14527133490174925014)#1] flush File{1}
2021-05-09 15:33:54,296 [DEBUG] [hz.peaceful_booth.jet.cooperative.thread-59] [c.h.j.i.u.AsyncSnapshotWriterImpl]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Stats for filesSink(/tmp/write-file-p14527133490174925014): keys=0, chunks=0, bytes=0
2021-05-09 15:33:54,296 [DEBUG] [hz.peaceful_booth.jet.cooperative.thread-59] [c.h.j.i.o.SnapshotPhase1Operation]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Snapshot 220 phase 1 for job '0628-af7d-f342-0001', execution 0628-af9e-4717-0001 finished successfully on member
2021-05-09 15:33:54,301 [DEBUG] [hz.peaceful_booth.cached.thread-5] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Snapshot 220 phase 1 for job '0628-af7d-f342-0001', execution 0628-af9e-4717-0001 completed with status SUCCESS in 79ms, 37 bytes, 1 keys in 1 chunks, stored in '__jet.snapshot.0628-af7d-f342-0001.0', proceeding to phase 2
2021-05-09 15:33:54,304 [DEBUG] [hz.peaceful_booth.cached.thread-5] [c.h.j.i.JobRepository]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Cleared snapshot data map __jet.snapshot.0628-af7d-f342-0001.1
2021-05-09 15:33:54,304 [DEBUG] [hz.peaceful_booth.cached.thread-5] [c.h.j.i.e.ExecutionContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Starting snapshot 220 phase 2 for job '0628-af7d-f342-0001', execution 0628-af9e-4717-0001 on member
2021-05-09 15:33:54,309 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-2] [c.h.j.i.o.SnapshotPhase2Operation]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Snapshot 220 phase 2 for job '0628-af7d-f342-0001', execution 0628-af9e-4717-0001 finished successfully on member
2021-05-09 15:33:54,310 [DEBUG] [hz.peaceful_booth.cached.thread-32] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] job '0628-af7d-f342-0001', execution 0628-af9e-4717-0001 snapshot is scheduled in 50ms
2021-05-09 15:33:54,310 [DEBUG] [hz.peaceful_booth.cached.thread-32] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Snapshot 220 for job '0628-af7d-f342-0001', execution 0628-af9e-4717-0001 completed in 91ms, status=success
2021-05-09 15:33:54,363 [DEBUG] [hz.peaceful_booth.cached.thread-5] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Starting snapshot 221 for job '0628-af7d-f342-0001', execution 0628-af9e-4717-0001, flags: terminal=no,export=no, writing to: null
2021-05-09 15:33:54,364 [DEBUG] [hz.peaceful_booth.cached.thread-5] [c.h.j.i.e.ExecutionContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Starting snapshot 221 phase 1 for job '0628-af7d-f342-0001', execution 0628-af9e-4717-0001 on member
2021-05-09 15:33:54,369 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-1] [c.h.j.i.c.ConvenientSourceP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-af7d-f342-0001/src#0] src vertex saved to snapshot: 191
2021-05-09 15:33:54,369 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-3] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-af7d-f342-0001/filesSink(/tmp/write-file-p14527133490174925014)#0] flush File{0}
2021-05-09 15:33:54,370 [DEBUG] [hz.peaceful_booth.jet.cooperative.thread-58] [c.h.j.i.u.AsyncSnapshotWriterImpl]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Stats for src: keys=1, chunks=1, bytes=37
2021-05-09 15:33:54,374 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-2] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-af7d-f342-0001/filesSink(/tmp/write-file-p14527133490174925014)#1] flush File{1}
2021-05-09 15:33:54,375 [DEBUG] [hz.peaceful_booth.jet.cooperative.thread-59] [c.h.j.i.u.AsyncSnapshotWriterImpl]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Stats for filesSink(/tmp/write-file-p14527133490174925014): keys=0, chunks=0, bytes=0
2021-05-09 15:33:54,375 [DEBUG] [hz.peaceful_booth.jet.cooperative.thread-59] [c.h.j.i.o.SnapshotPhase1Operation]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Snapshot 221 phase 1 for job '0628-af7d-f342-0001', execution 0628-af9e-4717-0001 finished successfully on member
2021-05-09 15:33:54,377 [DEBUG] [hz.peaceful_booth.cached.thread-5] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Snapshot 221 phase 1 for job '0628-af7d-f342-0001', execution 0628-af9e-4717-0001 completed with status SUCCESS in 15ms, 37 bytes, 1 keys in 1 chunks, stored in '__jet.snapshot.0628-af7d-f342-0001.1', proceeding to phase 2
2021-05-09 15:33:54,381 [DEBUG] [hz.peaceful_booth.cached.thread-5] [c.h.j.i.JobRepository]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Cleared snapshot data map __jet.snapshot.0628-af7d-f342-0001.0
2021-05-09 15:33:54,381 [DEBUG] [hz.peaceful_booth.cached.thread-5] [c.h.j.i.e.ExecutionContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Starting snapshot 221 phase 2 for job '0628-af7d-f342-0001', execution 0628-af9e-4717-0001 on member
2021-05-09 15:33:54,385 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-1] [c.h.j.i.o.SnapshotPhase2Operation]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Snapshot 221 phase 2 for job '0628-af7d-f342-0001', execution 0628-af9e-4717-0001 finished successfully on member
2021-05-09 15:33:54,387 [DEBUG] [hz.peaceful_booth.cached.thread-5] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] job '0628-af7d-f342-0001', execution 0628-af9e-4717-0001 snapshot is scheduled in 50ms
2021-05-09 15:33:54,387 [DEBUG] [hz.peaceful_booth.cached.thread-5] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Snapshot 221 for job '0628-af7d-f342-0001', execution 0628-af9e-4717-0001 completed in 26ms, status=success
2021-05-09 15:33:54,413 [DEBUG] [stressTest_atLeastOnce_forceful] [c.h.j.Job]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Sending RESTART_FORCEFUL request for job 0628-af7d-f342-0001 (name ??)
2021-05-09 15:33:54,426 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-2] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Execution of job '0628-af7d-f342-0001', execution 0628-af9e-4717-0001 completed with failure
java.util.concurrent.CompletionException: com.hazelcast.jet.impl.exception.JobTerminateRequestedException: RESTART_FORCEFUL
	at java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:331) ~[?:?]
	at java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:346) ~[?:?]
	at java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:632) ~[?:?]
	at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:506) [?:?]
	at java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:2152) [?:?]
	at com.hazelcast.jet.impl.util.NonCompletableFuture.internalCompleteExceptionally(NonCompletableFuture.java:59) [classes/:?]
	at com.hazelcast.jet.impl.execution.TaskletExecutionService$ExecutionTracker.taskletDone(TaskletExecutionService.java:468) [classes/:?]
	at com.hazelcast.jet.impl.execution.TaskletExecutionService$BlockingWorker.run(TaskletExecutionService.java:310) [classes/:?]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [?:?]
	at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630) [?:?]
	at java.lang.Thread.run(Thread.java:832) [?:?]
Caused by: com.hazelcast.jet.impl.exception.JobTerminateRequestedException: RESTART_FORCEFUL
	at com.hazelcast.jet.impl.execution.ExecutionContext.terminateExecution(ExecutionContext.java:235) ~[classes/:?]
	at com.hazelcast.jet.impl.operation.TerminateExecutionOperation.run(TerminateExecutionOperation.java:61) ~[classes/:?]
	at com.hazelcast.spi.impl.operationservice.Operation.call(Operation.java:189) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.call(OperationRunnerImpl.java:272) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:248) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:213) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationexecutor.impl.OperationExecutorImpl.run(OperationExecutorImpl.java:411) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationexecutor.impl.OperationExecutorImpl.runOrExecute(OperationExecutorImpl.java:438) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.doInvokeLocal(Invocation.java:600) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.doInvoke(Invocation.java:579) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke0(Invocation.java:540) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke(Invocation.java:240) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.InvocationBuilderImpl.invoke(InvocationBuilderImpl.java:59) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.jet.impl.MasterContext.invokeOnParticipant(MasterContext.java:264) ~[classes/:?]
	at com.hazelcast.jet.impl.MasterContext.invokeOnParticipants(MasterContext.java:247) ~[classes/:?]
	at com.hazelcast.jet.impl.MasterJobContext.lambda$cancelExecutionInvocations$16(MasterJobContext.java:601) ~[classes/:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130) ~[?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630) ~[?:?]
	at java.lang.Thread.run(Thread.java:832) ~[?:?]
	at com.hazelcast.internal.util.executor.HazelcastManagedThread.executeRun(HazelcastManagedThread.java:76) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.internal.util.executor.HazelcastManagedThread.run(HazelcastManagedThread.java:102) ~[hazelcast-4.2.jar:4.2]
2021-05-09 15:33:54,427 [DEBUG] [ForkJoinPool.commonPool-worker-239] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Execution of job '0628-af7d-f342-0001', execution 0628-af9e-4717-0001 has failures: [[127.0.0.1]:5701=com.hazelcast.jet.impl.exception.JobTerminateRequestedException: RESTART_FORCEFUL]
2021-05-09 15:33:54,428 [DEBUG] [hz.peaceful_booth.cached.thread-5] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Sending CompleteExecutionOperation for job '0628-af7d-f342-0001', execution 0628-af9e-4717-0001
2021-05-09 15:33:54,428 [DEBUG] [hz.peaceful_booth.cached.thread-5] [c.h.j.i.o.CompleteExecutionOperation]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Completing execution 0628-af9e-4717-0001 from caller [127.0.0.1]:5701, error=com.hazelcast.jet.impl.exception.JobTerminateRequestedException: RESTART_FORCEFUL
2021-05-09 15:33:54,428 [DEBUG] [hz.peaceful_booth.cached.thread-5] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-af7d-f342-0001/filesSink(/tmp/write-file-p14527133490174925014)#0] rollback File{0}
2021-05-09 15:33:54,428 [DEBUG] [hz.peaceful_booth.cached.thread-5] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-af7d-f342-0001/filesSink(/tmp/write-file-p14527133490174925014)#0] release File{0}
2021-05-09 15:33:54,428 [DEBUG] [hz.peaceful_booth.cached.thread-5] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-af7d-f342-0001/filesSink(/tmp/write-file-p14527133490174925014)#0] closing 0
2021-05-09 15:33:54,428 [DEBUG] [hz.peaceful_booth.cached.thread-5] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-af7d-f342-0001/filesSink(/tmp/write-file-p14527133490174925014)#1] rollback File{1}
2021-05-09 15:33:54,428 [DEBUG] [hz.peaceful_booth.cached.thread-5] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-af7d-f342-0001/filesSink(/tmp/write-file-p14527133490174925014)#1] release File{1}
2021-05-09 15:33:54,428 [DEBUG] [hz.peaceful_booth.cached.thread-5] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-af7d-f342-0001/filesSink(/tmp/write-file-p14527133490174925014)#1] closing 1
2021-05-09 15:33:54,428 [DEBUG] [hz.peaceful_booth.cached.thread-5] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Completed execution of job '0628-af7d-f342-0001', execution 0628-af9e-4717-0001
2021-05-09 15:33:54,431 [ INFO] [hz.peaceful_booth.cached.thread-5] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] About to restore the state of job '0628-af7d-f342-0001', execution 0628-af9e-4718-0001 from snapshot 221, mapName = __jet.snapshot.0628-af7d-f342-0001.1
2021-05-09 15:33:54,431 [ INFO] [hz.peaceful_booth.cached.thread-5] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Start executing job '0628-af7d-f342-0001', execution 0628-af9e-4718-0001, execution graph in DOT format:
digraph DAG {
	"src" [localParallelism=1];
	"filesSink(/tmp/write-file-p14527133490174925014)" [localParallelism=2];
	"src" -> "filesSink(/tmp/write-file-p14527133490174925014)" [queueSize=1024];
}
HINT: You can use graphviz or http://viz-js.com to visualize the printed graph.
2021-05-09 15:33:54,431 [DEBUG] [hz.peaceful_booth.cached.thread-5] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Building execution plan for job '0628-af7d-f342-0001', execution 0628-af9e-4718-0001
2021-05-09 15:33:54,432 [DEBUG] [hz.peaceful_booth.cached.thread-5] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Built execution plans for job '0628-af7d-f342-0001', execution 0628-af9e-4718-0001
2021-05-09 15:33:54,433 [DEBUG] [hz.peaceful_booth.cached.thread-5] [c.h.j.i.o.InitExecutionOperation]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Initializing execution plan for job 0628-af7d-f342-0001, execution 0628-af9e-4718-0001 from [127.0.0.1]:5701
2021-05-09 15:33:54,438 [DEBUG] [hz.peaceful_booth.cached.thread-32] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Not beginning snapshot, job '0628-af7d-f342-0001', execution 0628-af9e-4718-0001 is not RUNNING, but STARTING
2021-05-09 15:33:54,438 [ INFO] [hz.peaceful_booth.cached.thread-5] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Execution plan for jobId=0628-af7d-f342-0001, jobName='0628-af7d-f342-0001', executionId=0628-af9e-4718-0001 initialized
2021-05-09 15:33:54,442 [DEBUG] [hz.peaceful_booth.cached.thread-5] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Init of job '0628-af7d-f342-0001', execution 0628-af9e-4718-0001 was successful
2021-05-09 15:33:54,442 [DEBUG] [hz.peaceful_booth.cached.thread-5] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Executing job '0628-af7d-f342-0001', execution 0628-af9e-4718-0001
2021-05-09 15:33:54,442 [ INFO] [hz.peaceful_booth.cached.thread-5] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Start execution of job '0628-af7d-f342-0001', execution 0628-af9e-4718-0001 from coordinator [127.0.0.1]:5701
2021-05-09 15:33:54,461 [DEBUG] [hz.peaceful_booth.cached.thread-5] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] job '0628-af7d-f342-0001', execution 0628-af9e-4718-0001 snapshot is scheduled in 50ms
2021-05-09 15:33:54,534 [DEBUG] [hz.peaceful_booth.cached.thread-5] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Starting snapshot 222 for job '0628-af7d-f342-0001', execution 0628-af9e-4718-0001, flags: terminal=no,export=no, writing to: null
2021-05-09 15:33:54,534 [DEBUG] [hz.peaceful_booth.cached.thread-5] [c.h.j.i.e.ExecutionContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Starting snapshot 222 phase 1 for job '0628-af7d-f342-0001', execution 0628-af9e-4718-0001 on member
2021-05-09 15:33:54,534 [ INFO] [hz.peaceful_booth.cached.thread-5] [c.h.j.i.e.SnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Snapshot 222 for job '0628-af7d-f342-0001', execution 0628-af9e-4718-0001 is postponed until all higher priority vertices are completed (number of such vertices = 2)
2021-05-09 15:33:54,676 [ INFO] [hz.peaceful_booth.jet.cooperative.thread-62] [c.h.j.i.e.SnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Postponed snapshot 222 for job '0628-af7d-f342-0001', execution 0628-af9e-4718-0001 started
2021-05-09 15:33:54,677 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-2] [c.h.j.i.c.ConvenientSourceP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-af7d-f342-0001/src#0] src vertex restored from snapshot: 191
2021-05-09 15:33:54,677 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-2] [c.h.j.i.c.ConvenientSourceP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-af7d-f342-0001/src#0] src vertex saved to snapshot: 191
2021-05-09 15:33:54,678 [DEBUG] [hz.peaceful_booth.jet.cooperative.thread-63] [c.h.j.i.u.AsyncSnapshotWriterImpl]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Stats for src: keys=1, chunks=1, bytes=37
2021-05-09 15:33:54,683 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-1] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-af7d-f342-0001/filesSink(/tmp/write-file-p14527133490174925014)#0] creating /tmp/write-file-p14527133490174925014/0
2021-05-09 15:33:54,687 [DEBUG] [hz.peaceful_booth.jet.cooperative.thread-64] [c.h.j.i.u.AsyncSnapshotWriterImpl]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Stats for filesSink(/tmp/write-file-p14527133490174925014): keys=0, chunks=0, bytes=0
2021-05-09 15:33:54,687 [DEBUG] [hz.peaceful_booth.jet.cooperative.thread-64] [c.h.j.i.o.SnapshotPhase1Operation]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Snapshot 222 phase 1 for job '0628-af7d-f342-0001', execution 0628-af9e-4718-0001 finished successfully on member
2021-05-09 15:33:54,688 [DEBUG] [hz.peaceful_booth.cached.thread-57] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Snapshot 222 phase 1 for job '0628-af7d-f342-0001', execution 0628-af9e-4718-0001 completed with status SUCCESS in 174ms, 37 bytes, 1 keys in 1 chunks, stored in '__jet.snapshot.0628-af7d-f342-0001.0', proceeding to phase 2
2021-05-09 15:33:54,692 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-3] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-af7d-f342-0001/filesSink(/tmp/write-file-p14527133490174925014)#1] creating /tmp/write-file-p14527133490174925014/1
2021-05-09 15:33:54,710 [DEBUG] [hz.peaceful_booth.cached.thread-57] [c.h.j.i.JobRepository]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Cleared snapshot data map __jet.snapshot.0628-af7d-f342-0001.1
2021-05-09 15:33:54,710 [DEBUG] [hz.peaceful_booth.cached.thread-57] [c.h.j.i.e.ExecutionContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Starting snapshot 222 phase 2 for job '0628-af7d-f342-0001', execution 0628-af9e-4718-0001 on member
2021-05-09 15:33:54,714 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-2] [c.h.j.i.o.SnapshotPhase2Operation]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Snapshot 222 phase 2 for job '0628-af7d-f342-0001', execution 0628-af9e-4718-0001 finished successfully on member
2021-05-09 15:33:54,714 [DEBUG] [hz.peaceful_booth.cached.thread-5] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] job '0628-af7d-f342-0001', execution 0628-af9e-4718-0001 snapshot is scheduled in 50ms
2021-05-09 15:33:54,714 [DEBUG] [hz.peaceful_booth.cached.thread-5] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Snapshot 222 for job '0628-af7d-f342-0001', execution 0628-af9e-4718-0001 completed in 200ms, status=success
2021-05-09 15:33:54,773 [DEBUG] [hz.peaceful_booth.cached.thread-5] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Starting snapshot 223 for job '0628-af7d-f342-0001', execution 0628-af9e-4718-0001, flags: terminal=no,export=no, writing to: null
2021-05-09 15:33:54,773 [DEBUG] [hz.peaceful_booth.cached.thread-5] [c.h.j.i.e.ExecutionContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Starting snapshot 223 phase 1 for job '0628-af7d-f342-0001', execution 0628-af9e-4718-0001 on member
2021-05-09 15:33:54,779 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-2] [c.h.j.i.c.ConvenientSourceP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-af7d-f342-0001/src#0] src vertex saved to snapshot: 209
2021-05-09 15:33:54,779 [DEBUG] [hz.peaceful_booth.jet.cooperative.thread-63] [c.h.j.i.u.AsyncSnapshotWriterImpl]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Stats for src: keys=1, chunks=1, bytes=37
2021-05-09 15:33:54,779 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-1] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-af7d-f342-0001/filesSink(/tmp/write-file-p14527133490174925014)#0] flush File{0}
2021-05-09 15:33:54,779 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-3] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-af7d-f342-0001/filesSink(/tmp/write-file-p14527133490174925014)#1] flush File{1}
2021-05-09 15:33:54,802 [DEBUG] [hz.peaceful_booth.jet.cooperative.thread-64] [c.h.j.i.u.AsyncSnapshotWriterImpl]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Stats for filesSink(/tmp/write-file-p14527133490174925014): keys=0, chunks=0, bytes=0
2021-05-09 15:33:54,802 [DEBUG] [hz.peaceful_booth.jet.cooperative.thread-64] [c.h.j.i.o.SnapshotPhase1Operation]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Snapshot 223 phase 1 for job '0628-af7d-f342-0001', execution 0628-af9e-4718-0001 finished successfully on member
2021-05-09 15:33:54,807 [DEBUG] [hz.peaceful_booth.cached.thread-5] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Snapshot 223 phase 1 for job '0628-af7d-f342-0001', execution 0628-af9e-4718-0001 completed with status SUCCESS in 41ms, 37 bytes, 1 keys in 1 chunks, stored in '__jet.snapshot.0628-af7d-f342-0001.1', proceeding to phase 2
2021-05-09 15:33:54,809 [DEBUG] [hz.peaceful_booth.cached.thread-5] [c.h.j.i.JobRepository]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Cleared snapshot data map __jet.snapshot.0628-af7d-f342-0001.0
2021-05-09 15:33:54,809 [DEBUG] [hz.peaceful_booth.cached.thread-5] [c.h.j.i.e.ExecutionContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Starting snapshot 223 phase 2 for job '0628-af7d-f342-0001', execution 0628-af9e-4718-0001 on member
2021-05-09 15:33:54,813 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-2] [c.h.j.i.o.SnapshotPhase2Operation]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Snapshot 223 phase 2 for job '0628-af7d-f342-0001', execution 0628-af9e-4718-0001 finished successfully on member
2021-05-09 15:33:54,813 [DEBUG] [hz.peaceful_booth.cached.thread-5] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] job '0628-af7d-f342-0001', execution 0628-af9e-4718-0001 snapshot is scheduled in 50ms
2021-05-09 15:33:54,813 [DEBUG] [hz.peaceful_booth.cached.thread-5] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Snapshot 223 for job '0628-af7d-f342-0001', execution 0628-af9e-4718-0001 completed in 48ms, status=success
2021-05-09 15:33:54,834 [ INFO] [stressTest_atLeastOnce_forceful] [c.h.j.c.JetTestSupport]: Next snapshot found after 416 ms (id=223, previous id=221)
2021-05-09 15:33:54,835 [DEBUG] [stressTest_atLeastOnce_forceful] [c.h.j.Job]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Sending CANCEL_FORCEFUL request for job 0628-af7d-f342-0001 (name ??)
2021-05-09 15:33:54,867 [DEBUG] [hz.peaceful_booth.cached.thread-48] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Starting snapshot 224 for job '0628-af7d-f342-0001', execution 0628-af9e-4718-0001, flags: terminal=no,export=no, writing to: null
2021-05-09 15:33:54,867 [DEBUG] [hz.peaceful_booth.cached.thread-48] [c.h.j.i.e.ExecutionContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Starting snapshot 224 phase 1 for job '0628-af7d-f342-0001', execution 0628-af9e-4718-0001 on member
2021-05-09 15:33:54,867 [ERROR] [hz.peaceful_booth.cached.thread-48] [c.h.j.i.o.SnapshotPhase1Operation]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] null
java.util.concurrent.CancellationException: null
	at com.hazelcast.jet.impl.execution.ExecutionContext.beginSnapshotPhase1(ExecutionContext.java:253) ~[classes/:?]
	at com.hazelcast.jet.impl.operation.SnapshotPhase1Operation.doRun(SnapshotPhase1Operation.java:64) ~[classes/:?]
	at com.hazelcast.jet.impl.operation.AsyncOperation.run(AsyncOperation.java:53) ~[classes/:?]
	at com.hazelcast.spi.impl.operationservice.Operation.call(Operation.java:189) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.call(OperationRunnerImpl.java:272) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:248) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:213) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationexecutor.impl.OperationExecutorImpl.run(OperationExecutorImpl.java:411) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationexecutor.impl.OperationExecutorImpl.runOrExecute(OperationExecutorImpl.java:438) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.doInvokeLocal(Invocation.java:600) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.doInvoke(Invocation.java:579) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke0(Invocation.java:540) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke(Invocation.java:240) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.InvocationBuilderImpl.invoke(InvocationBuilderImpl.java:59) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.jet.impl.MasterContext.invokeOnParticipant(MasterContext.java:264) ~[classes/:?]
	at com.hazelcast.jet.impl.MasterContext.invokeOnParticipants(MasterContext.java:247) ~[classes/:?]
	at com.hazelcast.jet.impl.MasterSnapshotContext.lambda$tryBeginSnapshot$2(MasterSnapshotContext.java:173) ~[classes/:?]
	at com.hazelcast.jet.impl.JobCoordinationService.lambda$submitToCoordinatorThread$46(JobCoordinationService.java:1039) ~[classes/:?]
	at com.hazelcast.jet.impl.JobCoordinationService.lambda$submitToCoordinatorThread$47(JobCoordinationService.java:1060) ~[classes/:?]
	at com.hazelcast.internal.util.executor.CompletableFutureTask.run(CompletableFutureTask.java:64) [hazelcast-4.2.jar:4.2]
	at com.hazelcast.internal.util.executor.CachedExecutorServiceDelegate$Worker.run(CachedExecutorServiceDelegate.java:217) [hazelcast-4.2.jar:4.2]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630) [?:?]
	at java.lang.Thread.run(Thread.java:832) [?:?]
	at com.hazelcast.internal.util.executor.HazelcastManagedThread.executeRun(HazelcastManagedThread.java:76) [hazelcast-4.2.jar:4.2]
	at com.hazelcast.internal.util.executor.HazelcastManagedThread.run(HazelcastManagedThread.java:102) [hazelcast-4.2.jar:4.2]
2021-05-09 15:33:54,868 [DEBUG] [hz.peaceful_booth.cached.thread-5] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Snapshot 224 phase 1 for job '0628-af7d-f342-0001', execution 0628-af9e-4718-0001 completed with status FAILURE in 4ms, 0 bytes, 0 keys in 0 chunks, stored in '__jet.snapshot.0628-af7d-f342-0001.0', proceeding to phase 2
2021-05-09 15:33:54,868 [ WARN] [hz.peaceful_booth.cached.thread-5] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] job '0628-af7d-f342-0001', execution 0628-af9e-4718-0001 snapshot 224 phase 1 failed on some member(s), one of the failures: java.util.concurrent.CancellationException
2021-05-09 15:33:54,877 [DEBUG] [hz.peaceful_booth.jet.cooperative.thread-64] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Execution of job '0628-af7d-f342-0001', execution 0628-af9e-4718-0001 completed with failure
java.util.concurrent.CompletionException: com.hazelcast.jet.impl.exception.JobTerminateRequestedException: CANCEL_FORCEFUL
	at java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:331) ~[?:?]
	at java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:346) ~[?:?]
	at java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:632) ~[?:?]
	at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:506) ~[?:?]
	at java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:2152) ~[?:?]
	at com.hazelcast.jet.impl.util.NonCompletableFuture.internalCompleteExceptionally(NonCompletableFuture.java:59) ~[classes/:?]
	at com.hazelcast.jet.impl.execution.TaskletExecutionService$ExecutionTracker.taskletDone(TaskletExecutionService.java:468) ~[classes/:?]
	at com.hazelcast.jet.impl.execution.TaskletExecutionService$CooperativeWorker.dismissTasklet(TaskletExecutionService.java:399) ~[classes/:?]
	at com.hazelcast.jet.impl.execution.TaskletExecutionService$CooperativeWorker.runTasklet(TaskletExecutionService.java:385) ~[classes/:?]
	at java.util.concurrent.CopyOnWriteArrayList.forEach(CopyOnWriteArrayList.java:807) [?:?]
	at com.hazelcast.jet.impl.execution.TaskletExecutionService$CooperativeWorker.run(TaskletExecutionService.java:347) [classes/:?]
	at java.lang.Thread.run(Thread.java:832) [?:?]
Caused by: com.hazelcast.jet.impl.exception.JobTerminateRequestedException: CANCEL_FORCEFUL
	at com.hazelcast.jet.impl.execution.ExecutionContext.terminateExecution(ExecutionContext.java:235) ~[classes/:?]
	at com.hazelcast.jet.impl.operation.TerminateExecutionOperation.run(TerminateExecutionOperation.java:61) ~[classes/:?]
	at com.hazelcast.spi.impl.operationservice.Operation.call(Operation.java:189) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.call(OperationRunnerImpl.java:272) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:248) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:213) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationexecutor.impl.OperationExecutorImpl.run(OperationExecutorImpl.java:411) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationexecutor.impl.OperationExecutorImpl.runOrExecute(OperationExecutorImpl.java:438) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.doInvokeLocal(Invocation.java:600) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.doInvoke(Invocation.java:579) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke0(Invocation.java:540) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke(Invocation.java:240) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.InvocationBuilderImpl.invoke(InvocationBuilderImpl.java:59) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.jet.impl.MasterContext.invokeOnParticipant(MasterContext.java:264) ~[classes/:?]
	at com.hazelcast.jet.impl.MasterContext.invokeOnParticipants(MasterContext.java:247) ~[classes/:?]
	at com.hazelcast.jet.impl.MasterJobContext.lambda$cancelExecutionInvocations$16(MasterJobContext.java:601) ~[classes/:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130) ~[?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630) ~[?:?]
	at java.lang.Thread.run(Thread.java:832) ~[?:?]
	at com.hazelcast.internal.util.executor.HazelcastManagedThread.executeRun(HazelcastManagedThread.java:76) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.internal.util.executor.HazelcastManagedThread.run(HazelcastManagedThread.java:102) ~[hazelcast-4.2.jar:4.2]
2021-05-09 15:33:54,878 [DEBUG] [ForkJoinPool.commonPool-worker-239] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] job '0628-af7d-f342-0001', execution 0628-af9e-4718-0001 to be cancelled after Execution
2021-05-09 15:33:54,879 [DEBUG] [hz.peaceful_booth.cached.thread-57] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Sending CompleteExecutionOperation for job '0628-af7d-f342-0001', execution 0628-af9e-4718-0001
2021-05-09 15:33:54,879 [DEBUG] [hz.peaceful_booth.cached.thread-57] [c.h.j.i.o.CompleteExecutionOperation]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Completing execution 0628-af9e-4718-0001 from caller [127.0.0.1]:5701, error=java.util.concurrent.CancellationException
2021-05-09 15:33:54,879 [DEBUG] [hz.peaceful_booth.cached.thread-57] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-af7d-f342-0001/filesSink(/tmp/write-file-p14527133490174925014)#0] rollback File{0}
2021-05-09 15:33:54,879 [DEBUG] [hz.peaceful_booth.cached.thread-57] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-af7d-f342-0001/filesSink(/tmp/write-file-p14527133490174925014)#0] release File{0}
2021-05-09 15:33:54,879 [DEBUG] [hz.peaceful_booth.cached.thread-57] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-af7d-f342-0001/filesSink(/tmp/write-file-p14527133490174925014)#0] closing 0
2021-05-09 15:33:54,879 [DEBUG] [hz.peaceful_booth.cached.thread-57] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-af7d-f342-0001/filesSink(/tmp/write-file-p14527133490174925014)#1] rollback File{1}
2021-05-09 15:33:54,879 [DEBUG] [hz.peaceful_booth.cached.thread-57] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-af7d-f342-0001/filesSink(/tmp/write-file-p14527133490174925014)#1] release File{1}
2021-05-09 15:33:54,879 [DEBUG] [hz.peaceful_booth.cached.thread-57] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-af7d-f342-0001/filesSink(/tmp/write-file-p14527133490174925014)#1] closing 1
2021-05-09 15:33:54,879 [DEBUG] [hz.peaceful_booth.cached.thread-57] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Completed execution of job '0628-af7d-f342-0001', execution 0628-af9e-4718-0001
2021-05-09 15:33:54,886 [DEBUG] [hz.peaceful_booth.cached.thread-5] [c.h.j.i.JobRepository]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Cleared snapshot data map __jet.snapshot.0628-af7d-f342-0001.0
2021-05-09 15:33:54,886 [ERROR] [hz.peaceful_booth.cached.thread-5] [c.h.j.i.o.SnapshotPhase2Operation]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] job 0628-af7d-f342-0001, execution 0628-af9e-4718-0001 not found for coordinator [127.0.0.1]:5701 for 'SnapshotPhase2Operation'
com.hazelcast.jet.core.TopologyChangedException: job 0628-af7d-f342-0001, execution 0628-af9e-4718-0001 not found for coordinator [127.0.0.1]:5701 for 'SnapshotPhase2Operation'
	at com.hazelcast.jet.impl.JobExecutionService.assertExecutionContext(JobExecutionService.java:326) ~[classes/:?]
	at com.hazelcast.jet.impl.operation.SnapshotPhase2Operation.doRun(SnapshotPhase2Operation.java:50) ~[classes/:?]
	at com.hazelcast.jet.impl.operation.AsyncOperation.run(AsyncOperation.java:53) ~[classes/:?]
	at com.hazelcast.spi.impl.operationservice.Operation.call(Operation.java:189) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.call(OperationRunnerImpl.java:272) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:248) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:213) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationexecutor.impl.OperationExecutorImpl.run(OperationExecutorImpl.java:411) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationexecutor.impl.OperationExecutorImpl.runOrExecute(OperationExecutorImpl.java:438) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.doInvokeLocal(Invocation.java:600) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.doInvoke(Invocation.java:579) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke0(Invocation.java:540) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke(Invocation.java:240) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.InvocationBuilderImpl.invoke(InvocationBuilderImpl.java:59) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.jet.impl.MasterContext.invokeOnParticipant(MasterContext.java:264) ~[classes/:?]
	at com.hazelcast.jet.impl.MasterContext.invokeOnParticipants(MasterContext.java:247) ~[classes/:?]
	at com.hazelcast.jet.impl.MasterSnapshotContext.lambda$onSnapshotPhase1Complete$5(MasterSnapshotContext.java:277) ~[classes/:?]
	at com.hazelcast.jet.impl.JobCoordinationService.lambda$submitToCoordinatorThread$46(JobCoordinationService.java:1039) ~[classes/:?]
	at com.hazelcast.jet.impl.JobCoordinationService.lambda$submitToCoordinatorThread$47(JobCoordinationService.java:1060) ~[classes/:?]
	at com.hazelcast.internal.util.executor.CompletableFutureTask.run(CompletableFutureTask.java:64) [hazelcast-4.2.jar:4.2]
	at com.hazelcast.internal.util.executor.CachedExecutorServiceDelegate$Worker.run(CachedExecutorServiceDelegate.java:217) [hazelcast-4.2.jar:4.2]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630) [?:?]
	at java.lang.Thread.run(Thread.java:832) [?:?]
	at com.hazelcast.internal.util.executor.HazelcastManagedThread.executeRun(HazelcastManagedThread.java:76) [hazelcast-4.2.jar:4.2]
	at com.hazelcast.internal.util.executor.HazelcastManagedThread.run(HazelcastManagedThread.java:102) [hazelcast-4.2.jar:4.2]
2021-05-09 15:33:54,887 [ INFO] [hz.peaceful_booth.cached.thread-48] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Execution of job '0628-af7d-f342-0001', execution 0628-af9e-4718-0001 got terminated, reason=java.util.concurrent.CancellationException
	Start time: 2021-05-09T15:33:54.428
	Duration: 00:00:00.458
	To see additional job metrics enable JobConfig.storeMetricsAfterJobCompletion
2021-05-09 15:33:54,887 [DEBUG] [hz.peaceful_booth.cached.thread-48] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] job '0628-af7d-f342-0001', execution 0628-af9e-4718-0001 is completed
2021-05-09 15:33:54,888 [ WARN] [hz.peaceful_booth.cached.thread-57] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] SnapshotPhase2Operation for snapshot 224 in job '0628-af7d-f342-0001', execution 0628-af9e-4718-0001 failed on member: MemberInfo{address=[127.0.0.1]:5701, uuid=e576beac-64f2-440a-b59d-d2c173094e1f, liteMember=false, memberListJoinVersion=1}=com.hazelcast.jet.core.TopologyChangedException: job 0628-af7d-f342-0001, execution 0628-af9e-4718-0001 not found for coordinator [127.0.0.1]:5701 for 'SnapshotPhase2Operation'
com.hazelcast.jet.core.TopologyChangedException: job 0628-af7d-f342-0001, execution 0628-af9e-4718-0001 not found for coordinator [127.0.0.1]:5701 for 'SnapshotPhase2Operation'
	at com.hazelcast.jet.impl.JobExecutionService.assertExecutionContext(JobExecutionService.java:326) ~[classes/:?]
	at com.hazelcast.jet.impl.operation.SnapshotPhase2Operation.doRun(SnapshotPhase2Operation.java:50) ~[classes/:?]
	at com.hazelcast.jet.impl.operation.AsyncOperation.run(AsyncOperation.java:53) ~[classes/:?]
	at com.hazelcast.spi.impl.operationservice.Operation.call(Operation.java:189) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.call(OperationRunnerImpl.java:272) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:248) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:213) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationexecutor.impl.OperationExecutorImpl.run(OperationExecutorImpl.java:411) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationexecutor.impl.OperationExecutorImpl.runOrExecute(OperationExecutorImpl.java:438) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.doInvokeLocal(Invocation.java:600) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.doInvoke(Invocation.java:579) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke0(Invocation.java:540) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke(Invocation.java:240) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.InvocationBuilderImpl.invoke(InvocationBuilderImpl.java:59) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.jet.impl.MasterContext.invokeOnParticipant(MasterContext.java:264) ~[classes/:?]
	at com.hazelcast.jet.impl.MasterContext.invokeOnParticipants(MasterContext.java:247) ~[classes/:?]
	at com.hazelcast.jet.impl.MasterSnapshotContext.lambda$onSnapshotPhase1Complete$5(MasterSnapshotContext.java:277) ~[classes/:?]
	at com.hazelcast.jet.impl.JobCoordinationService.lambda$submitToCoordinatorThread$46(JobCoordinationService.java:1039) ~[classes/:?]
	at com.hazelcast.jet.impl.JobCoordinationService.lambda$submitToCoordinatorThread$47(JobCoordinationService.java:1060) ~[classes/:?]
	at com.hazelcast.internal.util.executor.CompletableFutureTask.run(CompletableFutureTask.java:64) [hazelcast-4.2.jar:4.2]
	at com.hazelcast.internal.util.executor.CachedExecutorServiceDelegate$Worker.run(CachedExecutorServiceDelegate.java:217) [hazelcast-4.2.jar:4.2]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630) [?:?]
	at java.lang.Thread.run(Thread.java:832) [?:?]
	at com.hazelcast.internal.util.executor.HazelcastManagedThread.executeRun(HazelcastManagedThread.java:76) [hazelcast-4.2.jar:4.2]
	at com.hazelcast.internal.util.executor.HazelcastManagedThread.run(HazelcastManagedThread.java:102) [hazelcast-4.2.jar:4.2]
2021-05-09 15:33:54,888 [DEBUG] [hz.peaceful_booth.cached.thread-57] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] job '0628-af7d-f342-0001', execution 0628-af9e-4718-0001 snapshot is scheduled in 50ms
2021-05-09 15:33:54,888 [DEBUG] [hz.peaceful_booth.cached.thread-57] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Snapshot 224 for job '0628-af7d-f342-0001', execution 0628-af9e-4718-0001 completed in 24ms, status=failure: java.util.concurrent.CancellationException
2021-05-09 15:33:54,888 [DEBUG] [hz.peaceful_booth.cached.thread-57] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Not beginning snapshot, job '0628-af7d-f342-0001', execution 0628-af9e-4718-0001 is not RUNNING, but FAILED
2021-05-09 15:33:55,728 [DEBUG] [hz.peaceful_booth.cached.thread-5] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Not beginning snapshot, job '0628-af7d-f342-0001', execution 0628-af9e-4718-0001 is not RUNNING, but FAILED
2021-05-09 15:33:55,777 [ INFO] [Time-limited test] [c.h.j.SimpleTestInClusterSupport]: Ditching 1 jobs in SimpleTestInClusterSupport.@After: [0628-af7d-f342-0001]
2021-05-09 15:33:55,777 [ INFO] [Time-limited test] [c.h.j.SimpleTestInClusterSupport]: Destroying 8 distributed objects in SimpleTestInClusterSupport.@After: [hz:impl:mapService/__jet.executionRecords, hz:impl:mapService/__jet.snapshot.0628-af7d-f342-0001.0, hz:impl:mapService/__jet.snapshot.0628-af7d-f342-0001.1, hz:impl:mapService/__jet.exportedSnapshotsCache, hz:impl:mapService/__jet.results, hz:impl:mapService/__jet.results.metrics, hz:impl:mapService/__jet.records, hz:impl:flakeIdGeneratorService/__jet.ids]
BuildInfo right after stressTest_atLeastOnce_forceful(com.hazelcast.jet.impl.connector.WriteFilePTest): BuildInfo{version='4.2', build='20210324', buildNumber=20210324, revision=405cfd1, enterprise=false, serializationVersion=1, jet=JetBuildInfo{version='4.5.1-SNAPSHOT', build='20210509', revision='32b32b4'}}
Hiccups measured while running test 'stressTest_atLeastOnce_forceful(com.hazelcast.jet.impl.connector.WriteFilePTest):'
15:32:50, accumulated pauses: 2871 ms, max pause: 67 ms, pauses over 1000 ms: 0
15:32:55, accumulated pauses: 3129 ms, max pause: 41 ms, pauses over 1000 ms: 0
15:33:00, accumulated pauses: 1995 ms, max pause: 127 ms, pauses over 1000 ms: 0
15:33:05, accumulated pauses: 508 ms, max pause: 4 ms, pauses over 1000 ms: 0
15:33:10, accumulated pauses: 1270 ms, max pause: 79 ms, pauses over 1000 ms: 0
15:33:15, accumulated pauses: 2527 ms, max pause: 75 ms, pauses over 1000 ms: 0
15:33:20, accumulated pauses: 1429 ms, max pause: 139 ms, pauses over 1000 ms: 0
15:33:25, accumulated pauses: 820 ms, max pause: 26 ms, pauses over 1000 ms: 0
15:33:30, accumulated pauses: 278 ms, max pause: 12 ms, pauses over 1000 ms: 0
15:33:35, accumulated pauses: 383 ms, max pause: 41 ms, pauses over 1000 ms: 0
15:33:40, accumulated pauses: 322 ms, max pause: 158 ms, pauses over 1000 ms: 0
15:33:45, accumulated pauses: 295 ms, max pause: 9 ms, pauses over 1000 ms: 0
15:33:50, accumulated pauses: 1342 ms, max pause: 834 ms, pauses over 1000 ms: 0
15:33:55, accumulated pauses: 3 ms, max pause: 0 ms, pauses over 1000 ms: 0

Standard output for stressTest_exactlyOnce_forceful:

Started Running Test: stressTest_exactlyOnce_forceful
2021-05-09 15:34:19,443 [DEBUG] [hz.peaceful_booth.cached.thread-25] [c.h.j.i.p.Planner]: Watermarks in the pipeline will be throttled to 1000
2021-05-09 15:34:19,444 [ INFO] [hz.peaceful_booth.cached.thread-25] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Starting job 0628-afbd-b4e2-0001 based on submit request
2021-05-09 15:34:19,445 [ INFO] [hz.peaceful_booth.cached.thread-25] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Didn't find any snapshot to restore for job '0628-afbd-b4e2-0001', execution 0628-afbd-b4e3-0001
2021-05-09 15:34:19,445 [ INFO] [hz.peaceful_booth.cached.thread-25] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Start executing job '0628-afbd-b4e2-0001', execution 0628-afbd-b4e3-0001, execution graph in DOT format:
digraph DAG {
	"src" [localParallelism=1];
	"filesSink(/tmp/write-file-p4865701519209436653)" [localParallelism=2];
	"src" -> "filesSink(/tmp/write-file-p4865701519209436653)" [queueSize=1024];
}
HINT: You can use graphviz or http://viz-js.com to visualize the printed graph.
2021-05-09 15:34:19,445 [DEBUG] [hz.peaceful_booth.cached.thread-25] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Building execution plan for job '0628-afbd-b4e2-0001', execution 0628-afbd-b4e3-0001
2021-05-09 15:34:19,446 [DEBUG] [hz.peaceful_booth.cached.thread-25] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Built execution plans for job '0628-afbd-b4e2-0001', execution 0628-afbd-b4e3-0001
2021-05-09 15:34:19,446 [DEBUG] [hz.peaceful_booth.cached.thread-25] [c.h.j.i.o.InitExecutionOperation]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Initializing execution plan for job 0628-afbd-b4e2-0001, execution 0628-afbd-b4e3-0001 from [127.0.0.1]:5701
2021-05-09 15:34:19,454 [ INFO] [hz.peaceful_booth.cached.thread-25] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Execution plan for jobId=0628-afbd-b4e2-0001, jobName='0628-afbd-b4e2-0001', executionId=0628-afbd-b4e3-0001 initialized
2021-05-09 15:34:19,455 [DEBUG] [hz.peaceful_booth.cached.thread-18] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Init of job '0628-afbd-b4e2-0001', execution 0628-afbd-b4e3-0001 was successful
2021-05-09 15:34:19,455 [DEBUG] [hz.peaceful_booth.cached.thread-18] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Executing job '0628-afbd-b4e2-0001', execution 0628-afbd-b4e3-0001
2021-05-09 15:34:19,455 [ INFO] [hz.peaceful_booth.cached.thread-18] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Start execution of job '0628-afbd-b4e2-0001', execution 0628-afbd-b4e3-0001 from coordinator [127.0.0.1]:5701
2021-05-09 15:34:19,463 [DEBUG] [hz.peaceful_booth.cached.thread-18] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] job '0628-afbd-b4e2-0001', execution 0628-afbd-b4e3-0001 snapshot is scheduled in 50ms
2021-05-09 15:34:19,475 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-2] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-afbd-b4e2-0001/filesSink(/tmp/write-file-p4865701519209436653)#0] aborting unfinished transactions
2021-05-09 15:34:19,475 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-2] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-afbd-b4e2-0001/filesSink(/tmp/write-file-p4865701519209436653)#0] begin File{0-0}
2021-05-09 15:34:19,475 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-2] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-afbd-b4e2-0001/filesSink(/tmp/write-file-p4865701519209436653)#0] creating /tmp/write-file-p4865701519209436653/0-0.tmp
2021-05-09 15:34:19,486 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-3] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-afbd-b4e2-0001/filesSink(/tmp/write-file-p4865701519209436653)#1] aborting unfinished transactions
2021-05-09 15:34:19,486 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-3] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-afbd-b4e2-0001/filesSink(/tmp/write-file-p4865701519209436653)#1] begin File{1-0}
2021-05-09 15:34:19,486 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-3] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-afbd-b4e2-0001/filesSink(/tmp/write-file-p4865701519209436653)#1] creating /tmp/write-file-p4865701519209436653/1-0.tmp
2021-05-09 15:34:19,529 [DEBUG] [hz.peaceful_booth.cached.thread-25] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Starting snapshot 0 for job '0628-afbd-b4e2-0001', execution 0628-afbd-b4e3-0001, flags: terminal=no,export=no, writing to: null
2021-05-09 15:34:19,530 [DEBUG] [hz.peaceful_booth.cached.thread-25] [c.h.j.i.e.ExecutionContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Starting snapshot 0 phase 1 for job '0628-afbd-b4e2-0001', execution 0628-afbd-b4e3-0001 on member
2021-05-09 15:34:19,532 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-1] [c.h.j.i.c.ConvenientSourceP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-afbd-b4e2-0001/src#0] src vertex saved to snapshot: 8
2021-05-09 15:34:19,535 [DEBUG] [hz.peaceful_booth.jet.cooperative.thread-18] [c.h.j.i.u.AsyncSnapshotWriterImpl]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Stats for src: keys=1, chunks=1, bytes=37
2021-05-09 15:34:19,535 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-3] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-afbd-b4e2-0001/filesSink(/tmp/write-file-p4865701519209436653)#1] endAndPrepare File{1-0}
2021-05-09 15:34:19,535 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-3] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-afbd-b4e2-0001/filesSink(/tmp/write-file-p4865701519209436653)#1] closing 1-0
2021-05-09 15:34:19,537 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-2] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-afbd-b4e2-0001/filesSink(/tmp/write-file-p4865701519209436653)#0] endAndPrepare File{0-0}
2021-05-09 15:34:19,537 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-2] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-afbd-b4e2-0001/filesSink(/tmp/write-file-p4865701519209436653)#0] closing 0-0
2021-05-09 15:34:19,540 [DEBUG] [hz.peaceful_booth.jet.cooperative.thread-19] [c.h.j.i.u.AsyncSnapshotWriterImpl]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Stats for filesSink(/tmp/write-file-p4865701519209436653): keys=2, chunks=2, bytes=100
2021-05-09 15:34:19,540 [DEBUG] [hz.peaceful_booth.jet.cooperative.thread-19] [c.h.j.i.o.SnapshotPhase1Operation]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Snapshot 0 phase 1 for job '0628-afbd-b4e2-0001', execution 0628-afbd-b4e3-0001 finished successfully on member
2021-05-09 15:34:19,545 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-2] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-afbd-b4e2-0001/filesSink(/tmp/write-file-p4865701519209436653)#0] begin File{0-1}
2021-05-09 15:34:19,545 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-2] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-afbd-b4e2-0001/filesSink(/tmp/write-file-p4865701519209436653)#0] creating /tmp/write-file-p4865701519209436653/0-1.tmp
2021-05-09 15:34:19,556 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-3] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-afbd-b4e2-0001/filesSink(/tmp/write-file-p4865701519209436653)#1] begin File{1-1}
2021-05-09 15:34:19,557 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-3] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-afbd-b4e2-0001/filesSink(/tmp/write-file-p4865701519209436653)#1] creating /tmp/write-file-p4865701519209436653/1-1.tmp
2021-05-09 15:34:19,557 [DEBUG] [hz.peaceful_booth.cached.thread-25] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Snapshot 0 phase 1 for job '0628-afbd-b4e2-0001', execution 0628-afbd-b4e3-0001 completed with status SUCCESS in 23ms, 137 bytes, 3 keys in 3 chunks, stored in '__jet.snapshot.0628-afbd-b4e2-0001.0', proceeding to phase 2
2021-05-09 15:34:19,570 [DEBUG] [hz.peaceful_booth.cached.thread-25] [c.h.j.i.JobRepository]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Cleared snapshot data map __jet.snapshot.0628-afbd-b4e2-0001.1
2021-05-09 15:34:19,570 [DEBUG] [hz.peaceful_booth.cached.thread-25] [c.h.j.i.e.ExecutionContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Starting snapshot 0 phase 2 for job '0628-afbd-b4e2-0001', execution 0628-afbd-b4e3-0001 on member
2021-05-09 15:34:19,572 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-2] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-afbd-b4e2-0001/filesSink(/tmp/write-file-p4865701519209436653)#0] commit File{0-0}
2021-05-09 15:34:19,572 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-2] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-afbd-b4e2-0001/filesSink(/tmp/write-file-p4865701519209436653)#0] release File{0-0}
2021-05-09 15:34:19,576 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-3] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-afbd-b4e2-0001/filesSink(/tmp/write-file-p4865701519209436653)#1] commit File{1-0}
2021-05-09 15:34:19,576 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-3] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-afbd-b4e2-0001/filesSink(/tmp/write-file-p4865701519209436653)#1] release File{1-0}
2021-05-09 15:34:19,576 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-3] [c.h.j.i.o.SnapshotPhase2Operation]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Snapshot 0 phase 2 for job '0628-afbd-b4e2-0001', execution 0628-afbd-b4e3-0001 finished successfully on member
2021-05-09 15:34:19,582 [DEBUG] [hz.peaceful_booth.cached.thread-25] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] job '0628-afbd-b4e2-0001', execution 0628-afbd-b4e3-0001 snapshot is scheduled in 50ms
2021-05-09 15:34:19,582 [DEBUG] [hz.peaceful_booth.cached.thread-25] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Snapshot 0 for job '0628-afbd-b4e2-0001', execution 0628-afbd-b4e3-0001 completed in 63ms, status=success
2021-05-09 15:34:19,644 [DEBUG] [hz.peaceful_booth.cached.thread-25] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Starting snapshot 1 for job '0628-afbd-b4e2-0001', execution 0628-afbd-b4e3-0001, flags: terminal=no,export=no, writing to: null
2021-05-09 15:34:19,644 [DEBUG] [hz.peaceful_booth.cached.thread-25] [c.h.j.i.e.ExecutionContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Starting snapshot 1 phase 1 for job '0628-afbd-b4e2-0001', execution 0628-afbd-b4e3-0001 on member
2021-05-09 15:34:19,646 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-1] [c.h.j.i.c.ConvenientSourceP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-afbd-b4e2-0001/src#0] src vertex saved to snapshot: 26
2021-05-09 15:34:19,648 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-2] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-afbd-b4e2-0001/filesSink(/tmp/write-file-p4865701519209436653)#0] endAndPrepare File{0-1}
2021-05-09 15:34:19,648 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-2] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-afbd-b4e2-0001/filesSink(/tmp/write-file-p4865701519209436653)#0] closing 0-1
2021-05-09 15:34:19,652 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-3] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-afbd-b4e2-0001/filesSink(/tmp/write-file-p4865701519209436653)#1] endAndPrepare File{1-1}
2021-05-09 15:34:19,652 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-3] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-afbd-b4e2-0001/filesSink(/tmp/write-file-p4865701519209436653)#1] closing 1-1
2021-05-09 15:34:19,653 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-2] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-afbd-b4e2-0001/filesSink(/tmp/write-file-p4865701519209436653)#0] begin File{0-2}
2021-05-09 15:34:19,653 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-2] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-afbd-b4e2-0001/filesSink(/tmp/write-file-p4865701519209436653)#0] creating /tmp/write-file-p4865701519209436653/0-2.tmp
2021-05-09 15:34:19,654 [DEBUG] [hz.peaceful_booth.jet.cooperative.thread-18] [c.h.j.i.u.AsyncSnapshotWriterImpl]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Stats for src: keys=1, chunks=1, bytes=37
2021-05-09 15:34:19,657 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-3] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-afbd-b4e2-0001/filesSink(/tmp/write-file-p4865701519209436653)#1] begin File{1-2}
2021-05-09 15:34:19,657 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-3] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-afbd-b4e2-0001/filesSink(/tmp/write-file-p4865701519209436653)#1] creating /tmp/write-file-p4865701519209436653/1-2.tmp
2021-05-09 15:34:19,658 [DEBUG] [hz.peaceful_booth.jet.cooperative.thread-19] [c.h.j.i.u.AsyncSnapshotWriterImpl]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Stats for filesSink(/tmp/write-file-p4865701519209436653): keys=2, chunks=2, bytes=100
2021-05-09 15:34:19,660 [DEBUG] [hz.peaceful_booth.jet.cooperative.thread-18] [c.h.j.i.o.SnapshotPhase1Operation]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Snapshot 1 phase 1 for job '0628-afbd-b4e2-0001', execution 0628-afbd-b4e3-0001 finished successfully on member
2021-05-09 15:34:19,661 [DEBUG] [hz.peaceful_booth.cached.thread-18] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Snapshot 1 phase 1 for job '0628-afbd-b4e2-0001', execution 0628-afbd-b4e3-0001 completed with status SUCCESS in 22ms, 137 bytes, 3 keys in 3 chunks, stored in '__jet.snapshot.0628-afbd-b4e2-0001.1', proceeding to phase 2
2021-05-09 15:34:19,672 [DEBUG] [hz.peaceful_booth.cached.thread-18] [c.h.j.i.JobRepository]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Cleared snapshot data map __jet.snapshot.0628-afbd-b4e2-0001.0
2021-05-09 15:34:19,672 [DEBUG] [hz.peaceful_booth.cached.thread-18] [c.h.j.i.e.ExecutionContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Starting snapshot 1 phase 2 for job '0628-afbd-b4e2-0001', execution 0628-afbd-b4e3-0001 on member
2021-05-09 15:34:19,673 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-2] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-afbd-b4e2-0001/filesSink(/tmp/write-file-p4865701519209436653)#0] commit File{0-1}
2021-05-09 15:34:19,673 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-2] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-afbd-b4e2-0001/filesSink(/tmp/write-file-p4865701519209436653)#0] release File{0-1}
2021-05-09 15:34:19,673 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-3] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-afbd-b4e2-0001/filesSink(/tmp/write-file-p4865701519209436653)#1] commit File{1-1}
2021-05-09 15:34:19,673 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-3] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-afbd-b4e2-0001/filesSink(/tmp/write-file-p4865701519209436653)#1] release File{1-1}
2021-05-09 15:34:19,673 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-3] [c.h.j.i.o.SnapshotPhase2Operation]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Snapshot 1 phase 2 for job '0628-afbd-b4e2-0001', execution 0628-afbd-b4e3-0001 finished successfully on member
2021-05-09 15:34:19,677 [DEBUG] [hz.peaceful_booth.cached.thread-18] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] job '0628-afbd-b4e2-0001', execution 0628-afbd-b4e3-0001 snapshot is scheduled in 50ms
2021-05-09 15:34:19,677 [DEBUG] [hz.peaceful_booth.cached.thread-18] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Snapshot 1 for job '0628-afbd-b4e2-0001', execution 0628-afbd-b4e3-0001 completed in 38ms, status=success
2021-05-09 15:34:19,705 [DEBUG] [hz.peaceful_booth.cached.thread-18] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Not beginning snapshot, job '0628-afbd-b4de-0001', execution 0628-afbd-b4df-0001 is not RUNNING, but COMPLETED
2021-05-09 15:34:19,735 [DEBUG] [hz.peaceful_booth.cached.thread-71] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Starting snapshot 2 for job '0628-afbd-b4e2-0001', execution 0628-afbd-b4e3-0001, flags: terminal=no,export=no, writing to: null
2021-05-09 15:34:19,736 [DEBUG] [hz.peaceful_booth.cached.thread-71] [c.h.j.i.e.ExecutionContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Starting snapshot 2 phase 1 for job '0628-afbd-b4e2-0001', execution 0628-afbd-b4e3-0001 on member
2021-05-09 15:34:19,739 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-1] [c.h.j.i.c.ConvenientSourceP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-afbd-b4e2-0001/src#0] src vertex saved to snapshot: 43
2021-05-09 15:34:19,740 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-3] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-afbd-b4e2-0001/filesSink(/tmp/write-file-p4865701519209436653)#1] endAndPrepare File{1-2}
2021-05-09 15:34:19,740 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-3] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-afbd-b4e2-0001/filesSink(/tmp/write-file-p4865701519209436653)#1] closing 1-2
2021-05-09 15:34:19,742 [DEBUG] [hz.peaceful_booth.jet.cooperative.thread-18] [c.h.j.i.u.AsyncSnapshotWriterImpl]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Stats for src: keys=1, chunks=1, bytes=37
2021-05-09 15:34:19,742 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-2] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-afbd-b4e2-0001/filesSink(/tmp/write-file-p4865701519209436653)#0] endAndPrepare File{0-2}
2021-05-09 15:34:19,742 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-2] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-afbd-b4e2-0001/filesSink(/tmp/write-file-p4865701519209436653)#0] closing 0-2
2021-05-09 15:34:19,745 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-3] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-afbd-b4e2-0001/filesSink(/tmp/write-file-p4865701519209436653)#1] begin File{1-3}
2021-05-09 15:34:19,745 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-3] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-afbd-b4e2-0001/filesSink(/tmp/write-file-p4865701519209436653)#1] creating /tmp/write-file-p4865701519209436653/1-3.tmp
2021-05-09 15:34:19,751 [DEBUG] [hz.peaceful_booth.jet.cooperative.thread-19] [c.h.j.i.u.AsyncSnapshotWriterImpl]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Stats for filesSink(/tmp/write-file-p4865701519209436653): keys=2, chunks=2, bytes=100
2021-05-09 15:34:19,753 [DEBUG] [hz.peaceful_booth.jet.cooperative.thread-19] [c.h.j.i.o.SnapshotPhase1Operation]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Snapshot 2 phase 1 for job '0628-afbd-b4e2-0001', execution 0628-afbd-b4e3-0001 finished successfully on member
2021-05-09 15:34:19,753 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-2] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-afbd-b4e2-0001/filesSink(/tmp/write-file-p4865701519209436653)#0] begin File{0-3}
2021-05-09 15:34:19,753 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-2] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-afbd-b4e2-0001/filesSink(/tmp/write-file-p4865701519209436653)#0] creating /tmp/write-file-p4865701519209436653/0-3.tmp
2021-05-09 15:34:19,756 [DEBUG] [hz.peaceful_booth.cached.thread-71] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Snapshot 2 phase 1 for job '0628-afbd-b4e2-0001', execution 0628-afbd-b4e3-0001 completed with status SUCCESS in 28ms, 137 bytes, 3 keys in 3 chunks, stored in '__jet.snapshot.0628-afbd-b4e2-0001.0', proceeding to phase 2
2021-05-09 15:34:19,758 [DEBUG] [stressTest_exactlyOnce_forceful] [c.h.j.Job]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Sending RESTART_FORCEFUL request for job 0628-afbd-b4e2-0001 (name ??)
2021-05-09 15:34:19,773 [DEBUG] [hz.peaceful_booth.cached.thread-71] [c.h.j.i.JobRepository]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Cleared snapshot data map __jet.snapshot.0628-afbd-b4e2-0001.1
2021-05-09 15:34:19,773 [DEBUG] [hz.peaceful_booth.cached.thread-71] [c.h.j.i.e.ExecutionContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Starting snapshot 2 phase 2 for job '0628-afbd-b4e2-0001', execution 0628-afbd-b4e3-0001 on member
2021-05-09 15:34:19,774 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-3] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-afbd-b4e2-0001/filesSink(/tmp/write-file-p4865701519209436653)#1] commit File{1-2}
2021-05-09 15:34:19,774 [DEBUG] [hz.peaceful_booth.async.thread-44] [c.h.j.i.o.SnapshotPhase2Operation]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Snapshot 2 phase 2 for job '0628-afbd-b4e2-0001', execution 0628-afbd-b4e3-0001 finished successfully on member
2021-05-09 15:34:19,774 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-3] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-afbd-b4e2-0001/filesSink(/tmp/write-file-p4865701519209436653)#1] release File{1-2}
2021-05-09 15:34:19,776 [DEBUG] [hz.peaceful_booth.cached.thread-25] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] job '0628-afbd-b4e2-0001', execution 0628-afbd-b4e3-0001 snapshot is scheduled in 50ms
2021-05-09 15:34:19,776 [DEBUG] [hz.peaceful_booth.cached.thread-25] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Snapshot 2 for job '0628-afbd-b4e2-0001', execution 0628-afbd-b4e3-0001 completed in 48ms, status=success
2021-05-09 15:34:19,780 [DEBUG] [hz.peaceful_booth.jet.cooperative.thread-18] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Execution of job '0628-afbd-b4e2-0001', execution 0628-afbd-b4e3-0001 completed with failure
java.util.concurrent.CompletionException: com.hazelcast.jet.impl.exception.JobTerminateRequestedException: RESTART_FORCEFUL
	at java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:331) ~[?:?]
	at java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:346) ~[?:?]
	at java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:632) ~[?:?]
	at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:506) ~[?:?]
	at java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:2152) ~[?:?]
	at com.hazelcast.jet.impl.util.NonCompletableFuture.internalCompleteExceptionally(NonCompletableFuture.java:59) ~[classes/:?]
	at com.hazelcast.jet.impl.execution.TaskletExecutionService$ExecutionTracker.taskletDone(TaskletExecutionService.java:468) ~[classes/:?]
	at com.hazelcast.jet.impl.execution.TaskletExecutionService$CooperativeWorker.dismissTasklet(TaskletExecutionService.java:399) ~[classes/:?]
	at com.hazelcast.jet.impl.execution.TaskletExecutionService$CooperativeWorker.runTasklet(TaskletExecutionService.java:385) ~[classes/:?]
	at java.util.concurrent.CopyOnWriteArrayList.forEach(CopyOnWriteArrayList.java:807) [?:?]
	at com.hazelcast.jet.impl.execution.TaskletExecutionService$CooperativeWorker.run(TaskletExecutionService.java:347) [classes/:?]
	at java.lang.Thread.run(Thread.java:832) [?:?]
Caused by: com.hazelcast.jet.impl.exception.JobTerminateRequestedException: RESTART_FORCEFUL
	at com.hazelcast.jet.impl.execution.ExecutionContext.terminateExecution(ExecutionContext.java:235) ~[classes/:?]
	at com.hazelcast.jet.impl.operation.TerminateExecutionOperation.run(TerminateExecutionOperation.java:61) ~[classes/:?]
	at com.hazelcast.spi.impl.operationservice.Operation.call(Operation.java:189) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.call(OperationRunnerImpl.java:272) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:248) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:213) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationexecutor.impl.OperationExecutorImpl.run(OperationExecutorImpl.java:411) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationexecutor.impl.OperationExecutorImpl.runOrExecute(OperationExecutorImpl.java:438) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.doInvokeLocal(Invocation.java:600) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.doInvoke(Invocation.java:579) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke0(Invocation.java:540) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke(Invocation.java:240) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.InvocationBuilderImpl.invoke(InvocationBuilderImpl.java:59) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.jet.impl.MasterContext.invokeOnParticipant(MasterContext.java:264) ~[classes/:?]
	at com.hazelcast.jet.impl.MasterContext.invokeOnParticipants(MasterContext.java:247) ~[classes/:?]
	at com.hazelcast.jet.impl.MasterJobContext.lambda$cancelExecutionInvocations$16(MasterJobContext.java:601) ~[classes/:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130) ~[?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630) ~[?:?]
	at java.lang.Thread.run(Thread.java:832) ~[?:?]
	at com.hazelcast.internal.util.executor.HazelcastManagedThread.executeRun(HazelcastManagedThread.java:76) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.internal.util.executor.HazelcastManagedThread.run(HazelcastManagedThread.java:102) ~[hazelcast-4.2.jar:4.2]
2021-05-09 15:34:19,782 [DEBUG] [ForkJoinPool.commonPool-worker-155] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Execution of job '0628-afbd-b4e2-0001', execution 0628-afbd-b4e3-0001 has failures: [[127.0.0.1]:5701=com.hazelcast.jet.impl.exception.JobTerminateRequestedException: RESTART_FORCEFUL]
2021-05-09 15:34:19,783 [DEBUG] [hz.peaceful_booth.cached.thread-25] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Sending CompleteExecutionOperation for job '0628-afbd-b4e2-0001', execution 0628-afbd-b4e3-0001
2021-05-09 15:34:19,783 [DEBUG] [hz.peaceful_booth.cached.thread-25] [c.h.j.i.o.CompleteExecutionOperation]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Completing execution 0628-afbd-b4e3-0001 from caller [127.0.0.1]:5701, error=com.hazelcast.jet.impl.exception.JobTerminateRequestedException: RESTART_FORCEFUL
2021-05-09 15:34:19,783 [DEBUG] [hz.peaceful_booth.cached.thread-25] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-afbd-b4e2-0001/filesSink(/tmp/write-file-p4865701519209436653)#0] rollback File{0-3}
2021-05-09 15:34:19,783 [DEBUG] [hz.peaceful_booth.cached.thread-25] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-afbd-b4e2-0001/filesSink(/tmp/write-file-p4865701519209436653)#0] release File{0-3}
2021-05-09 15:34:19,783 [DEBUG] [hz.peaceful_booth.cached.thread-25] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-afbd-b4e2-0001/filesSink(/tmp/write-file-p4865701519209436653)#0] release File{0-2}
2021-05-09 15:34:19,783 [DEBUG] [hz.peaceful_booth.cached.thread-25] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-afbd-b4e2-0001/filesSink(/tmp/write-file-p4865701519209436653)#1] rollback File{1-3}
2021-05-09 15:34:19,783 [DEBUG] [hz.peaceful_booth.cached.thread-25] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-afbd-b4e2-0001/filesSink(/tmp/write-file-p4865701519209436653)#1] release File{1-3}
2021-05-09 15:34:19,783 [DEBUG] [hz.peaceful_booth.cached.thread-25] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Completed execution of job '0628-afbd-b4e2-0001', execution 0628-afbd-b4e3-0001
2021-05-09 15:34:19,791 [ INFO] [hz.peaceful_booth.cached.thread-25] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] About to restore the state of job '0628-afbd-b4e2-0001', execution 0628-afbd-b4e4-0001 from snapshot 2, mapName = __jet.snapshot.0628-afbd-b4e2-0001.0
2021-05-09 15:34:19,792 [ INFO] [hz.peaceful_booth.cached.thread-25] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Start executing job '0628-afbd-b4e2-0001', execution 0628-afbd-b4e4-0001, execution graph in DOT format:
digraph DAG {
	"src" [localParallelism=1];
	"filesSink(/tmp/write-file-p4865701519209436653)" [localParallelism=2];
	"src" -> "filesSink(/tmp/write-file-p4865701519209436653)" [queueSize=1024];
}
HINT: You can use graphviz or http://viz-js.com to visualize the printed graph.
2021-05-09 15:34:19,792 [DEBUG] [hz.peaceful_booth.cached.thread-25] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Building execution plan for job '0628-afbd-b4e2-0001', execution 0628-afbd-b4e4-0001
2021-05-09 15:34:19,792 [DEBUG] [hz.peaceful_booth.cached.thread-25] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Built execution plans for job '0628-afbd-b4e2-0001', execution 0628-afbd-b4e4-0001
2021-05-09 15:34:19,793 [DEBUG] [hz.peaceful_booth.cached.thread-25] [c.h.j.i.o.InitExecutionOperation]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Initializing execution plan for job 0628-afbd-b4e2-0001, execution 0628-afbd-b4e4-0001 from [127.0.0.1]:5701
2021-05-09 15:34:19,796 [ INFO] [hz.peaceful_booth.cached.thread-25] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Execution plan for jobId=0628-afbd-b4e2-0001, jobName='0628-afbd-b4e2-0001', executionId=0628-afbd-b4e4-0001 initialized
2021-05-09 15:34:19,796 [DEBUG] [hz.peaceful_booth.cached.thread-25] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Init of job '0628-afbd-b4e2-0001', execution 0628-afbd-b4e4-0001 was successful
2021-05-09 15:34:19,796 [DEBUG] [hz.peaceful_booth.cached.thread-25] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Executing job '0628-afbd-b4e2-0001', execution 0628-afbd-b4e4-0001
2021-05-09 15:34:19,796 [ INFO] [hz.peaceful_booth.cached.thread-25] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Start execution of job '0628-afbd-b4e2-0001', execution 0628-afbd-b4e4-0001 from coordinator [127.0.0.1]:5701
2021-05-09 15:34:19,799 [DEBUG] [hz.peaceful_booth.cached.thread-25] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] job '0628-afbd-b4e2-0001', execution 0628-afbd-b4e4-0001 snapshot is scheduled in 50ms
2021-05-09 15:34:19,827 [DEBUG] [hz.peaceful_booth.cached.thread-3] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Not beginning snapshot since unexpected execution ID received for job '0628-afbd-b4e2-0001', execution 0628-afbd-b4e4-0001. Received execution ID: 0628-afbd-b4e3-0001
2021-05-09 15:34:19,874 [DEBUG] [hz.peaceful_booth.cached.thread-3] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Starting snapshot 3 for job '0628-afbd-b4e2-0001', execution 0628-afbd-b4e4-0001, flags: terminal=no,export=no, writing to: null
2021-05-09 15:34:19,874 [DEBUG] [hz.peaceful_booth.cached.thread-3] [c.h.j.i.e.ExecutionContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Starting snapshot 3 phase 1 for job '0628-afbd-b4e2-0001', execution 0628-afbd-b4e4-0001 on member
2021-05-09 15:34:19,874 [ INFO] [hz.peaceful_booth.cached.thread-3] [c.h.j.i.e.SnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Snapshot 3 for job '0628-afbd-b4e2-0001', execution 0628-afbd-b4e4-0001 is postponed until all higher priority vertices are completed (number of such vertices = 2)
2021-05-09 15:34:20,080 [DEBUG] [stressTest_exactlyOnce_forceful] [c.h.j.Job]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Sending RESTART_FORCEFUL request for job 0628-afbd-b4e2-0001 (name ??)
2021-05-09 15:34:20,084 [ WARN] [hz.peaceful_booth.async.thread-45] [c.h.j.i.o.SnapshotPhase1Operation]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Snapshot 3 phase 1 for job '0628-afbd-b4e2-0001', execution 0628-afbd-b4e4-0001 finished with an error on member: java.util.concurrent.CancellationException: execution cancelled
2021-05-09 15:34:20,085 [DEBUG] [hz.peaceful_booth.cached.thread-3] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Snapshot 3 phase 1 for job '0628-afbd-b4e2-0001', execution 0628-afbd-b4e4-0001 completed with status FAILURE in 226ms, 0 bytes, 0 keys in 0 chunks, stored in '__jet.snapshot.0628-afbd-b4e2-0001.1', proceeding to phase 2
2021-05-09 15:34:20,085 [ WARN] [hz.peaceful_booth.cached.thread-3] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] job '0628-afbd-b4e2-0001', execution 0628-afbd-b4e4-0001 snapshot 3 phase 1 failed on some member(s), one of the failures: java.util.concurrent.CancellationException: execution cancelled
2021-05-09 15:34:20,107 [DEBUG] [hz.peaceful_booth.cached.thread-3] [c.h.j.i.JobRepository]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Cleared snapshot data map __jet.snapshot.0628-afbd-b4e2-0001.1
2021-05-09 15:34:20,107 [DEBUG] [hz.peaceful_booth.cached.thread-3] [c.h.j.i.e.ExecutionContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Starting snapshot 3 phase 2 for job '0628-afbd-b4e2-0001', execution 0628-afbd-b4e4-0001 on member
2021-05-09 15:34:20,107 [ERROR] [hz.peaceful_booth.cached.thread-3] [c.h.j.i.o.SnapshotPhase2Operation]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] null
java.util.concurrent.CancellationException: null
	at com.hazelcast.jet.impl.execution.ExecutionContext.beginSnapshotPhase2(ExecutionContext.java:271) ~[classes/:?]
	at com.hazelcast.jet.impl.operation.SnapshotPhase2Operation.doRun(SnapshotPhase2Operation.java:54) ~[classes/:?]
	at com.hazelcast.jet.impl.operation.AsyncOperation.run(AsyncOperation.java:53) ~[classes/:?]
	at com.hazelcast.spi.impl.operationservice.Operation.call(Operation.java:189) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.call(OperationRunnerImpl.java:272) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:248) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:213) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationexecutor.impl.OperationExecutorImpl.run(OperationExecutorImpl.java:411) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationexecutor.impl.OperationExecutorImpl.runOrExecute(OperationExecutorImpl.java:438) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.doInvokeLocal(Invocation.java:600) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.doInvoke(Invocation.java:579) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke0(Invocation.java:540) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke(Invocation.java:240) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.InvocationBuilderImpl.invoke(InvocationBuilderImpl.java:59) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.jet.impl.MasterContext.invokeOnParticipant(MasterContext.java:264) ~[classes/:?]
	at com.hazelcast.jet.impl.MasterContext.invokeOnParticipants(MasterContext.java:247) ~[classes/:?]
	at com.hazelcast.jet.impl.MasterSnapshotContext.lambda$onSnapshotPhase1Complete$5(MasterSnapshotContext.java:277) ~[classes/:?]
	at com.hazelcast.jet.impl.JobCoordinationService.lambda$submitToCoordinatorThread$46(JobCoordinationService.java:1039) ~[classes/:?]
	at com.hazelcast.jet.impl.JobCoordinationService.lambda$submitToCoordinatorThread$47(JobCoordinationService.java:1060) ~[classes/:?]
	at com.hazelcast.internal.util.executor.CompletableFutureTask.run(CompletableFutureTask.java:64) [hazelcast-4.2.jar:4.2]
	at com.hazelcast.internal.util.executor.CachedExecutorServiceDelegate$Worker.run(CachedExecutorServiceDelegate.java:217) [hazelcast-4.2.jar:4.2]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630) [?:?]
	at java.lang.Thread.run(Thread.java:832) [?:?]
	at com.hazelcast.internal.util.executor.HazelcastManagedThread.executeRun(HazelcastManagedThread.java:76) [hazelcast-4.2.jar:4.2]
	at com.hazelcast.internal.util.executor.HazelcastManagedThread.run(HazelcastManagedThread.java:102) [hazelcast-4.2.jar:4.2]
2021-05-09 15:34:20,107 [ WARN] [hz.peaceful_booth.cached.thread-53] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] SnapshotPhase2Operation for snapshot 3 in job '0628-afbd-b4e2-0001', execution 0628-afbd-b4e4-0001 failed on member: MemberInfo{address=[127.0.0.1]:5701, uuid=e576beac-64f2-440a-b59d-d2c173094e1f, liteMember=false, memberListJoinVersion=1}=java.util.concurrent.CancellationException
java.util.concurrent.CancellationException: null
	at com.hazelcast.jet.impl.execution.ExecutionContext.beginSnapshotPhase2(ExecutionContext.java:271) ~[classes/:?]
	at com.hazelcast.jet.impl.operation.SnapshotPhase2Operation.doRun(SnapshotPhase2Operation.java:54) ~[classes/:?]
	at com.hazelcast.jet.impl.operation.AsyncOperation.run(AsyncOperation.java:53) ~[classes/:?]
	at com.hazelcast.spi.impl.operationservice.Operation.call(Operation.java:189) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.call(OperationRunnerImpl.java:272) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:248) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:213) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationexecutor.impl.OperationExecutorImpl.run(OperationExecutorImpl.java:411) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationexecutor.impl.OperationExecutorImpl.runOrExecute(OperationExecutorImpl.java:438) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.doInvokeLocal(Invocation.java:600) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.doInvoke(Invocation.java:579) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke0(Invocation.java:540) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke(Invocation.java:240) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.InvocationBuilderImpl.invoke(InvocationBuilderImpl.java:59) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.jet.impl.MasterContext.invokeOnParticipant(MasterContext.java:264) ~[classes/:?]
	at com.hazelcast.jet.impl.MasterContext.invokeOnParticipants(MasterContext.java:247) ~[classes/:?]
	at com.hazelcast.jet.impl.MasterSnapshotContext.lambda$onSnapshotPhase1Complete$5(MasterSnapshotContext.java:277) ~[classes/:?]
	at com.hazelcast.jet.impl.JobCoordinationService.lambda$submitToCoordinatorThread$46(JobCoordinationService.java:1039) ~[classes/:?]
	at com.hazelcast.jet.impl.JobCoordinationService.lambda$submitToCoordinatorThread$47(JobCoordinationService.java:1060) ~[classes/:?]
	at com.hazelcast.internal.util.executor.CompletableFutureTask.run(CompletableFutureTask.java:64) [hazelcast-4.2.jar:4.2]
	at com.hazelcast.internal.util.executor.CachedExecutorServiceDelegate$Worker.run(CachedExecutorServiceDelegate.java:217) [hazelcast-4.2.jar:4.2]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630) [?:?]
	at java.lang.Thread.run(Thread.java:832) [?:?]
	at com.hazelcast.internal.util.executor.HazelcastManagedThread.executeRun(HazelcastManagedThread.java:76) [hazelcast-4.2.jar:4.2]
	at com.hazelcast.internal.util.executor.HazelcastManagedThread.run(HazelcastManagedThread.java:102) [hazelcast-4.2.jar:4.2]
2021-05-09 15:34:20,108 [DEBUG] [hz.peaceful_booth.cached.thread-53] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] job '0628-afbd-b4e2-0001', execution 0628-afbd-b4e4-0001 snapshot is scheduled in 50ms
2021-05-09 15:34:20,108 [DEBUG] [hz.peaceful_booth.cached.thread-53] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Snapshot 3 for job '0628-afbd-b4e2-0001', execution 0628-afbd-b4e4-0001 completed in 249ms, status=failure: java.util.concurrent.CancellationException: execution cancelled
2021-05-09 15:34:20,164 [DEBUG] [hz.peaceful_booth.cached.thread-53] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Starting snapshot 4 for job '0628-afbd-b4e2-0001', execution 0628-afbd-b4e4-0001, flags: terminal=no,export=no, writing to: null
2021-05-09 15:34:20,164 [DEBUG] [hz.peaceful_booth.cached.thread-53] [c.h.j.i.e.ExecutionContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Starting snapshot 4 phase 1 for job '0628-afbd-b4e2-0001', execution 0628-afbd-b4e4-0001 on member
2021-05-09 15:34:20,164 [ERROR] [hz.peaceful_booth.cached.thread-53] [c.h.j.i.o.SnapshotPhase1Operation]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] null
java.util.concurrent.CancellationException: null
	at com.hazelcast.jet.impl.execution.ExecutionContext.beginSnapshotPhase1(ExecutionContext.java:253) ~[classes/:?]
	at com.hazelcast.jet.impl.operation.SnapshotPhase1Operation.doRun(SnapshotPhase1Operation.java:64) ~[classes/:?]
	at com.hazelcast.jet.impl.operation.AsyncOperation.run(AsyncOperation.java:53) ~[classes/:?]
	at com.hazelcast.spi.impl.operationservice.Operation.call(Operation.java:189) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.call(OperationRunnerImpl.java:272) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:248) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:213) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationexecutor.impl.OperationExecutorImpl.run(OperationExecutorImpl.java:411) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationexecutor.impl.OperationExecutorImpl.runOrExecute(OperationExecutorImpl.java:438) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.doInvokeLocal(Invocation.java:600) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.doInvoke(Invocation.java:579) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke0(Invocation.java:540) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke(Invocation.java:240) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.InvocationBuilderImpl.invoke(InvocationBuilderImpl.java:59) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.jet.impl.MasterContext.invokeOnParticipant(MasterContext.java:264) ~[classes/:?]
	at com.hazelcast.jet.impl.MasterContext.invokeOnParticipants(MasterContext.java:247) ~[classes/:?]
	at com.hazelcast.jet.impl.MasterSnapshotContext.lambda$tryBeginSnapshot$2(MasterSnapshotContext.java:173) ~[classes/:?]
	at com.hazelcast.jet.impl.JobCoordinationService.lambda$submitToCoordinatorThread$46(JobCoordinationService.java:1039) ~[classes/:?]
	at com.hazelcast.jet.impl.JobCoordinationService.lambda$submitToCoordinatorThread$47(JobCoordinationService.java:1060) ~[classes/:?]
	at com.hazelcast.internal.util.executor.CompletableFutureTask.run(CompletableFutureTask.java:64) [hazelcast-4.2.jar:4.2]
	at com.hazelcast.internal.util.executor.CachedExecutorServiceDelegate$Worker.run(CachedExecutorServiceDelegate.java:217) [hazelcast-4.2.jar:4.2]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630) [?:?]
	at java.lang.Thread.run(Thread.java:832) [?:?]
	at com.hazelcast.internal.util.executor.HazelcastManagedThread.executeRun(HazelcastManagedThread.java:76) [hazelcast-4.2.jar:4.2]
	at com.hazelcast.internal.util.executor.HazelcastManagedThread.run(HazelcastManagedThread.java:102) [hazelcast-4.2.jar:4.2]
2021-05-09 15:34:20,168 [DEBUG] [hz.peaceful_booth.cached.thread-16] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Snapshot 4 phase 1 for job '0628-afbd-b4e2-0001', execution 0628-afbd-b4e4-0001 completed with status FAILURE in 7ms, 0 bytes, 0 keys in 0 chunks, stored in '__jet.snapshot.0628-afbd-b4e2-0001.1', proceeding to phase 2
2021-05-09 15:34:20,168 [ WARN] [hz.peaceful_booth.cached.thread-16] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] job '0628-afbd-b4e2-0001', execution 0628-afbd-b4e4-0001 snapshot 4 phase 1 failed on some member(s), one of the failures: java.util.concurrent.CancellationException
2021-05-09 15:34:20,176 [DEBUG] [hz.peaceful_booth.cached.thread-16] [c.h.j.i.JobRepository]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Cleared snapshot data map __jet.snapshot.0628-afbd-b4e2-0001.1
2021-05-09 15:34:20,176 [DEBUG] [hz.peaceful_booth.cached.thread-16] [c.h.j.i.e.ExecutionContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Starting snapshot 4 phase 2 for job '0628-afbd-b4e2-0001', execution 0628-afbd-b4e4-0001 on member
2021-05-09 15:34:20,176 [ERROR] [hz.peaceful_booth.cached.thread-16] [c.h.j.i.o.SnapshotPhase2Operation]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] null
java.util.concurrent.CancellationException: null
	at com.hazelcast.jet.impl.execution.ExecutionContext.beginSnapshotPhase2(ExecutionContext.java:271) ~[classes/:?]
	at com.hazelcast.jet.impl.operation.SnapshotPhase2Operation.doRun(SnapshotPhase2Operation.java:54) ~[classes/:?]
	at com.hazelcast.jet.impl.operation.AsyncOperation.run(AsyncOperation.java:53) ~[classes/:?]
	at com.hazelcast.spi.impl.operationservice.Operation.call(Operation.java:189) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.call(OperationRunnerImpl.java:272) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:248) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:213) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationexecutor.impl.OperationExecutorImpl.run(OperationExecutorImpl.java:411) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationexecutor.impl.OperationExecutorImpl.runOrExecute(OperationExecutorImpl.java:438) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.doInvokeLocal(Invocation.java:600) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.doInvoke(Invocation.java:579) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke0(Invocation.java:540) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke(Invocation.java:240) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.InvocationBuilderImpl.invoke(InvocationBuilderImpl.java:59) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.jet.impl.MasterContext.invokeOnParticipant(MasterContext.java:264) ~[classes/:?]
	at com.hazelcast.jet.impl.MasterContext.invokeOnParticipants(MasterContext.java:247) ~[classes/:?]
	at com.hazelcast.jet.impl.MasterSnapshotContext.lambda$onSnapshotPhase1Complete$5(MasterSnapshotContext.java:277) ~[classes/:?]
	at com.hazelcast.jet.impl.JobCoordinationService.lambda$submitToCoordinatorThread$46(JobCoordinationService.java:1039) ~[classes/:?]
	at com.hazelcast.jet.impl.JobCoordinationService.lambda$submitToCoordinatorThread$47(JobCoordinationService.java:1060) ~[classes/:?]
	at com.hazelcast.internal.util.executor.CompletableFutureTask.run(CompletableFutureTask.java:64) [hazelcast-4.2.jar:4.2]
	at com.hazelcast.internal.util.executor.CachedExecutorServiceDelegate$Worker.run(CachedExecutorServiceDelegate.java:217) [hazelcast-4.2.jar:4.2]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630) [?:?]
	at java.lang.Thread.run(Thread.java:832) [?:?]
	at com.hazelcast.internal.util.executor.HazelcastManagedThread.executeRun(HazelcastManagedThread.java:76) [hazelcast-4.2.jar:4.2]
	at com.hazelcast.internal.util.executor.HazelcastManagedThread.run(HazelcastManagedThread.java:102) [hazelcast-4.2.jar:4.2]
2021-05-09 15:34:20,177 [ WARN] [hz.peaceful_booth.cached.thread-16] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] SnapshotPhase2Operation for snapshot 4 in job '0628-afbd-b4e2-0001', execution 0628-afbd-b4e4-0001 failed on member: MemberInfo{address=[127.0.0.1]:5701, uuid=e576beac-64f2-440a-b59d-d2c173094e1f, liteMember=false, memberListJoinVersion=1}=java.util.concurrent.CancellationException
java.util.concurrent.CancellationException: null
	at com.hazelcast.jet.impl.execution.ExecutionContext.beginSnapshotPhase2(ExecutionContext.java:271) ~[classes/:?]
	at com.hazelcast.jet.impl.operation.SnapshotPhase2Operation.doRun(SnapshotPhase2Operation.java:54) ~[classes/:?]
	at com.hazelcast.jet.impl.operation.AsyncOperation.run(AsyncOperation.java:53) ~[classes/:?]
	at com.hazelcast.spi.impl.operationservice.Operation.call(Operation.java:189) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.call(OperationRunnerImpl.java:272) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.im
...[truncated 3468924 chars]...
shot 214, mapName = __jet.snapshot.0628-afbd-b4e2-0001.1
2021-05-09 15:35:19,263 [ INFO] [hz.peaceful_booth.cached.thread-2] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Start executing job '0628-afbd-b4e2-0001', execution 0628-b006-5412-0001, execution graph in DOT format:
digraph DAG {
	"src" [localParallelism=1];
	"filesSink(/tmp/write-file-p4865701519209436653)" [localParallelism=2];
	"src" -> "filesSink(/tmp/write-file-p4865701519209436653)" [queueSize=1024];
}
HINT: You can use graphviz or http://viz-js.com to visualize the printed graph.
2021-05-09 15:35:19,263 [DEBUG] [hz.peaceful_booth.cached.thread-2] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Building execution plan for job '0628-afbd-b4e2-0001', execution 0628-b006-5412-0001
2021-05-09 15:35:19,263 [DEBUG] [hz.peaceful_booth.cached.thread-2] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Built execution plans for job '0628-afbd-b4e2-0001', execution 0628-b006-5412-0001
2021-05-09 15:35:19,264 [DEBUG] [hz.peaceful_booth.cached.thread-2] [c.h.j.i.o.InitExecutionOperation]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Initializing execution plan for job 0628-afbd-b4e2-0001, execution 0628-b006-5412-0001 from [127.0.0.1]:5701
2021-05-09 15:35:19,267 [ INFO] [hz.peaceful_booth.cached.thread-2] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Execution plan for jobId=0628-afbd-b4e2-0001, jobName='0628-afbd-b4e2-0001', executionId=0628-b006-5412-0001 initialized
2021-05-09 15:35:19,267 [DEBUG] [hz.peaceful_booth.cached.thread-48] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Init of job '0628-afbd-b4e2-0001', execution 0628-b006-5412-0001 was successful
2021-05-09 15:35:19,267 [DEBUG] [hz.peaceful_booth.cached.thread-48] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Executing job '0628-afbd-b4e2-0001', execution 0628-b006-5412-0001
2021-05-09 15:35:19,267 [ INFO] [hz.peaceful_booth.cached.thread-48] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Start execution of job '0628-afbd-b4e2-0001', execution 0628-b006-5412-0001 from coordinator [127.0.0.1]:5701
2021-05-09 15:35:19,271 [DEBUG] [hz.peaceful_booth.cached.thread-48] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] job '0628-afbd-b4e2-0001', execution 0628-b006-5412-0001 snapshot is scheduled in 50ms
2021-05-09 15:35:19,271 [DEBUG] [hz.peaceful_booth.cached.thread-64] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Not beginning snapshot since unexpected execution ID received for job '0628-afbd-b4e2-0001', execution 0628-b006-5412-0001. Received execution ID: 0628-b006-5411-0001
2021-05-09 15:35:19,362 [DEBUG] [hz.peaceful_booth.cached.thread-57] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Starting snapshot 233 for job '0628-afbd-b4e2-0001', execution 0628-b006-5412-0001, flags: terminal=no,export=no, writing to: null
2021-05-09 15:35:19,362 [DEBUG] [hz.peaceful_booth.cached.thread-57] [c.h.j.i.e.ExecutionContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Starting snapshot 233 phase 1 for job '0628-afbd-b4e2-0001', execution 0628-b006-5412-0001 on member
2021-05-09 15:35:19,362 [ INFO] [hz.peaceful_booth.cached.thread-57] [c.h.j.i.e.SnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Snapshot 233 for job '0628-afbd-b4e2-0001', execution 0628-b006-5412-0001 is postponed until all higher priority vertices are completed (number of such vertices = 2)
2021-05-09 15:35:19,466 [DEBUG] [stressTest_exactlyOnce_forceful] [c.h.j.Job]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Sending RESTART_FORCEFUL request for job 0628-afbd-b4e2-0001 (name ??)
2021-05-09 15:35:19,467 [ WARN] [hz.peaceful_booth.async.thread-11] [c.h.j.i.o.SnapshotPhase1Operation]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Snapshot 233 phase 1 for job '0628-afbd-b4e2-0001', execution 0628-b006-5412-0001 finished with an error on member: java.util.concurrent.CancellationException: execution cancelled
2021-05-09 15:35:19,469 [DEBUG] [hz.peaceful_booth.cached.thread-32] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Snapshot 233 phase 1 for job '0628-afbd-b4e2-0001', execution 0628-b006-5412-0001 completed with status FAILURE in 128ms, 0 bytes, 0 keys in 0 chunks, stored in '__jet.snapshot.0628-afbd-b4e2-0001.0', proceeding to phase 2
2021-05-09 15:35:19,469 [ WARN] [hz.peaceful_booth.cached.thread-32] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] job '0628-afbd-b4e2-0001', execution 0628-b006-5412-0001 snapshot 233 phase 1 failed on some member(s), one of the failures: java.util.concurrent.CancellationException: execution cancelled
2021-05-09 15:35:19,492 [DEBUG] [hz.peaceful_booth.jet.cooperative.thread-18] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Execution of job '0628-afbd-b4e2-0001', execution 0628-b006-5412-0001 completed with failure
java.util.concurrent.CompletionException: com.hazelcast.jet.impl.exception.JobTerminateRequestedException: RESTART_FORCEFUL
	at java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:331) ~[?:?]
	at java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:346) ~[?:?]
	at java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:632) ~[?:?]
	at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:506) ~[?:?]
	at java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:2152) ~[?:?]
	at com.hazelcast.jet.impl.util.NonCompletableFuture.internalCompleteExceptionally(NonCompletableFuture.java:59) ~[classes/:?]
	at com.hazelcast.jet.impl.execution.TaskletExecutionService$ExecutionTracker.taskletDone(TaskletExecutionService.java:468) ~[classes/:?]
	at com.hazelcast.jet.impl.execution.TaskletExecutionService$CooperativeWorker.dismissTasklet(TaskletExecutionService.java:399) ~[classes/:?]
	at com.hazelcast.jet.impl.execution.TaskletExecutionService$CooperativeWorker.runTasklet(TaskletExecutionService.java:385) ~[classes/:?]
	at java.util.concurrent.CopyOnWriteArrayList.forEach(CopyOnWriteArrayList.java:807) [?:?]
	at com.hazelcast.jet.impl.execution.TaskletExecutionService$CooperativeWorker.run(TaskletExecutionService.java:347) [classes/:?]
	at java.lang.Thread.run(Thread.java:832) [?:?]
Caused by: com.hazelcast.jet.impl.exception.JobTerminateRequestedException: RESTART_FORCEFUL
	at com.hazelcast.jet.impl.execution.ExecutionContext.terminateExecution(ExecutionContext.java:235) ~[classes/:?]
	at com.hazelcast.jet.impl.operation.TerminateExecutionOperation.run(TerminateExecutionOperation.java:61) ~[classes/:?]
	at com.hazelcast.spi.impl.operationservice.Operation.call(Operation.java:189) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.call(OperationRunnerImpl.java:272) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:248) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:213) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationexecutor.impl.OperationExecutorImpl.run(OperationExecutorImpl.java:411) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationexecutor.impl.OperationExecutorImpl.runOrExecute(OperationExecutorImpl.java:438) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.doInvokeLocal(Invocation.java:600) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.doInvoke(Invocation.java:579) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke0(Invocation.java:540) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke(Invocation.java:240) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.InvocationBuilderImpl.invoke(InvocationBuilderImpl.java:59) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.jet.impl.MasterContext.invokeOnParticipant(MasterContext.java:264) ~[classes/:?]
	at com.hazelcast.jet.impl.MasterContext.invokeOnParticipants(MasterContext.java:247) ~[classes/:?]
	at com.hazelcast.jet.impl.MasterJobContext.lambda$cancelExecutionInvocations$16(MasterJobContext.java:601) ~[classes/:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130) ~[?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630) ~[?:?]
	at java.lang.Thread.run(Thread.java:832) ~[?:?]
	at com.hazelcast.internal.util.executor.HazelcastManagedThread.executeRun(HazelcastManagedThread.java:76) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.internal.util.executor.HazelcastManagedThread.run(HazelcastManagedThread.java:102) ~[hazelcast-4.2.jar:4.2]
2021-05-09 15:35:19,492 [DEBUG] [ForkJoinPool.commonPool-worker-203] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Execution of job '0628-afbd-b4e2-0001', execution 0628-b006-5412-0001 has failures: [[127.0.0.1]:5701=com.hazelcast.jet.impl.exception.JobTerminateRequestedException: RESTART_FORCEFUL]
2021-05-09 15:35:19,493 [DEBUG] [hz.peaceful_booth.cached.thread-30] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Sending CompleteExecutionOperation for job '0628-afbd-b4e2-0001', execution 0628-b006-5412-0001
2021-05-09 15:35:19,493 [DEBUG] [hz.peaceful_booth.cached.thread-30] [c.h.j.i.o.CompleteExecutionOperation]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Completing execution 0628-b006-5412-0001 from caller [127.0.0.1]:5701, error=com.hazelcast.jet.impl.exception.JobTerminateRequestedException: RESTART_FORCEFUL
2021-05-09 15:35:19,493 [DEBUG] [hz.peaceful_booth.cached.thread-30] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Completed execution of job '0628-afbd-b4e2-0001', execution 0628-b006-5412-0001
2021-05-09 15:35:19,495 [DEBUG] [hz.peaceful_booth.cached.thread-32] [c.h.j.i.JobRepository]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Cleared snapshot data map __jet.snapshot.0628-afbd-b4e2-0001.0
2021-05-09 15:35:19,495 [ERROR] [hz.peaceful_booth.cached.thread-32] [c.h.j.i.o.SnapshotPhase2Operation]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] job 0628-afbd-b4e2-0001, execution 0628-b006-5412-0001 not found for coordinator [127.0.0.1]:5701 for 'SnapshotPhase2Operation'
com.hazelcast.jet.core.TopologyChangedException: job 0628-afbd-b4e2-0001, execution 0628-b006-5412-0001 not found for coordinator [127.0.0.1]:5701 for 'SnapshotPhase2Operation'
	at com.hazelcast.jet.impl.JobExecutionService.assertExecutionContext(JobExecutionService.java:326) ~[classes/:?]
	at com.hazelcast.jet.impl.operation.SnapshotPhase2Operation.doRun(SnapshotPhase2Operation.java:50) ~[classes/:?]
	at com.hazelcast.jet.impl.operation.AsyncOperation.run(AsyncOperation.java:53) ~[classes/:?]
	at com.hazelcast.spi.impl.operationservice.Operation.call(Operation.java:189) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.call(OperationRunnerImpl.java:272) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:248) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:213) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationexecutor.impl.OperationExecutorImpl.run(OperationExecutorImpl.java:411) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationexecutor.impl.OperationExecutorImpl.runOrExecute(OperationExecutorImpl.java:438) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.doInvokeLocal(Invocation.java:600) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.doInvoke(Invocation.java:579) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke0(Invocation.java:540) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke(Invocation.java:240) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.InvocationBuilderImpl.invoke(InvocationBuilderImpl.java:59) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.jet.impl.MasterContext.invokeOnParticipant(MasterContext.java:264) ~[classes/:?]
	at com.hazelcast.jet.impl.MasterContext.invokeOnParticipants(MasterContext.java:247) ~[classes/:?]
	at com.hazelcast.jet.impl.MasterSnapshotContext.lambda$onSnapshotPhase1Complete$5(MasterSnapshotContext.java:277) ~[classes/:?]
	at com.hazelcast.jet.impl.JobCoordinationService.lambda$submitToCoordinatorThread$46(JobCoordinationService.java:1039) ~[classes/:?]
	at com.hazelcast.jet.impl.JobCoordinationService.lambda$submitToCoordinatorThread$47(JobCoordinationService.java:1060) ~[classes/:?]
	at com.hazelcast.internal.util.executor.CompletableFutureTask.run(CompletableFutureTask.java:64) [hazelcast-4.2.jar:4.2]
	at com.hazelcast.internal.util.executor.CachedExecutorServiceDelegate$Worker.run(CachedExecutorServiceDelegate.java:217) [hazelcast-4.2.jar:4.2]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630) [?:?]
	at java.lang.Thread.run(Thread.java:832) [?:?]
	at com.hazelcast.internal.util.executor.HazelcastManagedThread.executeRun(HazelcastManagedThread.java:76) [hazelcast-4.2.jar:4.2]
	at com.hazelcast.internal.util.executor.HazelcastManagedThread.run(HazelcastManagedThread.java:102) [hazelcast-4.2.jar:4.2]
2021-05-09 15:35:19,497 [ WARN] [hz.peaceful_booth.cached.thread-39] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] SnapshotPhase2Operation for snapshot 233 in job '0628-afbd-b4e2-0001', execution 0628-b006-5412-0001 failed on member: MemberInfo{address=[127.0.0.1]:5701, uuid=e576beac-64f2-440a-b59d-d2c173094e1f, liteMember=false, memberListJoinVersion=1}=com.hazelcast.jet.core.TopologyChangedException: job 0628-afbd-b4e2-0001, execution 0628-b006-5412-0001 not found for coordinator [127.0.0.1]:5701 for 'SnapshotPhase2Operation'
com.hazelcast.jet.core.TopologyChangedException: job 0628-afbd-b4e2-0001, execution 0628-b006-5412-0001 not found for coordinator [127.0.0.1]:5701 for 'SnapshotPhase2Operation'
	at com.hazelcast.jet.impl.JobExecutionService.assertExecutionContext(JobExecutionService.java:326) ~[classes/:?]
	at com.hazelcast.jet.impl.operation.SnapshotPhase2Operation.doRun(SnapshotPhase2Operation.java:50) ~[classes/:?]
	at com.hazelcast.jet.impl.operation.AsyncOperation.run(AsyncOperation.java:53) ~[classes/:?]
	at com.hazelcast.spi.impl.operationservice.Operation.call(Operation.java:189) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.call(OperationRunnerImpl.java:272) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:248) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:213) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationexecutor.impl.OperationExecutorImpl.run(OperationExecutorImpl.java:411) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationexecutor.impl.OperationExecutorImpl.runOrExecute(OperationExecutorImpl.java:438) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.doInvokeLocal(Invocation.java:600) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.doInvoke(Invocation.java:579) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke0(Invocation.java:540) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke(Invocation.java:240) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.InvocationBuilderImpl.invoke(InvocationBuilderImpl.java:59) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.jet.impl.MasterContext.invokeOnParticipant(MasterContext.java:264) ~[classes/:?]
	at com.hazelcast.jet.impl.MasterContext.invokeOnParticipants(MasterContext.java:247) ~[classes/:?]
	at com.hazelcast.jet.impl.MasterSnapshotContext.lambda$onSnapshotPhase1Complete$5(MasterSnapshotContext.java:277) ~[classes/:?]
	at com.hazelcast.jet.impl.JobCoordinationService.lambda$submitToCoordinatorThread$46(JobCoordinationService.java:1039) ~[classes/:?]
	at com.hazelcast.jet.impl.JobCoordinationService.lambda$submitToCoordinatorThread$47(JobCoordinationService.java:1060) ~[classes/:?]
	at com.hazelcast.internal.util.executor.CompletableFutureTask.run(CompletableFutureTask.java:64) [hazelcast-4.2.jar:4.2]
	at com.hazelcast.internal.util.executor.CachedExecutorServiceDelegate$Worker.run(CachedExecutorServiceDelegate.java:217) [hazelcast-4.2.jar:4.2]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630) [?:?]
	at java.lang.Thread.run(Thread.java:832) [?:?]
	at com.hazelcast.internal.util.executor.HazelcastManagedThread.executeRun(HazelcastManagedThread.java:76) [hazelcast-4.2.jar:4.2]
	at com.hazelcast.internal.util.executor.HazelcastManagedThread.run(HazelcastManagedThread.java:102) [hazelcast-4.2.jar:4.2]
2021-05-09 15:35:19,497 [DEBUG] [hz.peaceful_booth.cached.thread-39] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] job '0628-afbd-b4e2-0001', execution 0628-b006-5412-0001 snapshot is scheduled in 50ms
2021-05-09 15:35:19,497 [DEBUG] [hz.peaceful_booth.cached.thread-39] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Snapshot 233 for job '0628-afbd-b4e2-0001', execution 0628-b006-5412-0001 completed in 156ms, status=failure: java.util.concurrent.CancellationException: execution cancelled
2021-05-09 15:35:19,556 [ INFO] [hz.peaceful_booth.cached.thread-57] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] About to restore the state of job '0628-afbd-b4e2-0001', execution 0628-b006-5413-0001 from snapshot 214, mapName = __jet.snapshot.0628-afbd-b4e2-0001.1
2021-05-09 15:35:19,556 [ INFO] [hz.peaceful_booth.cached.thread-57] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Start executing job '0628-afbd-b4e2-0001', execution 0628-b006-5413-0001, execution graph in DOT format:
digraph DAG {
	"src" [localParallelism=1];
	"filesSink(/tmp/write-file-p4865701519209436653)" [localParallelism=2];
	"src" -> "filesSink(/tmp/write-file-p4865701519209436653)" [queueSize=1024];
}
HINT: You can use graphviz or http://viz-js.com to visualize the printed graph.
2021-05-09 15:35:19,556 [DEBUG] [hz.peaceful_booth.cached.thread-57] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Building execution plan for job '0628-afbd-b4e2-0001', execution 0628-b006-5413-0001
2021-05-09 15:35:19,556 [DEBUG] [hz.peaceful_booth.cached.thread-57] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Built execution plans for job '0628-afbd-b4e2-0001', execution 0628-b006-5413-0001
2021-05-09 15:35:19,557 [DEBUG] [hz.peaceful_booth.cached.thread-57] [c.h.j.i.o.InitExecutionOperation]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Initializing execution plan for job 0628-afbd-b4e2-0001, execution 0628-b006-5413-0001 from [127.0.0.1]:5701
2021-05-09 15:35:19,564 [DEBUG] [hz.peaceful_booth.cached.thread-39] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Not beginning snapshot, job '0628-afbd-b4e2-0001', execution 0628-b006-5413-0001 is not RUNNING, but STARTING
2021-05-09 15:35:19,572 [ INFO] [hz.peaceful_booth.cached.thread-57] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Execution plan for jobId=0628-afbd-b4e2-0001, jobName='0628-afbd-b4e2-0001', executionId=0628-b006-5413-0001 initialized
2021-05-09 15:35:19,572 [DEBUG] [hz.peaceful_booth.cached.thread-32] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Init of job '0628-afbd-b4e2-0001', execution 0628-b006-5413-0001 was successful
2021-05-09 15:35:19,572 [DEBUG] [hz.peaceful_booth.cached.thread-32] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Executing job '0628-afbd-b4e2-0001', execution 0628-b006-5413-0001
2021-05-09 15:35:19,572 [ INFO] [hz.peaceful_booth.cached.thread-32] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Start execution of job '0628-afbd-b4e2-0001', execution 0628-b006-5413-0001 from coordinator [127.0.0.1]:5701
2021-05-09 15:35:19,576 [DEBUG] [hz.peaceful_booth.cached.thread-32] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] job '0628-afbd-b4e2-0001', execution 0628-b006-5413-0001 snapshot is scheduled in 50ms
2021-05-09 15:35:19,646 [DEBUG] [hz.peaceful_booth.cached.thread-50] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Starting snapshot 234 for job '0628-afbd-b4e2-0001', execution 0628-b006-5413-0001, flags: terminal=no,export=no, writing to: null
2021-05-09 15:35:19,646 [DEBUG] [hz.peaceful_booth.cached.thread-50] [c.h.j.i.e.ExecutionContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Starting snapshot 234 phase 1 for job '0628-afbd-b4e2-0001', execution 0628-b006-5413-0001 on member
2021-05-09 15:35:19,646 [ INFO] [hz.peaceful_booth.cached.thread-50] [c.h.j.i.e.SnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Snapshot 234 for job '0628-afbd-b4e2-0001', execution 0628-b006-5413-0001 is postponed until all higher priority vertices are completed (number of such vertices = 2)
2021-05-09 15:35:19,657 [DEBUG] [hz.peaceful_booth.cached.thread-2] [c.h.j.i.JobRepository]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Job cleanup took 10ms
2021-05-09 15:35:19,805 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-1] [c.h.j.i.c.ConvenientSourceP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-afbd-b4e2-0001/src#0] src vertex restored from snapshot: 279
2021-05-09 15:35:19,809 [ INFO] [hz.peaceful_booth.jet.cooperative.thread-1] [c.h.j.i.e.SnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Postponed snapshot 234 for job '0628-afbd-b4e2-0001', execution 0628-b006-5413-0001 started
2021-05-09 15:35:19,812 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-1] [c.h.j.i.c.ConvenientSourceP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-afbd-b4e2-0001/src#0] src vertex saved to snapshot: 280
2021-05-09 15:35:19,814 [DEBUG] [hz.peaceful_booth.jet.cooperative.thread-2] [c.h.j.i.u.AsyncSnapshotWriterImpl]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Stats for src: keys=1, chunks=1, bytes=37
2021-05-09 15:35:19,814 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-2] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-afbd-b4e2-0001/filesSink(/tmp/write-file-p4865701519209436653)#0] aborting unfinished transactions
2021-05-09 15:35:19,814 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-2] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-afbd-b4e2-0001/filesSink(/tmp/write-file-p4865701519209436653)#0] deleting /tmp/write-file-p4865701519209436653/0-34.tmp
2021-05-09 15:35:19,815 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-2] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-afbd-b4e2-0001/filesSink(/tmp/write-file-p4865701519209436653)#0] begin File{0-34}
2021-05-09 15:35:19,815 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-2] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-afbd-b4e2-0001/filesSink(/tmp/write-file-p4865701519209436653)#0] creating /tmp/write-file-p4865701519209436653/0-34.tmp
2021-05-09 15:35:19,815 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-2] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-afbd-b4e2-0001/filesSink(/tmp/write-file-p4865701519209436653)#0] endAndPrepare File{0-34}
2021-05-09 15:35:19,815 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-2] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-afbd-b4e2-0001/filesSink(/tmp/write-file-p4865701519209436653)#0] closing 0-34
2021-05-09 15:35:19,817 [DEBUG] [hz.peaceful_booth.jet.cooperative.thread-3] [c.h.j.i.u.AsyncSnapshotWriterImpl]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Stats for filesSink(/tmp/write-file-p4865701519209436653): keys=1, chunks=1, bytes=51
2021-05-09 15:35:19,818 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-3] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-afbd-b4e2-0001/filesSink(/tmp/write-file-p4865701519209436653)#1] aborting unfinished transactions
2021-05-09 15:35:19,819 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-3] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-afbd-b4e2-0001/filesSink(/tmp/write-file-p4865701519209436653)#1] begin File{1-23}
2021-05-09 15:35:19,819 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-3] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-afbd-b4e2-0001/filesSink(/tmp/write-file-p4865701519209436653)#1] creating /tmp/write-file-p4865701519209436653/1-23.tmp
2021-05-09 15:35:19,820 [DEBUG] [hz.peaceful_booth.jet.cooperative.thread-3] [c.h.j.i.o.SnapshotPhase1Operation]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Snapshot 234 phase 1 for job '0628-afbd-b4e2-0001', execution 0628-b006-5413-0001 finished successfully on member
2021-05-09 15:35:19,826 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-2] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-afbd-b4e2-0001/filesSink(/tmp/write-file-p4865701519209436653)#0] begin File{0-35}
2021-05-09 15:35:19,826 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-2] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-afbd-b4e2-0001/filesSink(/tmp/write-file-p4865701519209436653)#0] creating /tmp/write-file-p4865701519209436653/0-35.tmp
2021-05-09 15:35:19,845 [DEBUG] [hz.peaceful_booth.cached.thread-60] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Snapshot 234 phase 1 for job '0628-afbd-b4e2-0001', execution 0628-b006-5413-0001 completed with status SUCCESS in 197ms, 88 bytes, 2 keys in 2 chunks, stored in '__jet.snapshot.0628-afbd-b4e2-0001.0', proceeding to phase 2
2021-05-09 15:35:19,849 [DEBUG] [hz.peaceful_booth.cached.thread-60] [c.h.j.i.JobRepository]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Cleared snapshot data map __jet.snapshot.0628-afbd-b4e2-0001.1
2021-05-09 15:35:19,849 [DEBUG] [hz.peaceful_booth.cached.thread-60] [c.h.j.i.e.ExecutionContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Starting snapshot 234 phase 2 for job '0628-afbd-b4e2-0001', execution 0628-b006-5413-0001 on member
2021-05-09 15:35:19,850 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-2] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-afbd-b4e2-0001/filesSink(/tmp/write-file-p4865701519209436653)#0] commit File{0-34}
2021-05-09 15:35:19,850 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-2] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-afbd-b4e2-0001/filesSink(/tmp/write-file-p4865701519209436653)#0] release File{0-34}
2021-05-09 15:35:19,850 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-2] [c.h.j.i.o.SnapshotPhase2Operation]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Snapshot 234 phase 2 for job '0628-afbd-b4e2-0001', execution 0628-b006-5413-0001 finished successfully on member
2021-05-09 15:35:19,851 [DEBUG] [hz.peaceful_booth.cached.thread-60] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] job '0628-afbd-b4e2-0001', execution 0628-b006-5413-0001 snapshot is scheduled in 50ms
2021-05-09 15:35:19,851 [DEBUG] [hz.peaceful_booth.cached.thread-60] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Snapshot 234 for job '0628-afbd-b4e2-0001', execution 0628-b006-5413-0001 completed in 216ms, status=success
2021-05-09 15:35:19,900 [ INFO] [stressTest_exactlyOnce_forceful] [c.h.j.c.JetTestSupport]: Next snapshot found after 426 ms (id=234, previous id=214)
2021-05-09 15:35:19,907 [DEBUG] [stressTest_exactlyOnce_forceful] [c.h.j.Job]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Sending CANCEL_FORCEFUL request for job 0628-afbd-b4e2-0001 (name ??)
2021-05-09 15:35:19,909 [DEBUG] [hz.peaceful_booth.jet.blocking.thread-3] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Execution of job '0628-afbd-b4e2-0001', execution 0628-b006-5413-0001 completed with failure
java.util.concurrent.CompletionException: com.hazelcast.jet.impl.exception.JobTerminateRequestedException: CANCEL_FORCEFUL
	at java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:331) ~[?:?]
	at java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:346) ~[?:?]
	at java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:632) ~[?:?]
	at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:506) [?:?]
	at java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:2152) [?:?]
	at com.hazelcast.jet.impl.util.NonCompletableFuture.internalCompleteExceptionally(NonCompletableFuture.java:59) [classes/:?]
	at com.hazelcast.jet.impl.execution.TaskletExecutionService$ExecutionTracker.taskletDone(TaskletExecutionService.java:468) [classes/:?]
	at com.hazelcast.jet.impl.execution.TaskletExecutionService$BlockingWorker.run(TaskletExecutionService.java:310) [classes/:?]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [?:?]
	at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630) [?:?]
	at java.lang.Thread.run(Thread.java:832) [?:?]
Caused by: com.hazelcast.jet.impl.exception.JobTerminateRequestedException: CANCEL_FORCEFUL
	at com.hazelcast.jet.impl.execution.ExecutionContext.terminateExecution(ExecutionContext.java:235) ~[classes/:?]
	at com.hazelcast.jet.impl.operation.TerminateExecutionOperation.run(TerminateExecutionOperation.java:61) ~[classes/:?]
	at com.hazelcast.spi.impl.operationservice.Operation.call(Operation.java:189) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.call(OperationRunnerImpl.java:272) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:248) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:213) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationexecutor.impl.OperationExecutorImpl.run(OperationExecutorImpl.java:411) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationexecutor.impl.OperationExecutorImpl.runOrExecute(OperationExecutorImpl.java:438) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.doInvokeLocal(Invocation.java:600) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.doInvoke(Invocation.java:579) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke0(Invocation.java:540) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke(Invocation.java:240) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.InvocationBuilderImpl.invoke(InvocationBuilderImpl.java:59) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.jet.impl.MasterContext.invokeOnParticipant(MasterContext.java:264) ~[classes/:?]
	at com.hazelcast.jet.impl.MasterContext.invokeOnParticipants(MasterContext.java:247) ~[classes/:?]
	at com.hazelcast.jet.impl.MasterJobContext.lambda$cancelExecutionInvocations$16(MasterJobContext.java:601) ~[classes/:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130) ~[?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630) ~[?:?]
	at java.lang.Thread.run(Thread.java:832) ~[?:?]
	at com.hazelcast.internal.util.executor.HazelcastManagedThread.executeRun(HazelcastManagedThread.java:76) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.internal.util.executor.HazelcastManagedThread.run(HazelcastManagedThread.java:102) ~[hazelcast-4.2.jar:4.2]
2021-05-09 15:35:19,911 [DEBUG] [ForkJoinPool.commonPool-worker-203] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] job '0628-afbd-b4e2-0001', execution 0628-b006-5413-0001 to be cancelled after Execution
2021-05-09 15:35:19,911 [DEBUG] [hz.peaceful_booth.cached.thread-57] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Sending CompleteExecutionOperation for job '0628-afbd-b4e2-0001', execution 0628-b006-5413-0001
2021-05-09 15:35:19,911 [DEBUG] [hz.peaceful_booth.cached.thread-60] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Starting snapshot 235 for job '0628-afbd-b4e2-0001', execution 0628-b006-5413-0001, flags: terminal=no,export=no, writing to: null
2021-05-09 15:35:19,911 [DEBUG] [hz.peaceful_booth.cached.thread-57] [c.h.j.i.o.CompleteExecutionOperation]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Completing execution 0628-b006-5413-0001 from caller [127.0.0.1]:5701, error=java.util.concurrent.CancellationException
2021-05-09 15:35:19,911 [DEBUG] [hz.peaceful_booth.cached.thread-60] [c.h.j.i.e.ExecutionContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Starting snapshot 235 phase 1 for job '0628-afbd-b4e2-0001', execution 0628-b006-5413-0001 on member
2021-05-09 15:35:19,911 [DEBUG] [hz.peaceful_booth.cached.thread-57] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-afbd-b4e2-0001/filesSink(/tmp/write-file-p4865701519209436653)#0] rollback File{0-35}
2021-05-09 15:35:19,911 [DEBUG] [hz.peaceful_booth.cached.thread-57] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-afbd-b4e2-0001/filesSink(/tmp/write-file-p4865701519209436653)#0] release File{0-35}
2021-05-09 15:35:19,911 [DEBUG] [hz.peaceful_booth.cached.thread-57] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-afbd-b4e2-0001/filesSink(/tmp/write-file-p4865701519209436653)#1] rollback File{1-23}
2021-05-09 15:35:19,911 [ERROR] [hz.peaceful_booth.cached.thread-60] [c.h.j.i.o.SnapshotPhase1Operation]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] null
java.util.concurrent.CancellationException: null
	at com.hazelcast.jet.impl.execution.ExecutionContext.beginSnapshotPhase1(ExecutionContext.java:253) ~[classes/:?]
	at com.hazelcast.jet.impl.operation.SnapshotPhase1Operation.doRun(SnapshotPhase1Operation.java:64) ~[classes/:?]
	at com.hazelcast.jet.impl.operation.AsyncOperation.run(AsyncOperation.java:53) ~[classes/:?]
	at com.hazelcast.spi.impl.operationservice.Operation.call(Operation.java:189) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.call(OperationRunnerImpl.java:272) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:248) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:213) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationexecutor.impl.OperationExecutorImpl.run(OperationExecutorImpl.java:411) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationexecutor.impl.OperationExecutorImpl.runOrExecute(OperationExecutorImpl.java:438) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.doInvokeLocal(Invocation.java:600) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.doInvoke(Invocation.java:579) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke0(Invocation.java:540) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke(Invocation.java:240) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.InvocationBuilderImpl.invoke(InvocationBuilderImpl.java:59) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.jet.impl.MasterContext.invokeOnParticipant(MasterContext.java:264) ~[classes/:?]
	at com.hazelcast.jet.impl.MasterContext.invokeOnParticipants(MasterContext.java:247) ~[classes/:?]
	at com.hazelcast.jet.impl.MasterSnapshotContext.lambda$tryBeginSnapshot$2(MasterSnapshotContext.java:173) ~[classes/:?]
	at com.hazelcast.jet.impl.JobCoordinationService.lambda$submitToCoordinatorThread$46(JobCoordinationService.java:1039) ~[classes/:?]
	at com.hazelcast.jet.impl.JobCoordinationService.lambda$submitToCoordinatorThread$47(JobCoordinationService.java:1060) ~[classes/:?]
	at com.hazelcast.internal.util.executor.CompletableFutureTask.run(CompletableFutureTask.java:64) [hazelcast-4.2.jar:4.2]
	at com.hazelcast.internal.util.executor.CachedExecutorServiceDelegate$Worker.run(CachedExecutorServiceDelegate.java:217) [hazelcast-4.2.jar:4.2]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630) [?:?]
	at java.lang.Thread.run(Thread.java:832) [?:?]
	at com.hazelcast.internal.util.executor.HazelcastManagedThread.executeRun(HazelcastManagedThread.java:76) [hazelcast-4.2.jar:4.2]
	at com.hazelcast.internal.util.executor.HazelcastManagedThread.run(HazelcastManagedThread.java:102) [hazelcast-4.2.jar:4.2]
2021-05-09 15:35:19,912 [DEBUG] [hz.peaceful_booth.cached.thread-57] [c.h.j.i.c.WriteFileP]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] [0628-afbd-b4e2-0001/filesSink(/tmp/write-file-p4865701519209436653)#1] release File{1-23}
2021-05-09 15:35:19,912 [DEBUG] [hz.peaceful_booth.cached.thread-57] [c.h.j.i.JobExecutionService]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Completed execution of job '0628-afbd-b4e2-0001', execution 0628-b006-5413-0001
2021-05-09 15:35:19,915 [DEBUG] [hz.peaceful_booth.cached.thread-60] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Snapshot 235 phase 1 for job '0628-afbd-b4e2-0001', execution 0628-b006-5413-0001 completed with status FAILURE in 7ms, 0 bytes, 0 keys in 0 chunks, stored in '__jet.snapshot.0628-afbd-b4e2-0001.1', proceeding to phase 2
2021-05-09 15:35:19,915 [ WARN] [hz.peaceful_booth.cached.thread-60] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] job '0628-afbd-b4e2-0001', execution 0628-b006-5413-0001 snapshot 235 phase 1 failed on some member(s), one of the failures: java.util.concurrent.CancellationException
2021-05-09 15:35:19,933 [DEBUG] [hz.peaceful_booth.cached.thread-60] [c.h.j.i.JobRepository]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Cleared snapshot data map __jet.snapshot.0628-afbd-b4e2-0001.1
2021-05-09 15:35:19,933 [ERROR] [hz.peaceful_booth.cached.thread-60] [c.h.j.i.o.SnapshotPhase2Operation]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] job 0628-afbd-b4e2-0001, execution 0628-b006-5413-0001 not found for coordinator [127.0.0.1]:5701 for 'SnapshotPhase2Operation'
com.hazelcast.jet.core.TopologyChangedException: job 0628-afbd-b4e2-0001, execution 0628-b006-5413-0001 not found for coordinator [127.0.0.1]:5701 for 'SnapshotPhase2Operation'
	at com.hazelcast.jet.impl.JobExecutionService.assertExecutionContext(JobExecutionService.java:326) ~[classes/:?]
	at com.hazelcast.jet.impl.operation.SnapshotPhase2Operation.doRun(SnapshotPhase2Operation.java:50) ~[classes/:?]
	at com.hazelcast.jet.impl.operation.AsyncOperation.run(AsyncOperation.java:53) ~[classes/:?]
	at com.hazelcast.spi.impl.operationservice.Operation.call(Operation.java:189) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.call(OperationRunnerImpl.java:272) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:248) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:213) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationexecutor.impl.OperationExecutorImpl.run(OperationExecutorImpl.java:411) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationexecutor.impl.OperationExecutorImpl.runOrExecute(OperationExecutorImpl.java:438) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.doInvokeLocal(Invocation.java:600) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.doInvoke(Invocation.java:579) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke0(Invocation.java:540) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke(Invocation.java:240) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.InvocationBuilderImpl.invoke(InvocationBuilderImpl.java:59) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.jet.impl.MasterContext.invokeOnParticipant(MasterContext.java:264) ~[classes/:?]
	at com.hazelcast.jet.impl.MasterContext.invokeOnParticipants(MasterContext.java:247) ~[classes/:?]
	at com.hazelcast.jet.impl.MasterSnapshotContext.lambda$onSnapshotPhase1Complete$5(MasterSnapshotContext.java:277) ~[classes/:?]
	at com.hazelcast.jet.impl.JobCoordinationService.lambda$submitToCoordinatorThread$46(JobCoordinationService.java:1039) ~[classes/:?]
	at com.hazelcast.jet.impl.JobCoordinationService.lambda$submitToCoordinatorThread$47(JobCoordinationService.java:1060) ~[classes/:?]
	at com.hazelcast.internal.util.executor.CompletableFutureTask.run(CompletableFutureTask.java:64) [hazelcast-4.2.jar:4.2]
	at com.hazelcast.internal.util.executor.CachedExecutorServiceDelegate$Worker.run(CachedExecutorServiceDelegate.java:217) [hazelcast-4.2.jar:4.2]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630) [?:?]
	at java.lang.Thread.run(Thread.java:832) [?:?]
	at com.hazelcast.internal.util.executor.HazelcastManagedThread.executeRun(HazelcastManagedThread.java:76) [hazelcast-4.2.jar:4.2]
	at com.hazelcast.internal.util.executor.HazelcastManagedThread.run(HazelcastManagedThread.java:102) [hazelcast-4.2.jar:4.2]
2021-05-09 15:35:19,939 [ WARN] [hz.peaceful_booth.cached.thread-60] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] SnapshotPhase2Operation for snapshot 235 in job '0628-afbd-b4e2-0001', execution 0628-b006-5413-0001 failed on member: MemberInfo{address=[127.0.0.1]:5701, uuid=e576beac-64f2-440a-b59d-d2c173094e1f, liteMember=false, memberListJoinVersion=1}=com.hazelcast.jet.core.TopologyChangedException: job 0628-afbd-b4e2-0001, execution 0628-b006-5413-0001 not found for coordinator [127.0.0.1]:5701 for 'SnapshotPhase2Operation'
com.hazelcast.jet.core.TopologyChangedException: job 0628-afbd-b4e2-0001, execution 0628-b006-5413-0001 not found for coordinator [127.0.0.1]:5701 for 'SnapshotPhase2Operation'
	at com.hazelcast.jet.impl.JobExecutionService.assertExecutionContext(JobExecutionService.java:326) ~[classes/:?]
	at com.hazelcast.jet.impl.operation.SnapshotPhase2Operation.doRun(SnapshotPhase2Operation.java:50) ~[classes/:?]
	at com.hazelcast.jet.impl.operation.AsyncOperation.run(AsyncOperation.java:53) ~[classes/:?]
	at com.hazelcast.spi.impl.operationservice.Operation.call(Operation.java:189) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.call(OperationRunnerImpl.java:272) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:248) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.OperationRunnerImpl.run(OperationRunnerImpl.java:213) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationexecutor.impl.OperationExecutorImpl.run(OperationExecutorImpl.java:411) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationexecutor.impl.OperationExecutorImpl.runOrExecute(OperationExecutorImpl.java:438) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.doInvokeLocal(Invocation.java:600) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.doInvoke(Invocation.java:579) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke0(Invocation.java:540) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.Invocation.invoke(Invocation.java:240) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.spi.impl.operationservice.impl.InvocationBuilderImpl.invoke(InvocationBuilderImpl.java:59) ~[hazelcast-4.2.jar:4.2]
	at com.hazelcast.jet.impl.MasterContext.invokeOnParticipant(MasterContext.java:264) ~[classes/:?]
	at com.hazelcast.jet.impl.MasterContext.invokeOnParticipants(MasterContext.java:247) ~[classes/:?]
	at com.hazelcast.jet.impl.MasterSnapshotContext.lambda$onSnapshotPhase1Complete$5(MasterSnapshotContext.java:277) ~[classes/:?]
	at com.hazelcast.jet.impl.JobCoordinationService.lambda$submitToCoordinatorThread$46(JobCoordinationService.java:1039) ~[classes/:?]
	at com.hazelcast.jet.impl.JobCoordinationService.lambda$submitToCoordinatorThread$47(JobCoordinationService.java:1060) ~[classes/:?]
	at com.hazelcast.internal.util.executor.CompletableFutureTask.run(CompletableFutureTask.java:64) [hazelcast-4.2.jar:4.2]
	at com.hazelcast.internal.util.executor.CachedExecutorServiceDelegate$Worker.run(CachedExecutorServiceDelegate.java:217) [hazelcast-4.2.jar:4.2]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630) [?:?]
	at java.lang.Thread.run(Thread.java:832) [?:?]
	at com.hazelcast.internal.util.executor.HazelcastManagedThread.executeRun(HazelcastManagedThread.java:76) [hazelcast-4.2.jar:4.2]
	at com.hazelcast.internal.util.executor.HazelcastManagedThread.run(HazelcastManagedThread.java:102) [hazelcast-4.2.jar:4.2]
2021-05-09 15:35:19,940 [ INFO] [hz.peaceful_booth.cached.thread-2] [c.h.j.i.MasterJobContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Execution of job '0628-afbd-b4e2-0001', execution 0628-b006-5413-0001 got terminated, reason=java.util.concurrent.CancellationException
	Start time: 2021-05-09T15:35:19.502
	Duration: 00:00:00.437
	To see additional job metrics enable JobConfig.storeMetricsAfterJobCompletion
2021-05-09 15:35:19,950 [DEBUG] [hz.peaceful_booth.cached.thread-2] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] job '0628-afbd-b4e2-0001', execution 0628-b006-5413-0001 is completed
2021-05-09 15:35:19,951 [DEBUG] [hz.peaceful_booth.cached.thread-60] [c.h.j.i.JobCoordinationService]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] job '0628-afbd-b4e2-0001', execution 0628-b006-5413-0001 snapshot is scheduled in 50ms
2021-05-09 15:35:19,951 [DEBUG] [hz.peaceful_booth.cached.thread-60] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Snapshot 235 for job '0628-afbd-b4e2-0001', execution 0628-b006-5413-0001 completed in 46ms, status=failure: java.util.concurrent.CancellationException
2021-05-09 15:35:19,951 [DEBUG] [hz.peaceful_booth.cached.thread-60] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Not beginning snapshot, job '0628-afbd-b4e2-0001', execution 0628-b006-5413-0001 is not RUNNING, but FAILED
2021-05-09 15:35:20,512 [DEBUG] [hz.peaceful_booth.cached.thread-2] [c.h.j.i.MasterSnapshotContext]: [127.0.0.1]:5701 [jet] [4.5.1-SNAPSHOT] Not beginning snapshot, job '0628-afbd-b4e2-0001', execution 0628-b006-5413-0001 is not RUNNING, but FAILED
2021-05-09 15:35:20,557 [ INFO] [Time-limited test] [c.h.j.SimpleTestInClusterSupport]: Ditching 2 jobs in SimpleTestInClusterSupport.@After: [0628-afbd-b4e0-0001, 0628-afbd-b4e2-0001]
2021-05-09 15:35:20,590 [ INFO] [Time-limited test] [c.h.j.SimpleTestInClusterSupport]: Destroying 8 distributed objects in SimpleTestInClusterSupport.@After: [hz:impl:mapService/__jet.executionRecords, hz:impl:mapService/__jet.snapshot.0628-afbd-b4e2-0001.0, hz:impl:mapService/__jet.exportedSnapshotsCache, hz:impl:mapService/__jet.results, hz:impl:mapService/__jet.results.metrics, hz:impl:mapService/__jet.records, hz:impl:mapService/__jet.snapshot.0628-afbd-b4e2-0001.1, hz:impl:flakeIdGeneratorService/__jet.ids]
BuildInfo right after stressTest_exactlyOnce_forceful(com.hazelcast.jet.impl.connector.WriteFilePTest): BuildInfo{version='4.2', build='20210324', buildNumber=20210324, revision=405cfd1, enterprise=false, serializationVersion=1, jet=JetBuildInfo{version='4.5.1-SNAPSHOT', build='20210509', revision='32b32b4'}}
Hiccups measured while running test 'stressTest_exactlyOnce_forceful(com.hazelcast.jet.impl.connector.WriteFilePTest):'
15:34:15, accumulated pauses: 224 ms, max pause: 9 ms, pauses over 1000 ms: 0
15:34:20, accumulated pauses: 291 ms, max pause: 46 ms, pauses over 1000 ms: 0
15:34:25, accumulated pauses: 555 ms, max pause: 104 ms, pauses over 1000 ms: 0
15:34:30, accumulated pauses: 935 ms, max pause: 41 ms, pauses over 1000 ms: 0
15:34:35, accumulated pauses: 302 ms, max pause: 27 ms, pauses over 1000 ms: 0
15:34:40, accumulated pauses: 517 ms, max pause: 16 ms, pauses over 1000 ms: 0
15:34:45, accumulated pauses: 383 ms, max pause: 92 ms, pauses over 1000 ms: 0
15:34:50, accumulated pauses: 365 ms, max pause: 8 ms, pauses over 1000 ms: 0
15:34:55, accumulated pauses: 235 ms, max pause: 11 ms, pauses over 1000 ms: 0
15:35:00, accumulated pauses: 332 ms, max pause: 153 ms, pauses over 1000 ms: 0
15:35:05, accumulated pauses: 410 ms, max pause: 9 ms, pauses over 1000 ms: 0
15:35:10, accumulated pauses: 634 ms, max pause: 29 ms, pauses over 1000 ms: 0
15:35:15, accumulated pauses: 1177 ms, max pause: 544 ms, pauses over 1000 ms: 0
15:35:20, accumulated pauses: 6 ms, max pause: 0 ms, pauses over 1000 ms: 0
@olukas olukas added this to the 4.5.1 milestone May 10, 2021
@degerhz degerhz modified the milestones: 4.5.1, 4.5.2 Sep 14, 2021
@frant-hartm frant-hartm modified the milestones: 4.5.2, 4.5.3 Dec 15, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
test-failure
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@olukas @frant-hartm @degerhz