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

shard-snb5

IGT-Version: 1.29-NO-GIT (x86_64) (Linux: 6.12.0-CI_DRM_15725-ge46649e7764a+ x86_64)

Using IGT_SRANDOM=1732199044 for randomisation
Opened device: /dev/dri/card0
Using monotonic timestamps
Starting subtest: plain-flip-ts-check-interruptible
Starting dynamic subtest: A-VGA1
  1024x768: 60 65000 1024 1048 1184 1344 768 771 777 806 0x40 0xa 
Expected frametime: 16666us; measured 17557.7us +- 7.613us accuracy 0.13%
vblank interval differs from modeline! expected 16665.6us, measured 17558us +- 7.613us, difference 892.1us (117.2 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:2114 __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-VGA1: FAIL (3.526s)
Starting dynamic subtest: B-VGA1
  1024x768: 60 65000 1024 1048 1184 1344 768 771 777 806 0x40 0xa 
Expected frametime: 16666us; measured 17213.4us +- 5.488us accuracy 0.10%
vblank interval differs from modeline! expected 16665.6us, measured 17213us +- 5.488us, difference 547.8us (99.8 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:2114 __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-VGA1: FAIL (4.850s)
Starting dynamic subtest: A-HDMI-A1
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16890.8us +- 5.902us accuracy 0.10%
vblank interval differs from modeline! expected 16666.7us, measured 16891us +- 5.902us, difference 224.1us (38.0 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:2114 __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-A1: FAIL (6.008s)
Starting dynamic subtest: B-HDMI-A1
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16752.5us +- 6.976us accuracy 0.12%
vblank interval differs from modeline! expected 16666.7us, measured 16753us +- 6.976us, difference 85.8us (12.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:2114 __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-A1: FAIL (10.976s)
Subtest plain-flip-ts-check-interruptible: FAIL (25.365s)
Stack trace:
  #0 ../lib/igt_core.c:2051 __igt_fail_assert()
  #1 ../lib/igt_kms.c:2246 kmstest_set_connector_dpms()
  #2 ../lib/igt_core.c:2930 igt_atexit_handler()
  #3 [erand48_r+0x1d6]
  #4 [exit+0x1e]
  #5 ../lib/igt_core.c:2386 igt_exit()
  #6 [main+0x3f]
  #7 [__libc_init_first+0x8a]
  #8 [__libc_start_main+0x8b]
  #9 [_start+0x25]

Starting subtest: plain-flip-ts-check-interruptible
Starting dynamic subtest: A-VGA1
(kms_flip:1728) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:1728) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:1728) CRITICAL: Last errno: 4, Interrupted system call
Dynamic subtest A-VGA1 failed.
**** DEBUG ****
(kms_flip:1728) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1024, height=768, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:1728) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=1, pitch=4096)
(kms_flip:1728) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:1728) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1024, height=768, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:1728) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=2, pitch=4096)
(kms_flip:1728) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:1728) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:1728) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:1728) igt_fb-DEBUG: Test requirement passed: cairo_surface_status(fb->cairo_surface) == CAIRO_STATUS_SUCCESS
(kms_flip:1728) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:1728) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:1728) igt_fb-DEBUG: Test requirement passed: cairo_surface_status(fb->cairo_surface) == CAIRO_STATUS_SUCCESS
(kms_flip:1728) igt_kms-INFO:   1024x768: 60 65000 1024 1048 1184 1344 768 771 777 806 0x40 0xa 
(kms_flip:1728) DEBUG: No stale events found
(kms_flip:1728) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:1728) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:1728) INFO: Expected frametime: 16666us; measured 17557.7us +- 7.613us accuracy 0.13%
(kms_flip:1728) INFO: vblank interval differs from modeline! expected 16665.6us, measured 17558us +- 7.613us, difference 892.1us (117.2 sigma)
(kms_flip:1728) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 56.820042
current_received_ts = 56.819424
current_seq = 863
count = 0
seq_step = 1
(kms_flip:1728) DEBUG: name = flip
last_ts = 56.820042
last_received_ts = 56.819424
last_seq = 863
current_ts = 56.837597
current_received_ts = 56.836960
current_seq = 864
count = 1
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 56.820042/863, current 56.837597/864: elapsed=17555.0us expected=17557.7us +- 87.8us, error 0.0%
(kms_flip:1728) DEBUG: name = flip
last_ts = 56.837597
last_received_ts = 56.836960
last_seq = 864
current_ts = 56.855091
current_received_ts = 56.854534
current_seq = 865
count = 2
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 56.837597/864, current 56.855091/865: elapsed=17495.0us expected=17557.7us +- 87.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 56.855091
last_received_ts = 56.854534
last_seq = 865
current_ts = 56.872555
current_received_ts = 56.873425
current_seq = 866
count = 3
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 56.855091/865, current 56.872555/866: elapsed=17461.0us expected=17557.7us +- 87.8us, error 0.6%
(kms_flip:1728) DEBUG: inconsistent flip ts/seq: last 56.855091/865, current 56.872555/866: elapsed=17461.0us expected=17557.7us
(kms_flip:1728) DEBUG: expected 63856, counted 3, encoder type 1
(kms_flip:1728) DEBUG: dropped frames, expected 63856, counted 3, encoder type 1
(kms_flip:1728) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:1728) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:1728) CRITICAL: Last errno: 4, Interrupted system call
(kms_flip:1728) igt_core-INFO: Stack trace:
(kms_flip:1728) igt_core-INFO:   #0 ../lib/igt_core.c:2051 __igt_fail_assert()
(kms_flip:1728) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:1728) igt_core-INFO:   #2 ../tests/kms_flip.c:1845 run_test()
(kms_flip:1728) igt_core-INFO:   #3 ../tests/kms_flip.c:2114 __igt_unique____real_main2001()
(kms_flip:1728) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:1728) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:1728) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:1728) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest A-VGA1: FAIL (3.526s)
Starting dynamic subtest: B-VGA1
(kms_flip:1728) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:1728) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:1728) CRITICAL: Last errno: 4, Interrupted system call
Dynamic subtest B-VGA1 failed.
**** DEBUG ****
(kms_flip:1728) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1024, height=768, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:1728) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=3, pitch=4096)
(kms_flip:1728) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:1728) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1024, height=768, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:1728) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=4, pitch=4096)
(kms_flip:1728) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:1728) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:1728) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:1728) igt_fb-DEBUG: Test requirement passed: cairo_surface_status(fb->cairo_surface) == CAIRO_STATUS_SUCCESS
(kms_flip:1728) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:1728) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:1728) igt_fb-DEBUG: Test requirement passed: cairo_surface_status(fb->cairo_surface) == CAIRO_STATUS_SUCCESS
(kms_flip:1728) igt_kms-INFO:   1024x768: 60 65000 1024 1048 1184 1344 768 771 777 806 0x40 0xa 
(kms_flip:1728) DEBUG: No stale events found
(kms_flip:1728) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:1728) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:1728) INFO: Expected frametime: 16666us; measured 17213.4us +- 5.488us accuracy 0.10%
(kms_flip:1728) INFO: vblank interval differs from modeline! expected 16665.6us, measured 17213us +- 5.488us, difference 547.8us (99.8 sigma)
(kms_flip:1728) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 60.389126
current_received_ts = 60.388519
current_seq = 68
count = 0
seq_step = 1
(kms_flip:1728) DEBUG: name = flip
last_ts = 60.389126
last_received_ts = 60.388519
last_seq = 68
current_ts = 60.406342
current_received_ts = 60.405746
current_seq = 69
count = 1
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 60.389126/68, current 60.406342/69: elapsed=17214.0us expected=17213.4us +- 86.1us, error 0.0%
(kms_flip:1728) DEBUG: name = flip
last_ts = 60.406342
last_received_ts = 60.405746
last_seq = 69
current_ts = 60.423553
current_received_ts = 60.422867
current_seq = 70
count = 2
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 60.406342/69, current 60.423553/70: elapsed=17212.0us expected=17213.4us +- 86.1us, error 0.0%
(kms_flip:1728) DEBUG: name = flip
last_ts = 60.423553
last_received_ts = 60.422867
last_seq = 70
current_ts = 60.440765
current_received_ts = 60.440128
current_seq = 71
count = 3
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 60.423553/70, current 60.440765/71: elapsed=17214.0us expected=17213.4us +- 86.1us, error 0.0%
(kms_flip:1728) DEBUG: name = flip
last_ts = 60.440765
last_received_ts = 60.440128
last_seq = 71
current_ts = 60.457985
current_received_ts = 60.457367
current_seq = 72
count = 4
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 60.440765/71, current 60.457985/72: elapsed=17219.0us expected=17213.4us +- 86.1us, error 0.0%
(kms_flip:1728) DEBUG: name = flip
last_ts = 60.457985
last_received_ts = 60.457367
last_seq = 72
current_ts = 60.475212
current_received_ts = 60.474663
current_seq = 73
count = 5
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 60.457985/72, current 60.475212/73: elapsed=17225.0us expected=17213.4us +- 86.1us, error 0.1%
(kms_flip:1728) DEBUG: name = flip
last_ts = 60.475212
last_received_ts = 60.474663
last_seq = 73
current_ts = 60.492420
current_received_ts = 60.491802
current_seq = 74
count = 6
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 60.475212/73, current 60.492420/74: elapsed=17210.0us expected=17213.4us +- 86.1us, error 0.0%
(kms_flip:1728) DEBUG: name = flip
last_ts = 60.492420
last_received_ts = 60.491802
last_seq = 74
current_ts = 60.509632
current_received_ts = 60.508949
current_seq = 75
count = 7
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 60.492420/74, current 60.509632/75: elapsed=17212.0us expected=17213.4us +- 86.1us, error 0.0%
(kms_flip:1728) DEBUG: name = flip
last_ts = 60.509632
last_received_ts = 60.508949
last_seq = 75
current_ts = 60.526836
current_received_ts = 60.526192
current_seq = 76
count = 8
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 60.509632/75, current 60.526836/76: elapsed=17204.0us expected=17213.4us +- 86.1us, error 0.1%
(kms_flip:1728) DEBUG: name = flip
last_ts = 60.526836
last_received_ts = 60.526192
last_seq = 76
current_ts = 60.544048
current_received_ts = 60.543449
current_seq = 77
count = 9
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 60.526836/76, current 60.544048/77: elapsed=17213.0us expected=17213.4us +- 86.1us, error 0.0%
(kms_flip:1728) DEBUG: name = flip
last_ts = 60.544048
last_received_ts = 60.543449
last_seq = 77
current_ts = 60.561260
current_received_ts = 60.560661
current_seq = 78
count = 10
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 60.544048/77, current 60.561260/78: elapsed=17210.0us expected=17213.4us +- 86.1us, error 0.0%
(kms_flip:1728) DEBUG: name = flip
last_ts = 60.561260
last_received_ts = 60.560661
last_seq = 78
current_ts = 60.578472
current_received_ts = 60.577896
current_seq = 79
count = 11
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 60.561260/78, current 60.578472/79: elapsed=17214.0us expected=17213.4us +- 86.1us, error 0.0%
(kms_flip:1728) DEBUG: name = flip
last_ts = 60.578472
last_received_ts = 60.577896
last_seq = 79
current_ts = 60.595688
current_received_ts = 60.595112
current_seq = 80
count = 12
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 60.578472/79, current 60.595688/80: elapsed=17213.0us expected=17213.4us +- 86.1us, error 0.0%
(kms_flip:1728) DEBUG: name = flip
last_ts = 60.595688
last_received_ts = 60.595112
last_seq = 80
current_ts = 60.612911
current_received_ts = 60.612209
current_seq = 81
count = 13
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 60.595688/80, current 60.612911/81: elapsed=17226.0us expected=17213.4us +- 86.1us, error 0.1%
(kms_flip:1728) DEBUG: name = flip
last_ts = 60.612911
last_received_ts = 60.612209
last_seq = 81
current_ts = 60.630119
current_received_ts = 60.629520
current_seq = 82
count = 14
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 60.612911/81, current 60.630119/82: elapsed=17207.0us expected=17213.4us +- 86.1us, error 0.0%
(kms_flip:1728) DEBUG: name = flip
last_ts = 60.630119
last_received_ts = 60.629520
last_seq = 82
current_ts = 60.647343
current_received_ts = 60.646725
current_seq = 83
count = 15
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 60.630119/82, current 60.647343/83: elapsed=17222.0us expected=17213.4us +- 86.1us, error 0.1%
(kms_flip:1728) DEBUG: name = flip
last_ts = 60.647343
last_received_ts = 60.646725
last_seq = 83
current_ts = 60.664555
current_received_ts = 60.663841
current_seq = 84
count = 16
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 60.647343/83, current 60.664555/84: elapsed=17212.0us expected=17213.4us +- 86.1us, error 0.0%
(kms_flip:1728) DEBUG: name = flip
last_ts = 60.664555
last_received_ts = 60.663841
last_seq = 84
current_ts = 60.681755
current_received_ts = 60.681122
current_seq = 85
count = 17
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 60.664555/84, current 60.681755/85: elapsed=17202.0us expected=17213.4us +- 86.1us, error 0.1%
(kms_flip:1728) DEBUG: name = flip
last_ts = 60.681755
last_received_ts = 60.681122
last_seq = 85
current_ts = 60.698982
current_received_ts = 60.698372
current_seq = 86
count = 18
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 60.681755/85, current 60.698982/86: elapsed=17227.0us expected=17213.4us +- 86.1us, error 0.1%
(kms_flip:1728) DEBUG: name = flip
last_ts = 60.698982
last_received_ts = 60.698372
last_seq = 86
current_ts = 60.716183
current_received_ts = 60.715542
current_seq = 87
count = 19
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 60.698982/86, current 60.716183/87: elapsed=17200.0us expected=17213.4us +- 86.1us, error 0.1%
(kms_flip:1728) DEBUG: name = flip
last_ts = 60.716183
last_received_ts = 60.715542
last_seq = 87
current_ts = 60.733410
current_received_ts = 60.732811
current_seq = 88
count = 20
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 60.716183/87, current 60.733410/88: elapsed=17227.0us expected=17213.4us +- 86.1us, error 0.1%
(kms_flip:1728) DEBUG: name = flip
last_ts = 60.733410
last_received_ts = 60.732811
last_seq = 88
current_ts = 60.750614
current_received_ts = 60.749996
current_seq = 89
count = 21
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 60.733410/88, current 60.750614/89: elapsed=17205.0us expected=17213.4us +- 86.1us, error 0.0%
(kms_flip:1728) DEBUG: name = flip
last_ts = 60.750614
last_received_ts = 60.749996
last_seq = 89
current_ts = 60.767830
current_received_ts = 60.767231
current_seq = 90
count = 22
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 60.750614/89, current 60.767830/90: elapsed=17214.0us expected=17213.4us +- 86.1us, error 0.0%
(kms_flip:1728) DEBUG: name = flip
last_ts = 60.767830
last_received_ts = 60.767231
last_seq = 90
current_ts = 60.785042
current_received_ts = 60.784439
current_seq = 91
count = 23
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 60.767830/90, current 60.785042/91: elapsed=17213.0us expected=17213.4us +- 86.1us, error 0.0%
(kms_flip:1728) DEBUG: name = flip
last_ts = 60.785042
last_received_ts = 60.784439
last_seq = 91
current_ts = 60.802242
current_received_ts = 60.801662
current_seq = 92
count = 24
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 60.785042/91, current 60.802242/92: elapsed=17202.0us expected=17213.4us +- 86.1us, error 0.1%
(kms_flip:1728) DEBUG: name = flip
last_ts = 60.802242
last_received_ts = 60.801662
last_seq = 92
current_ts = 60.819458
current_received_ts = 60.818848
current_seq = 93
count = 25
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 60.802242/92, current 60.819458/93: elapsed=17213.0us expected=17213.4us +- 86.1us, error 0.0%
(kms_flip:1728) DEBUG: name = flip
last_ts = 60.819458
last_received_ts = 60.818848
last_seq = 93
current_ts = 60.836674
current_received_ts = 60.836109
current_seq = 94
count = 26
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 60.819458/93, current 60.836674/94: elapsed=17218.0us expected=17213.4us +- 86.1us, error 0.0%
(kms_flip:1728) DEBUG: name = flip
last_ts = 60.836674
last_received_ts = 60.836109
last_seq = 94
current_ts = 60.853851
current_received_ts = 60.853256
current_seq = 95
count = 27
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 60.836674/94, current 60.853851/95: elapsed=17176.0us expected=17213.4us +- 86.1us, error 0.2%
(kms_flip:1728) DEBUG: name = flip
last_ts = 60.853851
last_received_ts = 60.853256
last_seq = 95
current_ts = 60.871006
current_received_ts = 60.870377
current_seq = 96
count = 28
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 60.853851/95, current 60.871006/96: elapsed=17156.0us expected=17213.4us +- 86.1us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 60.871006
last_received_ts = 60.870377
last_seq = 96
current_ts = 60.888161
current_received_ts = 60.887562
current_seq = 97
count = 29
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 60.871006/96, current 60.888161/97: elapsed=17152.0us expected=17213.4us +- 86.1us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 60.888161
last_received_ts = 60.887562
last_seq = 97
current_ts = 60.905308
current_received_ts = 60.904720
current_seq = 98
count = 30
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 60.888161/97, current 60.905308/98: elapsed=17149.0us expected=17213.4us +- 86.1us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 60.905308
last_received_ts = 60.904720
last_seq = 98
current_ts = 60.922466
current_received_ts = 60.921898
current_seq = 99
count = 31
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 60.905308/98, current 60.922466/99: elapsed=17159.0us expected=17213.4us +- 86.1us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 60.922466
last_received_ts = 60.921898
last_seq = 99
current_ts = 60.939617
current_received_ts = 60.938992
current_seq = 100
count = 32
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 60.922466/99, current 60.939617/100: elapsed=17149.0us expected=17213.4us +- 86.1us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 60.939617
last_received_ts = 60.938992
last_seq = 100
current_ts = 60.956764
current_received_ts = 60.956154
current_seq = 101
count = 33
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 60.939617/100, current 60.956764/101: elapsed=17148.0us expected=17213.4us +- 86.1us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 60.956764
last_received_ts = 60.956154
last_seq = 101
current_ts = 60.973923
current_received_ts = 60.973289
current_seq = 102
count = 34
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 60.956764/101, current 60.973923/102: elapsed=17157.0us expected=17213.4us +- 86.1us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 60.973923
last_received_ts = 60.973289
last_seq = 102
current_ts = 60.991070
current_received_ts = 60.990486
current_seq = 103
count = 35
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 60.973923/102, current 60.991070/103: elapsed=17150.0us expected=17213.4us +- 86.1us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 60.991070
last_received_ts = 60.990486
last_seq = 103
current_ts = 61.008228
current_received_ts = 61.007599
current_seq = 104
count = 36
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 60.991070/103, current 61.008228/104: elapsed=17156.0us expected=17213.4us +- 86.1us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 61.008228
last_received_ts = 61.007599
last_seq = 104
current_ts = 61.025375
current_received_ts = 61.024731
current_seq = 105
count = 37
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 61.008228/104, current 61.025375/105: elapsed=17149.0us expected=17213.4us +- 86.1us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 61.025375
last_received_ts = 61.024731
last_seq = 105
current_ts = 61.042530
current_received_ts = 61.041885
current_seq = 106
count = 38
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 61.025375/105, current 61.042530/106: elapsed=17155.0us expected=17213.4us +- 86.1us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 61.042530
last_received_ts = 61.041885
last_seq = 106
current_ts = 61.059696
current_received_ts = 61.059006
current_seq = 107
count = 39
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 61.042530/106, current 61.059696/107: elapsed=17164.0us expected=17213.4us +- 86.1us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 61.059696
last_received_ts = 61.059006
last_seq = 107
current_ts = 61.076843
current_received_ts = 61.076180
current_seq = 108
count = 40
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 61.059696/107, current 61.076843/108: elapsed=17147.0us expected=17213.4us +- 86.1us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 61.076843
last_received_ts = 61.076180
last_seq = 108
current_ts = 61.093983
current_received_ts = 61.093361
current_seq = 109
count = 41
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 61.076843/108, current 61.093983/109: elapsed=17142.0us expected=17213.4us +- 86.1us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 61.093983
last_received_ts = 61.093361
last_seq = 109
current_ts = 61.111145
current_received_ts = 61.110500
current_seq = 110
count = 42
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 61.093983/109, current 61.111145/110: elapsed=17162.0us expected=17213.4us +- 86.1us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 61.111145
last_received_ts = 61.110500
last_seq = 110
current_ts = 61.128304
current_received_ts = 61.127659
current_seq = 111
count = 43
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 61.111145/110, current 61.128304/111: elapsed=17159.0us expected=17213.4us +- 86.1us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 61.128304
last_received_ts = 61.127659
last_seq = 111
current_ts = 61.145454
current_received_ts = 61.144775
current_seq = 112
count = 44
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 61.128304/111, current 61.145454/112: elapsed=17150.0us expected=17213.4us +- 86.1us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 61.145454
last_received_ts = 61.144775
last_seq = 112
current_ts = 61.162598
current_received_ts = 61.161964
current_seq = 113
count = 45
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 61.145454/112, current 61.162598/113: elapsed=17143.0us expected=17213.4us +- 86.1us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 61.162598
last_received_ts = 61.161964
last_seq = 113
current_ts = 61.179764
current_received_ts = 61.179115
current_seq = 114
count = 46
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 61.162598/113, current 61.179764/114: elapsed=17164.0us expected=17213.4us +- 86.1us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 61.179764
last_received_ts = 61.179115
last_seq = 114
current_ts = 61.196899
current_received_ts = 61.196297
current_seq = 115
count = 47
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 61.179764/114, current 61.196899/115: elapsed=17136.0us expected=17213.4us +- 86.1us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 61.196899
last_received_ts = 61.196297
last_seq = 115
current_ts = 61.214050
current_received_ts = 61.213428
current_seq = 116
count = 48
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 61.196899/115, current 61.214050/116: elapsed=17153.0us expected=17213.4us +- 86.1us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 61.214050
last_received_ts = 61.213428
last_seq = 116
current_ts = 61.231216
current_received_ts = 61.230614
current_seq = 117
count = 49
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 61.214050/116, current 61.231216/117: elapsed=17164.0us expected=17213.4us +- 86.1us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 61.231216
last_received_ts = 61.230614
last_seq = 117
current_ts = 61.248356
current_received_ts = 61.247768
current_seq = 118
count = 50
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 61.231216/117, current 61.248356/118: elapsed=17142.0us expected=17213.4us +- 86.1us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 61.248356
last_received_ts = 61.247768
last_seq = 118
current_ts = 61.265507
current_received_ts = 61.264919
current_seq = 119
count = 51
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 61.248356/118, current 61.265507/119: elapsed=17151.0us expected=17213.4us +- 86.1us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 61.265507
last_received_ts = 61.264919
last_seq = 119
current_ts = 61.282661
current_received_ts = 61.281902
current_seq = 120
count = 52
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 61.265507/119, current 61.282661/120: elapsed=17154.0us expected=17213.4us +- 86.1us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 61.282661
last_received_ts = 61.281902
last_seq = 120
current_ts = 61.299820
current_received_ts = 61.299179
current_seq = 121
count = 53
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 61.282661/120, current 61.299820/121: elapsed=17157.0us expected=17213.4us +- 86.1us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 61.299820
last_received_ts = 61.299179
last_seq = 121
current_ts = 61.316963
current_received_ts = 61.316334
current_seq = 122
count = 54
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 61.299820/121, current 61.316963/122: elapsed=17143.0us expected=17213.4us +- 86.1us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 61.316963
last_received_ts = 61.316334
last_seq = 122
current_ts = 61.334129
current_received_ts = 61.333447
current_seq = 123
count = 55
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 61.316963/122, current 61.334129/123: elapsed=17169.0us expected=17213.4us +- 86.1us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 61.334129
last_received_ts = 61.333447
last_seq = 123
current_ts = 61.351280
current_received_ts = 61.350594
current_seq = 124
count = 56
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 61.334129/123, current 61.351280/124: elapsed=17151.0us expected=17213.4us +- 86.1us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 61.351280
last_received_ts = 61.350594
last_seq = 124
current_ts = 61.368431
current_received_ts = 61.367764
current_seq = 125
count = 57
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 61.351280/124, current 61.368431/125: elapsed=17148.0us expected=17213.4us +- 86.1us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 61.368431
last_received_ts = 61.367764
last_seq = 125
current_ts = 61.385578
current_received_ts = 61.384903
current_seq = 126
count = 58
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 61.368431/125, current 61.385578/126: elapsed=17149.0us expected=17213.4us +- 86.1us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 61.385578
last_received_ts = 61.384903
last_seq = 126
current_ts = 61.402721
current_received_ts = 61.402164
current_seq = 127
count = 59
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 61.385578/126, current 61.402721/127: elapsed=17144.0us expected=17213.4us +- 86.1us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 61.402721
last_received_ts = 61.402164
last_seq = 127
current_ts = 61.419888
current_received_ts = 61.419212
current_seq = 128
count = 60
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 61.402721/127, current 61.419888/128: elapsed=17163.0us expected=17213.4us +- 86.1us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 61.419888
last_received_ts = 61.419212
last_seq = 128
current_ts = 61.437042
current_received_ts = 61.436447
current_seq = 129
count = 61
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 61.419888/128, current 61.437042/129: elapsed=17158.0us expected=17213.4us +- 86.1us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 61.437042
last_received_ts = 61.436447
last_seq = 129
current_ts = 61.454189
current_received_ts = 61.453613
current_seq = 130
count = 62
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 61.437042/129, current 61.454189/130: elapsed=17144.0us expected=17213.4us +- 86.1us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 61.454189
last_received_ts = 61.453613
last_seq = 130
current_ts = 61.471352
current_received_ts = 61.470680
current_seq = 131
count = 63
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 61.454189/130, current 61.471352/131: elapsed=17162.0us expected=17213.4us +- 86.1us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 61.471352
last_received_ts = 61.470680
last_seq = 131
current_ts = 61.488487
current_received_ts = 61.487907
current_seq = 132
count = 64
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 61.471352/131, current 61.488487/132: elapsed=17139.0us expected=17213.4us +- 86.1us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 61.488487
last_received_ts = 61.487907
last_seq = 132
current_ts = 61.505646
current_received_ts = 61.505085
current_seq = 133
count = 65
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 61.488487/132, current 61.505646/133: elapsed=17155.0us expected=17213.4us +- 86.1us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 61.505646
last_received_ts = 61.505085
last_seq = 133
current_ts = 61.522793
current_received_ts = 61.522156
current_seq = 134
count = 66
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 61.505646/133, current 61.522793/134: elapsed=17147.0us expected=17213.4us +- 86.1us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 61.522793
last_received_ts = 61.522156
last_seq = 134
current_ts = 61.539951
current_received_ts = 61.539253
current_seq = 135
count = 67
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 61.522793/134, current 61.539951/135: elapsed=17162.0us expected=17213.4us +- 86.1us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 61.539951
last_received_ts = 61.539253
last_seq = 135
current_ts = 61.557110
current_received_ts = 61.556450
current_seq = 136
count = 68
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 61.539951/135, current 61.557110/136: elapsed=17155.0us expected=17213.4us +- 86.1us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 61.557110
last_received_ts = 61.556450
last_seq = 136
current_ts = 61.574249
current_received_ts = 61.573540
current_seq = 137
count = 69
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 61.557110/136, current 61.574249/137: elapsed=17142.0us expected=17213.4us +- 86.1us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 61.574249
last_received_ts = 61.573540
last_seq = 137
current_ts = 61.591415
current_received_ts = 61.590717
current_seq = 138
count = 70
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 61.574249/137, current 61.591415/138: elapsed=17165.0us expected=17213.4us +- 86.1us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 61.591415
last_received_ts = 61.590717
last_seq = 138
current_ts = 61.608566
current_received_ts = 61.607883
current_seq = 139
count = 71
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 61.591415/138, current 61.608566/139: elapsed=17151.0us expected=17213.4us +- 86.1us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 61.608566
last_received_ts = 61.607883
last_seq = 139
current_ts = 61.625713
current_received_ts = 61.625008
current_seq = 140
count = 72
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 61.608566/139, current 61.625713/140: elapsed=17148.0us expected=17213.4us +- 86.1us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 61.625713
last_received_ts = 61.625008
last_seq = 140
current_ts = 61.642860
current_received_ts = 61.642162
current_seq = 141
count = 73
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 61.625713/140, current 61.642860/141: elapsed=17147.0us expected=17213.4us +- 86.1us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 61.642860
last_received_ts = 61.642162
last_seq = 141
current_ts = 61.660023
current_received_ts = 61.659317
current_seq = 142
count = 74
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 61.642860/141, current 61.660023/142: elapsed=17162.0us expected=17213.4us +- 86.1us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 61.660023
last_received_ts = 61.659317
last_seq = 142
current_ts = 61.677170
current_received_ts = 61.676472
current_seq = 143
count = 75
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 61.660023/142, current 61.677170/143: elapsed=17148.0us expected=17213.4us +- 86.1us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 61.677170
last_received_ts = 61.676472
last_seq = 143
current_ts = 61.694324
current_received_ts = 61.693607
current_seq = 144
count = 76
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 61.677170/143, current 61.694324/144: elapsed=17153.0us expected=17213.4us +- 86.1us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 61.694324
last_received_ts = 61.693607
last_seq = 144
current_ts = 61.711479
current_received_ts = 61.710793
current_seq = 145
count = 77
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 61.694324/144, current 61.711479/145: elapsed=17157.0us expected=17213.4us +- 86.1us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 61.711479
last_received_ts = 61.710793
last_seq = 145
current_ts = 61.728634
current_received_ts = 61.727936
current_seq = 146
count = 78
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 61.711479/145, current 61.728634/146: elapsed=17152.0us expected=17213.4us +- 86.1us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 61.728634
last_received_ts = 61.727936
last_seq = 146
current_ts = 61.745785
current_received_ts = 61.745064
current_seq = 147
count = 79
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 61.728634/146, current 61.745785/147: elapsed=17153.0us expected=17213.4us +- 86.1us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 61.745785
last_received_ts = 61.745064
last_seq = 147
current_ts = 61.762939
current_received_ts = 61.762249
current_seq = 148
count = 80
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 61.745785/147, current 61.762939/148: elapsed=17152.0us expected=17213.4us +- 86.1us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 61.762939
last_received_ts = 61.762249
last_seq = 148
current_ts = 61.780090
current_received_ts = 61.779404
current_seq = 149
count = 81
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 61.762939/148, current 61.780090/149: elapsed=17151.0us expected=17213.4us +- 86.1us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 61.780090
last_received_ts = 61.779404
last_seq = 149
current_ts = 61.797241
current_received_ts = 61.796535
current_seq = 150
count = 82
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 61.780090/149, current 61.797241/150: elapsed=17152.0us expected=17213.4us +- 86.1us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 61.797241
last_received_ts = 61.796535
last_seq = 150
current_ts = 61.814392
current_received_ts = 61.813690
current_seq = 151
count = 83
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 61.797241/150, current 61.814392/151: elapsed=17152.0us expected=17213.4us +- 86.1us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 61.814392
last_received_ts = 61.813690
last_seq = 151
current_ts = 61.831547
current_received_ts = 61.830853
current_seq = 152
count = 84
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 61.814392/151, current 61.831547/152: elapsed=17152.0us expected=17213.4us +- 86.1us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 61.831547
last_received_ts = 61.830853
last_seq = 152
current_ts = 61.848682
current_received_ts = 61.847973
current_seq = 153
count = 85
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 61.831547/152, current 61.848682/153: elapsed=17137.0us expected=17213.4us +- 86.1us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 61.848682
last_received_ts = 61.847973
last_seq = 153
current_ts = 61.865780
current_received_ts = 61.865097
current_seq = 154
count = 86
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 61.848682/153, current 61.865780/154: elapsed=17098.0us expected=17213.4us +- 86.1us, error 0.7%
(kms_flip:1728) DEBUG: inconsistent flip ts/seq: last 61.848682/153, current 61.865780/154: elapsed=17098.0us expected=17213.4us
(kms_flip:1728) DEBUG: expected 65133, counted 86, encoder type 1
(kms_flip:1728) DEBUG: dropped frames, expected 65133, counted 86, encoder type 1
(kms_flip:1728) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:1728) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:1728) CRITICAL: Last errno: 4, Interrupted system call
(kms_flip:1728) igt_core-INFO: Stack trace:
(kms_flip:1728) igt_core-INFO:   #0 ../lib/igt_core.c:2051 __igt_fail_assert()
(kms_flip:1728) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:1728) igt_core-INFO:   #2 ../tests/kms_flip.c:1845 run_test()
(kms_flip:1728) igt_core-INFO:   #3 ../tests/kms_flip.c:2114 __igt_unique____real_main2001()
(kms_flip:1728) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:1728) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:1728) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:1728) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-VGA1: FAIL (4.850s)
Starting dynamic subtest: A-HDMI-A1
(kms_flip:1728) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:1728) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:1728) CRITICAL: Last errno: 4, Interrupted system call
Dynamic subtest A-HDMI-A1 failed.
**** DEBUG ****
(kms_flip:1728) DEBUG: name = flip
last_ts = 65.882439
last_received_ts = 65.881966
last_seq = 921
current_ts = 65.899300
current_received_ts = 65.898811
current_seq = 922
count = 31
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 65.882439/921, current 65.899300/922: elapsed=16861.0us expected=16890.8us +- 84.5us, error 0.2%
(kms_flip:1728) DEBUG: name = flip
last_ts = 65.899300
last_received_ts = 65.898811
last_seq = 922
current_ts = 65.916153
current_received_ts = 65.915703
current_seq = 923
count = 32
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 65.899300/922, current 65.916153/923: elapsed=16856.0us expected=16890.8us +- 84.5us, error 0.2%
(kms_flip:1728) DEBUG: name = flip
last_ts = 65.916153
last_received_ts = 65.915703
last_seq = 923
current_ts = 65.933014
current_received_ts = 65.932526
current_seq = 924
count = 33
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 65.916153/923, current 65.933014/924: elapsed=16860.0us expected=16890.8us +- 84.5us, error 0.2%
(kms_flip:1728) DEBUG: name = flip
last_ts = 65.933014
last_received_ts = 65.932526
last_seq = 924
current_ts = 65.949867
current_received_ts = 65.949348
current_seq = 925
count = 34
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 65.933014/924, current 65.949867/925: elapsed=16850.0us expected=16890.8us +- 84.5us, error 0.2%
(kms_flip:1728) DEBUG: name = flip
last_ts = 65.949867
last_received_ts = 65.949348
last_seq = 925
current_ts = 65.966736
current_received_ts = 65.966225
current_seq = 926
count = 35
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 65.949867/925, current 65.966736/926: elapsed=16868.0us expected=16890.8us +- 84.5us, error 0.1%
(kms_flip:1728) DEBUG: name = flip
last_ts = 65.966736
last_received_ts = 65.966225
last_seq = 926
current_ts = 65.983582
current_received_ts = 65.983109
current_seq = 927
count = 36
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 65.966736/926, current 65.983582/927: elapsed=16848.0us expected=16890.8us +- 84.5us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 65.983582
last_received_ts = 65.983109
last_seq = 927
current_ts = 66.000450
current_received_ts = 65.999893
current_seq = 928
count = 37
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 65.983582/927, current 66.000450/928: elapsed=16869.0us expected=16890.8us +- 84.5us, error 0.1%
(kms_flip:1728) DEBUG: name = flip
last_ts = 66.000450
last_received_ts = 65.999893
last_seq = 928
current_ts = 66.017311
current_received_ts = 66.016838
current_seq = 929
count = 38
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 66.000450/928, current 66.017311/929: elapsed=16862.0us expected=16890.8us +- 84.5us, error 0.2%
(kms_flip:1728) DEBUG: name = flip
last_ts = 66.017311
last_received_ts = 66.016838
last_seq = 929
current_ts = 66.034172
current_received_ts = 66.033691
current_seq = 930
count = 39
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 66.017311/929, current 66.034172/930: elapsed=16859.0us expected=16890.8us +- 84.5us, error 0.2%
(kms_flip:1728) DEBUG: name = flip
last_ts = 66.034172
last_received_ts = 66.033691
last_seq = 930
current_ts = 66.051033
current_received_ts = 66.050545
current_seq = 931
count = 40
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 66.034172/930, current 66.051033/931: elapsed=16859.0us expected=16890.8us +- 84.5us, error 0.2%
(kms_flip:1728) DEBUG: name = flip
last_ts = 66.051033
last_received_ts = 66.050545
last_seq = 931
current_ts = 66.067886
current_received_ts = 66.067383
current_seq = 932
count = 41
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 66.051033/931, current 66.067886/932: elapsed=16857.0us expected=16890.8us +- 84.5us, error 0.2%
(kms_flip:1728) DEBUG: name = flip
last_ts = 66.067886
last_received_ts = 66.067383
last_seq = 932
current_ts = 66.084747
current_received_ts = 66.084221
current_seq = 933
count = 42
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 66.067886/932, current 66.084747/933: elapsed=16858.0us expected=16890.8us +- 84.5us, error 0.2%
(kms_flip:1728) DEBUG: name = flip
last_ts = 66.084747
last_received_ts = 66.084221
last_seq = 933
current_ts = 66.101601
current_received_ts = 66.101105
current_seq = 934
count = 43
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 66.084747/933, current 66.101601/934: elapsed=16854.0us expected=16890.8us +- 84.5us, error 0.2%
(kms_flip:1728) DEBUG: name = flip
last_ts = 66.101601
last_received_ts = 66.101105
last_seq = 934
current_ts = 66.118469
current_received_ts = 66.117989
current_seq = 935
count = 44
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 66.101601/934, current 66.118469/935: elapsed=16868.0us expected=16890.8us +- 84.5us, error 0.1%
(kms_flip:1728) DEBUG: name = flip
last_ts = 66.118469
last_received_ts = 66.117989
last_seq = 935
current_ts = 66.135330
current_received_ts = 66.134750
current_seq = 936
count = 45
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 66.118469/935, current 66.135330/936: elapsed=16860.0us expected=16890.8us +- 84.5us, error 0.2%
(kms_flip:1728) DEBUG: name = flip
last_ts = 66.135330
last_received_ts = 66.134750
last_seq = 936
current_ts = 66.152176
current_received_ts = 66.151672
current_seq = 937
count = 46
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 66.135330/936, current 66.152176/937: elapsed=16851.0us expected=16890.8us +- 84.5us, error 0.2%
(kms_flip:1728) DEBUG: name = flip
last_ts = 66.152176
last_received_ts = 66.151672
last_seq = 937
current_ts = 66.169044
current_received_ts = 66.168556
current_seq = 938
count = 47
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 66.152176/937, current 66.169044/938: elapsed=16867.0us expected=16890.8us +- 84.5us, error 0.1%
(kms_flip:1728) DEBUG: name = flip
last_ts = 66.169044
last_received_ts = 66.168556
last_seq = 938
current_ts = 66.185898
current_received_ts = 66.185379
current_seq = 939
count = 48
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 66.169044/938, current 66.185898/939: elapsed=16851.0us expected=16890.8us +- 84.5us, error 0.2%
(kms_flip:1728) DEBUG: name = flip
last_ts = 66.185898
last_received_ts = 66.185379
last_seq = 939
current_ts = 66.202759
current_received_ts = 66.202248
current_seq = 940
count = 49
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 66.185898/939, current 66.202759/940: elapsed=16864.0us expected=16890.8us +- 84.5us, error 0.2%
(kms_flip:1728) DEBUG: name = flip
last_ts = 66.202759
last_received_ts = 66.202248
last_seq = 940
current_ts = 66.219612
current_received_ts = 66.219116
current_seq = 941
count = 50
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 66.202759/940, current 66.219612/941: elapsed=16854.0us expected=16890.8us +- 84.5us, error 0.2%
(kms_flip:1728) DEBUG: name = flip
last_ts = 66.219612
last_received_ts = 66.219116
last_seq = 941
current_ts = 66.236481
current_received_ts = 66.235886
current_seq = 942
count = 51
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 66.219612/941, current 66.236481/942: elapsed=16863.0us expected=16890.8us +- 84.5us, error 0.2%
(kms_flip:1728) DEBUG: name = flip
last_ts = 66.236481
last_received_ts = 66.235886
last_seq = 942
current_ts = 66.253342
current_received_ts = 66.252853
current_seq = 943
count = 52
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 66.236481/942, current 66.253342/943: elapsed=16864.0us expected=16890.8us +- 84.5us, error 0.2%
(kms_flip:1728) DEBUG: name = flip
last_ts = 66.253342
last_received_ts = 66.252853
last_seq = 943
current_ts = 66.270195
current_received_ts = 66.269661
current_seq = 944
count = 53
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 66.253342/943, current 66.270195/944: elapsed=16856.0us expected=16890.8us +- 84.5us, error 0.2%
(kms_flip:1728) DEBUG: name = flip
last_ts = 66.270195
last_received_ts = 66.269661
last_seq = 944
current_ts = 66.287056
current_received_ts = 66.286560
current_seq = 945
count = 54
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 66.270195/944, current 66.287056/945: elapsed=16860.0us expected=16890.8us +- 84.5us, error 0.2%
(kms_flip:1728) DEBUG: name = flip
last_ts = 66.287056
last_received_ts = 66.286560
last_seq = 945
current_ts = 66.303909
current_received_ts = 66.303413
current_seq = 946
count = 55
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 66.287056/945, current 66.303909/946: elapsed=16853.0us expected=16890.8us +- 84.5us, error 0.2%
(kms_flip:1728) DEBUG: name = flip
last_ts = 66.303909
last_received_ts = 66.303413
last_seq = 946
current_ts = 66.320778
current_received_ts = 66.320274
current_seq = 947
count = 56
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 66.303909/946, current 66.320778/947: elapsed=16866.0us expected=16890.8us +- 84.5us, error 0.1%
(kms_flip:1728) DEBUG: name = flip
last_ts = 66.320778
last_received_ts = 66.320274
last_seq = 947
current_ts = 66.337624
current_received_ts = 66.337112
current_seq = 948
count = 57
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 66.320778/947, current 66.337624/948: elapsed=16851.0us expected=16890.8us +- 84.5us, error 0.2%
(kms_flip:1728) DEBUG: name = flip
last_ts = 66.337624
last_received_ts = 66.337112
last_seq = 948
current_ts = 66.354492
current_received_ts = 66.354057
current_seq = 949
count = 58
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 66.337624/948, current 66.354492/949: elapsed=16869.0us expected=16890.8us +- 84.5us, error 0.1%
(kms_flip:1728) DEBUG: name = flip
last_ts = 66.354492
last_received_ts = 66.354057
last_seq = 949
current_ts = 66.371346
current_received_ts = 66.370888
current_seq = 950
count = 59
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 66.354492/949, current 66.371346/950: elapsed=16848.0us expected=16890.8us +- 84.5us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 66.371346
last_received_ts = 66.370888
last_seq = 950
current_ts = 66.388214
current_received_ts = 66.387741
current_seq = 951
count = 60
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 66.371346/950, current 66.388214/951: elapsed=16871.0us expected=16890.8us +- 84.5us, error 0.1%
(kms_flip:1728) DEBUG: name = flip
last_ts = 66.388214
last_received_ts = 66.387741
last_seq = 951
current_ts = 66.405075
current_received_ts = 66.404602
current_seq = 952
count = 61
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 66.388214/951, current 66.405075/952: elapsed=16859.0us expected=16890.8us +- 84.5us, error 0.2%
(kms_flip:1728) DEBUG: name = flip
last_ts = 66.405075
last_received_ts = 66.404602
last_seq = 952
current_ts = 66.421936
current_received_ts = 66.421432
current_seq = 953
count = 62
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 66.405075/952, current 66.421936/953: elapsed=16859.0us expected=16890.8us +- 84.5us, error 0.2%
(kms_flip:1728) DEBUG: name = flip
last_ts = 66.421936
last_received_ts = 66.421432
last_seq = 953
current_ts = 66.438789
current_received_ts = 66.438278
current_seq = 954
count = 63
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 66.421936/953, current 66.438789/954: elapsed=16855.0us expected=16890.8us +- 84.5us, error 0.2%
(kms_flip:1728) DEBUG: name = flip
last_ts = 66.438789
last_received_ts = 66.438278
last_seq = 954
current_ts = 66.455650
current_received_ts = 66.455116
current_seq = 955
count = 64
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 66.438789/954, current 66.455650/955: elapsed=16860.0us expected=16890.8us +- 84.5us, error 0.2%
(kms_flip:1728) DEBUG: name = flip
last_ts = 66.455650
last_received_ts = 66.455116
last_seq = 955
current_ts = 66.472511
current_received_ts = 66.471977
current_seq = 956
count = 65
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 66.455650/955, current 66.472511/956: elapsed=16864.0us expected=16890.8us +- 84.5us, error 0.2%
(kms_flip:1728) DEBUG: name = flip
last_ts = 66.472511
last_received_ts = 66.471977
last_seq = 956
current_ts = 66.489372
current_received_ts = 66.488907
current_seq = 957
count = 66
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 66.472511/956, current 66.489372/957: elapsed=16858.0us expected=16890.8us +- 84.5us, error 0.2%
(kms_flip:1728) DEBUG: name = flip
last_ts = 66.489372
last_received_ts = 66.488907
last_seq = 957
current_ts = 66.506233
current_received_ts = 66.505737
current_seq = 958
count = 67
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 66.489372/957, current 66.506233/958: elapsed=16860.0us expected=16890.8us +- 84.5us, error 0.2%
(kms_flip:1728) DEBUG: name = flip
last_ts = 66.506233
last_received_ts = 66.505737
last_seq = 958
current_ts = 66.523079
current_received_ts = 66.522606
current_seq = 959
count = 68
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 66.506233/958, current 66.523079/959: elapsed=16851.0us expected=16890.8us +- 84.5us, error 0.2%
(kms_flip:1728) DEBUG: name = flip
last_ts = 66.523079
last_received_ts = 66.522606
last_seq = 959
current_ts = 66.539948
current_received_ts = 66.539482
current_seq = 960
count = 69
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 66.523079/959, current 66.539948/960: elapsed=16868.0us expected=16890.8us +- 84.5us, error 0.1%
(kms_flip:1728) DEBUG: name = flip
last_ts = 66.539948
last_received_ts = 66.539482
last_seq = 960
current_ts = 66.556808
current_received_ts = 66.556313
current_seq = 961
count = 70
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 66.539948/960, current 66.556808/961: elapsed=16857.0us expected=16890.8us +- 84.5us, error 0.2%
(kms_flip:1728) DEBUG: name = flip
last_ts = 66.556808
last_received_ts = 66.556313
last_seq = 961
current_ts = 66.573669
current_received_ts = 66.573082
current_seq = 962
count = 71
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 66.556808/961, current 66.573669/962: elapsed=16861.0us expected=16890.8us +- 84.5us, error 0.2%
(kms_flip:1728) DEBUG: name = flip
last_ts = 66.573669
last_received_ts = 66.573082
last_seq = 962
current_ts = 66.590515
current_received_ts = 66.590050
current_seq = 963
count = 72
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 66.573669/962, current 66.590515/963: elapsed=16849.0us expected=16890.8us +- 84.5us, error 0.2%
(kms_flip:1728) DEBUG: name = flip
last_ts = 66.590515
last_received_ts = 66.590050
last_seq = 963
current_ts = 66.607368
current_received_ts = 66.606850
current_seq = 964
count = 73
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 66.590515/963, current 66.607368/964: elapsed=16855.0us expected=16890.8us +- 84.5us, error 0.2%
(kms_flip:1728) DEBUG: name = flip
last_ts = 66.607368
last_received_ts = 66.606850
last_seq = 964
current_ts = 66.624229
current_received_ts = 66.623779
current_seq = 965
count = 74
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 66.607368/964, current 66.624229/965: elapsed=16862.0us expected=16890.8us +- 84.5us, error 0.2%
(kms_flip:1728) DEBUG: name = flip
last_ts = 66.624229
last_received_ts = 66.623779
last_seq = 965
current_ts = 66.641090
current_received_ts = 66.640617
current_seq = 966
count = 75
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 66.624229/965, current 66.641090/966: elapsed=16860.0us expected=16890.8us +- 84.5us, error 0.2%
(kms_flip:1728) DEBUG: name = flip
last_ts = 66.641090
last_received_ts = 66.640617
last_seq = 966
current_ts = 66.657959
current_received_ts = 66.657486
current_seq = 967
count = 76
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 66.641090/966, current 66.657959/967: elapsed=16869.0us expected=16890.8us +- 84.5us, error 0.1%
(kms_flip:1728) DEBUG: name = flip
last_ts = 66.657959
last_received_ts = 66.657486
last_seq = 967
current_ts = 66.674820
current_received_ts = 66.674194
current_seq = 968
count = 77
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 66.657959/967, current 66.674820/968: elapsed=16858.0us expected=16890.8us +- 84.5us, error 0.2%
(kms_flip:1728) DEBUG: name = flip
last_ts = 66.674820
last_received_ts = 66.674194
last_seq = 968
current_ts = 66.691666
current_received_ts = 66.691132
current_seq = 969
count = 78
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 66.674820/968, current 66.691666/969: elapsed=16848.0us expected=16890.8us +- 84.5us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 66.691666
last_received_ts = 66.691132
last_seq = 969
current_ts = 66.708542
current_received_ts = 66.708076
current_seq = 970
count = 79
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 66.691666/969, current 66.708542/970: elapsed=16871.0us expected=16890.8us +- 84.5us, error 0.1%
(kms_flip:1728) DEBUG: name = flip
last_ts = 66.708542
last_received_ts = 66.708076
last_seq = 970
current_ts = 66.725395
current_received_ts = 66.724876
current_seq = 971
count = 80
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 66.708542/970, current 66.725395/971: elapsed=16855.0us expected=16890.8us +- 84.5us, error 0.2%
(kms_flip:1728) DEBUG: name = flip
last_ts = 66.725395
last_received_ts = 66.724876
last_seq = 971
current_ts = 66.742256
current_received_ts = 66.741760
current_seq = 972
count = 81
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 66.725395/971, current 66.742256/972: elapsed=16864.0us expected=16890.8us +- 84.5us, error 0.2%
(kms_flip:1728) DEBUG: name = flip
last_ts = 66.742256
last_received_ts = 66.741760
last_seq = 972
current_ts = 66.759109
current_received_ts = 66.758621
current_seq = 973
count = 82
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 66.742256/972, current 66.759109/973: elapsed=16851.0us expected=16890.8us +- 84.5us, error 0.2%
(kms_flip:1728) DEBUG: name = flip
last_ts = 66.759109
last_received_ts = 66.758621
last_seq = 973
current_ts = 66.775978
current_received_ts = 66.775452
current_seq = 974
count = 83
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 66.759109/973, current 66.775978/974: elapsed=16866.0us expected=16890.8us +- 84.5us, error 0.1%
(kms_flip:1728) DEBUG: name = flip
last_ts = 66.775978
last_received_ts = 66.775452
last_seq = 974
current_ts = 66.792831
current_received_ts = 66.792358
current_seq = 975
count = 84
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 66.775978/974, current 66.792831/975: elapsed=16855.0us expected=16890.8us +- 84.5us, error 0.2%
(kms_flip:1728) DEBUG: name = flip
last_ts = 66.792831
last_received_ts = 66.792358
last_seq = 975
current_ts = 66.809685
current_received_ts = 66.809181
current_seq = 976
count = 85
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 66.792831/975, current 66.809685/976: elapsed=16855.0us expected=16890.8us +- 84.5us, error 0.2%
(kms_flip:1728) DEBUG: name = flip
last_ts = 66.809685
last_received_ts = 66.809181
last_seq = 976
current_ts = 66.826546
current_received_ts = 66.826103
current_seq = 977
count = 86
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 66.809685/976, current 66.826546/977: elapsed=16859.0us expected=16890.8us +- 84.5us, error 0.2%
(kms_flip:1728) DEBUG: name = flip
last_ts = 66.826546
last_received_ts = 66.826103
last_seq = 977
current_ts = 66.843414
current_received_ts = 66.842941
current_seq = 978
count = 87
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 66.826546/977, current 66.843414/978: elapsed=16869.0us expected=16890.8us +- 84.5us, error 0.1%
(kms_flip:1728) DEBUG: name = flip
last_ts = 66.843414
last_received_ts = 66.842941
last_seq = 978
current_ts = 66.860245
current_received_ts = 66.859756
current_seq = 979
count = 88
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 66.843414/978, current 66.860245/979: elapsed=16834.0us expected=16890.8us +- 84.5us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 66.860245
last_received_ts = 66.859756
last_seq = 979
current_ts = 66.877068
current_received_ts = 66.876572
current_seq = 980
count = 89
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 66.860245/979, current 66.877068/980: elapsed=16823.0us expected=16890.8us +- 84.5us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 66.877068
last_received_ts = 66.876572
last_seq = 980
current_ts = 66.893898
current_received_ts = 66.893402
current_seq = 981
count = 90
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 66.877068/980, current 66.893898/981: elapsed=16830.0us expected=16890.8us +- 84.5us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 66.893898
last_received_ts = 66.893402
last_seq = 981
current_ts = 66.910736
current_received_ts = 66.910202
current_seq = 982
count = 91
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 66.893898/981, current 66.910736/982: elapsed=16839.0us expected=16890.8us +- 84.5us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 66.910736
last_received_ts = 66.910202
last_seq = 982
current_ts = 66.927574
current_received_ts = 66.927101
current_seq = 983
count = 92
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 66.910736/982, current 66.927574/983: elapsed=16835.0us expected=16890.8us +- 84.5us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 66.927574
last_received_ts = 66.927101
last_seq = 983
current_ts = 66.944405
current_received_ts = 66.943932
current_seq = 984
count = 93
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 66.927574/983, current 66.944405/984: elapsed=16831.0us expected=16890.8us +- 84.5us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 66.944405
last_received_ts = 66.943932
last_seq = 984
current_ts = 66.961243
current_received_ts = 66.960754
current_seq = 985
count = 94
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 66.944405/984, current 66.961243/985: elapsed=16834.0us expected=16890.8us +- 84.5us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 66.961243
last_received_ts = 66.960754
last_seq = 985
current_ts = 66.978065
current_received_ts = 66.977585
current_seq = 986
count = 95
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 66.961243/985, current 66.978065/986: elapsed=16828.0us expected=16890.8us +- 84.5us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 66.978065
last_received_ts = 66.977585
last_seq = 986
current_ts = 66.994888
current_received_ts = 66.994385
current_seq = 987
count = 96
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 66.978065/986, current 66.994888/987: elapsed=16824.0us expected=16890.8us +- 84.5us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 66.994888
last_received_ts = 66.994385
last_seq = 987
current_ts = 67.011726
current_received_ts = 67.011185
current_seq = 988
count = 97
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 66.994888/987, current 67.011726/988: elapsed=16839.0us expected=16890.8us +- 84.5us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 67.011726
last_received_ts = 67.011185
last_seq = 988
current_ts = 67.028557
current_received_ts = 67.028091
current_seq = 989
count = 98
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 67.011726/988, current 67.028557/989: elapsed=16827.0us expected=16890.8us +- 84.5us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 67.028557
last_received_ts = 67.028091
last_seq = 989
current_ts = 67.045395
current_received_ts = 67.044922
current_seq = 990
count = 99
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 67.028557/989, current 67.045395/990: elapsed=16840.0us expected=16890.8us +- 84.5us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 67.045395
last_received_ts = 67.044922
last_seq = 990
current_ts = 67.062225
current_received_ts = 67.061661
current_seq = 991
count = 100
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 67.045395/990, current 67.062225/991: elapsed=16830.0us expected=16890.8us +- 84.5us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 67.062225
last_received_ts = 67.061661
last_seq = 991
current_ts = 67.079056
current_received_ts = 67.078568
current_seq = 992
count = 101
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 67.062225/991, current 67.079056/992: elapsed=16830.0us expected=16890.8us +- 84.5us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 67.079056
last_received_ts = 67.078568
last_seq = 992
current_ts = 67.095886
current_received_ts = 67.095360
current_seq = 993
count = 102
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 67.079056/992, current 67.095886/993: elapsed=16831.0us expected=16890.8us +- 84.5us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 67.095886
last_received_ts = 67.095360
last_seq = 993
current_ts = 67.112724
current_received_ts = 67.112236
current_seq = 994
count = 103
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 67.095886/993, current 67.112724/994: elapsed=16838.0us expected=16890.8us +- 84.5us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 67.112724
last_received_ts = 67.112236
last_seq = 994
current_ts = 67.129555
current_received_ts = 67.129112
current_seq = 995
count = 104
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 67.112724/994, current 67.129555/995: elapsed=16831.0us expected=16890.8us +- 84.5us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 67.129555
last_received_ts = 67.129112
last_seq = 995
current_ts = 67.146385
current_received_ts = 67.145889
current_seq = 996
count = 105
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 67.129555/995, current 67.146385/996: elapsed=16826.0us expected=16890.8us +- 84.5us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 67.146385
last_received_ts = 67.145889
last_seq = 996
current_ts = 67.163216
current_received_ts = 67.162804
current_seq = 997
count = 106
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 67.146385/996, current 67.163216/997: elapsed=16832.0us expected=16890.8us +- 84.5us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 67.163216
last_received_ts = 67.162804
last_seq = 997
current_ts = 67.180054
current_received_ts = 67.179581
current_seq = 998
count = 107
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 67.163216/997, current 67.180054/998: elapsed=16838.0us expected=16890.8us +- 84.5us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 67.180054
last_received_ts = 67.179581
last_seq = 998
current_ts = 67.196884
current_received_ts = 67.196411
current_seq = 999
count = 108
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 67.180054/998, current 67.196884/999: elapsed=16832.0us expected=16890.8us +- 84.5us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 67.196884
last_received_ts = 67.196411
last_seq = 999
current_ts = 67.213715
current_received_ts = 67.213211
current_seq = 1000
count = 109
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 67.196884/999, current 67.213715/1000: elapsed=16828.0us expected=16890.8us +- 84.5us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 67.213715
last_received_ts = 67.213211
last_seq = 1000
current_ts = 67.230553
current_received_ts = 67.230087
current_seq = 1001
count = 110
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 67.213715/1000, current 67.230553/1001: elapsed=16837.0us expected=16890.8us +- 84.5us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 67.230553
last_received_ts = 67.230087
last_seq = 1001
current_ts = 67.247375
current_received_ts = 67.246841
current_seq = 1002
count = 111
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 67.230553/1001, current 67.247375/1002: elapsed=16827.0us expected=16890.8us +- 84.5us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 67.247375
last_received_ts = 67.246841
last_seq = 1002
current_ts = 67.264214
current_received_ts = 67.263748
current_seq = 1003
count = 112
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 67.247375/1002, current 67.264214/1003: elapsed=16836.0us expected=16890.8us +- 84.5us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 67.264214
last_received_ts = 67.263748
last_seq = 1003
current_ts = 67.281036
current_received_ts = 67.280525
current_seq = 1004
count = 113
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 67.264214/1003, current 67.281036/1004: elapsed=16823.0us expected=16890.8us +- 84.5us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 67.281036
last_received_ts = 67.280525
last_seq = 1004
current_ts = 67.297874
current_received_ts = 67.297417
current_seq = 1005
count = 114
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 67.281036/1004, current 67.297874/1005: elapsed=16835.0us expected=16890.8us +- 84.5us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 67.297874
last_received_ts = 67.297417
last_seq = 1005
current_ts = 67.314705
current_received_ts = 67.314201
current_seq = 1006
count = 115
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 67.297874/1005, current 67.314705/1006: elapsed=16837.0us expected=16890.8us +- 84.5us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 67.314705
last_received_ts = 67.314201
last_seq = 1006
current_ts = 67.331535
current_received_ts = 67.330978
current_seq = 1007
count = 116
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 67.314705/1006, current 67.331535/1007: elapsed=16831.0us expected=16890.8us +- 84.5us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 67.331535
last_received_ts = 67.330978
last_seq = 1007
current_ts = 67.348373
current_received_ts = 67.347885
current_seq = 1008
count = 117
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 67.331535/1007, current 67.348373/1008: elapsed=16834.0us expected=16890.8us +- 84.5us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 67.348373
last_received_ts = 67.347885
last_seq = 1008
current_ts = 67.365196
current_received_ts = 67.364716
current_seq = 1009
count = 118
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 67.348373/1008, current 67.365196/1009: elapsed=16824.0us expected=16890.8us +- 84.5us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 67.365196
last_received_ts = 67.364716
last_seq = 1009
current_ts = 67.382034
current_received_ts = 67.381470
current_seq = 1010
count = 119
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 67.365196/1009, current 67.382034/1010: elapsed=16837.0us expected=16890.8us +- 84.5us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 67.382034
last_received_ts = 67.381470
last_seq = 1010
current_ts = 67.398857
current_received_ts = 67.398399
current_seq = 1011
count = 120
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 67.382034/1010, current 67.398857/1011: elapsed=16822.0us expected=16890.8us +- 84.5us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 67.398857
last_received_ts = 67.398399
last_seq = 1011
current_ts = 67.415695
current_received_ts = 67.415184
current_seq = 1012
count = 121
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 67.398857/1011, current 67.415695/1012: elapsed=16841.0us expected=16890.8us +- 84.5us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 67.415695
last_received_ts = 67.415184
last_seq = 1012
current_ts = 67.432533
current_received_ts = 67.432083
current_seq = 1013
count = 122
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 67.415695/1012, current 67.432533/1013: elapsed=16836.0us expected=16890.8us +- 84.5us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 67.432533
last_received_ts = 67.432083
last_seq = 1013
current_ts = 67.449364
current_received_ts = 67.448822
current_seq = 1014
count = 123
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 67.432533/1013, current 67.449364/1014: elapsed=16830.0us expected=16890.8us +- 84.5us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 67.449364
last_received_ts = 67.448822
last_seq = 1014
current_ts = 67.466194
current_received_ts = 67.465721
current_seq = 1015
count = 124
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 67.449364/1014, current 67.466194/1015: elapsed=16831.0us expected=16890.8us +- 84.5us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 67.466194
last_received_ts = 67.465721
last_seq = 1015
current_ts = 67.483025
current_received_ts = 67.482544
current_seq = 1016
count = 125
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 67.466194/1015, current 67.483025/1016: elapsed=16827.0us expected=16890.8us +- 84.5us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 67.483025
last_received_ts = 67.482544
last_seq = 1016
current_ts = 67.499855
current_received_ts = 67.499367
current_seq = 1017
count = 126
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 67.483025/1016, current 67.499855/1017: elapsed=16836.0us expected=16890.8us +- 84.5us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 67.499855
last_received_ts = 67.499367
last_seq = 1017
current_ts = 67.516685
current_received_ts = 67.516235
current_seq = 1018
count = 127
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 67.499855/1017, current 67.516685/1018: elapsed=16828.0us expected=16890.8us +- 84.5us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 67.516685
last_received_ts = 67.516235
last_seq = 1018
current_ts = 67.533524
current_received_ts = 67.533073
current_seq = 1019
count = 128
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 67.516685/1018, current 67.533524/1019: elapsed=16840.0us expected=16890.8us +- 84.5us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 67.533524
last_received_ts = 67.533073
last_seq = 1019
current_ts = 67.550354
current_received_ts = 67.549889
current_seq = 1020
count = 129
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 67.533524/1019, current 67.550354/1020: elapsed=16831.0us expected=16890.8us +- 84.5us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 67.550354
last_received_ts = 67.549889
last_seq = 1020
current_ts = 67.567184
current_received_ts = 67.566666
current_seq = 1021
count = 130
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 67.550354/1020, current 67.567184/1021: elapsed=16828.0us expected=16890.8us +- 84.5us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 67.567184
last_received_ts = 67.566666
last_seq = 1021
current_ts = 67.584015
current_received_ts = 67.583496
current_seq = 1022
count = 131
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 67.567184/1021, current 67.584015/1022: elapsed=16830.0us expected=16890.8us +- 84.5us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 67.584015
last_received_ts = 67.583496
last_seq = 1022
current_ts = 67.600853
current_received_ts = 67.600372
current_seq = 1023
count = 132
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 67.584015/1022, current 67.600853/1023: elapsed=16838.0us expected=16890.8us +- 84.5us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 67.600853
last_received_ts = 67.600372
last_seq = 1023
current_ts = 67.617676
current_received_ts = 67.617104
current_seq = 1024
count = 133
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 67.600853/1023, current 67.617676/1024: elapsed=16822.0us expected=16890.8us +- 84.5us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 67.617676
last_received_ts = 67.617104
last_seq = 1024
current_ts = 67.634514
current_received_ts = 67.634064
current_seq = 1025
count = 134
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 67.617676/1024, current 67.634514/1025: elapsed=16842.0us expected=16890.8us +- 84.5us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 67.634514
last_received_ts = 67.634064
last_seq = 1025
current_ts = 67.651337
current_received_ts = 67.650848
current_seq = 1026
count = 135
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 67.634514/1025, current 67.651337/1026: elapsed=16822.0us expected=16890.8us +- 84.5us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 67.651337
last_received_ts = 67.650848
last_seq = 1026
current_ts = 67.668182
current_received_ts = 67.667717
current_seq = 1027
count = 136
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 67.651337/1026, current 67.668182/1027: elapsed=16842.0us expected=16890.8us +- 84.5us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 67.668182
last_received_ts = 67.667717
last_seq = 1027
current_ts = 67.685013
current_received_ts = 67.684486
current_seq = 1028
count = 137
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 67.668182/1027, current 67.685013/1028: elapsed=16830.0us expected=16890.8us +- 84.5us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 67.685013
last_received_ts = 67.684486
last_seq = 1028
current_ts = 67.701836
current_received_ts = 67.701340
current_seq = 1029
count = 138
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 67.685013/1028, current 67.701836/1029: elapsed=16829.0us expected=16890.8us +- 84.5us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 67.701836
last_received_ts = 67.701340
last_seq = 1029
current_ts = 67.718674
current_received_ts = 67.718178
current_seq = 1030
count = 139
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 67.701836/1029, current 67.718674/1030: elapsed=16834.0us expected=16890.8us +- 84.5us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 67.718674
last_received_ts = 67.718178
last_seq = 1030
current_ts = 67.735504
current_received_ts = 67.734993
current_seq = 1031
count = 140
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 67.718674/1030, current 67.735504/1031: elapsed=16830.0us expected=16890.8us +- 84.5us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 67.735504
last_received_ts = 67.734993
last_seq = 1031
current_ts = 67.752335
current_received_ts = 67.751846
current_seq = 1032
count = 141
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 67.735504/1031, current 67.752335/1032: elapsed=16834.0us expected=16890.8us +- 84.5us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 67.752335
last_received_ts = 67.751846
last_seq = 1032
current_ts = 67.769173
current_received_ts = 67.768700
current_seq = 1033
count = 142
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 67.752335/1032, current 67.769173/1033: elapsed=16835.0us expected=16890.8us +- 84.5us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 67.769173
last_received_ts = 67.768700
last_seq = 1033
current_ts = 67.785995
current_received_ts = 67.785492
current_seq = 1034
count = 143
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 67.769173/1033, current 67.785995/1034: elapsed=16827.0us expected=16890.8us +- 84.5us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 67.785995
last_received_ts = 67.785492
last_seq = 1034
current_ts = 67.802834
current_received_ts = 67.802322
current_seq = 1035
count = 144
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 67.785995/1034, current 67.802834/1035: elapsed=16834.0us expected=16890.8us +- 84.5us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 67.802834
last_received_ts = 67.802322
last_seq = 1035
current_ts = 67.819656
current_received_ts = 67.819206
current_seq = 1036
count = 145
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 67.802834/1035, current 67.819656/1036: elapsed=16823.0us expected=16890.8us +- 84.5us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 67.819656
last_received_ts = 67.819206
last_seq = 1036
current_ts = 67.836494
current_received_ts = 67.835938
current_seq = 1037
count = 146
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 67.819656/1036, current 67.836494/1037: elapsed=16842.0us expected=16890.8us +- 84.5us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 67.836494
last_received_ts = 67.835938
last_seq = 1037
current_ts = 67.853310
current_received_ts = 67.852859
current_seq = 1038
count = 147
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 67.836494/1037, current 67.853310/1038: elapsed=16808.0us expected=16890.8us +- 84.5us, error 0.5%
(kms_flip:1728) DEBUG: name = flip
last_ts = 67.853310
last_received_ts = 67.852859
last_seq = 1038
current_ts = 67.870125
current_received_ts = 67.869690
current_seq = 1039
count = 148
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 67.853310/1038, current 67.870125/1039: elapsed=16821.0us expected=16890.8us +- 84.5us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 67.870125
last_received_ts = 67.869690
last_seq = 1039
current_ts = 67.886932
current_received_ts = 67.886497
current_seq = 1040
count = 149
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 67.870125/1039, current 67.886932/1040: elapsed=16807.0us expected=16890.8us +- 84.5us, error 0.5%
(kms_flip:1728) DEBUG: name = flip
last_ts = 67.886932
last_received_ts = 67.886497
last_seq = 1040
current_ts = 67.903732
current_received_ts = 67.903221
current_seq = 1041
count = 150
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 67.886932/1040, current 67.903732/1041: elapsed=16797.0us expected=16890.8us +- 84.5us, error 0.6%
(kms_flip:1728) DEBUG: inconsistent flip ts/seq: last 67.886932/1040, current 67.903732/1041: elapsed=16797.0us expected=16890.8us
(kms_flip:1728) DEBUG: expected 66377, counted 150, encoder type 2
(kms_flip:1728) DEBUG: dropped frames, expected 66377, counted 150, encoder type 2
(kms_flip:1728) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:1728) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:1728) CRITICAL: Last errno: 4, Interrupted system call
(kms_flip:1728) igt_core-INFO: Stack trace:
(kms_flip:1728) igt_core-INFO:   #0 ../lib/igt_core.c:2051 __igt_fail_assert()
(kms_flip:1728) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:1728) igt_core-INFO:   #2 ../tests/kms_flip.c:1845 run_test()
(kms_flip:1728) igt_core-INFO:   #3 ../tests/kms_flip.c:2114 __igt_unique____real_main2001()
(kms_flip:1728) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:1728) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:1728) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:1728) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest A-HDMI-A1: FAIL (6.008s)
Starting dynamic subtest: B-HDMI-A1
(kms_flip:1728) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:1728) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:1728) CRITICAL: Last errno: 4, Interrupted system call
Dynamic subtest B-HDMI-A1 failed.
**** DEBUG ****
(kms_flip:1728) DEBUG: name = flip
last_ts = 76.926552
last_received_ts = 76.926079
last_seq = 504
current_ts = 76.943237
current_received_ts = 76.942696
current_seq = 505
count = 326
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 76.926552/504, current 76.943237/505: elapsed=16682.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 76.943237
last_received_ts = 76.942696
last_seq = 505
current_ts = 76.959938
current_received_ts = 76.959419
current_seq = 506
count = 327
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 76.943237/505, current 76.959938/506: elapsed=16699.0us expected=16752.5us +- 83.8us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 76.959938
last_received_ts = 76.959419
last_seq = 506
current_ts = 76.976624
current_received_ts = 76.976151
current_seq = 507
count = 328
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 76.959938/506, current 76.976624/507: elapsed=16691.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 76.976624
last_received_ts = 76.976151
last_seq = 507
current_ts = 76.993317
current_received_ts = 76.992798
current_seq = 508
count = 329
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 76.976624/507, current 76.993317/508: elapsed=16690.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 76.993317
last_received_ts = 76.992798
last_seq = 508
current_ts = 77.010010
current_received_ts = 77.009514
current_seq = 509
count = 330
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 76.993317/508, current 77.010010/509: elapsed=16695.0us expected=16752.5us +- 83.8us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 77.010010
last_received_ts = 77.009514
last_seq = 509
current_ts = 77.026688
current_received_ts = 77.026215
current_seq = 510
count = 331
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 77.010010/509, current 77.026688/510: elapsed=16680.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 77.026688
last_received_ts = 77.026215
last_seq = 510
current_ts = 77.043388
current_received_ts = 77.042831
current_seq = 511
count = 332
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 77.026688/510, current 77.043388/511: elapsed=16694.0us expected=16752.5us +- 83.8us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 77.043388
last_received_ts = 77.042831
last_seq = 511
current_ts = 77.060081
current_received_ts = 77.059601
current_seq = 512
count = 333
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 77.043388/511, current 77.060081/512: elapsed=16694.0us expected=16752.5us +- 83.8us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 77.060081
last_received_ts = 77.059601
last_seq = 512
current_ts = 77.076767
current_received_ts = 77.076279
current_seq = 513
count = 334
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 77.060081/512, current 77.076767/513: elapsed=16689.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 77.076767
last_received_ts = 77.076279
last_seq = 513
current_ts = 77.093468
current_received_ts = 77.093018
current_seq = 514
count = 335
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 77.076767/513, current 77.093468/514: elapsed=16700.0us expected=16752.5us +- 83.8us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 77.093468
last_received_ts = 77.093018
last_seq = 514
current_ts = 77.110161
current_received_ts = 77.109726
current_seq = 515
count = 336
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 77.093468/514, current 77.110161/515: elapsed=16692.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 77.110161
last_received_ts = 77.109726
last_seq = 515
current_ts = 77.126846
current_received_ts = 77.126259
current_seq = 516
count = 337
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 77.110161/515, current 77.126846/516: elapsed=16688.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 77.126846
last_received_ts = 77.126259
last_seq = 516
current_ts = 77.143539
current_received_ts = 77.143082
current_seq = 517
count = 338
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 77.126846/516, current 77.143539/517: elapsed=16694.0us expected=16752.5us +- 83.8us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 77.143539
last_received_ts = 77.143082
last_seq = 517
current_ts = 77.160233
current_received_ts = 77.159775
current_seq = 518
count = 339
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 77.143539/517, current 77.160233/518: elapsed=16689.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 77.160233
last_received_ts = 77.159775
last_seq = 518
current_ts = 77.176926
current_received_ts = 77.176376
current_seq = 519
count = 340
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 77.160233/518, current 77.176926/519: elapsed=16691.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 77.176926
last_received_ts = 77.176376
last_seq = 519
current_ts = 77.193611
current_received_ts = 77.193153
current_seq = 520
count = 341
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 77.176926/519, current 77.193611/520: elapsed=16688.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 77.193611
last_received_ts = 77.193153
last_seq = 520
current_ts = 77.210304
current_received_ts = 77.209793
current_seq = 521
count = 342
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 77.193611/520, current 77.210304/521: elapsed=16696.0us expected=16752.5us +- 83.8us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 77.210304
last_received_ts = 77.209793
last_seq = 521
current_ts = 77.226997
current_received_ts = 77.226479
current_seq = 522
count = 343
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 77.210304/521, current 77.226997/522: elapsed=16690.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 77.226997
last_received_ts = 77.226479
last_seq = 522
current_ts = 77.243675
current_received_ts = 77.243134
current_seq = 523
count = 344
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 77.226997/522, current 77.243675/523: elapsed=16682.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 77.243675
last_received_ts = 77.243134
last_seq = 523
current_ts = 77.260384
current_received_ts = 77.259865
current_seq = 524
count = 345
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 77.243675/523, current 77.260384/524: elapsed=16702.0us expected=16752.5us +- 83.8us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 77.260384
last_received_ts = 77.259865
last_seq = 524
current_ts = 77.277077
current_received_ts = 77.276566
current_seq = 525
count = 346
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 77.260384/524, current 77.277077/525: elapsed=16694.0us expected=16752.5us +- 83.8us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 77.277077
last_received_ts = 77.276566
last_seq = 525
current_ts = 77.293762
current_received_ts = 77.293213
current_seq = 526
count = 347
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 77.277077/525, current 77.293762/526: elapsed=16686.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 77.293762
last_received_ts = 77.293213
last_seq = 526
current_ts = 77.310455
current_received_ts = 77.309967
current_seq = 527
count = 348
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 77.293762/526, current 77.310455/527: elapsed=16696.0us expected=16752.5us +- 83.8us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 77.310455
last_received_ts = 77.309967
last_seq = 527
current_ts = 77.327141
current_received_ts = 77.326637
current_seq = 528
count = 349
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 77.310455/527, current 77.327141/528: elapsed=16683.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 77.327141
last_received_ts = 77.326637
last_seq = 528
current_ts = 77.343842
current_received_ts = 77.343323
current_seq = 529
count = 350
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 77.327141/528, current 77.343842/529: elapsed=16699.0us expected=16752.5us +- 83.8us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 77.343842
last_received_ts = 77.343323
last_seq = 529
current_ts = 77.360519
current_received_ts = 77.360023
current_seq = 530
count = 351
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 77.343842/529, current 77.360519/530: elapsed=16681.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 77.360519
last_received_ts = 77.360023
last_seq = 530
current_ts = 77.377213
current_received_ts = 77.376732
current_seq = 531
count = 352
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 77.360519/530, current 77.377213/531: elapsed=16696.0us expected=16752.5us +- 83.8us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 77.377213
last_received_ts = 77.376732
last_seq = 531
current_ts = 77.393913
current_received_ts = 77.393425
current_seq = 532
count = 353
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 77.377213/531, current 77.393913/532: elapsed=16699.0us expected=16752.5us +- 83.8us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 77.393913
last_received_ts = 77.393425
last_seq = 532
current_ts = 77.410591
current_received_ts = 77.410049
current_seq = 533
count = 354
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 77.393913/532, current 77.410591/533: elapsed=16680.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 77.410591
last_received_ts = 77.410049
last_seq = 533
current_ts = 77.427299
current_received_ts = 77.426811
current_seq = 534
count = 355
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 77.410591/533, current 77.427299/534: elapsed=16703.0us expected=16752.5us +- 83.8us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 77.427299
last_received_ts = 77.426811
last_seq = 534
current_ts = 77.443985
current_received_ts = 77.443466
current_seq = 535
count = 356
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 77.427299/534, current 77.443985/535: elapsed=16685.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 77.443985
last_received_ts = 77.443466
last_seq = 535
current_ts = 77.460670
current_received_ts = 77.460175
current_seq = 536
count = 357
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 77.443985/535, current 77.460670/536: elapsed=16687.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 77.460670
last_received_ts = 77.460175
last_seq = 536
current_ts = 77.477371
current_received_ts = 77.476906
current_seq = 537
count = 358
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 77.460670/536, current 77.477371/537: elapsed=16702.0us expected=16752.5us +- 83.8us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 77.477371
last_received_ts = 77.476906
last_seq = 537
current_ts = 77.494057
current_received_ts = 77.493576
current_seq = 538
count = 359
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 77.477371/537, current 77.494057/538: elapsed=16684.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 77.494057
last_received_ts = 77.493576
last_seq = 538
current_ts = 77.510750
current_received_ts = 77.510231
current_seq = 539
count = 360
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 77.494057/538, current 77.510750/539: elapsed=16694.0us expected=16752.5us +- 83.8us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 77.510750
last_received_ts = 77.510231
last_seq = 539
current_ts = 77.527451
current_received_ts = 77.526962
current_seq = 540
count = 361
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 77.510750/539, current 77.527451/540: elapsed=16698.0us expected=16752.5us +- 83.8us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 77.527451
last_received_ts = 77.526962
last_seq = 540
current_ts = 77.544128
current_received_ts = 77.543633
current_seq = 541
count = 362
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 77.527451/540, current 77.544128/541: elapsed=16681.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 77.544128
last_received_ts = 77.543633
last_seq = 541
current_ts = 77.560822
current_received_ts = 77.560326
current_seq = 542
count = 363
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 77.544128/541, current 77.560822/542: elapsed=16694.0us expected=16752.5us +- 83.8us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 77.560822
last_received_ts = 77.560326
last_seq = 542
current_ts = 77.577522
current_received_ts = 77.577095
current_seq = 543
count = 364
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 77.560822/542, current 77.577522/543: elapsed=16698.0us expected=16752.5us +- 83.8us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 77.577522
last_received_ts = 77.577095
last_seq = 543
current_ts = 77.594208
current_received_ts = 77.593719
current_seq = 544
count = 365
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 77.577522/543, current 77.594208/544: elapsed=16688.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 77.594208
last_received_ts = 77.593719
last_seq = 544
current_ts = 77.610901
current_received_ts = 77.610420
current_seq = 545
count = 366
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 77.594208/544, current 77.610901/545: elapsed=16695.0us expected=16752.5us +- 83.8us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 77.610901
last_received_ts = 77.610420
last_seq = 545
current_ts = 77.627594
current_received_ts = 77.627075
current_seq = 546
count = 367
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 77.610901/545, current 77.627594/546: elapsed=16689.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 77.627594
last_received_ts = 77.627075
last_seq = 546
current_ts = 77.644279
current_received_ts = 77.643738
current_seq = 547
count = 368
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 77.627594/546, current 77.644279/547: elapsed=16690.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 77.644279
last_received_ts = 77.643738
last_seq = 547
current_ts = 77.660973
current_received_ts = 77.660408
current_seq = 548
count = 369
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 77.644279/547, current 77.660973/548: elapsed=16693.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 77.660973
last_received_ts = 77.660408
last_seq = 548
current_ts = 77.677658
current_received_ts = 77.677101
current_seq = 549
count = 370
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 77.660973/548, current 77.677658/549: elapsed=16683.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 77.677658
last_received_ts = 77.677101
last_seq = 549
current_ts = 77.694359
current_received_ts = 77.693848
current_seq = 550
count = 371
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 77.677658/549, current 77.694359/550: elapsed=16703.0us expected=16752.5us +- 83.8us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 77.694359
last_received_ts = 77.693848
last_seq = 550
current_ts = 77.711052
current_received_ts = 77.710564
current_seq = 551
count = 372
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 77.694359/550, current 77.711052/551: elapsed=16691.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 77.711052
last_received_ts = 77.710564
last_seq = 551
current_ts = 77.727730
current_received_ts = 77.727226
current_seq = 552
count = 373
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 77.711052/551, current 77.727730/552: elapsed=16681.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 77.727730
last_received_ts = 77.727226
last_seq = 552
current_ts = 77.744438
current_received_ts = 77.744003
current_seq = 553
count = 374
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 77.727730/552, current 77.744438/553: elapsed=16702.0us expected=16752.5us +- 83.8us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 77.744438
last_received_ts = 77.744003
last_seq = 553
current_ts = 77.761116
current_received_ts = 77.760651
current_seq = 554
count = 375
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 77.744438/553, current 77.761116/554: elapsed=16684.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 77.761116
last_received_ts = 77.760651
last_seq = 554
current_ts = 77.777802
current_received_ts = 77.777336
current_seq = 555
count = 376
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 77.761116/554, current 77.777802/555: elapsed=16686.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 77.777802
last_received_ts = 77.777336
last_seq = 555
current_ts = 77.794510
current_received_ts = 77.794067
current_seq = 556
count = 377
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 77.777802/555, current 77.794510/556: elapsed=16704.0us expected=16752.5us +- 83.8us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 77.794510
last_received_ts = 77.794067
last_seq = 556
current_ts = 77.811188
current_received_ts = 77.810669
current_seq = 557
count = 378
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 77.794510/556, current 77.811188/557: elapsed=16681.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 77.811188
last_received_ts = 77.810669
last_seq = 557
current_ts = 77.827888
current_received_ts = 77.827370
current_seq = 558
count = 379
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 77.811188/557, current 77.827888/558: elapsed=16699.0us expected=16752.5us +- 83.8us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 77.827888
last_received_ts = 77.827370
last_seq = 558
current_ts = 77.844582
current_received_ts = 77.844093
current_seq = 559
count = 380
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 77.827888/558, current 77.844582/559: elapsed=16694.0us expected=16752.5us +- 83.8us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 77.844582
last_received_ts = 77.844093
last_seq = 559
current_ts = 77.861252
current_received_ts = 77.860641
current_seq = 560
count = 381
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 77.844582/559, current 77.861252/560: elapsed=16672.0us expected=16752.5us +- 83.8us, error 0.5%
(kms_flip:1728) DEBUG: name = flip
last_ts = 77.861252
last_received_ts = 77.860641
last_seq = 560
current_ts = 77.877937
current_received_ts = 77.877426
current_seq = 561
count = 382
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 77.861252/560, current 77.877937/561: elapsed=16685.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 77.877937
last_received_ts = 77.877426
last_seq = 561
current_ts = 77.894630
current_received_ts = 77.894150
current_seq = 562
count = 383
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 77.877937/561, current 77.894630/562: elapsed=16687.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 77.894630
last_received_ts = 77.894150
last_seq = 562
current_ts = 77.911316
current_received_ts = 77.910751
current_seq = 563
count = 384
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 77.894630/562, current 77.911316/563: elapsed=16692.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 77.911316
last_received_ts = 77.910751
last_seq = 563
current_ts = 77.928001
current_received_ts = 77.927513
current_seq = 564
count = 385
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 77.911316/563, current 77.928001/564: elapsed=16685.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 77.928001
last_received_ts = 77.927513
last_seq = 564
current_ts = 77.944687
current_received_ts = 77.944160
current_seq = 565
count = 386
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 77.928001/564, current 77.944687/565: elapsed=16685.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 77.944687
last_received_ts = 77.944160
last_seq = 565
current_ts = 77.961372
current_received_ts = 77.960899
current_seq = 566
count = 387
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 77.944687/565, current 77.961372/566: elapsed=16687.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 77.961372
last_received_ts = 77.960899
last_seq = 566
current_ts = 77.978065
current_received_ts = 77.977600
current_seq = 567
count = 388
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 77.961372/566, current 77.978065/567: elapsed=16688.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 77.978065
last_received_ts = 77.977600
last_seq = 567
current_ts = 77.994743
current_received_ts = 77.994293
current_seq = 568
count = 389
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 77.978065/567, current 77.994743/568: elapsed=16678.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 77.994743
last_received_ts = 77.994293
last_seq = 568
current_ts = 78.011421
current_received_ts = 78.010895
current_seq = 569
count = 390
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 77.994743/568, current 78.011421/569: elapsed=16681.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 78.011421
last_received_ts = 78.010895
last_seq = 569
current_ts = 78.028122
current_received_ts = 78.027649
current_seq = 570
count = 391
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 78.011421/569, current 78.028122/570: elapsed=16696.0us expected=16752.5us +- 83.8us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 78.028122
last_received_ts = 78.027649
last_seq = 570
current_ts = 78.044800
current_received_ts = 78.044312
current_seq = 571
count = 392
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 78.028122/570, current 78.044800/571: elapsed=16678.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 78.044800
last_received_ts = 78.044312
last_seq = 571
current_ts = 78.061493
current_received_ts = 78.061043
current_seq = 572
count = 393
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 78.044800/571, current 78.061493/572: elapsed=16694.0us expected=16752.5us +- 83.8us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 78.061493
last_received_ts = 78.061043
last_seq = 572
current_ts = 78.078178
current_received_ts = 78.077690
current_seq = 573
count = 394
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 78.061493/572, current 78.078178/573: elapsed=16684.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 78.078178
last_received_ts = 78.077690
last_seq = 573
current_ts = 78.094849
current_received_ts = 78.094345
current_seq = 574
count = 395
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 78.078178/573, current 78.094849/574: elapsed=16675.0us expected=16752.5us +- 83.8us, error 0.5%
(kms_flip:1728) DEBUG: name = flip
last_ts = 78.094849
last_received_ts = 78.094345
last_seq = 574
current_ts = 78.111549
current_received_ts = 78.111076
current_seq = 575
count = 396
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 78.094849/574, current 78.111549/575: elapsed=16696.0us expected=16752.5us +- 83.8us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 78.111549
last_received_ts = 78.111076
last_seq = 575
current_ts = 78.128227
current_received_ts = 78.127708
current_seq = 576
count = 397
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 78.111549/575, current 78.128227/576: elapsed=16678.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 78.128227
last_received_ts = 78.127708
last_seq = 576
current_ts = 78.144913
current_received_ts = 78.144409
current_seq = 577
count = 398
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 78.128227/576, current 78.144913/577: elapsed=16690.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 78.144913
last_received_ts = 78.144409
last_seq = 577
current_ts = 78.161591
current_received_ts = 78.161102
current_seq = 578
count = 399
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 78.144913/577, current 78.161591/578: elapsed=16680.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 78.161591
last_received_ts = 78.161102
last_seq = 578
current_ts = 78.178276
current_received_ts = 78.177734
current_seq = 579
count = 400
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 78.161591/578, current 78.178276/579: elapsed=16685.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 78.178276
last_received_ts = 78.177734
last_seq = 579
current_ts = 78.194962
current_received_ts = 78.194481
current_seq = 580
count = 401
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 78.178276/579, current 78.194962/580: elapsed=16684.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 78.194962
last_received_ts = 78.194481
last_seq = 580
current_ts = 78.211655
current_received_ts = 78.211121
current_seq = 581
count = 402
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 78.194962/580, current 78.211655/581: elapsed=16693.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 78.211655
last_received_ts = 78.211121
last_seq = 581
current_ts = 78.228333
current_received_ts = 78.227783
current_seq = 582
count = 403
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 78.211655/581, current 78.228333/582: elapsed=16676.0us expected=16752.5us +- 83.8us, error 0.5%
(kms_flip:1728) DEBUG: name = flip
last_ts = 78.228333
last_received_ts = 78.227783
last_seq = 582
current_ts = 78.245018
current_received_ts = 78.244537
current_seq = 583
count = 404
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 78.228333/582, current 78.245018/583: elapsed=16689.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 78.245018
last_received_ts = 78.244537
last_seq = 583
current_ts = 78.261711
current_received_ts = 78.261169
current_seq = 584
count = 405
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 78.245018/583, current 78.261711/584: elapsed=16691.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 78.261711
last_received_ts = 78.261169
last_seq = 584
current_ts = 78.278389
current_received_ts = 78.277817
current_seq = 585
count = 406
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 78.261711/584, current 78.278389/585: elapsed=16676.0us expected=16752.5us +- 83.8us, error 0.5%
(kms_flip:1728) DEBUG: name = flip
last_ts = 78.278389
last_received_ts = 78.277817
last_seq = 585
current_ts = 78.295082
current_received_ts = 78.294609
current_seq = 586
count = 407
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 78.278389/585, current 78.295082/586: elapsed=16695.0us expected=16752.5us +- 83.8us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 78.295082
last_received_ts = 78.294609
last_seq = 586
current_ts = 78.311760
current_received_ts = 78.311241
current_seq = 587
count = 408
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 78.295082/586, current 78.311760/587: elapsed=16675.0us expected=16752.5us +- 83.8us, error 0.5%
(kms_flip:1728) DEBUG: name = flip
last_ts = 78.311760
last_received_ts = 78.311241
last_seq = 587
current_ts = 78.328445
current_received_ts = 78.327858
current_seq = 588
count = 409
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 78.311760/587, current 78.328445/588: elapsed=16691.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 78.328445
last_received_ts = 78.327858
last_seq = 588
current_ts = 78.345139
current_received_ts = 78.344666
current_seq = 589
count = 410
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 78.328445/588, current 78.345139/589: elapsed=16689.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 78.345139
last_received_ts = 78.344666
last_seq = 589
current_ts = 78.361816
current_received_ts = 78.361305
current_seq = 590
count = 411
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 78.345139/589, current 78.361816/590: elapsed=16682.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 78.361816
last_received_ts = 78.361305
last_seq = 590
current_ts = 78.378510
current_received_ts = 78.378036
current_seq = 591
count = 412
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 78.361816/590, current 78.378510/591: elapsed=16688.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 78.378510
last_received_ts = 78.378036
last_seq = 591
current_ts = 78.395195
current_received_ts = 78.394730
current_seq = 592
count = 413
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 78.378510/591, current 78.395195/592: elapsed=16686.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 78.395195
last_received_ts = 78.394730
last_seq = 592
current_ts = 78.411873
current_received_ts = 78.411362
current_seq = 593
count = 414
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 78.395195/592, current 78.411873/593: elapsed=16678.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 78.411873
last_received_ts = 78.411362
last_seq = 593
current_ts = 78.428551
current_received_ts = 78.428108
current_seq = 594
count = 415
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 78.411873/593, current 78.428551/594: elapsed=16679.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 78.428551
last_received_ts = 78.428108
last_seq = 594
current_ts = 78.445244
current_received_ts = 78.444763
current_seq = 595
count = 416
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 78.428551/594, current 78.445244/595: elapsed=16692.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 78.445244
last_received_ts = 78.444763
last_seq = 595
current_ts = 78.461929
current_received_ts = 78.461418
current_seq = 596
count = 417
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 78.445244/595, current 78.461929/596: elapsed=16688.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 78.461929
last_received_ts = 78.461418
last_seq = 596
current_ts = 78.478622
current_received_ts = 78.478111
current_seq = 597
count = 418
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 78.461929/596, current 78.478622/597: elapsed=16688.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 78.478622
last_received_ts = 78.478111
last_seq = 597
current_ts = 78.495293
current_received_ts = 78.494781
current_seq = 598
count = 419
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 78.478622/597, current 78.495293/598: elapsed=16676.0us expected=16752.5us +- 83.8us, error 0.5%
(kms_flip:1728) DEBUG: name = flip
last_ts = 78.495293
last_received_ts = 78.494781
last_seq = 598
current_ts = 78.511986
current_received_ts = 78.511513
current_seq = 599
count = 420
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 78.495293/598, current 78.511986/599: elapsed=16689.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 78.511986
last_received_ts = 78.511513
last_seq = 599
current_ts = 78.528671
current_received_ts = 78.528168
current_seq = 600
count = 421
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 78.511986/599, current 78.528671/600: elapsed=16688.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 78.528671
last_received_ts = 78.528168
last_seq = 600
current_ts = 78.545357
current_received_ts = 78.544891
current_seq = 601
count = 422
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 78.528671/600, current 78.545357/601: elapsed=16687.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 78.545357
last_received_ts = 78.544891
last_seq = 601
current_ts = 78.562042
current_received_ts = 78.561455
current_seq = 602
count = 423
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 78.545357/601, current 78.562042/602: elapsed=16683.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 78.562042
last_received_ts = 78.561455
last_seq = 602
current_ts = 78.578720
current_received_ts = 78.578201
current_seq = 603
count = 424
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 78.562042/602, current 78.578720/603: elapsed=16677.0us expected=16752.5us +- 83.8us, error 0.5%
(kms_flip:1728) DEBUG: name = flip
last_ts = 78.578720
last_received_ts = 78.578201
last_seq = 603
current_ts = 78.595406
current_received_ts = 78.594933
current_seq = 604
count = 425
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 78.578720/603, current 78.595406/604: elapsed=16683.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 78.595406
last_received_ts = 78.594933
last_seq = 604
current_ts = 78.612091
current_received_ts = 78.611641
current_seq = 605
count = 426
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 78.595406/604, current 78.612091/605: elapsed=16687.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 78.612091
last_received_ts = 78.611641
last_seq = 605
current_ts = 78.628777
current_received_ts = 78.628281
current_seq = 606
count = 427
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 78.612091/605, current 78.628777/606: elapsed=16684.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 78.628777
last_received_ts = 78.628281
last_seq = 606
current_ts = 78.645470
current_received_ts = 78.644905
current_seq = 607
count = 428
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 78.628777/606, current 78.645470/607: elapsed=16694.0us expected=16752.5us +- 83.8us, error 0.3%
(kms_flip:1728) DEBUG: name = flip
last_ts = 78.645470
last_received_ts = 78.644905
last_seq = 607
current_ts = 78.662155
current_received_ts = 78.661674
current_seq = 608
count = 429
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 78.645470/607, current 78.662155/608: elapsed=16688.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 78.662155
last_received_ts = 78.661674
last_seq = 608
current_ts = 78.678833
current_received_ts = 78.678375
current_seq = 609
count = 430
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 78.662155/608, current 78.678833/609: elapsed=16681.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 78.678833
last_received_ts = 78.678375
last_seq = 609
current_ts = 78.695526
current_received_ts = 78.695084
current_seq = 610
count = 431
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 78.678833/609, current 78.695526/610: elapsed=16688.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 78.695526
last_received_ts = 78.695084
last_seq = 610
current_ts = 78.712212
current_received_ts = 78.711769
current_seq = 611
count = 432
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 78.695526/610, current 78.712212/611: elapsed=16687.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 78.712212
last_received_ts = 78.711769
last_seq = 611
current_ts = 78.728897
current_received_ts = 78.728386
current_seq = 612
count = 433
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 78.712212/611, current 78.728897/612: elapsed=16684.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 78.728897
last_received_ts = 78.728386
last_seq = 612
current_ts = 78.745583
current_received_ts = 78.745079
current_seq = 613
count = 434
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 78.728897/612, current 78.745583/613: elapsed=16684.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 78.745583
last_received_ts = 78.745079
last_seq = 613
current_ts = 78.762260
current_received_ts = 78.761787
current_seq = 614
count = 435
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 78.745583/613, current 78.762260/614: elapsed=16680.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 78.762260
last_received_ts = 78.761787
last_seq = 614
current_ts = 78.778946
current_received_ts = 78.778481
current_seq = 615
count = 436
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 78.762260/614, current 78.778946/615: elapsed=16687.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 78.778946
last_received_ts = 78.778481
last_seq = 615
current_ts = 78.795624
current_received_ts = 78.795082
current_seq = 616
count = 437
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 78.778946/615, current 78.795624/616: elapsed=16680.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 78.795624
last_received_ts = 78.795082
last_seq = 616
current_ts = 78.812317
current_received_ts = 78.811836
current_seq = 617
count = 438
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 78.795624/616, current 78.812317/617: elapsed=16693.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 78.812317
last_received_ts = 78.811836
last_seq = 617
current_ts = 78.829010
current_received_ts = 78.828560
current_seq = 618
count = 439
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 78.812317/617, current 78.829010/618: elapsed=16688.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 78.829010
last_received_ts = 78.828560
last_seq = 618
current_ts = 78.845680
current_received_ts = 78.845177
current_seq = 619
count = 440
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 78.829010/618, current 78.845680/619: elapsed=16677.0us expected=16752.5us +- 83.8us, error 0.5%
(kms_flip:1728) DEBUG: name = flip
last_ts = 78.845680
last_received_ts = 78.845177
last_seq = 619
current_ts = 78.862366
current_received_ts = 78.861877
current_seq = 620
count = 441
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 78.845680/619, current 78.862366/620: elapsed=16685.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 78.862366
last_received_ts = 78.861877
last_seq = 620
current_ts = 78.879036
current_received_ts = 78.878540
current_seq = 621
count = 442
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 78.862366/620, current 78.879036/621: elapsed=16670.0us expected=16752.5us +- 83.8us, error 0.5%
(kms_flip:1728) DEBUG: name = flip
last_ts = 78.879036
last_received_ts = 78.878540
last_seq = 621
current_ts = 78.895729
current_received_ts = 78.895218
current_seq = 622
count = 443
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 78.879036/621, current 78.895729/622: elapsed=16690.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 78.895729
last_received_ts = 78.895218
last_seq = 622
current_ts = 78.912415
current_received_ts = 78.911880
current_seq = 623
count = 444
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 78.895729/622, current 78.912415/623: elapsed=16683.0us expected=16752.5us +- 83.8us, error 0.4%
(kms_flip:1728) DEBUG: name = flip
last_ts = 78.912415
last_received_ts = 78.911880
last_seq = 623
current_ts = 78.929077
current_received_ts = 78.928581
current_seq = 624
count = 445
seq_step = 1
(kms_flip:1728) DEBUG: flip ts/seq: last 78.912415/623, current 78.929077/624: elapsed=16668.0us expected=16752.5us +- 83.8us, error 0.5%
(kms_flip:1728) DEBUG: inconsistent flip ts/seq: last 78.912415/623, current 78.929077/624: elapsed=16668.0us expected=16752.5us
(kms_flip:1728) DEBUG: expected 66925, counted 445, encoder type 2
(kms_flip:1728) DEBUG: dropped frames, expected 66925, counted 445, encoder type 2
(kms_flip:1728) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:1728) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:1728) CRITICAL: Last errno: 4, Interrupted system call
(kms_flip:1728) igt_core-INFO: Stack trace:
(kms_flip:1728) igt_core-INFO:   #0 ../lib/igt_core.c:2051 __igt_fail_assert()
(kms_flip:1728) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:1728) igt_core-INFO:   #2 ../tests/kms_flip.c:1845 run_test()
(kms_flip:1728) igt_core-INFO:   #3 ../tests/kms_flip.c:2114 __igt_unique____real_main2001()
(kms_flip:1728) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:1728) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:1728) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:1728) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-HDMI-A1: FAIL (10.976s)
Subtest plain-flip-ts-check-interruptible: FAIL (25.365s)
(kms_flip:1728) igt_kms-CRITICAL: Test assertion failure function kmstest_set_connector_dpms, file ../lib/igt_kms.c:2246:
(kms_flip:1728) igt_kms-CRITICAL: Failed assertion: found_it
(kms_flip:1728) igt_kms-CRITICAL: Last errno: 9, Bad file descriptor
(kms_flip:1728) igt_kms-CRITICAL: DPMS property not found on 67