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

shard-rkl-4

IGT-Version: 2.0-g87be12f9e (x86_64) (Linux: 6.14.0-rc7-CI_DRM_16301-ga123616cf3af+ x86_64)

Using IGT_SRANDOM=1742664256 for randomisation
Opened device: /dev/dri/card0
Using monotonic timestamps
Starting subtest: plain-flip-fb-recreate
Starting dynamic subtest: A-HDMI-A1
  1920x1080: 53 139930 1920 2008 2096 2360 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 18974us; measured 18988.0us +- 4.290us accuracy 0.07%
vblank interval differs from modeline! expected 18973.8us, measured 18988us +- 4.290us, difference 14.2us (3.3 sigma)
Stack trace:
  #0 ../lib/igt_core.c:2055 __igt_fail_assert()
  #1 ../tests/kms_flip.c:777 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1831 run_test()
  #3 ../tests/kms_flip.c:2064 __igt_unique____real_main1987()
  #4 ../tests/kms_flip.c:1987 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest A-HDMI-A1: FAIL (15.729s)
Starting dynamic subtest: B-HDMI-A1
  1920x1080: 53 139930 1920 2008 2096 2360 1080 1084 1089 1125 0x48 0x5 
Expected frametime: 18974us; measured 18832.3us +- 8.284us accuracy 0.13%
vblank interval differs from modeline! expected 18973.8us, measured 18832us +- 8.284us, difference 141.5us (17.1 sigma)
Stack trace:
  #0 ../lib/igt_core.c:2055 __igt_fail_assert()
  #1 ../tests/kms_flip.c:777 run_test_on_crtc_set.constprop.0()
  #2 ../tests/kms_flip.c:1831 run_test()
  #3 ../tests/kms_flip.c:2064 __igt_unique____real_main1987()
  #4 ../tests/kms_flip.c:1987 main()
  #5 [__libc_init_first+0x8a]
  #6 [__libc_start_main+0x8b]
  #7 [_start+0x25]
Dynamic subtest B-HDMI-A1: FAIL (18.775s)
Subtest plain-flip-fb-recreate: FAIL (34.508s)
Stack trace:
  #0 ../lib/igt_core.c:2055 __igt_fail_assert()
  #1 ../lib/igt_kms.c:2246 kmstest_set_connector_dpms()
  #2 ../lib/igt_core.c:2935 igt_atexit_handler()
  #3 [erand48_r+0x1d6]
  #4 [exit+0x1e]
  #5 ../lib/igt_core.c:2390 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-HDMI-A1
(kms_flip:2358) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1660:
(kms_flip:2358) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest A-HDMI-A1 failed.
**** DEBUG ****
(kms_flip:2358) DEBUG: flip ts/seq: last 220.576004/5055, current 220.594986/5056: elapsed=18984.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 220.594986
last_received_ts = 220.594284
last_seq = 5056
current_ts = 220.613968
current_received_ts = 220.613281
current_seq = 5057
count = 514
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 220.594986/5056, current 220.613968/5057: elapsed=18986.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 220.613968
last_received_ts = 220.613281
last_seq = 5057
current_ts = 220.632950
current_received_ts = 220.632263
current_seq = 5058
count = 515
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 220.613968/5057, current 220.632950/5058: elapsed=18986.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 220.632950
last_received_ts = 220.632263
last_seq = 5058
current_ts = 220.651947
current_received_ts = 220.651245
current_seq = 5059
count = 516
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 220.632950/5058, current 220.651947/5059: elapsed=18987.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 220.651947
last_received_ts = 220.651245
last_seq = 5059
current_ts = 220.670929
current_received_ts = 220.670242
current_seq = 5060
count = 517
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 220.651947/5059, current 220.670929/5060: elapsed=18984.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 220.670929
last_received_ts = 220.670242
last_seq = 5060
current_ts = 220.689911
current_received_ts = 220.689224
current_seq = 5061
count = 518
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 220.670929/5060, current 220.689911/5061: elapsed=18986.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 220.689911
last_received_ts = 220.689224
last_seq = 5061
current_ts = 220.708893
current_received_ts = 220.708206
current_seq = 5062
count = 519
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 220.689911/5061, current 220.708893/5062: elapsed=18987.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 220.708893
last_received_ts = 220.708206
last_seq = 5062
current_ts = 220.727875
current_received_ts = 220.727188
current_seq = 5063
count = 520
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 220.708893/5062, current 220.727875/5063: elapsed=18985.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 220.727875
last_received_ts = 220.727188
last_seq = 5063
current_ts = 220.746872
current_received_ts = 220.746185
current_seq = 5064
count = 521
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 220.727875/5063, current 220.746872/5064: elapsed=18986.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 220.746872
last_received_ts = 220.746185
last_seq = 5064
current_ts = 220.765854
current_received_ts = 220.765167
current_seq = 5065
count = 522
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 220.746872/5064, current 220.765854/5065: elapsed=18986.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 220.765854
last_received_ts = 220.765167
last_seq = 5065
current_ts = 220.784836
current_received_ts = 220.784149
current_seq = 5066
count = 523
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 220.765854/5065, current 220.784836/5066: elapsed=18986.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 220.784836
last_received_ts = 220.784149
last_seq = 5066
current_ts = 220.803818
current_received_ts = 220.803131
current_seq = 5067
count = 524
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 220.784836/5066, current 220.803818/5067: elapsed=18985.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 220.803818
last_received_ts = 220.803131
last_seq = 5067
current_ts = 220.822815
current_received_ts = 220.822128
current_seq = 5068
count = 525
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 220.803818/5067, current 220.822815/5068: elapsed=18986.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 220.822815
last_received_ts = 220.822128
last_seq = 5068
current_ts = 220.841797
current_received_ts = 220.841110
current_seq = 5069
count = 526
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 220.822815/5068, current 220.841797/5069: elapsed=18985.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 220.841797
last_received_ts = 220.841110
last_seq = 5069
current_ts = 220.860779
current_received_ts = 220.860092
current_seq = 5070
count = 527
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 220.841797/5069, current 220.860779/5070: elapsed=18987.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 220.860779
last_received_ts = 220.860092
last_seq = 5070
current_ts = 220.879761
current_received_ts = 220.879074
current_seq = 5071
count = 528
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 220.860779/5070, current 220.879761/5071: elapsed=18985.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 220.879761
last_received_ts = 220.879074
last_seq = 5071
current_ts = 220.898758
current_received_ts = 220.898071
current_seq = 5072
count = 529
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 220.879761/5071, current 220.898758/5072: elapsed=18986.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 220.898758
last_received_ts = 220.898071
last_seq = 5072
current_ts = 220.917740
current_received_ts = 220.917068
current_seq = 5073
count = 530
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 220.898758/5072, current 220.917740/5073: elapsed=18985.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 220.917740
last_received_ts = 220.917068
last_seq = 5073
current_ts = 220.936722
current_received_ts = 220.936081
current_seq = 5074
count = 531
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 220.917740/5073, current 220.936722/5074: elapsed=18986.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 220.936722
last_received_ts = 220.936081
last_seq = 5074
current_ts = 220.955704
current_received_ts = 220.955093
current_seq = 5075
count = 532
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 220.936722/5074, current 220.955704/5075: elapsed=18986.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 220.955704
last_received_ts = 220.955093
last_seq = 5075
current_ts = 220.974701
current_received_ts = 220.974030
current_seq = 5076
count = 533
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 220.955704/5075, current 220.974701/5076: elapsed=18986.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 220.974701
last_received_ts = 220.974030
last_seq = 5076
current_ts = 220.993683
current_received_ts = 220.992996
current_seq = 5077
count = 534
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 220.974701/5076, current 220.993683/5077: elapsed=18985.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 220.993683
last_received_ts = 220.992996
last_seq = 5077
current_ts = 221.012665
current_received_ts = 221.011978
current_seq = 5078
count = 535
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 220.993683/5077, current 221.012665/5078: elapsed=18985.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 221.012665
last_received_ts = 221.011978
last_seq = 5078
current_ts = 221.031647
current_received_ts = 221.030960
current_seq = 5079
count = 536
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 221.012665/5078, current 221.031647/5079: elapsed=18986.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 221.031647
last_received_ts = 221.030960
last_seq = 5079
current_ts = 221.050644
current_received_ts = 221.049957
current_seq = 5080
count = 537
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 221.031647/5079, current 221.050644/5080: elapsed=18986.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 221.050644
last_received_ts = 221.049957
last_seq = 5080
current_ts = 221.069626
current_received_ts = 221.068939
current_seq = 5081
count = 538
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 221.050644/5080, current 221.069626/5081: elapsed=18986.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 221.069626
last_received_ts = 221.068939
last_seq = 5081
current_ts = 221.088608
current_received_ts = 221.087921
current_seq = 5082
count = 539
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 221.069626/5081, current 221.088608/5082: elapsed=18985.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 221.088608
last_received_ts = 221.087921
last_seq = 5082
current_ts = 221.107590
current_received_ts = 221.106903
current_seq = 5083
count = 540
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 221.088608/5082, current 221.107590/5083: elapsed=18985.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 221.107590
last_received_ts = 221.106903
last_seq = 5083
current_ts = 221.126587
current_received_ts = 221.125885
current_seq = 5084
count = 541
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 221.107590/5083, current 221.126587/5084: elapsed=18986.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 221.126587
last_received_ts = 221.125885
last_seq = 5084
current_ts = 221.145569
current_received_ts = 221.144882
current_seq = 5085
count = 542
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 221.126587/5084, current 221.145569/5085: elapsed=18986.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 221.145569
last_received_ts = 221.144882
last_seq = 5085
current_ts = 221.164551
current_received_ts = 221.163864
current_seq = 5086
count = 543
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 221.145569/5085, current 221.164551/5086: elapsed=18985.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 221.164551
last_received_ts = 221.163864
last_seq = 5086
current_ts = 221.183533
current_received_ts = 221.182846
current_seq = 5087
count = 544
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 221.164551/5086, current 221.183533/5087: elapsed=18984.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 221.183533
last_received_ts = 221.182846
last_seq = 5087
current_ts = 221.202530
current_received_ts = 221.201828
current_seq = 5088
count = 545
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 221.183533/5087, current 221.202530/5088: elapsed=18988.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 221.202530
last_received_ts = 221.201828
last_seq = 5088
current_ts = 221.221512
current_received_ts = 221.220825
current_seq = 5089
count = 546
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 221.202530/5088, current 221.221512/5089: elapsed=18985.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 221.221512
last_received_ts = 221.220825
last_seq = 5089
current_ts = 221.240494
current_received_ts = 221.239807
current_seq = 5090
count = 547
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 221.221512/5089, current 221.240494/5090: elapsed=18986.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 221.240494
last_received_ts = 221.239807
last_seq = 5090
current_ts = 221.259476
current_received_ts = 221.258789
current_seq = 5091
count = 548
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 221.240494/5090, current 221.259476/5091: elapsed=18985.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 221.259476
last_received_ts = 221.258789
last_seq = 5091
current_ts = 221.278473
current_received_ts = 221.277771
current_seq = 5092
count = 549
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 221.259476/5091, current 221.278473/5092: elapsed=18986.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 221.278473
last_received_ts = 221.277771
last_seq = 5092
current_ts = 221.297455
current_received_ts = 221.296768
current_seq = 5093
count = 550
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 221.278473/5092, current 221.297455/5093: elapsed=18985.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 221.297455
last_received_ts = 221.296768
last_seq = 5093
current_ts = 221.316437
current_received_ts = 221.315750
current_seq = 5094
count = 551
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 221.297455/5093, current 221.316437/5094: elapsed=18986.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 221.316437
last_received_ts = 221.315750
last_seq = 5094
current_ts = 221.335419
current_received_ts = 221.334732
current_seq = 5095
count = 552
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 221.316437/5094, current 221.335419/5095: elapsed=18985.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 221.335419
last_received_ts = 221.334732
last_seq = 5095
current_ts = 221.354416
current_received_ts = 221.353729
current_seq = 5096
count = 553
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 221.335419/5095, current 221.354416/5096: elapsed=18987.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 221.354416
last_received_ts = 221.353729
last_seq = 5096
current_ts = 221.373398
current_received_ts = 221.372711
current_seq = 5097
count = 554
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 221.354416/5096, current 221.373398/5097: elapsed=18985.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 221.373398
last_received_ts = 221.372711
last_seq = 5097
current_ts = 221.392380
current_received_ts = 221.391693
current_seq = 5098
count = 555
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 221.373398/5097, current 221.392380/5098: elapsed=18986.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 221.392380
last_received_ts = 221.391693
last_seq = 5098
current_ts = 221.411362
current_received_ts = 221.410675
current_seq = 5099
count = 556
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 221.392380/5098, current 221.411362/5099: elapsed=18986.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 221.411362
last_received_ts = 221.410675
last_seq = 5099
current_ts = 221.430344
current_received_ts = 221.429657
current_seq = 5100
count = 557
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 221.411362/5099, current 221.430344/5100: elapsed=18985.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 221.430344
last_received_ts = 221.429657
last_seq = 5100
current_ts = 221.449341
current_received_ts = 221.448654
current_seq = 5101
count = 558
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 221.430344/5100, current 221.449341/5101: elapsed=18985.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 221.449341
last_received_ts = 221.448654
last_seq = 5101
current_ts = 221.468323
current_received_ts = 221.467636
current_seq = 5102
count = 559
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 221.449341/5101, current 221.468323/5102: elapsed=18986.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 221.468323
last_received_ts = 221.467636
last_seq = 5102
current_ts = 221.487305
current_received_ts = 221.486618
current_seq = 5103
count = 560
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 221.468323/5102, current 221.487305/5103: elapsed=18986.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 221.487305
last_received_ts = 221.486618
last_seq = 5103
current_ts = 221.506287
current_received_ts = 221.505600
current_seq = 5104
count = 561
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 221.487305/5103, current 221.506287/5104: elapsed=18985.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 221.506287
last_received_ts = 221.505600
last_seq = 5104
current_ts = 221.525284
current_received_ts = 221.524597
current_seq = 5105
count = 562
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 221.506287/5104, current 221.525284/5105: elapsed=18986.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 221.525284
last_received_ts = 221.524597
last_seq = 5105
current_ts = 221.544266
current_received_ts = 221.543579
current_seq = 5106
count = 563
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 221.525284/5105, current 221.544266/5106: elapsed=18986.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 221.544266
last_received_ts = 221.543579
last_seq = 5106
current_ts = 221.563248
current_received_ts = 221.562561
current_seq = 5107
count = 564
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 221.544266/5106, current 221.563248/5107: elapsed=18986.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 221.563248
last_received_ts = 221.562561
last_seq = 5107
current_ts = 221.582230
current_received_ts = 221.581543
current_seq = 5108
count = 565
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 221.563248/5107, current 221.582230/5108: elapsed=18986.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 221.582230
last_received_ts = 221.581543
last_seq = 5108
current_ts = 221.601227
current_received_ts = 221.600525
current_seq = 5109
count = 566
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 221.582230/5108, current 221.601227/5109: elapsed=18985.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 221.601227
last_received_ts = 221.600525
last_seq = 5109
current_ts = 221.620209
current_received_ts = 221.619522
current_seq = 5110
count = 567
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 221.601227/5109, current 221.620209/5110: elapsed=18985.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 221.620209
last_received_ts = 221.619522
last_seq = 5110
current_ts = 221.639191
current_received_ts = 221.638504
current_seq = 5111
count = 568
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 221.620209/5110, current 221.639191/5111: elapsed=18986.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 221.639191
last_received_ts = 221.638504
last_seq = 5111
current_ts = 221.658173
current_received_ts = 221.657486
current_seq = 5112
count = 569
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 221.639191/5111, current 221.658173/5112: elapsed=18986.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 221.658173
last_received_ts = 221.657486
last_seq = 5112
current_ts = 221.677170
current_received_ts = 221.676483
current_seq = 5113
count = 570
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 221.658173/5112, current 221.677170/5113: elapsed=18985.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 221.677170
last_received_ts = 221.676483
last_seq = 5113
current_ts = 221.696152
current_received_ts = 221.695465
current_seq = 5114
count = 571
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 221.677170/5113, current 221.696152/5114: elapsed=18985.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 221.696152
last_received_ts = 221.695465
last_seq = 5114
current_ts = 221.715134
current_received_ts = 221.714447
current_seq = 5115
count = 572
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 221.696152/5114, current 221.715134/5115: elapsed=18986.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 221.715134
last_received_ts = 221.714447
last_seq = 5115
current_ts = 221.734116
current_received_ts = 221.733429
current_seq = 5116
count = 573
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 221.715134/5115, current 221.734116/5116: elapsed=18986.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 221.734116
last_received_ts = 221.733429
last_seq = 5116
current_ts = 221.753113
current_received_ts = 221.752426
current_seq = 5117
count = 574
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 221.734116/5116, current 221.753113/5117: elapsed=18985.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 221.753113
last_received_ts = 221.752426
last_seq = 5117
current_ts = 221.772095
current_received_ts = 221.771408
current_seq = 5118
count = 575
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 221.753113/5117, current 221.772095/5118: elapsed=18986.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 221.772095
last_received_ts = 221.771408
last_seq = 5118
current_ts = 221.791077
current_received_ts = 221.790390
current_seq = 5119
count = 576
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 221.772095/5118, current 221.791077/5119: elapsed=18986.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 221.791077
last_received_ts = 221.790390
last_seq = 5119
current_ts = 221.810059
current_received_ts = 221.809372
current_seq = 5120
count = 577
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 221.791077/5119, current 221.810059/5120: elapsed=18985.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 221.810059
last_received_ts = 221.809372
last_seq = 5120
current_ts = 221.829056
current_received_ts = 221.828354
current_seq = 5121
count = 578
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 221.810059/5120, current 221.829056/5121: elapsed=18986.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 221.829056
last_received_ts = 221.828354
last_seq = 5121
current_ts = 221.848038
current_received_ts = 221.847351
current_seq = 5122
count = 579
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 221.829056/5121, current 221.848038/5122: elapsed=18985.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 221.848038
last_received_ts = 221.847351
last_seq = 5122
current_ts = 221.867020
current_received_ts = 221.866333
current_seq = 5123
count = 580
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 221.848038/5122, current 221.867020/5123: elapsed=18986.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 221.867020
last_received_ts = 221.866333
last_seq = 5123
current_ts = 221.886002
current_received_ts = 221.885315
current_seq = 5124
count = 581
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 221.867020/5123, current 221.886002/5124: elapsed=18986.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 221.886002
last_received_ts = 221.885315
last_seq = 5124
current_ts = 221.904984
current_received_ts = 221.904297
current_seq = 5125
count = 582
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 221.886002/5124, current 221.904984/5125: elapsed=18985.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 221.904984
last_received_ts = 221.904297
last_seq = 5125
current_ts = 221.923981
current_received_ts = 221.923279
current_seq = 5126
count = 583
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 221.904984/5125, current 221.923981/5126: elapsed=18985.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 221.923981
last_received_ts = 221.923279
last_seq = 5126
current_ts = 221.942963
current_received_ts = 221.942276
current_seq = 5127
count = 584
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 221.923981/5126, current 221.942963/5127: elapsed=18986.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 221.942963
last_received_ts = 221.942276
last_seq = 5127
current_ts = 221.961945
current_received_ts = 221.961258
current_seq = 5128
count = 585
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 221.942963/5127, current 221.961945/5128: elapsed=18985.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 221.961945
last_received_ts = 221.961258
last_seq = 5128
current_ts = 221.980927
current_received_ts = 221.980240
current_seq = 5129
count = 586
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 221.961945/5128, current 221.980927/5129: elapsed=18986.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 221.980927
last_received_ts = 221.980240
last_seq = 5129
current_ts = 221.999924
current_received_ts = 221.999222
current_seq = 5130
count = 587
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 221.980927/5129, current 221.999924/5130: elapsed=18985.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 221.999924
last_received_ts = 221.999222
last_seq = 5130
current_ts = 222.018906
current_received_ts = 222.018204
current_seq = 5131
count = 588
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 221.999924/5130, current 222.018906/5131: elapsed=18985.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 222.018906
last_received_ts = 222.018204
last_seq = 5131
current_ts = 222.037888
current_received_ts = 222.037201
current_seq = 5132
count = 589
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 222.018906/5131, current 222.037888/5132: elapsed=18986.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 222.037888
last_received_ts = 222.037201
last_seq = 5132
current_ts = 222.056870
current_received_ts = 222.056183
current_seq = 5133
count = 590
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 222.037888/5132, current 222.056870/5133: elapsed=18986.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 222.056870
last_received_ts = 222.056183
last_seq = 5133
current_ts = 222.075867
current_received_ts = 222.075165
current_seq = 5134
count = 591
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 222.056870/5133, current 222.075867/5134: elapsed=18986.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 222.075867
last_received_ts = 222.075165
last_seq = 5134
current_ts = 222.094849
current_received_ts = 222.094147
current_seq = 5135
count = 592
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 222.075867/5134, current 222.094849/5135: elapsed=18984.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 222.094849
last_received_ts = 222.094147
last_seq = 5135
current_ts = 222.113831
current_received_ts = 222.113144
current_seq = 5136
count = 593
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 222.094849/5135, current 222.113831/5136: elapsed=18986.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 222.113831
last_received_ts = 222.113144
last_seq = 5136
current_ts = 222.132812
current_received_ts = 222.132126
current_seq = 5137
count = 594
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 222.113831/5136, current 222.132812/5137: elapsed=18986.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 222.132812
last_received_ts = 222.132126
last_seq = 5137
current_ts = 222.151794
current_received_ts = 222.151123
current_seq = 5138
count = 595
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 222.132812/5137, current 222.151794/5138: elapsed=18985.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 222.151794
last_received_ts = 222.151123
last_seq = 5138
current_ts = 222.170792
current_received_ts = 222.170090
current_seq = 5139
count = 596
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 222.151794/5138, current 222.170792/5139: elapsed=18986.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 222.170792
last_received_ts = 222.170090
last_seq = 5139
current_ts = 222.189774
current_received_ts = 222.189072
current_seq = 5140
count = 597
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 222.170792/5139, current 222.189774/5140: elapsed=18985.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 222.189774
last_received_ts = 222.189072
last_seq = 5140
current_ts = 222.208755
current_received_ts = 222.208099
current_seq = 5141
count = 598
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 222.189774/5140, current 222.208755/5141: elapsed=18986.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 222.208755
last_received_ts = 222.208099
last_seq = 5141
current_ts = 222.227737
current_received_ts = 222.227066
current_seq = 5142
count = 599
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 222.208755/5141, current 222.227737/5142: elapsed=18986.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 222.227737
last_received_ts = 222.227066
last_seq = 5142
current_ts = 222.246735
current_received_ts = 222.246078
current_seq = 5143
count = 600
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 222.227737/5142, current 222.246735/5143: elapsed=18985.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 222.246735
last_received_ts = 222.246078
last_seq = 5143
current_ts = 222.265717
current_received_ts = 222.265060
current_seq = 5144
count = 601
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 222.246735/5143, current 222.265717/5144: elapsed=18985.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 222.265717
last_received_ts = 222.265060
last_seq = 5144
current_ts = 222.284698
current_received_ts = 222.284027
current_seq = 5145
count = 602
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 222.265717/5144, current 222.284698/5145: elapsed=18985.0us expected=18988.0us +- 94.9us, error 0.0%
(kms_flip:2358) DEBUG: name = flip
last_ts = 222.284698
last_received_ts = 222.284027
last_seq = 5145
current_ts = 222.303665
current_received_ts = 222.302979
current_seq = 5146
count = 603
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 222.284698/5145, current 222.303665/5146: elapsed=18972.0us expected=18988.0us +- 94.9us, error 0.1%
(kms_flip:2358) DEBUG: name = flip
last_ts = 222.303665
last_received_ts = 222.302979
last_seq = 5146
current_ts = 222.322632
current_received_ts = 222.321945
current_seq = 5147
count = 604
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 222.303665/5146, current 222.322632/5147: elapsed=18967.0us expected=18988.0us +- 94.9us, error 0.1%
(kms_flip:2358) DEBUG: name = flip
last_ts = 222.322632
last_received_ts = 222.321945
last_seq = 5147
current_ts = 222.341599
current_received_ts = 222.340912
current_seq = 5148
count = 605
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 222.322632/5147, current 222.341599/5148: elapsed=18966.0us expected=18988.0us +- 94.9us, error 0.1%
(kms_flip:2358) DEBUG: name = flip
last_ts = 222.341599
last_received_ts = 222.340912
last_seq = 5148
current_ts = 222.360565
current_received_ts = 222.359879
current_seq = 5149
count = 606
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 222.341599/5148, current 222.360565/5149: elapsed=18967.0us expected=18988.0us +- 94.9us, error 0.1%
(kms_flip:2358) DEBUG: name = flip
last_ts = 222.360565
last_received_ts = 222.359879
last_seq = 5149
current_ts = 222.379532
current_received_ts = 222.378845
current_seq = 5150
count = 607
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 222.360565/5149, current 222.379532/5150: elapsed=18966.0us expected=18988.0us +- 94.9us, error 0.1%
(kms_flip:2358) DEBUG: name = flip
last_ts = 222.379532
last_received_ts = 222.378845
last_seq = 5150
current_ts = 222.398499
current_received_ts = 222.397812
current_seq = 5151
count = 608
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 222.379532/5150, current 222.398499/5151: elapsed=18967.0us expected=18988.0us +- 94.9us, error 0.1%
(kms_flip:2358) DEBUG: name = flip
last_ts = 222.398499
last_received_ts = 222.397812
last_seq = 5151
current_ts = 222.417465
current_received_ts = 222.416779
current_seq = 5152
count = 609
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 222.398499/5151, current 222.417465/5152: elapsed=18967.0us expected=18988.0us +- 94.9us, error 0.1%
(kms_flip:2358) DEBUG: name = flip
last_ts = 222.417465
last_received_ts = 222.416779
last_seq = 5152
current_ts = 222.436432
current_received_ts = 222.435745
current_seq = 5153
count = 610
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 222.417465/5152, current 222.436432/5153: elapsed=18965.0us expected=18988.0us +- 94.9us, error 0.1%
(kms_flip:2358) DEBUG: name = flip
last_ts = 222.436432
last_received_ts = 222.435745
last_seq = 5153
current_ts = 222.455399
current_received_ts = 222.454712
current_seq = 5154
count = 611
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 222.436432/5153, current 222.455399/5154: elapsed=18967.0us expected=18988.0us +- 94.9us, error 0.1%
(kms_flip:2358) DEBUG: name = flip
last_ts = 222.455399
last_received_ts = 222.454712
last_seq = 5154
current_ts = 222.474365
current_received_ts = 222.473679
current_seq = 5155
count = 612
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 222.455399/5154, current 222.474365/5155: elapsed=18967.0us expected=18988.0us +- 94.9us, error 0.1%
(kms_flip:2358) DEBUG: name = flip
last_ts = 222.474365
last_received_ts = 222.473679
last_seq = 5155
current_ts = 222.493332
current_received_ts = 222.492645
current_seq = 5156
count = 613
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 222.474365/5155, current 222.493332/5156: elapsed=18967.0us expected=18988.0us +- 94.9us, error 0.1%
(kms_flip:2358) DEBUG: name = flip
last_ts = 222.493332
last_received_ts = 222.492645
last_seq = 5156
current_ts = 222.512299
current_received_ts = 222.511612
current_seq = 5157
count = 614
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 222.493332/5156, current 222.512299/5157: elapsed=18965.0us expected=18988.0us +- 94.9us, error 0.1%
(kms_flip:2358) DEBUG: name = flip
last_ts = 222.512299
last_received_ts = 222.511612
last_seq = 5157
current_ts = 222.531265
current_received_ts = 222.530579
current_seq = 5158
count = 615
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 222.512299/5157, current 222.531265/5158: elapsed=18967.0us expected=18988.0us +- 94.9us, error 0.1%
(kms_flip:2358) DEBUG: name = flip
last_ts = 222.531265
last_received_ts = 222.530579
last_seq = 5158
current_ts = 222.550232
current_received_ts = 222.549545
current_seq = 5159
count = 616
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 222.531265/5158, current 222.550232/5159: elapsed=18967.0us expected=18988.0us +- 94.9us, error 0.1%
(kms_flip:2358) DEBUG: name = flip
last_ts = 222.550232
last_received_ts = 222.549545
last_seq = 5159
current_ts = 222.569199
current_received_ts = 222.568512
current_seq = 5160
count = 617
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 222.550232/5159, current 222.569199/5160: elapsed=18966.0us expected=18988.0us +- 94.9us, error 0.1%
(kms_flip:2358) DEBUG: name = flip
last_ts = 222.569199
last_received_ts = 222.568512
last_seq = 5160
current_ts = 222.588165
current_received_ts = 222.587479
current_seq = 5161
count = 618
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 222.569199/5160, current 222.588165/5161: elapsed=18967.0us expected=18988.0us +- 94.9us, error 0.1%
(kms_flip:2358) DEBUG: name = flip
last_ts = 222.588165
last_received_ts = 222.587479
last_seq = 5161
current_ts = 222.607132
current_received_ts = 222.606445
current_seq = 5162
count = 619
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 222.588165/5161, current 222.607132/5162: elapsed=18966.0us expected=18988.0us +- 94.9us, error 0.1%
(kms_flip:2358) DEBUG: name = flip
last_ts = 222.607132
last_received_ts = 222.606445
last_seq = 5162
current_ts = 222.626099
current_received_ts = 222.625412
current_seq = 5163
count = 620
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 222.607132/5162, current 222.626099/5163: elapsed=18967.0us expected=18988.0us +- 94.9us, error 0.1%
(kms_flip:2358) DEBUG: name = flip
last_ts = 222.626099
last_received_ts = 222.625412
last_seq = 5163
current_ts = 222.645065
current_received_ts = 222.645111
current_seq = 5164
count = 621
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 222.626099/5163, current 222.645065/5164: elapsed=18966.0us expected=18988.0us +- 94.9us, error 0.1%
(kms_flip:2358) DEBUG: name = flip
last_ts = 222.645065
last_received_ts = 222.645111
last_seq = 5164
current_ts = 222.664032
current_received_ts = 222.663361
current_seq = 5165
count = 622
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 222.645065/5164, current 222.664032/5165: elapsed=18968.0us expected=18988.0us +- 94.9us, error 0.1%
(kms_flip:2358) DEBUG: name = flip
last_ts = 222.664032
last_received_ts = 222.663361
last_seq = 5165
current_ts = 222.682999
current_received_ts = 222.682327
current_seq = 5166
count = 623
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 222.664032/5165, current 222.682999/5166: elapsed=18965.0us expected=18988.0us +- 94.9us, error 0.1%
(kms_flip:2358) DEBUG: name = flip
last_ts = 222.682999
last_received_ts = 222.682327
last_seq = 5166
current_ts = 222.701965
current_received_ts = 222.701279
current_seq = 5167
count = 624
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 222.682999/5166, current 222.701965/5167: elapsed=18967.0us expected=18988.0us +- 94.9us, error 0.1%
(kms_flip:2358) DEBUG: name = flip
last_ts = 222.701965
last_received_ts = 222.701279
last_seq = 5167
current_ts = 222.720932
current_received_ts = 222.720245
current_seq = 5168
count = 625
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 222.701965/5167, current 222.720932/5168: elapsed=18966.0us expected=18988.0us +- 94.9us, error 0.1%
(kms_flip:2358) DEBUG: name = flip
last_ts = 222.720932
last_received_ts = 222.720245
last_seq = 5168
current_ts = 222.739899
current_received_ts = 222.739212
current_seq = 5169
count = 626
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 222.720932/5168, current 222.739899/5169: elapsed=18967.0us expected=18988.0us +- 94.9us, error 0.1%
(kms_flip:2358) DEBUG: name = flip
last_ts = 222.739899
last_received_ts = 222.739212
last_seq = 5169
current_ts = 222.758865
current_received_ts = 222.758179
current_seq = 5170
count = 627
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 222.739899/5169, current 222.758865/5170: elapsed=18966.0us expected=18988.0us +- 94.9us, error 0.1%
(kms_flip:2358) DEBUG: name = flip
last_ts = 222.758865
last_received_ts = 222.758179
last_seq = 5170
current_ts = 222.777832
current_received_ts = 222.777145
current_seq = 5171
count = 628
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 222.758865/5170, current 222.777832/5171: elapsed=18967.0us expected=18988.0us +- 94.9us, error 0.1%
(kms_flip:2358) DEBUG: name = flip
last_ts = 222.777832
last_received_ts = 222.777145
last_seq = 5171
current_ts = 222.796799
current_received_ts = 222.796112
current_seq = 5172
count = 629
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 222.777832/5171, current 222.796799/5172: elapsed=18966.0us expected=18988.0us +- 94.9us, error 0.1%
(kms_flip:2358) DEBUG: name = flip
last_ts = 222.796799
last_received_ts = 222.796112
last_seq = 5172
current_ts = 222.815765
current_received_ts = 222.815079
current_seq = 5173
count = 630
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 222.796799/5172, current 222.815765/5173: elapsed=18966.0us expected=18988.0us +- 94.9us, error 0.1%
(kms_flip:2358) DEBUG: name = flip
last_ts = 222.815765
last_received_ts = 222.815079
last_seq = 5173
current_ts = 222.834732
current_received_ts = 222.834045
current_seq = 5174
count = 631
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 222.815765/5173, current 222.834732/5174: elapsed=18968.0us expected=18988.0us +- 94.9us, error 0.1%
(kms_flip:2358) DEBUG: name = flip
last_ts = 222.834732
last_received_ts = 222.834045
last_seq = 5174
current_ts = 222.853699
current_received_ts = 222.853043
current_seq = 5175
count = 632
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 222.834732/5174, current 222.853699/5175: elapsed=18966.0us expected=18988.0us +- 94.9us, error 0.1%
(kms_flip:2358) DEBUG: name = flip
last_ts = 222.853699
last_received_ts = 222.853043
last_seq = 5175
current_ts = 222.872543
current_received_ts = 222.871857
current_seq = 5176
count = 633
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 222.853699/5175, current 222.872543/5176: elapsed=18847.0us expected=18988.0us +- 94.9us, error 0.7%
(kms_flip:2358) DEBUG: inconsistent flip ts/seq: last 222.853699/5175, current 222.872543/5176: elapsed=18847.0us expected=18988.0us
(kms_flip:2358) DEBUG: expected 0, counted 633, encoder type 2
(kms_flip:2358) DEBUG: dropped frames, expected 0, counted 633, encoder type 2
(kms_flip:2358) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1660:
(kms_flip:2358) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:2358) igt_core-INFO: Stack trace:
(kms_flip:2358) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:2358) igt_core-INFO:   #1 ../tests/kms_flip.c:777 run_test_on_crtc_set.constprop.0()
(kms_flip:2358) igt_core-INFO:   #2 ../tests/kms_flip.c:1831 run_test()
(kms_flip:2358) igt_core-INFO:   #3 ../tests/kms_flip.c:2064 __igt_unique____real_main1987()
(kms_flip:2358) igt_core-INFO:   #4 ../tests/kms_flip.c:1987 main()
(kms_flip:2358) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2358) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2358) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest A-HDMI-A1: FAIL (15.729s)
Starting dynamic subtest: B-HDMI-A1
(kms_flip:2358) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1660:
(kms_flip:2358) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
Dynamic subtest B-HDMI-A1 failed.
**** DEBUG ****
(kms_flip:2358) DEBUG: name = flip
last_ts = 239.251984
last_received_ts = 239.251297
last_seq = 1016
current_ts = 239.270889
current_received_ts = 239.270203
current_seq = 1017
count = 674
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 239.251984/1016, current 239.270889/1017: elapsed=18907.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 239.270889
last_received_ts = 239.270203
last_seq = 1017
current_ts = 239.289795
current_received_ts = 239.289108
current_seq = 1018
count = 675
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 239.270889/1017, current 239.289795/1018: elapsed=18908.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 239.289795
last_received_ts = 239.289108
last_seq = 1018
current_ts = 239.308701
current_received_ts = 239.308029
current_seq = 1019
count = 676
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 239.289795/1018, current 239.308701/1019: elapsed=18907.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 239.308701
last_received_ts = 239.308029
last_seq = 1019
current_ts = 239.327606
current_received_ts = 239.326920
current_seq = 1020
count = 677
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 239.308701/1019, current 239.327606/1020: elapsed=18907.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 239.327606
last_received_ts = 239.326920
last_seq = 1020
current_ts = 239.346512
current_received_ts = 239.345825
current_seq = 1021
count = 678
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 239.327606/1020, current 239.346512/1021: elapsed=18907.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 239.346512
last_received_ts = 239.345825
last_seq = 1021
current_ts = 239.365433
current_received_ts = 239.364731
current_seq = 1022
count = 679
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 239.346512/1021, current 239.365433/1022: elapsed=18908.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 239.365433
last_received_ts = 239.364731
last_seq = 1022
current_ts = 239.384338
current_received_ts = 239.383636
current_seq = 1023
count = 680
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 239.365433/1022, current 239.384338/1023: elapsed=18907.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 239.384338
last_received_ts = 239.383636
last_seq = 1023
current_ts = 239.403244
current_received_ts = 239.402557
current_seq = 1024
count = 681
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 239.384338/1023, current 239.403244/1024: elapsed=18908.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 239.403244
last_received_ts = 239.402557
last_seq = 1024
current_ts = 239.422150
current_received_ts = 239.421463
current_seq = 1025
count = 682
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 239.403244/1024, current 239.422150/1025: elapsed=18906.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 239.422150
last_received_ts = 239.421463
last_seq = 1025
current_ts = 239.441055
current_received_ts = 239.440369
current_seq = 1026
count = 683
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 239.422150/1025, current 239.441055/1026: elapsed=18907.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 239.441055
last_received_ts = 239.440369
last_seq = 1026
current_ts = 239.459961
current_received_ts = 239.459274
current_seq = 1027
count = 684
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 239.441055/1026, current 239.459961/1027: elapsed=18908.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 239.459961
last_received_ts = 239.459274
last_seq = 1027
current_ts = 239.478867
current_received_ts = 239.478180
current_seq = 1028
count = 685
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 239.459961/1027, current 239.478867/1028: elapsed=18907.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 239.478867
last_received_ts = 239.478180
last_seq = 1028
current_ts = 239.497772
current_received_ts = 239.497086
current_seq = 1029
count = 686
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 239.478867/1028, current 239.497772/1029: elapsed=18908.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 239.497772
last_received_ts = 239.497086
last_seq = 1029
current_ts = 239.516678
current_received_ts = 239.515991
current_seq = 1030
count = 687
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 239.497772/1029, current 239.516678/1030: elapsed=18907.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 239.516678
last_received_ts = 239.515991
last_seq = 1030
current_ts = 239.535599
current_received_ts = 239.534912
current_seq = 1031
count = 688
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 239.516678/1030, current 239.535599/1031: elapsed=18910.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 239.535599
last_received_ts = 239.534912
last_seq = 1031
current_ts = 239.554504
current_received_ts = 239.553818
current_seq = 1032
count = 689
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 239.535599/1031, current 239.554504/1032: elapsed=18907.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 239.554504
last_received_ts = 239.553818
last_seq = 1032
current_ts = 239.573410
current_received_ts = 239.572723
current_seq = 1033
count = 690
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 239.554504/1032, current 239.573410/1033: elapsed=18908.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 239.573410
last_received_ts = 239.572723
last_seq = 1033
current_ts = 239.592316
current_received_ts = 239.591629
current_seq = 1034
count = 691
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 239.573410/1033, current 239.592316/1034: elapsed=18906.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 239.592316
last_received_ts = 239.591629
last_seq = 1034
current_ts = 239.611221
current_received_ts = 239.610535
current_seq = 1035
count = 692
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 239.592316/1034, current 239.611221/1035: elapsed=18908.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 239.611221
last_received_ts = 239.610535
last_seq = 1035
current_ts = 239.630127
current_received_ts = 239.629440
current_seq = 1036
count = 693
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 239.611221/1035, current 239.630127/1036: elapsed=18907.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 239.630127
last_received_ts = 239.629440
last_seq = 1036
current_ts = 239.649033
current_received_ts = 239.648346
current_seq = 1037
count = 694
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 239.630127/1036, current 239.649033/1037: elapsed=18908.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 239.649033
last_received_ts = 239.648346
last_seq = 1037
current_ts = 239.667938
current_received_ts = 239.667252
current_seq = 1038
count = 695
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 239.649033/1037, current 239.667938/1038: elapsed=18906.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 239.667938
last_received_ts = 239.667252
last_seq = 1038
current_ts = 239.686859
current_received_ts = 239.686157
current_seq = 1039
count = 696
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 239.667938/1038, current 239.686859/1039: elapsed=18908.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 239.686859
last_received_ts = 239.686157
last_seq = 1039
current_ts = 239.705765
current_received_ts = 239.705078
current_seq = 1040
count = 697
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 239.686859/1039, current 239.705765/1040: elapsed=18917.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 239.705765
last_received_ts = 239.705078
last_seq = 1040
current_ts = 239.724670
current_received_ts = 239.723984
current_seq = 1041
count = 698
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 239.705765/1040, current 239.724670/1041: elapsed=18898.0us expected=18832.3us +- 94.2us, error 0.3%
(kms_flip:2358) DEBUG: name = flip
last_ts = 239.724670
last_received_ts = 239.723984
last_seq = 1041
current_ts = 239.743576
current_received_ts = 239.742889
current_seq = 1042
count = 699
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 239.724670/1041, current 239.743576/1042: elapsed=18907.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 239.743576
last_received_ts = 239.742889
last_seq = 1042
current_ts = 239.762482
current_received_ts = 239.761795
current_seq = 1043
count = 700
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 239.743576/1042, current 239.762482/1043: elapsed=18907.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 239.762482
last_received_ts = 239.761795
last_seq = 1043
current_ts = 239.781387
current_received_ts = 239.780701
current_seq = 1044
count = 701
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 239.762482/1043, current 239.781387/1044: elapsed=18907.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 239.781387
last_received_ts = 239.780701
last_seq = 1044
current_ts = 239.800293
current_received_ts = 239.799606
current_seq = 1045
count = 702
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 239.781387/1044, current 239.800293/1045: elapsed=18908.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 239.800293
last_received_ts = 239.799606
last_seq = 1045
current_ts = 239.819199
current_received_ts = 239.818512
current_seq = 1046
count = 703
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 239.800293/1045, current 239.819199/1046: elapsed=18907.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 239.819199
last_received_ts = 239.818512
last_seq = 1046
current_ts = 239.838104
current_received_ts = 239.837418
current_seq = 1047
count = 704
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 239.819199/1046, current 239.838104/1047: elapsed=18907.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 239.838104
last_received_ts = 239.837418
last_seq = 1047
current_ts = 239.857025
current_received_ts = 239.856323
current_seq = 1048
count = 705
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 239.838104/1047, current 239.857025/1048: elapsed=18907.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 239.857025
last_received_ts = 239.856323
last_seq = 1048
current_ts = 239.875931
current_received_ts = 239.875244
current_seq = 1049
count = 706
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 239.857025/1048, current 239.875931/1049: elapsed=18911.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 239.875931
last_received_ts = 239.875244
last_seq = 1049
current_ts = 239.894836
current_received_ts = 239.894150
current_seq = 1050
count = 707
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 239.875931/1049, current 239.894836/1050: elapsed=18911.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 239.894836
last_received_ts = 239.894150
last_seq = 1050
current_ts = 239.913757
current_received_ts = 239.913071
current_seq = 1051
count = 708
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 239.894836/1050, current 239.913757/1051: elapsed=18916.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 239.913757
last_received_ts = 239.913071
last_seq = 1051
current_ts = 239.932663
current_received_ts = 239.931976
current_seq = 1052
count = 709
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 239.913757/1051, current 239.932663/1052: elapsed=18905.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 239.932663
last_received_ts = 239.931976
last_seq = 1052
current_ts = 239.951569
current_received_ts = 239.950882
current_seq = 1053
count = 710
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 239.932663/1052, current 239.951569/1053: elapsed=18911.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 239.951569
last_received_ts = 239.950882
last_seq = 1053
current_ts = 239.970490
current_received_ts = 239.969788
current_seq = 1054
count = 711
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 239.951569/1053, current 239.970490/1054: elapsed=18911.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 239.970490
last_received_ts = 239.969788
last_seq = 1054
current_ts = 239.989395
current_received_ts = 239.988708
current_seq = 1055
count = 712
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 239.970490/1054, current 239.989395/1055: elapsed=18911.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 239.989395
last_received_ts = 239.988708
last_seq = 1055
current_ts = 240.008301
current_received_ts = 240.007614
current_seq = 1056
count = 713
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 239.989395/1055, current 240.008301/1056: elapsed=18910.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 240.008301
last_received_ts = 240.007614
last_seq = 1056
current_ts = 240.027222
current_received_ts = 240.026520
current_seq = 1057
count = 714
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 240.008301/1056, current 240.027222/1057: elapsed=18912.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 240.027222
last_received_ts = 240.026520
last_seq = 1057
current_ts = 240.046127
current_received_ts = 240.045441
current_seq = 1058
count = 715
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 240.027222/1057, current 240.046127/1058: elapsed=18911.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 240.046127
last_received_ts = 240.045441
last_seq = 1058
current_ts = 240.065033
current_received_ts = 240.064346
current_seq = 1059
count = 716
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 240.046127/1058, current 240.065033/1059: elapsed=18911.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 240.065033
last_received_ts = 240.064346
last_seq = 1059
current_ts = 240.083954
current_received_ts = 240.083267
current_seq = 1060
count = 717
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 240.065033/1059, current 240.083954/1060: elapsed=18910.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 240.083954
last_received_ts = 240.083267
last_seq = 1060
current_ts = 240.102859
current_received_ts = 240.102173
current_seq = 1061
count = 718
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 240.083954/1060, current 240.102859/1061: elapsed=18911.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 240.102859
last_received_ts = 240.102173
last_seq = 1061
current_ts = 240.121765
current_received_ts = 240.121078
current_seq = 1062
count = 719
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 240.102859/1061, current 240.121765/1062: elapsed=18912.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 240.121765
last_received_ts = 240.121078
last_seq = 1062
current_ts = 240.140686
current_received_ts = 240.139984
current_seq = 1063
count = 720
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 240.121765/1062, current 240.140686/1063: elapsed=18910.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 240.140686
last_received_ts = 240.139984
last_seq = 1063
current_ts = 240.159592
current_received_ts = 240.158905
current_seq = 1064
count = 721
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 240.140686/1063, current 240.159592/1064: elapsed=18911.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 240.159592
last_received_ts = 240.158905
last_seq = 1064
current_ts = 240.178497
current_received_ts = 240.177811
current_seq = 1065
count = 722
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 240.159592/1064, current 240.178497/1065: elapsed=18910.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 240.178497
last_received_ts = 240.177811
last_seq = 1065
current_ts = 240.197418
current_received_ts = 240.196716
current_seq = 1066
count = 723
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 240.178497/1065, current 240.197418/1066: elapsed=18911.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 240.197418
last_received_ts = 240.196716
last_seq = 1066
current_ts = 240.216324
current_received_ts = 240.215637
current_seq = 1067
count = 724
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 240.197418/1066, current 240.216324/1067: elapsed=18911.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 240.216324
last_received_ts = 240.215637
last_seq = 1067
current_ts = 240.235229
current_received_ts = 240.234543
current_seq = 1068
count = 725
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 240.216324/1067, current 240.235229/1068: elapsed=18911.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 240.235229
last_received_ts = 240.234543
last_seq = 1068
current_ts = 240.254150
current_received_ts = 240.253448
current_seq = 1069
count = 726
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 240.235229/1068, current 240.254150/1069: elapsed=18910.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 240.254150
last_received_ts = 240.253448
last_seq = 1069
current_ts = 240.273056
current_received_ts = 240.272369
current_seq = 1070
count = 727
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 240.254150/1069, current 240.273056/1070: elapsed=18911.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 240.273056
last_received_ts = 240.272369
last_seq = 1070
current_ts = 240.291962
current_received_ts = 240.291275
current_seq = 1071
count = 728
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 240.273056/1070, current 240.291962/1071: elapsed=18911.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 240.291962
last_received_ts = 240.291275
last_seq = 1071
current_ts = 240.310883
current_received_ts = 240.310181
current_seq = 1072
count = 729
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 240.291962/1071, current 240.310883/1072: elapsed=18911.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 240.310883
last_received_ts = 240.310181
last_seq = 1072
current_ts = 240.329788
current_received_ts = 240.329102
current_seq = 1073
count = 730
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 240.310883/1072, current 240.329788/1073: elapsed=18911.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 240.329788
last_received_ts = 240.329102
last_seq = 1073
current_ts = 240.348694
current_received_ts = 240.348038
current_seq = 1074
count = 731
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 240.329788/1073, current 240.348694/1074: elapsed=18910.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 240.348694
last_received_ts = 240.348038
last_seq = 1074
current_ts = 240.367615
current_received_ts = 240.366928
current_seq = 1075
count = 732
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 240.348694/1074, current 240.367615/1075: elapsed=18911.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 240.367615
last_received_ts = 240.366928
last_seq = 1075
current_ts = 240.386520
current_received_ts = 240.385834
current_seq = 1076
count = 733
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 240.367615/1075, current 240.386520/1076: elapsed=18911.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 240.386520
last_received_ts = 240.385834
last_seq = 1076
current_ts = 240.405426
current_received_ts = 240.404739
current_seq = 1077
count = 734
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 240.386520/1076, current 240.405426/1077: elapsed=18912.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 240.405426
last_received_ts = 240.404739
last_seq = 1077
current_ts = 240.424347
current_received_ts = 240.423645
current_seq = 1078
count = 735
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 240.405426/1077, current 240.424347/1078: elapsed=18910.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 240.424347
last_received_ts = 240.423645
last_seq = 1078
current_ts = 240.443253
current_received_ts = 240.442566
current_seq = 1079
count = 736
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 240.424347/1078, current 240.443253/1079: elapsed=18911.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 240.443253
last_received_ts = 240.442566
last_seq = 1079
current_ts = 240.462158
current_received_ts = 240.461487
current_seq = 1080
count = 737
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 240.443253/1079, current 240.462158/1080: elapsed=18911.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 240.462158
last_received_ts = 240.461487
last_seq = 1080
current_ts = 240.481079
current_received_ts = 240.480392
current_seq = 1081
count = 738
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 240.462158/1080, current 240.481079/1081: elapsed=18911.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 240.481079
last_received_ts = 240.480392
last_seq = 1081
current_ts = 240.499985
current_received_ts = 240.499298
current_seq = 1082
count = 739
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 240.481079/1081, current 240.499985/1082: elapsed=18911.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 240.499985
last_received_ts = 240.499298
last_seq = 1082
current_ts = 240.518890
current_received_ts = 240.518204
current_seq = 1083
count = 740
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 240.499985/1082, current 240.518890/1083: elapsed=18910.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 240.518890
last_received_ts = 240.518204
last_seq = 1083
current_ts = 240.537811
current_received_ts = 240.537125
current_seq = 1084
count = 741
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 240.518890/1083, current 240.537811/1084: elapsed=18911.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 240.537811
last_received_ts = 240.537125
last_seq = 1084
current_ts = 240.556717
current_received_ts = 240.556046
current_seq = 1085
count = 742
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 240.537811/1084, current 240.556717/1085: elapsed=18911.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 240.556717
last_received_ts = 240.556046
last_seq = 1085
current_ts = 240.575623
current_received_ts = 240.574936
current_seq = 1086
count = 743
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 240.556717/1085, current 240.575623/1086: elapsed=18911.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 240.575623
last_received_ts = 240.574936
last_seq = 1086
current_ts = 240.594543
current_received_ts = 240.593857
current_seq = 1087
count = 744
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 240.575623/1086, current 240.594543/1087: elapsed=18910.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 240.594543
last_received_ts = 240.593857
last_seq = 1087
current_ts = 240.613449
current_received_ts = 240.612762
current_seq = 1088
count = 745
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 240.594543/1087, current 240.613449/1088: elapsed=18911.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 240.613449
last_received_ts = 240.612762
last_seq = 1088
current_ts = 240.632355
current_received_ts = 240.631668
current_seq = 1089
count = 746
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 240.613449/1088, current 240.632355/1089: elapsed=18911.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 240.632355
last_received_ts = 240.631668
last_seq = 1089
current_ts = 240.651276
current_received_ts = 240.650589
current_seq = 1090
count = 747
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 240.632355/1089, current 240.651276/1090: elapsed=18912.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 240.651276
last_received_ts = 240.650589
last_seq = 1090
current_ts = 240.670181
current_received_ts = 240.669495
current_seq = 1091
count = 748
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 240.651276/1090, current 240.670181/1091: elapsed=18910.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 240.670181
last_received_ts = 240.669495
last_seq = 1091
current_ts = 240.689087
current_received_ts = 240.688400
current_seq = 1092
count = 749
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 240.670181/1091, current 240.689087/1092: elapsed=18910.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 240.689087
last_received_ts = 240.688400
last_seq = 1092
current_ts = 240.708008
current_received_ts = 240.707321
current_seq = 1093
count = 750
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 240.689087/1092, current 240.708008/1093: elapsed=18912.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 240.708008
last_received_ts = 240.707321
last_seq = 1093
current_ts = 240.726913
current_received_ts = 240.726227
current_seq = 1094
count = 751
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 240.708008/1093, current 240.726913/1094: elapsed=18910.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 240.726913
last_received_ts = 240.726227
last_seq = 1094
current_ts = 240.745834
current_received_ts = 240.745148
current_seq = 1095
count = 752
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 240.726913/1094, current 240.745834/1095: elapsed=18912.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 240.745834
last_received_ts = 240.745148
last_seq = 1095
current_ts = 240.764740
current_received_ts = 240.764069
current_seq = 1096
count = 753
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 240.745834/1095, current 240.764740/1096: elapsed=18909.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 240.764740
last_received_ts = 240.764069
last_seq = 1096
current_ts = 240.783646
current_received_ts = 240.782974
current_seq = 1097
count = 754
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 240.764740/1096, current 240.783646/1097: elapsed=18911.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 240.783646
last_received_ts = 240.782974
last_seq = 1097
current_ts = 240.802567
current_received_ts = 240.801880
current_seq = 1098
count = 755
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 240.783646/1097, current 240.802567/1098: elapsed=18911.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 240.802567
last_received_ts = 240.801880
last_seq = 1098
current_ts = 240.821472
current_received_ts = 240.820786
current_seq = 1099
count = 756
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 240.802567/1098, current 240.821472/1099: elapsed=18912.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 240.821472
last_received_ts = 240.820786
last_seq = 1099
current_ts = 240.840378
current_received_ts = 240.839706
current_seq = 1100
count = 757
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 240.821472/1099, current 240.840378/1100: elapsed=18910.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 240.840378
last_received_ts = 240.839706
last_seq = 1100
current_ts = 240.859299
current_received_ts = 240.858658
current_seq = 1101
count = 758
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 240.840378/1100, current 240.859299/1101: elapsed=18911.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 240.859299
last_received_ts = 240.858658
last_seq = 1101
current_ts = 240.878204
current_received_ts = 240.877563
current_seq = 1102
count = 759
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 240.859299/1101, current 240.878204/1102: elapsed=18915.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 240.878204
last_received_ts = 240.877563
last_seq = 1102
current_ts = 240.897125
current_received_ts = 240.896439
current_seq = 1103
count = 760
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 240.878204/1102, current 240.897125/1103: elapsed=18925.0us expected=18832.3us +- 94.2us, error 0.5%
(kms_flip:2358) DEBUG: name = flip
last_ts = 240.897125
last_received_ts = 240.896439
last_seq = 1103
current_ts = 240.916046
current_received_ts = 240.915314
current_seq = 1104
count = 761
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 240.897125/1103, current 240.916046/1104: elapsed=18908.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 240.916046
last_received_ts = 240.915314
last_seq = 1104
current_ts = 240.934952
current_received_ts = 240.934235
current_seq = 1105
count = 762
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 240.916046/1104, current 240.934952/1105: elapsed=18914.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 240.934952
last_received_ts = 240.934235
last_seq = 1105
current_ts = 240.953873
current_received_ts = 240.953156
current_seq = 1106
count = 763
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 240.934952/1105, current 240.953873/1106: elapsed=18916.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 240.953873
last_received_ts = 240.953156
last_seq = 1106
current_ts = 240.972778
current_received_ts = 240.972107
current_seq = 1107
count = 764
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 240.953873/1106, current 240.972778/1107: elapsed=18910.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 240.972778
last_received_ts = 240.972107
last_seq = 1107
current_ts = 240.991699
current_received_ts = 240.991058
current_seq = 1108
count = 765
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 240.972778/1107, current 240.991699/1108: elapsed=18912.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 240.991699
last_received_ts = 240.991058
last_seq = 1108
current_ts = 241.010605
current_received_ts = 241.009918
current_seq = 1109
count = 766
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 240.991699/1108, current 241.010605/1109: elapsed=18913.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 241.010605
last_received_ts = 241.009918
last_seq = 1109
current_ts = 241.029526
current_received_ts = 241.028839
current_seq = 1110
count = 767
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 241.010605/1109, current 241.029526/1110: elapsed=18914.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 241.029526
last_received_ts = 241.028839
last_seq = 1110
current_ts = 241.048431
current_received_ts = 241.047760
current_seq = 1111
count = 768
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 241.029526/1110, current 241.048431/1111: elapsed=18915.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 241.048431
last_received_ts = 241.047760
last_seq = 1111
current_ts = 241.067352
current_received_ts = 241.066666
current_seq = 1112
count = 769
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 241.048431/1111, current 241.067352/1112: elapsed=18914.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 241.067352
last_received_ts = 241.066666
last_seq = 1112
current_ts = 241.086258
current_received_ts = 241.085587
current_seq = 1113
count = 770
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 241.067352/1112, current 241.086258/1113: elapsed=18913.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 241.086258
last_received_ts = 241.085587
last_seq = 1113
current_ts = 241.105179
current_received_ts = 241.104492
current_seq = 1114
count = 771
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 241.086258/1113, current 241.105179/1114: elapsed=18915.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 241.105179
last_received_ts = 241.104492
last_seq = 1114
current_ts = 241.124084
current_received_ts = 241.123413
current_seq = 1115
count = 772
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 241.105179/1114, current 241.124084/1115: elapsed=18914.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 241.124084
last_received_ts = 241.123413
last_seq = 1115
current_ts = 241.143005
current_received_ts = 241.142319
current_seq = 1116
count = 773
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 241.124084/1115, current 241.143005/1116: elapsed=18915.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 241.143005
last_received_ts = 241.142319
last_seq = 1116
current_ts = 241.161926
current_received_ts = 241.161240
current_seq = 1117
count = 774
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 241.143005/1116, current 241.161926/1117: elapsed=18914.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 241.161926
last_received_ts = 241.161240
last_seq = 1117
current_ts = 241.180832
current_received_ts = 241.180145
current_seq = 1118
count = 775
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 241.161926/1117, current 241.180832/1118: elapsed=18913.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 241.180832
last_received_ts = 241.180145
last_seq = 1118
current_ts = 241.199753
current_received_ts = 241.199066
current_seq = 1119
count = 776
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 241.180832/1118, current 241.199753/1119: elapsed=18918.0us expected=18832.3us +- 94.2us, error 0.5%
(kms_flip:2358) DEBUG: name = flip
last_ts = 241.199753
last_received_ts = 241.199066
last_seq = 1119
current_ts = 241.218658
current_received_ts = 241.217987
current_seq = 1120
count = 777
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 241.199753/1119, current 241.218658/1120: elapsed=18912.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 241.218658
last_received_ts = 241.217987
last_seq = 1120
current_ts = 241.237579
current_received_ts = 241.236893
current_seq = 1121
count = 778
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 241.218658/1120, current 241.237579/1121: elapsed=18914.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 241.237579
last_received_ts = 241.236893
last_seq = 1121
current_ts = 241.256485
current_received_ts = 241.255814
current_seq = 1122
count = 779
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 241.237579/1121, current 241.256485/1122: elapsed=18913.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 241.256485
last_received_ts = 241.255814
last_seq = 1122
current_ts = 241.275406
current_received_ts = 241.274719
current_seq = 1123
count = 780
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 241.256485/1122, current 241.275406/1123: elapsed=18914.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 241.275406
last_received_ts = 241.274719
last_seq = 1123
current_ts = 241.294312
current_received_ts = 241.293640
current_seq = 1124
count = 781
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 241.275406/1123, current 241.294312/1124: elapsed=18915.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 241.294312
last_received_ts = 241.293640
last_seq = 1124
current_ts = 241.313232
current_received_ts = 241.312546
current_seq = 1125
count = 782
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 241.294312/1124, current 241.313232/1125: elapsed=18914.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 241.313232
last_received_ts = 241.312546
last_seq = 1125
current_ts = 241.332153
current_received_ts = 241.331467
current_seq = 1126
count = 783
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 241.313232/1125, current 241.332153/1126: elapsed=18915.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 241.332153
last_received_ts = 241.331467
last_seq = 1126
current_ts = 241.351059
current_received_ts = 241.350372
current_seq = 1127
count = 784
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 241.332153/1126, current 241.351059/1127: elapsed=18913.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 241.351059
last_received_ts = 241.350372
last_seq = 1127
current_ts = 241.369980
current_received_ts = 241.369293
current_seq = 1128
count = 785
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 241.351059/1127, current 241.369980/1128: elapsed=18915.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 241.369980
last_received_ts = 241.369293
last_seq = 1128
current_ts = 241.388885
current_received_ts = 241.388214
current_seq = 1129
count = 786
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 241.369980/1128, current 241.388885/1129: elapsed=18914.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 241.388885
last_received_ts = 241.388214
last_seq = 1129
current_ts = 241.407806
current_received_ts = 241.407120
current_seq = 1130
count = 787
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 241.388885/1129, current 241.407806/1130: elapsed=18914.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 241.407806
last_received_ts = 241.407120
last_seq = 1130
current_ts = 241.426712
current_received_ts = 241.426041
current_seq = 1131
count = 788
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 241.407806/1130, current 241.426712/1131: elapsed=18914.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 241.426712
last_received_ts = 241.426041
last_seq = 1131
current_ts = 241.445633
current_received_ts = 241.444946
current_seq = 1132
count = 789
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 241.426712/1131, current 241.445633/1132: elapsed=18914.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 241.445633
last_received_ts = 241.444946
last_seq = 1132
current_ts = 241.464539
current_received_ts = 241.463867
current_seq = 1133
count = 790
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 241.445633/1132, current 241.464539/1133: elapsed=18914.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 241.464539
last_received_ts = 241.463867
last_seq = 1133
current_ts = 241.483459
current_received_ts = 241.482773
current_seq = 1134
count = 791
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 241.464539/1133, current 241.483459/1134: elapsed=18915.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 241.483459
last_received_ts = 241.482773
last_seq = 1134
current_ts = 241.502380
current_received_ts = 241.501694
current_seq = 1135
count = 792
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 241.483459/1134, current 241.502380/1135: elapsed=18915.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 241.502380
last_received_ts = 241.501694
last_seq = 1135
current_ts = 241.521286
current_received_ts = 241.520599
current_seq = 1136
count = 793
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 241.502380/1135, current 241.521286/1136: elapsed=18913.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: name = flip
last_ts = 241.521286
last_received_ts = 241.520599
last_seq = 1136
current_ts = 241.540207
current_received_ts = 241.539520
current_seq = 1137
count = 794
seq_step = 1
(kms_flip:2358) DEBUG: flip ts/seq: last 241.521286/1136, current 241.540207/1137: elapsed=18914.0us expected=18832.3us +- 94.2us, error 0.4%
(kms_flip:2358) DEBUG: expected 797, counted 795, encoder type 2
(kms_flip:2358) DEBUG: dropped frames, expected 797, counted 795, encoder type 2
(kms_flip:2358) CRITICAL: Test assertion failure function __run_test_on_crtc_set, file ../tests/kms_flip.c:1660:
(kms_flip:2358) CRITICAL: Failed assertion: !retried && needs_retry_after_link_reset(mon)
(kms_flip:2358) igt_core-INFO: Stack trace:
(kms_flip:2358) igt_core-INFO:   #0 ../lib/igt_core.c:2055 __igt_fail_assert()
(kms_flip:2358) igt_core-INFO:   #1 ../tests/kms_flip.c:777 run_test_on_crtc_set.constprop.0()
(kms_flip:2358) igt_core-INFO:   #2 ../tests/kms_flip.c:1831 run_test()
(kms_flip:2358) igt_core-INFO:   #3 ../tests/kms_flip.c:2064 __igt_unique____real_main1987()
(kms_flip:2358) igt_core-INFO:   #4 ../tests/kms_flip.c:1987 main()
(kms_flip:2358) igt_core-INFO:   #5 [__libc_init_first+0x8a]
(kms_flip:2358) igt_core-INFO:   #6 [__libc_start_main+0x8b]
(kms_flip:2358) igt_core-INFO:   #7 [_start+0x25]
****  END  ****
Dynamic subtest B-HDMI-A1: FAIL (18.775s)
Subtest plain-flip-fb-recreate: FAIL (34.508s)
(kms_flip:2358) igt_kms-CRITICAL: Test assertion failure function kmstest_set_connector_dpms, file ../lib/igt_kms.c:2246:
(kms_flip:2358) igt_kms-CRITICAL: Failed assertion: found_it
(kms_flip:2358) igt_kms-CRITICAL: Last errno: 9, Bad file descriptor
(kms_flip:2358) igt_kms-CRITICAL: DPMS property not found on 137