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

IGT-Version: 2.1-g8a840cd64 (x86_64) (Linux: 6.17.0-rc3-lgci-xe-xe-3643-99f4b32d88cb9718c+ x86_64)

Using IGT_SRANDOM=1756524157 for randomisation
Opened device: /dev/dri/card0
Using monotonic timestamps
Starting subtest: plain-flip-fb-recreate
Starting dynamic subtest: A-eDP1
  2560x1600: 240 1175040 2560 2608 2640 2720 1600 1663 1669 1800 0x48 0xa 
Expected frametime: 4167us; measured 4166.7us +- 1.138us accuracy 0.08%
Event flip: expected 2401, counted 1215, passrate = 2.39%, encoder type 2
Expected frametime: 4167us; measured 4166.7us +- 0.946us accuracy 0.07%
Event flip: expected 2400, counted 1214, passrate = 2.31%, encoder type 2
Stack trace:
  #0 ../lib/igt_core.c:2075 __igt_fail_assert()
  #1 ../tests/kms_flip.c:973 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1884 run_test()
  #3 ../tests/kms_flip.c:2117 __igt_unique____real_main2040()
  #4 ../tests/kms_flip.c:2040 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest A-eDP1: FAIL (25.980s)
Starting dynamic subtest: B-eDP1
  2560x1600: 240 1175040 2560 2608 2640 2720 1600 1663 1669 1800 0x48 0xa 
Expected frametime: 4167us; measured 4166.7us +- 1.138us accuracy 0.08%
Event flip: expected 2400, counted 1209, passrate = 1.49%, encoder type 2
Expected frametime: 4167us; measured 4166.8us +- 1.167us accuracy 0.08%
Event flip: expected 2400, counted 1207, passrate = 1.16%, encoder type 2
Stack trace:
  #0 ../lib/igt_core.c:2075 __igt_fail_assert()
  #1 ../tests/kms_flip.c:973 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1884 run_test()
  #3 ../tests/kms_flip.c:2117 __igt_unique____real_main2040()
  #4 ../tests/kms_flip.c:2040 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest B-eDP1: FAIL (26.043s)
Starting dynamic subtest: C-eDP1
  2560x1600: 240 1175040 2560 2608 2640 2720 1600 1663 1669 1800 0x48 0xa 
Expected frametime: 4167us; measured 4166.9us +- 1.360us accuracy 0.10%
Event flip: expected 2399, counted 1214, passrate = 2.47%, encoder type 2
Expected frametime: 4167us; measured 4166.7us +- 1.138us accuracy 0.08%
Event flip: expected 2400, counted 1212, passrate = 2.06%, encoder type 2
Stack trace:
  #0 ../lib/igt_core.c:2075 __igt_fail_assert()
  #1 ../tests/kms_flip.c:973 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1884 run_test()
  #3 ../tests/kms_flip.c:2117 __igt_unique____real_main2040()
  #4 ../tests/kms_flip.c:2040 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest C-eDP1: FAIL (26.065s)
Subtest plain-flip-fb-recreate: FAIL (78.096s)
Stack trace:
  #0 ../lib/igt_core.c:2075 __igt_fail_assert()
  #1 ../lib/igt_kms.c:2247 kmstest_set_connector_dpms()
  #2 ../lib/igt_core.c:2961 igt_atexit_handler()
  #3 [erand48_r+0x1d6]
  #4 [exit+0x1e]
  #5 ../lib/igt_core.c:2416 igt_exit()
  #6 [main+0x3f]
  #7 [__libc_init_first+0x8a]
  #8 [__libc_start_main+0x8b]
  #9 [_start+0x25]

Starting subtest: plain-flip-fb-recreate
Starting dynamic subtest: A-eDP1
(kms_flip:2459) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1704:
(kms_flip:2459) CRITICAL: Failed assertion: !retried
Dynamic subtest A-eDP1 failed.
**** DEBUG ****
(kms_flip:2459) DEBUG: name = flip
last_ts = 227.506714
last_received_ts = 227.506302
last_seq = 5379
current_ts = 227.515045
current_received_ts = 227.514694
current_seq = 5381
count = 1132
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 227.506714/5379, current 227.515045/5381: elapsed=8334.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5381, expected 5380
(kms_flip:2459) DEBUG: name = flip
last_ts = 227.515045
last_received_ts = 227.514694
last_seq = 5381
current_ts = 227.523376
current_received_ts = 227.523056
current_seq = 5383
count = 1133
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 227.515045/5381, current 227.523376/5383: elapsed=8332.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5383, expected 5382
(kms_flip:2459) DEBUG: name = flip
last_ts = 227.523376
last_received_ts = 227.523056
last_seq = 5383
current_ts = 227.531708
current_received_ts = 227.531296
current_seq = 5385
count = 1134
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 227.523376/5383, current 227.531708/5385: elapsed=8333.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5385, expected 5384
(kms_flip:2459) DEBUG: name = flip
last_ts = 227.531708
last_received_ts = 227.531296
last_seq = 5385
current_ts = 227.540039
current_received_ts = 227.539673
current_seq = 5387
count = 1135
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 227.531708/5385, current 227.540039/5387: elapsed=8333.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5387, expected 5386
(kms_flip:2459) DEBUG: name = flip
last_ts = 227.540039
last_received_ts = 227.539673
last_seq = 5387
current_ts = 227.548370
current_received_ts = 227.548050
current_seq = 5389
count = 1136
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 227.540039/5387, current 227.548370/5389: elapsed=8334.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5389, expected 5388
(kms_flip:2459) DEBUG: name = flip
last_ts = 227.548370
last_received_ts = 227.548050
last_seq = 5389
current_ts = 227.556702
current_received_ts = 227.556335
current_seq = 5391
count = 1137
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 227.548370/5389, current 227.556702/5391: elapsed=8334.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5391, expected 5390
(kms_flip:2459) DEBUG: name = flip
last_ts = 227.556702
last_received_ts = 227.556335
last_seq = 5391
current_ts = 227.565048
current_received_ts = 227.564682
current_seq = 5393
count = 1138
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 227.556702/5391, current 227.565048/5393: elapsed=8332.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5393, expected 5392
(kms_flip:2459) DEBUG: name = flip
last_ts = 227.565048
last_received_ts = 227.564682
last_seq = 5393
current_ts = 227.573380
current_received_ts = 227.573044
current_seq = 5395
count = 1139
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 227.565048/5393, current 227.573380/5395: elapsed=8333.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5395, expected 5394
(kms_flip:2459) DEBUG: name = flip
last_ts = 227.573380
last_received_ts = 227.573044
last_seq = 5395
current_ts = 227.581711
current_received_ts = 227.581314
current_seq = 5397
count = 1140
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 227.573380/5395, current 227.581711/5397: elapsed=8334.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5397, expected 5396
(kms_flip:2459) DEBUG: name = flip
last_ts = 227.581711
last_received_ts = 227.581314
last_seq = 5397
current_ts = 227.590042
current_received_ts = 227.589691
current_seq = 5399
count = 1141
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 227.581711/5397, current 227.590042/5399: elapsed=8333.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5399, expected 5398
(kms_flip:2459) DEBUG: name = flip
last_ts = 227.590042
last_received_ts = 227.589691
last_seq = 5399
current_ts = 227.598373
current_received_ts = 227.598022
current_seq = 5401
count = 1142
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 227.590042/5399, current 227.598373/5401: elapsed=8333.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5401, expected 5400
(kms_flip:2459) DEBUG: name = flip
last_ts = 227.598373
last_received_ts = 227.598022
last_seq = 5401
current_ts = 227.606705
current_received_ts = 227.606293
current_seq = 5403
count = 1143
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 227.598373/5401, current 227.606705/5403: elapsed=8334.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5403, expected 5402
(kms_flip:2459) DEBUG: name = flip
last_ts = 227.606705
last_received_ts = 227.606293
last_seq = 5403
current_ts = 227.615036
current_received_ts = 227.614685
current_seq = 5405
count = 1144
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 227.606705/5403, current 227.615036/5405: elapsed=8333.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5405, expected 5404
(kms_flip:2459) DEBUG: name = flip
last_ts = 227.615036
last_received_ts = 227.614685
last_seq = 5405
current_ts = 227.623367
current_received_ts = 227.623047
current_seq = 5407
count = 1145
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 227.615036/5405, current 227.623367/5407: elapsed=8333.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5407, expected 5406
(kms_flip:2459) DEBUG: name = flip
last_ts = 227.623367
last_received_ts = 227.623047
last_seq = 5407
current_ts = 227.631714
current_received_ts = 227.631302
current_seq = 5409
count = 1146
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 227.623367/5407, current 227.631714/5409: elapsed=8334.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5409, expected 5408
(kms_flip:2459) DEBUG: name = flip
last_ts = 227.631714
last_received_ts = 227.631302
last_seq = 5409
current_ts = 227.640045
current_received_ts = 227.639694
current_seq = 5411
count = 1147
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 227.631714/5409, current 227.640045/5411: elapsed=8333.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5411, expected 5410
(kms_flip:2459) DEBUG: name = flip
last_ts = 227.640045
last_received_ts = 227.639694
last_seq = 5411
current_ts = 227.648376
current_received_ts = 227.648041
current_seq = 5413
count = 1148
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 227.640045/5411, current 227.648376/5413: elapsed=8333.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5413, expected 5412
(kms_flip:2459) DEBUG: name = flip
last_ts = 227.648376
last_received_ts = 227.648041
last_seq = 5413
current_ts = 227.656708
current_received_ts = 227.656296
current_seq = 5415
count = 1149
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 227.648376/5413, current 227.656708/5415: elapsed=8334.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5415, expected 5414
(kms_flip:2459) DEBUG: name = flip
last_ts = 227.656708
last_received_ts = 227.656296
last_seq = 5415
current_ts = 227.665039
current_received_ts = 227.664703
current_seq = 5417
count = 1150
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 227.656708/5415, current 227.665039/5417: elapsed=8333.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5417, expected 5416
(kms_flip:2459) DEBUG: name = flip
last_ts = 227.665039
last_received_ts = 227.664703
last_seq = 5417
current_ts = 227.673370
current_received_ts = 227.673035
current_seq = 5419
count = 1151
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 227.665039/5417, current 227.673370/5419: elapsed=8334.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5419, expected 5418
(kms_flip:2459) DEBUG: name = flip
last_ts = 227.673370
last_received_ts = 227.673035
last_seq = 5419
current_ts = 227.681702
current_received_ts = 227.681290
current_seq = 5421
count = 1152
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 227.673370/5419, current 227.681702/5421: elapsed=8333.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5421, expected 5420
(kms_flip:2459) DEBUG: name = flip
last_ts = 227.681702
last_received_ts = 227.681290
last_seq = 5421
current_ts = 227.690048
current_received_ts = 227.689697
current_seq = 5423
count = 1153
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 227.681702/5421, current 227.690048/5423: elapsed=8333.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5423, expected 5422
(kms_flip:2459) DEBUG: name = flip
last_ts = 227.690048
last_received_ts = 227.689697
last_seq = 5423
current_ts = 227.698380
current_received_ts = 227.698044
current_seq = 5425
count = 1154
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 227.690048/5423, current 227.698380/5425: elapsed=8334.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5425, expected 5424
(kms_flip:2459) DEBUG: name = flip
last_ts = 227.698380
last_received_ts = 227.698044
last_seq = 5425
current_ts = 227.706711
current_received_ts = 227.706329
current_seq = 5427
count = 1155
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 227.698380/5425, current 227.706711/5427: elapsed=8333.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5427, expected 5426
(kms_flip:2459) DEBUG: name = flip
last_ts = 227.706711
last_received_ts = 227.706329
last_seq = 5427
current_ts = 227.715042
current_received_ts = 227.714691
current_seq = 5429
count = 1156
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 227.706711/5427, current 227.715042/5429: elapsed=8333.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5429, expected 5428
(kms_flip:2459) DEBUG: name = flip
last_ts = 227.715042
last_received_ts = 227.714691
last_seq = 5429
current_ts = 227.723373
current_received_ts = 227.723053
current_seq = 5431
count = 1157
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 227.715042/5429, current 227.723373/5431: elapsed=8333.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5431, expected 5430
(kms_flip:2459) DEBUG: name = flip
last_ts = 227.723373
last_received_ts = 227.723053
last_seq = 5431
current_ts = 227.731705
current_received_ts = 227.731293
current_seq = 5433
count = 1158
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 227.723373/5431, current 227.731705/5433: elapsed=8334.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5433, expected 5432
(kms_flip:2459) DEBUG: name = flip
last_ts = 227.731705
last_received_ts = 227.731293
last_seq = 5433
current_ts = 227.740036
current_received_ts = 227.739685
current_seq = 5435
count = 1159
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 227.731705/5433, current 227.740036/5435: elapsed=8333.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5435, expected 5434
(kms_flip:2459) DEBUG: name = flip
last_ts = 227.740036
last_received_ts = 227.739685
last_seq = 5435
current_ts = 227.748383
current_received_ts = 227.748032
current_seq = 5437
count = 1160
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 227.740036/5435, current 227.748383/5437: elapsed=8334.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5437, expected 5436
(kms_flip:2459) DEBUG: name = flip
last_ts = 227.748383
last_received_ts = 227.748032
last_seq = 5437
current_ts = 227.752548
current_received_ts = 227.752121
current_seq = 5438
count = 1161
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 227.748383/5437, current 227.752548/5438: elapsed=4166.0us expected=4166.7us +- 20.8us, error 0.0%
(kms_flip:2459) DEBUG: name = flip
last_ts = 227.752548
last_received_ts = 227.752121
last_seq = 5438
current_ts = 227.756714
current_received_ts = 227.756317
current_seq = 5439
count = 1162
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 227.752548/5438, current 227.756714/5439: elapsed=4167.0us expected=4166.7us +- 20.8us, error 0.0%
(kms_flip:2459) DEBUG: name = flip
last_ts = 227.756714
last_received_ts = 227.756317
last_seq = 5439
current_ts = 227.765045
current_received_ts = 227.764694
current_seq = 5441
count = 1163
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 227.756714/5439, current 227.765045/5441: elapsed=8333.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5441, expected 5440
(kms_flip:2459) DEBUG: name = flip
last_ts = 227.765045
last_received_ts = 227.764694
last_seq = 5441
current_ts = 227.773376
current_received_ts = 227.773041
current_seq = 5443
count = 1164
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 227.765045/5441, current 227.773376/5443: elapsed=8334.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5443, expected 5442
(kms_flip:2459) DEBUG: name = flip
last_ts = 227.773376
last_received_ts = 227.773041
last_seq = 5443
current_ts = 227.781708
current_received_ts = 227.781311
current_seq = 5445
count = 1165
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 227.773376/5443, current 227.781708/5445: elapsed=8333.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5445, expected 5444
(kms_flip:2459) DEBUG: name = flip
last_ts = 227.781708
last_received_ts = 227.781311
last_seq = 5445
current_ts = 227.790039
current_received_ts = 227.789688
current_seq = 5447
count = 1166
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 227.781708/5445, current 227.790039/5447: elapsed=8333.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5447, expected 5446
(kms_flip:2459) DEBUG: name = flip
last_ts = 227.790039
last_received_ts = 227.789688
last_seq = 5447
current_ts = 227.798370
current_received_ts = 227.798050
current_seq = 5449
count = 1167
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 227.790039/5447, current 227.798370/5449: elapsed=8333.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5449, expected 5448
(kms_flip:2459) DEBUG: name = flip
last_ts = 227.798370
last_received_ts = 227.798050
last_seq = 5449
current_ts = 227.806702
current_received_ts = 227.806305
current_seq = 5451
count = 1168
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 227.798370/5449, current 227.806702/5451: elapsed=8333.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5451, expected 5450
(kms_flip:2459) DEBUG: name = flip
last_ts = 227.806702
last_received_ts = 227.806305
last_seq = 5451
current_ts = 227.815048
current_received_ts = 227.814697
current_seq = 5453
count = 1169
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 227.806702/5451, current 227.815048/5453: elapsed=8334.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5453, expected 5452
(kms_flip:2459) DEBUG: name = flip
last_ts = 227.815048
last_received_ts = 227.814697
last_seq = 5453
current_ts = 227.823380
current_received_ts = 227.823044
current_seq = 5455
count = 1170
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 227.815048/5453, current 227.823380/5455: elapsed=8334.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5455, expected 5454
(kms_flip:2459) DEBUG: name = flip
last_ts = 227.823380
last_received_ts = 227.823044
last_seq = 5455
current_ts = 227.831711
current_received_ts = 227.831299
current_seq = 5457
count = 1171
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 227.823380/5455, current 227.831711/5457: elapsed=8333.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5457, expected 5456
(kms_flip:2459) DEBUG: name = flip
last_ts = 227.831711
last_received_ts = 227.831299
last_seq = 5457
current_ts = 227.840042
current_received_ts = 227.839691
current_seq = 5459
count = 1172
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 227.831711/5457, current 227.840042/5459: elapsed=8334.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5459, expected 5458
(kms_flip:2459) DEBUG: name = flip
last_ts = 227.840042
last_received_ts = 227.839691
last_seq = 5459
current_ts = 227.848373
current_received_ts = 227.848053
current_seq = 5461
count = 1173
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 227.840042/5459, current 227.848373/5461: elapsed=8334.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5461, expected 5460
(kms_flip:2459) DEBUG: name = flip
last_ts = 227.848373
last_received_ts = 227.848053
last_seq = 5461
current_ts = 227.856705
current_received_ts = 227.856293
current_seq = 5463
count = 1174
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 227.848373/5461, current 227.856705/5463: elapsed=8332.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5463, expected 5462
(kms_flip:2459) DEBUG: name = flip
last_ts = 227.856705
last_received_ts = 227.856293
last_seq = 5463
current_ts = 227.865036
current_received_ts = 227.864700
current_seq = 5465
count = 1175
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 227.856705/5463, current 227.865036/5465: elapsed=8333.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5465, expected 5464
(kms_flip:2459) DEBUG: name = flip
last_ts = 227.865036
last_received_ts = 227.864700
last_seq = 5465
current_ts = 227.873383
current_received_ts = 227.873047
current_seq = 5467
count = 1176
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 227.865036/5465, current 227.873383/5467: elapsed=8334.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5467, expected 5466
(kms_flip:2459) DEBUG: name = flip
last_ts = 227.873383
last_received_ts = 227.873047
last_seq = 5467
current_ts = 227.881714
current_received_ts = 227.881302
current_seq = 5469
count = 1177
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 227.873383/5467, current 227.881714/5469: elapsed=8332.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5469, expected 5468
(kms_flip:2459) DEBUG: name = flip
last_ts = 227.881714
last_received_ts = 227.881302
last_seq = 5469
current_ts = 227.890045
current_received_ts = 227.889694
current_seq = 5471
count = 1178
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 227.881714/5469, current 227.890045/5471: elapsed=8334.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5471, expected 5470
(kms_flip:2459) DEBUG: name = flip
last_ts = 227.890045
last_received_ts = 227.889694
last_seq = 5471
current_ts = 227.898376
current_received_ts = 227.898026
current_seq = 5473
count = 1179
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 227.890045/5471, current 227.898376/5473: elapsed=8333.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5473, expected 5472
(kms_flip:2459) DEBUG: name = flip
last_ts = 227.898376
last_received_ts = 227.898026
last_seq = 5473
current_ts = 227.906708
current_received_ts = 227.906296
current_seq = 5475
count = 1180
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 227.898376/5473, current 227.906708/5475: elapsed=8335.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5475, expected 5474
(kms_flip:2459) DEBUG: name = flip
last_ts = 227.906708
last_received_ts = 227.906296
last_seq = 5475
current_ts = 227.915039
current_received_ts = 227.914673
current_seq = 5477
count = 1181
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 227.906708/5475, current 227.915039/5477: elapsed=8332.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5477, expected 5476
(kms_flip:2459) DEBUG: name = flip
last_ts = 227.915039
last_received_ts = 227.914673
last_seq = 5477
current_ts = 227.919205
current_received_ts = 227.918869
current_seq = 5478
count = 1182
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 227.915039/5477, current 227.919205/5478: elapsed=4167.0us expected=4166.7us +- 20.8us, error 0.0%
(kms_flip:2459) DEBUG: name = flip
last_ts = 227.919205
last_received_ts = 227.918869
last_seq = 5478
current_ts = 227.923370
current_received_ts = 227.923050
current_seq = 5479
count = 1183
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 227.919205/5478, current 227.923370/5479: elapsed=4168.0us expected=4166.7us +- 20.8us, error 0.0%
(kms_flip:2459) DEBUG: name = flip
last_ts = 227.923370
last_received_ts = 227.923050
last_seq = 5479
current_ts = 227.931702
current_received_ts = 227.931335
current_seq = 5481
count = 1184
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 227.923370/5479, current 227.931702/5481: elapsed=8332.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5481, expected 5480
(kms_flip:2459) DEBUG: name = flip
last_ts = 227.931702
last_received_ts = 227.931335
last_seq = 5481
current_ts = 227.940048
current_received_ts = 227.939713
current_seq = 5483
count = 1185
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 227.931702/5481, current 227.940048/5483: elapsed=8334.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5483, expected 5482
(kms_flip:2459) DEBUG: name = flip
last_ts = 227.940048
last_received_ts = 227.939713
last_seq = 5483
current_ts = 227.948380
current_received_ts = 227.948074
current_seq = 5485
count = 1186
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 227.940048/5483, current 227.948380/5485: elapsed=8333.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5485, expected 5484
(kms_flip:2459) DEBUG: name = flip
last_ts = 227.948380
last_received_ts = 227.948074
last_seq = 5485
current_ts = 227.956711
current_received_ts = 227.956314
current_seq = 5487
count = 1187
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 227.948380/5485, current 227.956711/5487: elapsed=8334.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5487, expected 5486
(kms_flip:2459) DEBUG: name = flip
last_ts = 227.956711
last_received_ts = 227.956314
last_seq = 5487
current_ts = 227.965042
current_received_ts = 227.964691
current_seq = 5489
count = 1188
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 227.956711/5487, current 227.965042/5489: elapsed=8333.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5489, expected 5488
(kms_flip:2459) DEBUG: name = flip
last_ts = 227.965042
last_received_ts = 227.964691
last_seq = 5489
current_ts = 227.973373
current_received_ts = 227.973038
current_seq = 5491
count = 1189
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 227.965042/5489, current 227.973373/5491: elapsed=8332.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5491, expected 5490
(kms_flip:2459) DEBUG: name = flip
last_ts = 227.973373
last_received_ts = 227.973038
last_seq = 5491
current_ts = 227.981705
current_received_ts = 227.981308
current_seq = 5493
count = 1190
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 227.973373/5491, current 227.981705/5493: elapsed=8334.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5493, expected 5492
(kms_flip:2459) DEBUG: name = flip
last_ts = 227.981705
last_received_ts = 227.981308
last_seq = 5493
current_ts = 227.990036
current_received_ts = 227.989700
current_seq = 5495
count = 1191
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 227.981705/5493, current 227.990036/5495: elapsed=8333.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5495, expected 5494
(kms_flip:2459) DEBUG: name = flip
last_ts = 227.990036
last_received_ts = 227.989700
last_seq = 5495
current_ts = 227.998383
current_received_ts = 227.998047
current_seq = 5497
count = 1192
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 227.990036/5495, current 227.998383/5497: elapsed=8334.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5497, expected 5496
(kms_flip:2459) DEBUG: name = flip
last_ts = 227.998383
last_received_ts = 227.998047
last_seq = 5497
current_ts = 228.006714
current_received_ts = 228.006317
current_seq = 5499
count = 1193
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 227.998383/5497, current 228.006714/5499: elapsed=8334.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5499, expected 5498
(kms_flip:2459) DEBUG: name = flip
last_ts = 228.006714
last_received_ts = 228.006317
last_seq = 5499
current_ts = 228.015045
current_received_ts = 228.014694
current_seq = 5501
count = 1194
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 228.006714/5499, current 228.015045/5501: elapsed=8333.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5501, expected 5500
(kms_flip:2459) DEBUG: name = flip
last_ts = 228.015045
last_received_ts = 228.014694
last_seq = 5501
current_ts = 228.023376
current_received_ts = 228.023026
current_seq = 5503
count = 1195
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 228.015045/5501, current 228.023376/5503: elapsed=8333.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5503, expected 5502
(kms_flip:2459) DEBUG: name = flip
last_ts = 228.023376
last_received_ts = 228.023026
last_seq = 5503
current_ts = 228.031708
current_received_ts = 228.031296
current_seq = 5505
count = 1196
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 228.023376/5503, current 228.031708/5505: elapsed=8334.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5505, expected 5504
(kms_flip:2459) DEBUG: name = flip
last_ts = 228.031708
last_received_ts = 228.031296
last_seq = 5505
current_ts = 228.040039
current_received_ts = 228.039703
current_seq = 5507
count = 1197
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 228.031708/5505, current 228.040039/5507: elapsed=8334.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5507, expected 5506
(kms_flip:2459) DEBUG: name = flip
last_ts = 228.040039
last_received_ts = 228.039703
last_seq = 5507
current_ts = 228.048370
current_received_ts = 228.048050
current_seq = 5509
count = 1198
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 228.040039/5507, current 228.048370/5509: elapsed=8333.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5509, expected 5508
(kms_flip:2459) DEBUG: name = flip
last_ts = 228.048370
last_received_ts = 228.048050
last_seq = 5509
current_ts = 228.056702
current_received_ts = 228.056320
current_seq = 5511
count = 1199
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 228.048370/5509, current 228.056702/5511: elapsed=8331.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5511, expected 5510
(kms_flip:2459) DEBUG: name = flip
last_ts = 228.056702
last_received_ts = 228.056320
last_seq = 5511
current_ts = 228.065048
current_received_ts = 228.064697
current_seq = 5513
count = 1200
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 228.056702/5511, current 228.065048/5513: elapsed=8334.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5513, expected 5512
(kms_flip:2459) DEBUG: name = flip
last_ts = 228.065048
last_received_ts = 228.064697
last_seq = 5513
current_ts = 228.073380
current_received_ts = 228.073044
current_seq = 5515
count = 1201
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 228.065048/5513, current 228.073380/5515: elapsed=8334.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5515, expected 5514
(kms_flip:2459) DEBUG: name = flip
last_ts = 228.073380
last_received_ts = 228.073044
last_seq = 5515
current_ts = 228.081711
current_received_ts = 228.081329
current_seq = 5517
count = 1202
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 228.073380/5515, current 228.081711/5517: elapsed=8332.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5517, expected 5516
(kms_flip:2459) DEBUG: name = flip
last_ts = 228.081711
last_received_ts = 228.081329
last_seq = 5517
current_ts = 228.090042
current_received_ts = 228.089691
current_seq = 5519
count = 1203
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 228.081711/5517, current 228.090042/5519: elapsed=8336.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5519, expected 5518
(kms_flip:2459) DEBUG: name = flip
last_ts = 228.090042
last_received_ts = 228.089691
last_seq = 5519
current_ts = 228.098373
current_received_ts = 228.098022
current_seq = 5521
count = 1204
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 228.090042/5519, current 228.098373/5521: elapsed=8332.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5521, expected 5520
(kms_flip:2459) DEBUG: name = flip
last_ts = 228.098373
last_received_ts = 228.098022
last_seq = 5521
current_ts = 228.106705
current_received_ts = 228.106293
current_seq = 5523
count = 1205
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 228.098373/5521, current 228.106705/5523: elapsed=8332.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5523, expected 5522
(kms_flip:2459) DEBUG: name = flip
last_ts = 228.106705
last_received_ts = 228.106293
last_seq = 5523
current_ts = 228.115036
current_received_ts = 228.114700
current_seq = 5525
count = 1206
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 228.106705/5523, current 228.115036/5525: elapsed=8334.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5525, expected 5524
(kms_flip:2459) DEBUG: name = flip
last_ts = 228.115036
last_received_ts = 228.114700
last_seq = 5525
current_ts = 228.123383
current_received_ts = 228.123047
current_seq = 5527
count = 1207
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 228.115036/5525, current 228.123383/5527: elapsed=8335.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5527, expected 5526
(kms_flip:2459) DEBUG: name = flip
last_ts = 228.123383
last_received_ts = 228.123047
last_seq = 5527
current_ts = 228.131714
current_received_ts = 228.131302
current_seq = 5529
count = 1208
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 228.123383/5527, current 228.131714/5529: elapsed=8333.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5529, expected 5528
(kms_flip:2459) DEBUG: name = flip
last_ts = 228.131714
last_received_ts = 228.131302
last_seq = 5529
current_ts = 228.140045
current_received_ts = 228.139694
current_seq = 5531
count = 1209
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 228.131714/5529, current 228.140045/5531: elapsed=8332.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5531, expected 5530
(kms_flip:2459) DEBUG: name = flip
last_ts = 228.140045
last_received_ts = 228.139694
last_seq = 5531
current_ts = 228.148376
current_received_ts = 228.148026
current_seq = 5533
count = 1210
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 228.140045/5531, current 228.148376/5533: elapsed=8334.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5533, expected 5532
(kms_flip:2459) DEBUG: name = flip
last_ts = 228.148376
last_received_ts = 228.148026
last_seq = 5533
current_ts = 228.156708
current_received_ts = 228.156296
current_seq = 5535
count = 1211
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 228.148376/5533, current 228.156708/5535: elapsed=8332.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5535, expected 5534
(kms_flip:2459) DEBUG: name = flip
last_ts = 228.156708
last_received_ts = 228.156296
last_seq = 5535
current_ts = 228.165039
current_received_ts = 228.164688
current_seq = 5537
count = 1212
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 228.156708/5535, current 228.165039/5537: elapsed=8334.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5537, expected 5536
(kms_flip:2459) DEBUG: name = flip
last_ts = 228.165039
last_received_ts = 228.164688
last_seq = 5537
current_ts = 228.173370
current_received_ts = 228.173035
current_seq = 5539
count = 1213
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 228.165039/5537, current 228.173370/5539: elapsed=8335.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5539, expected 5538
(kms_flip:2459) INFO: Event flip: expected 2400, counted 1214, passrate = 2.31%, encoder type 2
(kms_flip:2459) DEBUG: dropped frames, expected 2400, counted 1214, passrate = 2.31%, encoder type 2
(kms_flip:2459) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1704:
(kms_flip:2459) CRITICAL: Failed assertion: !retried
(kms_flip:2459) igt_core-INFO: Stack trace:
(kms_flip:2459) igt_core-INFO:   #0 ../lib/igt_core.c:2075 __igt_fail_assert()
(kms_flip:2459) igt_core-INFO:   #1 ../tests/kms_flip.c:973 run_test_on_crtc_set.constprop.0()
(kms_flip:2459) igt_core-INFO:   #2 ../tests/kms_flip.c:1884 run_test()
(kms_flip:2459) igt_core-INFO:   #3 ../tests/kms_flip.c:2117 __igt_unique____real_main2040()
(kms_flip:2459) igt_core-INFO:   #4 ../tests/kms_flip.c:2040 main()
(kms_flip:2459) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2459) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2459) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest A-eDP1: FAIL (25.980s)
Starting dynamic subtest: B-eDP1
(kms_flip:2459) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1704:
(kms_flip:2459) CRITICAL: Failed assertion: !retried
Dynamic subtest B-eDP1 failed.
**** DEBUG ****
(kms_flip:2459) DEBUG: flip ts/seq: last 253.543167/5117, current 253.551498/5119: elapsed=8332.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5119, expected 5118
(kms_flip:2459) DEBUG: name = flip
last_ts = 253.551498
last_received_ts = 253.551117
last_seq = 5119
current_ts = 253.559845
current_received_ts = 253.559494
current_seq = 5121
count = 1127
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 253.551498/5119, current 253.559845/5121: elapsed=8335.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5121, expected 5120
(kms_flip:2459) DEBUG: name = flip
last_ts = 253.559845
last_received_ts = 253.559494
last_seq = 5121
current_ts = 253.568176
current_received_ts = 253.567810
current_seq = 5123
count = 1128
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 253.559845/5121, current 253.568176/5123: elapsed=8334.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5123, expected 5122
(kms_flip:2459) DEBUG: name = flip
last_ts = 253.568176
last_received_ts = 253.567810
last_seq = 5123
current_ts = 253.576508
current_received_ts = 253.576096
current_seq = 5125
count = 1129
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 253.568176/5123, current 253.576508/5125: elapsed=8334.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5125, expected 5124
(kms_flip:2459) DEBUG: name = flip
last_ts = 253.576508
last_received_ts = 253.576096
last_seq = 5125
current_ts = 253.584839
current_received_ts = 253.584488
current_seq = 5127
count = 1130
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 253.576508/5125, current 253.584839/5127: elapsed=8335.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5127, expected 5126
(kms_flip:2459) DEBUG: name = flip
last_ts = 253.584839
last_received_ts = 253.584488
last_seq = 5127
current_ts = 253.593170
current_received_ts = 253.592834
current_seq = 5129
count = 1131
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 253.584839/5127, current 253.593170/5129: elapsed=8332.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5129, expected 5128
(kms_flip:2459) DEBUG: name = flip
last_ts = 253.593170
last_received_ts = 253.592834
last_seq = 5129
current_ts = 253.601501
current_received_ts = 253.601105
current_seq = 5131
count = 1132
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 253.593170/5129, current 253.601501/5131: elapsed=8335.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5131, expected 5130
(kms_flip:2459) DEBUG: name = flip
last_ts = 253.601501
last_received_ts = 253.601105
last_seq = 5131
current_ts = 253.609848
current_received_ts = 253.609497
current_seq = 5133
count = 1133
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 253.601501/5131, current 253.609848/5133: elapsed=8333.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5133, expected 5132
(kms_flip:2459) DEBUG: name = flip
last_ts = 253.609848
last_received_ts = 253.609497
last_seq = 5133
current_ts = 253.618179
current_received_ts = 253.617828
current_seq = 5135
count = 1134
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 253.609848/5133, current 253.618179/5135: elapsed=8333.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5135, expected 5134
(kms_flip:2459) DEBUG: name = flip
last_ts = 253.618179
last_received_ts = 253.617828
last_seq = 5135
current_ts = 253.626511
current_received_ts = 253.626114
current_seq = 5137
count = 1135
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 253.618179/5135, current 253.626511/5137: elapsed=8335.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5137, expected 5136
(kms_flip:2459) DEBUG: name = flip
last_ts = 253.626511
last_received_ts = 253.626114
last_seq = 5137
current_ts = 253.634842
current_received_ts = 253.634506
current_seq = 5139
count = 1136
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 253.626511/5137, current 253.634842/5139: elapsed=8332.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5139, expected 5138
(kms_flip:2459) DEBUG: name = flip
last_ts = 253.634842
last_received_ts = 253.634506
last_seq = 5139
current_ts = 253.643173
current_received_ts = 253.642838
current_seq = 5141
count = 1137
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 253.634842/5139, current 253.643173/5141: elapsed=8336.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5141, expected 5140
(kms_flip:2459) DEBUG: name = flip
last_ts = 253.643173
last_received_ts = 253.642838
last_seq = 5141
current_ts = 253.651505
current_received_ts = 253.651108
current_seq = 5143
count = 1138
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 253.643173/5141, current 253.651505/5143: elapsed=8333.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5143, expected 5142
(kms_flip:2459) DEBUG: name = flip
last_ts = 253.651505
last_received_ts = 253.651108
last_seq = 5143
current_ts = 253.659851
current_received_ts = 253.659500
current_seq = 5145
count = 1139
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 253.651505/5143, current 253.659851/5145: elapsed=8334.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5145, expected 5144
(kms_flip:2459) DEBUG: name = flip
last_ts = 253.659851
last_received_ts = 253.659500
last_seq = 5145
current_ts = 253.668182
current_received_ts = 253.667831
current_seq = 5147
count = 1140
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 253.659851/5145, current 253.668182/5147: elapsed=8333.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5147, expected 5146
(kms_flip:2459) DEBUG: name = flip
last_ts = 253.668182
last_received_ts = 253.667831
last_seq = 5147
current_ts = 253.676514
current_received_ts = 253.676117
current_seq = 5149
count = 1141
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 253.668182/5147, current 253.676514/5149: elapsed=8333.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5149, expected 5148
(kms_flip:2459) DEBUG: name = flip
last_ts = 253.676514
last_received_ts = 253.676117
last_seq = 5149
current_ts = 253.684845
current_received_ts = 253.684494
current_seq = 5151
count = 1142
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 253.676514/5149, current 253.684845/5151: elapsed=8334.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5151, expected 5150
(kms_flip:2459) DEBUG: name = flip
last_ts = 253.684845
last_received_ts = 253.684494
last_seq = 5151
current_ts = 253.693176
current_received_ts = 253.692825
current_seq = 5153
count = 1143
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 253.684845/5151, current 253.693176/5153: elapsed=8336.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5153, expected 5152
(kms_flip:2459) DEBUG: name = flip
last_ts = 253.693176
last_received_ts = 253.692825
last_seq = 5153
current_ts = 253.701508
current_received_ts = 253.701111
current_seq = 5155
count = 1144
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 253.693176/5153, current 253.701508/5155: elapsed=8331.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5155, expected 5154
(kms_flip:2459) DEBUG: name = flip
last_ts = 253.701508
last_received_ts = 253.701111
last_seq = 5155
current_ts = 253.709854
current_received_ts = 253.709488
current_seq = 5157
count = 1145
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 253.701508/5155, current 253.709854/5157: elapsed=8336.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5157, expected 5156
(kms_flip:2459) DEBUG: name = flip
last_ts = 253.709854
last_received_ts = 253.709488
last_seq = 5157
current_ts = 253.718185
current_received_ts = 253.717834
current_seq = 5159
count = 1146
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 253.709854/5157, current 253.718185/5159: elapsed=8334.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5159, expected 5158
(kms_flip:2459) DEBUG: name = flip
last_ts = 253.718185
last_received_ts = 253.717834
last_seq = 5159
current_ts = 253.726517
current_received_ts = 253.726105
current_seq = 5161
count = 1147
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 253.718185/5159, current 253.726517/5161: elapsed=8332.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5161, expected 5160
(kms_flip:2459) DEBUG: name = flip
last_ts = 253.726517
last_received_ts = 253.726105
last_seq = 5161
current_ts = 253.734848
current_received_ts = 253.734497
current_seq = 5163
count = 1148
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 253.726517/5161, current 253.734848/5163: elapsed=8335.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5163, expected 5162
(kms_flip:2459) DEBUG: name = flip
last_ts = 253.734848
last_received_ts = 253.734497
last_seq = 5163
current_ts = 253.743179
current_received_ts = 253.742828
current_seq = 5165
count = 1149
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 253.734848/5163, current 253.743179/5165: elapsed=8334.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5165, expected 5164
(kms_flip:2459) DEBUG: name = flip
last_ts = 253.743179
last_received_ts = 253.742828
last_seq = 5165
current_ts = 253.751511
current_received_ts = 253.751114
current_seq = 5167
count = 1150
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 253.743179/5165, current 253.751511/5167: elapsed=8332.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5167, expected 5166
(kms_flip:2459) DEBUG: name = flip
last_ts = 253.751511
last_received_ts = 253.751114
last_seq = 5167
current_ts = 253.759842
current_received_ts = 253.759506
current_seq = 5169
count = 1151
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 253.751511/5167, current 253.759842/5169: elapsed=8334.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5169, expected 5168
(kms_flip:2459) DEBUG: name = flip
last_ts = 253.759842
last_received_ts = 253.759506
last_seq = 5169
current_ts = 253.768188
current_received_ts = 253.767838
current_seq = 5171
count = 1152
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 253.759842/5169, current 253.768188/5171: elapsed=8335.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5171, expected 5170
(kms_flip:2459) DEBUG: name = flip
last_ts = 253.768188
last_received_ts = 253.767838
last_seq = 5171
current_ts = 253.776520
current_received_ts = 253.776108
current_seq = 5173
count = 1153
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 253.768188/5171, current 253.776520/5173: elapsed=8334.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5173, expected 5172
(kms_flip:2459) DEBUG: name = flip
last_ts = 253.776520
last_received_ts = 253.776108
last_seq = 5173
current_ts = 253.784851
current_received_ts = 253.784500
current_seq = 5175
count = 1154
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 253.776520/5173, current 253.784851/5175: elapsed=8333.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5175, expected 5174
(kms_flip:2459) DEBUG: name = flip
last_ts = 253.784851
last_received_ts = 253.784500
last_seq = 5175
current_ts = 253.793182
current_received_ts = 253.792847
current_seq = 5177
count = 1155
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 253.784851/5175, current 253.793182/5177: elapsed=8334.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5177, expected 5176
(kms_flip:2459) DEBUG: name = flip
last_ts = 253.793182
last_received_ts = 253.792847
last_seq = 5177
current_ts = 253.801514
current_received_ts = 253.801117
current_seq = 5179
count = 1156
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 253.793182/5177, current 253.801514/5179: elapsed=8334.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5179, expected 5178
(kms_flip:2459) DEBUG: name = flip
last_ts = 253.801514
last_received_ts = 253.801117
last_seq = 5179
current_ts = 253.809845
current_received_ts = 253.809509
current_seq = 5181
count = 1157
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 253.801514/5179, current 253.809845/5181: elapsed=8333.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5181, expected 5180
(kms_flip:2459) DEBUG: name = flip
last_ts = 253.809845
last_received_ts = 253.809509
last_seq = 5181
current_ts = 253.818192
current_received_ts = 253.817841
current_seq = 5183
count = 1158
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 253.809845/5181, current 253.818192/5183: elapsed=8334.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5183, expected 5182
(kms_flip:2459) DEBUG: name = flip
last_ts = 253.818192
last_received_ts = 253.817841
last_seq = 5183
current_ts = 253.826523
current_received_ts = 253.826111
current_seq = 5185
count = 1159
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 253.818192/5183, current 253.826523/5185: elapsed=8334.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5185, expected 5184
(kms_flip:2459) DEBUG: name = flip
last_ts = 253.826523
last_received_ts = 253.826111
last_seq = 5185
current_ts = 253.834854
current_received_ts = 253.834503
current_seq = 5187
count = 1160
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 253.826523/5185, current 253.834854/5187: elapsed=8333.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5187, expected 5186
(kms_flip:2459) DEBUG: name = flip
last_ts = 253.834854
last_received_ts = 253.834503
last_seq = 5187
current_ts = 253.843185
current_received_ts = 253.842834
current_seq = 5189
count = 1161
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 253.834854/5187, current 253.843185/5189: elapsed=8334.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5189, expected 5188
(kms_flip:2459) DEBUG: name = flip
last_ts = 253.843185
last_received_ts = 253.842834
last_seq = 5189
current_ts = 253.851517
current_received_ts = 253.851105
current_seq = 5191
count = 1162
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 253.843185/5189, current 253.851517/5191: elapsed=8334.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5191, expected 5190
(kms_flip:2459) DEBUG: name = flip
last_ts = 253.851517
last_received_ts = 253.851105
last_seq = 5191
current_ts = 253.859848
current_received_ts = 253.859512
current_seq = 5193
count = 1163
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 253.851517/5191, current 253.859848/5193: elapsed=8334.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5193, expected 5192
(kms_flip:2459) DEBUG: name = flip
last_ts = 253.859848
last_received_ts = 253.859512
last_seq = 5193
current_ts = 253.868195
current_received_ts = 253.867844
current_seq = 5195
count = 1164
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 253.859848/5193, current 253.868195/5195: elapsed=8334.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5195, expected 5194
(kms_flip:2459) DEBUG: name = flip
last_ts = 253.868195
last_received_ts = 253.867844
last_seq = 5195
current_ts = 253.876526
current_received_ts = 253.876114
current_seq = 5197
count = 1165
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 253.868195/5195, current 253.876526/5197: elapsed=8332.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5197, expected 5196
(kms_flip:2459) DEBUG: name = flip
last_ts = 253.876526
last_received_ts = 253.876114
last_seq = 5197
current_ts = 253.884857
current_received_ts = 253.884506
current_seq = 5199
count = 1166
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 253.876526/5197, current 253.884857/5199: elapsed=8336.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5199, expected 5198
(kms_flip:2459) DEBUG: name = flip
last_ts = 253.884857
last_received_ts = 253.884506
last_seq = 5199
current_ts = 253.893188
current_received_ts = 253.892838
current_seq = 5201
count = 1167
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 253.884857/5199, current 253.893188/5201: elapsed=8333.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5201, expected 5200
(kms_flip:2459) DEBUG: name = flip
last_ts = 253.893188
last_received_ts = 253.892838
last_seq = 5201
current_ts = 253.901520
current_received_ts = 253.901108
current_seq = 5203
count = 1168
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 253.893188/5201, current 253.901520/5203: elapsed=8334.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5203, expected 5202
(kms_flip:2459) DEBUG: name = flip
last_ts = 253.901520
last_received_ts = 253.901108
last_seq = 5203
current_ts = 253.909851
current_received_ts = 253.909515
current_seq = 5205
count = 1169
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 253.901520/5203, current 253.909851/5205: elapsed=8332.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5205, expected 5204
(kms_flip:2459) DEBUG: name = flip
last_ts = 253.909851
last_received_ts = 253.909515
last_seq = 5205
current_ts = 253.918198
current_received_ts = 253.917847
current_seq = 5207
count = 1170
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 253.909851/5205, current 253.918198/5207: elapsed=8336.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5207, expected 5206
(kms_flip:2459) DEBUG: name = flip
last_ts = 253.918198
last_received_ts = 253.917847
last_seq = 5207
current_ts = 253.926529
current_received_ts = 253.926117
current_seq = 5209
count = 1171
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 253.918198/5207, current 253.926529/5209: elapsed=8332.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5209, expected 5208
(kms_flip:2459) DEBUG: name = flip
last_ts = 253.926529
last_received_ts = 253.926117
last_seq = 5209
current_ts = 253.934860
current_received_ts = 253.934509
current_seq = 5211
count = 1172
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 253.926529/5209, current 253.934860/5211: elapsed=8334.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5211, expected 5210
(kms_flip:2459) DEBUG: name = flip
last_ts = 253.934860
last_received_ts = 253.934509
last_seq = 5211
current_ts = 253.943192
current_received_ts = 253.942825
current_seq = 5213
count = 1173
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 253.934860/5211, current 253.943192/5213: elapsed=8334.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5213, expected 5212
(kms_flip:2459) DEBUG: name = flip
last_ts = 253.943192
last_received_ts = 253.942825
last_seq = 5213
current_ts = 253.951523
current_received_ts = 253.951126
current_seq = 5215
count = 1174
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 253.943192/5213, current 253.951523/5215: elapsed=8333.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5215, expected 5214
(kms_flip:2459) DEBUG: name = flip
last_ts = 253.951523
last_received_ts = 253.951126
last_seq = 5215
current_ts = 253.959854
current_received_ts = 253.959518
current_seq = 5217
count = 1175
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 253.951523/5215, current 253.959854/5217: elapsed=8334.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5217, expected 5216
(kms_flip:2459) DEBUG: name = flip
last_ts = 253.959854
last_received_ts = 253.959518
last_seq = 5217
current_ts = 253.968201
current_received_ts = 253.967850
current_seq = 5219
count = 1176
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 253.959854/5217, current 253.968201/5219: elapsed=8336.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5219, expected 5218
(kms_flip:2459) DEBUG: name = flip
last_ts = 253.968201
last_received_ts = 253.967850
last_seq = 5219
current_ts = 253.976532
current_received_ts = 253.976120
current_seq = 5221
count = 1177
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 253.968201/5219, current 253.976532/5221: elapsed=8332.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5221, expected 5220
(kms_flip:2459) DEBUG: name = flip
last_ts = 253.976532
last_received_ts = 253.976120
last_seq = 5221
current_ts = 253.984863
current_received_ts = 253.984512
current_seq = 5223
count = 1178
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 253.976532/5221, current 253.984863/5223: elapsed=8334.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5223, expected 5222
(kms_flip:2459) DEBUG: name = flip
last_ts = 253.984863
last_received_ts = 253.984512
last_seq = 5223
current_ts = 253.993195
current_received_ts = 253.992844
current_seq = 5225
count = 1179
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 253.984863/5223, current 253.993195/5225: elapsed=8334.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5225, expected 5224
(kms_flip:2459) DEBUG: name = flip
last_ts = 253.993195
last_received_ts = 253.992844
last_seq = 5225
current_ts = 254.001526
current_received_ts = 254.001129
current_seq = 5227
count = 1180
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 253.993195/5225, current 254.001526/5227: elapsed=8334.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5227, expected 5226
(kms_flip:2459) DEBUG: name = flip
last_ts = 254.001526
last_received_ts = 254.001129
last_seq = 5227
current_ts = 254.009857
current_received_ts = 254.009506
current_seq = 5229
count = 1181
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 254.001526/5227, current 254.009857/5229: elapsed=8334.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5229, expected 5228
(kms_flip:2459) DEBUG: name = flip
last_ts = 254.009857
last_received_ts = 254.009506
last_seq = 5229
current_ts = 254.018188
current_received_ts = 254.017853
current_seq = 5231
count = 1182
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 254.009857/5229, current 254.018188/5231: elapsed=8333.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5231, expected 5230
(kms_flip:2459) DEBUG: name = flip
last_ts = 254.018188
last_received_ts = 254.017853
last_seq = 5231
current_ts = 254.026535
current_received_ts = 254.026123
current_seq = 5233
count = 1183
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 254.018188/5231, current 254.026535/5233: elapsed=8334.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5233, expected 5232
(kms_flip:2459) DEBUG: name = flip
last_ts = 254.026535
last_received_ts = 254.026123
last_seq = 5233
current_ts = 254.034866
current_received_ts = 254.034515
current_seq = 5235
count = 1184
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 254.026535/5233, current 254.034866/5235: elapsed=8334.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5235, expected 5234
(kms_flip:2459) DEBUG: name = flip
last_ts = 254.034866
last_received_ts = 254.034515
last_seq = 5235
current_ts = 254.043198
current_received_ts = 254.042847
current_seq = 5237
count = 1185
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 254.034866/5235, current 254.043198/5237: elapsed=8333.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5237, expected 5236
(kms_flip:2459) DEBUG: name = flip
last_ts = 254.043198
last_received_ts = 254.042847
last_seq = 5237
current_ts = 254.051529
current_received_ts = 254.051132
current_seq = 5239
count = 1186
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 254.043198/5237, current 254.051529/5239: elapsed=8334.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5239, expected 5238
(kms_flip:2459) DEBUG: name = flip
last_ts = 254.051529
last_received_ts = 254.051132
last_seq = 5239
current_ts = 254.059860
current_received_ts = 254.059525
current_seq = 5241
count = 1187
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 254.051529/5239, current 254.059860/5241: elapsed=8333.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5241, expected 5240
(kms_flip:2459) DEBUG: name = flip
last_ts = 254.059860
last_received_ts = 254.059525
last_seq = 5241
current_ts = 254.068192
current_received_ts = 254.067856
current_seq = 5243
count = 1188
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 254.059860/5241, current 254.068192/5243: elapsed=8335.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5243, expected 5242
(kms_flip:2459) DEBUG: name = flip
last_ts = 254.068192
last_received_ts = 254.067856
last_seq = 5243
current_ts = 254.076538
current_received_ts = 254.076126
current_seq = 5245
count = 1189
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 254.068192/5243, current 254.076538/5245: elapsed=8333.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5245, expected 5244
(kms_flip:2459) DEBUG: name = flip
last_ts = 254.076538
last_received_ts = 254.076126
last_seq = 5245
current_ts = 254.084869
current_received_ts = 254.084518
current_seq = 5247
count = 1190
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 254.076538/5245, current 254.084869/5247: elapsed=8334.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5247, expected 5246
(kms_flip:2459) DEBUG: name = flip
last_ts = 254.084869
last_received_ts = 254.084518
last_seq = 5247
current_ts = 254.093201
current_received_ts = 254.092850
current_seq = 5249
count = 1191
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 254.084869/5247, current 254.093201/5249: elapsed=8333.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5249, expected 5248
(kms_flip:2459) DEBUG: name = flip
last_ts = 254.093201
last_received_ts = 254.092850
last_seq = 5249
current_ts = 254.101532
current_received_ts = 254.101120
current_seq = 5251
count = 1192
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 254.093201/5249, current 254.101532/5251: elapsed=8334.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5251, expected 5250
(kms_flip:2459) DEBUG: name = flip
last_ts = 254.101532
last_received_ts = 254.101120
last_seq = 5251
current_ts = 254.109863
current_received_ts = 254.109512
current_seq = 5253
count = 1193
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 254.101532/5251, current 254.109863/5253: elapsed=8335.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5253, expected 5252
(kms_flip:2459) DEBUG: name = flip
last_ts = 254.109863
last_received_ts = 254.109512
last_seq = 5253
current_ts = 254.118195
current_received_ts = 254.117859
current_seq = 5255
count = 1194
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 254.109863/5253, current 254.118195/5255: elapsed=8333.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5255, expected 5254
(kms_flip:2459) DEBUG: name = flip
last_ts = 254.118195
last_received_ts = 254.117859
last_seq = 5255
current_ts = 254.126541
current_received_ts = 254.126129
current_seq = 5257
count = 1195
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 254.118195/5255, current 254.126541/5257: elapsed=8334.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5257, expected 5256
(kms_flip:2459) DEBUG: name = flip
last_ts = 254.126541
last_received_ts = 254.126129
last_seq = 5257
current_ts = 254.134872
current_received_ts = 254.134521
current_seq = 5259
count = 1196
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 254.126541/5257, current 254.134872/5259: elapsed=8335.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5259, expected 5258
(kms_flip:2459) DEBUG: name = flip
last_ts = 254.134872
last_received_ts = 254.134521
last_seq = 5259
current_ts = 254.143204
current_received_ts = 254.142868
current_seq = 5261
count = 1197
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 254.134872/5259, current 254.143204/5261: elapsed=8332.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5261, expected 5260
(kms_flip:2459) DEBUG: name = flip
last_ts = 254.143204
last_received_ts = 254.142868
last_seq = 5261
current_ts = 254.151535
current_received_ts = 254.151138
current_seq = 5263
count = 1198
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 254.143204/5261, current 254.151535/5263: elapsed=8334.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5263, expected 5262
(kms_flip:2459) DEBUG: name = flip
last_ts = 254.151535
last_received_ts = 254.151138
last_seq = 5263
current_ts = 254.159866
current_received_ts = 254.159531
current_seq = 5265
count = 1199
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 254.151535/5263, current 254.159866/5265: elapsed=8333.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5265, expected 5264
(kms_flip:2459) DEBUG: name = flip
last_ts = 254.159866
last_received_ts = 254.159531
last_seq = 5265
current_ts = 254.168198
current_received_ts = 254.167862
current_seq = 5267
count = 1200
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 254.159866/5265, current 254.168198/5267: elapsed=8334.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5267, expected 5266
(kms_flip:2459) DEBUG: name = flip
last_ts = 254.168198
last_received_ts = 254.167862
last_seq = 5267
current_ts = 254.176544
current_received_ts = 254.176132
current_seq = 5269
count = 1201
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 254.168198/5267, current 254.176544/5269: elapsed=8335.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5269, expected 5268
(kms_flip:2459) DEBUG: name = flip
last_ts = 254.176544
last_received_ts = 254.176132
last_seq = 5269
current_ts = 254.184875
current_received_ts = 254.184509
current_seq = 5271
count = 1202
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 254.176544/5269, current 254.184875/5271: elapsed=8333.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5271, expected 5270
(kms_flip:2459) DEBUG: name = flip
last_ts = 254.184875
last_received_ts = 254.184509
last_seq = 5271
current_ts = 254.193207
current_received_ts = 254.192856
current_seq = 5273
count = 1203
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 254.184875/5271, current 254.193207/5273: elapsed=8333.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5273, expected 5272
(kms_flip:2459) DEBUG: name = flip
last_ts = 254.193207
last_received_ts = 254.192856
last_seq = 5273
current_ts = 254.201538
current_received_ts = 254.201126
current_seq = 5275
count = 1204
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 254.193207/5273, current 254.201538/5275: elapsed=8335.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5275, expected 5274
(kms_flip:2459) DEBUG: name = flip
last_ts = 254.201538
last_received_ts = 254.201126
last_seq = 5275
current_ts = 254.209869
current_received_ts = 254.209518
current_seq = 5277
count = 1205
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 254.201538/5275, current 254.209869/5277: elapsed=8334.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5277, expected 5276
(kms_flip:2459) DEBUG: name = flip
last_ts = 254.209869
last_received_ts = 254.209518
last_seq = 5277
current_ts = 254.218201
current_received_ts = 254.217865
current_seq = 5279
count = 1206
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 254.209869/5277, current 254.218201/5279: elapsed=8335.0us expected=8333.6us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 5279, expected 5278
(kms_flip:2459) INFO: Event flip: expected 2400, counted 1207, passrate = 1.16%, encoder type 2
(kms_flip:2459) DEBUG: dropped frames, expected 2400, counted 1207, passrate = 1.16%, encoder type 2
(kms_flip:2459) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1704:
(kms_flip:2459) CRITICAL: Failed assertion: !retried
(kms_flip:2459) igt_core-INFO: Stack trace:
(kms_flip:2459) igt_core-INFO:   #0 ../lib/igt_core.c:2075 __igt_fail_assert()
(kms_flip:2459) igt_core-INFO:   #1 ../tests/kms_flip.c:973 run_test_on_crtc_set.constprop.0()
(kms_flip:2459) igt_core-INFO:   #2 ../tests/kms_flip.c:1884 run_test()
(kms_flip:2459) igt_core-INFO:   #3 ../tests/kms_flip.c:2117 __igt_unique____real_main2040()
(kms_flip:2459) igt_core-INFO:   #4 ../tests/kms_flip.c:2040 main()
(kms_flip:2459) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2459) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2459) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-eDP1: FAIL (26.043s)
Starting dynamic subtest: C-eDP1
(kms_flip:2459) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1704:
(kms_flip:2459) CRITICAL: Failed assertion: !retried
Dynamic subtest C-eDP1 failed.
**** DEBUG ****
(kms_flip:2459) DEBUG: flip ts/seq: last 279.611298/9449, current 279.619629/9451: elapsed=8332.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9451, expected 9450
(kms_flip:2459) DEBUG: name = flip
last_ts = 279.619629
last_received_ts = 279.619232
last_seq = 9451
current_ts = 279.627960
current_received_ts = 279.627625
current_seq = 9453
count = 1132
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 279.619629/9451, current 279.627960/9453: elapsed=8334.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9453, expected 9452
(kms_flip:2459) DEBUG: name = flip
last_ts = 279.627960
last_received_ts = 279.627625
last_seq = 9453
current_ts = 279.636292
current_received_ts = 279.635956
current_seq = 9455
count = 1133
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 279.627960/9453, current 279.636292/9455: elapsed=8335.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9455, expected 9454
(kms_flip:2459) DEBUG: name = flip
last_ts = 279.636292
last_received_ts = 279.635956
last_seq = 9455
current_ts = 279.644623
current_received_ts = 279.644257
current_seq = 9457
count = 1134
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 279.636292/9455, current 279.644623/9457: elapsed=8333.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9457, expected 9456
(kms_flip:2459) DEBUG: name = flip
last_ts = 279.644623
last_received_ts = 279.644257
last_seq = 9457
current_ts = 279.652985
current_received_ts = 279.652649
current_seq = 9459
count = 1135
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 279.644623/9457, current 279.652985/9459: elapsed=8334.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9459, expected 9458
(kms_flip:2459) DEBUG: name = flip
last_ts = 279.652985
last_received_ts = 279.652649
last_seq = 9459
current_ts = 279.661316
current_received_ts = 279.660980
current_seq = 9461
count = 1136
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 279.652985/9459, current 279.661316/9461: elapsed=8334.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9461, expected 9460
(kms_flip:2459) DEBUG: name = flip
last_ts = 279.661316
last_received_ts = 279.660980
last_seq = 9461
current_ts = 279.669647
current_received_ts = 279.669220
current_seq = 9463
count = 1137
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 279.661316/9461, current 279.669647/9463: elapsed=8332.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9463, expected 9462
(kms_flip:2459) DEBUG: name = flip
last_ts = 279.669647
last_received_ts = 279.669220
last_seq = 9463
current_ts = 279.677979
current_received_ts = 279.677643
current_seq = 9465
count = 1138
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 279.669647/9463, current 279.677979/9465: elapsed=8333.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9465, expected 9464
(kms_flip:2459) DEBUG: name = flip
last_ts = 279.677979
last_received_ts = 279.677643
last_seq = 9465
current_ts = 279.686310
current_received_ts = 279.685974
current_seq = 9467
count = 1139
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 279.677979/9465, current 279.686310/9467: elapsed=8333.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9467, expected 9466
(kms_flip:2459) DEBUG: name = flip
last_ts = 279.686310
last_received_ts = 279.685974
last_seq = 9467
current_ts = 279.694641
current_received_ts = 279.694244
current_seq = 9469
count = 1140
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 279.686310/9467, current 279.694641/9469: elapsed=8334.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9469, expected 9468
(kms_flip:2459) DEBUG: name = flip
last_ts = 279.694641
last_received_ts = 279.694244
last_seq = 9469
current_ts = 279.702972
current_received_ts = 279.702637
current_seq = 9471
count = 1141
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 279.694641/9469, current 279.702972/9471: elapsed=8334.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9471, expected 9470
(kms_flip:2459) DEBUG: name = flip
last_ts = 279.702972
last_received_ts = 279.702637
last_seq = 9471
current_ts = 279.711304
current_received_ts = 279.710968
current_seq = 9473
count = 1142
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 279.702972/9471, current 279.711304/9473: elapsed=8333.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9473, expected 9472
(kms_flip:2459) DEBUG: name = flip
last_ts = 279.711304
last_received_ts = 279.710968
last_seq = 9473
current_ts = 279.719635
current_received_ts = 279.719238
current_seq = 9475
count = 1143
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 279.711304/9473, current 279.719635/9475: elapsed=8334.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9475, expected 9474
(kms_flip:2459) DEBUG: name = flip
last_ts = 279.719635
last_received_ts = 279.719238
last_seq = 9475
current_ts = 279.727966
current_received_ts = 279.727631
current_seq = 9477
count = 1144
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 279.719635/9475, current 279.727966/9477: elapsed=8334.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9477, expected 9476
(kms_flip:2459) DEBUG: name = flip
last_ts = 279.727966
last_received_ts = 279.727631
last_seq = 9477
current_ts = 279.736298
current_received_ts = 279.735931
current_seq = 9479
count = 1145
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 279.727966/9477, current 279.736298/9479: elapsed=8335.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9479, expected 9478
(kms_flip:2459) DEBUG: name = flip
last_ts = 279.736298
last_received_ts = 279.735931
last_seq = 9479
current_ts = 279.744629
current_received_ts = 279.744263
current_seq = 9481
count = 1146
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 279.736298/9479, current 279.744629/9481: elapsed=8333.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9481, expected 9480
(kms_flip:2459) DEBUG: name = flip
last_ts = 279.744629
last_received_ts = 279.744263
last_seq = 9481
current_ts = 279.752960
current_received_ts = 279.752625
current_seq = 9483
count = 1147
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 279.744629/9481, current 279.752960/9483: elapsed=8334.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9483, expected 9482
(kms_flip:2459) DEBUG: name = flip
last_ts = 279.752960
last_received_ts = 279.752625
last_seq = 9483
current_ts = 279.761322
current_received_ts = 279.760956
current_seq = 9485
count = 1148
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 279.752960/9483, current 279.761322/9485: elapsed=8333.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9485, expected 9484
(kms_flip:2459) DEBUG: name = flip
last_ts = 279.761322
last_received_ts = 279.760956
last_seq = 9485
current_ts = 279.769653
current_received_ts = 279.769257
current_seq = 9487
count = 1149
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 279.761322/9485, current 279.769653/9487: elapsed=8332.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9487, expected 9486
(kms_flip:2459) DEBUG: name = flip
last_ts = 279.769653
last_received_ts = 279.769257
last_seq = 9487
current_ts = 279.777985
current_received_ts = 279.777618
current_seq = 9489
count = 1150
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 279.769653/9487, current 279.777985/9489: elapsed=8335.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9489, expected 9488
(kms_flip:2459) DEBUG: name = flip
last_ts = 279.777985
last_received_ts = 279.777618
last_seq = 9489
current_ts = 279.786316
current_received_ts = 279.785980
current_seq = 9491
count = 1151
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 279.777985/9489, current 279.786316/9491: elapsed=8332.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9491, expected 9490
(kms_flip:2459) DEBUG: name = flip
last_ts = 279.786316
last_received_ts = 279.785980
last_seq = 9491
current_ts = 279.794647
current_received_ts = 279.794281
current_seq = 9493
count = 1152
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 279.786316/9491, current 279.794647/9493: elapsed=8333.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9493, expected 9492
(kms_flip:2459) DEBUG: name = flip
last_ts = 279.794647
last_received_ts = 279.794281
last_seq = 9493
current_ts = 279.802979
current_received_ts = 279.802612
current_seq = 9495
count = 1153
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 279.794647/9493, current 279.802979/9495: elapsed=8337.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9495, expected 9494
(kms_flip:2459) DEBUG: name = flip
last_ts = 279.802979
last_received_ts = 279.802612
last_seq = 9495
current_ts = 279.811310
current_received_ts = 279.810974
current_seq = 9497
count = 1154
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 279.802979/9495, current 279.811310/9497: elapsed=8333.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9497, expected 9496
(kms_flip:2459) DEBUG: name = flip
last_ts = 279.811310
last_received_ts = 279.810974
last_seq = 9497
current_ts = 279.819641
current_received_ts = 279.819244
current_seq = 9499
count = 1155
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 279.811310/9497, current 279.819641/9499: elapsed=8332.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9499, expected 9498
(kms_flip:2459) DEBUG: name = flip
last_ts = 279.819641
last_received_ts = 279.819244
last_seq = 9499
current_ts = 279.827972
current_received_ts = 279.827606
current_seq = 9501
count = 1156
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 279.819641/9499, current 279.827972/9501: elapsed=8335.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9501, expected 9500
(kms_flip:2459) DEBUG: name = flip
last_ts = 279.827972
last_received_ts = 279.827606
last_seq = 9501
current_ts = 279.836304
current_received_ts = 279.835968
current_seq = 9503
count = 1157
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 279.827972/9501, current 279.836304/9503: elapsed=8334.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9503, expected 9502
(kms_flip:2459) DEBUG: name = flip
last_ts = 279.836304
last_received_ts = 279.835968
last_seq = 9503
current_ts = 279.844635
current_received_ts = 279.844238
current_seq = 9505
count = 1158
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 279.836304/9503, current 279.844635/9505: elapsed=8332.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9505, expected 9504
(kms_flip:2459) DEBUG: name = flip
last_ts = 279.844635
last_received_ts = 279.844238
last_seq = 9505
current_ts = 279.852966
current_received_ts = 279.852631
current_seq = 9507
count = 1159
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 279.844635/9505, current 279.852966/9507: elapsed=8334.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9507, expected 9506
(kms_flip:2459) DEBUG: name = flip
last_ts = 279.852966
last_received_ts = 279.852631
last_seq = 9507
current_ts = 279.861298
current_received_ts = 279.860962
current_seq = 9509
count = 1160
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 279.852966/9507, current 279.861298/9509: elapsed=8333.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9509, expected 9508
(kms_flip:2459) DEBUG: name = flip
last_ts = 279.861298
last_received_ts = 279.860962
last_seq = 9509
current_ts = 279.869629
current_received_ts = 279.869232
current_seq = 9511
count = 1161
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 279.861298/9509, current 279.869629/9511: elapsed=8333.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9511, expected 9510
(kms_flip:2459) DEBUG: name = flip
last_ts = 279.869629
last_received_ts = 279.869232
last_seq = 9511
current_ts = 279.877960
current_received_ts = 279.877625
current_seq = 9513
count = 1162
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 279.869629/9511, current 279.877960/9513: elapsed=8333.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9513, expected 9512
(kms_flip:2459) DEBUG: name = flip
last_ts = 279.877960
last_received_ts = 279.877625
last_seq = 9513
current_ts = 279.886322
current_received_ts = 279.885956
current_seq = 9515
count = 1163
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 279.877960/9513, current 279.886322/9515: elapsed=8336.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9515, expected 9514
(kms_flip:2459) DEBUG: name = flip
last_ts = 279.886322
last_received_ts = 279.885956
last_seq = 9515
current_ts = 279.894653
current_received_ts = 279.894257
current_seq = 9517
count = 1164
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 279.886322/9515, current 279.894653/9517: elapsed=8331.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9517, expected 9516
(kms_flip:2459) DEBUG: name = flip
last_ts = 279.894653
last_received_ts = 279.894257
last_seq = 9517
current_ts = 279.902985
current_received_ts = 279.902649
current_seq = 9519
count = 1165
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 279.894653/9517, current 279.902985/9519: elapsed=8336.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9519, expected 9518
(kms_flip:2459) DEBUG: name = flip
last_ts = 279.902985
last_received_ts = 279.902649
last_seq = 9519
current_ts = 279.911316
current_received_ts = 279.910980
current_seq = 9521
count = 1166
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 279.902985/9519, current 279.911316/9521: elapsed=8332.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9521, expected 9520
(kms_flip:2459) DEBUG: name = flip
last_ts = 279.911316
last_received_ts = 279.910980
last_seq = 9521
current_ts = 279.919647
current_received_ts = 279.919281
current_seq = 9523
count = 1167
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 279.911316/9521, current 279.919647/9523: elapsed=8333.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9523, expected 9522
(kms_flip:2459) DEBUG: name = flip
last_ts = 279.919647
last_received_ts = 279.919281
last_seq = 9523
current_ts = 279.927979
current_received_ts = 279.927612
current_seq = 9525
count = 1168
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 279.919647/9523, current 279.927979/9525: elapsed=8334.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9525, expected 9524
(kms_flip:2459) DEBUG: name = flip
last_ts = 279.927979
last_received_ts = 279.927612
last_seq = 9525
current_ts = 279.936310
current_received_ts = 279.935944
current_seq = 9527
count = 1169
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 279.927979/9525, current 279.936310/9527: elapsed=8335.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9527, expected 9526
(kms_flip:2459) DEBUG: name = flip
last_ts = 279.936310
last_received_ts = 279.935944
last_seq = 9527
current_ts = 279.944641
current_received_ts = 279.944244
current_seq = 9529
count = 1170
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 279.936310/9527, current 279.944641/9529: elapsed=8334.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9529, expected 9528
(kms_flip:2459) DEBUG: name = flip
last_ts = 279.944641
last_received_ts = 279.944244
last_seq = 9529
current_ts = 279.952972
current_received_ts = 279.952606
current_seq = 9531
count = 1171
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 279.944641/9529, current 279.952972/9531: elapsed=8333.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9531, expected 9530
(kms_flip:2459) DEBUG: name = flip
last_ts = 279.952972
last_received_ts = 279.952606
last_seq = 9531
current_ts = 279.961304
current_received_ts = 279.960907
current_seq = 9533
count = 1172
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 279.952972/9531, current 279.961304/9533: elapsed=8332.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9533, expected 9532
(kms_flip:2459) DEBUG: name = flip
last_ts = 279.961304
last_received_ts = 279.960907
last_seq = 9533
current_ts = 279.969635
current_received_ts = 279.969269
current_seq = 9535
count = 1173
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 279.961304/9533, current 279.969635/9535: elapsed=8335.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9535, expected 9534
(kms_flip:2459) DEBUG: name = flip
last_ts = 279.969635
last_received_ts = 279.969269
last_seq = 9535
current_ts = 279.977966
current_received_ts = 279.977600
current_seq = 9537
count = 1174
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 279.969635/9535, current 279.977966/9537: elapsed=8332.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9537, expected 9536
(kms_flip:2459) DEBUG: name = flip
last_ts = 279.977966
last_received_ts = 279.977600
last_seq = 9537
current_ts = 279.986328
current_received_ts = 279.985931
current_seq = 9539
count = 1175
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 279.977966/9537, current 279.986328/9539: elapsed=8335.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9539, expected 9538
(kms_flip:2459) DEBUG: name = flip
last_ts = 279.986328
last_received_ts = 279.985931
last_seq = 9539
current_ts = 279.994659
current_received_ts = 279.994232
current_seq = 9541
count = 1176
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 279.986328/9539, current 279.994659/9541: elapsed=8332.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9541, expected 9540
(kms_flip:2459) DEBUG: name = flip
last_ts = 279.994659
last_received_ts = 279.994232
last_seq = 9541
current_ts = 280.002991
current_received_ts = 280.002594
current_seq = 9543
count = 1177
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 279.994659/9541, current 280.002991/9543: elapsed=8336.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9543, expected 9542
(kms_flip:2459) DEBUG: name = flip
last_ts = 280.002991
last_received_ts = 280.002594
last_seq = 9543
current_ts = 280.011322
current_received_ts = 280.010925
current_seq = 9545
count = 1178
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 280.002991/9543, current 280.011322/9545: elapsed=8333.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9545, expected 9544
(kms_flip:2459) DEBUG: name = flip
last_ts = 280.011322
last_received_ts = 280.010925
last_seq = 9545
current_ts = 280.019653
current_received_ts = 280.019226
current_seq = 9547
count = 1179
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 280.011322/9545, current 280.019653/9547: elapsed=8332.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9547, expected 9546
(kms_flip:2459) DEBUG: name = flip
last_ts = 280.019653
last_received_ts = 280.019226
last_seq = 9547
current_ts = 280.027985
current_received_ts = 280.027588
current_seq = 9549
count = 1180
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 280.019653/9547, current 280.027985/9549: elapsed=8336.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9549, expected 9548
(kms_flip:2459) DEBUG: name = flip
last_ts = 280.027985
last_received_ts = 280.027588
last_seq = 9549
current_ts = 280.036316
current_received_ts = 280.035919
current_seq = 9551
count = 1181
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 280.027985/9549, current 280.036316/9551: elapsed=8332.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9551, expected 9550
(kms_flip:2459) DEBUG: name = flip
last_ts = 280.036316
last_received_ts = 280.035919
last_seq = 9551
current_ts = 280.044647
current_received_ts = 280.044220
current_seq = 9553
count = 1182
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 280.036316/9551, current 280.044647/9553: elapsed=8333.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9553, expected 9552
(kms_flip:2459) DEBUG: name = flip
last_ts = 280.044647
last_received_ts = 280.044220
last_seq = 9553
current_ts = 280.052979
current_received_ts = 280.052582
current_seq = 9555
count = 1183
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 280.044647/9553, current 280.052979/9555: elapsed=8333.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9555, expected 9554
(kms_flip:2459) DEBUG: name = flip
last_ts = 280.052979
last_received_ts = 280.052582
last_seq = 9555
current_ts = 280.061310
current_received_ts = 280.060913
current_seq = 9557
count = 1184
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 280.052979/9555, current 280.061310/9557: elapsed=8335.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9557, expected 9556
(kms_flip:2459) DEBUG: name = flip
last_ts = 280.061310
last_received_ts = 280.060913
last_seq = 9557
current_ts = 280.069641
current_received_ts = 280.069214
current_seq = 9559
count = 1185
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 280.061310/9557, current 280.069641/9559: elapsed=8332.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9559, expected 9558
(kms_flip:2459) DEBUG: name = flip
last_ts = 280.069641
last_received_ts = 280.069214
last_seq = 9559
current_ts = 280.077972
current_received_ts = 280.077576
current_seq = 9561
count = 1186
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 280.069641/9559, current 280.077972/9561: elapsed=8335.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9561, expected 9560
(kms_flip:2459) DEBUG: name = flip
last_ts = 280.077972
last_received_ts = 280.077576
last_seq = 9561
current_ts = 280.086304
current_received_ts = 280.085938
current_seq = 9563
count = 1187
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 280.077972/9561, current 280.086304/9563: elapsed=8333.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9563, expected 9562
(kms_flip:2459) DEBUG: name = flip
last_ts = 280.086304
last_received_ts = 280.085938
last_seq = 9563
current_ts = 280.094635
current_received_ts = 280.094238
current_seq = 9565
count = 1188
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 280.086304/9563, current 280.094635/9565: elapsed=8333.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9565, expected 9564
(kms_flip:2459) DEBUG: name = flip
last_ts = 280.094635
last_received_ts = 280.094238
last_seq = 9565
current_ts = 280.102997
current_received_ts = 280.102570
current_seq = 9567
count = 1189
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 280.094635/9565, current 280.102997/9567: elapsed=8334.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9567, expected 9566
(kms_flip:2459) DEBUG: name = flip
last_ts = 280.102997
last_received_ts = 280.102570
last_seq = 9567
current_ts = 280.111328
current_received_ts = 280.110901
current_seq = 9569
count = 1190
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 280.102997/9567, current 280.111328/9569: elapsed=8335.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9569, expected 9568
(kms_flip:2459) DEBUG: name = flip
last_ts = 280.111328
last_received_ts = 280.110901
last_seq = 9569
current_ts = 280.119659
current_received_ts = 280.119232
current_seq = 9571
count = 1191
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 280.111328/9569, current 280.119659/9571: elapsed=8333.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9571, expected 9570
(kms_flip:2459) DEBUG: name = flip
last_ts = 280.119659
last_received_ts = 280.119232
last_seq = 9571
current_ts = 280.127991
current_received_ts = 280.127594
current_seq = 9573
count = 1192
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 280.119659/9571, current 280.127991/9573: elapsed=8334.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9573, expected 9572
(kms_flip:2459) DEBUG: name = flip
last_ts = 280.127991
last_received_ts = 280.127594
last_seq = 9573
current_ts = 280.136322
current_received_ts = 280.135925
current_seq = 9575
count = 1193
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 280.127991/9573, current 280.136322/9575: elapsed=8333.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9575, expected 9574
(kms_flip:2459) DEBUG: name = flip
last_ts = 280.136322
last_received_ts = 280.135925
last_seq = 9575
current_ts = 280.144653
current_received_ts = 280.144257
current_seq = 9577
count = 1194
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 280.136322/9575, current 280.144653/9577: elapsed=8334.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9577, expected 9576
(kms_flip:2459) DEBUG: name = flip
last_ts = 280.144653
last_received_ts = 280.144257
last_seq = 9577
current_ts = 280.152985
current_received_ts = 280.152588
current_seq = 9579
count = 1195
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 280.144653/9577, current 280.152985/9579: elapsed=8333.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9579, expected 9578
(kms_flip:2459) DEBUG: name = flip
last_ts = 280.152985
last_received_ts = 280.152588
last_seq = 9579
current_ts = 280.161316
current_received_ts = 280.160919
current_seq = 9581
count = 1196
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 280.152985/9579, current 280.161316/9581: elapsed=8334.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9581, expected 9580
(kms_flip:2459) DEBUG: name = flip
last_ts = 280.161316
last_received_ts = 280.160919
last_seq = 9581
current_ts = 280.169647
current_received_ts = 280.169250
current_seq = 9583
count = 1197
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 280.161316/9581, current 280.169647/9583: elapsed=8334.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9583, expected 9582
(kms_flip:2459) DEBUG: name = flip
last_ts = 280.169647
last_received_ts = 280.169250
last_seq = 9583
current_ts = 280.177979
current_received_ts = 280.177612
current_seq = 9585
count = 1198
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 280.169647/9583, current 280.177979/9585: elapsed=8333.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9585, expected 9584
(kms_flip:2459) DEBUG: name = flip
last_ts = 280.177979
last_received_ts = 280.177612
last_seq = 9585
current_ts = 280.186310
current_received_ts = 280.185913
current_seq = 9587
count = 1199
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 280.177979/9585, current 280.186310/9587: elapsed=8334.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9587, expected 9586
(kms_flip:2459) DEBUG: name = flip
last_ts = 280.186310
last_received_ts = 280.185913
last_seq = 9587
current_ts = 280.194641
current_received_ts = 280.194244
current_seq = 9589
count = 1200
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 280.186310/9587, current 280.194641/9589: elapsed=8333.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9589, expected 9588
(kms_flip:2459) DEBUG: name = flip
last_ts = 280.194641
last_received_ts = 280.194244
last_seq = 9589
current_ts = 280.202972
current_received_ts = 280.202576
current_seq = 9591
count = 1201
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 280.194641/9589, current 280.202972/9591: elapsed=8334.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9591, expected 9590
(kms_flip:2459) DEBUG: name = flip
last_ts = 280.202972
last_received_ts = 280.202576
last_seq = 9591
current_ts = 280.211334
current_received_ts = 280.210938
current_seq = 9593
count = 1202
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 280.202972/9591, current 280.211334/9593: elapsed=8333.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9593, expected 9592
(kms_flip:2459) DEBUG: name = flip
last_ts = 280.211334
last_received_ts = 280.210938
last_seq = 9593
current_ts = 280.219666
current_received_ts = 280.219269
current_seq = 9595
count = 1203
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 280.211334/9593, current 280.219666/9595: elapsed=8334.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9595, expected 9594
(kms_flip:2459) DEBUG: name = flip
last_ts = 280.219666
last_received_ts = 280.219269
last_seq = 9595
current_ts = 280.227997
current_received_ts = 280.227600
current_seq = 9597
count = 1204
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 280.219666/9595, current 280.227997/9597: elapsed=8333.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9597, expected 9596
(kms_flip:2459) DEBUG: name = flip
last_ts = 280.227997
last_received_ts = 280.227600
last_seq = 9597
current_ts = 280.236328
current_received_ts = 280.235931
current_seq = 9599
count = 1205
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 280.227997/9597, current 280.236328/9599: elapsed=8335.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9599, expected 9598
(kms_flip:2459) DEBUG: name = flip
last_ts = 280.236328
last_received_ts = 280.235931
last_seq = 9599
current_ts = 280.244659
current_received_ts = 280.244354
current_seq = 9601
count = 1206
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 280.236328/9599, current 280.244659/9601: elapsed=8332.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9601, expected 9600
(kms_flip:2459) DEBUG: name = flip
last_ts = 280.244659
last_received_ts = 280.244354
last_seq = 9601
current_ts = 280.252991
current_received_ts = 280.252594
current_seq = 9603
count = 1207
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 280.244659/9601, current 280.252991/9603: elapsed=8334.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9603, expected 9602
(kms_flip:2459) DEBUG: name = flip
last_ts = 280.252991
last_received_ts = 280.252594
last_seq = 9603
current_ts = 280.261322
current_received_ts = 280.260925
current_seq = 9605
count = 1208
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 280.252991/9603, current 280.261322/9605: elapsed=8332.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9605, expected 9604
(kms_flip:2459) DEBUG: name = flip
last_ts = 280.261322
last_received_ts = 280.260925
last_seq = 9605
current_ts = 280.269653
current_received_ts = 280.269348
current_seq = 9607
count = 1209
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 280.261322/9605, current 280.269653/9607: elapsed=8334.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9607, expected 9606
(kms_flip:2459) DEBUG: name = flip
last_ts = 280.269653
last_received_ts = 280.269348
last_seq = 9607
current_ts = 280.277985
current_received_ts = 280.277588
current_seq = 9609
count = 1210
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 280.269653/9607, current 280.277985/9609: elapsed=8334.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9609, expected 9608
(kms_flip:2459) DEBUG: name = flip
last_ts = 280.277985
last_received_ts = 280.277588
last_seq = 9609
current_ts = 280.286316
current_received_ts = 280.285919
current_seq = 9611
count = 1211
seq_step = 1
(kms_flip:2459) DEBUG: flip ts/seq: last 280.277985/9609, current 280.286316/9611: elapsed=8333.0us expected=8333.4us +- 41.7us, error 0.0%
(kms_flip:2459) DEBUG: unexpected flip seq 9611, expected 9610
(kms_flip:2459) INFO: Event flip: expected 2400, counted 1212, passrate = 2.06%, encoder type 2
(kms_flip:2459) DEBUG: dropped frames, expected 2400, counted 1212, passrate = 2.06%, encoder type 2
(kms_flip:2459) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1704:
(kms_flip:2459) CRITICAL: Failed assertion: !retried
(kms_flip:2459) igt_core-INFO: Stack trace:
(kms_flip:2459) igt_core-INFO:   #0 ../lib/igt_core.c:2075 __igt_fail_assert()
(kms_flip:2459) igt_core-INFO:   #1 ../tests/kms_flip.c:973 run_test_on_crtc_set.constprop.0()
(kms_flip:2459) igt_core-INFO:   #2 ../tests/kms_flip.c:1884 run_test()
(kms_flip:2459) igt_core-INFO:   #3 ../tests/kms_flip.c:2117 __igt_unique____real_main2040()
(kms_flip:2459) igt_core-INFO:   #4 ../tests/kms_flip.c:2040 main()
(kms_flip:2459) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2459) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2459) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest C-eDP1: FAIL (26.065s)
Subtest plain-flip-fb-recreate: FAIL (78.096s)
(kms_flip:2459) igt_kms-CRITICAL: Test assertion failure function kmstest_set_connector_dpms, file ../lib/igt_kms.c:2247:
(kms_flip:2459) igt_kms-CRITICAL: Failed assertion: found_it
(kms_flip:2459) igt_kms-CRITICAL: Last errno: 9, Bad file descriptor
(kms_flip:2459) igt_kms-CRITICAL: DPMS property not found on 205