Results for igt@kms_flip@plain-flip-ts-check

shard-dg2-7

IGT-Version: 1.29-gb0c59bb94 (x86_64) (Linux: 6.13.0-rc1-CI_DRM_15796-g1b7746f77088+ x86_64)

Using IGT_SRANDOM=1733440032 for randomisation
Opened device: /dev/dri/card0
Using monotonic timestamps
Starting subtest: plain-flip-ts-check
Starting dynamic subtest: A-HDMI-A3
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 17167.9us +- 7.822us accuracy 0.14%
vblank interval differs from modeline! expected 16666.7us, measured 17168us +- 7.822us, difference 501.2us (64.1 sigma)
Stack trace:
  #0 ../lib/igt_core.c:2051 __igt_fail_assert()
  #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1845 run_test()
  #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
  #4 ../tests/kms_flip.c:2001 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest A-HDMI-A3: FAIL (5.277s)
Starting dynamic subtest: B-HDMI-A3
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16928.4us +- 6.022us accuracy 0.11%
vblank interval differs from modeline! expected 16666.7us, measured 16928us +- 6.022us, difference 261.8us (43.5 sigma)
Stack trace:
  #0 ../lib/igt_core.c:2051 __igt_fail_assert()
  #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1845 run_test()
  #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
  #4 ../tests/kms_flip.c:2001 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest B-HDMI-A3: FAIL (5.897s)
Starting dynamic subtest: C-HDMI-A3
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16789.1us +- 6.688us accuracy 0.12%
vblank interval differs from modeline! expected 16666.7us, measured 16789us +- 6.688us, difference 122.4us (18.3 sigma)
Stack trace:
  #0 ../lib/igt_core.c:2051 __igt_fail_assert()
  #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1845 run_test()
  #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
  #4 ../tests/kms_flip.c:2001 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest C-HDMI-A3: FAIL (11.183s)
Starting dynamic subtest: D-HDMI-A3
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16702.1us +- 5.005us accuracy 0.09%
vblank interval differs from modeline! expected 16666.7us, measured 16702us +- 5.005us, difference 35.5us (7.1 sigma)
Dynamic subtest D-HDMI-A3: SUCCESS (7.988s)
Subtest plain-flip-ts-check: FAIL (30.356s)

Starting subtest: plain-flip-ts-check
Starting dynamic subtest: A-HDMI-A3
(kms_flip:2181) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:2181) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest A-HDMI-A3 failed.
**** DEBUG ****
(kms_flip:2181) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:2181) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=1, pitch=7680)
(kms_flip:2181) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:2181) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:2181) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=2, pitch=7680)
(kms_flip:2181) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:2181) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2181) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2181) igt_fb-DEBUG: Test requirement passed: gem_has_contexts(fb->fd)
(kms_flip:2181) intel_allocator_reloc-DEBUG: Using reloc allocator
(kms_flip:2181) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2181) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2181) igt_fb-DEBUG: Test requirement passed: gem_has_contexts(fb->fd)
(kms_flip:2181) intel_allocator_reloc-DEBUG: Using reloc allocator
(kms_flip:2181) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2181) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2181) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2181) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2181) igt_fb-DEBUG: Test requirement passed: gem_has_contexts(fb->fd)
(kms_flip:2181) intel_allocator_reloc-DEBUG: Using reloc allocator
(kms_flip:2181) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2181) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2181) igt_fb-DEBUG: Test requirement passed: gem_has_contexts(fb->fd)
(kms_flip:2181) intel_allocator_reloc-DEBUG: Using reloc allocator
(kms_flip:2181) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2181) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2181) igt_kms-INFO:   1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
(kms_flip:2181) DEBUG: No stale events found
(kms_flip:2181) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:2181) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:2181) INFO: Expected frametime: 16667us; measured 17167.9us +- 7.822us accuracy 0.14%
(kms_flip:2181) INFO: vblank interval differs from modeline! expected 16666.7us, measured 17168us +- 7.822us, difference 501.2us (64.1 sigma)
(kms_flip:2181) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 116.365517
current_received_ts = 116.365082
current_seq = 2774
count = 0
seq_step = 1
(kms_flip:2181) DEBUG: name = flip
last_ts = 116.365517
last_received_ts = 116.365082
last_seq = 2774
current_ts = 116.382690
current_received_ts = 116.382385
current_seq = 2775
count = 1
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 116.365517/2774, current 116.382690/2775: elapsed=17173.0us expected=17167.9us +- 85.8us, error 0.0%
(kms_flip:2181) DEBUG: name = flip
last_ts = 116.382690
last_received_ts = 116.382385
last_seq = 2775
current_ts = 116.399849
current_received_ts = 116.399437
current_seq = 2776
count = 2
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 116.382690/2775, current 116.399849/2776: elapsed=17162.0us expected=17167.9us +- 85.8us, error 0.0%
(kms_flip:2181) DEBUG: name = flip
last_ts = 116.399849
last_received_ts = 116.399437
last_seq = 2776
current_ts = 116.417023
current_received_ts = 116.416641
current_seq = 2777
count = 3
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 116.399849/2776, current 116.417023/2777: elapsed=17171.0us expected=17167.9us +- 85.8us, error 0.0%
(kms_flip:2181) DEBUG: name = flip
last_ts = 116.417023
last_received_ts = 116.416641
last_seq = 2777
current_ts = 116.434196
current_received_ts = 116.433784
current_seq = 2778
count = 4
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 116.417023/2777, current 116.434196/2778: elapsed=17173.0us expected=17167.9us +- 85.8us, error 0.0%
(kms_flip:2181) DEBUG: name = flip
last_ts = 116.434196
last_received_ts = 116.433784
last_seq = 2778
current_ts = 116.451363
current_received_ts = 116.450912
current_seq = 2779
count = 5
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 116.434196/2778, current 116.451363/2779: elapsed=17163.0us expected=17167.9us +- 85.8us, error 0.0%
(kms_flip:2181) DEBUG: name = flip
last_ts = 116.451363
last_received_ts = 116.450912
last_seq = 2779
current_ts = 116.468529
current_received_ts = 116.468140
current_seq = 2780
count = 6
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 116.451363/2779, current 116.468529/2780: elapsed=17166.0us expected=17167.9us +- 85.8us, error 0.0%
(kms_flip:2181) DEBUG: name = flip
last_ts = 116.468529
last_received_ts = 116.468140
last_seq = 2780
current_ts = 116.485680
current_received_ts = 116.485336
current_seq = 2781
count = 7
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 116.468529/2780, current 116.485680/2781: elapsed=17158.0us expected=17167.9us +- 85.8us, error 0.1%
(kms_flip:2181) DEBUG: name = flip
last_ts = 116.485680
last_received_ts = 116.485336
last_seq = 2781
current_ts = 116.502861
current_received_ts = 116.502373
current_seq = 2782
count = 8
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 116.485680/2781, current 116.502861/2782: elapsed=17179.0us expected=17167.9us +- 85.8us, error 0.1%
(kms_flip:2181) DEBUG: name = flip
last_ts = 116.502861
last_received_ts = 116.502373
last_seq = 2782
current_ts = 116.520027
current_received_ts = 116.519547
current_seq = 2783
count = 9
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 116.502861/2782, current 116.520027/2783: elapsed=17166.0us expected=17167.9us +- 85.8us, error 0.0%
(kms_flip:2181) DEBUG: name = flip
last_ts = 116.520027
last_received_ts = 116.519547
last_seq = 2783
current_ts = 116.537186
current_received_ts = 116.536743
current_seq = 2784
count = 10
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 116.520027/2783, current 116.537186/2784: elapsed=17159.0us expected=17167.9us +- 85.8us, error 0.1%
(kms_flip:2181) DEBUG: name = flip
last_ts = 116.537186
last_received_ts = 116.536743
last_seq = 2784
current_ts = 116.554352
current_received_ts = 116.553894
current_seq = 2785
count = 11
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 116.537186/2784, current 116.554352/2785: elapsed=17166.0us expected=17167.9us +- 85.8us, error 0.0%
(kms_flip:2181) DEBUG: name = flip
last_ts = 116.554352
last_received_ts = 116.553894
last_seq = 2785
current_ts = 116.571526
current_received_ts = 116.571167
current_seq = 2786
count = 12
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 116.554352/2785, current 116.571526/2786: elapsed=17176.0us expected=17167.9us +- 85.8us, error 0.0%
(kms_flip:2181) DEBUG: name = flip
last_ts = 116.571526
last_received_ts = 116.571167
last_seq = 2786
current_ts = 116.588692
current_received_ts = 116.588303
current_seq = 2787
count = 13
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 116.571526/2786, current 116.588692/2787: elapsed=17161.0us expected=17167.9us +- 85.8us, error 0.0%
(kms_flip:2181) DEBUG: name = flip
last_ts = 116.588692
last_received_ts = 116.588303
last_seq = 2787
current_ts = 116.605873
current_received_ts = 116.605453
current_seq = 2788
count = 14
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 116.588692/2787, current 116.605873/2788: elapsed=17180.0us expected=17167.9us +- 85.8us, error 0.1%
(kms_flip:2181) DEBUG: name = flip
last_ts = 116.605873
last_received_ts = 116.605453
last_seq = 2788
current_ts = 116.623032
current_received_ts = 116.622726
current_seq = 2789
count = 15
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 116.605873/2788, current 116.623032/2789: elapsed=17161.0us expected=17167.9us +- 85.8us, error 0.0%
(kms_flip:2181) DEBUG: name = flip
last_ts = 116.623032
last_received_ts = 116.622726
last_seq = 2789
current_ts = 116.640198
current_received_ts = 116.639793
current_seq = 2790
count = 16
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 116.623032/2789, current 116.640198/2790: elapsed=17167.0us expected=17167.9us +- 85.8us, error 0.0%
(kms_flip:2181) DEBUG: name = flip
last_ts = 116.640198
last_received_ts = 116.639793
last_seq = 2790
current_ts = 116.657372
current_received_ts = 116.656952
current_seq = 2791
count = 17
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 116.640198/2790, current 116.657372/2791: elapsed=17171.0us expected=17167.9us +- 85.8us, error 0.0%
(kms_flip:2181) DEBUG: name = flip
last_ts = 116.657372
last_received_ts = 116.656952
last_seq = 2791
current_ts = 116.674530
current_received_ts = 116.674133
current_seq = 2792
count = 18
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 116.657372/2791, current 116.674530/2792: elapsed=17162.0us expected=17167.9us +- 85.8us, error 0.0%
(kms_flip:2181) DEBUG: name = flip
last_ts = 116.674530
last_received_ts = 116.674133
last_seq = 2792
current_ts = 116.691704
current_received_ts = 116.691299
current_seq = 2793
count = 19
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 116.674530/2792, current 116.691704/2793: elapsed=17176.0us expected=17167.9us +- 85.8us, error 0.0%
(kms_flip:2181) DEBUG: name = flip
last_ts = 116.691704
last_received_ts = 116.691299
last_seq = 2793
current_ts = 116.708870
current_received_ts = 116.708443
current_seq = 2794
count = 20
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 116.691704/2793, current 116.708870/2794: elapsed=17160.0us expected=17167.9us +- 85.8us, error 0.0%
(kms_flip:2181) DEBUG: name = flip
last_ts = 116.708870
last_received_ts = 116.708443
last_seq = 2794
current_ts = 116.726028
current_received_ts = 116.725624
current_seq = 2795
count = 21
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 116.708870/2794, current 116.726028/2795: elapsed=17165.0us expected=17167.9us +- 85.8us, error 0.0%
(kms_flip:2181) DEBUG: name = flip
last_ts = 116.726028
last_received_ts = 116.725624
last_seq = 2795
current_ts = 116.743195
current_received_ts = 116.742775
current_seq = 2796
count = 22
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 116.726028/2795, current 116.743195/2796: elapsed=17165.0us expected=17167.9us +- 85.8us, error 0.0%
(kms_flip:2181) DEBUG: name = flip
last_ts = 116.743195
last_received_ts = 116.742775
last_seq = 2796
current_ts = 116.760376
current_received_ts = 116.759964
current_seq = 2797
count = 23
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 116.743195/2796, current 116.760376/2797: elapsed=17178.0us expected=17167.9us +- 85.8us, error 0.1%
(kms_flip:2181) DEBUG: name = flip
last_ts = 116.760376
last_received_ts = 116.759964
last_seq = 2797
current_ts = 116.777542
current_received_ts = 116.777168
current_seq = 2798
count = 24
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 116.760376/2797, current 116.777542/2798: elapsed=17165.0us expected=17167.9us +- 85.8us, error 0.0%
(kms_flip:2181) DEBUG: name = flip
last_ts = 116.777542
last_received_ts = 116.777168
last_seq = 2798
current_ts = 116.794708
current_received_ts = 116.794350
current_seq = 2799
count = 25
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 116.777542/2798, current 116.794708/2799: elapsed=17171.0us expected=17167.9us +- 85.8us, error 0.0%
(kms_flip:2181) DEBUG: name = flip
last_ts = 116.794708
last_received_ts = 116.794350
last_seq = 2799
current_ts = 116.811874
current_received_ts = 116.811462
current_seq = 2800
count = 26
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 116.794708/2799, current 116.811874/2800: elapsed=17161.0us expected=17167.9us +- 85.8us, error 0.0%
(kms_flip:2181) DEBUG: name = flip
last_ts = 116.811874
last_received_ts = 116.811462
last_seq = 2800
current_ts = 116.829033
current_received_ts = 116.828667
current_seq = 2801
count = 27
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 116.811874/2800, current 116.829033/2801: elapsed=17163.0us expected=17167.9us +- 85.8us, error 0.0%
(kms_flip:2181) DEBUG: name = flip
last_ts = 116.829033
last_received_ts = 116.828667
last_seq = 2801
current_ts = 116.846207
current_received_ts = 116.845795
current_seq = 2802
count = 28
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 116.829033/2801, current 116.846207/2802: elapsed=17170.0us expected=17167.9us +- 85.8us, error 0.0%
(kms_flip:2181) DEBUG: name = flip
last_ts = 116.846207
last_received_ts = 116.845795
last_seq = 2802
current_ts = 116.863373
current_received_ts = 116.862938
current_seq = 2803
count = 29
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 116.846207/2802, current 116.863373/2803: elapsed=17168.0us expected=17167.9us +- 85.8us, error 0.0%
(kms_flip:2181) DEBUG: name = flip
last_ts = 116.863373
last_received_ts = 116.862938
last_seq = 2803
current_ts = 116.880539
current_received_ts = 116.880150
current_seq = 2804
count = 30
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 116.863373/2803, current 116.880539/2804: elapsed=17167.0us expected=17167.9us +- 85.8us, error 0.0%
(kms_flip:2181) DEBUG: name = flip
last_ts = 116.880539
last_received_ts = 116.880150
last_seq = 2804
current_ts = 116.897705
current_received_ts = 116.897308
current_seq = 2805
count = 31
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 116.880539/2804, current 116.897705/2805: elapsed=17164.0us expected=17167.9us +- 85.8us, error 0.0%
(kms_flip:2181) DEBUG: name = flip
last_ts = 116.897705
last_received_ts = 116.897308
last_seq = 2805
current_ts = 116.914879
current_received_ts = 116.914467
current_seq = 2806
count = 32
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 116.897705/2805, current 116.914879/2806: elapsed=17173.0us expected=17167.9us +- 85.8us, error 0.0%
(kms_flip:2181) DEBUG: name = flip
last_ts = 116.914879
last_received_ts = 116.914467
last_seq = 2806
current_ts = 116.932037
current_received_ts = 116.931648
current_seq = 2807
count = 33
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 116.914879/2806, current 116.932037/2807: elapsed=17163.0us expected=17167.9us +- 85.8us, error 0.0%
(kms_flip:2181) DEBUG: name = flip
last_ts = 116.932037
last_received_ts = 116.931648
last_seq = 2807
current_ts = 116.949142
current_received_ts = 116.948700
current_seq = 2808
count = 34
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 116.932037/2807, current 116.949142/2808: elapsed=17106.0us expected=17167.9us +- 85.8us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 116.949142
last_received_ts = 116.948700
last_seq = 2808
current_ts = 116.966263
current_received_ts = 116.965775
current_seq = 2809
count = 35
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 116.949142/2808, current 116.966263/2809: elapsed=17118.0us expected=17167.9us +- 85.8us, error 0.3%
(kms_flip:2181) DEBUG: name = flip
last_ts = 116.966263
last_received_ts = 116.965775
last_seq = 2809
current_ts = 116.983368
current_received_ts = 116.982918
current_seq = 2810
count = 36
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 116.966263/2809, current 116.983368/2810: elapsed=17101.0us expected=17167.9us +- 85.8us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 116.983368
last_received_ts = 116.982918
last_seq = 2810
current_ts = 117.000473
current_received_ts = 117.000076
current_seq = 2811
count = 37
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 116.983368/2810, current 117.000473/2811: elapsed=17107.0us expected=17167.9us +- 85.8us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 117.000473
last_received_ts = 117.000076
last_seq = 2811
current_ts = 117.017586
current_received_ts = 117.017296
current_seq = 2812
count = 38
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 117.000473/2811, current 117.017586/2812: elapsed=17112.0us expected=17167.9us +- 85.8us, error 0.3%
(kms_flip:2181) DEBUG: name = flip
last_ts = 117.017586
last_received_ts = 117.017296
last_seq = 2812
current_ts = 117.034683
current_received_ts = 117.034309
current_seq = 2813
count = 39
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 117.017586/2812, current 117.034683/2813: elapsed=17096.0us expected=17167.9us +- 85.8us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 117.034683
last_received_ts = 117.034309
last_seq = 2813
current_ts = 117.051781
current_received_ts = 117.051346
current_seq = 2814
count = 40
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 117.034683/2813, current 117.051781/2814: elapsed=17100.0us expected=17167.9us +- 85.8us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 117.051781
last_received_ts = 117.051346
last_seq = 2814
current_ts = 117.068893
current_received_ts = 117.068451
current_seq = 2815
count = 41
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 117.051781/2814, current 117.068893/2815: elapsed=17113.0us expected=17167.9us +- 85.8us, error 0.3%
(kms_flip:2181) DEBUG: name = flip
last_ts = 117.068893
last_received_ts = 117.068451
last_seq = 2815
current_ts = 117.085991
current_received_ts = 117.085564
current_seq = 2816
count = 42
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 117.068893/2815, current 117.085991/2816: elapsed=17101.0us expected=17167.9us +- 85.8us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 117.085991
last_received_ts = 117.085564
last_seq = 2816
current_ts = 117.103104
current_received_ts = 117.102623
current_seq = 2817
count = 43
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 117.085991/2816, current 117.103104/2817: elapsed=17112.0us expected=17167.9us +- 85.8us, error 0.3%
(kms_flip:2181) DEBUG: name = flip
last_ts = 117.103104
last_received_ts = 117.102623
last_seq = 2817
current_ts = 117.120201
current_received_ts = 117.119759
current_seq = 2818
count = 44
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 117.103104/2817, current 117.120201/2818: elapsed=17097.0us expected=17167.9us +- 85.8us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 117.120201
last_received_ts = 117.119759
last_seq = 2818
current_ts = 117.137314
current_received_ts = 117.136894
current_seq = 2819
count = 45
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 117.120201/2818, current 117.137314/2819: elapsed=17109.0us expected=17167.9us +- 85.8us, error 0.3%
(kms_flip:2181) DEBUG: name = flip
last_ts = 117.137314
last_received_ts = 117.136894
last_seq = 2819
current_ts = 117.154427
current_received_ts = 117.153969
current_seq = 2820
count = 46
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 117.137314/2819, current 117.154427/2820: elapsed=17112.0us expected=17167.9us +- 85.8us, error 0.3%
(kms_flip:2181) DEBUG: name = flip
last_ts = 117.154427
last_received_ts = 117.153969
last_seq = 2820
current_ts = 117.171532
current_received_ts = 117.171097
current_seq = 2821
count = 47
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 117.154427/2820, current 117.171532/2821: elapsed=17110.0us expected=17167.9us +- 85.8us, error 0.3%
(kms_flip:2181) DEBUG: name = flip
last_ts = 117.171532
last_received_ts = 117.171097
last_seq = 2821
current_ts = 117.188644
current_received_ts = 117.188232
current_seq = 2822
count = 48
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 117.171532/2821, current 117.188644/2822: elapsed=17108.0us expected=17167.9us +- 85.8us, error 0.3%
(kms_flip:2181) DEBUG: name = flip
last_ts = 117.188644
last_received_ts = 117.188232
last_seq = 2822
current_ts = 117.205742
current_received_ts = 117.205383
current_seq = 2823
count = 49
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 117.188644/2822, current 117.205742/2823: elapsed=17099.0us expected=17167.9us +- 85.8us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 117.205742
last_received_ts = 117.205383
last_seq = 2823
current_ts = 117.222847
current_received_ts = 117.223297
current_seq = 2824
count = 50
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 117.205742/2823, current 117.222847/2824: elapsed=17106.0us expected=17167.9us +- 85.8us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 117.222847
last_received_ts = 117.223297
last_seq = 2824
current_ts = 117.239944
current_received_ts = 117.239471
current_seq = 2825
count = 51
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 117.222847/2824, current 117.239944/2825: elapsed=17098.0us expected=17167.9us +- 85.8us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 117.239944
last_received_ts = 117.239471
last_seq = 2825
current_ts = 117.257057
current_received_ts = 117.256599
current_seq = 2826
count = 52
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 117.239944/2825, current 117.257057/2826: elapsed=17115.0us expected=17167.9us +- 85.8us, error 0.3%
(kms_flip:2181) DEBUG: name = flip
last_ts = 117.257057
last_received_ts = 117.256599
last_seq = 2826
current_ts = 117.274162
current_received_ts = 117.273811
current_seq = 2827
count = 53
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 117.257057/2826, current 117.274162/2827: elapsed=17106.0us expected=17167.9us +- 85.8us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 117.274162
last_received_ts = 117.273811
last_seq = 2827
current_ts = 117.291267
current_received_ts = 117.290848
current_seq = 2828
count = 54
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 117.274162/2827, current 117.291267/2828: elapsed=17104.0us expected=17167.9us +- 85.8us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 117.291267
last_received_ts = 117.290848
last_seq = 2828
current_ts = 117.308380
current_received_ts = 117.307899
current_seq = 2829
count = 55
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 117.291267/2828, current 117.308380/2829: elapsed=17110.0us expected=17167.9us +- 85.8us, error 0.3%
(kms_flip:2181) DEBUG: name = flip
last_ts = 117.308380
last_received_ts = 117.307899
last_seq = 2829
current_ts = 117.325478
current_received_ts = 117.325157
current_seq = 2830
count = 56
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 117.308380/2829, current 117.325478/2830: elapsed=17098.0us expected=17167.9us +- 85.8us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 117.325478
last_received_ts = 117.325157
last_seq = 2830
current_ts = 117.342590
current_received_ts = 117.342171
current_seq = 2831
count = 57
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 117.325478/2830, current 117.342590/2831: elapsed=17114.0us expected=17167.9us +- 85.8us, error 0.3%
(kms_flip:2181) DEBUG: name = flip
last_ts = 117.342590
last_received_ts = 117.342171
last_seq = 2831
current_ts = 117.359695
current_received_ts = 117.359276
current_seq = 2832
count = 58
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 117.342590/2831, current 117.359695/2832: elapsed=17107.0us expected=17167.9us +- 85.8us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 117.359695
last_received_ts = 117.359276
last_seq = 2832
current_ts = 117.376801
current_received_ts = 117.376274
current_seq = 2833
count = 59
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 117.359695/2832, current 117.376801/2833: elapsed=17103.0us expected=17167.9us +- 85.8us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 117.376801
last_received_ts = 117.376274
last_seq = 2833
current_ts = 117.393898
current_received_ts = 117.393440
current_seq = 2834
count = 60
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 117.376801/2833, current 117.393898/2834: elapsed=17096.0us expected=17167.9us +- 85.8us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 117.393898
last_received_ts = 117.393440
last_seq = 2834
current_ts = 117.411018
current_received_ts = 117.410645
current_seq = 2835
count = 61
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 117.393898/2834, current 117.411018/2835: elapsed=17119.0us expected=17167.9us +- 85.8us, error 0.3%
(kms_flip:2181) DEBUG: name = flip
last_ts = 117.411018
last_received_ts = 117.410645
last_seq = 2835
current_ts = 117.428116
current_received_ts = 117.427628
current_seq = 2836
count = 62
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 117.411018/2835, current 117.428116/2836: elapsed=17098.0us expected=17167.9us +- 85.8us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 117.428116
last_received_ts = 117.427628
last_seq = 2836
current_ts = 117.445229
current_received_ts = 117.444778
current_seq = 2837
count = 63
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 117.428116/2836, current 117.445229/2837: elapsed=17114.0us expected=17167.9us +- 85.8us, error 0.3%
(kms_flip:2181) DEBUG: name = flip
last_ts = 117.445229
last_received_ts = 117.444778
last_seq = 2837
current_ts = 117.462334
current_received_ts = 117.461906
current_seq = 2838
count = 64
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 117.445229/2837, current 117.462334/2838: elapsed=17106.0us expected=17167.9us +- 85.8us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 117.462334
last_received_ts = 117.461906
last_seq = 2838
current_ts = 117.479439
current_received_ts = 117.478981
current_seq = 2839
count = 65
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 117.462334/2838, current 117.479439/2839: elapsed=17104.0us expected=17167.9us +- 85.8us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 117.479439
last_received_ts = 117.478981
last_seq = 2839
current_ts = 117.496536
current_received_ts = 117.496162
current_seq = 2840
count = 66
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 117.479439/2839, current 117.496536/2840: elapsed=17100.0us expected=17167.9us +- 85.8us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 117.496536
last_received_ts = 117.496162
last_seq = 2840
current_ts = 117.513641
current_received_ts = 117.513214
current_seq = 2841
count = 67
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 117.496536/2840, current 117.513641/2841: elapsed=17101.0us expected=17167.9us +- 85.8us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 117.513641
last_received_ts = 117.513214
last_seq = 2841
current_ts = 117.530746
current_received_ts = 117.530403
current_seq = 2842
count = 68
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 117.513641/2841, current 117.530746/2842: elapsed=17106.0us expected=17167.9us +- 85.8us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 117.530746
last_received_ts = 117.530403
last_seq = 2842
current_ts = 117.547867
current_received_ts = 117.547440
current_seq = 2843
count = 69
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 117.530746/2842, current 117.547867/2843: elapsed=17118.0us expected=17167.9us +- 85.8us, error 0.3%
(kms_flip:2181) DEBUG: name = flip
last_ts = 117.547867
last_received_ts = 117.547440
last_seq = 2843
current_ts = 117.564964
current_received_ts = 117.564522
current_seq = 2844
count = 70
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 117.547867/2843, current 117.564964/2844: elapsed=17097.0us expected=17167.9us +- 85.8us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 117.564964
last_received_ts = 117.564522
last_seq = 2844
current_ts = 117.582077
current_received_ts = 117.581642
current_seq = 2845
count = 71
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 117.564964/2844, current 117.582077/2845: elapsed=17113.0us expected=17167.9us +- 85.8us, error 0.3%
(kms_flip:2181) DEBUG: name = flip
last_ts = 117.582077
last_received_ts = 117.581642
last_seq = 2845
current_ts = 117.599174
current_received_ts = 117.598755
current_seq = 2846
count = 72
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 117.582077/2845, current 117.599174/2846: elapsed=17098.0us expected=17167.9us +- 85.8us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 117.599174
last_received_ts = 117.598755
last_seq = 2846
current_ts = 117.616287
current_received_ts = 117.615829
current_seq = 2847
count = 73
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 117.599174/2846, current 117.616287/2847: elapsed=17113.0us expected=17167.9us +- 85.8us, error 0.3%
(kms_flip:2181) DEBUG: name = flip
last_ts = 117.616287
last_received_ts = 117.615829
last_seq = 2847
current_ts = 117.633392
current_received_ts = 117.632957
current_seq = 2848
count = 74
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 117.616287/2847, current 117.633392/2848: elapsed=17104.0us expected=17167.9us +- 85.8us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 117.633392
last_received_ts = 117.632957
last_seq = 2848
current_ts = 117.650497
current_received_ts = 117.650085
current_seq = 2849
count = 75
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 117.633392/2848, current 117.650497/2849: elapsed=17107.0us expected=17167.9us +- 85.8us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 117.650497
last_received_ts = 117.650085
last_seq = 2849
current_ts = 117.667595
current_received_ts = 117.667160
current_seq = 2850
count = 76
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 117.650497/2849, current 117.667595/2850: elapsed=17098.0us expected=17167.9us +- 85.8us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 117.667595
last_received_ts = 117.667160
last_seq = 2850
current_ts = 117.684700
current_received_ts = 117.684280
current_seq = 2851
count = 77
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 117.667595/2850, current 117.684700/2851: elapsed=17109.0us expected=17167.9us +- 85.8us, error 0.3%
(kms_flip:2181) DEBUG: name = flip
last_ts = 117.684700
last_received_ts = 117.684280
last_seq = 2851
current_ts = 117.701813
current_received_ts = 117.701317
current_seq = 2852
count = 78
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 117.684700/2851, current 117.701813/2852: elapsed=17108.0us expected=17167.9us +- 85.8us, error 0.3%
(kms_flip:2181) DEBUG: name = flip
last_ts = 117.701813
last_received_ts = 117.701317
last_seq = 2852
current_ts = 117.718918
current_received_ts = 117.718452
current_seq = 2853
count = 79
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 117.701813/2852, current 117.718918/2853: elapsed=17109.0us expected=17167.9us +- 85.8us, error 0.3%
(kms_flip:2181) DEBUG: name = flip
last_ts = 117.718918
last_received_ts = 117.718452
last_seq = 2853
current_ts = 117.736031
current_received_ts = 117.735580
current_seq = 2854
count = 80
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 117.718918/2853, current 117.736031/2854: elapsed=17107.0us expected=17167.9us +- 85.8us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 117.736031
last_received_ts = 117.735580
last_seq = 2854
current_ts = 117.753120
current_received_ts = 117.752678
current_seq = 2855
count = 81
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 117.736031/2854, current 117.753120/2855: elapsed=17095.0us expected=17167.9us +- 85.8us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 117.753120
last_received_ts = 117.752678
last_seq = 2855
current_ts = 117.770241
current_received_ts = 117.769791
current_seq = 2856
count = 82
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 117.753120/2855, current 117.770241/2856: elapsed=17116.0us expected=17167.9us +- 85.8us, error 0.3%
(kms_flip:2181) DEBUG: name = flip
last_ts = 117.770241
last_received_ts = 117.769791
last_seq = 2856
current_ts = 117.787331
current_received_ts = 117.786919
current_seq = 2857
count = 83
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 117.770241/2856, current 117.787331/2857: elapsed=17095.0us expected=17167.9us +- 85.8us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 117.787331
last_received_ts = 117.786919
last_seq = 2857
current_ts = 117.804443
current_received_ts = 117.804024
current_seq = 2858
count = 84
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 117.787331/2857, current 117.804443/2858: elapsed=17111.0us expected=17167.9us +- 85.8us, error 0.3%
(kms_flip:2181) DEBUG: name = flip
last_ts = 117.804443
last_received_ts = 117.804024
last_seq = 2858
current_ts = 117.821556
current_received_ts = 117.821106
current_seq = 2859
count = 85
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 117.804443/2858, current 117.821556/2859: elapsed=17113.0us expected=17167.9us +- 85.8us, error 0.3%
(kms_flip:2181) DEBUG: name = flip
last_ts = 117.821556
last_received_ts = 117.821106
last_seq = 2859
current_ts = 117.838661
current_received_ts = 117.838242
current_seq = 2860
count = 86
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 117.821556/2859, current 117.838661/2860: elapsed=17106.0us expected=17167.9us +- 85.8us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 117.838661
last_received_ts = 117.838242
last_seq = 2860
current_ts = 117.855759
current_received_ts = 117.855400
current_seq = 2861
count = 87
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 117.838661/2860, current 117.855759/2861: elapsed=17099.0us expected=17167.9us +- 85.8us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 117.855759
last_received_ts = 117.855400
last_seq = 2861
current_ts = 117.872871
current_received_ts = 117.872414
current_seq = 2862
count = 88
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 117.855759/2861, current 117.872871/2862: elapsed=17107.0us expected=17167.9us +- 85.8us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 117.872871
last_received_ts = 117.872414
last_seq = 2862
current_ts = 117.889977
current_received_ts = 117.889542
current_seq = 2863
count = 89
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 117.872871/2862, current 117.889977/2863: elapsed=17108.0us expected=17167.9us +- 85.8us, error 0.3%
(kms_flip:2181) DEBUG: name = flip
last_ts = 117.889977
last_received_ts = 117.889542
last_seq = 2863
current_ts = 117.907089
current_received_ts = 117.906746
current_seq = 2864
count = 90
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 117.889977/2863, current 117.907089/2864: elapsed=17110.0us expected=17167.9us +- 85.8us, error 0.3%
(kms_flip:2181) DEBUG: name = flip
last_ts = 117.907089
last_received_ts = 117.906746
last_seq = 2864
current_ts = 117.924187
current_received_ts = 117.923744
current_seq = 2865
count = 91
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 117.907089/2864, current 117.924187/2865: elapsed=17096.0us expected=17167.9us +- 85.8us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 117.924187
last_received_ts = 117.923744
last_seq = 2865
current_ts = 117.941269
current_received_ts = 117.940857
current_seq = 2866
count = 92
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 117.924187/2865, current 117.941269/2866: elapsed=17089.0us expected=17167.9us +- 85.8us, error 0.5%
(kms_flip:2181) DEBUG: name = flip
last_ts = 117.941269
last_received_ts = 117.940857
last_seq = 2866
current_ts = 117.958313
current_received_ts = 117.957909
current_seq = 2867
count = 93
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 117.941269/2866, current 117.958313/2867: elapsed=17038.0us expected=17167.9us +- 85.8us, error 0.8%
(kms_flip:2181) DEBUG: inconsistent flip ts/seq: last 117.941269/2866, current 117.958313/2867: elapsed=17038.0us expected=17167.9us
(kms_flip:2181) DEBUG: expected 0, counted 93, encoder type 2
(kms_flip:2181) DEBUG: dropped frames, expected 0, counted 93, encoder type 2
(kms_flip:2181) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:2181) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:2181) igt_core-INFO: Stack trace:
(kms_flip:2181) igt_core-INFO:   #0 ../lib/igt_core.c:2051 __igt_fail_assert()
(kms_flip:2181) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:2181) igt_core-INFO:   #2 ../tests/kms_flip.c:1845 run_test()
(kms_flip:2181) igt_core-INFO:   #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
(kms_flip:2181) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:2181) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2181) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2181) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest A-HDMI-A3: FAIL (5.277s)
Starting dynamic subtest: B-HDMI-A3
(kms_flip:2181) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:2181) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest B-HDMI-A3 failed.
**** DEBUG ****
(kms_flip:2181) DEBUG: flip ts/seq: last 121.904137/91, current 121.921066/92: elapsed=16931.0us expected=16928.4us +- 84.6us, error 0.0%
(kms_flip:2181) DEBUG: name = flip
last_ts = 121.921066
last_received_ts = 121.920700
last_seq = 92
current_ts = 121.937981
current_received_ts = 121.937576
current_seq = 93
count = 10
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 121.921066/92, current 121.937981/93: elapsed=16914.0us expected=16928.4us +- 84.6us, error 0.1%
(kms_flip:2181) DEBUG: name = flip
last_ts = 121.937981
last_received_ts = 121.937576
last_seq = 93
current_ts = 121.954872
current_received_ts = 121.954445
current_seq = 94
count = 11
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 121.937981/93, current 121.954872/94: elapsed=16893.0us expected=16928.4us +- 84.6us, error 0.2%
(kms_flip:2181) DEBUG: name = flip
last_ts = 121.954872
last_received_ts = 121.954445
last_seq = 94
current_ts = 121.971771
current_received_ts = 121.971336
current_seq = 95
count = 12
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 121.954872/94, current 121.971771/95: elapsed=16896.0us expected=16928.4us +- 84.6us, error 0.2%
(kms_flip:2181) DEBUG: name = flip
last_ts = 121.971771
last_received_ts = 121.971336
last_seq = 95
current_ts = 121.988670
current_received_ts = 121.988327
current_seq = 96
count = 13
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 121.971771/95, current 121.988670/96: elapsed=16897.0us expected=16928.4us +- 84.6us, error 0.2%
(kms_flip:2181) DEBUG: name = flip
last_ts = 121.988670
last_received_ts = 121.988327
last_seq = 96
current_ts = 122.005562
current_received_ts = 122.005188
current_seq = 97
count = 14
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 121.988670/96, current 122.005562/97: elapsed=16897.0us expected=16928.4us +- 84.6us, error 0.2%
(kms_flip:2181) DEBUG: name = flip
last_ts = 122.005562
last_received_ts = 122.005188
last_seq = 97
current_ts = 122.022469
current_received_ts = 122.022133
current_seq = 98
count = 15
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 122.005562/97, current 122.022469/98: elapsed=16903.0us expected=16928.4us +- 84.6us, error 0.2%
(kms_flip:2181) DEBUG: name = flip
last_ts = 122.022469
last_received_ts = 122.022133
last_seq = 98
current_ts = 122.039368
current_received_ts = 122.039116
current_seq = 99
count = 16
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 122.022469/98, current 122.039368/99: elapsed=16899.0us expected=16928.4us +- 84.6us, error 0.2%
(kms_flip:2181) DEBUG: name = flip
last_ts = 122.039368
last_received_ts = 122.039116
last_seq = 99
current_ts = 122.056259
current_received_ts = 122.055969
current_seq = 100
count = 17
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 122.039368/99, current 122.056259/100: elapsed=16892.0us expected=16928.4us +- 84.6us, error 0.2%
(kms_flip:2181) DEBUG: name = flip
last_ts = 122.056259
last_received_ts = 122.055969
last_seq = 100
current_ts = 122.073158
current_received_ts = 122.072777
current_seq = 101
count = 18
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 122.056259/100, current 122.073158/101: elapsed=16897.0us expected=16928.4us +- 84.6us, error 0.2%
(kms_flip:2181) DEBUG: name = flip
last_ts = 122.073158
last_received_ts = 122.072777
last_seq = 101
current_ts = 122.090050
current_received_ts = 122.089737
current_seq = 102
count = 19
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 122.073158/101, current 122.090050/102: elapsed=16891.0us expected=16928.4us +- 84.6us, error 0.2%
(kms_flip:2181) DEBUG: name = flip
last_ts = 122.090050
last_received_ts = 122.089737
last_seq = 102
current_ts = 122.106956
current_received_ts = 122.106560
current_seq = 103
count = 20
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 122.090050/102, current 122.106956/103: elapsed=16906.0us expected=16928.4us +- 84.6us, error 0.1%
(kms_flip:2181) DEBUG: name = flip
last_ts = 122.106956
last_received_ts = 122.106560
last_seq = 103
current_ts = 122.123840
current_received_ts = 122.123459
current_seq = 104
count = 21
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 122.106956/103, current 122.123840/104: elapsed=16885.0us expected=16928.4us +- 84.6us, error 0.3%
(kms_flip:2181) DEBUG: name = flip
last_ts = 122.123840
last_received_ts = 122.123459
last_seq = 104
current_ts = 122.140739
current_received_ts = 122.140335
current_seq = 105
count = 22
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 122.123840/104, current 122.140739/105: elapsed=16898.0us expected=16928.4us +- 84.6us, error 0.2%
(kms_flip:2181) DEBUG: name = flip
last_ts = 122.140739
last_received_ts = 122.140335
last_seq = 105
current_ts = 122.157639
current_received_ts = 122.157387
current_seq = 106
count = 23
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 122.140739/105, current 122.157639/106: elapsed=16899.0us expected=16928.4us +- 84.6us, error 0.2%
(kms_flip:2181) DEBUG: name = flip
last_ts = 122.157639
last_received_ts = 122.157387
last_seq = 106
current_ts = 122.174530
current_received_ts = 122.174179
current_seq = 107
count = 24
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 122.157639/106, current 122.174530/107: elapsed=16898.0us expected=16928.4us +- 84.6us, error 0.2%
(kms_flip:2181) DEBUG: name = flip
last_ts = 122.174530
last_received_ts = 122.174179
last_seq = 107
current_ts = 122.191422
current_received_ts = 122.191078
current_seq = 108
count = 25
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 122.174530/107, current 122.191422/108: elapsed=16889.0us expected=16928.4us +- 84.6us, error 0.2%
(kms_flip:2181) DEBUG: name = flip
last_ts = 122.191422
last_received_ts = 122.191078
last_seq = 108
current_ts = 122.208328
current_received_ts = 122.207939
current_seq = 109
count = 26
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 122.191422/108, current 122.208328/109: elapsed=16907.0us expected=16928.4us +- 84.6us, error 0.1%
(kms_flip:2181) DEBUG: name = flip
last_ts = 122.208328
last_received_ts = 122.207939
last_seq = 109
current_ts = 122.225220
current_received_ts = 122.224823
current_seq = 110
count = 27
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 122.208328/109, current 122.225220/110: elapsed=16889.0us expected=16928.4us +- 84.6us, error 0.2%
(kms_flip:2181) DEBUG: name = flip
last_ts = 122.225220
last_received_ts = 122.224823
last_seq = 110
current_ts = 122.242119
current_received_ts = 122.241714
current_seq = 111
count = 28
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 122.225220/110, current 122.242119/111: elapsed=16901.0us expected=16928.4us +- 84.6us, error 0.2%
(kms_flip:2181) DEBUG: name = flip
last_ts = 122.242119
last_received_ts = 122.241714
last_seq = 111
current_ts = 122.259018
current_received_ts = 122.258713
current_seq = 112
count = 29
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 122.242119/111, current 122.259018/112: elapsed=16897.0us expected=16928.4us +- 84.6us, error 0.2%
(kms_flip:2181) DEBUG: name = flip
last_ts = 122.259018
last_received_ts = 122.258713
last_seq = 112
current_ts = 122.275909
current_received_ts = 122.275520
current_seq = 113
count = 30
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 122.259018/112, current 122.275909/113: elapsed=16892.0us expected=16928.4us +- 84.6us, error 0.2%
(kms_flip:2181) DEBUG: name = flip
last_ts = 122.275909
last_received_ts = 122.275520
last_seq = 113
current_ts = 122.292809
current_received_ts = 122.292419
current_seq = 114
count = 31
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 122.275909/113, current 122.292809/114: elapsed=16902.0us expected=16928.4us +- 84.6us, error 0.2%
(kms_flip:2181) DEBUG: name = flip
last_ts = 122.292809
last_received_ts = 122.292419
last_seq = 114
current_ts = 122.309700
current_received_ts = 122.309319
current_seq = 115
count = 32
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 122.292809/114, current 122.309700/115: elapsed=16889.0us expected=16928.4us +- 84.6us, error 0.2%
(kms_flip:2181) DEBUG: name = flip
last_ts = 122.309700
last_received_ts = 122.309319
last_seq = 115
current_ts = 122.326599
current_received_ts = 122.326340
current_seq = 116
count = 33
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 122.309700/115, current 122.326599/116: elapsed=16900.0us expected=16928.4us +- 84.6us, error 0.2%
(kms_flip:2181) DEBUG: name = flip
last_ts = 122.326599
last_received_ts = 122.326340
last_seq = 116
current_ts = 122.343483
current_received_ts = 122.343147
current_seq = 117
count = 34
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 122.326599/116, current 122.343483/117: elapsed=16887.0us expected=16928.4us +- 84.6us, error 0.2%
(kms_flip:2181) DEBUG: name = flip
last_ts = 122.343483
last_received_ts = 122.343147
last_seq = 117
current_ts = 122.360390
current_received_ts = 122.360069
current_seq = 118
count = 35
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 122.343483/117, current 122.360390/118: elapsed=16906.0us expected=16928.4us +- 84.6us, error 0.1%
(kms_flip:2181) DEBUG: name = flip
last_ts = 122.360390
last_received_ts = 122.360069
last_seq = 118
current_ts = 122.377281
current_received_ts = 122.376884
current_seq = 119
count = 36
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 122.360390/118, current 122.377281/119: elapsed=16890.0us expected=16928.4us +- 84.6us, error 0.2%
(kms_flip:2181) DEBUG: name = flip
last_ts = 122.377281
last_received_ts = 122.376884
last_seq = 119
current_ts = 122.394188
current_received_ts = 122.393784
current_seq = 120
count = 37
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 122.377281/119, current 122.394188/120: elapsed=16906.0us expected=16928.4us +- 84.6us, error 0.1%
(kms_flip:2181) DEBUG: name = flip
last_ts = 122.394188
last_received_ts = 122.393784
last_seq = 120
current_ts = 122.411072
current_received_ts = 122.410690
current_seq = 121
count = 38
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 122.394188/120, current 122.411072/121: elapsed=16887.0us expected=16928.4us +- 84.6us, error 0.2%
(kms_flip:2181) DEBUG: name = flip
last_ts = 122.411072
last_received_ts = 122.410690
last_seq = 121
current_ts = 122.427979
current_received_ts = 122.427605
current_seq = 122
count = 39
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 122.411072/121, current 122.427979/122: elapsed=16900.0us expected=16928.4us +- 84.6us, error 0.2%
(kms_flip:2181) DEBUG: name = flip
last_ts = 122.427979
last_received_ts = 122.427605
last_seq = 122
current_ts = 122.444870
current_received_ts = 122.444450
current_seq = 123
count = 40
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 122.427979/122, current 122.444870/123: elapsed=16893.0us expected=16928.4us +- 84.6us, error 0.2%
(kms_flip:2181) DEBUG: name = flip
last_ts = 122.444870
last_received_ts = 122.444450
last_seq = 123
current_ts = 122.461761
current_received_ts = 122.461334
current_seq = 124
count = 41
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 122.444870/123, current 122.461761/124: elapsed=16892.0us expected=16928.4us +- 84.6us, error 0.2%
(kms_flip:2181) DEBUG: name = flip
last_ts = 122.461761
last_received_ts = 122.461334
last_seq = 124
current_ts = 122.478661
current_received_ts = 122.478287
current_seq = 125
count = 42
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 122.461761/124, current 122.478661/125: elapsed=16904.0us expected=16928.4us +- 84.6us, error 0.1%
(kms_flip:2181) DEBUG: name = flip
last_ts = 122.478661
last_received_ts = 122.478287
last_seq = 125
current_ts = 122.495552
current_received_ts = 122.495255
current_seq = 126
count = 43
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 122.478661/125, current 122.495552/126: elapsed=16889.0us expected=16928.4us +- 84.6us, error 0.2%
(kms_flip:2181) DEBUG: name = flip
last_ts = 122.495552
last_received_ts = 122.495255
last_seq = 126
current_ts = 122.512459
current_received_ts = 122.512077
current_seq = 127
count = 44
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 122.495552/126, current 122.512459/127: elapsed=16907.0us expected=16928.4us +- 84.6us, error 0.1%
(kms_flip:2181) DEBUG: name = flip
last_ts = 122.512459
last_received_ts = 122.512077
last_seq = 127
current_ts = 122.529350
current_received_ts = 122.528946
current_seq = 128
count = 45
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 122.512459/127, current 122.529350/128: elapsed=16893.0us expected=16928.4us +- 84.6us, error 0.2%
(kms_flip:2181) DEBUG: name = flip
last_ts = 122.529350
last_received_ts = 122.528946
last_seq = 128
current_ts = 122.546249
current_received_ts = 122.545784
current_seq = 129
count = 46
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 122.529350/128, current 122.546249/129: elapsed=16893.0us expected=16928.4us +- 84.6us, error 0.2%
(kms_flip:2181) DEBUG: name = flip
last_ts = 122.546249
last_received_ts = 122.545784
last_seq = 129
current_ts = 122.563141
current_received_ts = 122.562805
current_seq = 130
count = 47
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 122.546249/129, current 122.563141/130: elapsed=16897.0us expected=16928.4us +- 84.6us, error 0.2%
(kms_flip:2181) DEBUG: name = flip
last_ts = 122.563141
last_received_ts = 122.562805
last_seq = 130
current_ts = 122.580040
current_received_ts = 122.579628
current_seq = 131
count = 48
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 122.563141/130, current 122.580040/131: elapsed=16898.0us expected=16928.4us +- 84.6us, error 0.2%
(kms_flip:2181) DEBUG: name = flip
last_ts = 122.580040
last_received_ts = 122.579628
last_seq = 131
current_ts = 122.596931
current_received_ts = 122.596581
current_seq = 132
count = 49
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 122.580040/131, current 122.596931/132: elapsed=16894.0us expected=16928.4us +- 84.6us, error 0.2%
(kms_flip:2181) DEBUG: name = flip
last_ts = 122.596931
last_received_ts = 122.596581
last_seq = 132
current_ts = 122.613831
current_received_ts = 122.613411
current_seq = 133
count = 50
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 122.596931/132, current 122.613831/133: elapsed=16898.0us expected=16928.4us +- 84.6us, error 0.2%
(kms_flip:2181) DEBUG: name = flip
last_ts = 122.613831
last_received_ts = 122.613411
last_seq = 133
current_ts = 122.630737
current_received_ts = 122.630310
current_seq = 134
count = 51
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 122.613831/133, current 122.630737/134: elapsed=16901.0us expected=16928.4us +- 84.6us, error 0.2%
(kms_flip:2181) DEBUG: name = flip
last_ts = 122.630737
last_received_ts = 122.630310
last_seq = 134
current_ts = 122.647621
current_received_ts = 122.647163
current_seq = 135
count = 52
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 122.630737/134, current 122.647621/135: elapsed=16885.0us expected=16928.4us +- 84.6us, error 0.3%
(kms_flip:2181) DEBUG: name = flip
last_ts = 122.647621
last_received_ts = 122.647163
last_seq = 135
current_ts = 122.664513
current_received_ts = 122.664108
current_seq = 136
count = 53
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 122.647621/135, current 122.664513/136: elapsed=16894.0us expected=16928.4us +- 84.6us, error 0.2%
(kms_flip:2181) DEBUG: name = flip
last_ts = 122.664513
last_received_ts = 122.664108
last_seq = 136
current_ts = 122.681412
current_received_ts = 122.680893
current_seq = 137
count = 54
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 122.664513/136, current 122.681412/137: elapsed=16897.0us expected=16928.4us +- 84.6us, error 0.2%
(kms_flip:2181) DEBUG: name = flip
last_ts = 122.681412
last_received_ts = 122.680893
last_seq = 137
current_ts = 122.698318
current_received_ts = 122.697754
current_seq = 138
count = 55
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 122.681412/137, current 122.698318/138: elapsed=16907.0us expected=16928.4us +- 84.6us, error 0.1%
(kms_flip:2181) DEBUG: name = flip
last_ts = 122.698318
last_received_ts = 122.697754
last_seq = 138
current_ts = 122.715210
current_received_ts = 122.714645
current_seq = 139
count = 56
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 122.698318/138, current 122.715210/139: elapsed=16892.0us expected=16928.4us +- 84.6us, error 0.2%
(kms_flip:2181) DEBUG: name = flip
last_ts = 122.715210
last_received_ts = 122.714645
last_seq = 139
current_ts = 122.732101
current_received_ts = 122.731659
current_seq = 140
count = 57
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 122.715210/139, current 122.732101/140: elapsed=16890.0us expected=16928.4us +- 84.6us, error 0.2%
(kms_flip:2181) DEBUG: name = flip
last_ts = 122.732101
last_received_ts = 122.731659
last_seq = 140
current_ts = 122.749001
current_received_ts = 122.748528
current_seq = 141
count = 58
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 122.732101/140, current 122.749001/141: elapsed=16901.0us expected=16928.4us +- 84.6us, error 0.2%
(kms_flip:2181) DEBUG: name = flip
last_ts = 122.749001
last_received_ts = 122.748528
last_seq = 141
current_ts = 122.765907
current_received_ts = 122.765526
current_seq = 142
count = 59
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 122.749001/141, current 122.765907/142: elapsed=16904.0us expected=16928.4us +- 84.6us, error 0.1%
(kms_flip:2181) DEBUG: name = flip
last_ts = 122.765907
last_received_ts = 122.765526
last_seq = 142
current_ts = 122.782791
current_received_ts = 122.782387
current_seq = 143
count = 60
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 122.765907/142, current 122.782791/143: elapsed=16886.0us expected=16928.4us +- 84.6us, error 0.3%
(kms_flip:2181) DEBUG: name = flip
last_ts = 122.782791
last_received_ts = 122.782387
last_seq = 143
current_ts = 122.799683
current_received_ts = 122.799309
current_seq = 144
count = 61
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 122.782791/143, current 122.799683/144: elapsed=16895.0us expected=16928.4us +- 84.6us, error 0.2%
(kms_flip:2181) DEBUG: name = flip
last_ts = 122.799683
last_received_ts = 122.799309
last_seq = 144
current_ts = 122.816582
current_received_ts = 122.816345
current_seq = 145
count = 62
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 122.799683/144, current 122.816582/145: elapsed=16899.0us expected=16928.4us +- 84.6us, error 0.2%
(kms_flip:2181) DEBUG: name = flip
last_ts = 122.816582
last_received_ts = 122.816345
last_seq = 145
current_ts = 122.833481
current_received_ts = 122.833122
current_seq = 146
count = 63
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 122.816582/145, current 122.833481/146: elapsed=16894.0us expected=16928.4us +- 84.6us, error 0.2%
(kms_flip:2181) DEBUG: name = flip
last_ts = 122.833481
last_received_ts = 122.833122
last_seq = 146
current_ts = 122.850372
current_received_ts = 122.850143
current_seq = 147
count = 64
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 122.833481/146, current 122.850372/147: elapsed=16894.0us expected=16928.4us +- 84.6us, error 0.2%
(kms_flip:2181) DEBUG: name = flip
last_ts = 122.850372
last_received_ts = 122.850143
last_seq = 147
current_ts = 122.867264
current_received_ts = 122.866905
current_seq = 148
count = 65
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 122.850372/147, current 122.867264/148: elapsed=16895.0us expected=16928.4us +- 84.6us, error 0.2%
(kms_flip:2181) DEBUG: name = flip
last_ts = 122.867264
last_received_ts = 122.866905
last_seq = 148
current_ts = 122.884171
current_received_ts = 122.883781
current_seq = 149
count = 66
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 122.867264/148, current 122.884171/149: elapsed=16902.0us expected=16928.4us +- 84.6us, error 0.2%
(kms_flip:2181) DEBUG: name = flip
last_ts = 122.884171
last_received_ts = 122.883781
last_seq = 149
current_ts = 122.901062
current_received_ts = 122.900665
current_seq = 150
count = 67
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 122.884171/149, current 122.901062/150: elapsed=16893.0us expected=16928.4us +- 84.6us, error 0.2%
(kms_flip:2181) DEBUG: name = flip
last_ts = 122.901062
last_received_ts = 122.900665
last_seq = 150
current_ts = 122.917969
current_received_ts = 122.917587
current_seq = 151
count = 68
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 122.901062/150, current 122.917969/151: elapsed=16904.0us expected=16928.4us +- 84.6us, error 0.1%
(kms_flip:2181) DEBUG: name = flip
last_ts = 122.917969
last_received_ts = 122.917587
last_seq = 151
current_ts = 122.934853
current_received_ts = 122.934464
current_seq = 152
count = 69
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 122.917969/151, current 122.934853/152: elapsed=16889.0us expected=16928.4us +- 84.6us, error 0.2%
(kms_flip:2181) DEBUG: name = flip
last_ts = 122.934853
last_received_ts = 122.934464
last_seq = 152
current_ts = 122.951729
current_received_ts = 122.951424
current_seq = 153
count = 70
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 122.934853/152, current 122.951729/153: elapsed=16873.0us expected=16928.4us +- 84.6us, error 0.3%
(kms_flip:2181) DEBUG: name = flip
last_ts = 122.951729
last_received_ts = 122.951424
last_seq = 153
current_ts = 122.968590
current_received_ts = 122.968338
current_seq = 154
count = 71
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 122.951729/153, current 122.968590/154: elapsed=16863.0us expected=16928.4us +- 84.6us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 122.968590
last_received_ts = 122.968338
last_seq = 154
current_ts = 122.985458
current_received_ts = 122.985138
current_seq = 155
count = 72
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 122.968590/154, current 122.985458/155: elapsed=16871.0us expected=16928.4us +- 84.6us, error 0.3%
(kms_flip:2181) DEBUG: name = flip
last_ts = 122.985458
last_received_ts = 122.985138
last_seq = 155
current_ts = 123.002319
current_received_ts = 123.001938
current_seq = 156
count = 73
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 122.985458/155, current 123.002319/156: elapsed=16860.0us expected=16928.4us +- 84.6us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 123.002319
last_received_ts = 123.001938
last_seq = 156
current_ts = 123.019196
current_received_ts = 123.018784
current_seq = 157
count = 74
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 123.002319/156, current 123.019196/157: elapsed=16870.0us expected=16928.4us +- 84.6us, error 0.3%
(kms_flip:2181) DEBUG: name = flip
last_ts = 123.019196
last_received_ts = 123.018784
last_seq = 157
current_ts = 123.036064
current_received_ts = 123.035690
current_seq = 158
count = 75
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 123.019196/157, current 123.036064/158: elapsed=16871.0us expected=16928.4us +- 84.6us, error 0.3%
(kms_flip:2181) DEBUG: name = flip
last_ts = 123.036064
last_received_ts = 123.035690
last_seq = 158
current_ts = 123.052933
current_received_ts = 123.052528
current_seq = 159
count = 76
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 123.036064/158, current 123.052933/159: elapsed=16868.0us expected=16928.4us +- 84.6us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 123.052933
last_received_ts = 123.052528
last_seq = 159
current_ts = 123.069809
current_received_ts = 123.069366
current_seq = 160
count = 77
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 123.052933/159, current 123.069809/160: elapsed=16879.0us expected=16928.4us +- 84.6us, error 0.3%
(kms_flip:2181) DEBUG: name = flip
last_ts = 123.069809
last_received_ts = 123.069366
last_seq = 160
current_ts = 123.086670
current_received_ts = 123.086418
current_seq = 161
count = 78
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 123.069809/160, current 123.086670/161: elapsed=16858.0us expected=16928.4us +- 84.6us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 123.086670
last_received_ts = 123.086418
last_seq = 161
current_ts = 123.103539
current_received_ts = 123.103226
current_seq = 162
count = 79
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 123.086670/161, current 123.103539/162: elapsed=16871.0us expected=16928.4us +- 84.6us, error 0.3%
(kms_flip:2181) DEBUG: name = flip
last_ts = 123.103539
last_received_ts = 123.103226
last_seq = 162
current_ts = 123.120415
current_received_ts = 123.120056
current_seq = 163
count = 80
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 123.103539/162, current 123.120415/163: elapsed=16874.0us expected=16928.4us +- 84.6us, error 0.3%
(kms_flip:2181) DEBUG: name = flip
last_ts = 123.120415
last_received_ts = 123.120056
last_seq = 163
current_ts = 123.137276
current_received_ts = 123.136894
current_seq = 164
count = 81
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 123.120415/163, current 123.137276/164: elapsed=16865.0us expected=16928.4us +- 84.6us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 123.137276
last_received_ts = 123.136894
last_seq = 164
current_ts = 123.154144
current_received_ts = 123.153748
current_seq = 165
count = 82
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 123.137276/164, current 123.154144/165: elapsed=16863.0us expected=16928.4us +- 84.6us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 123.154144
last_received_ts = 123.153748
last_seq = 165
current_ts = 123.171021
current_received_ts = 123.170715
current_seq = 166
count = 83
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 123.154144/165, current 123.171021/166: elapsed=16879.0us expected=16928.4us +- 84.6us, error 0.3%
(kms_flip:2181) DEBUG: name = flip
last_ts = 123.171021
last_received_ts = 123.170715
last_seq = 166
current_ts = 123.187889
current_received_ts = 123.187477
current_seq = 167
count = 84
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 123.171021/166, current 123.187889/167: elapsed=16868.0us expected=16928.4us +- 84.6us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 123.187889
last_received_ts = 123.187477
last_seq = 167
current_ts = 123.204742
current_received_ts = 123.204445
current_seq = 168
count = 85
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 123.187889/167, current 123.204742/168: elapsed=16858.0us expected=16928.4us +- 84.6us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 123.204742
last_received_ts = 123.204445
last_seq = 168
current_ts = 123.221619
current_received_ts = 123.221291
current_seq = 169
count = 86
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 123.204742/168, current 123.221619/169: elapsed=16873.0us expected=16928.4us +- 84.6us, error 0.3%
(kms_flip:2181) DEBUG: name = flip
last_ts = 123.221619
last_received_ts = 123.221291
last_seq = 169
current_ts = 123.238487
current_received_ts = 123.238129
current_seq = 170
count = 87
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 123.221619/169, current 123.238487/170: elapsed=16870.0us expected=16928.4us +- 84.6us, error 0.3%
(kms_flip:2181) DEBUG: name = flip
last_ts = 123.238487
last_received_ts = 123.238129
last_seq = 170
current_ts = 123.255348
current_received_ts = 123.254951
current_seq = 171
count = 88
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 123.238487/170, current 123.255348/171: elapsed=16863.0us expected=16928.4us +- 84.6us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 123.255348
last_received_ts = 123.254951
last_seq = 171
current_ts = 123.272232
current_received_ts = 123.271866
current_seq = 172
count = 89
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 123.255348/171, current 123.272232/172: elapsed=16877.0us expected=16928.4us +- 84.6us, error 0.3%
(kms_flip:2181) DEBUG: name = flip
last_ts = 123.272232
last_received_ts = 123.271866
last_seq = 172
current_ts = 123.289093
current_received_ts = 123.288719
current_seq = 173
count = 90
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 123.272232/172, current 123.289093/173: elapsed=16863.0us expected=16928.4us +- 84.6us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 123.289093
last_received_ts = 123.288719
last_seq = 173
current_ts = 123.305962
current_received_ts = 123.305565
current_seq = 174
count = 91
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 123.289093/173, current 123.305962/174: elapsed=16867.0us expected=16928.4us +- 84.6us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 123.305962
last_received_ts = 123.305565
last_seq = 174
current_ts = 123.322830
current_received_ts = 123.322433
current_seq = 175
count = 92
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 123.305962/174, current 123.322830/175: elapsed=16868.0us expected=16928.4us +- 84.6us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 123.322830
last_received_ts = 123.322433
last_seq = 175
current_ts = 123.339699
current_received_ts = 123.339287
current_seq = 176
count = 93
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 123.322830/175, current 123.339699/176: elapsed=16868.0us expected=16928.4us +- 84.6us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 123.339699
last_received_ts = 123.339287
last_seq = 176
current_ts = 123.356567
current_received_ts = 123.356148
current_seq = 177
count = 94
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 123.339699/176, current 123.356567/177: elapsed=16874.0us expected=16928.4us +- 84.6us, error 0.3%
(kms_flip:2181) DEBUG: name = flip
last_ts = 123.356567
last_received_ts = 123.356148
last_seq = 177
current_ts = 123.373444
current_received_ts = 123.373108
current_seq = 178
count = 95
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 123.356567/177, current 123.373444/178: elapsed=16874.0us expected=16928.4us +- 84.6us, error 0.3%
(kms_flip:2181) DEBUG: name = flip
last_ts = 123.373444
last_received_ts = 123.373108
last_seq = 178
current_ts = 123.390312
current_received_ts = 123.390060
current_seq = 179
count = 96
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 123.373444/178, current 123.390312/179: elapsed=16868.0us expected=16928.4us +- 84.6us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 123.390312
last_received_ts = 123.390060
last_seq = 179
current_ts = 123.407173
current_received_ts = 123.406883
current_seq = 180
count = 97
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 123.390312/179, current 123.407173/180: elapsed=16864.0us expected=16928.4us +- 84.6us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 123.407173
last_received_ts = 123.406883
last_seq = 180
current_ts = 123.424042
current_received_ts = 123.423691
current_seq = 181
count = 98
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 123.407173/180, current 123.424042/181: elapsed=16870.0us expected=16928.4us +- 84.6us, error 0.3%
(kms_flip:2181) DEBUG: name = flip
last_ts = 123.424042
last_received_ts = 123.423691
last_seq = 181
current_ts = 123.440903
current_received_ts = 123.440544
current_seq = 182
count = 99
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 123.424042/181, current 123.440903/182: elapsed=16860.0us expected=16928.4us +- 84.6us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 123.440903
last_received_ts = 123.440544
last_seq = 182
current_ts = 123.457787
current_received_ts = 123.457336
current_seq = 183
count = 100
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 123.440903/182, current 123.457787/183: elapsed=16880.0us expected=16928.4us +- 84.6us, error 0.3%
(kms_flip:2181) DEBUG: name = flip
last_ts = 123.457787
last_received_ts = 123.457336
last_seq = 183
current_ts = 123.474655
current_received_ts = 123.474258
current_seq = 184
count = 101
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 123.457787/183, current 123.474655/184: elapsed=16868.0us expected=16928.4us +- 84.6us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 123.474655
last_received_ts = 123.474258
last_seq = 184
current_ts = 123.491516
current_received_ts = 123.491165
current_seq = 185
count = 102
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 123.474655/184, current 123.491516/185: elapsed=16862.0us expected=16928.4us +- 84.6us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 123.491516
last_received_ts = 123.491165
last_seq = 185
current_ts = 123.508377
current_received_ts = 123.508118
current_seq = 186
count = 103
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 123.491516/185, current 123.508377/186: elapsed=16865.0us expected=16928.4us +- 84.6us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 123.508377
last_received_ts = 123.508118
last_seq = 186
current_ts = 123.525253
current_received_ts = 123.524895
current_seq = 187
count = 104
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 123.508377/186, current 123.525253/187: elapsed=16872.0us expected=16928.4us +- 84.6us, error 0.3%
(kms_flip:2181) DEBUG: name = flip
last_ts = 123.525253
last_received_ts = 123.524895
last_seq = 187
current_ts = 123.542130
current_received_ts = 123.541748
current_seq = 188
count = 105
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 123.525253/187, current 123.542130/188: elapsed=16878.0us expected=16928.4us +- 84.6us, error 0.3%
(kms_flip:2181) DEBUG: name = flip
last_ts = 123.542130
last_received_ts = 123.541748
last_seq = 188
current_ts = 123.558990
current_received_ts = 123.558586
current_seq = 189
count = 106
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 123.542130/188, current 123.558990/189: elapsed=16857.0us expected=16928.4us +- 84.6us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 123.558990
last_received_ts = 123.558586
last_seq = 189
current_ts = 123.575859
current_received_ts = 123.575439
current_seq = 190
count = 107
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 123.558990/189, current 123.575859/190: elapsed=16871.0us expected=16928.4us +- 84.6us, error 0.3%
(kms_flip:2181) DEBUG: name = flip
last_ts = 123.575859
last_received_ts = 123.575439
last_seq = 190
current_ts = 123.592735
current_received_ts = 123.592331
current_seq = 191
count = 108
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 123.575859/190, current 123.592735/191: elapsed=16875.0us expected=16928.4us +- 84.6us, error 0.3%
(kms_flip:2181) DEBUG: name = flip
last_ts = 123.592735
last_received_ts = 123.592331
last_seq = 191
current_ts = 123.609604
current_received_ts = 123.609177
current_seq = 192
count = 109
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 123.592735/191, current 123.609604/192: elapsed=16869.0us expected=16928.4us +- 84.6us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 123.609604
last_received_ts = 123.609177
last_seq = 192
current_ts = 123.626472
current_received_ts = 123.626122
current_seq = 193
count = 110
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 123.609604/192, current 123.626472/193: elapsed=16871.0us expected=16928.4us +- 84.6us, error 0.3%
(kms_flip:2181) DEBUG: name = flip
last_ts = 123.626472
last_received_ts = 123.626122
last_seq = 193
current_ts = 123.643341
current_received_ts = 123.642960
current_seq = 194
count = 111
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 123.626472/193, current 123.643341/194: elapsed=16867.0us expected=16928.4us +- 84.6us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 123.643341
last_received_ts = 123.642960
last_seq = 194
current_ts = 123.660194
current_received_ts = 123.659805
current_seq = 195
count = 112
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 123.643341/194, current 123.660194/195: elapsed=16858.0us expected=16928.4us +- 84.6us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 123.660194
last_received_ts = 123.659805
last_seq = 195
current_ts = 123.677071
current_received_ts = 123.676712
current_seq = 196
count = 113
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 123.660194/195, current 123.677071/196: elapsed=16874.0us expected=16928.4us +- 84.6us, error 0.3%
(kms_flip:2181) DEBUG: name = flip
last_ts = 123.677071
last_received_ts = 123.676712
last_seq = 196
current_ts = 123.693932
current_received_ts = 123.693550
current_seq = 197
count = 114
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 123.677071/196, current 123.693932/197: elapsed=16862.0us expected=16928.4us +- 84.6us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 123.693932
last_received_ts = 123.693550
last_seq = 197
current_ts = 123.710808
current_received_ts = 123.710411
current_seq = 198
count = 115
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 123.693932/197, current 123.710808/198: elapsed=16876.0us expected=16928.4us +- 84.6us, error 0.3%
(kms_flip:2181) DEBUG: name = flip
last_ts = 123.710808
last_received_ts = 123.710411
last_seq = 198
current_ts = 123.727676
current_received_ts = 123.727272
current_seq = 199
count = 116
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 123.710808/198, current 123.727676/199: elapsed=16870.0us expected=16928.4us +- 84.6us, error 0.3%
(kms_flip:2181) DEBUG: name = flip
last_ts = 123.727676
last_received_ts = 123.727272
last_seq = 199
current_ts = 123.744553
current_received_ts = 123.744194
current_seq = 200
count = 117
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 123.727676/199, current 123.744553/200: elapsed=16871.0us expected=16928.4us +- 84.6us, error 0.3%
(kms_flip:2181) DEBUG: name = flip
last_ts = 123.744553
last_received_ts = 123.744194
last_seq = 200
current_ts = 123.761406
current_received_ts = 123.761070
current_seq = 201
count = 118
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 123.744553/200, current 123.761406/201: elapsed=16858.0us expected=16928.4us +- 84.6us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 123.761406
last_received_ts = 123.761070
last_seq = 201
current_ts = 123.778282
current_received_ts = 123.777885
current_seq = 202
count = 119
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 123.761406/201, current 123.778282/202: elapsed=16871.0us expected=16928.4us +- 84.6us, error 0.3%
(kms_flip:2181) DEBUG: name = flip
last_ts = 123.778282
last_received_ts = 123.777885
last_seq = 202
current_ts = 123.795158
current_received_ts = 123.794853
current_seq = 203
count = 120
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 123.778282/202, current 123.795158/203: elapsed=16877.0us expected=16928.4us +- 84.6us, error 0.3%
(kms_flip:2181) DEBUG: name = flip
last_ts = 123.795158
last_received_ts = 123.794853
last_seq = 203
current_ts = 123.812012
current_received_ts = 123.811646
current_seq = 204
count = 121
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 123.795158/203, current 123.812012/204: elapsed=16858.0us expected=16928.4us +- 84.6us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 123.812012
last_received_ts = 123.811646
last_seq = 204
current_ts = 123.828888
current_received_ts = 123.828476
current_seq = 205
count = 122
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 123.812012/204, current 123.828888/205: elapsed=16872.0us expected=16928.4us +- 84.6us, error 0.3%
(kms_flip:2181) DEBUG: name = flip
last_ts = 123.828888
last_received_ts = 123.828476
last_seq = 205
current_ts = 123.845764
current_received_ts = 123.845428
current_seq = 206
count = 123
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 123.828888/205, current 123.845764/206: elapsed=16878.0us expected=16928.4us +- 84.6us, error 0.3%
(kms_flip:2181) DEBUG: name = flip
last_ts = 123.845764
last_received_ts = 123.845428
last_seq = 206
current_ts = 123.862625
current_received_ts = 123.862221
current_seq = 207
count = 124
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 123.845764/206, current 123.862625/207: elapsed=16862.0us expected=16928.4us +- 84.6us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 123.862625
last_received_ts = 123.862221
last_seq = 207
current_ts = 123.879501
current_received_ts = 123.879135
current_seq = 208
count = 125
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 123.862625/207, current 123.879501/208: elapsed=16873.0us expected=16928.4us +- 84.6us, error 0.3%
(kms_flip:2181) DEBUG: name = flip
last_ts = 123.879501
last_received_ts = 123.879135
last_seq = 208
current_ts = 123.896362
current_received_ts = 123.895973
current_seq = 209
count = 126
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 123.879501/208, current 123.896362/209: elapsed=16864.0us expected=16928.4us +- 84.6us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 123.896362
last_received_ts = 123.895973
last_seq = 209
current_ts = 123.913231
current_received_ts = 123.912933
current_seq = 210
count = 127
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 123.896362/209, current 123.913231/210: elapsed=16870.0us expected=16928.4us +- 84.6us, error 0.3%
(kms_flip:2181) DEBUG: name = flip
last_ts = 123.913231
last_received_ts = 123.912933
last_seq = 210
current_ts = 123.930099
current_received_ts = 123.929726
current_seq = 211
count = 128
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 123.913231/210, current 123.930099/211: elapsed=16867.0us expected=16928.4us +- 84.6us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 123.930099
last_received_ts = 123.929726
last_seq = 211
current_ts = 123.946938
current_received_ts = 123.946541
current_seq = 212
count = 129
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 123.930099/211, current 123.946938/212: elapsed=16840.0us expected=16928.4us +- 84.6us, error 0.5%
(kms_flip:2181) DEBUG: inconsistent flip ts/seq: last 123.930099/211, current 123.946938/212: elapsed=16840.0us expected=16928.4us
(kms_flip:2181) DEBUG: expected 0, counted 129, encoder type 2
(kms_flip:2181) DEBUG: dropped frames, expected 0, counted 129, encoder type 2
(kms_flip:2181) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:2181) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:2181) igt_core-INFO: Stack trace:
(kms_flip:2181) igt_core-INFO:   #0 ../lib/igt_core.c:2051 __igt_fail_assert()
(kms_flip:2181) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:2181) igt_core-INFO:   #2 ../tests/kms_flip.c:1845 run_test()
(kms_flip:2181) igt_core-INFO:   #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
(kms_flip:2181) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:2181) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2181) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2181) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-HDMI-A3: FAIL (5.897s)
Starting dynamic subtest: C-HDMI-A3
(kms_flip:2181) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:2181) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest C-HDMI-A3 failed.
**** DEBUG ****
(kms_flip:2181) DEBUG: name = flip
last_ts = 133.160522
last_received_ts = 133.160110
last_seq = 408
current_ts = 133.177231
current_received_ts = 133.176895
current_seq = 409
count = 327
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 133.160522/408, current 133.177231/409: elapsed=16717.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 133.177231
last_received_ts = 133.176895
last_seq = 409
current_ts = 133.193970
current_received_ts = 133.193542
current_seq = 410
count = 328
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 133.177231/409, current 133.193970/410: elapsed=16732.0us expected=16789.1us +- 83.9us, error 0.3%
(kms_flip:2181) DEBUG: name = flip
last_ts = 133.193970
last_received_ts = 133.193542
last_seq = 410
current_ts = 133.210693
current_received_ts = 133.210373
current_seq = 411
count = 329
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 133.193970/410, current 133.210693/411: elapsed=16730.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 133.210693
last_received_ts = 133.210373
last_seq = 411
current_ts = 133.227417
current_received_ts = 133.227127
current_seq = 412
count = 330
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 133.210693/411, current 133.227417/412: elapsed=16722.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 133.227417
last_received_ts = 133.227127
last_seq = 412
current_ts = 133.244141
current_received_ts = 133.243805
current_seq = 413
count = 331
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 133.227417/412, current 133.244141/413: elapsed=16722.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 133.244141
last_received_ts = 133.243805
last_seq = 413
current_ts = 133.260864
current_received_ts = 133.260422
current_seq = 414
count = 332
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 133.244141/413, current 133.260864/414: elapsed=16721.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 133.260864
last_received_ts = 133.260422
last_seq = 414
current_ts = 133.277588
current_received_ts = 133.277191
current_seq = 415
count = 333
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 133.260864/414, current 133.277588/415: elapsed=16729.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 133.277588
last_received_ts = 133.277191
last_seq = 415
current_ts = 133.294327
current_received_ts = 133.294037
current_seq = 416
count = 334
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 133.277588/415, current 133.294327/416: elapsed=16730.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 133.294327
last_received_ts = 133.294037
last_seq = 416
current_ts = 133.311050
current_received_ts = 133.310593
current_seq = 417
count = 335
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 133.294327/416, current 133.311050/417: elapsed=16731.0us expected=16789.1us +- 83.9us, error 0.3%
(kms_flip:2181) DEBUG: name = flip
last_ts = 133.311050
last_received_ts = 133.310593
last_seq = 417
current_ts = 133.327774
current_received_ts = 133.327362
current_seq = 418
count = 336
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 133.311050/417, current 133.327774/418: elapsed=16722.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 133.327774
last_received_ts = 133.327362
last_seq = 418
current_ts = 133.344498
current_received_ts = 133.344177
current_seq = 419
count = 337
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 133.327774/418, current 133.344498/419: elapsed=16721.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 133.344498
last_received_ts = 133.344177
last_seq = 419
current_ts = 133.361237
current_received_ts = 133.360916
current_seq = 420
count = 338
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 133.344498/419, current 133.361237/420: elapsed=16736.0us expected=16789.1us +- 83.9us, error 0.3%
(kms_flip:2181) DEBUG: name = flip
last_ts = 133.361237
last_received_ts = 133.360916
last_seq = 420
current_ts = 133.377960
current_received_ts = 133.377518
current_seq = 421
count = 339
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 133.361237/420, current 133.377960/421: elapsed=16724.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 133.377960
last_received_ts = 133.377518
last_seq = 421
current_ts = 133.394684
current_received_ts = 133.394257
current_seq = 422
count = 340
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 133.377960/421, current 133.394684/422: elapsed=16726.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 133.394684
last_received_ts = 133.394257
last_seq = 422
current_ts = 133.411407
current_received_ts = 133.411102
current_seq = 423
count = 341
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 133.394684/422, current 133.411407/423: elapsed=16716.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 133.411407
last_received_ts = 133.411102
last_seq = 423
current_ts = 133.428131
current_received_ts = 133.427795
current_seq = 424
count = 342
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 133.411407/423, current 133.428131/424: elapsed=16734.0us expected=16789.1us +- 83.9us, error 0.3%
(kms_flip:2181) DEBUG: name = flip
last_ts = 133.428131
last_received_ts = 133.427795
last_seq = 424
current_ts = 133.444855
current_received_ts = 133.444397
current_seq = 425
count = 343
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 133.428131/424, current 133.444855/425: elapsed=16722.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 133.444855
last_received_ts = 133.444397
last_seq = 425
current_ts = 133.461594
current_received_ts = 133.461197
current_seq = 426
count = 344
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 133.444855/425, current 133.461594/426: elapsed=16734.0us expected=16789.1us +- 83.9us, error 0.3%
(kms_flip:2181) DEBUG: name = flip
last_ts = 133.461594
last_received_ts = 133.461197
last_seq = 426
current_ts = 133.478317
current_received_ts = 133.477890
current_seq = 427
count = 345
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 133.461594/426, current 133.478317/427: elapsed=16725.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 133.478317
last_received_ts = 133.477890
last_seq = 427
current_ts = 133.495041
current_received_ts = 133.494598
current_seq = 428
count = 346
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 133.478317/427, current 133.495041/428: elapsed=16723.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 133.495041
last_received_ts = 133.494598
last_seq = 428
current_ts = 133.511765
current_received_ts = 133.511322
current_seq = 429
count = 347
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 133.495041/428, current 133.511765/429: elapsed=16726.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 133.511765
last_received_ts = 133.511322
last_seq = 429
current_ts = 133.528488
current_received_ts = 133.528107
current_seq = 430
count = 348
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 133.511765/429, current 133.528488/430: elapsed=16729.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 133.528488
last_received_ts = 133.528107
last_seq = 430
current_ts = 133.545212
current_received_ts = 133.544800
current_seq = 431
count = 349
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 133.528488/430, current 133.545212/431: elapsed=16726.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 133.545212
last_received_ts = 133.544800
last_seq = 431
current_ts = 133.561951
current_received_ts = 133.561554
current_seq = 432
count = 350
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 133.545212/431, current 133.561951/432: elapsed=16728.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 133.561951
last_received_ts = 133.561554
last_seq = 432
current_ts = 133.578659
current_received_ts = 133.578232
current_seq = 433
count = 351
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 133.561951/432, current 133.578659/433: elapsed=16718.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 133.578659
last_received_ts = 133.578232
last_seq = 433
current_ts = 133.595398
current_received_ts = 133.594986
current_seq = 434
count = 352
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 133.578659/433, current 133.595398/434: elapsed=16732.0us expected=16789.1us +- 83.9us, error 0.3%
(kms_flip:2181) DEBUG: name = flip
last_ts = 133.595398
last_received_ts = 133.594986
last_seq = 434
current_ts = 133.612122
current_received_ts = 133.611801
current_seq = 435
count = 353
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 133.595398/434, current 133.612122/435: elapsed=16726.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 133.612122
last_received_ts = 133.611801
last_seq = 435
current_ts = 133.628845
current_received_ts = 133.628403
current_seq = 436
count = 354
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 133.612122/435, current 133.628845/436: elapsed=16720.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 133.628845
last_received_ts = 133.628403
last_seq = 436
current_ts = 133.645569
current_received_ts = 133.645279
current_seq = 437
count = 355
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 133.628845/436, current 133.645569/437: elapsed=16728.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 133.645569
last_received_ts = 133.645279
last_seq = 437
current_ts = 133.662308
current_received_ts = 133.661987
current_seq = 438
count = 356
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 133.645569/437, current 133.662308/438: elapsed=16735.0us expected=16789.1us +- 83.9us, error 0.3%
(kms_flip:2181) DEBUG: name = flip
last_ts = 133.662308
last_received_ts = 133.661987
last_seq = 438
current_ts = 133.679016
current_received_ts = 133.678574
current_seq = 439
count = 357
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 133.662308/438, current 133.679016/439: elapsed=16714.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 133.679016
last_received_ts = 133.678574
last_seq = 439
current_ts = 133.695755
current_received_ts = 133.695312
current_seq = 440
count = 358
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 133.679016/439, current 133.695755/440: elapsed=16738.0us expected=16789.1us +- 83.9us, error 0.3%
(kms_flip:2181) DEBUG: name = flip
last_ts = 133.695755
last_received_ts = 133.695312
last_seq = 440
current_ts = 133.712479
current_received_ts = 133.712112
current_seq = 441
count = 359
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 133.695755/440, current 133.712479/441: elapsed=16720.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 133.712479
last_received_ts = 133.712112
last_seq = 441
current_ts = 133.729202
current_received_ts = 133.728760
current_seq = 442
count = 360
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 133.712479/441, current 133.729202/442: elapsed=16725.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 133.729202
last_received_ts = 133.728760
last_seq = 442
current_ts = 133.745926
current_received_ts = 133.745438
current_seq = 443
count = 361
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 133.729202/442, current 133.745926/443: elapsed=16728.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 133.745926
last_received_ts = 133.745438
last_seq = 443
current_ts = 133.762665
current_received_ts = 133.762268
current_seq = 444
count = 362
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 133.745926/443, current 133.762665/444: elapsed=16727.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 133.762665
last_received_ts = 133.762268
last_seq = 444
current_ts = 133.779388
current_received_ts = 133.779083
current_seq = 445
count = 363
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 133.762665/444, current 133.779388/445: elapsed=16723.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 133.779388
last_received_ts = 133.779083
last_seq = 445
current_ts = 133.796112
current_received_ts = 133.795685
current_seq = 446
count = 364
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 133.779388/445, current 133.796112/446: elapsed=16730.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 133.796112
last_received_ts = 133.795685
last_seq = 446
current_ts = 133.812836
current_received_ts = 133.812378
current_seq = 447
count = 365
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 133.796112/446, current 133.812836/447: elapsed=16719.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 133.812836
last_received_ts = 133.812378
last_seq = 447
current_ts = 133.829559
current_received_ts = 133.829254
current_seq = 448
count = 366
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 133.812836/447, current 133.829559/448: elapsed=16729.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 133.829559
last_received_ts = 133.829254
last_seq = 448
current_ts = 133.846298
current_received_ts = 133.845978
current_seq = 449
count = 367
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 133.829559/448, current 133.846298/449: elapsed=16734.0us expected=16789.1us +- 83.9us, error 0.3%
(kms_flip:2181) DEBUG: name = flip
last_ts = 133.846298
last_received_ts = 133.845978
last_seq = 449
current_ts = 133.863022
current_received_ts = 133.862610
current_seq = 450
count = 368
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 133.846298/449, current 133.863022/450: elapsed=16725.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 133.863022
last_received_ts = 133.862610
last_seq = 450
current_ts = 133.879745
current_received_ts = 133.879333
current_seq = 451
count = 369
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 133.863022/450, current 133.879745/451: elapsed=16724.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 133.879745
last_received_ts = 133.879333
last_seq = 451
current_ts = 133.896469
current_received_ts = 133.896225
current_seq = 452
count = 370
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 133.879745/451, current 133.896469/452: elapsed=16724.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 133.896469
last_received_ts = 133.896225
last_seq = 452
current_ts = 133.913193
current_received_ts = 133.912842
current_seq = 453
count = 371
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 133.896469/452, current 133.913193/453: elapsed=16732.0us expected=16789.1us +- 83.9us, error 0.3%
(kms_flip:2181) DEBUG: name = flip
last_ts = 133.913193
last_received_ts = 133.912842
last_seq = 453
current_ts = 133.929932
current_received_ts = 133.929504
current_seq = 454
count = 372
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 133.913193/453, current 133.929932/454: elapsed=16726.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 133.929932
last_received_ts = 133.929504
last_seq = 454
current_ts = 133.946640
current_received_ts = 133.946243
current_seq = 455
count = 373
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 133.929932/454, current 133.946640/455: elapsed=16713.0us expected=16789.1us +- 83.9us, error 0.5%
(kms_flip:2181) DEBUG: name = flip
last_ts = 133.946640
last_received_ts = 133.946243
last_seq = 455
current_ts = 133.963364
current_received_ts = 133.963058
current_seq = 456
count = 374
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 133.946640/455, current 133.963364/456: elapsed=16729.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 133.963364
last_received_ts = 133.963058
last_seq = 456
current_ts = 133.980072
current_received_ts = 133.979675
current_seq = 457
count = 375
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 133.963364/456, current 133.980072/457: elapsed=16710.0us expected=16789.1us +- 83.9us, error 0.5%
(kms_flip:2181) DEBUG: name = flip
last_ts = 133.980072
last_received_ts = 133.979675
last_seq = 457
current_ts = 133.996796
current_received_ts = 133.996399
current_seq = 458
count = 376
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 133.980072/457, current 133.996796/458: elapsed=16727.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 133.996796
last_received_ts = 133.996399
last_seq = 458
current_ts = 134.013519
current_received_ts = 134.013168
current_seq = 459
count = 377
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 133.996796/458, current 134.013519/459: elapsed=16716.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 134.013519
last_received_ts = 134.013168
last_seq = 459
current_ts = 134.030228
current_received_ts = 134.029861
current_seq = 460
count = 378
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 134.013519/459, current 134.030228/460: elapsed=16714.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 134.030228
last_received_ts = 134.029861
last_seq = 460
current_ts = 134.046951
current_received_ts = 134.046570
current_seq = 461
count = 379
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 134.030228/460, current 134.046951/461: elapsed=16719.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 134.046951
last_received_ts = 134.046570
last_seq = 461
current_ts = 134.063690
current_received_ts = 134.063278
current_seq = 462
count = 380
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 134.046951/461, current 134.063690/462: elapsed=16732.0us expected=16789.1us +- 83.9us, error 0.3%
(kms_flip:2181) DEBUG: name = flip
last_ts = 134.063690
last_received_ts = 134.063278
last_seq = 462
current_ts = 134.080399
current_received_ts = 134.080002
current_seq = 463
count = 381
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 134.063690/462, current 134.080399/463: elapsed=16711.0us expected=16789.1us +- 83.9us, error 0.5%
(kms_flip:2181) DEBUG: name = flip
last_ts = 134.080399
last_received_ts = 134.080002
last_seq = 463
current_ts = 134.097107
current_received_ts = 134.096817
current_seq = 464
count = 382
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 134.080399/463, current 134.097107/464: elapsed=16717.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 134.097107
last_received_ts = 134.096817
last_seq = 464
current_ts = 134.113846
current_received_ts = 134.113449
current_seq = 465
count = 383
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 134.097107/464, current 134.113846/465: elapsed=16727.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 134.113846
last_received_ts = 134.113449
last_seq = 465
current_ts = 134.130554
current_received_ts = 134.130280
current_seq = 466
count = 384
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 134.113846/465, current 134.130554/466: elapsed=16714.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 134.130554
last_received_ts = 134.130280
last_seq = 466
current_ts = 134.147278
current_received_ts = 134.146927
current_seq = 467
count = 385
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 134.130554/466, current 134.147278/467: elapsed=16728.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 134.147278
last_received_ts = 134.146927
last_seq = 467
current_ts = 134.164001
current_received_ts = 134.163635
current_seq = 468
count = 386
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 134.147278/467, current 134.164001/468: elapsed=16717.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 134.164001
last_received_ts = 134.163635
last_seq = 468
current_ts = 134.180725
current_received_ts = 134.180420
current_seq = 469
count = 387
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 134.164001/468, current 134.180725/469: elapsed=16725.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 134.180725
last_received_ts = 134.180420
last_seq = 469
current_ts = 134.197433
current_received_ts = 134.197113
current_seq = 470
count = 388
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 134.180725/469, current 134.197433/470: elapsed=16718.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 134.197433
last_received_ts = 134.197113
last_seq = 470
current_ts = 134.214157
current_received_ts = 134.213791
current_seq = 471
count = 389
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 134.197433/470, current 134.214157/471: elapsed=16714.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 134.214157
last_received_ts = 134.213791
last_seq = 471
current_ts = 134.230865
current_received_ts = 134.230469
current_seq = 472
count = 390
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 134.214157/471, current 134.230865/472: elapsed=16716.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 134.230865
last_received_ts = 134.230469
last_seq = 472
current_ts = 134.247589
current_received_ts = 134.247192
current_seq = 473
count = 391
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 134.230865/472, current 134.247589/473: elapsed=16723.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 134.247589
last_received_ts = 134.247192
last_seq = 473
current_ts = 134.264313
current_received_ts = 134.263947
current_seq = 474
count = 392
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 134.247589/473, current 134.264313/474: elapsed=16716.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 134.264313
last_received_ts = 134.263947
last_seq = 474
current_ts = 134.281036
current_received_ts = 134.280624
current_seq = 475
count = 393
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 134.264313/474, current 134.281036/475: elapsed=16720.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 134.281036
last_received_ts = 134.280624
last_seq = 475
current_ts = 134.297760
current_received_ts = 134.297318
current_seq = 476
count = 394
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 134.281036/475, current 134.297760/476: elapsed=16726.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 134.297760
last_received_ts = 134.297318
last_seq = 476
current_ts = 134.314468
current_received_ts = 134.314224
current_seq = 477
count = 395
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 134.297760/476, current 134.314468/477: elapsed=16717.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 134.314468
last_received_ts = 134.314224
last_seq = 477
current_ts = 134.331192
current_received_ts = 134.330765
current_seq = 478
count = 396
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 134.314468/477, current 134.331192/478: elapsed=16718.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 134.331192
last_received_ts = 134.330765
last_seq = 478
current_ts = 134.347916
current_received_ts = 134.347519
current_seq = 479
count = 397
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 134.331192/478, current 134.347916/479: elapsed=16727.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 134.347916
last_received_ts = 134.347519
last_seq = 479
current_ts = 134.364639
current_received_ts = 134.364304
current_seq = 480
count = 398
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 134.347916/479, current 134.364639/480: elapsed=16721.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 134.364639
last_received_ts = 134.364304
last_seq = 480
current_ts = 134.381363
current_received_ts = 134.381104
current_seq = 481
count = 399
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 134.364639/480, current 134.381363/481: elapsed=16720.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 134.381363
last_received_ts = 134.381104
last_seq = 481
current_ts = 134.398071
current_received_ts = 134.397690
current_seq = 482
count = 400
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 134.381363/481, current 134.398071/482: elapsed=16716.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 134.398071
last_received_ts = 134.397690
last_seq = 482
current_ts = 134.414795
current_received_ts = 134.414368
current_seq = 483
count = 401
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 134.398071/482, current 134.414795/483: elapsed=16715.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 134.414795
last_received_ts = 134.414368
last_seq = 483
current_ts = 134.431519
current_received_ts = 134.431091
current_seq = 484
count = 402
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 134.414795/483, current 134.431519/484: elapsed=16725.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 134.431519
last_received_ts = 134.431091
last_seq = 484
current_ts = 134.448227
current_received_ts = 134.447861
current_seq = 485
count = 403
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 134.431519/484, current 134.448227/485: elapsed=16717.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 134.448227
last_received_ts = 134.447861
last_seq = 485
current_ts = 134.464951
current_received_ts = 134.464523
current_seq = 486
count = 404
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 134.448227/485, current 134.464951/486: elapsed=16717.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 134.464951
last_received_ts = 134.464523
last_seq = 486
current_ts = 134.481674
current_received_ts = 134.481323
current_seq = 487
count = 405
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 134.464951/486, current 134.481674/487: elapsed=16727.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 134.481674
last_received_ts = 134.481323
last_seq = 487
current_ts = 134.498398
current_received_ts = 134.498062
current_seq = 488
count = 406
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 134.481674/487, current 134.498398/488: elapsed=16718.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 134.498398
last_received_ts = 134.498062
last_seq = 488
current_ts = 134.515106
current_received_ts = 134.514755
current_seq = 489
count = 407
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 134.498398/488, current 134.515106/489: elapsed=16713.0us expected=16789.1us +- 83.9us, error 0.5%
(kms_flip:2181) DEBUG: name = flip
last_ts = 134.515106
last_received_ts = 134.514755
last_seq = 489
current_ts = 134.531830
current_received_ts = 134.531418
current_seq = 490
count = 408
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 134.515106/489, current 134.531830/490: elapsed=16723.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 134.531830
last_received_ts = 134.531418
last_seq = 490
current_ts = 134.548553
current_received_ts = 134.548187
current_seq = 491
count = 409
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 134.531830/490, current 134.548553/491: elapsed=16726.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 134.548553
last_received_ts = 134.548187
last_seq = 491
current_ts = 134.565262
current_received_ts = 134.564911
current_seq = 492
count = 410
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 134.548553/491, current 134.565262/492: elapsed=16711.0us expected=16789.1us +- 83.9us, error 0.5%
(kms_flip:2181) DEBUG: name = flip
last_ts = 134.565262
last_received_ts = 134.564911
last_seq = 492
current_ts = 134.582001
current_received_ts = 134.581680
current_seq = 493
count = 411
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 134.565262/492, current 134.582001/493: elapsed=16731.0us expected=16789.1us +- 83.9us, error 0.3%
(kms_flip:2181) DEBUG: name = flip
last_ts = 134.582001
last_received_ts = 134.581680
last_seq = 493
current_ts = 134.598709
current_received_ts = 134.598419
current_seq = 494
count = 412
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 134.582001/493, current 134.598709/494: elapsed=16711.0us expected=16789.1us +- 83.9us, error 0.5%
(kms_flip:2181) DEBUG: name = flip
last_ts = 134.598709
last_received_ts = 134.598419
last_seq = 494
current_ts = 134.615433
current_received_ts = 134.615173
current_seq = 495
count = 413
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 134.598709/494, current 134.615433/495: elapsed=16720.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 134.615433
last_received_ts = 134.615173
last_seq = 495
current_ts = 134.632156
current_received_ts = 134.631744
current_seq = 496
count = 414
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 134.615433/495, current 134.632156/496: elapsed=16720.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 134.632156
last_received_ts = 134.631744
last_seq = 496
current_ts = 134.648865
current_received_ts = 134.648453
current_seq = 497
count = 415
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 134.632156/496, current 134.648865/497: elapsed=16721.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 134.648865
last_received_ts = 134.648453
last_seq = 497
current_ts = 134.665588
current_received_ts = 134.665359
current_seq = 498
count = 416
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 134.648865/497, current 134.665588/498: elapsed=16721.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 134.665588
last_received_ts = 134.665359
last_seq = 498
current_ts = 134.682312
current_received_ts = 134.681915
current_seq = 499
count = 417
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 134.665588/498, current 134.682312/499: elapsed=16716.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 134.682312
last_received_ts = 134.681915
last_seq = 499
current_ts = 134.699036
current_received_ts = 134.698654
current_seq = 500
count = 418
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 134.682312/499, current 134.699036/500: elapsed=16729.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 134.699036
last_received_ts = 134.698654
last_seq = 500
current_ts = 134.715744
current_received_ts = 134.715302
current_seq = 501
count = 419
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 134.699036/500, current 134.715744/501: elapsed=16713.0us expected=16789.1us +- 83.9us, error 0.5%
(kms_flip:2181) DEBUG: name = flip
last_ts = 134.715744
last_received_ts = 134.715302
last_seq = 501
current_ts = 134.732468
current_received_ts = 134.732101
current_seq = 502
count = 420
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 134.715744/501, current 134.732468/502: elapsed=16717.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 134.732468
last_received_ts = 134.732101
last_seq = 502
current_ts = 134.749191
current_received_ts = 134.748810
current_seq = 503
count = 421
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 134.732468/502, current 134.749191/503: elapsed=16731.0us expected=16789.1us +- 83.9us, error 0.3%
(kms_flip:2181) DEBUG: name = flip
last_ts = 134.749191
last_received_ts = 134.748810
last_seq = 503
current_ts = 134.765915
current_received_ts = 134.765549
current_seq = 504
count = 422
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 134.749191/503, current 134.765915/504: elapsed=16718.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 134.765915
last_received_ts = 134.765549
last_seq = 504
current_ts = 134.782623
current_received_ts = 134.782242
current_seq = 505
count = 423
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 134.765915/504, current 134.782623/505: elapsed=16715.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 134.782623
last_received_ts = 134.782242
last_seq = 505
current_ts = 134.799347
current_received_ts = 134.798950
current_seq = 506
count = 424
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 134.782623/505, current 134.799347/506: elapsed=16719.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 134.799347
last_received_ts = 134.798950
last_seq = 506
current_ts = 134.816071
current_received_ts = 134.815689
current_seq = 507
count = 425
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 134.799347/506, current 134.816071/507: elapsed=16724.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 134.816071
last_received_ts = 134.815689
last_seq = 507
current_ts = 134.832779
current_received_ts = 134.832336
current_seq = 508
count = 426
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 134.816071/507, current 134.832779/508: elapsed=16713.0us expected=16789.1us +- 83.9us, error 0.5%
(kms_flip:2181) DEBUG: name = flip
last_ts = 134.832779
last_received_ts = 134.832336
last_seq = 508
current_ts = 134.849503
current_received_ts = 134.849136
current_seq = 509
count = 427
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 134.832779/508, current 134.849503/509: elapsed=16724.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 134.849503
last_received_ts = 134.849136
last_seq = 509
current_ts = 134.866226
current_received_ts = 134.865860
current_seq = 510
count = 428
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 134.849503/509, current 134.866226/510: elapsed=16720.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 134.866226
last_received_ts = 134.865860
last_seq = 510
current_ts = 134.882950
current_received_ts = 134.882660
current_seq = 511
count = 429
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 134.866226/510, current 134.882950/511: elapsed=16716.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 134.882950
last_received_ts = 134.882660
last_seq = 511
current_ts = 134.899673
current_received_ts = 134.899414
current_seq = 512
count = 430
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 134.882950/511, current 134.899673/512: elapsed=16721.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 134.899673
last_received_ts = 134.899414
last_seq = 512
current_ts = 134.916382
current_received_ts = 134.916046
current_seq = 513
count = 431
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 134.899673/512, current 134.916382/513: elapsed=16714.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 134.916382
last_received_ts = 134.916046
last_seq = 513
current_ts = 134.933105
current_received_ts = 134.932724
current_seq = 514
count = 432
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 134.916382/513, current 134.933105/514: elapsed=16720.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 134.933105
last_received_ts = 134.932724
last_seq = 514
current_ts = 134.949829
current_received_ts = 134.949448
current_seq = 515
count = 433
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 134.933105/514, current 134.949829/515: elapsed=16721.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 134.949829
last_received_ts = 134.949448
last_seq = 515
current_ts = 134.966537
current_received_ts = 134.966156
current_seq = 516
count = 434
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 134.949829/515, current 134.966537/516: elapsed=16711.0us expected=16789.1us +- 83.9us, error 0.5%
(kms_flip:2181) DEBUG: name = flip
last_ts = 134.966537
last_received_ts = 134.966156
last_seq = 516
current_ts = 134.983246
current_received_ts = 134.982971
current_seq = 517
count = 435
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 134.966537/516, current 134.983246/517: elapsed=16711.0us expected=16789.1us +- 83.9us, error 0.5%
(kms_flip:2181) DEBUG: name = flip
last_ts = 134.983246
last_received_ts = 134.982971
last_seq = 517
current_ts = 134.999969
current_received_ts = 134.999588
current_seq = 518
count = 436
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 134.983246/517, current 134.999969/518: elapsed=16724.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 134.999969
last_received_ts = 134.999588
last_seq = 518
current_ts = 135.016678
current_received_ts = 135.016327
current_seq = 519
count = 437
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 134.999969/518, current 135.016678/519: elapsed=16715.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 135.016678
last_received_ts = 135.016327
last_seq = 519
current_ts = 135.033386
current_received_ts = 135.033127
current_seq = 520
count = 438
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 135.016678/519, current 135.033386/520: elapsed=16710.0us expected=16789.1us +- 83.9us, error 0.5%
(kms_flip:2181) DEBUG: name = flip
last_ts = 135.033386
last_received_ts = 135.033127
last_seq = 520
current_ts = 135.050095
current_received_ts = 135.049820
current_seq = 521
count = 439
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 135.033386/520, current 135.050095/521: elapsed=16709.0us expected=16789.1us +- 83.9us, error 0.5%
(kms_flip:2181) DEBUG: name = flip
last_ts = 135.050095
last_received_ts = 135.049820
last_seq = 521
current_ts = 135.066818
current_received_ts = 135.066422
current_seq = 522
count = 440
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 135.050095/521, current 135.066818/522: elapsed=16715.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 135.066818
last_received_ts = 135.066422
last_seq = 522
current_ts = 135.083527
current_received_ts = 135.083282
current_seq = 523
count = 441
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 135.066818/522, current 135.083527/523: elapsed=16715.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 135.083527
last_received_ts = 135.083282
last_seq = 523
current_ts = 135.100250
current_received_ts = 135.099884
current_seq = 524
count = 442
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 135.083527/523, current 135.100250/524: elapsed=16720.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 135.100250
last_received_ts = 135.099884
last_seq = 524
current_ts = 135.116959
current_received_ts = 135.116562
current_seq = 525
count = 443
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 135.100250/524, current 135.116959/525: elapsed=16711.0us expected=16789.1us +- 83.9us, error 0.5%
(kms_flip:2181) DEBUG: name = flip
last_ts = 135.116959
last_received_ts = 135.116562
last_seq = 525
current_ts = 135.133682
current_received_ts = 135.133301
current_seq = 526
count = 444
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 135.116959/525, current 135.133682/526: elapsed=16720.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: name = flip
last_ts = 135.133682
last_received_ts = 135.133301
last_seq = 526
current_ts = 135.150391
current_received_ts = 135.150055
current_seq = 527
count = 445
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 135.133682/526, current 135.150391/527: elapsed=16708.0us expected=16789.1us +- 83.9us, error 0.5%
(kms_flip:2181) DEBUG: name = flip
last_ts = 135.150391
last_received_ts = 135.150055
last_seq = 527
current_ts = 135.167099
current_received_ts = 135.166748
current_seq = 528
count = 446
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 135.150391/527, current 135.167099/528: elapsed=16711.0us expected=16789.1us +- 83.9us, error 0.5%
(kms_flip:2181) DEBUG: name = flip
last_ts = 135.167099
last_received_ts = 135.166748
last_seq = 528
current_ts = 135.183823
current_received_ts = 135.183426
current_seq = 529
count = 447
seq_step = 1
(kms_flip:2181) DEBUG: flip ts/seq: last 135.167099/528, current 135.183823/529: elapsed=16714.0us expected=16789.1us +- 83.9us, error 0.4%
(kms_flip:2181) DEBUG: expected 446, counted 448, encoder type 2
(kms_flip:2181) DEBUG: dropped frames, expected 446, counted 448, encoder type 2
(kms_flip:2181) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:2181) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:2181) igt_core-INFO: Stack trace:
(kms_flip:2181) igt_core-INFO:   #0 ../lib/igt_core.c:2051 __igt_fail_assert()
(kms_flip:2181) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:2181) igt_core-INFO:   #2 ../tests/kms_flip.c:1845 run_test()
(kms_flip:2181) igt_core-INFO:   #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
(kms_flip:2181) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:2181) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2181) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2181) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest C-HDMI-A3: FAIL (11.183s)
Starting dynamic subtest: D-HDMI-A3
Dynamic subtest D-HDMI-A3: SUCCESS (7.988s)
Subtest plain-flip-ts-check: FAIL (30.356s)