Results for igt@kms_flip@plain-flip-fb-recreate

shard-adlp-9

IGT-Version: 1.30-gee442ca97 (x86_64) (Linux: 6.14.0-rc5-xe+ x86_64)

Using IGT_SRANDOM=1741108275 for randomisation
Opened device: /dev/dri/card0
Using monotonic timestamps
Starting subtest: plain-flip-fb-recreate
Starting dynamic subtest: A-HDMI-A1
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16666.9us +- 6.424us accuracy 0.12%
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 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest A-HDMI-A1: FAIL (9.701s)
Starting dynamic subtest: B-HDMI-A1
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16302.6us +- 7.117us accuracy 0.13%
vblank interval differs from modeline! expected 16666.7us, measured 16303us +- 7.117us, difference 364.0us (51.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 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest B-HDMI-A1: FAIL (4.900s)
Starting dynamic subtest: C-HDMI-A1
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16475.7us +- 6.364us accuracy 0.12%
vblank interval differs from modeline! expected 16666.7us, measured 16476us +- 6.364us, difference 191.0us (30.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 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest C-HDMI-A1: FAIL (7.233s)
Starting dynamic subtest: D-HDMI-A1
  1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 16667us; measured 16586.8us +- 6.431us accuracy 0.12%
vblank interval differs from modeline! expected 16666.7us, measured 16587us +- 6.431us, difference 79.9us (12.4 sigma)
Dynamic subtest D-HDMI-A1: SUCCESS (7.962s)
Subtest plain-flip-fb-recreate: FAIL (30.013s)

Starting subtest: plain-flip-fb-recreate
Starting dynamic subtest: A-HDMI-A1
(kms_flip:5601) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:5601) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest A-HDMI-A1 failed.
**** DEBUG ****
(kms_flip:5601) DEBUG: flip ts/seq: last 386.598572/1040, current 386.615265/1041: elapsed=16677.0us expected=16666.9us +- 83.3us, error 0.1%
(kms_flip:5601) DEBUG: name = flip
last_ts = 386.615265
last_received_ts = 386.614960
last_seq = 1041
current_ts = 386.631927
current_received_ts = 386.631561
current_seq = 1042
count = 239
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 386.615265/1041, current 386.631927/1042: elapsed=16670.0us expected=16666.9us +- 83.3us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 386.631927
last_received_ts = 386.631561
last_seq = 1042
current_ts = 386.648590
current_received_ts = 386.648254
current_seq = 1043
count = 240
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 386.631927/1042, current 386.648590/1043: elapsed=16655.0us expected=16666.9us +- 83.3us, error 0.1%
(kms_flip:5601) DEBUG: name = flip
last_ts = 386.648590
last_received_ts = 386.648254
last_seq = 1043
current_ts = 386.665253
current_received_ts = 386.664948
current_seq = 1044
count = 241
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 386.648590/1043, current 386.665253/1044: elapsed=16668.0us expected=16666.9us +- 83.3us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 386.665253
last_received_ts = 386.664948
last_seq = 1044
current_ts = 386.681915
current_received_ts = 386.681488
current_seq = 1045
count = 242
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 386.665253/1044, current 386.681915/1045: elapsed=16676.0us expected=16666.9us +- 83.3us, error 0.1%
(kms_flip:5601) DEBUG: name = flip
last_ts = 386.681915
last_received_ts = 386.681488
last_seq = 1045
current_ts = 386.698578
current_received_ts = 386.698334
current_seq = 1046
count = 243
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 386.681915/1045, current 386.698578/1046: elapsed=16660.0us expected=16666.9us +- 83.3us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 386.698578
last_received_ts = 386.698334
last_seq = 1046
current_ts = 386.715240
current_received_ts = 386.714905
current_seq = 1047
count = 244
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 386.698578/1046, current 386.715240/1047: elapsed=16665.0us expected=16666.9us +- 83.3us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 386.715240
last_received_ts = 386.714905
last_seq = 1047
current_ts = 386.731934
current_received_ts = 386.731537
current_seq = 1048
count = 245
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 386.715240/1047, current 386.731934/1048: elapsed=16677.0us expected=16666.9us +- 83.3us, error 0.1%
(kms_flip:5601) DEBUG: name = flip
last_ts = 386.731934
last_received_ts = 386.731537
last_seq = 1048
current_ts = 386.748596
current_received_ts = 386.748260
current_seq = 1049
count = 246
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 386.731934/1048, current 386.748596/1049: elapsed=16662.0us expected=16666.9us +- 83.3us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 386.748596
last_received_ts = 386.748260
last_seq = 1049
current_ts = 386.765259
current_received_ts = 386.764954
current_seq = 1050
count = 247
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 386.748596/1049, current 386.765259/1050: elapsed=16676.0us expected=16666.9us +- 83.3us, error 0.1%
(kms_flip:5601) DEBUG: name = flip
last_ts = 386.765259
last_received_ts = 386.764954
last_seq = 1050
current_ts = 386.781921
current_received_ts = 386.781525
current_seq = 1051
count = 248
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 386.765259/1050, current 386.781921/1051: elapsed=16655.0us expected=16666.9us +- 83.3us, error 0.1%
(kms_flip:5601) DEBUG: name = flip
last_ts = 386.781921
last_received_ts = 386.781525
last_seq = 1051
current_ts = 386.798584
current_received_ts = 386.798340
current_seq = 1052
count = 249
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 386.781921/1051, current 386.798584/1052: elapsed=16677.0us expected=16666.9us +- 83.3us, error 0.1%
(kms_flip:5601) DEBUG: name = flip
last_ts = 386.798584
last_received_ts = 386.798340
last_seq = 1052
current_ts = 386.815247
current_received_ts = 386.814880
current_seq = 1053
count = 250
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 386.798584/1052, current 386.815247/1053: elapsed=16657.0us expected=16666.9us +- 83.3us, error 0.1%
(kms_flip:5601) DEBUG: name = flip
last_ts = 386.815247
last_received_ts = 386.814880
last_seq = 1053
current_ts = 386.831909
current_received_ts = 386.831482
current_seq = 1054
count = 251
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 386.815247/1053, current 386.831909/1054: elapsed=16670.0us expected=16666.9us +- 83.3us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 386.831909
last_received_ts = 386.831482
last_seq = 1054
current_ts = 386.848602
current_received_ts = 386.848389
current_seq = 1055
count = 252
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 386.831909/1054, current 386.848602/1055: elapsed=16673.0us expected=16666.9us +- 83.3us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 386.848602
last_received_ts = 386.848389
last_seq = 1055
current_ts = 386.865265
current_received_ts = 386.864960
current_seq = 1056
count = 253
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 386.848602/1055, current 386.865265/1056: elapsed=16660.0us expected=16666.9us +- 83.3us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 386.865265
last_received_ts = 386.864960
last_seq = 1056
current_ts = 386.881927
current_received_ts = 386.881561
current_seq = 1057
count = 254
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 386.865265/1056, current 386.881927/1057: elapsed=16672.0us expected=16666.9us +- 83.3us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 386.881927
last_received_ts = 386.881561
last_seq = 1057
current_ts = 386.898590
current_received_ts = 386.898254
current_seq = 1058
count = 255
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 386.881927/1057, current 386.898590/1058: elapsed=16673.0us expected=16666.9us +- 83.3us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 386.898590
last_received_ts = 386.898254
last_seq = 1058
current_ts = 386.915253
current_received_ts = 386.914978
current_seq = 1059
count = 256
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 386.898590/1058, current 386.915253/1059: elapsed=16657.0us expected=16666.9us +- 83.3us, error 0.1%
(kms_flip:5601) DEBUG: name = flip
last_ts = 386.915253
last_received_ts = 386.914978
last_seq = 1059
current_ts = 386.931915
current_received_ts = 386.931488
current_seq = 1060
count = 257
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 386.915253/1059, current 386.931915/1060: elapsed=16669.0us expected=16666.9us +- 83.3us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 386.931915
last_received_ts = 386.931488
last_seq = 1060
current_ts = 386.948608
current_received_ts = 386.948242
current_seq = 1061
count = 258
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 386.931915/1060, current 386.948608/1061: elapsed=16672.0us expected=16666.9us +- 83.3us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 386.948608
last_received_ts = 386.948242
last_seq = 1061
current_ts = 386.965271
current_received_ts = 386.964966
current_seq = 1062
count = 259
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 386.948608/1061, current 386.965271/1062: elapsed=16671.0us expected=16666.9us +- 83.3us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 386.965271
last_received_ts = 386.964966
last_seq = 1062
current_ts = 386.981934
current_received_ts = 386.981476
current_seq = 1063
count = 260
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 386.965271/1062, current 386.981934/1063: elapsed=16657.0us expected=16666.9us +- 83.3us, error 0.1%
(kms_flip:5601) DEBUG: name = flip
last_ts = 386.981934
last_received_ts = 386.981476
last_seq = 1063
current_ts = 386.998596
current_received_ts = 386.998383
current_seq = 1064
count = 261
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 386.981934/1063, current 386.998596/1064: elapsed=16678.0us expected=16666.9us +- 83.3us, error 0.1%
(kms_flip:5601) DEBUG: name = flip
last_ts = 386.998596
last_received_ts = 386.998383
last_seq = 1064
current_ts = 387.015259
current_received_ts = 387.014954
current_seq = 1065
count = 262
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 386.998596/1064, current 387.015259/1065: elapsed=16659.0us expected=16666.9us +- 83.3us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 387.015259
last_received_ts = 387.014954
last_seq = 1065
current_ts = 387.031921
current_received_ts = 387.031555
current_seq = 1066
count = 263
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 387.015259/1065, current 387.031921/1066: elapsed=16667.0us expected=16666.9us +- 83.3us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 387.031921
last_received_ts = 387.031555
last_seq = 1066
current_ts = 387.048584
current_received_ts = 387.048309
current_seq = 1067
count = 264
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 387.031921/1066, current 387.048584/1067: elapsed=16669.0us expected=16666.9us +- 83.3us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 387.048584
last_received_ts = 387.048309
last_seq = 1067
current_ts = 387.065247
current_received_ts = 387.064972
current_seq = 1068
count = 265
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 387.048584/1067, current 387.065247/1068: elapsed=16663.0us expected=16666.9us +- 83.3us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 387.065247
last_received_ts = 387.064972
last_seq = 1068
current_ts = 387.081940
current_received_ts = 387.081482
current_seq = 1069
count = 266
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 387.065247/1068, current 387.081940/1069: elapsed=16675.0us expected=16666.9us +- 83.3us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 387.081940
last_received_ts = 387.081482
last_seq = 1069
current_ts = 387.098602
current_received_ts = 387.098267
current_seq = 1070
count = 267
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 387.081940/1069, current 387.098602/1070: elapsed=16670.0us expected=16666.9us +- 83.3us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 387.098602
last_received_ts = 387.098267
last_seq = 1070
current_ts = 387.115265
current_received_ts = 387.114960
current_seq = 1071
count = 268
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 387.098602/1070, current 387.115265/1071: elapsed=16667.0us expected=16666.9us +- 83.3us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 387.115265
last_received_ts = 387.114960
last_seq = 1071
current_ts = 387.131927
current_received_ts = 387.131561
current_seq = 1072
count = 269
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 387.115265/1071, current 387.131927/1072: elapsed=16663.0us expected=16666.9us +- 83.3us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 387.131927
last_received_ts = 387.131561
last_seq = 1072
current_ts = 387.148590
current_received_ts = 387.148285
current_seq = 1073
count = 270
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 387.131927/1072, current 387.148590/1073: elapsed=16662.0us expected=16666.9us +- 83.3us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 387.148590
last_received_ts = 387.148285
last_seq = 1073
current_ts = 387.165283
current_received_ts = 387.164978
current_seq = 1074
count = 271
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 387.148590/1073, current 387.165283/1074: elapsed=16681.0us expected=16666.9us +- 83.3us, error 0.1%
(kms_flip:5601) DEBUG: name = flip
last_ts = 387.165283
last_received_ts = 387.164978
last_seq = 1074
current_ts = 387.181946
current_received_ts = 387.181549
current_seq = 1075
count = 272
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 387.165283/1074, current 387.181946/1075: elapsed=16660.0us expected=16666.9us +- 83.3us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 387.181946
last_received_ts = 387.181549
last_seq = 1075
current_ts = 387.198608
current_received_ts = 387.198273
current_seq = 1076
count = 273
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 387.181946/1075, current 387.198608/1076: elapsed=16674.0us expected=16666.9us +- 83.3us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 387.198608
last_received_ts = 387.198273
last_seq = 1076
current_ts = 387.215271
current_received_ts = 387.214996
current_seq = 1077
count = 274
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 387.198608/1076, current 387.215271/1077: elapsed=16655.0us expected=16666.9us +- 83.3us, error 0.1%
(kms_flip:5601) DEBUG: name = flip
last_ts = 387.215271
last_received_ts = 387.214996
last_seq = 1077
current_ts = 387.231934
current_received_ts = 387.231659
current_seq = 1078
count = 275
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 387.215271/1077, current 387.231934/1078: elapsed=16672.0us expected=16666.9us +- 83.3us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 387.231934
last_received_ts = 387.231659
last_seq = 1078
current_ts = 387.248627
current_received_ts = 387.248260
current_seq = 1079
count = 276
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 387.231934/1078, current 387.248627/1079: elapsed=16675.0us expected=16666.9us +- 83.3us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 387.248627
last_received_ts = 387.248260
last_seq = 1079
current_ts = 387.265289
current_received_ts = 387.264862
current_seq = 1080
count = 277
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 387.248627/1079, current 387.265289/1080: elapsed=16669.0us expected=16666.9us +- 83.3us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 387.265289
last_received_ts = 387.264862
last_seq = 1080
current_ts = 387.281921
current_received_ts = 387.281494
current_seq = 1081
count = 278
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 387.265289/1080, current 387.281921/1081: elapsed=16655.0us expected=16666.9us +- 83.3us, error 0.1%
(kms_flip:5601) DEBUG: name = flip
last_ts = 387.281921
last_received_ts = 387.281494
last_seq = 1081
current_ts = 387.298615
current_received_ts = 387.298248
current_seq = 1082
count = 279
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 387.281921/1081, current 387.298615/1082: elapsed=16674.0us expected=16666.9us +- 83.3us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 387.298615
last_received_ts = 387.298248
last_seq = 1082
current_ts = 387.315277
current_received_ts = 387.314972
current_seq = 1083
count = 280
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 387.298615/1082, current 387.315277/1083: elapsed=16663.0us expected=16666.9us +- 83.3us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 387.315277
last_received_ts = 387.314972
last_seq = 1083
current_ts = 387.331940
current_received_ts = 387.331635
current_seq = 1084
count = 281
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 387.315277/1083, current 387.331940/1084: elapsed=16668.0us expected=16666.9us +- 83.3us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 387.331940
last_received_ts = 387.331635
last_seq = 1084
current_ts = 387.348633
current_received_ts = 387.348389
current_seq = 1085
count = 282
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 387.331940/1084, current 387.348633/1085: elapsed=16677.0us expected=16666.9us +- 83.3us, error 0.1%
(kms_flip:5601) DEBUG: name = flip
last_ts = 387.348633
last_received_ts = 387.348389
last_seq = 1085
current_ts = 387.365265
current_received_ts = 387.364990
current_seq = 1086
count = 283
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 387.348633/1085, current 387.365265/1086: elapsed=16659.0us expected=16666.9us +- 83.3us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 387.365265
last_received_ts = 387.364990
last_seq = 1086
current_ts = 387.381927
current_received_ts = 387.381500
current_seq = 1087
count = 284
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 387.365265/1086, current 387.381927/1087: elapsed=16665.0us expected=16666.9us +- 83.3us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 387.381927
last_received_ts = 387.381500
last_seq = 1087
current_ts = 387.398621
current_received_ts = 387.398315
current_seq = 1088
count = 285
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 387.381927/1087, current 387.398621/1088: elapsed=16671.0us expected=16666.9us +- 83.3us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 387.398621
last_received_ts = 387.398315
last_seq = 1088
current_ts = 387.415283
current_received_ts = 387.414978
current_seq = 1089
count = 286
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 387.398621/1088, current 387.415283/1089: elapsed=16674.0us expected=16666.9us +- 83.3us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 387.415283
last_received_ts = 387.414978
last_seq = 1089
current_ts = 387.431946
current_received_ts = 387.431580
current_seq = 1090
count = 287
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 387.415283/1089, current 387.431946/1090: elapsed=16653.0us expected=16666.9us +- 83.3us, error 0.1%
(kms_flip:5601) DEBUG: name = flip
last_ts = 387.431946
last_received_ts = 387.431580
last_seq = 1090
current_ts = 387.448608
current_received_ts = 387.448334
current_seq = 1091
count = 288
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 387.431946/1090, current 387.448608/1091: elapsed=16677.0us expected=16666.9us +- 83.3us, error 0.1%
(kms_flip:5601) DEBUG: name = flip
last_ts = 387.448608
last_received_ts = 387.448334
last_seq = 1091
current_ts = 387.465271
current_received_ts = 387.464966
current_seq = 1092
count = 289
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 387.448608/1091, current 387.465271/1092: elapsed=16669.0us expected=16666.9us +- 83.3us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 387.465271
last_received_ts = 387.464966
last_seq = 1092
current_ts = 387.481934
current_received_ts = 387.481506
current_seq = 1093
count = 290
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 387.465271/1092, current 387.481934/1093: elapsed=16661.0us expected=16666.9us +- 83.3us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 387.481934
last_received_ts = 387.481506
last_seq = 1093
current_ts = 387.498627
current_received_ts = 387.498260
current_seq = 1094
count = 291
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 387.481934/1093, current 387.498627/1094: elapsed=16670.0us expected=16666.9us +- 83.3us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 387.498627
last_received_ts = 387.498260
last_seq = 1094
current_ts = 387.515289
current_received_ts = 387.514984
current_seq = 1095
count = 292
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 387.498627/1094, current 387.515289/1095: elapsed=16674.0us expected=16666.9us +- 83.3us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 387.515289
last_received_ts = 387.514984
last_seq = 1095
current_ts = 387.531952
current_received_ts = 387.531555
current_seq = 1096
count = 293
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 387.515289/1095, current 387.531952/1096: elapsed=16654.0us expected=16666.9us +- 83.3us, error 0.1%
(kms_flip:5601) DEBUG: name = flip
last_ts = 387.531952
last_received_ts = 387.531555
last_seq = 1096
current_ts = 387.548615
current_received_ts = 387.548370
current_seq = 1097
count = 294
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 387.531952/1096, current 387.548615/1097: elapsed=16674.0us expected=16666.9us +- 83.3us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 387.548615
last_received_ts = 387.548370
last_seq = 1097
current_ts = 387.565277
current_received_ts = 387.565002
current_seq = 1098
count = 295
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 387.548615/1097, current 387.565277/1098: elapsed=16664.0us expected=16666.9us +- 83.3us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 387.565277
last_received_ts = 387.565002
last_seq = 1098
current_ts = 387.581940
current_received_ts = 387.581512
current_seq = 1099
count = 296
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 387.565277/1098, current 387.581940/1099: elapsed=16670.0us expected=16666.9us +- 83.3us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 387.581940
last_received_ts = 387.581512
last_seq = 1099
current_ts = 387.598633
current_received_ts = 387.598328
current_seq = 1100
count = 297
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 387.581940/1099, current 387.598633/1100: elapsed=16675.0us expected=16666.9us +- 83.3us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 387.598633
last_received_ts = 387.598328
last_seq = 1100
current_ts = 387.615295
current_received_ts = 387.614960
current_seq = 1101
count = 298
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 387.598633/1100, current 387.615295/1101: elapsed=16663.0us expected=16666.9us +- 83.3us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 387.615295
last_received_ts = 387.614960
last_seq = 1101
current_ts = 387.631958
current_received_ts = 387.631561
current_seq = 1102
count = 299
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 387.615295/1101, current 387.631958/1102: elapsed=16660.0us expected=16666.9us +- 83.3us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 387.631958
last_received_ts = 387.631561
last_seq = 1102
current_ts = 387.648621
current_received_ts = 387.648285
current_seq = 1103
count = 300
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 387.631958/1102, current 387.648621/1103: elapsed=16671.0us expected=16666.9us +- 83.3us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 387.648621
last_received_ts = 387.648285
last_seq = 1103
current_ts = 387.665283
current_received_ts = 387.664917
current_seq = 1104
count = 301
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 387.648621/1103, current 387.665283/1104: elapsed=16674.0us expected=16666.9us +- 83.3us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 387.665283
last_received_ts = 387.664917
last_seq = 1104
current_ts = 387.681946
current_received_ts = 387.681488
current_seq = 1105
count = 302
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 387.665283/1104, current 387.681946/1105: elapsed=16657.0us expected=16666.9us +- 83.3us, error 0.1%
(kms_flip:5601) DEBUG: name = flip
last_ts = 387.681946
last_received_ts = 387.681488
last_seq = 1105
current_ts = 387.698639
current_received_ts = 387.698273
current_seq = 1106
count = 303
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 387.681946/1105, current 387.698639/1106: elapsed=16678.0us expected=16666.9us +- 83.3us, error 0.1%
(kms_flip:5601) DEBUG: name = flip
last_ts = 387.698639
last_received_ts = 387.698273
last_seq = 1106
current_ts = 387.715302
current_received_ts = 387.714905
current_seq = 1107
count = 304
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 387.698639/1106, current 387.715302/1107: elapsed=16657.0us expected=16666.9us +- 83.3us, error 0.1%
(kms_flip:5601) DEBUG: name = flip
last_ts = 387.715302
last_received_ts = 387.714905
last_seq = 1107
current_ts = 387.731964
current_received_ts = 387.731537
current_seq = 1108
count = 305
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 387.715302/1107, current 387.731964/1108: elapsed=16675.0us expected=16666.9us +- 83.3us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 387.731964
last_received_ts = 387.731537
last_seq = 1108
current_ts = 387.748657
current_received_ts = 387.748260
current_seq = 1109
count = 306
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 387.731964/1108, current 387.748657/1109: elapsed=16679.0us expected=16666.9us +- 83.3us, error 0.1%
(kms_flip:5601) DEBUG: name = flip
last_ts = 387.748657
last_received_ts = 387.748260
last_seq = 1109
current_ts = 387.765289
current_received_ts = 387.764984
current_seq = 1110
count = 307
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 387.748657/1109, current 387.765289/1110: elapsed=16652.0us expected=16666.9us +- 83.3us, error 0.1%
(kms_flip:5601) DEBUG: name = flip
last_ts = 387.765289
last_received_ts = 387.764984
last_seq = 1110
current_ts = 387.781952
current_received_ts = 387.781647
current_seq = 1111
count = 308
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 387.765289/1110, current 387.781952/1111: elapsed=16663.0us expected=16666.9us +- 83.3us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 387.781952
last_received_ts = 387.781647
last_seq = 1111
current_ts = 387.798645
current_received_ts = 387.798309
current_seq = 1112
count = 309
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 387.781952/1111, current 387.798645/1112: elapsed=16673.0us expected=16666.9us +- 83.3us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 387.798645
last_received_ts = 387.798309
last_seq = 1112
current_ts = 387.815308
current_received_ts = 387.815063
current_seq = 1113
count = 310
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 387.798645/1112, current 387.815308/1113: elapsed=16675.0us expected=16666.9us +- 83.3us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 387.815308
last_received_ts = 387.815063
last_seq = 1113
current_ts = 387.831970
current_received_ts = 387.831604
current_seq = 1114
count = 311
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 387.815308/1113, current 387.831970/1114: elapsed=16653.0us expected=16666.9us +- 83.3us, error 0.1%
(kms_flip:5601) DEBUG: name = flip
last_ts = 387.831970
last_received_ts = 387.831604
last_seq = 1114
current_ts = 387.848633
current_received_ts = 387.848267
current_seq = 1115
count = 312
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 387.831970/1114, current 387.848633/1115: elapsed=16682.0us expected=16666.9us +- 83.3us, error 0.1%
(kms_flip:5601) DEBUG: name = flip
last_ts = 387.848633
last_received_ts = 387.848267
last_seq = 1115
current_ts = 387.865295
current_received_ts = 387.865051
current_seq = 1116
count = 313
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 387.848633/1115, current 387.865295/1116: elapsed=16665.0us expected=16666.9us +- 83.3us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 387.865295
last_received_ts = 387.865051
last_seq = 1116
current_ts = 387.881958
current_received_ts = 387.881561
current_seq = 1117
count = 314
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 387.865295/1116, current 387.881958/1117: elapsed=16666.0us expected=16666.9us +- 83.3us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 387.881958
last_received_ts = 387.881561
last_seq = 1117
current_ts = 387.898621
current_received_ts = 387.898285
current_seq = 1118
count = 315
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 387.881958/1117, current 387.898621/1118: elapsed=16657.0us expected=16666.9us +- 83.3us, error 0.1%
(kms_flip:5601) DEBUG: name = flip
last_ts = 387.898621
last_received_ts = 387.898285
last_seq = 1118
current_ts = 387.915314
current_received_ts = 387.915039
current_seq = 1119
count = 316
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 387.898621/1118, current 387.915314/1119: elapsed=16681.0us expected=16666.9us +- 83.3us, error 0.1%
(kms_flip:5601) DEBUG: name = flip
last_ts = 387.915314
last_received_ts = 387.915039
last_seq = 1119
current_ts = 387.931976
current_received_ts = 387.931610
current_seq = 1120
count = 317
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 387.915314/1119, current 387.931976/1120: elapsed=16657.0us expected=16666.9us +- 83.3us, error 0.1%
(kms_flip:5601) DEBUG: name = flip
last_ts = 387.931976
last_received_ts = 387.931610
last_seq = 1120
current_ts = 387.948639
current_received_ts = 387.948273
current_seq = 1121
count = 318
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 387.931976/1120, current 387.948639/1121: elapsed=16669.0us expected=16666.9us +- 83.3us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 387.948639
last_received_ts = 387.948273
last_seq = 1121
current_ts = 387.965271
current_received_ts = 387.964996
current_seq = 1122
count = 319
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 387.948639/1121, current 387.965271/1122: elapsed=16649.0us expected=16666.9us +- 83.3us, error 0.1%
(kms_flip:5601) DEBUG: name = flip
last_ts = 387.965271
last_received_ts = 387.964996
last_seq = 1122
current_ts = 387.981964
current_received_ts = 387.981537
current_seq = 1123
count = 320
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 387.965271/1122, current 387.981964/1123: elapsed=16670.0us expected=16666.9us +- 83.3us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 387.981964
last_received_ts = 387.981537
last_seq = 1123
current_ts = 387.998596
current_received_ts = 387.998291
current_seq = 1124
count = 321
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 387.981964/1123, current 387.998596/1124: elapsed=16647.0us expected=16666.9us +- 83.3us, error 0.1%
(kms_flip:5601) DEBUG: name = flip
last_ts = 387.998596
last_received_ts = 387.998291
last_seq = 1124
current_ts = 388.015259
current_received_ts = 388.014984
current_seq = 1125
count = 322
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 387.998596/1124, current 388.015259/1125: elapsed=16659.0us expected=16666.9us +- 83.3us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 388.015259
last_received_ts = 388.014984
last_seq = 1125
current_ts = 388.031921
current_received_ts = 388.031525
current_seq = 1126
count = 323
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 388.015259/1125, current 388.031921/1126: elapsed=16659.0us expected=16666.9us +- 83.3us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 388.031921
last_received_ts = 388.031525
last_seq = 1126
current_ts = 388.048584
current_received_ts = 388.048248
current_seq = 1127
count = 324
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 388.031921/1126, current 388.048584/1127: elapsed=16668.0us expected=16666.9us +- 83.3us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 388.048584
last_received_ts = 388.048248
last_seq = 1127
current_ts = 388.065247
current_received_ts = 388.064941
current_seq = 1128
count = 325
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 388.048584/1127, current 388.065247/1128: elapsed=16657.0us expected=16666.9us +- 83.3us, error 0.1%
(kms_flip:5601) DEBUG: name = flip
last_ts = 388.065247
last_received_ts = 388.064941
last_seq = 1128
current_ts = 388.081909
current_received_ts = 388.081482
current_seq = 1129
count = 326
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 388.065247/1128, current 388.081909/1129: elapsed=16661.0us expected=16666.9us +- 83.3us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 388.081909
last_received_ts = 388.081482
last_seq = 1129
current_ts = 388.098541
current_received_ts = 388.098267
current_seq = 1130
count = 327
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 388.081909/1129, current 388.098541/1130: elapsed=16651.0us expected=16666.9us +- 83.3us, error 0.1%
(kms_flip:5601) DEBUG: name = flip
last_ts = 388.098541
last_received_ts = 388.098267
last_seq = 1130
current_ts = 388.115234
current_received_ts = 388.114899
current_seq = 1131
count = 328
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 388.098541/1130, current 388.115234/1131: elapsed=16667.0us expected=16666.9us +- 83.3us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 388.115234
last_received_ts = 388.114899
last_seq = 1131
current_ts = 388.131866
current_received_ts = 388.131500
current_seq = 1132
count = 329
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 388.115234/1131, current 388.131866/1132: elapsed=16656.0us expected=16666.9us +- 83.3us, error 0.1%
(kms_flip:5601) DEBUG: name = flip
last_ts = 388.131866
last_received_ts = 388.131500
last_seq = 1132
current_ts = 388.148529
current_received_ts = 388.148254
current_seq = 1133
count = 330
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 388.131866/1132, current 388.148529/1133: elapsed=16659.0us expected=16666.9us +- 83.3us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 388.148529
last_received_ts = 388.148254
last_seq = 1133
current_ts = 388.165192
current_received_ts = 388.164917
current_seq = 1134
count = 331
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 388.148529/1133, current 388.165192/1134: elapsed=16654.0us expected=16666.9us +- 83.3us, error 0.1%
(kms_flip:5601) DEBUG: name = flip
last_ts = 388.165192
last_received_ts = 388.164917
last_seq = 1134
current_ts = 388.181854
current_received_ts = 388.181458
current_seq = 1135
count = 332
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 388.165192/1134, current 388.181854/1135: elapsed=16653.0us expected=16666.9us +- 83.3us, error 0.1%
(kms_flip:5601) DEBUG: name = flip
last_ts = 388.181854
last_received_ts = 388.181458
last_seq = 1135
current_ts = 388.198517
current_received_ts = 388.198273
current_seq = 1136
count = 333
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 388.181854/1135, current 388.198517/1136: elapsed=16670.0us expected=16666.9us +- 83.3us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 388.198517
last_received_ts = 388.198273
last_seq = 1136
current_ts = 388.215179
current_received_ts = 388.214874
current_seq = 1137
count = 334
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 388.198517/1136, current 388.215179/1137: elapsed=16655.0us expected=16666.9us +- 83.3us, error 0.1%
(kms_flip:5601) DEBUG: name = flip
last_ts = 388.215179
last_received_ts = 388.214874
last_seq = 1137
current_ts = 388.231842
current_received_ts = 388.231476
current_seq = 1138
count = 335
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 388.215179/1137, current 388.231842/1138: elapsed=16659.0us expected=16666.9us +- 83.3us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 388.231842
last_received_ts = 388.231476
last_seq = 1138
current_ts = 388.248474
current_received_ts = 388.248230
current_seq = 1139
count = 336
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 388.231842/1138, current 388.248474/1139: elapsed=16649.0us expected=16666.9us +- 83.3us, error 0.1%
(kms_flip:5601) DEBUG: name = flip
last_ts = 388.248474
last_received_ts = 388.248230
last_seq = 1139
current_ts = 388.265137
current_received_ts = 388.264832
current_seq = 1140
count = 337
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 388.248474/1139, current 388.265137/1140: elapsed=16657.0us expected=16666.9us +- 83.3us, error 0.1%
(kms_flip:5601) DEBUG: name = flip
last_ts = 388.265137
last_received_ts = 388.264832
last_seq = 1140
current_ts = 388.281799
current_received_ts = 388.281372
current_seq = 1141
count = 338
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 388.265137/1140, current 388.281799/1141: elapsed=16670.0us expected=16666.9us +- 83.3us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 388.281799
last_received_ts = 388.281372
last_seq = 1141
current_ts = 388.298462
current_received_ts = 388.298218
current_seq = 1142
count = 339
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 388.281799/1141, current 388.298462/1142: elapsed=16647.0us expected=16666.9us +- 83.3us, error 0.1%
(kms_flip:5601) DEBUG: name = flip
last_ts = 388.298462
last_received_ts = 388.298218
last_seq = 1142
current_ts = 388.315125
current_received_ts = 388.314819
current_seq = 1143
count = 340
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 388.298462/1142, current 388.315125/1143: elapsed=16672.0us expected=16666.9us +- 83.3us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 388.315125
last_received_ts = 388.314819
last_seq = 1143
current_ts = 388.331787
current_received_ts = 388.331360
current_seq = 1144
count = 341
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 388.315125/1143, current 388.331787/1144: elapsed=16657.0us expected=16666.9us +- 83.3us, error 0.1%
(kms_flip:5601) DEBUG: name = flip
last_ts = 388.331787
last_received_ts = 388.331360
last_seq = 1144
current_ts = 388.348419
current_received_ts = 388.348145
current_seq = 1145
count = 342
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 388.331787/1144, current 388.348419/1145: elapsed=16647.0us expected=16666.9us +- 83.3us, error 0.1%
(kms_flip:5601) DEBUG: name = flip
last_ts = 388.348419
last_received_ts = 388.348145
last_seq = 1145
current_ts = 388.365082
current_received_ts = 388.364807
current_seq = 1146
count = 343
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 388.348419/1145, current 388.365082/1146: elapsed=16662.0us expected=16666.9us +- 83.3us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 388.365082
last_received_ts = 388.364807
last_seq = 1146
current_ts = 388.381744
current_received_ts = 388.381317
current_seq = 1147
count = 344
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 388.365082/1146, current 388.381744/1147: elapsed=16659.0us expected=16666.9us +- 83.3us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 388.381744
last_received_ts = 388.381317
last_seq = 1147
current_ts = 388.398407
current_received_ts = 388.398132
current_seq = 1148
count = 345
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 388.381744/1147, current 388.398407/1148: elapsed=16666.0us expected=16666.9us +- 83.3us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 388.398407
last_received_ts = 388.398132
last_seq = 1148
current_ts = 388.415070
current_received_ts = 388.414734
current_seq = 1149
count = 346
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 388.398407/1148, current 388.415070/1149: elapsed=16648.0us expected=16666.9us +- 83.3us, error 0.1%
(kms_flip:5601) DEBUG: name = flip
last_ts = 388.415070
last_received_ts = 388.414734
last_seq = 1149
current_ts = 388.431732
current_received_ts = 388.431366
current_seq = 1150
count = 347
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 388.415070/1149, current 388.431732/1150: elapsed=16658.0us expected=16666.9us +- 83.3us, error 0.1%
(kms_flip:5601) DEBUG: name = flip
last_ts = 388.431732
last_received_ts = 388.431366
last_seq = 1150
current_ts = 388.448395
current_received_ts = 388.448120
current_seq = 1151
count = 348
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 388.431732/1150, current 388.448395/1151: elapsed=16670.0us expected=16666.9us +- 83.3us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 388.448395
last_received_ts = 388.448120
last_seq = 1151
current_ts = 388.465057
current_received_ts = 388.464691
current_seq = 1152
count = 349
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 388.448395/1151, current 388.465057/1152: elapsed=16654.0us expected=16666.9us +- 83.3us, error 0.1%
(kms_flip:5601) DEBUG: name = flip
last_ts = 388.465057
last_received_ts = 388.464691
last_seq = 1152
current_ts = 388.481720
current_received_ts = 388.481323
current_seq = 1153
count = 350
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 388.465057/1152, current 388.481720/1153: elapsed=16663.0us expected=16666.9us +- 83.3us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 388.481720
last_received_ts = 388.481323
last_seq = 1153
current_ts = 388.498352
current_received_ts = 388.498108
current_seq = 1154
count = 351
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 388.481720/1153, current 388.498352/1154: elapsed=16659.0us expected=16666.9us +- 83.3us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 388.498352
last_received_ts = 388.498108
last_seq = 1154
current_ts = 388.515015
current_received_ts = 388.514740
current_seq = 1155
count = 352
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 388.498352/1154, current 388.515015/1155: elapsed=16654.0us expected=16666.9us +- 83.3us, error 0.1%
(kms_flip:5601) DEBUG: name = flip
last_ts = 388.515015
last_received_ts = 388.514740
last_seq = 1155
current_ts = 388.531677
current_received_ts = 388.531342
current_seq = 1156
count = 353
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 388.515015/1155, current 388.531677/1156: elapsed=16651.0us expected=16666.9us +- 83.3us, error 0.1%
(kms_flip:5601) DEBUG: name = flip
last_ts = 388.531677
last_received_ts = 388.531342
last_seq = 1156
current_ts = 388.548340
current_received_ts = 388.548096
current_seq = 1157
count = 354
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 388.531677/1156, current 388.548340/1157: elapsed=16668.0us expected=16666.9us +- 83.3us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 388.548340
last_received_ts = 388.548096
last_seq = 1157
current_ts = 388.565002
current_received_ts = 388.564697
current_seq = 1158
count = 355
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 388.548340/1157, current 388.565002/1158: elapsed=16655.0us expected=16666.9us +- 83.3us, error 0.1%
(kms_flip:5601) DEBUG: name = flip
last_ts = 388.565002
last_received_ts = 388.564697
last_seq = 1158
current_ts = 388.581635
current_received_ts = 388.581299
current_seq = 1159
count = 356
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 388.565002/1158, current 388.581635/1159: elapsed=16652.0us expected=16666.9us +- 83.3us, error 0.1%
(kms_flip:5601) DEBUG: name = flip
last_ts = 388.581635
last_received_ts = 388.581299
last_seq = 1159
current_ts = 388.598297
current_received_ts = 388.598083
current_seq = 1160
count = 357
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 388.581635/1159, current 388.598297/1160: elapsed=16659.0us expected=16666.9us +- 83.3us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 388.598297
last_received_ts = 388.598083
last_seq = 1160
current_ts = 388.614594
current_received_ts = 388.614227
current_seq = 1161
count = 358
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 388.598297/1160, current 388.614594/1161: elapsed=16275.0us expected=16666.9us +- 83.3us, error 2.4%
(kms_flip:5601) DEBUG: inconsistent flip ts/seq: last 388.598297/1160, current 388.614594/1161: elapsed=16275.0us expected=16666.9us
(kms_flip:5601) DEBUG: expected 0, counted 358, encoder type 2
(kms_flip:5601) DEBUG: dropped frames, expected 0, counted 358, encoder type 2
(kms_flip:5601) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:5601) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:5601) igt_core-INFO: Stack trace:
(kms_flip:5601) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:5601) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:5601) igt_core-INFO:   #2 ../tests/kms_flip.c:1845 run_test()
(kms_flip:5601) igt_core-INFO:   #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
(kms_flip:5601) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:5601) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:5601) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:5601) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest A-HDMI-A1: FAIL (9.701s)
Starting dynamic subtest: B-HDMI-A1
(kms_flip:5601) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:5601) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest B-HDMI-A1 failed.
**** DEBUG ****
(kms_flip:5601) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:5601) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=3, pitch=7680)
(kms_flip:5601) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:5601) igt_fb-DEBUG: igt_create_fb_with_bo_size(width=1920, height=1080, format=XR24(0x34325258), modifier=0x0, size=0)
(kms_flip:5601) igt_fb-DEBUG: igt_create_fb_with_bo_size(handle=4, pitch=7680)
(kms_flip:5601) ioctl_wrappers-DEBUG: Test requirement passed: igt_has_fb_modifiers(fd)
(kms_flip:5601) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:5601) intel_allocator_simple-DEBUG: <ial: 0x61e94bb3eac0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:5601) intel_allocator_simple-DEBUG: <ial: 0x61e94bb3eac0, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:5601) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:5601) intel_allocator_simple-DEBUG: <ial: 0x61e94bb3d190, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:5601) intel_allocator_simple-DEBUG: <ial: 0x61e94bb3d190, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:5601) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:5601) intel_allocator_simple-DEBUG: <ial: 0x61e94bb3d470, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:5601) intel_allocator_simple-DEBUG: <ial: 0x61e94bb3d470, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:5601) intel_allocator_simple-DEBUG: Using simple allocator
(kms_flip:5601) intel_allocator_simple-DEBUG: <ial: 0x61e94bb3d470, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:5601) intel_allocator_simple-DEBUG: <ial: 0x61e94bb3d470, fd: 5> objects: 3, reserved_areas: 0
(kms_flip:5601) igt_kms-INFO:   1920x1080: 60 148500 1920 2008 2052 2200 1080 1084 1089 1125 0x48 0x5 
(kms_flip:5601) DEBUG: No stale events found
(kms_flip:5601) i915/intel_drrs-DEBUG: Manually disabling DRRS. 0
(kms_flip:5601) i915/intel_drrs-DEBUG: Test requirement passed: dir >= 0
(kms_flip:5601) INFO: Expected frametime: 16667us; measured 16302.6us +- 7.117us accuracy 0.13%
(kms_flip:5601) INFO: vblank interval differs from modeline! expected 16666.7us, measured 16303us +- 7.117us, difference 364.0us (51.2 sigma)
(kms_flip:5601) DEBUG: name = flip
last_ts = 0.000000
last_received_ts = 0.000000
last_seq = 0
current_ts = 392.251343
current_received_ts = 392.251068
current_seq = 21
count = 0
seq_step = 1
(kms_flip:5601) DEBUG: name = flip
last_ts = 392.251343
last_received_ts = 392.251068
last_seq = 21
current_ts = 392.267639
current_received_ts = 392.267273
current_seq = 22
count = 1
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 392.251343/21, current 392.267639/22: elapsed=16299.0us expected=16302.6us +- 81.5us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 392.267639
last_received_ts = 392.267273
last_seq = 22
current_ts = 392.283936
current_received_ts = 392.283661
current_seq = 23
count = 2
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 392.267639/22, current 392.283936/23: elapsed=16299.0us expected=16302.6us +- 81.5us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 392.283936
last_received_ts = 392.283661
last_seq = 23
current_ts = 392.300232
current_received_ts = 392.300049
current_seq = 24
count = 3
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 392.283936/23, current 392.300232/24: elapsed=16304.0us expected=16302.6us +- 81.5us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 392.300232
last_received_ts = 392.300049
last_seq = 24
current_ts = 392.316528
current_received_ts = 392.316284
current_seq = 25
count = 4
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 392.300232/24, current 392.316528/25: elapsed=16300.0us expected=16302.6us +- 81.5us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 392.316528
last_received_ts = 392.316284
last_seq = 25
current_ts = 392.332855
current_received_ts = 392.332397
current_seq = 26
count = 5
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 392.316528/25, current 392.332855/26: elapsed=16307.0us expected=16302.6us +- 81.5us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 392.332855
last_received_ts = 392.332397
last_seq = 26
current_ts = 392.349152
current_received_ts = 392.348877
current_seq = 27
count = 6
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 392.332855/26, current 392.349152/27: elapsed=16306.0us expected=16302.6us +- 81.5us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 392.349152
last_received_ts = 392.348877
last_seq = 27
current_ts = 392.365448
current_received_ts = 392.365173
current_seq = 28
count = 7
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 392.349152/27, current 392.365448/28: elapsed=16303.0us expected=16302.6us +- 81.5us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 392.365448
last_received_ts = 392.365173
last_seq = 28
current_ts = 392.381744
current_received_ts = 392.381500
current_seq = 29
count = 8
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 392.365448/28, current 392.381744/29: elapsed=16300.0us expected=16302.6us +- 81.5us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 392.381744
last_received_ts = 392.381500
last_seq = 29
current_ts = 392.398071
current_received_ts = 392.397736
current_seq = 30
count = 9
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 392.381744/29, current 392.398071/30: elapsed=16305.0us expected=16302.6us +- 81.5us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 392.398071
last_received_ts = 392.397736
last_seq = 30
current_ts = 392.414368
current_received_ts = 392.414093
current_seq = 31
count = 10
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 392.398071/30, current 392.414368/31: elapsed=16293.0us expected=16302.6us +- 81.5us, error 0.1%
(kms_flip:5601) DEBUG: name = flip
last_ts = 392.414368
last_received_ts = 392.414093
last_seq = 31
current_ts = 392.430664
current_received_ts = 392.430267
current_seq = 32
count = 11
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 392.414368/31, current 392.430664/32: elapsed=16302.0us expected=16302.6us +- 81.5us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 392.430664
last_received_ts = 392.430267
last_seq = 32
current_ts = 392.446960
current_received_ts = 392.446594
current_seq = 33
count = 12
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 392.430664/32, current 392.446960/33: elapsed=16309.0us expected=16302.6us +- 81.5us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 392.446960
last_received_ts = 392.446594
last_seq = 33
current_ts = 392.463257
current_received_ts = 392.462982
current_seq = 34
count = 13
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 392.446960/33, current 392.463257/34: elapsed=16293.0us expected=16302.6us +- 81.5us, error 0.1%
(kms_flip:5601) DEBUG: name = flip
last_ts = 392.463257
last_received_ts = 392.462982
last_seq = 34
current_ts = 392.479584
current_received_ts = 392.479248
current_seq = 35
count = 14
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 392.463257/34, current 392.479584/35: elapsed=16312.0us expected=16302.6us +- 81.5us, error 0.1%
(kms_flip:5601) DEBUG: name = flip
last_ts = 392.479584
last_received_ts = 392.479248
last_seq = 35
current_ts = 392.495880
current_received_ts = 392.495422
current_seq = 36
count = 15
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 392.479584/35, current 392.495880/36: elapsed=16301.0us expected=16302.6us +- 81.5us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 392.495880
last_received_ts = 392.495422
last_seq = 36
current_ts = 392.512177
current_received_ts = 392.511902
current_seq = 37
count = 16
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 392.495880/36, current 392.512177/37: elapsed=16293.0us expected=16302.6us +- 81.5us, error 0.1%
(kms_flip:5601) DEBUG: name = flip
last_ts = 392.512177
last_received_ts = 392.511902
last_seq = 37
current_ts = 392.528473
current_received_ts = 392.528198
current_seq = 38
count = 17
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 392.512177/37, current 392.528473/38: elapsed=16303.0us expected=16302.6us +- 81.5us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 392.528473
last_received_ts = 392.528198
last_seq = 38
current_ts = 392.544769
current_received_ts = 392.544403
current_seq = 39
count = 18
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 392.528473/38, current 392.544769/39: elapsed=16308.0us expected=16302.6us +- 81.5us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 392.544769
last_received_ts = 392.544403
last_seq = 39
current_ts = 392.561096
current_received_ts = 392.560822
current_seq = 40
count = 19
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 392.544769/39, current 392.561096/40: elapsed=16308.0us expected=16302.6us +- 81.5us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 392.561096
last_received_ts = 392.560822
last_seq = 40
current_ts = 392.577393
current_received_ts = 392.577118
current_seq = 41
count = 20
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 392.561096/40, current 392.577393/41: elapsed=16302.0us expected=16302.6us +- 81.5us, error 0.0%
(kms_flip:5601) DEBUG: name = flip
last_ts = 392.577393
last_received_ts = 392.577118
last_seq = 41
current_ts = 392.593689
current_received_ts = 392.593384
current_seq = 42
count = 21
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 392.577393/41, current 392.593689/42: elapsed=16293.0us expected=16302.6us +- 81.5us, error 0.1%
(kms_flip:5601) DEBUG: name = flip
last_ts = 392.593689
last_received_ts = 392.593384
last_seq = 42
current_ts = 392.610016
current_received_ts = 392.609680
current_seq = 43
count = 22
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 392.593689/42, current 392.610016/43: elapsed=16323.0us expected=16302.6us +- 81.5us, error 0.1%
(kms_flip:5601) DEBUG: name = flip
last_ts = 392.610016
last_received_ts = 392.609680
last_seq = 43
current_ts = 392.626343
current_received_ts = 392.626129
current_seq = 44
count = 23
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 392.610016/43, current 392.626343/44: elapsed=16351.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 392.626343
last_received_ts = 392.626129
last_seq = 44
current_ts = 392.642700
current_received_ts = 392.642395
current_seq = 45
count = 24
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 392.626343/44, current 392.642700/45: elapsed=16346.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 392.642700
last_received_ts = 392.642395
last_seq = 45
current_ts = 392.659027
current_received_ts = 392.658752
current_seq = 46
count = 25
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 392.642700/45, current 392.659027/46: elapsed=16341.0us expected=16302.6us +- 81.5us, error 0.2%
(kms_flip:5601) DEBUG: name = flip
last_ts = 392.659027
last_received_ts = 392.658752
last_seq = 46
current_ts = 392.675385
current_received_ts = 392.675140
current_seq = 47
count = 26
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 392.659027/46, current 392.675385/47: elapsed=16357.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 392.675385
last_received_ts = 392.675140
last_seq = 47
current_ts = 392.691742
current_received_ts = 392.691406
current_seq = 48
count = 27
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 392.675385/47, current 392.691742/48: elapsed=16336.0us expected=16302.6us +- 81.5us, error 0.2%
(kms_flip:5601) DEBUG: name = flip
last_ts = 392.691742
last_received_ts = 392.691406
last_seq = 48
current_ts = 392.708099
current_received_ts = 392.707794
current_seq = 49
count = 28
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 392.691742/48, current 392.708099/49: elapsed=16352.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 392.708099
last_received_ts = 392.707794
last_seq = 49
current_ts = 392.724426
current_received_ts = 392.724182
current_seq = 50
count = 29
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 392.708099/49, current 392.724426/50: elapsed=16347.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 392.724426
last_received_ts = 392.724182
last_seq = 50
current_ts = 392.740784
current_received_ts = 392.740479
current_seq = 51
count = 30
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 392.724426/50, current 392.740784/51: elapsed=16349.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 392.740784
last_received_ts = 392.740479
last_seq = 51
current_ts = 392.757111
current_received_ts = 392.756836
current_seq = 52
count = 31
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 392.740784/51, current 392.757111/52: elapsed=16340.0us expected=16302.6us +- 81.5us, error 0.2%
(kms_flip:5601) DEBUG: name = flip
last_ts = 392.757111
last_received_ts = 392.756836
last_seq = 52
current_ts = 392.773468
current_received_ts = 392.773254
current_seq = 53
count = 32
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 392.757111/52, current 392.773468/53: elapsed=16353.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 392.773468
last_received_ts = 392.773254
last_seq = 53
current_ts = 392.789825
current_received_ts = 392.789490
current_seq = 54
count = 33
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 392.773468/53, current 392.789825/54: elapsed=16345.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 392.789825
last_received_ts = 392.789490
last_seq = 54
current_ts = 392.806152
current_received_ts = 392.805939
current_seq = 55
count = 34
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 392.789825/54, current 392.806152/55: elapsed=16341.0us expected=16302.6us +- 81.5us, error 0.2%
(kms_flip:5601) DEBUG: name = flip
last_ts = 392.806152
last_received_ts = 392.805939
last_seq = 55
current_ts = 392.822510
current_received_ts = 392.822235
current_seq = 56
count = 35
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 392.806152/55, current 392.822510/56: elapsed=16349.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 392.822510
last_received_ts = 392.822235
last_seq = 56
current_ts = 392.838867
current_received_ts = 392.838409
current_seq = 57
count = 36
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 392.822510/56, current 392.838867/57: elapsed=16356.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 392.838867
last_received_ts = 392.838409
last_seq = 57
current_ts = 392.855194
current_received_ts = 392.854919
current_seq = 58
count = 37
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 392.838867/57, current 392.855194/58: elapsed=16342.0us expected=16302.6us +- 81.5us, error 0.2%
(kms_flip:5601) DEBUG: name = flip
last_ts = 392.855194
last_received_ts = 392.854919
last_seq = 58
current_ts = 392.871552
current_received_ts = 392.871307
current_seq = 59
count = 38
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 392.855194/58, current 392.871552/59: elapsed=16347.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 392.871552
last_received_ts = 392.871307
last_seq = 59
current_ts = 392.887909
current_received_ts = 392.887512
current_seq = 60
count = 39
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 392.871552/59, current 392.887909/60: elapsed=16341.0us expected=16302.6us +- 81.5us, error 0.2%
(kms_flip:5601) DEBUG: name = flip
last_ts = 392.887909
last_received_ts = 392.887512
last_seq = 60
current_ts = 392.904236
current_received_ts = 392.903931
current_seq = 61
count = 40
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 392.887909/60, current 392.904236/61: elapsed=16344.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 392.904236
last_received_ts = 392.903931
last_seq = 61
current_ts = 392.920593
current_received_ts = 392.920288
current_seq = 62
count = 41
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 392.904236/61, current 392.920593/62: elapsed=16351.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 392.920593
last_received_ts = 392.920288
last_seq = 62
current_ts = 392.936951
current_received_ts = 392.936676
current_seq = 63
count = 42
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 392.920593/62, current 392.936951/63: elapsed=16350.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 392.936951
last_received_ts = 392.936676
last_seq = 63
current_ts = 392.953308
current_received_ts = 392.952972
current_seq = 64
count = 43
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 392.936951/63, current 392.953308/64: elapsed=16352.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 392.953308
last_received_ts = 392.952972
last_seq = 64
current_ts = 392.969635
current_received_ts = 392.969269
current_seq = 65
count = 44
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 392.953308/64, current 392.969635/65: elapsed=16348.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 392.969635
last_received_ts = 392.969269
last_seq = 65
current_ts = 392.985992
current_received_ts = 392.985626
current_seq = 66
count = 45
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 392.969635/65, current 392.985992/66: elapsed=16345.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 392.985992
last_received_ts = 392.985626
last_seq = 66
current_ts = 393.002319
current_received_ts = 393.002106
current_seq = 67
count = 46
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 392.985992/66, current 393.002319/67: elapsed=16342.0us expected=16302.6us +- 81.5us, error 0.2%
(kms_flip:5601) DEBUG: name = flip
last_ts = 393.002319
last_received_ts = 393.002106
last_seq = 67
current_ts = 393.018677
current_received_ts = 393.018280
current_seq = 68
count = 47
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 393.002319/67, current 393.018677/68: elapsed=16340.0us expected=16302.6us +- 81.5us, error 0.2%
(kms_flip:5601) DEBUG: name = flip
last_ts = 393.018677
last_received_ts = 393.018280
last_seq = 68
current_ts = 393.035034
current_received_ts = 393.034698
current_seq = 69
count = 48
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 393.018677/68, current 393.035034/69: elapsed=16362.0us expected=16302.6us +- 81.5us, error 0.4%
(kms_flip:5601) DEBUG: name = flip
last_ts = 393.035034
last_received_ts = 393.034698
last_seq = 69
current_ts = 393.051361
current_received_ts = 393.051117
current_seq = 70
count = 49
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 393.035034/69, current 393.051361/70: elapsed=16343.0us expected=16302.6us +- 81.5us, error 0.2%
(kms_flip:5601) DEBUG: name = flip
last_ts = 393.051361
last_received_ts = 393.051117
last_seq = 70
current_ts = 393.067719
current_received_ts = 393.067474
current_seq = 71
count = 50
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 393.051361/70, current 393.067719/71: elapsed=16336.0us expected=16302.6us +- 81.5us, error 0.2%
(kms_flip:5601) DEBUG: name = flip
last_ts = 393.067719
last_received_ts = 393.067474
last_seq = 71
current_ts = 393.084045
current_received_ts = 393.083801
current_seq = 72
count = 51
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 393.067719/71, current 393.084045/72: elapsed=16350.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 393.084045
last_received_ts = 393.083801
last_seq = 72
current_ts = 393.100403
current_received_ts = 393.099945
current_seq = 73
count = 52
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 393.084045/72, current 393.100403/73: elapsed=16345.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 393.100403
last_received_ts = 393.099945
last_seq = 73
current_ts = 393.116760
current_received_ts = 393.116180
current_seq = 74
count = 53
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 393.100403/73, current 393.116760/74: elapsed=16359.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 393.116760
last_received_ts = 393.116180
last_seq = 74
current_ts = 393.133118
current_received_ts = 393.132568
current_seq = 75
count = 54
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 393.116760/74, current 393.133118/75: elapsed=16346.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 393.133118
last_received_ts = 393.132568
last_seq = 75
current_ts = 393.149445
current_received_ts = 393.148895
current_seq = 76
count = 55
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 393.133118/75, current 393.149445/76: elapsed=16335.0us expected=16302.6us +- 81.5us, error 0.2%
(kms_flip:5601) DEBUG: name = flip
last_ts = 393.149445
last_received_ts = 393.148895
last_seq = 76
current_ts = 393.165802
current_received_ts = 393.165192
current_seq = 77
count = 56
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 393.149445/76, current 393.165802/77: elapsed=16354.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 393.165802
last_received_ts = 393.165192
last_seq = 77
current_ts = 393.182129
current_received_ts = 393.181671
current_seq = 78
count = 57
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 393.165802/77, current 393.182129/78: elapsed=16344.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 393.182129
last_received_ts = 393.181671
last_seq = 78
current_ts = 393.198486
current_received_ts = 393.198120
current_seq = 79
count = 58
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 393.182129/78, current 393.198486/79: elapsed=16347.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 393.198486
last_received_ts = 393.198120
last_seq = 79
current_ts = 393.214844
current_received_ts = 393.214325
current_seq = 80
count = 59
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 393.198486/79, current 393.214844/80: elapsed=16354.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 393.214844
last_received_ts = 393.214325
last_seq = 80
current_ts = 393.231201
current_received_ts = 393.230896
current_seq = 81
count = 60
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 393.214844/80, current 393.231201/81: elapsed=16345.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 393.231201
last_received_ts = 393.230896
last_seq = 81
current_ts = 393.247528
current_received_ts = 393.247253
current_seq = 82
count = 61
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 393.231201/81, current 393.247528/82: elapsed=16347.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 393.247528
last_received_ts = 393.247253
last_seq = 82
current_ts = 393.263885
current_received_ts = 393.263489
current_seq = 83
count = 62
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 393.247528/82, current 393.263885/83: elapsed=16341.0us expected=16302.6us +- 81.5us, error 0.2%
(kms_flip:5601) DEBUG: name = flip
last_ts = 393.263885
last_received_ts = 393.263489
last_seq = 83
current_ts = 393.280243
current_received_ts = 393.279938
current_seq = 84
count = 63
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 393.263885/83, current 393.280243/84: elapsed=16352.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 393.280243
last_received_ts = 393.279938
last_seq = 84
current_ts = 393.296570
current_received_ts = 393.296234
current_seq = 85
count = 64
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 393.280243/84, current 393.296570/85: elapsed=16345.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 393.296570
last_received_ts = 393.296234
last_seq = 85
current_ts = 393.312927
current_received_ts = 393.312531
current_seq = 86
count = 65
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 393.296570/85, current 393.312927/86: elapsed=16348.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 393.312927
last_received_ts = 393.312531
last_seq = 86
current_ts = 393.329254
current_received_ts = 393.328949
current_seq = 87
count = 66
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 393.312927/86, current 393.329254/87: elapsed=16338.0us expected=16302.6us +- 81.5us, error 0.2%
(kms_flip:5601) DEBUG: name = flip
last_ts = 393.329254
last_received_ts = 393.328949
last_seq = 87
current_ts = 393.345612
current_received_ts = 393.345276
current_seq = 88
count = 67
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 393.329254/87, current 393.345612/88: elapsed=16349.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 393.345612
last_received_ts = 393.345276
last_seq = 88
current_ts = 393.361969
current_received_ts = 393.361603
current_seq = 89
count = 68
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 393.345612/88, current 393.361969/89: elapsed=16346.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 393.361969
last_received_ts = 393.361603
last_seq = 89
current_ts = 393.378296
current_received_ts = 393.378052
current_seq = 90
count = 69
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 393.361969/89, current 393.378296/90: elapsed=16355.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 393.378296
last_received_ts = 393.378052
last_seq = 90
current_ts = 393.394653
current_received_ts = 393.394287
current_seq = 91
count = 70
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 393.378296/90, current 393.394653/91: elapsed=16343.0us expected=16302.6us +- 81.5us, error 0.2%
(kms_flip:5601) DEBUG: name = flip
last_ts = 393.394653
last_received_ts = 393.394287
last_seq = 91
current_ts = 393.410980
current_received_ts = 393.410706
current_seq = 92
count = 71
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 393.394653/91, current 393.410980/92: elapsed=16340.0us expected=16302.6us +- 81.5us, error 0.2%
(kms_flip:5601) DEBUG: name = flip
last_ts = 393.410980
last_received_ts = 393.410706
last_seq = 92
current_ts = 393.427338
current_received_ts = 393.427094
current_seq = 93
count = 72
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 393.410980/92, current 393.427338/93: elapsed=16346.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 393.427338
last_received_ts = 393.427094
last_seq = 93
current_ts = 393.443695
current_received_ts = 393.443390
current_seq = 94
count = 73
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 393.427338/93, current 393.443695/94: elapsed=16360.0us expected=16302.6us +- 81.5us, error 0.4%
(kms_flip:5601) DEBUG: name = flip
last_ts = 393.443695
last_received_ts = 393.443390
last_seq = 94
current_ts = 393.460022
current_received_ts = 393.459717
current_seq = 95
count = 74
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 393.443695/94, current 393.460022/95: elapsed=16338.0us expected=16302.6us +- 81.5us, error 0.2%
(kms_flip:5601) DEBUG: name = flip
last_ts = 393.460022
last_received_ts = 393.459717
last_seq = 95
current_ts = 393.476379
current_received_ts = 393.476135
current_seq = 96
count = 75
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 393.460022/95, current 393.476379/96: elapsed=16351.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 393.476379
last_received_ts = 393.476135
last_seq = 96
current_ts = 393.492737
current_received_ts = 393.492432
current_seq = 97
count = 76
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 393.476379/96, current 393.492737/97: elapsed=16338.0us expected=16302.6us +- 81.5us, error 0.2%
(kms_flip:5601) DEBUG: name = flip
last_ts = 393.492737
last_received_ts = 393.492432
last_seq = 97
current_ts = 393.509064
current_received_ts = 393.508789
current_seq = 98
count = 77
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 393.492737/97, current 393.509064/98: elapsed=16346.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 393.509064
last_received_ts = 393.508789
last_seq = 98
current_ts = 393.525421
current_received_ts = 393.525177
current_seq = 99
count = 78
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 393.509064/98, current 393.525421/99: elapsed=16357.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 393.525421
last_received_ts = 393.525177
last_seq = 99
current_ts = 393.541779
current_received_ts = 393.541290
current_seq = 100
count = 79
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 393.525421/99, current 393.541779/100: elapsed=16347.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 393.541779
last_received_ts = 393.541290
last_seq = 100
current_ts = 393.558105
current_received_ts = 393.557831
current_seq = 101
count = 80
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 393.541779/100, current 393.558105/101: elapsed=16342.0us expected=16302.6us +- 81.5us, error 0.2%
(kms_flip:5601) DEBUG: name = flip
last_ts = 393.558105
last_received_ts = 393.557831
last_seq = 101
current_ts = 393.574463
current_received_ts = 393.574219
current_seq = 102
count = 81
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 393.558105/101, current 393.574463/102: elapsed=16350.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 393.574463
last_received_ts = 393.574219
last_seq = 102
current_ts = 393.590820
current_received_ts = 393.590302
current_seq = 103
count = 82
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 393.574463/102, current 393.590820/103: elapsed=16350.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 393.590820
last_received_ts = 393.590302
last_seq = 103
current_ts = 393.607178
current_received_ts = 393.606873
current_seq = 104
count = 83
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 393.590820/103, current 393.607178/104: elapsed=16354.0us expected=16302.6us +- 81.5us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 393.607178
last_received_ts = 393.606873
last_seq = 104
current_ts = 393.623566
current_received_ts = 393.623230
current_seq = 105
count = 84
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 393.607178/104, current 393.623566/105: elapsed=16389.0us expected=16302.6us +- 81.5us, error 0.5%
(kms_flip:5601) DEBUG: inconsistent flip ts/seq: last 393.607178/104, current 393.623566/105: elapsed=16389.0us expected=16302.6us
(kms_flip:5601) DEBUG: expected 0, counted 84, encoder type 2
(kms_flip:5601) DEBUG: dropped frames, expected 0, counted 84, encoder type 2
(kms_flip:5601) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:5601) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:5601) igt_core-INFO: Stack trace:
(kms_flip:5601) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:5601) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:5601) igt_core-INFO:   #2 ../tests/kms_flip.c:1845 run_test()
(kms_flip:5601) igt_core-INFO:   #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
(kms_flip:5601) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:5601) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:5601) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:5601) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-HDMI-A1: FAIL (4.900s)
Starting dynamic subtest: C-HDMI-A1
(kms_flip:5601) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:5601) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest C-HDMI-A1 failed.
**** DEBUG ****
(kms_flip:5601) DEBUG: flip ts/seq: last 398.772308/113, current 398.788818/114: elapsed=16523.0us expected=16475.7us +- 82.4us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 398.788818
last_received_ts = 398.788452
last_seq = 114
current_ts = 398.805359
current_received_ts = 398.805084
current_seq = 115
count = 94
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 398.788818/114, current 398.805359/115: elapsed=16517.0us expected=16475.7us +- 82.4us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 398.805359
last_received_ts = 398.805084
last_seq = 115
current_ts = 398.821869
current_received_ts = 398.821564
current_seq = 116
count = 95
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 398.805359/115, current 398.821869/116: elapsed=16516.0us expected=16475.7us +- 82.4us, error 0.2%
(kms_flip:5601) DEBUG: name = flip
last_ts = 398.821869
last_received_ts = 398.821564
last_seq = 116
current_ts = 398.838379
current_received_ts = 398.838135
current_seq = 117
count = 96
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 398.821869/116, current 398.838379/117: elapsed=16523.0us expected=16475.7us +- 82.4us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 398.838379
last_received_ts = 398.838135
last_seq = 117
current_ts = 398.854889
current_received_ts = 398.854553
current_seq = 118
count = 97
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 398.838379/117, current 398.854889/118: elapsed=16519.0us expected=16475.7us +- 82.4us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 398.854889
last_received_ts = 398.854553
last_seq = 118
current_ts = 398.871399
current_received_ts = 398.871185
current_seq = 119
count = 98
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 398.854889/118, current 398.871399/119: elapsed=16510.0us expected=16475.7us +- 82.4us, error 0.2%
(kms_flip:5601) DEBUG: name = flip
last_ts = 398.871399
last_received_ts = 398.871185
last_seq = 119
current_ts = 398.887939
current_received_ts = 398.887573
current_seq = 120
count = 99
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 398.871399/119, current 398.887939/120: elapsed=16523.0us expected=16475.7us +- 82.4us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 398.887939
last_received_ts = 398.887573
last_seq = 120
current_ts = 398.904449
current_received_ts = 398.904297
current_seq = 121
count = 100
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 398.887939/120, current 398.904449/121: elapsed=16521.0us expected=16475.7us +- 82.4us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 398.904449
last_received_ts = 398.904297
last_seq = 121
current_ts = 398.920990
current_received_ts = 398.920685
current_seq = 122
count = 101
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 398.904449/121, current 398.920990/122: elapsed=16521.0us expected=16475.7us +- 82.4us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 398.920990
last_received_ts = 398.920685
last_seq = 122
current_ts = 398.937500
current_received_ts = 398.937256
current_seq = 123
count = 102
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 398.920990/122, current 398.937500/123: elapsed=16518.0us expected=16475.7us +- 82.4us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 398.937500
last_received_ts = 398.937256
last_seq = 123
current_ts = 398.954010
current_received_ts = 398.953674
current_seq = 124
count = 103
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 398.937500/123, current 398.954010/124: elapsed=16521.0us expected=16475.7us +- 82.4us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 398.954010
last_received_ts = 398.953674
last_seq = 124
current_ts = 398.970520
current_received_ts = 398.970215
current_seq = 125
count = 104
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 398.954010/124, current 398.970520/125: elapsed=16506.0us expected=16475.7us +- 82.4us, error 0.2%
(kms_flip:5601) DEBUG: name = flip
last_ts = 398.970520
last_received_ts = 398.970215
last_seq = 125
current_ts = 398.987061
current_received_ts = 398.986694
current_seq = 126
count = 105
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 398.970520/125, current 398.987061/126: elapsed=16532.0us expected=16475.7us +- 82.4us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 398.987061
last_received_ts = 398.986694
last_seq = 126
current_ts = 399.003571
current_received_ts = 399.003235
current_seq = 127
count = 106
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 398.987061/126, current 399.003571/127: elapsed=16509.0us expected=16475.7us +- 82.4us, error 0.2%
(kms_flip:5601) DEBUG: name = flip
last_ts = 399.003571
last_received_ts = 399.003235
last_seq = 127
current_ts = 399.020081
current_received_ts = 399.019775
current_seq = 128
count = 107
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 399.003571/127, current 399.020081/128: elapsed=16521.0us expected=16475.7us +- 82.4us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 399.020081
last_received_ts = 399.019775
last_seq = 128
current_ts = 399.036591
current_received_ts = 399.036255
current_seq = 129
count = 108
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 399.020081/128, current 399.036591/129: elapsed=16517.0us expected=16475.7us +- 82.4us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 399.036591
last_received_ts = 399.036255
last_seq = 129
current_ts = 399.053131
current_received_ts = 399.052795
current_seq = 130
count = 109
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 399.036591/129, current 399.053131/130: elapsed=16525.0us expected=16475.7us +- 82.4us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 399.053131
last_received_ts = 399.052795
last_seq = 130
current_ts = 399.069641
current_received_ts = 399.069427
current_seq = 131
count = 110
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 399.053131/130, current 399.069641/131: elapsed=16508.0us expected=16475.7us +- 82.4us, error 0.2%
(kms_flip:5601) DEBUG: name = flip
last_ts = 399.069641
last_received_ts = 399.069427
last_seq = 131
current_ts = 399.086151
current_received_ts = 399.085876
current_seq = 132
count = 111
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 399.069641/131, current 399.086151/132: elapsed=16520.0us expected=16475.7us +- 82.4us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 399.086151
last_received_ts = 399.085876
last_seq = 132
current_ts = 399.102661
current_received_ts = 399.102295
current_seq = 133
count = 112
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 399.086151/132, current 399.102661/133: elapsed=16516.0us expected=16475.7us +- 82.4us, error 0.2%
(kms_flip:5601) DEBUG: name = flip
last_ts = 399.102661
last_received_ts = 399.102295
last_seq = 133
current_ts = 399.119202
current_received_ts = 399.118896
current_seq = 134
count = 113
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 399.102661/133, current 399.119202/134: elapsed=16527.0us expected=16475.7us +- 82.4us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 399.119202
last_received_ts = 399.118896
last_seq = 134
current_ts = 399.135712
current_received_ts = 399.135315
current_seq = 135
count = 114
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 399.119202/134, current 399.135712/135: elapsed=16523.0us expected=16475.7us +- 82.4us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 399.135712
last_received_ts = 399.135315
last_seq = 135
current_ts = 399.152252
current_received_ts = 399.151947
current_seq = 136
count = 115
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 399.135712/135, current 399.152252/136: elapsed=16517.0us expected=16475.7us +- 82.4us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 399.152252
last_received_ts = 399.151947
last_seq = 136
current_ts = 399.168762
current_received_ts = 399.168427
current_seq = 137
count = 116
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 399.152252/136, current 399.168762/137: elapsed=16510.0us expected=16475.7us +- 82.4us, error 0.2%
(kms_flip:5601) DEBUG: name = flip
last_ts = 399.168762
last_received_ts = 399.168427
last_seq = 137
current_ts = 399.185272
current_received_ts = 399.184967
current_seq = 138
count = 117
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 399.168762/137, current 399.185272/138: elapsed=16528.0us expected=16475.7us +- 82.4us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 399.185272
last_received_ts = 399.184967
last_seq = 138
current_ts = 399.201782
current_received_ts = 399.201447
current_seq = 139
count = 118
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 399.185272/138, current 399.201782/139: elapsed=16518.0us expected=16475.7us +- 82.4us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 399.201782
last_received_ts = 399.201447
last_seq = 139
current_ts = 399.218323
current_received_ts = 399.218079
current_seq = 140
count = 119
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 399.201782/139, current 399.218323/140: elapsed=16513.0us expected=16475.7us +- 82.4us, error 0.2%
(kms_flip:5601) DEBUG: name = flip
last_ts = 399.218323
last_received_ts = 399.218079
last_seq = 140
current_ts = 399.234833
current_received_ts = 399.234436
current_seq = 141
count = 120
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 399.218323/140, current 399.234833/141: elapsed=16517.0us expected=16475.7us +- 82.4us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 399.234833
last_received_ts = 399.234436
last_seq = 141
current_ts = 399.251343
current_received_ts = 399.250916
current_seq = 142
count = 121
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 399.234833/141, current 399.251343/142: elapsed=16524.0us expected=16475.7us +- 82.4us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 399.251343
last_received_ts = 399.250916
last_seq = 142
current_ts = 399.267883
current_received_ts = 399.267517
current_seq = 143
count = 122
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 399.251343/142, current 399.267883/143: elapsed=16521.0us expected=16475.7us +- 82.4us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 399.267883
last_received_ts = 399.267517
last_seq = 143
current_ts = 399.284393
current_received_ts = 399.284119
current_seq = 144
count = 123
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 399.267883/143, current 399.284393/144: elapsed=16518.0us expected=16475.7us +- 82.4us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 399.284393
last_received_ts = 399.284119
last_seq = 144
current_ts = 399.300903
current_received_ts = 399.300629
current_seq = 145
count = 124
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 399.284393/144, current 399.300903/145: elapsed=16510.0us expected=16475.7us +- 82.4us, error 0.2%
(kms_flip:5601) DEBUG: name = flip
last_ts = 399.300903
last_received_ts = 399.300629
last_seq = 145
current_ts = 399.317413
current_received_ts = 399.317169
current_seq = 146
count = 125
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 399.300903/145, current 399.317413/146: elapsed=16515.0us expected=16475.7us +- 82.4us, error 0.2%
(kms_flip:5601) DEBUG: name = flip
last_ts = 399.317413
last_received_ts = 399.317169
last_seq = 146
current_ts = 399.333954
current_received_ts = 399.333557
current_seq = 147
count = 126
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 399.317413/146, current 399.333954/147: elapsed=16530.0us expected=16475.7us +- 82.4us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 399.333954
last_received_ts = 399.333557
last_seq = 147
current_ts = 399.350464
current_received_ts = 399.350189
current_seq = 148
count = 127
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 399.333954/147, current 399.350464/148: elapsed=16514.0us expected=16475.7us +- 82.4us, error 0.2%
(kms_flip:5601) DEBUG: name = flip
last_ts = 399.350464
last_received_ts = 399.350189
last_seq = 148
current_ts = 399.366974
current_received_ts = 399.366638
current_seq = 149
count = 128
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 399.350464/148, current 399.366974/149: elapsed=16522.0us expected=16475.7us +- 82.4us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 399.366974
last_received_ts = 399.366638
last_seq = 149
current_ts = 399.383514
current_received_ts = 399.383270
current_seq = 150
count = 129
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 399.366974/149, current 399.383514/150: elapsed=16521.0us expected=16475.7us +- 82.4us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 399.383514
last_received_ts = 399.383270
last_seq = 150
current_ts = 399.400024
current_received_ts = 399.399658
current_seq = 151
count = 130
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 399.383514/150, current 399.400024/151: elapsed=16515.0us expected=16475.7us +- 82.4us, error 0.2%
(kms_flip:5601) DEBUG: name = flip
last_ts = 399.400024
last_received_ts = 399.399658
last_seq = 151
current_ts = 399.416534
current_received_ts = 399.416229
current_seq = 152
count = 131
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 399.400024/151, current 399.416534/152: elapsed=16521.0us expected=16475.7us +- 82.4us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 399.416534
last_received_ts = 399.416229
last_seq = 152
current_ts = 399.433044
current_received_ts = 399.432709
current_seq = 153
count = 132
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 399.416534/152, current 399.433044/153: elapsed=16515.0us expected=16475.7us +- 82.4us, error 0.2%
(kms_flip:5601) DEBUG: name = flip
last_ts = 399.433044
last_received_ts = 399.432709
last_seq = 153
current_ts = 399.449554
current_received_ts = 399.449249
current_seq = 154
count = 133
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 399.433044/153, current 399.449554/154: elapsed=16517.0us expected=16475.7us +- 82.4us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 399.449554
last_received_ts = 399.449249
last_seq = 154
current_ts = 399.466095
current_received_ts = 399.465759
current_seq = 155
count = 134
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 399.449554/154, current 399.466095/155: elapsed=16513.0us expected=16475.7us +- 82.4us, error 0.2%
(kms_flip:5601) DEBUG: name = flip
last_ts = 399.466095
last_received_ts = 399.465759
last_seq = 155
current_ts = 399.482605
current_received_ts = 399.482269
current_seq = 156
count = 135
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 399.466095/155, current 399.482605/156: elapsed=16522.0us expected=16475.7us +- 82.4us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 399.482605
last_received_ts = 399.482269
last_seq = 156
current_ts = 399.499115
current_received_ts = 399.498810
current_seq = 157
count = 136
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 399.482605/156, current 399.499115/157: elapsed=16521.0us expected=16475.7us +- 82.4us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 399.499115
last_received_ts = 399.498810
last_seq = 157
current_ts = 399.515656
current_received_ts = 399.515289
current_seq = 158
count = 137
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 399.499115/157, current 399.515656/158: elapsed=16518.0us expected=16475.7us +- 82.4us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 399.515656
last_received_ts = 399.515289
last_seq = 158
current_ts = 399.532166
current_received_ts = 399.531830
current_seq = 159
count = 138
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 399.515656/158, current 399.532166/159: elapsed=16523.0us expected=16475.7us +- 82.4us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 399.532166
last_received_ts = 399.531830
last_seq = 159
current_ts = 399.548676
current_received_ts = 399.548309
current_seq = 160
count = 139
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 399.532166/159, current 399.548676/160: elapsed=16516.0us expected=16475.7us +- 82.4us, error 0.2%
(kms_flip:5601) DEBUG: name = flip
last_ts = 399.548676
last_received_ts = 399.548309
last_seq = 160
current_ts = 399.565186
current_received_ts = 399.564911
current_seq = 161
count = 140
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 399.548676/160, current 399.565186/161: elapsed=16510.0us expected=16475.7us +- 82.4us, error 0.2%
(kms_flip:5601) DEBUG: name = flip
last_ts = 399.565186
last_received_ts = 399.564911
last_seq = 161
current_ts = 399.581696
current_received_ts = 399.581360
current_seq = 162
count = 141
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 399.565186/161, current 399.581696/162: elapsed=16518.0us expected=16475.7us +- 82.4us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 399.581696
last_received_ts = 399.581360
last_seq = 162
current_ts = 399.598236
current_received_ts = 399.597931
current_seq = 163
count = 142
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 399.581696/162, current 399.598236/163: elapsed=16524.0us expected=16475.7us +- 82.4us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 399.598236
last_received_ts = 399.597931
last_seq = 163
current_ts = 399.614777
current_received_ts = 399.614380
current_seq = 164
count = 143
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 399.598236/163, current 399.614777/164: elapsed=16539.0us expected=16475.7us +- 82.4us, error 0.4%
(kms_flip:5601) DEBUG: name = flip
last_ts = 399.614777
last_received_ts = 399.614380
last_seq = 164
current_ts = 399.631287
current_received_ts = 399.631073
current_seq = 165
count = 144
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 399.614777/164, current 399.631287/165: elapsed=16527.0us expected=16475.7us +- 82.4us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 399.631287
last_received_ts = 399.631073
last_seq = 165
current_ts = 399.647827
current_received_ts = 399.647461
current_seq = 166
count = 145
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 399.631287/165, current 399.647827/166: elapsed=16539.0us expected=16475.7us +- 82.4us, error 0.4%
(kms_flip:5601) DEBUG: name = flip
last_ts = 399.647827
last_received_ts = 399.647461
last_seq = 166
current_ts = 399.664368
current_received_ts = 399.664093
current_seq = 167
count = 146
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 399.647827/166, current 399.664368/167: elapsed=16534.0us expected=16475.7us +- 82.4us, error 0.4%
(kms_flip:5601) DEBUG: name = flip
last_ts = 399.664368
last_received_ts = 399.664093
last_seq = 167
current_ts = 399.680908
current_received_ts = 399.680542
current_seq = 168
count = 147
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 399.664368/167, current 399.680908/168: elapsed=16535.0us expected=16475.7us +- 82.4us, error 0.4%
(kms_flip:5601) DEBUG: name = flip
last_ts = 399.680908
last_received_ts = 399.680542
last_seq = 168
current_ts = 399.697449
current_received_ts = 399.697174
current_seq = 169
count = 148
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 399.680908/168, current 399.697449/169: elapsed=16533.0us expected=16475.7us +- 82.4us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 399.697449
last_received_ts = 399.697174
last_seq = 169
current_ts = 399.713989
current_received_ts = 399.713654
current_seq = 170
count = 149
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 399.697449/169, current 399.713989/170: elapsed=16542.0us expected=16475.7us +- 82.4us, error 0.4%
(kms_flip:5601) DEBUG: name = flip
last_ts = 399.713989
last_received_ts = 399.713654
last_seq = 170
current_ts = 399.730530
current_received_ts = 399.730255
current_seq = 171
count = 150
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 399.713989/170, current 399.730530/171: elapsed=16535.0us expected=16475.7us +- 82.4us, error 0.4%
(kms_flip:5601) DEBUG: name = flip
last_ts = 399.730530
last_received_ts = 399.730255
last_seq = 171
current_ts = 399.747040
current_received_ts = 399.746674
current_seq = 172
count = 151
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 399.730530/171, current 399.747040/172: elapsed=16531.0us expected=16475.7us +- 82.4us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 399.747040
last_received_ts = 399.746674
last_seq = 172
current_ts = 399.763580
current_received_ts = 399.763245
current_seq = 173
count = 152
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 399.747040/172, current 399.763580/173: elapsed=16540.0us expected=16475.7us +- 82.4us, error 0.4%
(kms_flip:5601) DEBUG: name = flip
last_ts = 399.763580
last_received_ts = 399.763245
last_seq = 173
current_ts = 399.780121
current_received_ts = 399.779816
current_seq = 174
count = 153
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 399.763580/173, current 399.780121/174: elapsed=16539.0us expected=16475.7us +- 82.4us, error 0.4%
(kms_flip:5601) DEBUG: name = flip
last_ts = 399.780121
last_received_ts = 399.779816
last_seq = 174
current_ts = 399.796661
current_received_ts = 399.796265
current_seq = 175
count = 154
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 399.780121/174, current 399.796661/175: elapsed=16530.0us expected=16475.7us +- 82.4us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 399.796661
last_received_ts = 399.796265
last_seq = 175
current_ts = 399.813202
current_received_ts = 399.812897
current_seq = 176
count = 155
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 399.796661/175, current 399.813202/176: elapsed=16535.0us expected=16475.7us +- 82.4us, error 0.4%
(kms_flip:5601) DEBUG: name = flip
last_ts = 399.813202
last_received_ts = 399.812897
last_seq = 176
current_ts = 399.829742
current_received_ts = 399.829407
current_seq = 177
count = 156
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 399.813202/176, current 399.829742/177: elapsed=16545.0us expected=16475.7us +- 82.4us, error 0.4%
(kms_flip:5601) DEBUG: name = flip
last_ts = 399.829742
last_received_ts = 399.829407
last_seq = 177
current_ts = 399.846252
current_received_ts = 399.845978
current_seq = 178
count = 157
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 399.829742/177, current 399.846252/178: elapsed=16526.0us expected=16475.7us +- 82.4us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 399.846252
last_received_ts = 399.845978
last_seq = 178
current_ts = 399.862793
current_received_ts = 399.862305
current_seq = 179
count = 158
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 399.846252/178, current 399.862793/179: elapsed=16542.0us expected=16475.7us +- 82.4us, error 0.4%
(kms_flip:5601) DEBUG: name = flip
last_ts = 399.862793
last_received_ts = 399.862305
last_seq = 179
current_ts = 399.879333
current_received_ts = 399.879089
current_seq = 180
count = 159
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 399.862793/179, current 399.879333/180: elapsed=16538.0us expected=16475.7us +- 82.4us, error 0.4%
(kms_flip:5601) DEBUG: name = flip
last_ts = 399.879333
last_received_ts = 399.879089
last_seq = 180
current_ts = 399.895874
current_received_ts = 399.895538
current_seq = 181
count = 160
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 399.879333/180, current 399.895874/181: elapsed=16537.0us expected=16475.7us +- 82.4us, error 0.4%
(kms_flip:5601) DEBUG: name = flip
last_ts = 399.895874
last_received_ts = 399.895538
last_seq = 181
current_ts = 399.912415
current_received_ts = 399.912140
current_seq = 182
count = 161
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 399.895874/181, current 399.912415/182: elapsed=16527.0us expected=16475.7us +- 82.4us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 399.912415
last_received_ts = 399.912140
last_seq = 182
current_ts = 399.928955
current_received_ts = 399.928589
current_seq = 183
count = 162
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 399.912415/182, current 399.928955/183: elapsed=16536.0us expected=16475.7us +- 82.4us, error 0.4%
(kms_flip:5601) DEBUG: name = flip
last_ts = 399.928955
last_received_ts = 399.928589
last_seq = 183
current_ts = 399.945496
current_received_ts = 399.945221
current_seq = 184
count = 163
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 399.928955/183, current 399.945496/184: elapsed=16543.0us expected=16475.7us +- 82.4us, error 0.4%
(kms_flip:5601) DEBUG: name = flip
last_ts = 399.945496
last_received_ts = 399.945221
last_seq = 184
current_ts = 399.962036
current_received_ts = 399.961700
current_seq = 185
count = 164
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 399.945496/184, current 399.962036/185: elapsed=16541.0us expected=16475.7us +- 82.4us, error 0.4%
(kms_flip:5601) DEBUG: name = flip
last_ts = 399.962036
last_received_ts = 399.961700
last_seq = 185
current_ts = 399.978546
current_received_ts = 399.978241
current_seq = 186
count = 165
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 399.962036/185, current 399.978546/186: elapsed=16525.0us expected=16475.7us +- 82.4us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 399.978546
last_received_ts = 399.978241
last_seq = 186
current_ts = 399.995087
current_received_ts = 399.994659
current_seq = 187
count = 166
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 399.978546/186, current 399.995087/187: elapsed=16539.0us expected=16475.7us +- 82.4us, error 0.4%
(kms_flip:5601) DEBUG: name = flip
last_ts = 399.995087
last_received_ts = 399.994659
last_seq = 187
current_ts = 400.011627
current_received_ts = 400.011322
current_seq = 188
count = 167
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 399.995087/187, current 400.011627/188: elapsed=16541.0us expected=16475.7us +- 82.4us, error 0.4%
(kms_flip:5601) DEBUG: name = flip
last_ts = 400.011627
last_received_ts = 400.011322
last_seq = 188
current_ts = 400.028168
current_received_ts = 400.027863
current_seq = 189
count = 168
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 400.011627/188, current 400.028168/189: elapsed=16539.0us expected=16475.7us +- 82.4us, error 0.4%
(kms_flip:5601) DEBUG: name = flip
last_ts = 400.028168
last_received_ts = 400.027863
last_seq = 189
current_ts = 400.044708
current_received_ts = 400.044403
current_seq = 190
count = 169
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 400.028168/189, current 400.044708/190: elapsed=16536.0us expected=16475.7us +- 82.4us, error 0.4%
(kms_flip:5601) DEBUG: name = flip
last_ts = 400.044708
last_received_ts = 400.044403
last_seq = 190
current_ts = 400.061218
current_received_ts = 400.060944
current_seq = 191
count = 170
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 400.044708/190, current 400.061218/191: elapsed=16526.0us expected=16475.7us +- 82.4us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 400.061218
last_received_ts = 400.060944
last_seq = 191
current_ts = 400.077789
current_received_ts = 400.077393
current_seq = 192
count = 171
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 400.061218/191, current 400.077789/192: elapsed=16546.0us expected=16475.7us +- 82.4us, error 0.4%
(kms_flip:5601) DEBUG: name = flip
last_ts = 400.077789
last_received_ts = 400.077393
last_seq = 192
current_ts = 400.094299
current_received_ts = 400.094055
current_seq = 193
count = 172
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 400.077789/192, current 400.094299/193: elapsed=16526.0us expected=16475.7us +- 82.4us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 400.094299
last_received_ts = 400.094055
last_seq = 193
current_ts = 400.110840
current_received_ts = 400.110504
current_seq = 194
count = 173
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 400.094299/193, current 400.110840/194: elapsed=16537.0us expected=16475.7us +- 82.4us, error 0.4%
(kms_flip:5601) DEBUG: name = flip
last_ts = 400.110840
last_received_ts = 400.110504
last_seq = 194
current_ts = 400.127380
current_received_ts = 400.127106
current_seq = 195
count = 174
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 400.110840/194, current 400.127380/195: elapsed=16539.0us expected=16475.7us +- 82.4us, error 0.4%
(kms_flip:5601) DEBUG: name = flip
last_ts = 400.127380
last_received_ts = 400.127106
last_seq = 195
current_ts = 400.143921
current_received_ts = 400.143555
current_seq = 196
count = 175
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 400.127380/195, current 400.143921/196: elapsed=16541.0us expected=16475.7us +- 82.4us, error 0.4%
(kms_flip:5601) DEBUG: name = flip
last_ts = 400.143921
last_received_ts = 400.143555
last_seq = 196
current_ts = 400.160461
current_received_ts = 400.160217
current_seq = 197
count = 176
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 400.143921/196, current 400.160461/197: elapsed=16530.0us expected=16475.7us +- 82.4us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 400.160461
last_received_ts = 400.160217
last_seq = 197
current_ts = 400.177002
current_received_ts = 400.176636
current_seq = 198
count = 177
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 400.160461/197, current 400.177002/198: elapsed=16540.0us expected=16475.7us +- 82.4us, error 0.4%
(kms_flip:5601) DEBUG: name = flip
last_ts = 400.177002
last_received_ts = 400.176636
last_seq = 198
current_ts = 400.193512
current_received_ts = 400.193268
current_seq = 199
count = 178
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 400.177002/198, current 400.193512/199: elapsed=16527.0us expected=16475.7us +- 82.4us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 400.193512
last_received_ts = 400.193268
last_seq = 199
current_ts = 400.210052
current_received_ts = 400.209778
current_seq = 200
count = 179
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 400.193512/199, current 400.210052/200: elapsed=16545.0us expected=16475.7us +- 82.4us, error 0.4%
(kms_flip:5601) DEBUG: name = flip
last_ts = 400.210052
last_received_ts = 400.209778
last_seq = 200
current_ts = 400.226593
current_received_ts = 400.226257
current_seq = 201
count = 180
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 400.210052/200, current 400.226593/201: elapsed=16527.0us expected=16475.7us +- 82.4us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 400.226593
last_received_ts = 400.226257
last_seq = 201
current_ts = 400.243134
current_received_ts = 400.242828
current_seq = 202
count = 181
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 400.226593/201, current 400.243134/202: elapsed=16548.0us expected=16475.7us +- 82.4us, error 0.4%
(kms_flip:5601) DEBUG: name = flip
last_ts = 400.243134
last_received_ts = 400.242828
last_seq = 202
current_ts = 400.259674
current_received_ts = 400.259308
current_seq = 203
count = 182
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 400.243134/202, current 400.259674/203: elapsed=16534.0us expected=16475.7us +- 82.4us, error 0.4%
(kms_flip:5601) DEBUG: name = flip
last_ts = 400.259674
last_received_ts = 400.259308
last_seq = 203
current_ts = 400.276215
current_received_ts = 400.275940
current_seq = 204
count = 183
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 400.259674/203, current 400.276215/204: elapsed=16532.0us expected=16475.7us +- 82.4us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 400.276215
last_received_ts = 400.275940
last_seq = 204
current_ts = 400.292755
current_received_ts = 400.292450
current_seq = 205
count = 184
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 400.276215/204, current 400.292755/205: elapsed=16542.0us expected=16475.7us +- 82.4us, error 0.4%
(kms_flip:5601) DEBUG: name = flip
last_ts = 400.292755
last_received_ts = 400.292450
last_seq = 205
current_ts = 400.309265
current_received_ts = 400.308960
current_seq = 206
count = 185
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 400.292755/205, current 400.309265/206: elapsed=16523.0us expected=16475.7us +- 82.4us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 400.309265
last_received_ts = 400.308960
last_seq = 206
current_ts = 400.325806
current_received_ts = 400.325470
current_seq = 207
count = 186
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 400.309265/206, current 400.325806/207: elapsed=16539.0us expected=16475.7us +- 82.4us, error 0.4%
(kms_flip:5601) DEBUG: name = flip
last_ts = 400.325806
last_received_ts = 400.325470
last_seq = 207
current_ts = 400.342346
current_received_ts = 400.342072
current_seq = 208
count = 187
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 400.325806/207, current 400.342346/208: elapsed=16535.0us expected=16475.7us +- 82.4us, error 0.4%
(kms_flip:5601) DEBUG: name = flip
last_ts = 400.342346
last_received_ts = 400.342072
last_seq = 208
current_ts = 400.358887
current_received_ts = 400.358521
current_seq = 209
count = 188
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 400.342346/208, current 400.358887/209: elapsed=16534.0us expected=16475.7us +- 82.4us, error 0.4%
(kms_flip:5601) DEBUG: name = flip
last_ts = 400.358887
last_received_ts = 400.358521
last_seq = 209
current_ts = 400.375427
current_received_ts = 400.375214
current_seq = 210
count = 189
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 400.358887/209, current 400.375427/210: elapsed=16540.0us expected=16475.7us +- 82.4us, error 0.4%
(kms_flip:5601) DEBUG: name = flip
last_ts = 400.375427
last_received_ts = 400.375214
last_seq = 210
current_ts = 400.391968
current_received_ts = 400.391541
current_seq = 211
count = 190
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 400.375427/210, current 400.391968/211: elapsed=16535.0us expected=16475.7us +- 82.4us, error 0.4%
(kms_flip:5601) DEBUG: name = flip
last_ts = 400.391968
last_received_ts = 400.391541
last_seq = 211
current_ts = 400.408478
current_received_ts = 400.408264
current_seq = 212
count = 191
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 400.391968/211, current 400.408478/212: elapsed=16536.0us expected=16475.7us +- 82.4us, error 0.4%
(kms_flip:5601) DEBUG: name = flip
last_ts = 400.408478
last_received_ts = 400.408264
last_seq = 212
current_ts = 400.425049
current_received_ts = 400.424683
current_seq = 213
count = 192
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 400.408478/212, current 400.425049/213: elapsed=16545.0us expected=16475.7us +- 82.4us, error 0.4%
(kms_flip:5601) DEBUG: name = flip
last_ts = 400.425049
last_received_ts = 400.424683
last_seq = 213
current_ts = 400.441559
current_received_ts = 400.441315
current_seq = 214
count = 193
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 400.425049/213, current 400.441559/214: elapsed=16536.0us expected=16475.7us +- 82.4us, error 0.4%
(kms_flip:5601) DEBUG: name = flip
last_ts = 400.441559
last_received_ts = 400.441315
last_seq = 214
current_ts = 400.458099
current_received_ts = 400.457764
current_seq = 215
count = 194
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 400.441559/214, current 400.458099/215: elapsed=16526.0us expected=16475.7us +- 82.4us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 400.458099
last_received_ts = 400.457764
last_seq = 215
current_ts = 400.474640
current_received_ts = 400.474365
current_seq = 216
count = 195
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 400.458099/215, current 400.474640/216: elapsed=16542.0us expected=16475.7us +- 82.4us, error 0.4%
(kms_flip:5601) DEBUG: name = flip
last_ts = 400.474640
last_received_ts = 400.474365
last_seq = 216
current_ts = 400.491180
current_received_ts = 400.490845
current_seq = 217
count = 196
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 400.474640/216, current 400.491180/217: elapsed=16535.0us expected=16475.7us +- 82.4us, error 0.4%
(kms_flip:5601) DEBUG: name = flip
last_ts = 400.491180
last_received_ts = 400.490845
last_seq = 217
current_ts = 400.507721
current_received_ts = 400.507294
current_seq = 218
count = 197
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 400.491180/217, current 400.507721/218: elapsed=16541.0us expected=16475.7us +- 82.4us, error 0.4%
(kms_flip:5601) DEBUG: name = flip
last_ts = 400.507721
last_received_ts = 400.507294
last_seq = 218
current_ts = 400.524261
current_received_ts = 400.523987
current_seq = 219
count = 198
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 400.507721/218, current 400.524261/219: elapsed=16536.0us expected=16475.7us +- 82.4us, error 0.4%
(kms_flip:5601) DEBUG: name = flip
last_ts = 400.524261
last_received_ts = 400.523987
last_seq = 219
current_ts = 400.540771
current_received_ts = 400.540405
current_seq = 220
count = 199
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 400.524261/219, current 400.540771/220: elapsed=16534.0us expected=16475.7us +- 82.4us, error 0.4%
(kms_flip:5601) DEBUG: name = flip
last_ts = 400.540771
last_received_ts = 400.540405
last_seq = 220
current_ts = 400.557312
current_received_ts = 400.557068
current_seq = 221
count = 200
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 400.540771/220, current 400.557312/221: elapsed=16532.0us expected=16475.7us +- 82.4us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 400.557312
last_received_ts = 400.557068
last_seq = 221
current_ts = 400.573853
current_received_ts = 400.573517
current_seq = 222
count = 201
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 400.557312/221, current 400.573853/222: elapsed=16536.0us expected=16475.7us +- 82.4us, error 0.4%
(kms_flip:5601) DEBUG: name = flip
last_ts = 400.573853
last_received_ts = 400.573517
last_seq = 222
current_ts = 400.590393
current_received_ts = 400.590118
current_seq = 223
count = 202
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 400.573853/222, current 400.590393/223: elapsed=16537.0us expected=16475.7us +- 82.4us, error 0.4%
(kms_flip:5601) DEBUG: name = flip
last_ts = 400.590393
last_received_ts = 400.590118
last_seq = 223
current_ts = 400.606934
current_received_ts = 400.606537
current_seq = 224
count = 203
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 400.590393/223, current 400.606934/224: elapsed=16533.0us expected=16475.7us +- 82.4us, error 0.3%
(kms_flip:5601) DEBUG: name = flip
last_ts = 400.606934
last_received_ts = 400.606537
last_seq = 224
current_ts = 400.623474
current_received_ts = 400.623230
current_seq = 225
count = 204
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 400.606934/224, current 400.623474/225: elapsed=16554.0us expected=16475.7us +- 82.4us, error 0.5%
(kms_flip:5601) DEBUG: name = flip
last_ts = 400.623474
last_received_ts = 400.623230
last_seq = 225
current_ts = 400.640045
current_received_ts = 400.639740
current_seq = 226
count = 205
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 400.623474/225, current 400.640045/226: elapsed=16554.0us expected=16475.7us +- 82.4us, error 0.5%
(kms_flip:5601) DEBUG: name = flip
last_ts = 400.640045
last_received_ts = 400.639740
last_seq = 226
current_ts = 400.656586
current_received_ts = 400.656250
current_seq = 227
count = 206
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 400.640045/226, current 400.656586/227: elapsed=16558.0us expected=16475.7us +- 82.4us, error 0.5%
(kms_flip:5601) DEBUG: name = flip
last_ts = 400.656586
last_received_ts = 400.656250
last_seq = 227
current_ts = 400.673126
current_received_ts = 400.672852
current_seq = 228
count = 207
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 400.656586/227, current 400.673126/228: elapsed=16549.0us expected=16475.7us +- 82.4us, error 0.4%
(kms_flip:5601) DEBUG: name = flip
last_ts = 400.673126
last_received_ts = 400.672852
last_seq = 228
current_ts = 400.689697
current_received_ts = 400.689392
current_seq = 229
count = 208
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 400.673126/228, current 400.689697/229: elapsed=16554.0us expected=16475.7us +- 82.4us, error 0.5%
(kms_flip:5601) DEBUG: name = flip
last_ts = 400.689697
last_received_ts = 400.689392
last_seq = 229
current_ts = 400.706238
current_received_ts = 400.705933
current_seq = 230
count = 209
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 400.689697/229, current 400.706238/230: elapsed=16540.0us expected=16475.7us +- 82.4us, error 0.4%
(kms_flip:5601) DEBUG: name = flip
last_ts = 400.706238
last_received_ts = 400.705933
last_seq = 230
current_ts = 400.722778
current_received_ts = 400.722412
current_seq = 231
count = 210
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 400.706238/230, current 400.722778/231: elapsed=16553.0us expected=16475.7us +- 82.4us, error 0.5%
(kms_flip:5601) DEBUG: name = flip
last_ts = 400.722778
last_received_ts = 400.722412
last_seq = 231
current_ts = 400.739349
current_received_ts = 400.739075
current_seq = 232
count = 211
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 400.722778/231, current 400.739349/232: elapsed=16556.0us expected=16475.7us +- 82.4us, error 0.5%
(kms_flip:5601) DEBUG: name = flip
last_ts = 400.739349
last_received_ts = 400.739075
last_seq = 232
current_ts = 400.755890
current_received_ts = 400.755493
current_seq = 233
count = 212
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 400.739349/232, current 400.755890/233: elapsed=16547.0us expected=16475.7us +- 82.4us, error 0.4%
(kms_flip:5601) DEBUG: name = flip
last_ts = 400.755890
last_received_ts = 400.755493
last_seq = 233
current_ts = 400.772461
current_received_ts = 400.772186
current_seq = 234
count = 213
seq_step = 1
(kms_flip:5601) DEBUG: flip ts/seq: last 400.755890/233, current 400.772461/234: elapsed=16561.0us expected=16475.7us +- 82.4us, error 0.5%
(kms_flip:5601) DEBUG: inconsistent flip ts/seq: last 400.755890/233, current 400.772461/234: elapsed=16561.0us expected=16475.7us
(kms_flip:5601) DEBUG: expected 0, counted 213, encoder type 2
(kms_flip:5601) DEBUG: dropped frames, expected 0, counted 213, encoder type 2
(kms_flip:5601) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1674:
(kms_flip:5601) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:5601) igt_core-INFO: Stack trace:
(kms_flip:5601) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:5601) igt_core-INFO:   #1 ../tests/kms_flip.c:791 run_test_on_crtc_set.constprop.0()
(kms_flip:5601) igt_core-INFO:   #2 ../tests/kms_flip.c:1845 run_test()
(kms_flip:5601) igt_core-INFO:   #3 ../tests/kms_flip.c:2078 __igt_unique____real_main2001()
(kms_flip:5601) igt_core-INFO:   #4 ../tests/kms_flip.c:2001 main()
(kms_flip:5601) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:5601) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:5601) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest C-HDMI-A1: FAIL (7.233s)
Starting dynamic subtest: D-HDMI-A1
Dynamic subtest D-HDMI-A1: SUCCESS (7.962s)
Subtest plain-flip-fb-recreate: FAIL (30.013s)