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

shard-tglu-10

IGT-Version: 1.30-ga12df61e7 (x86_64) (Linux: 6.14.0-rc4-CI_DRM_16207-gf79125df2181+ x86_64)

Using IGT_SRANDOM=1740828412 for randomisation
Opened device: /dev/dri/card0
Using monotonic timestamps
Starting subtest: plain-flip-ts-check
Starting dynamic subtest: A-HDMI-A1
  1920x1080: 120 285500 1920 1968 2000 2080 1080 1083 1088 1144 0x48 0x5 
Expected frametime: 8335us; measured 8030.3us +- 3.459us accuracy 0.13%
vblank interval differs from modeline! expected 8334.6us, measured 8030us +- 3.459us, difference 304.3us (88.0 sigma)
Stack trace:
  #0 ../lib/igt_core.c:2055 __igt_fail_assert()
  #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1845 run_test()
  #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
  #4 ../tests/kms_flip.c:2001 main()
  #5 ../sysdeps/nptl/libc_start_call_main.h:74 __libc_start_call_main()
  #6 ../csu/libc-start.c:128 __libc_start_main@@GLIBC_2.34()
  #7 [_start+0x25]
Dynamic subtest A-HDMI-A1: FAIL (4.236s)
Starting dynamic subtest: B-HDMI-A1
  1920x1080: 120 285500 1920 1968 2000 2080 1080 1083 1088 1144 0x48 0x5 
Expected frametime: 8335us; measured 8156.3us +- 3.235us accuracy 0.12%
vblank interval differs from modeline! expected 8334.6us, measured 8156us +- 3.235us, difference 178.3us (55.1 sigma)
Stack trace:
  #0 ../lib/igt_core.c:2055 __igt_fail_assert()
  #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1845 run_test()
  #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
  #4 ../tests/kms_flip.c:2001 main()
  #5 ../sysdeps/nptl/libc_start_call_main.h:74 __libc_start_call_main()
  #6 ../csu/libc-start.c:128 __libc_start_main@@GLIBC_2.34()
  #7 [_start+0x25]
Dynamic subtest B-HDMI-A1: FAIL (5.087s)
Starting dynamic subtest: C-HDMI-A1
  1920x1080: 120 285500 1920 1968 2000 2080 1080 1083 1088 1144 0x48 0x5 
Expected frametime: 8335us; measured 8243.0us +- 3.916us accuracy 0.14%
vblank interval differs from modeline! expected 8334.6us, measured 8243us +- 3.916us, difference 91.6us (23.4 sigma)
Stack trace:
  #0 ../lib/igt_core.c:2055 __igt_fail_assert()
  #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1845 run_test()
  #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
  #4 ../tests/kms_flip.c:2001 main()
  #5 ../sysdeps/nptl/libc_start_call_main.h:74 __libc_start_call_main()
  #6 ../csu/libc-start.c:128 __libc_start_main@@GLIBC_2.34()
  #7 [_start+0x25]
Dynamic subtest C-HDMI-A1: FAIL (7.091s)
Starting dynamic subtest: D-HDMI-A1
  1920x1080: 120 285500 1920 1968 2000 2080 1080 1083 1088 1144 0x48 0x5 
Expected frametime: 8335us; measured 8298.8us +- 2.206us accuracy 0.08%
vblank interval differs from modeline! expected 8334.6us, measured 8299us +- 2.206us, difference 35.8us (16.2 sigma)
Stack trace:
  #0 ../lib/igt_core.c:2055 __igt_fail_assert()
  #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1845 run_test()
  #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
  #4 ../tests/kms_flip.c:2001 main()
  #5 ../sysdeps/nptl/libc_start_call_main.h:74 __libc_start_call_main()
  #6 ../csu/libc-start.c:128 __libc_start_main@@GLIBC_2.34()
  #7 [_start+0x25]
Dynamic subtest D-HDMI-A1: FAIL (10.969s)
Subtest plain-flip-ts-check: FAIL (27.388s)
Stack trace:
  #0 ../lib/igt_core.c:2055 __igt_fail_assert()
  #1 ../lib/igt_kms.c:2246 kmstest_set_connector_dpms()
  #2 ../lib/igt_core.c:2934 igt_atexit_handler()
  #3 ./stdlib/exit.c:109 __run_exit_handlers()
  #4 [exit+0x1e]
  #5 ../lib/igt_core.c:2390 igt_exit()
  #6 [main+0x3f]
  #7 ../sysdeps/nptl/libc_start_call_main.h:74 __libc_start_call_main()
  #8 ../csu/libc-start.c:128 __libc_start_main@@GLIBC_2.34()
  #9 [_start+0x25]

Starting subtest: plain-flip-ts-check
Starting dynamic subtest: A-HDMI-A1
(kms_flip:2017) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:2017) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest A-HDMI-A1 failed.
**** DEBUG ****
(kms_flip:2017) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:2017) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=1, pitch=7680)
(kms_flip:2017) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:2017) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:2017) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=2, pitch=7680)
(kms_flip:2017) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:2017) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2017) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2017) igt_fb-DEBUG: Test requirement passed: cairo_surface_status(fb->cairo_surface) == CAIRO_STATUS_SUCCESS
(kms_flip:2017) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2017) intel_blt-DEBUG: Test requirement passed: cmds_info
(kms_flip:2017) igt_fb-DEBUG: Test requirement passed: cairo_surface_status(fb->cairo_surface) == CAIRO_STATUS_SUCCESS
(kms_flip:2017) igt_kms-INFO:   1920x1080: 120 285500 1920 1968 2000 2080 1080 1083 1088 1144 0x48 0x5 
(kms_flip:2017) DEBUG: No stale events found
(kms_flip:2017) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:2017) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:2017) INFO: Expected frametime: 8335us; measured 8030.3us +- 3.459us accuracy 0.13%
(kms_flip:2017) INFO: vblank interval differs from modeline! expected 8334.6us, measured 8030us +- 3.459us, difference 304.3us (88.0 sigma)
(kms_flip:2017) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 46.371567
current_received_ts = 46.371223
current_seq = 1020
count = 0
seq_step = 1
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.371567
last_received_ts = 46.371223
last_seq = 1020
current_ts = 46.379597
current_received_ts = 46.379311
current_seq = 1021
count = 1
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.371567/1020, current 46.379597/1021: elapsed=8030.0us expected=8030.3us +- 40.2us, error 0.0%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.379597
last_received_ts = 46.379311
last_seq = 1021
current_ts = 46.387630
current_received_ts = 46.387344
current_seq = 1022
count = 2
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.379597/1021, current 46.387630/1022: elapsed=8034.0us expected=8030.3us +- 40.2us, error 0.0%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.387630
last_received_ts = 46.387344
last_seq = 1022
current_ts = 46.395664
current_received_ts = 46.395351
current_seq = 1023
count = 3
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.387630/1022, current 46.395664/1023: elapsed=8033.0us expected=8030.3us +- 40.2us, error 0.0%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.395664
last_received_ts = 46.395351
last_seq = 1023
current_ts = 46.403690
current_received_ts = 46.403339
current_seq = 1024
count = 4
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.395664/1023, current 46.403690/1024: elapsed=8026.0us expected=8030.3us +- 40.2us, error 0.1%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.403690
last_received_ts = 46.403339
last_seq = 1024
current_ts = 46.411720
current_received_ts = 46.411404
current_seq = 1025
count = 5
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.403690/1024, current 46.411720/1025: elapsed=8032.0us expected=8030.3us +- 40.2us, error 0.0%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.411720
last_received_ts = 46.411404
last_seq = 1025
current_ts = 46.419754
current_received_ts = 46.419464
current_seq = 1026
count = 6
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.411720/1025, current 46.419754/1026: elapsed=8032.0us expected=8030.3us +- 40.2us, error 0.0%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.419754
last_received_ts = 46.419464
last_seq = 1026
current_ts = 46.427776
current_received_ts = 46.427498
current_seq = 1027
count = 7
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.419754/1026, current 46.427776/1027: elapsed=8025.0us expected=8030.3us +- 40.2us, error 0.1%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.427776
last_received_ts = 46.427498
last_seq = 1027
current_ts = 46.435810
current_received_ts = 46.435452
current_seq = 1028
count = 8
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.427776/1027, current 46.435810/1028: elapsed=8033.0us expected=8030.3us +- 40.2us, error 0.0%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.435810
last_received_ts = 46.435452
last_seq = 1028
current_ts = 46.443840
current_received_ts = 46.443546
current_seq = 1029
count = 9
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.435810/1028, current 46.443840/1029: elapsed=8028.0us expected=8030.3us +- 40.2us, error 0.0%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.443840
last_received_ts = 46.443546
last_seq = 1029
current_ts = 46.451870
current_received_ts = 46.451595
current_seq = 1030
count = 10
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.443840/1029, current 46.451870/1030: elapsed=8032.0us expected=8030.3us +- 40.2us, error 0.0%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.451870
last_received_ts = 46.451595
last_seq = 1030
current_ts = 46.459900
current_received_ts = 46.459625
current_seq = 1031
count = 11
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.451870/1030, current 46.459900/1031: elapsed=8030.0us expected=8030.3us +- 40.2us, error 0.0%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.459900
last_received_ts = 46.459625
last_seq = 1031
current_ts = 46.467926
current_received_ts = 46.467697
current_seq = 1032
count = 12
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.459900/1031, current 46.467926/1032: elapsed=8026.0us expected=8030.3us +- 40.2us, error 0.1%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.467926
last_received_ts = 46.467697
last_seq = 1032
current_ts = 46.475964
current_received_ts = 46.475605
current_seq = 1033
count = 13
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.467926/1032, current 46.475964/1033: elapsed=8036.0us expected=8030.3us +- 40.2us, error 0.1%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.475964
last_received_ts = 46.475605
last_seq = 1033
current_ts = 46.483994
current_received_ts = 46.483669
current_seq = 1034
count = 14
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.475964/1033, current 46.483994/1034: elapsed=8030.0us expected=8030.3us +- 40.2us, error 0.0%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.483994
last_received_ts = 46.483669
last_seq = 1034
current_ts = 46.492020
current_received_ts = 46.491772
current_seq = 1035
count = 15
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.483994/1034, current 46.492020/1035: elapsed=8025.0us expected=8030.3us +- 40.2us, error 0.1%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.492020
last_received_ts = 46.491772
last_seq = 1035
current_ts = 46.500053
current_received_ts = 46.499683
current_seq = 1036
count = 16
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.492020/1035, current 46.500053/1036: elapsed=8034.0us expected=8030.3us +- 40.2us, error 0.0%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.500053
last_received_ts = 46.499683
last_seq = 1036
current_ts = 46.508083
current_received_ts = 46.507820
current_seq = 1037
count = 17
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.500053/1036, current 46.508083/1037: elapsed=8031.0us expected=8030.3us +- 40.2us, error 0.0%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.508083
last_received_ts = 46.507820
last_seq = 1037
current_ts = 46.516109
current_received_ts = 46.515873
current_seq = 1038
count = 18
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.508083/1037, current 46.516109/1038: elapsed=8025.0us expected=8030.3us +- 40.2us, error 0.1%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.516109
last_received_ts = 46.515873
last_seq = 1038
current_ts = 46.524139
current_received_ts = 46.523861
current_seq = 1039
count = 19
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.516109/1038, current 46.524139/1039: elapsed=8033.0us expected=8030.3us +- 40.2us, error 0.0%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.524139
last_received_ts = 46.523861
last_seq = 1039
current_ts = 46.532173
current_received_ts = 46.531929
current_seq = 1040
count = 20
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.524139/1039, current 46.532173/1040: elapsed=8034.0us expected=8030.3us +- 40.2us, error 0.0%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.532173
last_received_ts = 46.531929
last_seq = 1040
current_ts = 46.540207
current_received_ts = 46.539955
current_seq = 1041
count = 21
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.532173/1040, current 46.540207/1041: elapsed=8030.0us expected=8030.3us +- 40.2us, error 0.0%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.540207
last_received_ts = 46.539955
last_seq = 1041
current_ts = 46.548233
current_received_ts = 46.547886
current_seq = 1042
count = 22
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.540207/1041, current 46.548233/1042: elapsed=8028.0us expected=8030.3us +- 40.2us, error 0.0%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.548233
last_received_ts = 46.547886
last_seq = 1042
current_ts = 46.556267
current_received_ts = 46.555954
current_seq = 1043
count = 23
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.548233/1042, current 46.556267/1043: elapsed=8032.0us expected=8030.3us +- 40.2us, error 0.0%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.556267
last_received_ts = 46.555954
last_seq = 1043
current_ts = 46.564289
current_received_ts = 46.564114
current_seq = 1044
count = 24
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.556267/1043, current 46.564289/1044: elapsed=8025.0us expected=8030.3us +- 40.2us, error 0.1%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.564289
last_received_ts = 46.564114
last_seq = 1044
current_ts = 46.572327
current_received_ts = 46.571987
current_seq = 1045
count = 25
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.564289/1044, current 46.572327/1045: elapsed=8035.0us expected=8030.3us +- 40.2us, error 0.1%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.572327
last_received_ts = 46.571987
last_seq = 1045
current_ts = 46.580353
current_received_ts = 46.580097
current_seq = 1046
count = 26
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.572327/1045, current 46.580353/1046: elapsed=8028.0us expected=8030.3us +- 40.2us, error 0.0%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.580353
last_received_ts = 46.580097
last_seq = 1046
current_ts = 46.588383
current_received_ts = 46.588081
current_seq = 1047
count = 27
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.580353/1046, current 46.588383/1047: elapsed=8031.0us expected=8030.3us +- 40.2us, error 0.0%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.588383
last_received_ts = 46.588081
last_seq = 1047
current_ts = 46.596413
current_received_ts = 46.596142
current_seq = 1048
count = 28
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.588383/1047, current 46.596413/1048: elapsed=8030.0us expected=8030.3us +- 40.2us, error 0.0%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.596413
last_received_ts = 46.596142
last_seq = 1048
current_ts = 46.604450
current_received_ts = 46.604145
current_seq = 1049
count = 29
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.596413/1048, current 46.604450/1049: elapsed=8035.0us expected=8030.3us +- 40.2us, error 0.1%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.604450
last_received_ts = 46.604145
last_seq = 1049
current_ts = 46.612480
current_received_ts = 46.612137
current_seq = 1050
count = 30
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.604450/1049, current 46.612480/1050: elapsed=8030.0us expected=8030.3us +- 40.2us, error 0.0%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.612480
last_received_ts = 46.612137
last_seq = 1050
current_ts = 46.620506
current_received_ts = 46.620155
current_seq = 1051
count = 31
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.612480/1050, current 46.620506/1051: elapsed=8028.0us expected=8030.3us +- 40.2us, error 0.0%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.620506
last_received_ts = 46.620155
last_seq = 1051
current_ts = 46.628540
current_received_ts = 46.628216
current_seq = 1052
count = 32
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.620506/1051, current 46.628540/1052: elapsed=8034.0us expected=8030.3us +- 40.2us, error 0.0%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.628540
last_received_ts = 46.628216
last_seq = 1052
current_ts = 46.636566
current_received_ts = 46.636211
current_seq = 1053
count = 33
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.628540/1052, current 46.636566/1053: elapsed=8026.0us expected=8030.3us +- 40.2us, error 0.1%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.636566
last_received_ts = 46.636211
last_seq = 1053
current_ts = 46.644600
current_received_ts = 46.644249
current_seq = 1054
count = 34
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.636566/1053, current 46.644600/1054: elapsed=8031.0us expected=8030.3us +- 40.2us, error 0.0%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.644600
last_received_ts = 46.644249
last_seq = 1054
current_ts = 46.652626
current_received_ts = 46.652313
current_seq = 1055
count = 35
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.644600/1054, current 46.652626/1055: elapsed=8028.0us expected=8030.3us +- 40.2us, error 0.0%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.652626
last_received_ts = 46.652313
last_seq = 1055
current_ts = 46.660656
current_received_ts = 46.660351
current_seq = 1056
count = 36
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.652626/1055, current 46.660656/1056: elapsed=8031.0us expected=8030.3us +- 40.2us, error 0.0%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.660656
last_received_ts = 46.660351
last_seq = 1056
current_ts = 46.668690
current_received_ts = 46.668381
current_seq = 1057
count = 37
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.660656/1056, current 46.668690/1057: elapsed=8034.0us expected=8030.3us +- 40.2us, error 0.0%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.668690
last_received_ts = 46.668381
last_seq = 1057
current_ts = 46.676720
current_received_ts = 46.676357
current_seq = 1058
count = 38
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.668690/1057, current 46.676720/1058: elapsed=8027.0us expected=8030.3us +- 40.2us, error 0.0%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.676720
last_received_ts = 46.676357
last_seq = 1058
current_ts = 46.684750
current_received_ts = 46.684475
current_seq = 1059
count = 39
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.676720/1058, current 46.684750/1059: elapsed=8031.0us expected=8030.3us +- 40.2us, error 0.0%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.684750
last_received_ts = 46.684475
last_seq = 1059
current_ts = 46.692780
current_received_ts = 46.692543
current_seq = 1060
count = 40
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.684750/1059, current 46.692780/1060: elapsed=8031.0us expected=8030.3us +- 40.2us, error 0.0%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.692780
last_received_ts = 46.692543
last_seq = 1060
current_ts = 46.700809
current_received_ts = 46.700542
current_seq = 1061
count = 41
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.692780/1060, current 46.700809/1061: elapsed=8028.0us expected=8030.3us +- 40.2us, error 0.0%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.700809
last_received_ts = 46.700542
last_seq = 1061
current_ts = 46.708839
current_received_ts = 46.708569
current_seq = 1062
count = 42
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.700809/1061, current 46.708839/1062: elapsed=8032.0us expected=8030.3us +- 40.2us, error 0.0%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.708839
last_received_ts = 46.708569
last_seq = 1062
current_ts = 46.716869
current_received_ts = 46.716553
current_seq = 1063
count = 43
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.708839/1062, current 46.716869/1063: elapsed=8029.0us expected=8030.3us +- 40.2us, error 0.0%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.716869
last_received_ts = 46.716553
last_seq = 1063
current_ts = 46.724903
current_received_ts = 46.724632
current_seq = 1064
count = 44
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.716869/1063, current 46.724903/1064: elapsed=8034.0us expected=8030.3us +- 40.2us, error 0.0%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.724903
last_received_ts = 46.724632
last_seq = 1064
current_ts = 46.732929
current_received_ts = 46.732643
current_seq = 1065
count = 45
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.724903/1064, current 46.732929/1065: elapsed=8026.0us expected=8030.3us +- 40.2us, error 0.1%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.732929
last_received_ts = 46.732643
last_seq = 1065
current_ts = 46.740963
current_received_ts = 46.740685
current_seq = 1066
count = 46
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.732929/1065, current 46.740963/1066: elapsed=8033.0us expected=8030.3us +- 40.2us, error 0.0%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.740963
last_received_ts = 46.740685
last_seq = 1066
current_ts = 46.748989
current_received_ts = 46.748672
current_seq = 1067
count = 47
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.740963/1066, current 46.748989/1067: elapsed=8028.0us expected=8030.3us +- 40.2us, error 0.0%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.748989
last_received_ts = 46.748672
last_seq = 1067
current_ts = 46.757023
current_received_ts = 46.756752
current_seq = 1068
count = 48
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.748989/1067, current 46.757023/1068: elapsed=8033.0us expected=8030.3us +- 40.2us, error 0.0%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.757023
last_received_ts = 46.756752
last_seq = 1068
current_ts = 46.765049
current_received_ts = 46.764812
current_seq = 1069
count = 49
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.757023/1068, current 46.765049/1069: elapsed=8025.0us expected=8030.3us +- 40.2us, error 0.1%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.765049
last_received_ts = 46.764812
last_seq = 1069
current_ts = 46.773079
current_received_ts = 46.772873
current_seq = 1070
count = 50
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.765049/1069, current 46.773079/1070: elapsed=8032.0us expected=8030.3us +- 40.2us, error 0.0%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.773079
last_received_ts = 46.772873
last_seq = 1070
current_ts = 46.781105
current_received_ts = 46.780914
current_seq = 1071
count = 51
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.773079/1070, current 46.781105/1071: elapsed=8026.0us expected=8030.3us +- 40.2us, error 0.1%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.781105
last_received_ts = 46.780914
last_seq = 1071
current_ts = 46.789139
current_received_ts = 46.788982
current_seq = 1072
count = 52
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.781105/1071, current 46.789139/1072: elapsed=8033.0us expected=8030.3us +- 40.2us, error 0.0%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.789139
last_received_ts = 46.788982
last_seq = 1072
current_ts = 46.797173
current_received_ts = 46.797035
current_seq = 1073
count = 53
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.789139/1072, current 46.797173/1073: elapsed=8032.0us expected=8030.3us +- 40.2us, error 0.0%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.797173
last_received_ts = 46.797035
last_seq = 1073
current_ts = 46.805199
current_received_ts = 46.804916
current_seq = 1074
count = 54
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.797173/1073, current 46.805199/1074: elapsed=8029.0us expected=8030.3us +- 40.2us, error 0.0%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.805199
last_received_ts = 46.804916
last_seq = 1074
current_ts = 46.813236
current_received_ts = 46.812965
current_seq = 1075
count = 55
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.805199/1074, current 46.813236/1075: elapsed=8036.0us expected=8030.3us +- 40.2us, error 0.1%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.813236
last_received_ts = 46.812965
last_seq = 1075
current_ts = 46.821266
current_received_ts = 46.820957
current_seq = 1076
count = 56
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.813236/1075, current 46.821266/1076: elapsed=8031.0us expected=8030.3us +- 40.2us, error 0.0%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.821266
last_received_ts = 46.820957
last_seq = 1076
current_ts = 46.829292
current_received_ts = 46.829037
current_seq = 1077
count = 57
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.821266/1076, current 46.829292/1077: elapsed=8025.0us expected=8030.3us +- 40.2us, error 0.1%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.829292
last_received_ts = 46.829037
last_seq = 1077
current_ts = 46.837322
current_received_ts = 46.836983
current_seq = 1078
count = 58
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.829292/1077, current 46.837322/1078: elapsed=8032.0us expected=8030.3us +- 40.2us, error 0.0%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.837322
last_received_ts = 46.836983
last_seq = 1078
current_ts = 46.845352
current_received_ts = 46.845093
current_seq = 1079
count = 59
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.837322/1078, current 46.845352/1079: elapsed=8030.0us expected=8030.3us +- 40.2us, error 0.0%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.845352
last_received_ts = 46.845093
last_seq = 1079
current_ts = 46.853390
current_received_ts = 46.854290
current_seq = 1080
count = 60
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.845352/1079, current 46.853390/1080: elapsed=8035.0us expected=8030.3us +- 40.2us, error 0.1%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.853390
last_received_ts = 46.854290
last_seq = 1080
current_ts = 46.861412
current_received_ts = 46.861145
current_seq = 1081
count = 61
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.853390/1080, current 46.861412/1081: elapsed=8024.0us expected=8030.3us +- 40.2us, error 0.1%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.861412
last_received_ts = 46.861145
last_seq = 1081
current_ts = 46.869446
current_received_ts = 46.869183
current_seq = 1082
count = 62
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.861412/1081, current 46.869446/1082: elapsed=8032.0us expected=8030.3us +- 40.2us, error 0.0%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.869446
last_received_ts = 46.869183
last_seq = 1082
current_ts = 46.877476
current_received_ts = 46.877129
current_seq = 1083
count = 63
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.869446/1082, current 46.877476/1083: elapsed=8030.0us expected=8030.3us +- 40.2us, error 0.0%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.877476
last_received_ts = 46.877129
last_seq = 1083
current_ts = 46.885509
current_received_ts = 46.885174
current_seq = 1084
count = 64
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.877476/1083, current 46.885509/1084: elapsed=8035.0us expected=8030.3us +- 40.2us, error 0.1%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.885509
last_received_ts = 46.885174
last_seq = 1084
current_ts = 46.893536
current_received_ts = 46.893185
current_seq = 1085
count = 65
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.885509/1084, current 46.893536/1085: elapsed=8025.0us expected=8030.3us +- 40.2us, error 0.1%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.893536
last_received_ts = 46.893185
last_seq = 1085
current_ts = 46.901569
current_received_ts = 46.901264
current_seq = 1086
count = 66
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.893536/1085, current 46.901569/1086: elapsed=8035.0us expected=8030.3us +- 40.2us, error 0.1%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.901569
last_received_ts = 46.901264
last_seq = 1086
current_ts = 46.909595
current_received_ts = 46.909294
current_seq = 1087
count = 67
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.901569/1086, current 46.909595/1087: elapsed=8024.0us expected=8030.3us +- 40.2us, error 0.1%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.909595
last_received_ts = 46.909294
last_seq = 1087
current_ts = 46.917625
current_received_ts = 46.917336
current_seq = 1088
count = 68
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.909595/1087, current 46.917625/1088: elapsed=8032.0us expected=8030.3us +- 40.2us, error 0.0%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.917625
last_received_ts = 46.917336
last_seq = 1088
current_ts = 46.925655
current_received_ts = 46.925358
current_seq = 1089
count = 69
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.917625/1088, current 46.925655/1089: elapsed=8031.0us expected=8030.3us +- 40.2us, error 0.0%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.925655
last_received_ts = 46.925358
last_seq = 1089
current_ts = 46.933689
current_received_ts = 46.933403
current_seq = 1090
count = 70
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.925655/1089, current 46.933689/1090: elapsed=8031.0us expected=8030.3us +- 40.2us, error 0.0%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.933689
last_received_ts = 46.933403
last_seq = 1090
current_ts = 46.941719
current_received_ts = 46.941422
current_seq = 1091
count = 71
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.933689/1090, current 46.941719/1091: elapsed=8032.0us expected=8030.3us +- 40.2us, error 0.0%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.941719
last_received_ts = 46.941422
last_seq = 1091
current_ts = 46.949749
current_received_ts = 46.949436
current_seq = 1092
count = 72
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.941719/1091, current 46.949749/1092: elapsed=8029.0us expected=8030.3us +- 40.2us, error 0.0%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.949749
last_received_ts = 46.949436
last_seq = 1092
current_ts = 46.957775
current_received_ts = 46.957504
current_seq = 1093
count = 73
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.949749/1092, current 46.957775/1093: elapsed=8026.0us expected=8030.3us +- 40.2us, error 0.1%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.957775
last_received_ts = 46.957504
last_seq = 1093
current_ts = 46.965809
current_received_ts = 46.965492
current_seq = 1094
count = 74
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.957775/1093, current 46.965809/1094: elapsed=8033.0us expected=8030.3us +- 40.2us, error 0.0%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.965809
last_received_ts = 46.965492
last_seq = 1094
current_ts = 46.973839
current_received_ts = 46.973553
current_seq = 1095
count = 75
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.965809/1094, current 46.973839/1095: elapsed=8030.0us expected=8030.3us +- 40.2us, error 0.0%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.973839
last_received_ts = 46.973553
last_seq = 1095
current_ts = 46.981873
current_received_ts = 46.981522
current_seq = 1096
count = 76
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.973839/1095, current 46.981873/1096: elapsed=8036.0us expected=8030.3us +- 40.2us, error 0.1%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.981873
last_received_ts = 46.981522
last_seq = 1096
current_ts = 46.989902
current_received_ts = 46.989582
current_seq = 1097
count = 77
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.981873/1096, current 46.989902/1097: elapsed=8027.0us expected=8030.3us +- 40.2us, error 0.0%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.989902
last_received_ts = 46.989582
last_seq = 1097
current_ts = 46.997967
current_received_ts = 46.997665
current_seq = 1098
count = 78
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.989902/1097, current 46.997967/1098: elapsed=8064.0us expected=8030.3us +- 40.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 46.997967
last_received_ts = 46.997665
last_seq = 1098
current_ts = 47.006035
current_received_ts = 47.005684
current_seq = 1099
count = 79
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 46.997967/1098, current 47.006035/1099: elapsed=8070.0us expected=8030.3us +- 40.2us, error 0.5%
(kms_flip:2017) DEBUG: name = flip
last_ts = 47.006035
last_received_ts = 47.005684
last_seq = 1099
current_ts = 47.014103
current_received_ts = 47.013817
current_seq = 1100
count = 80
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 47.006035/1099, current 47.014103/1100: elapsed=8069.0us expected=8030.3us +- 40.2us, error 0.5%
(kms_flip:2017) DEBUG: name = flip
last_ts = 47.014103
last_received_ts = 47.013817
last_seq = 1100
current_ts = 47.022171
current_received_ts = 47.021912
current_seq = 1101
count = 81
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 47.014103/1100, current 47.022171/1101: elapsed=8066.0us expected=8030.3us +- 40.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 47.022171
last_received_ts = 47.021912
last_seq = 1101
current_ts = 47.030239
current_received_ts = 47.029922
current_seq = 1102
count = 82
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 47.022171/1101, current 47.030239/1102: elapsed=8070.0us expected=8030.3us +- 40.2us, error 0.5%
(kms_flip:2017) DEBUG: name = flip
last_ts = 47.030239
last_received_ts = 47.029922
last_seq = 1102
current_ts = 47.038303
current_received_ts = 47.038086
current_seq = 1103
count = 83
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 47.030239/1102, current 47.038303/1103: elapsed=8065.0us expected=8030.3us +- 40.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 47.038303
last_received_ts = 47.038086
last_seq = 1103
current_ts = 47.046371
current_received_ts = 47.046173
current_seq = 1104
count = 84
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 47.038303/1103, current 47.046371/1104: elapsed=8068.0us expected=8030.3us +- 40.2us, error 0.5%
(kms_flip:2017) DEBUG: name = flip
last_ts = 47.046371
last_received_ts = 47.046173
last_seq = 1104
current_ts = 47.054447
current_received_ts = 47.054085
current_seq = 1105
count = 85
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 47.046371/1104, current 47.054447/1105: elapsed=8075.0us expected=8030.3us +- 40.2us, error 0.6%
(kms_flip:2017) DEBUG: inconsistent flip ts/seq: last 47.046371/1104, current 47.054447/1105: elapsed=8075.0us expected=8030.3us
(kms_flip:2017) DEBUG: expected 32366, counted 85, encoder type 2
(kms_flip:2017) DEBUG: dropped frames, expected 32366, counted 85, encoder type 2
(kms_flip:2017) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:2017) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:2017) igt_core-INFO: Stack trace:
(kms_flip:2017) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:2017) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:2017) igt_core-INFO:   #2 ../tests/kms_flip.c:1845 run_test()
(kms_flip:2017) igt_core-INFO:   #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
(kms_flip:2017) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:2017) igt_core-INFO:   #5 ../sysdeps/nptl/libc_start_call_main.h:74 __libc_start_call_main()
(kms_flip:2017) igt_core-INFO:   #6 ../csu/libc-start.c:128 __libc_start_main@@GLIBC_2.34()
(kms_flip:2017) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest A-HDMI-A1: FAIL (4.236s)
Starting dynamic subtest: B-HDMI-A1
(kms_flip:2017) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:2017) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest B-HDMI-A1 failed.
**** DEBUG ****
(kms_flip:2017) DEBUG: flip ts/seq: last 51.017612/92, current 51.025791/93: elapsed=8179.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.025791
last_received_ts = 51.025524
last_seq = 93
current_ts = 51.033970
current_received_ts = 51.033737
current_seq = 94
count = 72
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.025791/93, current 51.033970/94: elapsed=8180.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.033970
last_received_ts = 51.033737
last_seq = 94
current_ts = 51.042145
current_received_ts = 51.041908
current_seq = 95
count = 73
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.033970/94, current 51.042145/95: elapsed=8175.0us expected=8156.3us +- 40.8us, error 0.2%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.042145
last_received_ts = 51.041908
last_seq = 95
current_ts = 51.050327
current_received_ts = 51.050102
current_seq = 96
count = 74
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.042145/95, current 51.050327/96: elapsed=8184.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.050327
last_received_ts = 51.050102
last_seq = 96
current_ts = 51.058502
current_received_ts = 51.058228
current_seq = 97
count = 75
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.050327/96, current 51.058502/97: elapsed=8175.0us expected=8156.3us +- 40.8us, error 0.2%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.058502
last_received_ts = 51.058228
last_seq = 97
current_ts = 51.066685
current_received_ts = 51.066418
current_seq = 98
count = 76
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.058502/97, current 51.066685/98: elapsed=8182.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.066685
last_received_ts = 51.066418
last_seq = 98
current_ts = 51.074863
current_received_ts = 51.074600
current_seq = 99
count = 77
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.066685/98, current 51.074863/99: elapsed=8179.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.074863
last_received_ts = 51.074600
last_seq = 99
current_ts = 51.083038
current_received_ts = 51.082867
current_seq = 100
count = 78
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.074863/99, current 51.083038/100: elapsed=8172.0us expected=8156.3us +- 40.8us, error 0.2%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.083038
last_received_ts = 51.082867
last_seq = 100
current_ts = 51.091217
current_received_ts = 51.090889
current_seq = 101
count = 79
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.083038/100, current 51.091217/101: elapsed=8181.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.091217
last_received_ts = 51.090889
last_seq = 101
current_ts = 51.099400
current_received_ts = 51.099174
current_seq = 102
count = 80
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.091217/101, current 51.099400/102: elapsed=8181.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.099400
last_received_ts = 51.099174
last_seq = 102
current_ts = 51.107578
current_received_ts = 51.107273
current_seq = 103
count = 81
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.099400/102, current 51.107578/103: elapsed=8181.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.107578
last_received_ts = 51.107273
last_seq = 103
current_ts = 51.115753
current_received_ts = 51.115429
current_seq = 104
count = 82
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.107578/103, current 51.115753/104: elapsed=8174.0us expected=8156.3us +- 40.8us, error 0.2%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.115753
last_received_ts = 51.115429
last_seq = 104
current_ts = 51.123936
current_received_ts = 51.123665
current_seq = 105
count = 83
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.115753/104, current 51.123936/105: elapsed=8181.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.123936
last_received_ts = 51.123665
last_seq = 105
current_ts = 51.132114
current_received_ts = 51.131866
current_seq = 106
count = 84
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.123936/105, current 51.132114/106: elapsed=8178.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.132114
last_received_ts = 51.131866
last_seq = 106
current_ts = 51.140289
current_received_ts = 51.139950
current_seq = 107
count = 85
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.132114/106, current 51.140289/107: elapsed=8177.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.140289
last_received_ts = 51.139950
last_seq = 107
current_ts = 51.148472
current_received_ts = 51.148224
current_seq = 108
count = 86
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.140289/107, current 51.148472/108: elapsed=8180.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.148472
last_received_ts = 51.148224
last_seq = 108
current_ts = 51.156651
current_received_ts = 51.156376
current_seq = 109
count = 87
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.148472/108, current 51.156651/109: elapsed=8180.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.156651
last_received_ts = 51.156376
last_seq = 109
current_ts = 51.164829
current_received_ts = 51.164482
current_seq = 110
count = 88
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.156651/109, current 51.164829/110: elapsed=8180.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.164829
last_received_ts = 51.164482
last_seq = 110
current_ts = 51.173004
current_received_ts = 51.172665
current_seq = 111
count = 89
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.164829/110, current 51.173004/111: elapsed=8173.0us expected=8156.3us +- 40.8us, error 0.2%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.173004
last_received_ts = 51.172665
last_seq = 111
current_ts = 51.181187
current_received_ts = 51.180939
current_seq = 112
count = 90
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.173004/111, current 51.181187/112: elapsed=8182.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.181187
last_received_ts = 51.180939
last_seq = 112
current_ts = 51.189362
current_received_ts = 51.189045
current_seq = 113
count = 91
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.181187/112, current 51.189362/113: elapsed=8175.0us expected=8156.3us +- 40.8us, error 0.2%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.189362
last_received_ts = 51.189045
last_seq = 113
current_ts = 51.197536
current_received_ts = 51.197247
current_seq = 114
count = 92
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.189362/113, current 51.197536/114: elapsed=8178.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.197536
last_received_ts = 51.197247
last_seq = 114
current_ts = 51.205719
current_received_ts = 51.205452
current_seq = 115
count = 93
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.197536/114, current 51.205719/115: elapsed=8180.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.205719
last_received_ts = 51.205452
last_seq = 115
current_ts = 51.213898
current_received_ts = 51.213593
current_seq = 116
count = 94
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.205719/115, current 51.213898/116: elapsed=8180.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.213898
last_received_ts = 51.213593
last_seq = 116
current_ts = 51.222080
current_received_ts = 51.221832
current_seq = 117
count = 95
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.213898/116, current 51.222080/117: elapsed=8181.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.222080
last_received_ts = 51.221832
last_seq = 117
current_ts = 51.230251
current_received_ts = 51.230080
current_seq = 118
count = 96
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.222080/117, current 51.230251/118: elapsed=8174.0us expected=8156.3us +- 40.8us, error 0.2%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.230251
last_received_ts = 51.230080
last_seq = 118
current_ts = 51.238434
current_received_ts = 51.238110
current_seq = 119
count = 97
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.230251/118, current 51.238434/119: elapsed=8180.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.238434
last_received_ts = 51.238110
last_seq = 119
current_ts = 51.246613
current_received_ts = 51.246330
current_seq = 120
count = 98
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.238434/119, current 51.246613/120: elapsed=8179.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.246613
last_received_ts = 51.246330
last_seq = 120
current_ts = 51.254787
current_received_ts = 51.254505
current_seq = 121
count = 99
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.246613/120, current 51.254787/121: elapsed=8176.0us expected=8156.3us +- 40.8us, error 0.2%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.254787
last_received_ts = 51.254505
last_seq = 121
current_ts = 51.262974
current_received_ts = 51.262630
current_seq = 122
count = 100
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.254787/121, current 51.262974/122: elapsed=8185.0us expected=8156.3us +- 40.8us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.262974
last_received_ts = 51.262630
last_seq = 122
current_ts = 51.271149
current_received_ts = 51.270809
current_seq = 123
count = 101
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.262974/122, current 51.271149/123: elapsed=8175.0us expected=8156.3us +- 40.8us, error 0.2%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.271149
last_received_ts = 51.270809
last_seq = 123
current_ts = 51.279324
current_received_ts = 51.278992
current_seq = 124
count = 102
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.271149/123, current 51.279324/124: elapsed=8176.0us expected=8156.3us +- 40.8us, error 0.2%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.279324
last_received_ts = 51.278992
last_seq = 124
current_ts = 51.287502
current_received_ts = 51.287231
current_seq = 125
count = 103
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.279324/124, current 51.287502/125: elapsed=8178.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.287502
last_received_ts = 51.287231
last_seq = 125
current_ts = 51.295685
current_received_ts = 51.295418
current_seq = 126
count = 104
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.287502/125, current 51.295685/126: elapsed=8181.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.295685
last_received_ts = 51.295418
last_seq = 126
current_ts = 51.303860
current_received_ts = 51.303596
current_seq = 127
count = 105
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.295685/126, current 51.303860/127: elapsed=8177.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.303860
last_received_ts = 51.303596
last_seq = 127
current_ts = 51.312038
current_received_ts = 51.311844
current_seq = 128
count = 106
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.303860/127, current 51.312038/128: elapsed=8178.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.312038
last_received_ts = 51.311844
last_seq = 128
current_ts = 51.320221
current_received_ts = 51.319866
current_seq = 129
count = 107
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.312038/128, current 51.320221/129: elapsed=8183.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.320221
last_received_ts = 51.319866
last_seq = 129
current_ts = 51.328392
current_received_ts = 51.328175
current_seq = 130
count = 108
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.320221/129, current 51.328392/130: elapsed=8171.0us expected=8156.3us +- 40.8us, error 0.2%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.328392
last_received_ts = 51.328175
last_seq = 130
current_ts = 51.336575
current_received_ts = 51.336239
current_seq = 131
count = 109
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.328392/130, current 51.336575/131: elapsed=8184.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.336575
last_received_ts = 51.336239
last_seq = 131
current_ts = 51.344757
current_received_ts = 51.344414
current_seq = 132
count = 110
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.336575/131, current 51.344757/132: elapsed=8182.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.344757
last_received_ts = 51.344414
last_seq = 132
current_ts = 51.352932
current_received_ts = 51.352657
current_seq = 133
count = 111
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.344757/132, current 51.352932/133: elapsed=8173.0us expected=8156.3us +- 40.8us, error 0.2%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.352932
last_received_ts = 51.352657
last_seq = 133
current_ts = 51.361115
current_received_ts = 51.360825
current_seq = 134
count = 112
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.352932/133, current 51.361115/134: elapsed=8182.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.361115
last_received_ts = 51.360825
last_seq = 134
current_ts = 51.369293
current_received_ts = 51.368942
current_seq = 135
count = 113
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.361115/134, current 51.369293/135: elapsed=8180.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.369293
last_received_ts = 51.368942
last_seq = 135
current_ts = 51.377464
current_received_ts = 51.377213
current_seq = 136
count = 114
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.369293/135, current 51.377464/136: elapsed=8173.0us expected=8156.3us +- 40.8us, error 0.2%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.377464
last_received_ts = 51.377213
last_seq = 136
current_ts = 51.385651
current_received_ts = 51.385307
current_seq = 137
count = 115
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.377464/136, current 51.385651/137: elapsed=8184.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.385651
last_received_ts = 51.385307
last_seq = 137
current_ts = 51.393826
current_received_ts = 51.393551
current_seq = 138
count = 116
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.385651/137, current 51.393826/138: elapsed=8177.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.393826
last_received_ts = 51.393551
last_seq = 138
current_ts = 51.402008
current_received_ts = 51.401665
current_seq = 139
count = 117
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.393826/138, current 51.402008/139: elapsed=8180.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.402008
last_received_ts = 51.401665
last_seq = 139
current_ts = 51.410183
current_received_ts = 51.409935
current_seq = 140
count = 118
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.402008/139, current 51.410183/140: elapsed=8176.0us expected=8156.3us +- 40.8us, error 0.2%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.410183
last_received_ts = 51.409935
last_seq = 140
current_ts = 51.418365
current_received_ts = 51.418034
current_seq = 141
count = 119
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.410183/140, current 51.418365/141: elapsed=8181.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.418365
last_received_ts = 51.418034
last_seq = 141
current_ts = 51.426540
current_received_ts = 51.426205
current_seq = 142
count = 120
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.418365/141, current 51.426540/142: elapsed=8178.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.426540
last_received_ts = 51.426205
last_seq = 142
current_ts = 51.434715
current_received_ts = 51.434425
current_seq = 143
count = 121
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.426540/142, current 51.434715/143: elapsed=8172.0us expected=8156.3us +- 40.8us, error 0.2%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.434715
last_received_ts = 51.434425
last_seq = 143
current_ts = 51.442894
current_received_ts = 51.442558
current_seq = 144
count = 122
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.434715/143, current 51.442894/144: elapsed=8179.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.442894
last_received_ts = 51.442558
last_seq = 144
current_ts = 51.451073
current_received_ts = 51.450817
current_seq = 145
count = 123
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.442894/144, current 51.451073/145: elapsed=8178.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.451073
last_received_ts = 51.450817
last_seq = 145
current_ts = 51.459251
current_received_ts = 51.459042
current_seq = 146
count = 124
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.451073/145, current 51.459251/146: elapsed=8181.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.459251
last_received_ts = 51.459042
last_seq = 146
current_ts = 51.467430
current_received_ts = 51.467194
current_seq = 147
count = 125
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.459251/146, current 51.467430/147: elapsed=8179.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.467430
last_received_ts = 51.467194
last_seq = 147
current_ts = 51.475609
current_received_ts = 51.475338
current_seq = 148
count = 126
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.467430/147, current 51.475609/148: elapsed=8177.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.475609
last_received_ts = 51.475338
last_seq = 148
current_ts = 51.483791
current_received_ts = 51.483437
current_seq = 149
count = 127
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.475609/148, current 51.483791/149: elapsed=8184.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.483791
last_received_ts = 51.483437
last_seq = 149
current_ts = 51.491966
current_received_ts = 51.491730
current_seq = 150
count = 128
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.483791/149, current 51.491966/150: elapsed=8175.0us expected=8156.3us +- 40.8us, error 0.2%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.491966
last_received_ts = 51.491730
last_seq = 150
current_ts = 51.500145
current_received_ts = 51.499901
current_seq = 151
count = 129
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.491966/150, current 51.500145/151: elapsed=8179.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.500145
last_received_ts = 51.499901
last_seq = 151
current_ts = 51.508324
current_received_ts = 51.508083
current_seq = 152
count = 130
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.500145/151, current 51.508324/152: elapsed=8179.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.508324
last_received_ts = 51.508083
last_seq = 152
current_ts = 51.516502
current_received_ts = 51.516216
current_seq = 153
count = 131
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.508324/152, current 51.516502/153: elapsed=8177.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.516502
last_received_ts = 51.516216
last_seq = 153
current_ts = 51.524677
current_received_ts = 51.524399
current_seq = 154
count = 132
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.516502/153, current 51.524677/154: elapsed=8177.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.524677
last_received_ts = 51.524399
last_seq = 154
current_ts = 51.532864
current_received_ts = 51.532513
current_seq = 155
count = 133
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.524677/154, current 51.532864/155: elapsed=8184.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.532864
last_received_ts = 51.532513
last_seq = 155
current_ts = 51.541039
current_received_ts = 51.540791
current_seq = 156
count = 134
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.532864/155, current 51.541039/156: elapsed=8174.0us expected=8156.3us +- 40.8us, error 0.2%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.541039
last_received_ts = 51.540791
last_seq = 156
current_ts = 51.549217
current_received_ts = 51.548878
current_seq = 157
count = 135
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.541039/156, current 51.549217/157: elapsed=8182.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.549217
last_received_ts = 51.548878
last_seq = 157
current_ts = 51.557392
current_received_ts = 51.557072
current_seq = 158
count = 136
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.549217/157, current 51.557392/158: elapsed=8174.0us expected=8156.3us +- 40.8us, error 0.2%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.557392
last_received_ts = 51.557072
last_seq = 158
current_ts = 51.565571
current_received_ts = 51.565285
current_seq = 159
count = 137
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.557392/158, current 51.565571/159: elapsed=8177.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.565571
last_received_ts = 51.565285
last_seq = 159
current_ts = 51.573750
current_received_ts = 51.573475
current_seq = 160
count = 138
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.565571/159, current 51.573750/160: elapsed=8179.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.573750
last_received_ts = 51.573475
last_seq = 160
current_ts = 51.581928
current_received_ts = 51.581654
current_seq = 161
count = 139
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.573750/160, current 51.581928/161: elapsed=8179.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.581928
last_received_ts = 51.581654
last_seq = 161
current_ts = 51.590103
current_received_ts = 51.589867
current_seq = 162
count = 140
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.581928/161, current 51.590103/162: elapsed=8177.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.590103
last_received_ts = 51.589867
last_seq = 162
current_ts = 51.598289
current_received_ts = 51.597939
current_seq = 163
count = 141
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.590103/162, current 51.598289/163: elapsed=8186.0us expected=8156.3us +- 40.8us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.598289
last_received_ts = 51.597939
last_seq = 163
current_ts = 51.606468
current_received_ts = 51.606216
current_seq = 164
count = 142
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.598289/163, current 51.606468/164: elapsed=8176.0us expected=8156.3us +- 40.8us, error 0.2%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.606468
last_received_ts = 51.606216
last_seq = 164
current_ts = 51.614647
current_received_ts = 51.614296
current_seq = 165
count = 143
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.606468/164, current 51.614647/165: elapsed=8181.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.614647
last_received_ts = 51.614296
last_seq = 165
current_ts = 51.622822
current_received_ts = 51.622486
current_seq = 166
count = 144
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.614647/165, current 51.622822/166: elapsed=8173.0us expected=8156.3us +- 40.8us, error 0.2%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.622822
last_received_ts = 51.622486
last_seq = 166
current_ts = 51.631004
current_received_ts = 51.630608
current_seq = 167
count = 145
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.622822/166, current 51.631004/167: elapsed=8182.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.631004
last_received_ts = 51.630608
last_seq = 167
current_ts = 51.639179
current_received_ts = 51.638763
current_seq = 168
count = 146
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.631004/167, current 51.639179/168: elapsed=8177.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.639179
last_received_ts = 51.638763
last_seq = 168
current_ts = 51.647362
current_received_ts = 51.647030
current_seq = 169
count = 147
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.639179/168, current 51.647362/169: elapsed=8181.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.647362
last_received_ts = 51.647030
last_seq = 169
current_ts = 51.655537
current_received_ts = 51.655167
current_seq = 170
count = 148
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.647362/169, current 51.655537/170: elapsed=8176.0us expected=8156.3us +- 40.8us, error 0.2%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.655537
last_received_ts = 51.655167
last_seq = 170
current_ts = 51.663715
current_received_ts = 51.663326
current_seq = 171
count = 149
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.655537/170, current 51.663715/171: elapsed=8180.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.663715
last_received_ts = 51.663326
last_seq = 171
current_ts = 51.671890
current_received_ts = 51.671501
current_seq = 172
count = 150
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.663715/171, current 51.671890/172: elapsed=8174.0us expected=8156.3us +- 40.8us, error 0.2%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.671890
last_received_ts = 51.671501
last_seq = 172
current_ts = 51.680069
current_received_ts = 51.679646
current_seq = 173
count = 151
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.671890/172, current 51.680069/173: elapsed=8179.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.680069
last_received_ts = 51.679646
last_seq = 173
current_ts = 51.688251
current_received_ts = 51.687828
current_seq = 174
count = 152
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.680069/173, current 51.688251/174: elapsed=8180.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.688251
last_received_ts = 51.687828
last_seq = 174
current_ts = 51.696426
current_received_ts = 51.696041
current_seq = 175
count = 153
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.688251/174, current 51.696426/175: elapsed=8177.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.696426
last_received_ts = 51.696041
last_seq = 175
current_ts = 51.704609
current_received_ts = 51.704311
current_seq = 176
count = 154
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.696426/175, current 51.704609/176: elapsed=8181.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.704609
last_received_ts = 51.704311
last_seq = 176
current_ts = 51.712788
current_received_ts = 51.712406
current_seq = 177
count = 155
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.704609/176, current 51.712788/177: elapsed=8181.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.712788
last_received_ts = 51.712406
last_seq = 177
current_ts = 51.720963
current_received_ts = 51.720699
current_seq = 178
count = 156
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.712788/177, current 51.720963/178: elapsed=8172.0us expected=8156.3us +- 40.8us, error 0.2%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.720963
last_received_ts = 51.720699
last_seq = 178
current_ts = 51.729145
current_received_ts = 51.728798
current_seq = 179
count = 157
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.720963/178, current 51.729145/179: elapsed=8185.0us expected=8156.3us +- 40.8us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.729145
last_received_ts = 51.728798
last_seq = 179
current_ts = 51.737324
current_received_ts = 51.736980
current_seq = 180
count = 158
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.729145/179, current 51.737324/180: elapsed=8178.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.737324
last_received_ts = 51.736980
last_seq = 180
current_ts = 51.745499
current_received_ts = 51.745171
current_seq = 181
count = 159
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.737324/180, current 51.745499/181: elapsed=8174.0us expected=8156.3us +- 40.8us, error 0.2%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.745499
last_received_ts = 51.745171
last_seq = 181
current_ts = 51.753681
current_received_ts = 51.753342
current_seq = 182
count = 160
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.745499/181, current 51.753681/182: elapsed=8184.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.753681
last_received_ts = 51.753342
last_seq = 182
current_ts = 51.761860
current_received_ts = 51.761555
current_seq = 183
count = 161
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.753681/182, current 51.761860/183: elapsed=8177.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.761860
last_received_ts = 51.761555
last_seq = 183
current_ts = 51.770035
current_received_ts = 51.769756
current_seq = 184
count = 162
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.761860/183, current 51.770035/184: elapsed=8174.0us expected=8156.3us +- 40.8us, error 0.2%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.770035
last_received_ts = 51.769756
last_seq = 184
current_ts = 51.778217
current_received_ts = 51.777866
current_seq = 185
count = 163
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.770035/184, current 51.778217/185: elapsed=8184.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.778217
last_received_ts = 51.777866
last_seq = 185
current_ts = 51.786388
current_received_ts = 51.786060
current_seq = 186
count = 164
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.778217/185, current 51.786388/186: elapsed=8173.0us expected=8156.3us +- 40.8us, error 0.2%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.786388
last_received_ts = 51.786060
last_seq = 186
current_ts = 51.794571
current_received_ts = 51.794273
current_seq = 187
count = 165
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.786388/186, current 51.794571/187: elapsed=8182.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.794571
last_received_ts = 51.794273
last_seq = 187
current_ts = 51.802750
current_received_ts = 51.802471
current_seq = 188
count = 166
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.794571/187, current 51.802750/188: elapsed=8176.0us expected=8156.3us +- 40.8us, error 0.2%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.802750
last_received_ts = 51.802471
last_seq = 188
current_ts = 51.810932
current_received_ts = 51.810654
current_seq = 189
count = 167
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.802750/188, current 51.810932/189: elapsed=8183.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.810932
last_received_ts = 51.810654
last_seq = 189
current_ts = 51.819103
current_received_ts = 51.818825
current_seq = 190
count = 168
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.810932/189, current 51.819103/190: elapsed=8174.0us expected=8156.3us +- 40.8us, error 0.2%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.819103
last_received_ts = 51.818825
last_seq = 190
current_ts = 51.827290
current_received_ts = 51.826942
current_seq = 191
count = 169
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.819103/190, current 51.827290/191: elapsed=8184.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.827290
last_received_ts = 51.826942
last_seq = 191
current_ts = 51.835461
current_received_ts = 51.835125
current_seq = 192
count = 170
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.827290/191, current 51.835461/192: elapsed=8173.0us expected=8156.3us +- 40.8us, error 0.2%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.835461
last_received_ts = 51.835125
last_seq = 192
current_ts = 51.843643
current_received_ts = 51.843380
current_seq = 193
count = 171
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.835461/192, current 51.843643/193: elapsed=8182.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.843643
last_received_ts = 51.843380
last_seq = 193
current_ts = 51.851822
current_received_ts = 51.851543
current_seq = 194
count = 172
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.843643/193, current 51.851822/194: elapsed=8178.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.851822
last_received_ts = 51.851543
last_seq = 194
current_ts = 51.860004
current_received_ts = 51.859657
current_seq = 195
count = 173
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.851822/194, current 51.860004/195: elapsed=8181.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.860004
last_received_ts = 51.859657
last_seq = 195
current_ts = 51.868176
current_received_ts = 51.867928
current_seq = 196
count = 174
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.860004/195, current 51.868176/196: elapsed=8172.0us expected=8156.3us +- 40.8us, error 0.2%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.868176
last_received_ts = 51.867928
last_seq = 196
current_ts = 51.876354
current_received_ts = 51.876118
current_seq = 197
count = 175
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.868176/196, current 51.876354/197: elapsed=8178.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.876354
last_received_ts = 51.876118
last_seq = 197
current_ts = 51.884533
current_received_ts = 51.884239
current_seq = 198
count = 176
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.876354/197, current 51.884533/198: elapsed=8179.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.884533
last_received_ts = 51.884239
last_seq = 198
current_ts = 51.892712
current_received_ts = 51.892376
current_seq = 199
count = 177
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.884533/198, current 51.892712/199: elapsed=8178.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.892712
last_received_ts = 51.892376
last_seq = 199
current_ts = 51.900890
current_received_ts = 51.900578
current_seq = 200
count = 178
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.892712/199, current 51.900890/200: elapsed=8179.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.900890
last_received_ts = 51.900578
last_seq = 200
current_ts = 51.909065
current_received_ts = 51.908829
current_seq = 201
count = 179
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.900890/200, current 51.909065/201: elapsed=8178.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.909065
last_received_ts = 51.908829
last_seq = 201
current_ts = 51.917248
current_received_ts = 51.917030
current_seq = 202
count = 180
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.909065/201, current 51.917248/202: elapsed=8181.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.917248
last_received_ts = 51.917030
last_seq = 202
current_ts = 51.925423
current_received_ts = 51.925194
current_seq = 203
count = 181
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.917248/202, current 51.925423/203: elapsed=8176.0us expected=8156.3us +- 40.8us, error 0.2%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.925423
last_received_ts = 51.925194
last_seq = 203
current_ts = 51.933601
current_received_ts = 51.933331
current_seq = 204
count = 182
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.925423/203, current 51.933601/204: elapsed=8178.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.933601
last_received_ts = 51.933331
last_seq = 204
current_ts = 51.941784
current_received_ts = 51.941505
current_seq = 205
count = 183
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.933601/204, current 51.941784/205: elapsed=8181.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.941784
last_received_ts = 51.941505
last_seq = 205
current_ts = 51.949966
current_received_ts = 51.949615
current_seq = 206
count = 184
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.941784/205, current 51.949966/206: elapsed=8183.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.949966
last_received_ts = 51.949615
last_seq = 206
current_ts = 51.958141
current_received_ts = 51.957867
current_seq = 207
count = 185
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.949966/206, current 51.958141/207: elapsed=8176.0us expected=8156.3us +- 40.8us, error 0.2%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.958141
last_received_ts = 51.957867
last_seq = 207
current_ts = 51.966320
current_received_ts = 51.966072
current_seq = 208
count = 186
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.958141/207, current 51.966320/208: elapsed=8178.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.966320
last_received_ts = 51.966072
last_seq = 208
current_ts = 51.974499
current_received_ts = 51.974232
current_seq = 209
count = 187
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.966320/208, current 51.974499/209: elapsed=8178.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.974499
last_received_ts = 51.974232
last_seq = 209
current_ts = 51.982681
current_received_ts = 51.982338
current_seq = 210
count = 188
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.974499/209, current 51.982681/210: elapsed=8182.0us expected=8156.3us +- 40.8us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.982681
last_received_ts = 51.982338
last_seq = 210
current_ts = 51.990852
current_received_ts = 51.990578
current_seq = 211
count = 189
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.982681/210, current 51.990852/211: elapsed=8174.0us expected=8156.3us +- 40.8us, error 0.2%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.990852
last_received_ts = 51.990578
last_seq = 211
current_ts = 51.999050
current_received_ts = 51.998814
current_seq = 212
count = 190
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.990852/211, current 51.999050/212: elapsed=8195.0us expected=8156.3us +- 40.8us, error 0.5%
(kms_flip:2017) DEBUG: name = flip
last_ts = 51.999050
last_received_ts = 51.998814
last_seq = 212
current_ts = 52.007252
current_received_ts = 52.006931
current_seq = 213
count = 191
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 51.999050/212, current 52.007252/213: elapsed=8201.0us expected=8156.3us +- 40.8us, error 0.5%
(kms_flip:2017) DEBUG: inconsistent flip ts/seq: last 51.999050/212, current 52.007252/213: elapsed=8201.0us expected=8156.3us
(kms_flip:2017) DEBUG: expected 31866, counted 191, encoder type 2
(kms_flip:2017) DEBUG: dropped frames, expected 31866, counted 191, encoder type 2
(kms_flip:2017) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:2017) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:2017) igt_core-INFO: Stack trace:
(kms_flip:2017) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:2017) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:2017) igt_core-INFO:   #2 ../tests/kms_flip.c:1845 run_test()
(kms_flip:2017) igt_core-INFO:   #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
(kms_flip:2017) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:2017) igt_core-INFO:   #5 ../sysdeps/nptl/libc_start_call_main.h:74 __libc_start_call_main()
(kms_flip:2017) igt_core-INFO:   #6 ../csu/libc-start.c:128 __libc_start_main@@GLIBC_2.34()
(kms_flip:2017) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-HDMI-A1: FAIL (5.087s)
Starting dynamic subtest: C-HDMI-A1
(kms_flip:2017) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:2017) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest C-HDMI-A1 failed.
**** DEBUG ****
(kms_flip:2017) DEBUG: flip ts/seq: last 58.032867/335, current 58.041134/336: elapsed=8266.0us expected=8243.0us +- 41.2us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.041134
last_received_ts = 58.040779
last_seq = 336
current_ts = 58.049408
current_received_ts = 58.049126
current_seq = 337
count = 314
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.041134/336, current 58.049408/337: elapsed=8277.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.049408
last_received_ts = 58.049126
last_seq = 337
current_ts = 58.057686
current_received_ts = 58.057335
current_seq = 338
count = 315
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.049408/337, current 58.057686/338: elapsed=8275.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.057686
last_received_ts = 58.057335
last_seq = 338
current_ts = 58.065956
current_received_ts = 58.065720
current_seq = 339
count = 316
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.057686/338, current 58.065956/339: elapsed=8272.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.065956
last_received_ts = 58.065720
last_seq = 339
current_ts = 58.074230
current_received_ts = 58.073872
current_seq = 340
count = 317
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.065956/339, current 58.074230/340: elapsed=8275.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.074230
last_received_ts = 58.073872
last_seq = 340
current_ts = 58.082497
current_received_ts = 58.082211
current_seq = 341
count = 318
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.074230/340, current 58.082497/341: elapsed=8267.0us expected=8243.0us +- 41.2us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.082497
last_received_ts = 58.082211
last_seq = 341
current_ts = 58.090775
current_received_ts = 58.090420
current_seq = 342
count = 319
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.082497/341, current 58.090775/342: elapsed=8275.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.090775
last_received_ts = 58.090420
last_seq = 342
current_ts = 58.099045
current_received_ts = 58.098701
current_seq = 343
count = 320
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.090775/342, current 58.099045/343: elapsed=8273.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.099045
last_received_ts = 58.098701
last_seq = 343
current_ts = 58.107323
current_received_ts = 58.107101
current_seq = 344
count = 321
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.099045/343, current 58.107323/344: elapsed=8275.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.107323
last_received_ts = 58.107101
last_seq = 344
current_ts = 58.115593
current_received_ts = 58.115307
current_seq = 345
count = 322
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.107323/344, current 58.115593/345: elapsed=8271.0us expected=8243.0us +- 41.2us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.115593
last_received_ts = 58.115307
last_seq = 345
current_ts = 58.123867
current_received_ts = 58.123520
current_seq = 346
count = 323
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.115593/345, current 58.123867/346: elapsed=8274.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.123867
last_received_ts = 58.123520
last_seq = 346
current_ts = 58.132145
current_received_ts = 58.131893
current_seq = 347
count = 324
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.123867/346, current 58.132145/347: elapsed=8278.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.132145
last_received_ts = 58.131893
last_seq = 347
current_ts = 58.140411
current_received_ts = 58.140144
current_seq = 348
count = 325
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.132145/347, current 58.140411/348: elapsed=8268.0us expected=8243.0us +- 41.2us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.140411
last_received_ts = 58.140144
last_seq = 348
current_ts = 58.148685
current_received_ts = 58.148346
current_seq = 349
count = 326
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.140411/348, current 58.148685/349: elapsed=8273.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.148685
last_received_ts = 58.148346
last_seq = 349
current_ts = 58.156960
current_received_ts = 58.156670
current_seq = 350
count = 327
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.148685/349, current 58.156960/350: elapsed=8274.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.156960
last_received_ts = 58.156670
last_seq = 350
current_ts = 58.165237
current_received_ts = 58.164989
current_seq = 351
count = 328
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.156960/350, current 58.165237/351: elapsed=8278.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.165237
last_received_ts = 58.164989
last_seq = 351
current_ts = 58.173508
current_received_ts = 58.173225
current_seq = 352
count = 329
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.165237/351, current 58.173508/352: elapsed=8272.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.173508
last_received_ts = 58.173225
last_seq = 352
current_ts = 58.181782
current_received_ts = 58.181503
current_seq = 353
count = 330
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.173508/352, current 58.181782/353: elapsed=8274.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.181782
last_received_ts = 58.181503
last_seq = 353
current_ts = 58.190052
current_received_ts = 58.189709
current_seq = 354
count = 331
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.181782/353, current 58.190052/354: elapsed=8268.0us expected=8243.0us +- 41.2us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.190052
last_received_ts = 58.189709
last_seq = 354
current_ts = 58.198326
current_received_ts = 58.198143
current_seq = 355
count = 332
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.190052/354, current 58.198326/355: elapsed=8275.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.198326
last_received_ts = 58.198143
last_seq = 355
current_ts = 58.206596
current_received_ts = 58.206310
current_seq = 356
count = 333
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.198326/355, current 58.206596/356: elapsed=8272.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.206596
last_received_ts = 58.206310
last_seq = 356
current_ts = 58.214870
current_received_ts = 58.214535
current_seq = 357
count = 334
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.206596/356, current 58.214870/357: elapsed=8274.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.214870
last_received_ts = 58.214535
last_seq = 357
current_ts = 58.223148
current_received_ts = 58.222874
current_seq = 358
count = 335
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.214870/357, current 58.223148/358: elapsed=8278.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.223148
last_received_ts = 58.222874
last_seq = 358
current_ts = 58.231419
current_received_ts = 58.231113
current_seq = 359
count = 336
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.223148/358, current 58.231419/359: elapsed=8270.0us expected=8243.0us +- 41.2us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.231419
last_received_ts = 58.231113
last_seq = 359
current_ts = 58.239693
current_received_ts = 58.239346
current_seq = 360
count = 337
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.231419/359, current 58.239693/360: elapsed=8272.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.239693
last_received_ts = 58.239346
last_seq = 360
current_ts = 58.247967
current_received_ts = 58.247692
current_seq = 361
count = 338
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.239693/360, current 58.247967/361: elapsed=8276.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.247967
last_received_ts = 58.247692
last_seq = 361
current_ts = 58.256241
current_received_ts = 58.255894
current_seq = 362
count = 339
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.247967/361, current 58.256241/362: elapsed=8271.0us expected=8243.0us +- 41.2us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.256241
last_received_ts = 58.255894
last_seq = 362
current_ts = 58.264515
current_received_ts = 58.264217
current_seq = 363
count = 340
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.256241/362, current 58.264515/363: elapsed=8277.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.264515
last_received_ts = 58.264217
last_seq = 363
current_ts = 58.272785
current_received_ts = 58.272507
current_seq = 364
count = 341
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.264515/363, current 58.272785/364: elapsed=8271.0us expected=8243.0us +- 41.2us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.272785
last_received_ts = 58.272507
last_seq = 364
current_ts = 58.281063
current_received_ts = 58.280811
current_seq = 365
count = 342
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.272785/364, current 58.281063/365: elapsed=8275.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.281063
last_received_ts = 58.280811
last_seq = 365
current_ts = 58.289333
current_received_ts = 58.288986
current_seq = 366
count = 343
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.281063/365, current 58.289333/366: elapsed=8270.0us expected=8243.0us +- 41.2us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.289333
last_received_ts = 58.288986
last_seq = 366
current_ts = 58.297607
current_received_ts = 58.297268
current_seq = 367
count = 344
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.289333/366, current 58.297607/367: elapsed=8274.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.297607
last_received_ts = 58.297268
last_seq = 367
current_ts = 58.305878
current_received_ts = 58.305626
current_seq = 368
count = 345
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.297607/367, current 58.305878/368: elapsed=8271.0us expected=8243.0us +- 41.2us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.305878
last_received_ts = 58.305626
last_seq = 368
current_ts = 58.314152
current_received_ts = 58.313908
current_seq = 369
count = 346
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.305878/368, current 58.314152/369: elapsed=8273.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.314152
last_received_ts = 58.313908
last_seq = 369
current_ts = 58.322426
current_received_ts = 58.322098
current_seq = 370
count = 347
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.314152/369, current 58.322426/370: elapsed=8276.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.322426
last_received_ts = 58.322098
last_seq = 370
current_ts = 58.330696
current_received_ts = 58.330414
current_seq = 371
count = 348
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.322426/370, current 58.330696/371: elapsed=8271.0us expected=8243.0us +- 41.2us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.330696
last_received_ts = 58.330414
last_seq = 371
current_ts = 58.338970
current_received_ts = 58.338627
current_seq = 372
count = 349
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.330696/371, current 58.338970/372: elapsed=8273.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.338970
last_received_ts = 58.338627
last_seq = 372
current_ts = 58.347244
current_received_ts = 58.346905
current_seq = 373
count = 350
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.338970/372, current 58.347244/373: elapsed=8275.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.347244
last_received_ts = 58.346905
last_seq = 373
current_ts = 58.355518
current_received_ts = 58.355278
current_seq = 374
count = 351
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.347244/373, current 58.355518/374: elapsed=8273.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.355518
last_received_ts = 58.355278
last_seq = 374
current_ts = 58.363796
current_received_ts = 58.363506
current_seq = 375
count = 352
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.355518/374, current 58.363796/375: elapsed=8277.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.363796
last_received_ts = 58.363506
last_seq = 375
current_ts = 58.372063
current_received_ts = 58.371719
current_seq = 376
count = 353
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.363796/375, current 58.372063/376: elapsed=8269.0us expected=8243.0us +- 41.2us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.372063
last_received_ts = 58.371719
last_seq = 376
current_ts = 58.380337
current_received_ts = 58.380131
current_seq = 377
count = 354
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.372063/376, current 58.380337/377: elapsed=8274.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.380337
last_received_ts = 58.380131
last_seq = 377
current_ts = 58.388615
current_received_ts = 58.388317
current_seq = 378
count = 355
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.380337/377, current 58.388615/378: elapsed=8278.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.388615
last_received_ts = 58.388317
last_seq = 378
current_ts = 58.396885
current_received_ts = 58.396584
current_seq = 379
count = 356
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.388615/378, current 58.396885/379: elapsed=8269.0us expected=8243.0us +- 41.2us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.396885
last_received_ts = 58.396584
last_seq = 379
current_ts = 58.405159
current_received_ts = 58.404873
current_seq = 380
count = 357
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.396885/379, current 58.405159/380: elapsed=8275.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.405159
last_received_ts = 58.404873
last_seq = 380
current_ts = 58.413433
current_received_ts = 58.413239
current_seq = 381
count = 358
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.405159/380, current 58.413433/381: elapsed=8273.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.413433
last_received_ts = 58.413239
last_seq = 381
current_ts = 58.421707
current_received_ts = 58.421333
current_seq = 382
count = 359
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.413433/381, current 58.421707/382: elapsed=8273.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.421707
last_received_ts = 58.421333
last_seq = 382
current_ts = 58.429977
current_received_ts = 58.429733
current_seq = 383
count = 360
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.421707/382, current 58.429977/383: elapsed=8272.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.429977
last_received_ts = 58.429733
last_seq = 383
current_ts = 58.438251
current_received_ts = 58.438046
current_seq = 384
count = 361
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.429977/383, current 58.438251/384: elapsed=8273.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.438251
last_received_ts = 58.438046
last_seq = 384
current_ts = 58.446522
current_received_ts = 58.446163
current_seq = 385
count = 362
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.438251/384, current 58.446522/385: elapsed=8272.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.446522
last_received_ts = 58.446163
last_seq = 385
current_ts = 58.454803
current_received_ts = 58.454525
current_seq = 386
count = 363
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.446522/385, current 58.454803/386: elapsed=8279.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.454803
last_received_ts = 58.454525
last_seq = 386
current_ts = 58.463070
current_received_ts = 58.462730
current_seq = 387
count = 364
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.454803/386, current 58.463070/387: elapsed=8269.0us expected=8243.0us +- 41.2us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.463070
last_received_ts = 58.462730
last_seq = 387
current_ts = 58.471348
current_received_ts = 58.471111
current_seq = 388
count = 365
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.463070/387, current 58.471348/388: elapsed=8277.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.471348
last_received_ts = 58.471111
last_seq = 388
current_ts = 58.479622
current_received_ts = 58.479263
current_seq = 389
count = 366
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.471348/388, current 58.479622/389: elapsed=8273.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.479622
last_received_ts = 58.479263
last_seq = 389
current_ts = 58.487892
current_received_ts = 58.487549
current_seq = 390
count = 367
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.479622/389, current 58.487892/390: elapsed=8273.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.487892
last_received_ts = 58.487549
last_seq = 390
current_ts = 58.496166
current_received_ts = 58.495918
current_seq = 391
count = 368
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.487892/390, current 58.496166/391: elapsed=8274.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.496166
last_received_ts = 58.495918
last_seq = 391
current_ts = 58.504436
current_received_ts = 58.504116
current_seq = 392
count = 369
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.496166/391, current 58.504436/392: elapsed=8270.0us expected=8243.0us +- 41.2us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.504436
last_received_ts = 58.504116
last_seq = 392
current_ts = 58.512711
current_received_ts = 58.512363
current_seq = 393
count = 370
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.504436/392, current 58.512711/393: elapsed=8273.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.512711
last_received_ts = 58.512363
last_seq = 393
current_ts = 58.520985
current_received_ts = 58.520634
current_seq = 394
count = 371
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.512711/393, current 58.520985/394: elapsed=8272.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.520985
last_received_ts = 58.520634
last_seq = 394
current_ts = 58.529259
current_received_ts = 58.528912
current_seq = 395
count = 372
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.520985/394, current 58.529259/395: elapsed=8275.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.529259
last_received_ts = 58.528912
last_seq = 395
current_ts = 58.537533
current_received_ts = 58.537216
current_seq = 396
count = 373
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.529259/395, current 58.537533/396: elapsed=8274.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.537533
last_received_ts = 58.537216
last_seq = 396
current_ts = 58.545807
current_received_ts = 58.545486
current_seq = 397
count = 374
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.537533/396, current 58.545807/397: elapsed=8273.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.545807
last_received_ts = 58.545486
last_seq = 397
current_ts = 58.554085
current_received_ts = 58.553726
current_seq = 398
count = 375
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.545807/397, current 58.554085/398: elapsed=8278.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.554085
last_received_ts = 58.553726
last_seq = 398
current_ts = 58.562351
current_received_ts = 58.562035
current_seq = 399
count = 376
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.554085/398, current 58.562351/399: elapsed=8268.0us expected=8243.0us +- 41.2us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.562351
last_received_ts = 58.562035
last_seq = 399
current_ts = 58.570621
current_received_ts = 58.570320
current_seq = 400
count = 377
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.562351/399, current 58.570621/400: elapsed=8271.0us expected=8243.0us +- 41.2us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.570621
last_received_ts = 58.570320
last_seq = 400
current_ts = 58.578896
current_received_ts = 58.578552
current_seq = 401
count = 378
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.570621/400, current 58.578896/401: elapsed=8274.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.578896
last_received_ts = 58.578552
last_seq = 401
current_ts = 58.587170
current_received_ts = 58.586826
current_seq = 402
count = 379
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.578896/401, current 58.587170/402: elapsed=8274.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.587170
last_received_ts = 58.586826
last_seq = 402
current_ts = 58.595448
current_received_ts = 58.595207
current_seq = 403
count = 380
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.587170/402, current 58.595448/403: elapsed=8276.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.595448
last_received_ts = 58.595207
last_seq = 403
current_ts = 58.603722
current_received_ts = 58.603439
current_seq = 404
count = 381
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.595448/403, current 58.603722/404: elapsed=8274.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.603722
last_received_ts = 58.603439
last_seq = 404
current_ts = 58.611988
current_received_ts = 58.611645
current_seq = 405
count = 382
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.603722/404, current 58.611988/405: elapsed=8268.0us expected=8243.0us +- 41.2us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.611988
last_received_ts = 58.611645
last_seq = 405
current_ts = 58.620262
current_received_ts = 58.619923
current_seq = 406
count = 383
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.611988/405, current 58.620262/406: elapsed=8276.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.620262
last_received_ts = 58.619923
last_seq = 406
current_ts = 58.628540
current_received_ts = 58.628254
current_seq = 407
count = 384
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.620262/406, current 58.628540/407: elapsed=8275.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.628540
last_received_ts = 58.628254
last_seq = 407
current_ts = 58.636810
current_received_ts = 58.636513
current_seq = 408
count = 385
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.628540/407, current 58.636810/408: elapsed=8272.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.636810
last_received_ts = 58.636513
last_seq = 408
current_ts = 58.645084
current_received_ts = 58.644779
current_seq = 409
count = 386
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.636810/408, current 58.645084/409: elapsed=8273.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.645084
last_received_ts = 58.644779
last_seq = 409
current_ts = 58.653358
current_received_ts = 58.652992
current_seq = 410
count = 387
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.645084/409, current 58.653358/410: elapsed=8275.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.653358
last_received_ts = 58.652992
last_seq = 410
current_ts = 58.661629
current_received_ts = 58.661289
current_seq = 411
count = 388
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.653358/410, current 58.661629/411: elapsed=8270.0us expected=8243.0us +- 41.2us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.661629
last_received_ts = 58.661289
last_seq = 411
current_ts = 58.669903
current_received_ts = 58.669556
current_seq = 412
count = 389
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.661629/411, current 58.669903/412: elapsed=8272.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.669903
last_received_ts = 58.669556
last_seq = 412
current_ts = 58.678181
current_received_ts = 58.677925
current_seq = 413
count = 390
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.669903/412, current 58.678181/413: elapsed=8280.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.678181
last_received_ts = 58.677925
last_seq = 413
current_ts = 58.686455
current_received_ts = 58.686111
current_seq = 414
count = 391
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.678181/413, current 58.686455/414: elapsed=8273.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.686455
last_received_ts = 58.686111
last_seq = 414
current_ts = 58.694729
current_received_ts = 58.694374
current_seq = 415
count = 392
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.686455/414, current 58.694729/415: elapsed=8274.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.694729
last_received_ts = 58.694374
last_seq = 415
current_ts = 58.702995
current_received_ts = 58.702660
current_seq = 416
count = 393
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.694729/415, current 58.702995/416: elapsed=8269.0us expected=8243.0us +- 41.2us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.702995
last_received_ts = 58.702660
last_seq = 416
current_ts = 58.711269
current_received_ts = 58.710930
current_seq = 417
count = 394
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.702995/416, current 58.711269/417: elapsed=8271.0us expected=8243.0us +- 41.2us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.711269
last_received_ts = 58.710930
last_seq = 417
current_ts = 58.719547
current_received_ts = 58.719269
current_seq = 418
count = 395
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.711269/417, current 58.719547/418: elapsed=8278.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.719547
last_received_ts = 58.719269
last_seq = 418
current_ts = 58.727821
current_received_ts = 58.727425
current_seq = 419
count = 396
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.719547/418, current 58.727821/419: elapsed=8275.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.727821
last_received_ts = 58.727425
last_seq = 419
current_ts = 58.736095
current_received_ts = 58.735847
current_seq = 420
count = 397
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.727821/419, current 58.736095/420: elapsed=8273.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.736095
last_received_ts = 58.735847
last_seq = 420
current_ts = 58.744370
current_received_ts = 58.743973
current_seq = 421
count = 398
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.736095/420, current 58.744370/421: elapsed=8274.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.744370
last_received_ts = 58.743973
last_seq = 421
current_ts = 58.752636
current_received_ts = 58.752289
current_seq = 422
count = 399
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.744370/421, current 58.752636/422: elapsed=8267.0us expected=8243.0us +- 41.2us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.752636
last_received_ts = 58.752289
last_seq = 422
current_ts = 58.760906
current_received_ts = 58.760567
current_seq = 423
count = 400
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.752636/422, current 58.760906/423: elapsed=8273.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.760906
last_received_ts = 58.760567
last_seq = 423
current_ts = 58.769180
current_received_ts = 58.768833
current_seq = 424
count = 401
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.760906/423, current 58.769180/424: elapsed=8274.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.769180
last_received_ts = 58.768833
last_seq = 424
current_ts = 58.777454
current_received_ts = 58.777218
current_seq = 425
count = 402
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.769180/424, current 58.777454/425: elapsed=8274.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.777454
last_received_ts = 58.777218
last_seq = 425
current_ts = 58.785732
current_received_ts = 58.785446
current_seq = 426
count = 403
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.777454/425, current 58.785732/426: elapsed=8276.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.785732
last_received_ts = 58.785446
last_seq = 426
current_ts = 58.794003
current_received_ts = 58.793659
current_seq = 427
count = 404
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.785732/426, current 58.794003/427: elapsed=8271.0us expected=8243.0us +- 41.2us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.794003
last_received_ts = 58.793659
last_seq = 427
current_ts = 58.802277
current_received_ts = 58.801933
current_seq = 428
count = 405
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.794003/427, current 58.802277/428: elapsed=8273.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.802277
last_received_ts = 58.801933
last_seq = 428
current_ts = 58.810551
current_received_ts = 58.810215
current_seq = 429
count = 406
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.802277/428, current 58.810551/429: elapsed=8276.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.810551
last_received_ts = 58.810215
last_seq = 429
current_ts = 58.818821
current_received_ts = 58.818474
current_seq = 430
count = 407
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.810551/429, current 58.818821/430: elapsed=8270.0us expected=8243.0us +- 41.2us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.818821
last_received_ts = 58.818474
last_seq = 430
current_ts = 58.827095
current_received_ts = 58.826801
current_seq = 431
count = 408
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.818821/430, current 58.827095/431: elapsed=8272.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.827095
last_received_ts = 58.826801
last_seq = 431
current_ts = 58.835369
current_received_ts = 58.835182
current_seq = 432
count = 409
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.827095/431, current 58.835369/432: elapsed=8274.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.835369
last_received_ts = 58.835182
last_seq = 432
current_ts = 58.843647
current_received_ts = 58.843342
current_seq = 433
count = 410
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.835369/432, current 58.843647/433: elapsed=8278.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.843647
last_received_ts = 58.843342
last_seq = 433
current_ts = 58.851917
current_received_ts = 58.851578
current_seq = 434
count = 411
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.843647/433, current 58.851917/434: elapsed=8273.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.851917
last_received_ts = 58.851578
last_seq = 434
current_ts = 58.860188
current_received_ts = 58.859840
current_seq = 435
count = 412
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.851917/434, current 58.860188/435: elapsed=8268.0us expected=8243.0us +- 41.2us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.860188
last_received_ts = 58.859840
last_seq = 435
current_ts = 58.868462
current_received_ts = 58.868122
current_seq = 436
count = 413
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.860188/435, current 58.868462/436: elapsed=8276.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.868462
last_received_ts = 58.868122
last_seq = 436
current_ts = 58.876736
current_received_ts = 58.876381
current_seq = 437
count = 414
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.868462/436, current 58.876736/437: elapsed=8271.0us expected=8243.0us +- 41.2us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.876736
last_received_ts = 58.876381
last_seq = 437
current_ts = 58.885006
current_received_ts = 58.884666
current_seq = 438
count = 415
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.876736/437, current 58.885006/438: elapsed=8273.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.885006
last_received_ts = 58.884666
last_seq = 438
current_ts = 58.893284
current_received_ts = 58.892941
current_seq = 439
count = 416
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.885006/438, current 58.893284/439: elapsed=8275.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.893284
last_received_ts = 58.892941
last_seq = 439
current_ts = 58.901558
current_received_ts = 58.901279
current_seq = 440
count = 417
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.893284/439, current 58.901558/440: elapsed=8276.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.901558
last_received_ts = 58.901279
last_seq = 440
current_ts = 58.909828
current_received_ts = 58.909489
current_seq = 441
count = 418
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.901558/440, current 58.909828/441: elapsed=8269.0us expected=8243.0us +- 41.2us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.909828
last_received_ts = 58.909489
last_seq = 441
current_ts = 58.918102
current_received_ts = 58.917755
current_seq = 442
count = 419
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.909828/441, current 58.918102/442: elapsed=8274.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.918102
last_received_ts = 58.917755
last_seq = 442
current_ts = 58.926376
current_received_ts = 58.926182
current_seq = 443
count = 420
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.918102/442, current 58.926376/443: elapsed=8277.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.926376
last_received_ts = 58.926182
last_seq = 443
current_ts = 58.934650
current_received_ts = 58.934311
current_seq = 444
count = 421
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.926376/443, current 58.934650/444: elapsed=8271.0us expected=8243.0us +- 41.2us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.934650
last_received_ts = 58.934311
last_seq = 444
current_ts = 58.942924
current_received_ts = 58.942616
current_seq = 445
count = 422
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.934650/444, current 58.942924/445: elapsed=8276.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.942924
last_received_ts = 58.942616
last_seq = 445
current_ts = 58.951195
current_received_ts = 58.950859
current_seq = 446
count = 423
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.942924/445, current 58.951195/446: elapsed=8270.0us expected=8243.0us +- 41.2us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.951195
last_received_ts = 58.950859
last_seq = 446
current_ts = 58.959465
current_received_ts = 58.959229
current_seq = 447
count = 424
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.951195/446, current 58.959465/447: elapsed=8271.0us expected=8243.0us +- 41.2us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.959465
last_received_ts = 58.959229
last_seq = 447
current_ts = 58.967743
current_received_ts = 58.967392
current_seq = 448
count = 425
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.959465/447, current 58.967743/448: elapsed=8275.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.967743
last_received_ts = 58.967392
last_seq = 448
current_ts = 58.976017
current_received_ts = 58.975670
current_seq = 449
count = 426
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.967743/448, current 58.976017/449: elapsed=8275.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.976017
last_received_ts = 58.975670
last_seq = 449
current_ts = 58.984287
current_received_ts = 58.983940
current_seq = 450
count = 427
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.976017/449, current 58.984287/450: elapsed=8271.0us expected=8243.0us +- 41.2us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.984287
last_received_ts = 58.983940
last_seq = 450
current_ts = 58.992565
current_received_ts = 58.992241
current_seq = 451
count = 428
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.984287/450, current 58.992565/451: elapsed=8278.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 58.992565
last_received_ts = 58.992241
last_seq = 451
current_ts = 59.000847
current_received_ts = 59.000534
current_seq = 452
count = 429
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 58.992565/451, current 59.000847/452: elapsed=8280.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 59.000847
last_received_ts = 59.000534
last_seq = 452
current_ts = 59.009129
current_received_ts = 59.008862
current_seq = 453
count = 430
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 59.000847/452, current 59.009129/453: elapsed=8283.0us expected=8243.0us +- 41.2us, error 0.5%
(kms_flip:2017) DEBUG: name = flip
last_ts = 59.009129
last_received_ts = 59.008862
last_seq = 453
current_ts = 59.017406
current_received_ts = 59.017056
current_seq = 454
count = 431
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 59.009129/453, current 59.017406/454: elapsed=8279.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 59.017406
last_received_ts = 59.017056
last_seq = 454
current_ts = 59.025684
current_received_ts = 59.025345
current_seq = 455
count = 432
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 59.017406/454, current 59.025684/455: elapsed=8278.0us expected=8243.0us +- 41.2us, error 0.4%
(kms_flip:2017) DEBUG: name = flip
last_ts = 59.025684
last_received_ts = 59.025345
last_seq = 455
current_ts = 59.033974
current_received_ts = 59.033627
current_seq = 456
count = 433
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 59.025684/455, current 59.033974/456: elapsed=8287.0us expected=8243.0us +- 41.2us, error 0.5%
(kms_flip:2017) DEBUG: inconsistent flip ts/seq: last 59.025684/455, current 59.033974/456: elapsed=8287.0us expected=8243.0us
(kms_flip:2017) DEBUG: expected 31531, counted 433, encoder type 2
(kms_flip:2017) DEBUG: dropped frames, expected 31531, counted 433, encoder type 2
(kms_flip:2017) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:2017) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:2017) igt_core-INFO: Stack trace:
(kms_flip:2017) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:2017) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:2017) igt_core-INFO:   #2 ../tests/kms_flip.c:1845 run_test()
(kms_flip:2017) igt_core-INFO:   #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
(kms_flip:2017) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:2017) igt_core-INFO:   #5 ../sysdeps/nptl/libc_start_call_main.h:74 __libc_start_call_main()
(kms_flip:2017) igt_core-INFO:   #6 ../csu/libc-start.c:128 __libc_start_main@@GLIBC_2.34()
(kms_flip:2017) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest C-HDMI-A1: FAIL (7.091s)
Starting dynamic subtest: D-HDMI-A1
(kms_flip:2017) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:2017) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest D-HDMI-A1 failed.
**** DEBUG ****
(kms_flip:2017) DEBUG: name = flip
last_ts = 68.992607
last_received_ts = 68.992279
last_seq = 804
current_ts = 69.000931
current_received_ts = 69.000687
current_seq = 805
count = 782
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 68.992607/804, current 69.000931/805: elapsed=8324.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.000931
last_received_ts = 69.000687
last_seq = 805
current_ts = 69.009247
current_received_ts = 69.009094
current_seq = 806
count = 783
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.000931/805, current 69.009247/806: elapsed=8317.0us expected=8298.8us +- 41.5us, error 0.2%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.009247
last_received_ts = 69.009094
last_seq = 806
current_ts = 69.017570
current_received_ts = 69.017326
current_seq = 807
count = 784
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.009247/806, current 69.017570/807: elapsed=8326.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.017570
last_received_ts = 69.017326
last_seq = 807
current_ts = 69.025894
current_received_ts = 69.025620
current_seq = 808
count = 785
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.017570/807, current 69.025894/808: elapsed=8320.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.025894
last_received_ts = 69.025620
last_seq = 808
current_ts = 69.034218
current_received_ts = 69.033913
current_seq = 809
count = 786
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.025894/808, current 69.034218/809: elapsed=8321.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.034218
last_received_ts = 69.033913
last_seq = 809
current_ts = 69.042534
current_received_ts = 69.042191
current_seq = 810
count = 787
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.034218/809, current 69.042534/810: elapsed=8318.0us expected=8298.8us +- 41.5us, error 0.2%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.042534
last_received_ts = 69.042191
last_seq = 810
current_ts = 69.050850
current_received_ts = 69.050461
current_seq = 811
count = 788
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.042534/810, current 69.050850/811: elapsed=8317.0us expected=8298.8us +- 41.5us, error 0.2%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.050850
last_received_ts = 69.050461
last_seq = 811
current_ts = 69.059174
current_received_ts = 69.058762
current_seq = 812
count = 789
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.050850/811, current 69.059174/812: elapsed=8325.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.059174
last_received_ts = 69.058762
last_seq = 812
current_ts = 69.067490
current_received_ts = 69.067101
current_seq = 813
count = 790
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.059174/812, current 69.067490/813: elapsed=8316.0us expected=8298.8us +- 41.5us, error 0.2%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.067490
last_received_ts = 69.067101
last_seq = 813
current_ts = 69.075813
current_received_ts = 69.075424
current_seq = 814
count = 791
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.067490/813, current 69.075813/814: elapsed=8326.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.075813
last_received_ts = 69.075424
last_seq = 814
current_ts = 69.084137
current_received_ts = 69.083748
current_seq = 815
count = 792
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.075813/814, current 69.084137/815: elapsed=8320.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.084137
last_received_ts = 69.083748
last_seq = 815
current_ts = 69.092461
current_received_ts = 69.092064
current_seq = 816
count = 793
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.084137/815, current 69.092461/816: elapsed=8320.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.092461
last_received_ts = 69.092064
last_seq = 816
current_ts = 69.100777
current_received_ts = 69.100357
current_seq = 817
count = 794
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.092461/816, current 69.100777/817: elapsed=8322.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.100777
last_received_ts = 69.100357
last_seq = 817
current_ts = 69.109100
current_received_ts = 69.108696
current_seq = 818
count = 795
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.100777/817, current 69.109100/818: elapsed=8319.0us expected=8298.8us +- 41.5us, error 0.2%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.109100
last_received_ts = 69.108696
last_seq = 818
current_ts = 69.117416
current_received_ts = 69.117027
current_seq = 819
count = 796
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.109100/818, current 69.117416/819: elapsed=8321.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.117416
last_received_ts = 69.117027
last_seq = 819
current_ts = 69.125740
current_received_ts = 69.125336
current_seq = 820
count = 797
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.117416/819, current 69.125740/820: elapsed=8320.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.125740
last_received_ts = 69.125336
last_seq = 820
current_ts = 69.134056
current_received_ts = 69.133652
current_seq = 821
count = 798
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.125740/820, current 69.134056/821: elapsed=8316.0us expected=8298.8us +- 41.5us, error 0.2%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.134056
last_received_ts = 69.133652
last_seq = 821
current_ts = 69.142380
current_received_ts = 69.141975
current_seq = 822
count = 799
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.134056/821, current 69.142380/822: elapsed=8321.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.142380
last_received_ts = 69.141975
last_seq = 822
current_ts = 69.150696
current_received_ts = 69.150307
current_seq = 823
count = 800
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.142380/822, current 69.150696/823: elapsed=8319.0us expected=8298.8us +- 41.5us, error 0.2%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.150696
last_received_ts = 69.150307
last_seq = 823
current_ts = 69.159019
current_received_ts = 69.158630
current_seq = 824
count = 801
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.150696/823, current 69.159019/824: elapsed=8322.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.159019
last_received_ts = 69.158630
last_seq = 824
current_ts = 69.167336
current_received_ts = 69.166939
current_seq = 825
count = 802
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.159019/824, current 69.167336/825: elapsed=8320.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.167336
last_received_ts = 69.166939
last_seq = 825
current_ts = 69.175659
current_received_ts = 69.175262
current_seq = 826
count = 803
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.167336/825, current 69.175659/826: elapsed=8320.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.175659
last_received_ts = 69.175262
last_seq = 826
current_ts = 69.183975
current_received_ts = 69.183586
current_seq = 827
count = 804
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.175659/826, current 69.183975/827: elapsed=8321.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.183975
last_received_ts = 69.183586
last_seq = 827
current_ts = 69.192299
current_received_ts = 69.191917
current_seq = 828
count = 805
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.183975/827, current 69.192299/828: elapsed=8321.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.192299
last_received_ts = 69.191917
last_seq = 828
current_ts = 69.200615
current_received_ts = 69.200218
current_seq = 829
count = 806
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.192299/828, current 69.200615/829: elapsed=8319.0us expected=8298.8us +- 41.5us, error 0.2%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.200615
last_received_ts = 69.200218
last_seq = 829
current_ts = 69.208939
current_received_ts = 69.208542
current_seq = 830
count = 807
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.200615/829, current 69.208939/830: elapsed=8321.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.208939
last_received_ts = 69.208542
last_seq = 830
current_ts = 69.217262
current_received_ts = 69.216866
current_seq = 831
count = 808
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.208939/830, current 69.217262/831: elapsed=8322.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.217262
last_received_ts = 69.216866
last_seq = 831
current_ts = 69.225578
current_received_ts = 69.225204
current_seq = 832
count = 809
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.217262/831, current 69.225578/832: elapsed=8321.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.225578
last_received_ts = 69.225204
last_seq = 832
current_ts = 69.233902
current_received_ts = 69.233521
current_seq = 833
count = 810
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.225578/832, current 69.233902/833: elapsed=8319.0us expected=8298.8us +- 41.5us, error 0.2%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.233902
last_received_ts = 69.233521
last_seq = 833
current_ts = 69.242218
current_received_ts = 69.241829
current_seq = 834
count = 811
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.233902/833, current 69.242218/834: elapsed=8320.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.242218
last_received_ts = 69.241829
last_seq = 834
current_ts = 69.250542
current_received_ts = 69.250137
current_seq = 835
count = 812
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.242218/834, current 69.250542/835: elapsed=8320.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.250542
last_received_ts = 69.250137
last_seq = 835
current_ts = 69.258858
current_received_ts = 69.258453
current_seq = 836
count = 813
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.250542/835, current 69.258858/836: elapsed=8320.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.258858
last_received_ts = 69.258453
last_seq = 836
current_ts = 69.267181
current_received_ts = 69.266884
current_seq = 837
count = 814
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.258858/836, current 69.267181/837: elapsed=8324.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.267181
last_received_ts = 69.266884
last_seq = 837
current_ts = 69.275505
current_received_ts = 69.275162
current_seq = 838
count = 815
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.267181/837, current 69.275505/838: elapsed=8320.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.275505
last_received_ts = 69.275162
last_seq = 838
current_ts = 69.283821
current_received_ts = 69.283470
current_seq = 839
count = 816
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.275505/838, current 69.283821/839: elapsed=8319.0us expected=8298.8us +- 41.5us, error 0.2%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.283821
last_received_ts = 69.283470
last_seq = 839
current_ts = 69.292145
current_received_ts = 69.291939
current_seq = 840
count = 817
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.283821/839, current 69.292145/840: elapsed=8321.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.292145
last_received_ts = 69.291939
last_seq = 840
current_ts = 69.300468
current_received_ts = 69.300194
current_seq = 841
count = 818
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.292145/840, current 69.300468/841: elapsed=8324.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.300468
last_received_ts = 69.300194
last_seq = 841
current_ts = 69.308784
current_received_ts = 69.308434
current_seq = 842
count = 819
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.300468/841, current 69.308784/842: elapsed=8317.0us expected=8298.8us +- 41.5us, error 0.2%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.308784
last_received_ts = 69.308434
last_seq = 842
current_ts = 69.317108
current_received_ts = 69.316811
current_seq = 843
count = 820
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.308784/842, current 69.317108/843: elapsed=8324.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.317108
last_received_ts = 69.316811
last_seq = 843
current_ts = 69.325424
current_received_ts = 69.325119
current_seq = 844
count = 821
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.317108/843, current 69.325424/844: elapsed=8315.0us expected=8298.8us +- 41.5us, error 0.2%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.325424
last_received_ts = 69.325119
last_seq = 844
current_ts = 69.333748
current_received_ts = 69.333397
current_seq = 845
count = 822
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.325424/844, current 69.333748/845: elapsed=8323.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.333748
last_received_ts = 69.333397
last_seq = 845
current_ts = 69.342064
current_received_ts = 69.341728
current_seq = 846
count = 823
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.333748/845, current 69.342064/846: elapsed=8318.0us expected=8298.8us +- 41.5us, error 0.2%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.342064
last_received_ts = 69.341728
last_seq = 846
current_ts = 69.350388
current_received_ts = 69.350075
current_seq = 847
count = 824
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.342064/846, current 69.350388/847: elapsed=8322.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.350388
last_received_ts = 69.350075
last_seq = 847
current_ts = 69.358704
current_received_ts = 69.358383
current_seq = 848
count = 825
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.350388/847, current 69.358704/848: elapsed=8318.0us expected=8298.8us +- 41.5us, error 0.2%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.358704
last_received_ts = 69.358383
last_seq = 848
current_ts = 69.367027
current_received_ts = 69.366684
current_seq = 849
count = 826
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.358704/848, current 69.367027/849: elapsed=8324.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.367027
last_received_ts = 69.366684
last_seq = 849
current_ts = 69.375351
current_received_ts = 69.375015
current_seq = 850
count = 827
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.367027/849, current 69.375351/850: elapsed=8320.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.375351
last_received_ts = 69.375015
last_seq = 850
current_ts = 69.383675
current_received_ts = 69.383369
current_seq = 851
count = 828
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.375351/850, current 69.383675/851: elapsed=8321.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.383675
last_received_ts = 69.383369
last_seq = 851
current_ts = 69.391991
current_received_ts = 69.391670
current_seq = 852
count = 829
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.383675/851, current 69.391991/852: elapsed=8319.0us expected=8298.8us +- 41.5us, error 0.2%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.391991
last_received_ts = 69.391670
last_seq = 852
current_ts = 69.400314
current_received_ts = 69.400108
current_seq = 853
count = 830
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.391991/852, current 69.400314/853: elapsed=8323.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.400314
last_received_ts = 69.400108
last_seq = 853
current_ts = 69.408630
current_received_ts = 69.408272
current_seq = 854
count = 831
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.400314/853, current 69.408630/854: elapsed=8319.0us expected=8298.8us +- 41.5us, error 0.2%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.408630
last_received_ts = 69.408272
last_seq = 854
current_ts = 69.416954
current_received_ts = 69.416656
current_seq = 855
count = 832
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.408630/854, current 69.416954/855: elapsed=8323.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.416954
last_received_ts = 69.416656
last_seq = 855
current_ts = 69.425278
current_received_ts = 69.425072
current_seq = 856
count = 833
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.416954/855, current 69.425278/856: elapsed=8321.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.425278
last_received_ts = 69.425072
last_seq = 856
current_ts = 69.433594
current_received_ts = 69.433235
current_seq = 857
count = 834
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.425278/856, current 69.433594/857: elapsed=8318.0us expected=8298.8us +- 41.5us, error 0.2%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.433594
last_received_ts = 69.433235
last_seq = 857
current_ts = 69.441917
current_received_ts = 69.441566
current_seq = 858
count = 835
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.433594/857, current 69.441917/858: elapsed=8320.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.441917
last_received_ts = 69.441566
last_seq = 858
current_ts = 69.450233
current_received_ts = 69.449844
current_seq = 859
count = 836
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.441917/858, current 69.450233/859: elapsed=8321.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.450233
last_received_ts = 69.449844
last_seq = 859
current_ts = 69.458557
current_received_ts = 69.458244
current_seq = 860
count = 837
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.450233/859, current 69.458557/860: elapsed=8321.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.458557
last_received_ts = 69.458244
last_seq = 860
current_ts = 69.466881
current_received_ts = 69.466560
current_seq = 861
count = 838
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.458557/860, current 69.466881/861: elapsed=8321.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.466881
last_received_ts = 69.466560
last_seq = 861
current_ts = 69.475197
current_received_ts = 69.474998
current_seq = 862
count = 839
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.466881/861, current 69.475197/862: elapsed=8321.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.475197
last_received_ts = 69.474998
last_seq = 862
current_ts = 69.483513
current_received_ts = 69.483215
current_seq = 863
count = 840
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.475197/862, current 69.483513/863: elapsed=8316.0us expected=8298.8us +- 41.5us, error 0.2%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.483513
last_received_ts = 69.483215
last_seq = 863
current_ts = 69.491837
current_received_ts = 69.491493
current_seq = 864
count = 841
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.483513/863, current 69.491837/864: elapsed=8323.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.491837
last_received_ts = 69.491493
last_seq = 864
current_ts = 69.500160
current_received_ts = 69.499908
current_seq = 865
count = 842
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.491837/864, current 69.500160/865: elapsed=8321.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.500160
last_received_ts = 69.499908
last_seq = 865
current_ts = 69.508476
current_received_ts = 69.508186
current_seq = 866
count = 843
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.500160/865, current 69.508476/866: elapsed=8320.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.508476
last_received_ts = 69.508186
last_seq = 866
current_ts = 69.516800
current_received_ts = 69.516449
current_seq = 867
count = 844
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.508476/866, current 69.516800/867: elapsed=8320.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.516800
last_received_ts = 69.516449
last_seq = 867
current_ts = 69.525116
current_received_ts = 69.524780
current_seq = 868
count = 845
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.516800/867, current 69.525116/868: elapsed=8319.0us expected=8298.8us +- 41.5us, error 0.2%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.525116
last_received_ts = 69.524780
last_seq = 868
current_ts = 69.533440
current_received_ts = 69.533203
current_seq = 869
count = 846
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.525116/868, current 69.533440/869: elapsed=8320.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.533440
last_received_ts = 69.533203
last_seq = 869
current_ts = 69.541763
current_received_ts = 69.541405
current_seq = 870
count = 847
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.533440/869, current 69.541763/870: elapsed=8323.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.541763
last_received_ts = 69.541405
last_seq = 870
current_ts = 69.550079
current_received_ts = 69.549721
current_seq = 871
count = 848
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.541763/870, current 69.550079/871: elapsed=8320.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.550079
last_received_ts = 69.549721
last_seq = 871
current_ts = 69.558403
current_received_ts = 69.558060
current_seq = 872
count = 849
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.550079/871, current 69.558403/872: elapsed=8321.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.558403
last_received_ts = 69.558060
last_seq = 872
current_ts = 69.566727
current_received_ts = 69.566414
current_seq = 873
count = 850
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.558403/872, current 69.566727/873: elapsed=8323.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.566727
last_received_ts = 69.566414
last_seq = 873
current_ts = 69.575043
current_received_ts = 69.574692
current_seq = 874
count = 851
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.566727/873, current 69.575043/874: elapsed=8318.0us expected=8298.8us +- 41.5us, error 0.2%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.575043
last_received_ts = 69.574692
last_seq = 874
current_ts = 69.583359
current_received_ts = 69.583023
current_seq = 875
count = 852
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.575043/874, current 69.583359/875: elapsed=8320.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.583359
last_received_ts = 69.583023
last_seq = 875
current_ts = 69.591682
current_received_ts = 69.591324
current_seq = 876
count = 853
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.583359/875, current 69.591682/876: elapsed=8323.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.591682
last_received_ts = 69.591324
last_seq = 876
current_ts = 69.599998
current_received_ts = 69.599693
current_seq = 877
count = 854
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.591682/876, current 69.599998/877: elapsed=8316.0us expected=8298.8us +- 41.5us, error 0.2%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.599998
last_received_ts = 69.599693
last_seq = 877
current_ts = 69.608322
current_received_ts = 69.608025
current_seq = 878
count = 855
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.599998/877, current 69.608322/878: elapsed=8323.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.608322
last_received_ts = 69.608025
last_seq = 878
current_ts = 69.616646
current_received_ts = 69.616333
current_seq = 879
count = 856
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.608322/878, current 69.616646/879: elapsed=8323.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.616646
last_received_ts = 69.616333
last_seq = 879
current_ts = 69.624969
current_received_ts = 69.624680
current_seq = 880
count = 857
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.616646/879, current 69.624969/880: elapsed=8319.0us expected=8298.8us +- 41.5us, error 0.2%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.624969
last_received_ts = 69.624680
last_seq = 880
current_ts = 69.633286
current_received_ts = 69.633141
current_seq = 881
count = 858
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.624969/880, current 69.633286/881: elapsed=8318.0us expected=8298.8us +- 41.5us, error 0.2%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.633286
last_received_ts = 69.633141
last_seq = 881
current_ts = 69.641602
current_received_ts = 69.641312
current_seq = 882
count = 859
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.633286/881, current 69.641602/882: elapsed=8321.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.641602
last_received_ts = 69.641312
last_seq = 882
current_ts = 69.649925
current_received_ts = 69.649605
current_seq = 883
count = 860
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.641602/882, current 69.649925/883: elapsed=8320.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.649925
last_received_ts = 69.649605
last_seq = 883
current_ts = 69.658249
current_received_ts = 69.657898
current_seq = 884
count = 861
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.649925/883, current 69.658249/884: elapsed=8321.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.658249
last_received_ts = 69.657898
last_seq = 884
current_ts = 69.666565
current_received_ts = 69.666222
current_seq = 885
count = 862
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.658249/884, current 69.666565/885: elapsed=8318.0us expected=8298.8us +- 41.5us, error 0.2%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.666565
last_received_ts = 69.666222
last_seq = 885
current_ts = 69.674889
current_received_ts = 69.674583
current_seq = 886
count = 863
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.666565/885, current 69.674889/886: elapsed=8323.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.674889
last_received_ts = 69.674583
last_seq = 886
current_ts = 69.683212
current_received_ts = 69.683022
current_seq = 887
count = 864
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.674889/886, current 69.683212/887: elapsed=8322.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.683212
last_received_ts = 69.683022
last_seq = 887
current_ts = 69.691528
current_received_ts = 69.691231
current_seq = 888
count = 865
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.683212/887, current 69.691528/888: elapsed=8322.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.691528
last_received_ts = 69.691231
last_seq = 888
current_ts = 69.699852
current_received_ts = 69.699501
current_seq = 889
count = 866
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.691528/888, current 69.699852/889: elapsed=8318.0us expected=8298.8us +- 41.5us, error 0.2%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.699852
last_received_ts = 69.699501
last_seq = 889
current_ts = 69.708176
current_received_ts = 69.707962
current_seq = 890
count = 867
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.699852/889, current 69.708176/890: elapsed=8323.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.708176
last_received_ts = 69.707962
last_seq = 890
current_ts = 69.716492
current_received_ts = 69.716217
current_seq = 891
count = 868
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.708176/890, current 69.716492/891: elapsed=8318.0us expected=8298.8us +- 41.5us, error 0.2%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.716492
last_received_ts = 69.716217
last_seq = 891
current_ts = 69.724815
current_received_ts = 69.724541
current_seq = 892
count = 869
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.716492/891, current 69.724815/892: elapsed=8322.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.724815
last_received_ts = 69.724541
last_seq = 892
current_ts = 69.733131
current_received_ts = 69.732849
current_seq = 893
count = 870
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.724815/892, current 69.733131/893: elapsed=8321.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.733131
last_received_ts = 69.732849
last_seq = 893
current_ts = 69.741447
current_received_ts = 69.741112
current_seq = 894
count = 871
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.733131/893, current 69.741447/894: elapsed=8316.0us expected=8298.8us +- 41.5us, error 0.2%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.741447
last_received_ts = 69.741112
last_seq = 894
current_ts = 69.749771
current_received_ts = 69.749428
current_seq = 895
count = 872
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.741447/894, current 69.749771/895: elapsed=8322.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.749771
last_received_ts = 69.749428
last_seq = 895
current_ts = 69.758095
current_received_ts = 69.757744
current_seq = 896
count = 873
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.749771/895, current 69.758095/896: elapsed=8321.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.758095
last_received_ts = 69.757744
last_seq = 896
current_ts = 69.766411
current_received_ts = 69.766121
current_seq = 897
count = 874
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.758095/896, current 69.766411/897: elapsed=8318.0us expected=8298.8us +- 41.5us, error 0.2%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.766411
last_received_ts = 69.766121
last_seq = 897
current_ts = 69.774734
current_received_ts = 69.774384
current_seq = 898
count = 875
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.766411/897, current 69.774734/898: elapsed=8323.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.774734
last_received_ts = 69.774384
last_seq = 898
current_ts = 69.783051
current_received_ts = 69.782753
current_seq = 899
count = 876
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.774734/898, current 69.783051/899: elapsed=8319.0us expected=8298.8us +- 41.5us, error 0.2%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.783051
last_received_ts = 69.782753
last_seq = 899
current_ts = 69.791374
current_received_ts = 69.791046
current_seq = 900
count = 877
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.783051/899, current 69.791374/900: elapsed=8321.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.791374
last_received_ts = 69.791046
last_seq = 900
current_ts = 69.799698
current_received_ts = 69.799408
current_seq = 901
count = 878
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.791374/900, current 69.799698/901: elapsed=8322.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.799698
last_received_ts = 69.799408
last_seq = 901
current_ts = 69.808014
current_received_ts = 69.807709
current_seq = 902
count = 879
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.799698/901, current 69.808014/902: elapsed=8317.0us expected=8298.8us +- 41.5us, error 0.2%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.808014
last_received_ts = 69.807709
last_seq = 902
current_ts = 69.816338
current_received_ts = 69.816124
current_seq = 903
count = 880
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.808014/902, current 69.816338/903: elapsed=8326.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.816338
last_received_ts = 69.816124
last_seq = 903
current_ts = 69.824654
current_received_ts = 69.824303
current_seq = 904
count = 881
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.816338/903, current 69.824654/904: elapsed=8317.0us expected=8298.8us +- 41.5us, error 0.2%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.824654
last_received_ts = 69.824303
last_seq = 904
current_ts = 69.832977
current_received_ts = 69.832626
current_seq = 905
count = 882
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.824654/904, current 69.832977/905: elapsed=8321.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.832977
last_received_ts = 69.832626
last_seq = 905
current_ts = 69.841301
current_received_ts = 69.841072
current_seq = 906
count = 883
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.832977/905, current 69.841301/906: elapsed=8323.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.841301
last_received_ts = 69.841072
last_seq = 906
current_ts = 69.849617
current_received_ts = 69.849319
current_seq = 907
count = 884
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.841301/906, current 69.849617/907: elapsed=8320.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.849617
last_received_ts = 69.849319
last_seq = 907
current_ts = 69.857933
current_received_ts = 69.857658
current_seq = 908
count = 885
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.849617/907, current 69.857933/908: elapsed=8317.0us expected=8298.8us +- 41.5us, error 0.2%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.857933
last_received_ts = 69.857658
last_seq = 908
current_ts = 69.866257
current_received_ts = 69.866089
current_seq = 909
count = 886
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.857933/908, current 69.866257/909: elapsed=8324.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.866257
last_received_ts = 69.866089
last_seq = 909
current_ts = 69.874573
current_received_ts = 69.874298
current_seq = 910
count = 887
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.866257/909, current 69.874573/910: elapsed=8315.0us expected=8298.8us +- 41.5us, error 0.2%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.874573
last_received_ts = 69.874298
last_seq = 910
current_ts = 69.882896
current_received_ts = 69.882545
current_seq = 911
count = 888
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.874573/910, current 69.882896/911: elapsed=8323.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.882896
last_received_ts = 69.882545
last_seq = 911
current_ts = 69.891220
current_received_ts = 69.891022
current_seq = 912
count = 889
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.882896/911, current 69.891220/912: elapsed=8321.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.891220
last_received_ts = 69.891022
last_seq = 912
current_ts = 69.899544
current_received_ts = 69.899200
current_seq = 913
count = 890
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.891220/912, current 69.899544/913: elapsed=8322.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.899544
last_received_ts = 69.899200
last_seq = 913
current_ts = 69.907860
current_received_ts = 69.907555
current_seq = 914
count = 891
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.899544/913, current 69.907860/914: elapsed=8318.0us expected=8298.8us +- 41.5us, error 0.2%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.907860
last_received_ts = 69.907555
last_seq = 914
current_ts = 69.916183
current_received_ts = 69.915932
current_seq = 915
count = 892
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.907860/914, current 69.916183/915: elapsed=8323.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.916183
last_received_ts = 69.915932
last_seq = 915
current_ts = 69.924500
current_received_ts = 69.924217
current_seq = 916
count = 893
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.916183/915, current 69.924500/916: elapsed=8319.0us expected=8298.8us +- 41.5us, error 0.2%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.924500
last_received_ts = 69.924217
last_seq = 916
current_ts = 69.932823
current_received_ts = 69.932510
current_seq = 917
count = 894
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.924500/916, current 69.932823/917: elapsed=8323.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.932823
last_received_ts = 69.932510
last_seq = 917
current_ts = 69.941139
current_received_ts = 69.940834
current_seq = 918
count = 895
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.932823/917, current 69.941139/918: elapsed=8315.0us expected=8298.8us +- 41.5us, error 0.2%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.941139
last_received_ts = 69.940834
last_seq = 918
current_ts = 69.949463
current_received_ts = 69.949158
current_seq = 919
count = 896
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.941139/918, current 69.949463/919: elapsed=8324.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.949463
last_received_ts = 69.949158
last_seq = 919
current_ts = 69.957779
current_received_ts = 69.957436
current_seq = 920
count = 897
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.949463/919, current 69.957779/920: elapsed=8318.0us expected=8298.8us +- 41.5us, error 0.2%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.957779
last_received_ts = 69.957436
last_seq = 920
current_ts = 69.966103
current_received_ts = 69.965797
current_seq = 921
count = 898
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.957779/920, current 69.966103/921: elapsed=8321.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.966103
last_received_ts = 69.965797
last_seq = 921
current_ts = 69.974426
current_received_ts = 69.974113
current_seq = 922
count = 899
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.966103/921, current 69.974426/922: elapsed=8321.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.974426
last_received_ts = 69.974113
last_seq = 922
current_ts = 69.982742
current_received_ts = 69.982399
current_seq = 923
count = 900
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.974426/922, current 69.982742/923: elapsed=8322.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.982742
last_received_ts = 69.982399
last_seq = 923
current_ts = 69.991066
current_received_ts = 69.990753
current_seq = 924
count = 901
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.982742/923, current 69.991066/924: elapsed=8318.0us expected=8298.8us +- 41.5us, error 0.2%
(kms_flip:2017) DEBUG: name = flip
last_ts = 69.991066
last_received_ts = 69.990753
last_seq = 924
current_ts = 69.999390
current_received_ts = 69.999054
current_seq = 925
count = 902
seq_step = 1
(kms_flip:2017) DEBUG: flip ts/seq: last 69.991066/924, current 69.999390/925: elapsed=8324.0us expected=8298.8us +- 41.5us, error 0.3%
(kms_flip:2017) DEBUG: expected 904, counted 903, encoder type 2
(kms_flip:2017) DEBUG: dropped frames, expected 904, counted 903, encoder type 2
(kms_flip:2017) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:2017) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:2017) igt_core-INFO: Stack trace:
(kms_flip:2017) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:2017) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:2017) igt_core-INFO:   #2 ../tests/kms_flip.c:1845 run_test()
(kms_flip:2017) igt_core-INFO:   #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
(kms_flip:2017) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:2017) igt_core-INFO:   #5 ../sysdeps/nptl/libc_start_call_main.h:74 __libc_start_call_main()
(kms_flip:2017) igt_core-INFO:   #6 ../csu/libc-start.c:128 __libc_start_main@@GLIBC_2.34()
(kms_flip:2017) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest D-HDMI-A1: FAIL (10.969s)
Subtest plain-flip-ts-check: FAIL (27.388s)
(kms_flip:2017) igt_kms-CRITICAL: Test assertion failure function kmstest_set_connector_dpms, file ../lib/igt_kms.c:2246:
(kms_flip:2017) igt_kms-CRITICAL: Failed assertion: found_it
(kms_flip:2017) igt_kms-CRITICAL: Last errno: 9, Bad file descriptor
(kms_flip:2017) igt_kms-CRITICAL: DPMS property not found on 313