-
Notifications
You must be signed in to change notification settings - Fork 0
/
Copy pathautoinst-log.txt
5615 lines (5539 loc) · 524 KB
/
autoinst-log.txt
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
281
282
283
284
285
286
287
288
289
290
291
292
293
294
295
296
297
298
299
300
301
302
303
304
305
306
307
308
309
310
311
312
313
314
315
316
317
318
319
320
321
322
323
324
325
326
327
328
329
330
331
332
333
334
335
336
337
338
339
340
341
342
343
344
345
346
347
348
349
350
351
352
353
354
355
356
357
358
359
360
361
362
363
364
365
366
367
368
369
370
371
372
373
374
375
376
377
378
379
380
381
382
383
384
385
386
387
388
389
390
391
392
393
394
395
396
397
398
399
400
401
402
403
404
405
406
407
408
409
410
411
412
413
414
415
416
417
418
419
420
421
422
423
424
425
426
427
428
429
430
431
432
433
434
435
436
437
438
439
440
441
442
443
444
445
446
447
448
449
450
451
452
453
454
455
456
457
458
459
460
461
462
463
464
465
466
467
468
469
470
471
472
473
474
475
476
477
478
479
480
481
482
483
484
485
486
487
488
489
490
491
492
493
494
495
496
497
498
499
500
501
502
503
504
505
506
507
508
509
510
511
512
513
514
515
516
517
518
519
520
521
522
523
524
525
526
527
528
529
530
531
532
533
534
535
536
537
538
539
540
541
542
543
544
545
546
547
548
549
550
551
552
553
554
555
556
557
558
559
560
561
562
563
564
565
566
567
568
569
570
571
572
573
574
575
576
577
578
579
580
581
582
583
584
585
586
587
588
589
590
591
592
593
594
595
596
597
598
599
600
601
602
603
604
605
606
607
608
609
610
611
612
613
614
615
616
617
618
619
620
621
622
623
624
625
626
627
628
629
630
631
632
633
634
635
636
637
638
639
640
641
642
643
644
645
646
647
648
649
650
651
652
653
654
655
656
657
658
659
660
661
662
663
664
665
666
667
668
669
670
671
672
673
674
675
676
677
678
679
680
681
682
683
684
685
686
687
688
689
690
691
692
693
694
695
696
697
698
699
700
701
702
703
704
705
706
707
708
709
710
711
712
713
714
715
716
717
718
719
720
721
722
723
724
725
726
727
728
729
730
731
732
733
734
735
736
737
738
739
740
741
742
743
744
745
746
747
748
749
750
751
752
753
754
755
756
757
758
759
760
761
762
763
764
765
766
767
768
769
770
771
772
773
774
775
776
777
778
779
780
781
782
783
784
785
786
787
788
789
790
791
792
793
794
795
796
797
798
799
800
801
802
803
804
805
806
807
808
809
810
811
812
813
814
815
816
817
818
819
820
821
822
823
824
825
826
827
828
829
830
831
832
833
834
835
836
837
838
839
840
841
842
843
844
845
846
847
848
849
850
851
852
853
854
855
856
857
858
859
860
861
862
863
864
865
866
867
868
869
870
871
872
873
874
875
876
877
878
879
880
881
882
883
884
885
886
887
888
889
890
891
892
893
894
895
896
897
898
899
900
901
902
903
904
905
906
907
908
909
910
911
912
913
914
915
916
917
918
919
920
921
922
923
924
925
926
927
928
929
930
931
932
933
934
935
936
937
938
939
940
941
942
943
944
945
946
947
948
949
950
951
952
953
954
955
956
957
958
959
960
961
962
963
964
965
966
967
968
969
970
971
972
973
974
975
976
977
978
979
980
981
982
983
984
985
986
987
988
989
990
991
992
993
994
995
996
997
998
999
1000
[2021-03-21T13:03:57.0394 CET] [info] +++ setup notes +++
[2021-03-21T13:03:57.0394 CET] [info] Running on openqaworker4:15 (Linux 5.3.18-lp152.66-default #1 SMP Tue Mar 2 13:18:19 UTC 2021 (73933a3) x86_64)
[2021-03-21T13:03:57.0406 CET] [debug] Found ASSET_1, caching Tumbleweed.x86_64-1.0-libvirt-Snapshot20210320.vagrant.libvirt.box
[2021-03-21T13:03:57.0412 CET] [info] Downloading Tumbleweed.x86_64-1.0-libvirt-Snapshot20210320.vagrant.libvirt.box, request #146617 sent to Cache Service
[2021-03-21T13:04:02.0509 CET] [info] Download of Tumbleweed.x86_64-1.0-libvirt-Snapshot20210320.vagrant.libvirt.box processed:
[info] [#146617]
Cache size of "/var/lib/openqa/cache" is 46GiB, with limit 50GiB
[info] [#146617]
Downloading "Tumbleweed.x86_64-1.0-libvirt-Snapshot20210320.vagrant.libvirt.box" from "http://openqa1-opensuse/tests/1675833/asset/other/Tumbleweed.x86_64-1.0-libvirt-Snapshot20210320.vagrant.libvirt.box"
[info] [#146617]
Content of "/var/lib/openqa/cache/openqa1-opensuse/Tumbleweed.x86_64-1.0-libvirt-Snapshot20210320.vagrant.libvirt.box" has not changed, updating last use
[2021-03-21T13:04:02.0518 CET] [debug] Found ASSET_2, caching Tumbleweed.x86_64-1.0-virtualbox-Snapshot20210320.vagrant.virtualbox.box
[2021-03-21T13:04:02.0522 CET] [info] Downloading Tumbleweed.x86_64-1.0-virtualbox-Snapshot20210320.vagrant.virtualbox.box, request #146618 sent to Cache Service
[2021-03-21T13:04:12.0627 CET] [info] Download of Tumbleweed.x86_64-1.0-virtualbox-Snapshot20210320.vagrant.virtualbox.box processed:
[info] [#146618]
Cache size of "/var/lib/openqa/cache" is 46GiB, with limit 50GiB
[info] [#146618]
Downloading "Tumbleweed.x86_64-1.0-virtualbox-Snapshot20210320.vagrant.virtualbox.box" from "http://openqa1-opensuse/tests/1675833/asset/other/Tumbleweed.x86_64-1.0-virtualbox-Snapshot20210320.vagrant.virtualbox.box"
[info] [#146618]
Content of "/var/lib/openqa/cache/openqa1-opensuse/Tumbleweed.x86_64-1.0-virtualbox-Snapshot20210320.vagrant.virtualbox.box" has not changed, updating last use
[2021-03-21T13:04:12.0633 CET] [debug] Found ASSET_256, caching openSUSE-Tumbleweed-DVD-x86_64-Snapshot20210320-Media.iso.sha256
[2021-03-21T13:04:12.0636 CET] [info] Downloading openSUSE-Tumbleweed-DVD-x86_64-Snapshot20210320-Media.iso.sha256, request #146620 sent to Cache Service
[2021-03-21T13:04:22.0974 CET] [info] Download of openSUSE-Tumbleweed-DVD-x86_64-Snapshot20210320-Media.iso.sha256 processed:
[info] [#146620]
Cache size of "/var/lib/openqa/cache" is 46GiB, with limit 50GiB
[info] [#146620]
Downloading "openSUSE-Tumbleweed-DVD-x86_64-Snapshot20210320-Media.iso.sha256" from "http://openqa1-opensuse/tests/1675833/asset/other/openSUSE-Tumbleweed-DVD-x86_64-Snapshot20210320-Media.iso.sha256"
[info] [#146620]
Content of "/var/lib/openqa/cache/openqa1-opensuse/openSUSE-Tumbleweed-DVD-x86_64-Snapshot20210320-Media.iso.sha256" has not changed, updating last use
[2021-03-21T13:04:22.0980 CET] [debug] Found HDD_1, caching [email protected]
[2021-03-21T13:04:23.0040 CET] [info] Downloading [email protected], request #146622 sent to Cache Service
[2021-03-21T13:04:33.0201 CET] [info] Download of [email protected] processed:
[info] [#146622]
Cache size of "/var/lib/openqa/cache" is 48GiB, with limit 50GiB
[info] [#146622]
Downloading "[email protected]" from "http://openqa1-opensuse/tests/1675833/asset/hdd/[email protected]"
[info] [#146622]
Content of "/var/lib/openqa/cache/openqa1-opensuse/[email protected]" has not changed, updating last use
[2021-03-21T13:04:33.0210 CET] [debug] Found ISO, caching openSUSE-Tumbleweed-DVD-x86_64-Snapshot20210320-Media.iso
[2021-03-21T13:04:33.0216 CET] [info] Downloading openSUSE-Tumbleweed-DVD-x86_64-Snapshot20210320-Media.iso, request #146624 sent to Cache Service
[2021-03-21T13:04:38.0278 CET] [info] Download of openSUSE-Tumbleweed-DVD-x86_64-Snapshot20210320-Media.iso processed:
[info] [#146624]
Cache size of "/var/lib/openqa/cache" is 48GiB, with limit 50GiB
[info] [#146624]
Downloading "openSUSE-Tumbleweed-DVD-x86_64-Snapshot20210320-Media.iso" from "http://openqa1-opensuse/tests/1675833/asset/iso/openSUSE-Tumbleweed-DVD-x86_64-Snapshot20210320-Media.iso"
[info] [#146624]
Content of "/var/lib/openqa/cache/openqa1-opensuse/openSUSE-Tumbleweed-DVD-x86_64-Snapshot20210320-Media.iso" has not changed, updating last use
[2021-03-21T13:04:38.0282 CET] [info] Rsync from 'rsync://openqa1-opensuse/tests' to '/var/lib/openqa/cache/openqa1-opensuse', request #146626 sent to Cache Service
[2021-03-21T13:04:43.0346 CET] [info] Output of rsync:
[info] [#146626] Calling: rsync -avHP rsync://openqa1-opensuse/tests/ --delete /var/lib/openqa/cache/openqa1-opensuse/tests/
receiving incremental file list
sent 1,892 bytes received 1,382,164 bytes 2,768,112.00 bytes/sec
total size is 5,191,767,628 speedup is 3,751.13
[2021-03-21T13:04:43.0346 CET] [info] Finished to rsync tests
[2021-03-21T13:04:43.0352 CET] [debug] +++ worker notes +++
[37m[2021-03-21T13:04:43.804 CET] [debug] Current version is 4.6.1615799823.a1b2e4ba [interface v23]
[0m[37m[2021-03-21T13:04:43.813 CET] [debug] git hash in /var/lib/openqa/cache/openqa1-opensuse/tests/opensuse: 33d82b07560850a2c142212ff5c1cb65a855d358
[0m[37m[2021-03-21T13:04:43.999 CET] [debug] usingenv DESKTOP=gnome
[0m[37m[2021-03-21T13:04:43.999 CET] [debug] usingenv DISTRI=opensuse
[0m[37m[2021-03-21T13:04:43.999 CET] [debug] usingenv NOAUTOLOGIN=0
[0m[37m[2021-03-21T13:04:43.999 CET] [debug] usingenv QEMUCPU=qemu64
[0m[37m[2021-03-21T13:04:43.999 CET] [debug] usingenv INSTLANG=en_US
[0m[37m[2021-03-21T13:04:43.999 CET] [debug] usingenv DVD=1
[0m[37m[2021-03-21T13:04:43.999 CET] [debug] usingenv GNOME=1
[0m[37m[2021-03-21T13:04:43.999 CET] [debug] usingenv ISO=/var/lib/openqa/pool/15/openSUSE-Tumbleweed-DVD-x86_64-Snapshot20210320-Media.iso
[0m[37m[2021-03-21T13:04:43.999 CET] [debug] usingenv ISO_MAXSIZE=4700372992
[0m[37m[2021-03-21T13:04:44.001 CET] [debug] scheduling boot_to_desktop tests/boot/boot_to_desktop.pm
[0m[37m[2021-03-21T13:04:44.002 CET] [debug] scheduling window_system tests/x11/window_system.pm
[0m[37m[2021-03-21T13:04:44.030 CET] [debug] scheduling nautilus_cut_file tests/x11/gnomecase/nautilus_cut_file.pm
[0m[37m[2021-03-21T13:04:44.031 CET] [debug] scheduling nautilus_permission tests/x11/gnomecase/nautilus_permission.pm
[0m[37m[2021-03-21T13:04:44.032 CET] [debug] scheduling nautilus_open_ftp tests/x11/gnomecase/nautilus_open_ftp.pm
[0m[37m[2021-03-21T13:04:44.034 CET] [debug] scheduling application_starts_on_login tests/x11/gnomecase/application_starts_on_login.pm
[0m[37m[2021-03-21T13:04:44.035 CET] [debug] scheduling login_test tests/x11/gnomecase/login_test.pm
[0m[37m[2021-03-21T13:04:44.037 CET] [debug] scheduling gnome_default_applications tests/x11/gnomecase/gnome_default_applications.pm
[0m[37m[2021-03-21T13:04:44.038 CET] [debug] scheduling gnome_window_switcher tests/x11/gnomecase/gnome_window_switcher.pm
[0m[37m[2021-03-21T13:04:44.040 CET] [debug] scheduling change_password tests/x11/gnomecase/change_password.pm
[0m[2021-03-21T13:04:44.048 CET] [info] cmdsrv: daemon reachable under http://*:20153/hXr5hruAVvVTqn4E/
[2021-03-21T13:04:44.050 CET] [info] Listening at "http://[::]:20153"
Web application available at http://[::]:20153
[37m[2021-03-21T13:04:44.052 CET] [debug] git hash in /var/lib/openqa/cache/openqa1-opensuse/tests/opensuse/products/opensuse/needles: aca406acfe59729d1ba905fa3e1c7371c4bff799
[0m[37m[2021-03-21T13:04:44.052 CET] [debug] init needles from /var/lib/openqa/cache/openqa1-opensuse/tests/opensuse/products/opensuse/needles
[0m[37m[2021-03-21T13:04:44.740 CET] [debug] inst-console-20200224 contains inst-console twice
[0m[37m[2021-03-21T13:04:45.272 CET] [debug] loaded 8773 needles
[0m[37m[2021-03-21T13:04:45.430 CET] [debug] Blocking SIGTERM
[0m[37m[2021-03-21T13:04:45.540 CET] [debug] Unblocking SIGTERM
[0m[37m32524: channel_out 15, channel_in 14
[2021-03-21T13:04:45.627 CET] [debug] Blocking SIGTERM
[0m[37m[2021-03-21T13:04:45.760 CET] [debug] Unblocking SIGTERM
[0m32612: cmdpipe 13, rsppipe 16
[37m[2021-03-21T13:04:45.763 CET] [debug] started mgmt loop with pid 32612
[0m[37m[2021-03-21T13:04:45.832 CET] [debug] qemu version detected: 4.2.1
[0m[37m[2021-03-21T13:04:45.834 CET] [debug] running /usr/bin/chattr -f +C /var/lib/openqa/pool/15/raid
[0m[37m[2021-03-21T13:04:45.862 CET] [debug] running /usr/bin/qemu-img info --output=json /var/lib/openqa/pool/15/[email protected]
[0m[37m[2021-03-21T13:04:45.911 CET] [debug] running /usr/bin/qemu-img info --output=json /var/lib/openqa/pool/15/openSUSE-Tumbleweed-DVD-x86_64-Snapshot20210320-Media.iso
[0m[37m[2021-03-21T13:04:45.928 CET] [debug] running /usr/bin/qemu-img create -f qcow2 -b /var/lib/openqa/pool/15/[email protected] /var/lib/openqa/pool/15/raid/hd0-overlay0 42949672960
[0m[37m[2021-03-21T13:04:45.943 CET] [debug] Formatting '/var/lib/openqa/pool/15/raid/hd0-overlay0', fmt=qcow2 size=42949672960 backing_file=/var/lib/openqa/pool/15/[email protected] cluster_size=65536 lazy_refcounts=off refcount_bits=16
[0m[37m[2021-03-21T13:04:45.943 CET] [debug] running /usr/bin/qemu-img create -f qcow2 -b /var/lib/openqa/pool/15/openSUSE-Tumbleweed-DVD-x86_64-Snapshot20210320-Media.iso /var/lib/openqa/pool/15/raid/cd0-overlay0 4665114624
[0m[37m[2021-03-21T13:04:45.957 CET] [debug] Formatting '/var/lib/openqa/pool/15/raid/cd0-overlay0', fmt=qcow2 size=4665114624 backing_file=/var/lib/openqa/pool/15/openSUSE-Tumbleweed-DVD-x86_64-Snapshot20210320-Media.iso cluster_size=65536 lazy_refcounts=off refcount_bits=16
[0m[37m[2021-03-21T13:04:45.958 CET] [debug] starting: /usr/bin/qemu-system-x86_64 -only-migratable -chardev ringbuf,id=serial0,logfile=serial0,logappend=on -serial chardev:serial0 -audiodev none,id=snd0 -device intel-hda -device hda-output,audiodev=snd0 -global isa-fdc.driveA= -m 1536 -cpu qemu64 -netdev user,id=qanet0 -device virtio-net,netdev=qanet0,mac=52:54:00:12:34:56 -boot order=c -device usb-ehci -device usb-tablet -smp 1 -enable-kvm -no-shutdown -vnc :105,share=force-shared -device virtio-serial -chardev pipe,id=virtio_console,path=virtio_console,logfile=virtio_console.log,logappend=on -device virtconsole,chardev=virtio_console,name=org.openqa.console.virtio_console -chardev socket,path=qmp_socket,server,nowait,id=qmp_socket,logfile=qmp_socket.log,logappend=on -qmp chardev:qmp_socket -S -device virtio-scsi-pci,id=scsi0 -blockdev driver=file,node-name=hd0-overlay0-file,filename=/var/lib/openqa/pool/15/raid/hd0-overlay0,cache.no-flush=on -blockdev driver=qcow2,node-name=hd0-overlay0,file=hd0-overlay0-file,cache.no-flush=on -device virtio-blk,id=hd0-device,drive=hd0-overlay0,bootindex=0,serial=hd0 -blockdev driver=file,node-name=cd0-overlay0-file,filename=/var/lib/openqa/pool/15/raid/cd0-overlay0,cache.no-flush=on -blockdev driver=qcow2,node-name=cd0-overlay0,file=cd0-overlay0-file,cache.no-flush=on -device scsi-cd,id=cd0-device,drive=cd0-overlay0,serial=cd0
[0m[37m[2021-03-21T13:04:45.963 CET] [debug] Waiting for 0 attempts
[0m[37m[2021-03-21T13:04:46.964 CET] [debug] Waiting for 1 attempts
[0m[37m[2021-03-21T13:04:47.964 CET] [debug] Finished after 2 attempts
[0m/usr/lib/os-autoinst/consoles/vnc_base.pm:62:{
"hostname" => "localhost",
"port" => 6005,
"connect_timeout" => 3
}
[37m[2021-03-21T13:04:47.987 CET] [debug] pointer type 0 0 640 480 -257
[0m[37m[2021-03-21T13:04:47.988 CET] [debug] led state 0 1 1 -261
[0mStart CPU
[37m[2021-03-21T13:04:48.047 CET] [debug] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"48820","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"6005","websocket":false}},"event":"VNC_CONNECTED","timestamp":{"microseconds":985748,"seconds":1616328287}}
[0m[37m[2021-03-21T13:04:48.048 CET] [debug] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"48820","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"6005","websocket":false}},"event":"VNC_INITIALIZED","timestamp":{"microseconds":986801,"seconds":1616328287}}
[0m[37m[2021-03-21T13:04:48.048 CET] [debug] EVENT {"event":"RESUME","timestamp":{"microseconds":47788,"seconds":1616328288}}
[0mGOT GO
[37m[2021-03-21T13:04:48.057 CET] [debug] QEMU: QEMU emulator version 4.2.1 (openSUSE Leap 15.2)
[0m[37m[2021-03-21T13:04:48.057 CET] [debug] QEMU: Copyright (c) 2003-2019 Fabrice Bellard and the QEMU Project developers
[0m[37m[2021-03-21T13:04:48.060 CET] [debug] Snapshots are supported
[0m[1;34m[2021-03-21T13:04:48.062 CET] [debug] ||| starting boot_to_desktop tests/boot/boot_to_desktop.pm
[0m[2021-03-21T13:04:48.065 CET] [debug] tests/boot/boot_to_desktop.pm:54 called opensusebasetest::wait_boot -> lib/opensusebasetest.pm:1113 called opensusebasetest::handle_grub -> lib/opensusebasetest.pm:902 called opensusebasetest::wait_grub -> lib/opensusebasetest.pm:657 called testapi::assert_screen
[2021-03-21T13:04:48.065 CET] [debug] <<< testapi::assert_screen(mustmatch=[
"grub2"
], timeout=80)
[37m[2021-03-21T13:04:50.133 CET] [debug] WARNING: check_asserted_screen took 1.08 seconds for 52 candidate needles - make your needles more specific
[0m[37m[2021-03-21T13:04:50.133 CET] [debug] no match: 79.0s, best candidate: bootmenu-SLES15-2-generic-20181026 (0.00)
[0m[32m[2021-03-21T13:04:51.023 CET] [debug] >>> testapi::_handle_found_needle: found grub2-TW-virtio-20190303, similarity 1.00 @ 11/147
[0m[2021-03-21T13:04:51.025 CET] [debug] tests/boot/boot_to_desktop.pm:54 called opensusebasetest::wait_boot -> lib/opensusebasetest.pm:1113 called opensusebasetest::handle_grub -> lib/opensusebasetest.pm:915 called opensusebasetest::grub_select -> lib/opensusebasetest.pm:879 called testapi::send_key
[2021-03-21T13:04:51.025 CET] [debug] <<< testapi::send_key(key="ret", wait_screen_change=0, do_wait=0)
[2021-03-21T13:04:51.297 CET] [debug] tests/boot/boot_to_desktop.pm:54 called opensusebasetest::wait_boot -> lib/opensusebasetest.pm:1129 called opensusebasetest::wait_boot_past_bootloader -> lib/opensusebasetest.pm:1042 called testapi::check_screen
[2021-03-21T13:04:51.298 CET] [debug] <<< testapi::check_screen(mustmatch=[
"generic-desktop",
"emergency-shell",
"emergency-mode",
"opensuse-welcome"
], timeout=30)
[37m[2021-03-21T13:04:54.845 CET] [debug] WARNING: check_asserted_screen took 3.54 seconds for 50 candidate needles - make your needles more specific
[0m[37m[2021-03-21T13:04:54.845 CET] [debug] no match: 29.9s, best candidate: generic-desktop-boo1170586_welcome_in_taskbar_but_no_window-20200503 (0.00)
[0m[37m[2021-03-21T13:04:54.846 CET] [debug] pointer type 1 0 800 600 -257
[0m[37m[2021-03-21T13:04:56.848 CET] [debug] WARNING: check_asserted_screen took 1.99 seconds for 50 candidate needles - make your needles more specific
[0m[37m[2021-03-21T13:04:56.849 CET] [debug] no match: 26.4s, best candidate: rescue-mode-emergency-shell-20180829 (0.18)
[0m[37m[2021-03-21T13:04:59.558 CET] [debug] WARNING: check_asserted_screen took 2.69 seconds for 50 candidate needles - make your needles more specific
[0m[37m[2021-03-21T13:04:59.558 CET] [debug] no match: 24.4s, best candidate: rescue-mode-emergency-shell-20180829 (0.18)
[0m[37m[2021-03-21T13:05:01.456 CET] [debug] WARNING: check_asserted_screen took 1.88 seconds for 50 candidate needles - make your needles more specific
[0m[37m[2021-03-21T13:05:01.456 CET] [debug] no match: 21.7s, best candidate: rescue-mode-emergency-shell-20180829 (0.18)
[0m[37m[2021-03-21T13:05:03.311 CET] [debug] WARNING: check_asserted_screen took 1.84 seconds for 50 candidate needles - make your needles more specific
[0m[37m[2021-03-21T13:05:03.311 CET] [debug] no match: 19.8s, best candidate: rescue-mode-emergency-shell-20180829 (0.18)
[0m[37m[2021-03-21T13:05:05.293 CET] [debug] WARNING: check_asserted_screen took 1.97 seconds for 50 candidate needles - make your needles more specific
[0m[37m[2021-03-21T13:05:05.293 CET] [debug] no match: 17.9s, best candidate: rescue-mode-emergency-shell-20180829 (0.18)
[0m[37m[2021-03-21T13:05:08.942 CET] [debug] WARNING: check_asserted_screen took 3.64 seconds for 50 candidate needles - make your needles more specific
[0m[37m[2021-03-21T13:05:08.942 CET] [debug] no match: 15.9s, best candidate: rescue-mode-emergency-shell-20180829 (0.18)
[0m[37m[2021-03-21T13:05:10.810 CET] [debug] WARNING: check_asserted_screen took 1.85 seconds for 50 candidate needles - make your needles more specific
[0m[37m[2021-03-21T13:05:10.810 CET] [debug] no match: 12.3s, best candidate: rescue-mode-emergency-shell-20180829 (0.18)
[0m[37m[2021-03-21T13:05:14.020 CET] [debug] WARNING: check_asserted_screen took 3.20 seconds for 50 candidate needles - make your needles more specific
[0m[37m[2021-03-21T13:05:14.020 CET] [debug] no match: 10.4s, best candidate: rescue-mode-emergency-shell-20180829 (0.18)
[0m[37m[2021-03-21T13:05:14.032 CET] [debug] no change: 7.2s
[0m[37m[2021-03-21T13:05:14.273 CET] [debug] considering VNC stalled, no update for 5.33 seconds
[0m[37m[2021-03-21T13:05:14.523 CET] [debug] pointer type 1 0 1024 768 -257
[0m[37m[2021-03-21T13:05:14.523 CET] [debug] led state 0 1 1 -261
[0m[37m[2021-03-21T13:05:15.024 CET] [debug] no change: 6.2s
[0m[37m[2021-03-21T13:05:16.026 CET] [debug] no change: 5.2s
[0m[37m[2021-03-21T13:05:19.404 CET] [debug] WARNING: check_asserted_screen took 2.38 seconds for 50 candidate needles - make your needles more specific
[0m[37m[2021-03-21T13:05:19.405 CET] [debug] no match: 4.2s, best candidate: consoletest_finish-gnome-leap15.0-20180416 (0.91)
[0m[32m[2021-03-21T13:05:21.932 CET] [debug] >>> testapi::_handle_found_needle: found consoletest_finish-gnome-TW-20190522, similarity 1.00 @ 0/1
[0m[37m[2021-03-21T13:05:21.957 CET] [debug] ||| finished boot_to_desktop boot at 2021-03-21 12:05:21 (33 s)
[0m[37m[2021-03-21T13:05:21.958 CET] [debug] Creating a VM snapshot lastgood
[0m[37m[2021-03-21T13:05:21.959 CET] [debug] EVENT {"data":{"path":"\/machine\/peripheral-anon\/device[2]\/virtio-backend"},"event":"NIC_RX_FILTER_CHANGED","timestamp":{"microseconds":869976,"seconds":1616328303}}
[0m[37m[2021-03-21T13:05:21.959 CET] [debug] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"48820","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"6005","websocket":false}},"event":"VNC_DISCONNECTED","timestamp":{"microseconds":273973,"seconds":1616328314}}
[0m[37m[2021-03-21T13:05:21.959 CET] [debug] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"49410","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"6005","websocket":false}},"event":"VNC_CONNECTED","timestamp":{"microseconds":275029,"seconds":1616328314}}
[0m[37m[2021-03-21T13:05:21.960 CET] [debug] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"49410","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"6005","websocket":false}},"event":"VNC_INITIALIZED","timestamp":{"microseconds":280711,"seconds":1616328314}}
[0m[37m[2021-03-21T13:05:21.960 CET] [debug] EVENT {"data":{"offset":0},"event":"RTC_CHANGE","timestamp":{"microseconds":211550,"seconds":1616328319}}
[0m[37m[2021-03-21T13:05:21.960 CET] [debug] Saving snapshot (Current VM state is running).
[0m[37m[2021-03-21T13:05:21.978 CET] [debug] EVENT {"event":"STOP","timestamp":{"microseconds":978188,"seconds":1616328321}}
[0m[37m[2021-03-21T13:05:21.984 CET] [debug] blockdev-snapshot-sync({'arguments' => {'format' => 'qcow2','node-name' => 'hd0-overlay0','snapshot-file' => '/var/lib/openqa/pool/15/raid/hd0-overlay1','snapshot-node-name' => 'hd0-overlay1'},'execute' => 'blockdev-snapshot-sync'}) -> {'return' => {}}
[0m[37m[2021-03-21T13:05:21.989 CET] [debug] blockdev-snapshot-sync({'arguments' => {'format' => 'qcow2','node-name' => 'cd0-overlay0','snapshot-file' => '/var/lib/openqa/pool/15/raid/cd0-overlay1','snapshot-node-name' => 'cd0-overlay1'},'execute' => 'blockdev-snapshot-sync'}) -> {'return' => {}}
[0m[37m[2021-03-21T13:05:21.992 CET] [debug] EVENT {"data":{"status":"setup"},"event":"MIGRATION","timestamp":{"microseconds":992716,"seconds":1616328321}}
[0m[37m[2021-03-21T13:05:22.493 CET] [debug] EVENT {"data":{"pass":1},"event":"MIGRATION_PASS","timestamp":{"microseconds":3140,"seconds":1616328322}}
[0m[37m[2021-03-21T13:05:22.493 CET] [debug] EVENT {"data":{"status":"active"},"event":"MIGRATION","timestamp":{"microseconds":3255,"seconds":1616328322}}
[0m[37m[2021-03-21T13:05:22.493 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:22.493 CET] [debug] Migrating remaining bytes: 1606377472
[0m[37m[2021-03-21T13:05:22.994 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:22.994 CET] [debug] Migrating remaining bytes: 1595101184
[0m[37m[2021-03-21T13:05:23.496 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:23.496 CET] [debug] Migrating remaining bytes: 1578995712
[0m[37m[2021-03-21T13:05:23.996 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:23.997 CET] [debug] Migrating remaining bytes: 1563635712
[0m[37m[2021-03-21T13:05:24.497 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:24.497 CET] [debug] Migrating remaining bytes: 1549328384
[0m[37m[2021-03-21T13:05:24.998 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:24.999 CET] [debug] Migrating remaining bytes: 1538195456
[0m[37m[2021-03-21T13:05:25.500 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:25.500 CET] [debug] Migrating remaining bytes: 1523912704
[0m[37m[2021-03-21T13:05:26.001 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:26.001 CET] [debug] Migrating remaining bytes: 1513492480
[0m[37m[2021-03-21T13:05:26.502 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:26.502 CET] [debug] Migrating remaining bytes: 1505939456
[0m[37m[2021-03-21T13:05:27.003 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:27.004 CET] [debug] Migrating remaining bytes: 1496870912
[0m[37m[2021-03-21T13:05:27.505 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:27.505 CET] [debug] Migrating remaining bytes: 1483517952
[0m[37m[2021-03-21T13:05:28.005 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:28.006 CET] [debug] Migrating remaining bytes: 1469616128
[0m[37m[2021-03-21T13:05:28.507 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:28.507 CET] [debug] Migrating remaining bytes: 1458479104
[0m[37m[2021-03-21T13:05:29.008 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:29.008 CET] [debug] Migrating remaining bytes: 1444769792
[0m[37m[2021-03-21T13:05:29.509 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:29.509 CET] [debug] Migrating remaining bytes: 1431785472
[0m[37m[2021-03-21T13:05:30.010 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:30.010 CET] [debug] Migrating remaining bytes: 1420685312
[0m[37m[2021-03-21T13:05:30.511 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:30.511 CET] [debug] Migrating remaining bytes: 1410019328
[0m[37m[2021-03-21T13:05:31.012 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:31.013 CET] [debug] Migrating remaining bytes: 1398374400
[0m[37m[2021-03-21T13:05:31.514 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:31.514 CET] [debug] Migrating remaining bytes: 1386381312
[0m[37m[2021-03-21T13:05:32.015 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:32.015 CET] [debug] Migrating remaining bytes: 1374842880
[0m[37m[2021-03-21T13:05:32.516 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:32.516 CET] [debug] Migrating remaining bytes: 1365356544
[0m[37m[2021-03-21T13:05:33.017 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:33.017 CET] [debug] Migrating remaining bytes: 1353166848
[0m[37m[2021-03-21T13:05:33.518 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:33.518 CET] [debug] Migrating remaining bytes: 1341206528
[0m[37m[2021-03-21T13:05:34.019 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:34.019 CET] [debug] Migrating remaining bytes: 1330307072
[0m[37m[2021-03-21T13:05:34.520 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:34.520 CET] [debug] Migrating remaining bytes: 1318866944
[0m[37m[2021-03-21T13:05:35.021 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:35.021 CET] [debug] Migrating remaining bytes: 1306316800
[0m[37m[2021-03-21T13:05:35.522 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:35.522 CET] [debug] Migrating remaining bytes: 1293144064
[0m[37m[2021-03-21T13:05:36.023 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:36.023 CET] [debug] Migrating remaining bytes: 1277198336
[0m[37m[2021-03-21T13:05:36.524 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:36.525 CET] [debug] Migrating remaining bytes: 1257738240
[0m[37m[2021-03-21T13:05:37.026 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:37.026 CET] [debug] Migrating remaining bytes: 1247440896
[0m[37m[2021-03-21T13:05:37.527 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:37.527 CET] [debug] Migrating remaining bytes: 1235525632
[0m[37m[2021-03-21T13:05:38.028 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:38.028 CET] [debug] Migrating remaining bytes: 1224093696
[0m[37m[2021-03-21T13:05:38.529 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:38.529 CET] [debug] Migrating remaining bytes: 1215520768
[0m[37m[2021-03-21T13:05:39.030 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:39.030 CET] [debug] Migrating remaining bytes: 1202266112
[0m[37m[2021-03-21T13:05:39.531 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:39.531 CET] [debug] Migrating remaining bytes: 1190645760
[0m[37m[2021-03-21T13:05:40.032 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:40.032 CET] [debug] Migrating remaining bytes: 1180893184
[0m[37m[2021-03-21T13:05:40.533 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:40.534 CET] [debug] Migrating remaining bytes: 1170432000
[0m[37m[2021-03-21T13:05:41.037 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:41.037 CET] [debug] Migrating remaining bytes: 1161494528
[0m[37m[2021-03-21T13:05:41.537 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:41.537 CET] [debug] Migrating remaining bytes: 1152012288
[0m[37m[2021-03-21T13:05:42.038 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:42.038 CET] [debug] Migrating remaining bytes: 1138126848
[0m[37m[2021-03-21T13:05:42.539 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:42.539 CET] [debug] Migrating remaining bytes: 1123950592
[0m[37m[2021-03-21T13:05:43.040 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:43.040 CET] [debug] Migrating remaining bytes: 1110712320
[0m[37m[2021-03-21T13:05:43.541 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:43.541 CET] [debug] Migrating remaining bytes: 1100128256
[0m[37m[2021-03-21T13:05:44.043 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:44.043 CET] [debug] Migrating remaining bytes: 1083613184
[0m[37m[2021-03-21T13:05:44.544 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:44.544 CET] [debug] Migrating remaining bytes: 1073799168
[0m[37m[2021-03-21T13:05:45.045 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:45.045 CET] [debug] Migrating remaining bytes: 1062387712
[0m[37m[2021-03-21T13:05:45.546 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:45.546 CET] [debug] Migrating remaining bytes: 1046798336
[0m[37m[2021-03-21T13:05:46.047 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:46.047 CET] [debug] Migrating remaining bytes: 1034661888
[0m[37m[2021-03-21T13:05:46.548 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:46.548 CET] [debug] Migrating remaining bytes: 1025449984
[0m[37m[2021-03-21T13:05:47.049 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:47.049 CET] [debug] Migrating remaining bytes: 1012203520
[0m[37m[2021-03-21T13:05:47.550 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:47.550 CET] [debug] Migrating remaining bytes: 1001156608
[0m[37m[2021-03-21T13:05:48.051 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:48.051 CET] [debug] Migrating remaining bytes: 988647424
[0m[37m[2021-03-21T13:05:48.552 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:48.552 CET] [debug] Migrating remaining bytes: 976728064
[0m[37m[2021-03-21T13:05:49.053 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:49.054 CET] [debug] Migrating remaining bytes: 964755456
[0m[37m[2021-03-21T13:05:49.554 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:49.554 CET] [debug] Migrating remaining bytes: 954081280
[0m[37m[2021-03-21T13:05:50.055 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:50.056 CET] [debug] Migrating remaining bytes: 939982848
[0m[37m[2021-03-21T13:05:50.556 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:50.557 CET] [debug] Migrating remaining bytes: 929361920
[0m[37m[2021-03-21T13:05:51.057 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:51.058 CET] [debug] Migrating remaining bytes: 917397504
[0m[37m[2021-03-21T13:05:51.558 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:51.558 CET] [debug] Migrating remaining bytes: 904978432
[0m[37m[2021-03-21T13:05:52.059 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:52.059 CET] [debug] Migrating remaining bytes: 891736064
[0m[37m[2021-03-21T13:05:52.560 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:52.560 CET] [debug] Migrating remaining bytes: 873705472
[0m[37m[2021-03-21T13:05:53.061 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:53.061 CET] [debug] Migrating remaining bytes: 857673728
[0m[37m[2021-03-21T13:05:53.562 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:53.562 CET] [debug] Migrating remaining bytes: 842309632
[0m[37m[2021-03-21T13:05:54.063 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:54.063 CET] [debug] Migrating remaining bytes: 827904000
[0m[37m[2021-03-21T13:05:54.564 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:54.564 CET] [debug] Migrating remaining bytes: 810561536
[0m[37m[2021-03-21T13:05:55.065 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:55.066 CET] [debug] Migrating remaining bytes: 785641472
[0m[37m[2021-03-21T13:05:55.566 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:55.567 CET] [debug] Migrating remaining bytes: 773849088
[0m[37m[2021-03-21T13:05:56.067 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:56.067 CET] [debug] Migrating remaining bytes: 762298368
[0m[37m[2021-03-21T13:05:56.568 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:56.568 CET] [debug] Migrating remaining bytes: 748154880
[0m[37m[2021-03-21T13:05:57.069 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:57.069 CET] [debug] Migrating remaining bytes: 734126080
[0m[37m[2021-03-21T13:05:57.570 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:57.570 CET] [debug] Migrating remaining bytes: 713256960
[0m[37m[2021-03-21T13:05:58.071 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:58.071 CET] [debug] Migrating remaining bytes: 698028032
[0m[37m[2021-03-21T13:05:58.572 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:58.572 CET] [debug] Migrating remaining bytes: 683118592
[0m[37m[2021-03-21T13:05:59.073 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:59.073 CET] [debug] Migrating remaining bytes: 668725248
[0m[37m[2021-03-21T13:05:59.574 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:05:59.574 CET] [debug] Migrating remaining bytes: 653217792
[0m[37m[2021-03-21T13:06:00.074 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:06:00.075 CET] [debug] Migrating remaining bytes: 636657664
[0m[37m[2021-03-21T13:06:00.575 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:06:00.576 CET] [debug] Migrating remaining bytes: 623341568
[0m[37m[2021-03-21T13:06:01.076 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:06:01.077 CET] [debug] Migrating remaining bytes: 611340288
[0m[37m[2021-03-21T13:06:01.577 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:06:01.578 CET] [debug] Migrating remaining bytes: 589766656
[0m[37m[2021-03-21T13:06:02.079 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:06:02.079 CET] [debug] Migrating remaining bytes: 570548224
[0m[37m[2021-03-21T13:06:02.579 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:06:02.580 CET] [debug] Migrating remaining bytes: 551059456
[0m[37m[2021-03-21T13:06:03.080 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:06:03.080 CET] [debug] Migrating remaining bytes: 532156416
[0m[37m[2021-03-21T13:06:03.581 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:06:03.581 CET] [debug] Migrating remaining bytes: 516976640
[0m[37m[2021-03-21T13:06:04.082 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:06:04.082 CET] [debug] Migrating remaining bytes: 500092928
[0m[37m[2021-03-21T13:06:04.583 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:06:04.583 CET] [debug] Migrating remaining bytes: 483831808
[0m[37m[2021-03-21T13:06:05.084 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:06:05.084 CET] [debug] Migrating remaining bytes: 466493440
[0m[37m[2021-03-21T13:06:05.585 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:06:05.585 CET] [debug] Migrating remaining bytes: 454508544
[0m[37m[2021-03-21T13:06:06.086 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:06:06.086 CET] [debug] Migrating remaining bytes: 320700416
[0m[37m[2021-03-21T13:06:06.587 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:06:06.587 CET] [debug] Migrating remaining bytes: 174084096
[0m[37m[2021-03-21T13:06:07.088 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:06:07.088 CET] [debug] Migrating remaining bytes: 157839360
[0m[37m[2021-03-21T13:06:07.589 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:06:07.589 CET] [debug] Migrating remaining bytes: 141549568
[0m[37m[2021-03-21T13:06:08.090 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:06:08.090 CET] [debug] Migrating remaining bytes: 42057728
[0m[37m[2021-03-21T13:06:08.591 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:06:08.591 CET] [debug] Migrating remaining bytes: 22241280
[0m[37m[2021-03-21T13:06:09.091 CET] [debug] EVENT {"data":{"pass":2},"event":"MIGRATION_PASS","timestamp":{"microseconds":885627,"seconds":1616328368}}
[0m[37m[2021-03-21T13:06:09.092 CET] [debug] EVENT {"data":{"pass":3},"event":"MIGRATION_PASS","timestamp":{"microseconds":938519,"seconds":1616328368}}
[0m[37m[2021-03-21T13:06:09.092 CET] [debug] EVENT {"data":{"pass":4},"event":"MIGRATION_PASS","timestamp":{"microseconds":938866,"seconds":1616328368}}
[0m[37m[2021-03-21T13:06:09.092 CET] [debug] EVENT {"data":{"status":"completed"},"event":"MIGRATION","timestamp":{"microseconds":964265,"seconds":1616328368}}
[0m[37m[2021-03-21T13:06:09.092 CET] [debug] Migrating total bytes: 1628250112
[0m[37m[2021-03-21T13:06:09.092 CET] [debug] Migrating remaining bytes: 0
[0m[37m[2021-03-21T13:06:09.092 CET] [debug] Snapshot complete
[0m[37m[2021-03-21T13:06:09.199 CET] [debug] EVENT {"event":"RESUME","timestamp":{"microseconds":199591,"seconds":1616328369}}
[0m[1;34m[2021-03-21T13:06:09.208 CET] [debug] ||| starting window_system tests/x11/window_system.pm
[0m[37m[2021-03-21T13:06:09.214 CET] [debug] QEMU: Formatting '/var/lib/openqa/pool/15/raid/hd0-overlay1', fmt=qcow2 size=42949672960 backing_file=/var/lib/openqa/pool/15/raid/hd0-overlay0 backing_fmt=qcow2 cluster_size=65536 lazy_refcounts=off refcount_bits=16
[0m[37m[2021-03-21T13:06:09.214 CET] [debug] QEMU: Formatting '/var/lib/openqa/pool/15/raid/cd0-overlay1', fmt=qcow2 size=4665114624 backing_file=/var/lib/openqa/pool/15/raid/cd0-overlay0 backing_fmt=qcow2 cluster_size=65536 lazy_refcounts=off refcount_bits=16
[0m[2021-03-21T13:06:09.215 CET] [debug] tests/x11/window_system.pm:23 called opensusebasetest::select_serial_terminal -> lib/opensusebasetest.pm:1251 called testapi::select_console
[2021-03-21T13:06:09.216 CET] [debug] <<< testapi::select_console(testapi_console="root-virtio-terminal")
[2021-03-21T13:06:09.216 CET] [debug] <<< consoles::virtio_terminal::open_pipe(pipe_prefix="/var/lib/openqa/pool/15/virtio_console")
[33m[2021-03-21T13:06:09.218 CET] [info] ::: consoles::virtio_terminal::open_pipe: Set PIPE_SZ from 65536 to 1048576
[0m[33m[2021-03-21T13:06:09.218 CET] [info] ::: consoles::virtio_terminal::open_pipe: Set PIPE_SZ from 65536 to 1048576
[0m[37m[2021-03-21T13:06:09.219 CET] [debug] activate_console, console: root-virtio-terminal, type: virtio-terminal
[0m[2021-03-21T13:06:09.220 CET] [debug] tests/x11/window_system.pm:23 called opensusebasetest::select_serial_terminal -> lib/opensusebasetest.pm:1251 called testapi::select_console -> lib/susedistribution.pm:743 called serial_terminal::login -> lib/serial_terminal.pm:104 called bmwqemu::log_call
[2021-03-21T13:06:09.220 CET] [debug] <<< serial_terminal::login()
[2021-03-21T13:06:09.220 CET] [debug] tests/x11/window_system.pm:23 called opensusebasetest::select_serial_terminal -> lib/opensusebasetest.pm:1251 called testapi::select_console -> lib/susedistribution.pm:743 called serial_terminal::login -> lib/serial_terminal.pm:109 called testapi::wait_serial
[2021-03-21T13:06:09.220 CET] [debug] <<< testapi::wait_serial(record_output=undef, regexp=qr/login:\s*$/ui, quiet=1, timeout=5, expect_not_found=0, no_regex=0, buffer_size=undef)
[2021-03-21T13:06:09.221 CET] [debug] <<< consoles::serial_screen::read_until(timeout=5, no_regex=0, record_output=undef, json_cmd_token="cSmxqCNj", regexp="(?^ui:login:\\s*\$)", quiet=1, cmd="backend_wait_serial", pattern="(?^ui:login:\\s*\$)", expect_not_found=0, buffer_size=undef)
[32m[2021-03-21T13:06:14.225 CET] [debug] >>> testapi::wait_serial: (?^ui:login:\s*$): fail
[0m[2021-03-21T13:06:14.225 CET] [debug] tests/x11/window_system.pm:23 called opensusebasetest::select_serial_terminal -> lib/opensusebasetest.pm:1251 called testapi::select_console -> lib/susedistribution.pm:743 called serial_terminal::login -> lib/serial_terminal.pm:112 called testapi::type_string
[2021-03-21T13:06:14.226 CET] [debug] <<< testapi::type_string(text="\n")
[2021-03-21T13:06:14.226 CET] [debug] <<< consoles::serial_screen::type_string(text="\n", json_cmd_token="MhOAnyXh", cmd="backend_type_string")
[2021-03-21T13:06:14.227 CET] [debug] tests/x11/window_system.pm:23 called opensusebasetest::select_serial_terminal -> lib/opensusebasetest.pm:1251 called testapi::select_console -> lib/susedistribution.pm:743 called serial_terminal::login -> lib/serial_terminal.pm:113 called testapi::wait_serial
[2021-03-21T13:06:14.227 CET] [debug] <<< testapi::wait_serial(record_output=undef, quiet=undef, regexp=qr/login:\s*$/ui, timeout=90, buffer_size=undef, no_regex=0, expect_not_found=0)
[2021-03-21T13:06:14.228 CET] [debug] <<< consoles::serial_screen::read_until(no_regex=0, timeout=90, expect_not_found=0, buffer_size=undef, cmd="backend_wait_serial", pattern="(?^ui:login:\\s*\$)", json_cmd_token="fzppZDJd", regexp="(?^ui:login:\\s*\$)", quiet=undef, record_output=undef)
[33m[2021-03-21T13:06:14.559 CET] [info] ::: consoles::serial_screen::read_until: Matched output from SUT in 4 loops & 0.331674821994966 seconds: login:
[0m[32m[2021-03-21T13:06:14.561 CET] [debug] >>> testapi::wait_serial: (?^ui:login:\s*$): ok
[0m[2021-03-21T13:06:14.561 CET] [debug] tests/x11/window_system.pm:23 called opensusebasetest::select_serial_terminal -> lib/opensusebasetest.pm:1251 called testapi::select_console -> lib/susedistribution.pm:743 called serial_terminal::login -> lib/serial_terminal.pm:114 called testapi::type_string
[2021-03-21T13:06:14.561 CET] [debug] <<< testapi::type_string(text="root\n")
[2021-03-21T13:06:14.562 CET] [debug] <<< consoles::serial_screen::type_string(text="root\n", json_cmd_token="SAjuSVnt", cmd="backend_type_string")
[2021-03-21T13:06:14.562 CET] [debug] tests/x11/window_system.pm:23 called opensusebasetest::select_serial_terminal -> lib/opensusebasetest.pm:1251 called testapi::select_console -> lib/susedistribution.pm:743 called serial_terminal::login -> lib/serial_terminal.pm:116 called testapi::wait_serial
[2021-03-21T13:06:14.562 CET] [debug] <<< testapi::wait_serial(quiet=undef, regexp=qr/Password:\s*$/ui, record_output=undef, buffer_size=undef, no_regex=0, expect_not_found=0, timeout=90)
[2021-03-21T13:06:14.563 CET] [debug] <<< consoles::serial_screen::read_until(buffer_size=undef, expect_not_found=0, cmd="backend_wait_serial", pattern="(?^ui:Password:\\s*\$)", quiet=undef, regexp="(?^ui:Password:\\s*\$)", json_cmd_token="ngrlcvIT", record_output=undef, no_regex=0, timeout=90)
[33m[2021-03-21T13:06:14.573 CET] [info] ::: consoles::serial_screen::read_until: Matched output from SUT in 8 loops & 0.00976289800019003 seconds: Password:
[0m[32m[2021-03-21T13:06:14.574 CET] [debug] >>> testapi::wait_serial: (?^ui:Password:\s*$): ok
[0m[2021-03-21T13:06:14.574 CET] [debug] tests/x11/window_system.pm:23 called opensusebasetest::select_serial_terminal -> lib/opensusebasetest.pm:1251 called testapi::select_console -> lib/susedistribution.pm:743 called serial_terminal::login -> lib/serial_terminal.pm:117 called testapi::type_password
[2021-03-21T13:06:14.574 CET] [debug] <<< testapi::type_string(text="SECRET STRING", secret=1, max_interval=100)
[2021-03-21T13:06:14.575 CET] [debug] <<< consoles::serial_screen::type_string(cmd="backend_type_string", secret=1, max_interval=100, json_cmd_token="VIlNPhPf", text="nots3cr3t")
[2021-03-21T13:06:14.575 CET] [debug] tests/x11/window_system.pm:23 called opensusebasetest::select_serial_terminal -> lib/opensusebasetest.pm:1251 called testapi::select_console -> lib/susedistribution.pm:743 called serial_terminal::login -> lib/serial_terminal.pm:118 called testapi::type_string
[2021-03-21T13:06:14.575 CET] [debug] <<< testapi::type_string(text="\n")
[2021-03-21T13:06:14.576 CET] [debug] <<< consoles::serial_screen::type_string(cmd="backend_type_string", text="\n", json_cmd_token="ciMqPDgF")
[2021-03-21T13:06:14.576 CET] [debug] tests/x11/window_system.pm:23 called opensusebasetest::select_serial_terminal -> lib/opensusebasetest.pm:1251 called testapi::select_console -> lib/susedistribution.pm:743 called serial_terminal::login -> lib/serial_terminal.pm:120 called testapi::wait_serial
[2021-03-21T13:06:14.577 CET] [debug] <<< testapi::wait_serial(quiet=undef, regexp=qr/(?^ux:(\e [\(\[] [\d\w]{1,2}))* \w+:~\s\# (?^ux:(\e [\(\[] [\d\w]{1,2}))* \s*$/ux, record_output=undef, buffer_size=undef, expect_not_found=0, no_regex=0, timeout=90)
[2021-03-21T13:06:14.577 CET] [debug] <<< consoles::serial_screen::read_until(expect_not_found=0, buffer_size=undef, cmd="backend_wait_serial", pattern="(?^ux:(?^ux:(\\e [\\(\\[] [\\d\\w]{1,2}))* \\w+:~\\s\\# (?^ux:(\\e [\\(\\[] [\\d\\w]{1,2}))* \\s*\$)", json_cmd_token="rcOSckkn", regexp="(?^ux:(?^ux:(\\e [\\(\\[] [\\d\\w]{1,2}))* \\w+:~\\s\\# (?^ux:(\\e [\\(\\[] [\\d\\w]{1,2}))* \\s*\$)", quiet=undef, record_output=undef, no_regex=0, timeout=90)
[33m[2021-03-21T13:06:14.987 CET] [info] ::: consoles::serial_screen::read_until: Matched output from SUT in 7 loops & 0.40953487000661 seconds: [1msusetest:~ #[m(B
[0m[32m[2021-03-21T13:06:14.988 CET] [debug] >>> testapi::wait_serial: (?^ux:(?^ux:(\e [\(\[] [\d\w]{1,2}))* \w+:~\s\# (?^ux:(\e [\(\[] [\d\w]{1,2}))* \s*$): ok
[0m[2021-03-21T13:06:14.988 CET] [debug] tests/x11/window_system.pm:23 called opensusebasetest::select_serial_terminal -> lib/opensusebasetest.pm:1251 called testapi::select_console -> lib/susedistribution.pm:743 called serial_terminal::login -> lib/serial_terminal.pm:121 called testapi::type_string
[2021-03-21T13:06:14.988 CET] [debug] <<< testapi::type_string(text="PS1=\"# \"\n")
[2021-03-21T13:06:14.989 CET] [debug] <<< consoles::serial_screen::type_string(json_cmd_token="BZwkbVCW", text="PS1=\"# \"\n", cmd="backend_type_string")
[2021-03-21T13:06:14.989 CET] [debug] tests/x11/window_system.pm:23 called opensusebasetest::select_serial_terminal -> lib/opensusebasetest.pm:1251 called testapi::select_console -> lib/susedistribution.pm:743 called serial_terminal::login -> lib/serial_terminal.pm:122 called testapi::wait_serial
[2021-03-21T13:06:14.989 CET] [debug] <<< testapi::wait_serial(record_output=undef, regexp=qr/PS1="# "/u, quiet=undef, timeout=90, expect_not_found=0, no_regex=0, buffer_size=undef)
[2021-03-21T13:06:14.990 CET] [debug] <<< consoles::serial_screen::read_until(timeout=90, no_regex=0, record_output=undef, json_cmd_token="cgdTrcCL", regexp="(?^u:PS1=\"# \")", quiet=undef, pattern="(?^u:PS1=\"# \")", cmd="backend_wait_serial", expect_not_found=0, buffer_size=undef)
[33m[2021-03-21T13:06:14.990 CET] [info] ::: consoles::serial_screen::read_until: Matched output from SUT in 2 loops & 0.000274855003226548 seconds: PS1="# "
[0m[32m[2021-03-21T13:06:14.990 CET] [debug] >>> testapi::wait_serial: (?^u:PS1="# "): ok
[0m[2021-03-21T13:06:14.990 CET] [debug] tests/x11/window_system.pm:23 called opensusebasetest::select_serial_terminal -> lib/opensusebasetest.pm:1251 called testapi::select_console -> lib/susedistribution.pm:743 called serial_terminal::login -> lib/serial_terminal.pm:124 called testapi::assert_script_run
[2021-03-21T13:06:14.991 CET] [debug] <<< testapi::assert_script_run(cmd="export TERM=dumb; stty cols 2048", quiet=undef, fail_message="", timeout=90)
[2021-03-21T13:06:14.991 CET] [debug] tests/x11/window_system.pm:23 called opensusebasetest::select_serial_terminal -> lib/opensusebasetest.pm:1251 called testapi::select_console -> lib/susedistribution.pm:743 called serial_terminal::login -> lib/serial_terminal.pm:124 called testapi::assert_script_run
[2021-03-21T13:06:14.991 CET] [debug] <<< testapi::wait_serial(timeout=90, expect_not_found=0, no_regex=1, buffer_size=undef, record_output=undef, regexp="# ", quiet=undef)
[2021-03-21T13:06:14.991 CET] [debug] <<< consoles::serial_screen::read_until(pattern=[
"# "
], cmd="backend_wait_serial", expect_not_found=0, buffer_size=undef, record_output=undef, regexp="# ", json_cmd_token="HAAVSARF", quiet=undef, timeout=90, no_regex=1)
[33m[2021-03-21T13:06:14.992 CET] [info] ::: consoles::serial_screen::read_until: Matched output from SUT in 1 loops & 0.000244821996602695 seconds: #
[0m[32m[2021-03-21T13:06:14.992 CET] [debug] >>> testapi::wait_serial: # : ok
[0m[2021-03-21T13:06:14.992 CET] [debug] tests/x11/window_system.pm:23 called opensusebasetest::select_serial_terminal -> lib/opensusebasetest.pm:1251 called testapi::select_console -> lib/susedistribution.pm:743 called serial_terminal::login -> lib/serial_terminal.pm:124 called testapi::assert_script_run
[2021-03-21T13:06:14.992 CET] [debug] <<< testapi::type_string(text="export TERM=dumb; stty cols 2048")
[2021-03-21T13:06:14.993 CET] [debug] <<< consoles::serial_screen::type_string(cmd="backend_type_string", text="export TERM=dumb; stty cols 2048", json_cmd_token="jCzKlrly")
[2021-03-21T13:06:14.993 CET] [debug] tests/x11/window_system.pm:23 called opensusebasetest::select_serial_terminal -> lib/opensusebasetest.pm:1251 called testapi::select_console -> lib/susedistribution.pm:743 called serial_terminal::login -> lib/serial_terminal.pm:124 called testapi::assert_script_run
[2021-03-21T13:06:14.993 CET] [debug] <<< testapi::type_string(text="; echo NtGTe-\$?-")
[2021-03-21T13:06:14.993 CET] [debug] <<< consoles::serial_screen::type_string(cmd="backend_type_string", json_cmd_token="HJVFHxlg", text="; echo NtGTe-\$?-")
[2021-03-21T13:06:14.994 CET] [debug] tests/x11/window_system.pm:23 called opensusebasetest::select_serial_terminal -> lib/opensusebasetest.pm:1251 called testapi::select_console -> lib/susedistribution.pm:743 called serial_terminal::login -> lib/serial_terminal.pm:124 called testapi::assert_script_run
[2021-03-21T13:06:14.994 CET] [debug] <<< testapi::wait_serial(expect_not_found=0, no_regex=1, buffer_size=undef, timeout=90, regexp="export TERM=dumb; stty cols 2048; echo NtGTe-\$?-", quiet=undef, record_output=undef)
[2021-03-21T13:06:14.994 CET] [debug] <<< consoles::serial_screen::read_until(regexp="export TERM=dumb; stty cols 2048; echo NtGTe-\$?-", json_cmd_token="YhslgZlY", quiet=undef, record_output=undef, expect_not_found=0, buffer_size=undef, cmd="backend_wait_serial", pattern=[
"export TERM=dumb; stty cols 2048; echo NtGTe-\$?-"
], no_regex=1, timeout=90)
[33m[2021-03-21T13:06:14.994 CET] [info] ::: consoles::serial_screen::read_until: Matched output from SUT in 2 loops & 0.000259448999713641 seconds: export TERM=dumb; stty cols 2048; echo NtGTe-$?-
[0m[32m[2021-03-21T13:06:14.995 CET] [debug] >>> testapi::wait_serial: export TERM=dumb; stty cols 2048; echo NtGTe-$?-: ok
[0m[2021-03-21T13:06:14.995 CET] [debug] tests/x11/window_system.pm:23 called opensusebasetest::select_serial_terminal -> lib/opensusebasetest.pm:1251 called testapi::select_console -> lib/susedistribution.pm:743 called serial_terminal::login -> lib/serial_terminal.pm:124 called testapi::assert_script_run
[2021-03-21T13:06:14.995 CET] [debug] <<< testapi::type_string(text="\n")
[2021-03-21T13:06:14.995 CET] [debug] <<< consoles::serial_screen::type_string(cmd="backend_type_string", json_cmd_token="QuYrGRXs", text="\n")
[2021-03-21T13:06:14.996 CET] [debug] tests/x11/window_system.pm:23 called opensusebasetest::select_serial_terminal -> lib/opensusebasetest.pm:1251 called testapi::select_console -> lib/susedistribution.pm:743 called serial_terminal::login -> lib/serial_terminal.pm:124 called testapi::assert_script_run
[2021-03-21T13:06:14.996 CET] [debug] <<< testapi::wait_serial(buffer_size=undef, no_regex=0, expect_not_found=0, timeout=90, quiet=undef, regexp=qr/NtGTe-\d+-/, record_output=undef)
[2021-03-21T13:06:14.996 CET] [debug] <<< consoles::serial_screen::read_until(timeout=90, no_regex=0, pattern="(?^:NtGTe-\\d+-)", cmd="backend_wait_serial", buffer_size=undef, expect_not_found=0, record_output=undef, quiet=undef, json_cmd_token="ZyaZvRki", regexp="(?^:NtGTe-\\d+-)")
[33m[2021-03-21T13:06:14.999 CET] [info] ::: consoles::serial_screen::read_until: Matched output from SUT in 3 loops & 0.00293861099635251 seconds: NtGTe-0-
[0m[32m[2021-03-21T13:06:15.000 CET] [debug] >>> testapi::wait_serial: (?^:NtGTe-\d+-): ok
[0m[2021-03-21T13:06:15.000 CET] [debug] tests/x11/window_system.pm:23 called opensusebasetest::select_serial_terminal -> lib/opensusebasetest.pm:1251 called testapi::select_console -> lib/susedistribution.pm:743 called serial_terminal::login -> lib/serial_terminal.pm:125 called testapi::assert_script_run
[2021-03-21T13:06:15.000 CET] [debug] <<< testapi::assert_script_run(cmd="echo Logged into \$(tty)", fail_message="", timeout=30, quiet=undef, result_title="vconsole_login")
[2021-03-21T13:06:15.000 CET] [debug] tests/x11/window_system.pm:23 called opensusebasetest::select_serial_terminal -> lib/opensusebasetest.pm:1251 called testapi::select_console -> lib/susedistribution.pm:743 called serial_terminal::login -> lib/serial_terminal.pm:125 called testapi::assert_script_run
[2021-03-21T13:06:15.000 CET] [debug] <<< testapi::wait_serial(record_output=undef, quiet=undef, regexp="# ", timeout=90, buffer_size=undef, expect_not_found=0, no_regex=1)
[2021-03-21T13:06:15.001 CET] [debug] <<< consoles::serial_screen::read_until(no_regex=1, timeout=90, expect_not_found=0, buffer_size=undef, cmd="backend_wait_serial", pattern=[
"# "
], regexp="# ", json_cmd_token="vWmilsum", quiet=undef, record_output=undef)
[33m[2021-03-21T13:06:15.001 CET] [info] ::: consoles::serial_screen::read_until: Matched output from SUT in 2 loops & 0.000282050001260359 seconds: #
[0m[32m[2021-03-21T13:06:15.001 CET] [debug] >>> testapi::wait_serial: # : ok
[0m[2021-03-21T13:06:15.002 CET] [debug] tests/x11/window_system.pm:23 called opensusebasetest::select_serial_terminal -> lib/opensusebasetest.pm:1251 called testapi::select_console -> lib/susedistribution.pm:743 called serial_terminal::login -> lib/serial_terminal.pm:125 called testapi::assert_script_run
[2021-03-21T13:06:15.002 CET] [debug] <<< testapi::type_string(text="echo Logged into \$(tty)")
[2021-03-21T13:06:15.002 CET] [debug] <<< consoles::serial_screen::type_string(cmd="backend_type_string", json_cmd_token="xMZWvtbO", text="echo Logged into \$(tty)")
[2021-03-21T13:06:15.002 CET] [debug] tests/x11/window_system.pm:23 called opensusebasetest::select_serial_terminal -> lib/opensusebasetest.pm:1251 called testapi::select_console -> lib/susedistribution.pm:743 called serial_terminal::login -> lib/serial_terminal.pm:125 called testapi::assert_script_run
[2021-03-21T13:06:15.002 CET] [debug] <<< testapi::type_string(text="; echo 1XrKo-\$?-")
[2021-03-21T13:06:15.003 CET] [debug] <<< consoles::serial_screen::type_string(cmd="backend_type_string", json_cmd_token="QtMTjhwG", text="; echo 1XrKo-\$?-")
[2021-03-21T13:06:15.003 CET] [debug] tests/x11/window_system.pm:23 called opensusebasetest::select_serial_terminal -> lib/opensusebasetest.pm:1251 called testapi::select_console -> lib/susedistribution.pm:743 called serial_terminal::login -> lib/serial_terminal.pm:125 called testapi::assert_script_run
[2021-03-21T13:06:15.003 CET] [debug] <<< testapi::wait_serial(quiet=undef, regexp="echo Logged into \$(tty); echo 1XrKo-\$?-", record_output=undef, buffer_size=undef, no_regex=1, expect_not_found=0, timeout=90)
[2021-03-21T13:06:15.004 CET] [debug] <<< consoles::serial_screen::read_until(timeout=90, no_regex=1, record_output=undef, regexp="echo Logged into \$(tty); echo 1XrKo-\$?-", json_cmd_token="olhrTVeK", quiet=undef, pattern=[
"echo Logged into \$(tty); echo 1XrKo-\$?-"
], cmd="backend_wait_serial", expect_not_found=0, buffer_size=undef)
[33m[2021-03-21T13:06:15.004 CET] [info] ::: consoles::serial_screen::read_until: Matched output from SUT in 2 loops & 0.000302278000162914 seconds: echo Logged into $(tty); echo 1XrKo-$?-
[0m[32m[2021-03-21T13:06:15.004 CET] [debug] >>> testapi::wait_serial: echo Logged into $(tty); echo 1XrKo-$?-: ok
[0m[2021-03-21T13:06:15.004 CET] [debug] tests/x11/window_system.pm:23 called opensusebasetest::select_serial_terminal -> lib/opensusebasetest.pm:1251 called testapi::select_console -> lib/susedistribution.pm:743 called serial_terminal::login -> lib/serial_terminal.pm:125 called testapi::assert_script_run
[2021-03-21T13:06:15.004 CET] [debug] <<< testapi::type_string(text="\n")
[2021-03-21T13:06:15.005 CET] [debug] <<< consoles::serial_screen::type_string(text="\n", json_cmd_token="FOlutqmu", cmd="backend_type_string")
[2021-03-21T13:06:15.005 CET] [debug] tests/x11/window_system.pm:23 called opensusebasetest::select_serial_terminal -> lib/opensusebasetest.pm:1251 called testapi::select_console -> lib/susedistribution.pm:743 called serial_terminal::login -> lib/serial_terminal.pm:125 called testapi::assert_script_run
[2021-03-21T13:06:15.005 CET] [debug] <<< testapi::wait_serial(record_output=undef, quiet=undef, regexp=qr/1XrKo-\d+-/, timeout=30, buffer_size=undef, no_regex=0, expect_not_found=0)
[2021-03-21T13:06:15.006 CET] [debug] <<< consoles::serial_screen::read_until(timeout=30, no_regex=0, pattern="(?^:1XrKo-\\d+-)", cmd="backend_wait_serial", buffer_size=undef, expect_not_found=0, record_output=undef, quiet=undef, json_cmd_token="RrZtlXic", regexp="(?^:1XrKo-\\d+-)")
[33m[2021-03-21T13:06:15.007 CET] [info] ::: consoles::serial_screen::read_until: Matched output from SUT in 5 loops & 0.00133887799893273 seconds: 1XrKo-0-
[0m[32m[2021-03-21T13:06:15.007 CET] [debug] >>> testapi::wait_serial: (?^:1XrKo-\d+-): ok
[0m[2021-03-21T13:06:15.008 CET] [debug] tests/x11/window_system.pm:25 called testapi::script_output
[2021-03-21T13:06:15.008 CET] [debug] <<< testapi::wait_serial(regexp="# ", quiet=undef, record_output=undef, no_regex=1, expect_not_found=0, buffer_size=undef, timeout=90)
[2021-03-21T13:06:15.009 CET] [debug] <<< consoles::serial_screen::read_until(buffer_size=undef, expect_not_found=0, cmd="backend_wait_serial", pattern=[
"# "
], quiet=undef, json_cmd_token="OasDtNYS", regexp="# ", record_output=undef, no_regex=1, timeout=90)
[33m[2021-03-21T13:06:15.009 CET] [info] ::: consoles::serial_screen::read_until: Matched output from SUT in 2 loops & 0.000444140001491178 seconds: #
[0m[32m[2021-03-21T13:06:15.009 CET] [debug] >>> testapi::wait_serial: # : ok
[0m[2021-03-21T13:06:15.009 CET] [debug] tests/x11/window_system.pm:25 called testapi::script_output
[2021-03-21T13:06:15.010 CET] [debug] <<< distribution::script_output("Content of /tmp/script2dsRG.sh :\n \"cat > /tmp/script2dsRG.sh << 'EOT_2dsRG'; echo 2dsRG-\$?-\" \n")
[2021-03-21T13:06:15.010 CET] [debug] tests/x11/window_system.pm:25 called testapi::script_output
[2021-03-21T13:06:15.010 CET] [debug] <<< testapi::type_string(text="cat > /tmp/script2dsRG.sh << 'EOT_2dsRG'; echo 2dsRG-\$?-\n")
[2021-03-21T13:06:15.010 CET] [debug] <<< consoles::serial_screen::type_string(json_cmd_token="ZqDZTtWI", text="cat > /tmp/script2dsRG.sh << 'EOT_2dsRG'; echo 2dsRG-\$?-\n", cmd="backend_type_string")
[2021-03-21T13:06:15.010 CET] [debug] tests/x11/window_system.pm:25 called testapi::script_output
[2021-03-21T13:06:15.011 CET] [debug] <<< testapi::wait_serial(no_regex=1, expect_not_found=0, buffer_size=undef, timeout=90, regexp="cat > /tmp/script2dsRG.sh << 'EOT_2dsRG'; echo 2dsRG-\$?-", quiet=undef, record_output=undef)
[2021-03-21T13:06:15.011 CET] [debug] <<< consoles::serial_screen::read_until(buffer_size=undef, expect_not_found=0, cmd="backend_wait_serial", pattern=[
"cat > /tmp/script2dsRG.sh << 'EOT_2dsRG'; echo 2dsRG-\$?-"
], quiet=undef, json_cmd_token="FuWRpzHk", regexp="cat > /tmp/script2dsRG.sh << 'EOT_2dsRG'; echo 2dsRG-\$?-", record_output=undef, no_regex=1, timeout=90)
[33m[2021-03-21T13:06:15.012 CET] [info] ::: consoles::serial_screen::read_until: Matched output from SUT in 2 loops & 0.000408182997489348 seconds: cat > /tmp/script2dsRG.sh << 'EOT_2dsRG'; echo 2dsRG-$?-
[0m[32m[2021-03-21T13:06:15.012 CET] [debug] >>> testapi::wait_serial: cat > /tmp/script2dsRG.sh << 'EOT_2dsRG'; echo 2dsRG-$?-: ok
[0m[2021-03-21T13:06:15.012 CET] [debug] tests/x11/window_system.pm:25 called testapi::script_output
[2021-03-21T13:06:15.012 CET] [debug] <<< testapi::wait_serial(buffer_size=undef, expect_not_found=0, no_regex=1, timeout=90, quiet=undef, regexp="> ", record_output=undef)
[2021-03-21T13:06:15.013 CET] [debug] <<< consoles::serial_screen::read_until(no_regex=1, timeout=90, expect_not_found=0, buffer_size=undef, cmd="backend_wait_serial", pattern=[
"> "
], json_cmd_token="uONHohlu", regexp="> ", quiet=undef, record_output=undef)
[33m[2021-03-21T13:06:15.013 CET] [info] ::: consoles::serial_screen::read_until: Matched output from SUT in 1 loops & 0.000397263997001573 seconds: >
[0m[32m[2021-03-21T13:06:15.014 CET] [debug] >>> testapi::wait_serial: > : ok
[0m[2021-03-21T13:06:15.014 CET] [debug] tests/x11/window_system.pm:25 called testapi::script_output
[2021-03-21T13:06:15.014 CET] [debug] <<< testapi::type_string(text="loginctl show-session \$(loginctl list-sessions | awk '/bernhard/ {print \$1};') -p Type | cut -f2 -d=\nEOT_2dsRG\n")
[2021-03-21T13:06:15.014 CET] [debug] <<< consoles::serial_screen::type_string(json_cmd_token="GObXWNDP", text="loginctl show-session \$(loginctl list-sessions | awk '/bernhard/ {print \$1};') -p Type | cut -f2 -d=\nEOT_2dsRG\n", cmd="backend_type_string")
[2021-03-21T13:06:15.015 CET] [debug] tests/x11/window_system.pm:25 called testapi::script_output
[2021-03-21T13:06:15.015 CET] [debug] <<< testapi::wait_serial(no_regex=1, expect_not_found=0, buffer_size=undef, timeout=90, regexp="> EOT_2dsRG", quiet=undef, record_output=undef)
[2021-03-21T13:06:15.015 CET] [debug] <<< consoles::serial_screen::read_until(buffer_size=undef, expect_not_found=0, cmd="backend_wait_serial", pattern=[
"> EOT_2dsRG"
], quiet=undef, regexp="> EOT_2dsRG", json_cmd_token="GRHAqjGH", record_output=undef, no_regex=1, timeout=90)
[33m[2021-03-21T13:06:15.016 CET] [info] ::: consoles::serial_screen::read_until: Matched output from SUT in 2 loops & 0.000399041004129685 seconds: > EOT_2dsRG
[0m[32m[2021-03-21T13:06:15.016 CET] [debug] >>> testapi::wait_serial: > EOT_2dsRG: ok
[0m[2021-03-21T13:06:15.016 CET] [debug] tests/x11/window_system.pm:25 called testapi::script_output
[2021-03-21T13:06:15.016 CET] [debug] <<< testapi::wait_serial(timeout=90, no_regex=0, expect_not_found=0, buffer_size=undef, record_output=undef, regexp="2dsRG-0-", quiet=undef)
[2021-03-21T13:06:15.017 CET] [debug] <<< consoles::serial_screen::read_until(record_output=undef, json_cmd_token="TEsPGffj", regexp="2dsRG-0-", quiet=undef, pattern="2dsRG-0-", cmd="backend_wait_serial", expect_not_found=0, buffer_size=undef, timeout=90, no_regex=0)
[33m[2021-03-21T13:06:15.017 CET] [info] ::: consoles::serial_screen::read_until: Matched output from SUT in 2 loops & 0.000436381000326946 seconds: 2dsRG-0-
[0m[32m[2021-03-21T13:06:15.018 CET] [debug] >>> testapi::wait_serial: 2dsRG-0-: ok
[0m[2021-03-21T13:06:15.018 CET] [debug] tests/x11/window_system.pm:25 called testapi::script_output
[2021-03-21T13:06:15.018 CET] [debug] <<< testapi::wait_serial(quiet=undef, regexp="# ", record_output=undef, buffer_size=undef, no_regex=1, expect_not_found=0, timeout=90)
[2021-03-21T13:06:15.019 CET] [debug] <<< consoles::serial_screen::read_until(pattern=[
"# "
], cmd="backend_wait_serial", buffer_size=undef, expect_not_found=0, record_output=undef, quiet=undef, json_cmd_token="sLDXwNuE", regexp="# ", timeout=90, no_regex=1)
[33m[2021-03-21T13:06:15.019 CET] [info] ::: consoles::serial_screen::read_until: Matched output from SUT in 1 loops & 0.000370586996723432 seconds: #
[0m[32m[2021-03-21T13:06:15.019 CET] [debug] >>> testapi::wait_serial: # : ok
[0m[2021-03-21T13:06:15.019 CET] [debug] tests/x11/window_system.pm:25 called testapi::script_output
[2021-03-21T13:06:15.019 CET] [debug] <<< testapi::type_string(text="echo 2dsRG; bash -oe pipefail /tmp/script2dsRG.sh ; echo SCRIPT_FINISHED2dsRG-\$?-\n")
[2021-03-21T13:06:15.020 CET] [debug] <<< consoles::serial_screen::type_string(cmd="backend_type_string", json_cmd_token="pWUcGRhy", text="echo 2dsRG; bash -oe pipefail /tmp/script2dsRG.sh ; echo SCRIPT_FINISHED2dsRG-\$?-\n")
[2021-03-21T13:06:15.020 CET] [debug] tests/x11/window_system.pm:25 called testapi::script_output
[2021-03-21T13:06:15.020 CET] [debug] <<< testapi::wait_serial(buffer_size=undef, no_regex=1, expect_not_found=0, timeout=90, quiet=undef, regexp="echo 2dsRG; bash -oe pipefail /tmp/script2dsRG.sh ; echo SCRIPT_FINISHED2dsRG-\$?-", record_output=undef)
[2021-03-21T13:06:15.021 CET] [debug] <<< consoles::serial_screen::read_until(timeout=90, no_regex=1, pattern=[
"echo 2dsRG; bash -oe pipefail /tmp/script2dsRG.sh ; echo SCRIPT_FINISHED2dsRG-\$?-"
], cmd="backend_wait_serial", buffer_size=undef, expect_not_found=0, record_output=undef, quiet=undef, json_cmd_token="FBQuJNXp", regexp="echo 2dsRG; bash -oe pipefail /tmp/script2dsRG.sh ; echo SCRIPT_FINISHED2dsRG-\$?-")
[33m[2021-03-21T13:06:15.021 CET] [info] ::: consoles::serial_screen::read_until: Matched output from SUT in 2 loops & 0.000427086000854615 seconds: echo 2dsRG; bash -oe pipefail /tmp/script2dsRG.sh ; echo SCRIPT_FINISHED2dsRG-$?-
[0m[32m[2021-03-21T13:06:15.022 CET] [debug] >>> testapi::wait_serial: echo 2dsRG; bash -oe pipefail /tmp/script2dsRG.sh ; echo SCRIPT_FINISHED2dsRG-$?-: ok
[0m[2021-03-21T13:06:15.022 CET] [debug] tests/x11/window_system.pm:25 called testapi::script_output
[2021-03-21T13:06:15.022 CET] [debug] <<< testapi::wait_serial(regexp="SCRIPT_FINISHED2dsRG-\\d+-", quiet=undef, record_output=1, no_regex=0, expect_not_found=0, buffer_size=undef, timeout=90)
[2021-03-21T13:06:15.023 CET] [debug] <<< consoles::serial_screen::read_until(timeout=90, no_regex=0, pattern="SCRIPT_FINISHED2dsRG-\\d+-", cmd="backend_wait_serial", expect_not_found=0, buffer_size=undef, record_output=1, json_cmd_token="XPzmaemg", regexp="SCRIPT_FINISHED2dsRG-\\d+-", quiet=undef)
[33m[2021-03-21T13:06:15.052 CET] [info] ::: consoles::serial_screen::read_until: Matched output from SUT in 4 loops & 0.0294258220019401 seconds: SCRIPT_FINISHED2dsRG-0-
[0m[32m[2021-03-21T13:06:15.053 CET] [debug] >>> testapi::wait_serial: SCRIPT_FINISHED2dsRG-\d+-: ok
[0m[2021-03-21T13:06:15.053 CET] [debug] tests/x11/window_system.pm:30 called testapi::record_info
[2021-03-21T13:06:15.053 CET] [debug] <<< testapi::record_info(title="wayland", output="Current session type is wayland", result="ok")
[2021-03-21T13:06:15.054 CET] [debug] tests/x11/window_system.pm:36 called testapi::select_console
[2021-03-21T13:06:15.054 CET] [debug] <<< testapi::select_console(testapi_console="x11")
[37m[2021-03-21T13:06:15.464 CET] [debug] activate_console, console: x11, type:
[0m[37m[2021-03-21T13:06:15.464 CET] [debug] activate_console called with generic type, no action
[0m[2021-03-21T13:06:15.464 CET] [debug] tests/x11/window_system.pm:36 called testapi::select_console -> lib/susedistribution.pm:889 called x11utils::ensure_unlocked_desktop -> lib/x11utils.pm:80 called testapi::assert_screen
[2021-03-21T13:06:15.464 CET] [debug] <<< testapi::assert_screen(mustmatch=[
"displaymanager",
"displaymanager-password-prompt",
"generic-desktop",
"screenlock",
"screenlock-password",
"authentication-required-user-settings",
"authentication-required-modify-system",
"guest-disabled-display",
"oh-no-something-has-gone-wrong"
], no_wait=1, timeout=30)
[32m[2021-03-21T13:06:18.522 CET] [debug] >>> testapi::_handle_found_needle: found consoletest_finish-gnome-TW-20190522, similarity 1.00 @ 0/1
[0m[2021-03-21T13:06:18.524 CET] [debug] tests/x11/window_system.pm:36 called testapi::select_console -> lib/susedistribution.pm:889 called x11utils::ensure_unlocked_desktop -> lib/x11utils.pm:128 called testapi::send_key
[2021-03-21T13:06:18.524 CET] [debug] <<< testapi::send_key(key="esc", wait_screen_change=0, do_wait=0)
[2021-03-21T13:06:18.793 CET] [debug] tests/x11/window_system.pm:36 called testapi::select_console -> lib/susedistribution.pm:889 called x11utils::ensure_unlocked_desktop -> lib/x11utils.pm:135 called testapi::mouse_hide
[2021-03-21T13:06:18.793 CET] [debug] <<< testapi::mouse_hide(border_offset=1)
[37m[2021-03-21T13:06:18.794 CET] [debug] mouse_move 1023, 767
[0m[37m[2021-03-21T13:06:18.794 CET] [debug] send_pointer_event 0, 1023, 767, 1
[0m[2021-03-21T13:06:18.795 CET] [debug] tests/x11/window_system.pm:36 called testapi::select_console -> lib/susedistribution.pm:889 called x11utils::ensure_unlocked_desktop -> lib/x11utils.pm:136 called testapi::send_key
[2021-03-21T13:06:18.795 CET] [debug] <<< testapi::send_key(key="alt-f2", wait_screen_change=0, do_wait=0)
[2021-03-21T13:06:19.130 CET] [debug] tests/x11/window_system.pm:36 called testapi::select_console -> lib/susedistribution.pm:889 called x11utils::ensure_unlocked_desktop -> lib/x11utils.pm:137 called testapi::check_screen
[2021-03-21T13:06:19.130 CET] [debug] <<< testapi::check_screen(mustmatch="desktop-runner", timeout=30)
[37m[2021-03-21T13:06:19.487 CET] [debug] no match: 29.9s, best candidate: desktop-runner-gnome-3.16+-20150325 (0.00)
[0m[32m[2021-03-21T13:06:20.347 CET] [debug] >>> testapi::_handle_found_needle: found desktop-runner-gnome-3.36+-20200218, similarity 1.00 @ 348/311
[0m[2021-03-21T13:06:20.348 CET] [debug] tests/x11/window_system.pm:36 called testapi::select_console -> lib/susedistribution.pm:889 called x11utils::ensure_unlocked_desktop -> lib/x11utils.pm:138 called testapi::send_key
[2021-03-21T13:06:20.348 CET] [debug] <<< testapi::send_key(key="esc", do_wait=0, wait_screen_change=0)
[2021-03-21T13:06:20.617 CET] [debug] tests/x11/window_system.pm:36 called testapi::select_console -> lib/susedistribution.pm:889 called x11utils::ensure_unlocked_desktop -> lib/x11utils.pm:139 called testapi::assert_screen
[2021-03-21T13:06:20.617 CET] [debug] <<< testapi::assert_screen(mustmatch="generic-desktop", timeout=30)
[32m[2021-03-21T13:06:22.091 CET] [debug] >>> testapi::_handle_found_needle: found consoletest_finish-gnome-TW-20190522, similarity 1.00 @ 0/1
[0m[37m[2021-03-21T13:06:22.094 CET] [debug] ||| finished window_system x11 at 2021-03-21 12:06:22 (13 s)
[0m[1;34m[2021-03-21T13:06:22.097 CET] [debug] ||| starting nautilus_cut_file tests/x11/gnomecase/nautilus_cut_file.pm
[0m[2021-03-21T13:06:22.098 CET] [debug] tests/x11/gnomecase/nautilus_cut_file.pm:28 called testapi::x11_start_program
[2021-03-21T13:06:22.098 CET] [debug] <<< testapi::x11_start_program(program="nautilus")
[2021-03-21T13:06:22.098 CET] [debug] tests/x11/gnomecase/nautilus_cut_file.pm:28 called testapi::x11_start_program -> lib/susedistribution.pm:265 called susedistribution::init_desktop_runner -> lib/susedistribution.pm:177 called testapi::send_key
[2021-03-21T13:06:22.098 CET] [debug] <<< testapi::send_key(key="alt-f2", do_wait=0, wait_screen_change=0)
[2021-03-21T13:06:22.433 CET] [debug] tests/x11/gnomecase/nautilus_cut_file.pm:28 called testapi::x11_start_program -> lib/susedistribution.pm:265 called susedistribution::init_desktop_runner -> lib/susedistribution.pm:179 called testapi::mouse_hide
[2021-03-21T13:06:22.433 CET] [debug] <<< testapi::mouse_hide(border_offset=200)
[37m[2021-03-21T13:06:22.434 CET] [debug] send_pointer_event 0, 1018, 762, 1
[0m[37m[2021-03-21T13:06:22.434 CET] [debug] mouse_move 1023, 767
[0m[37m[2021-03-21T13:06:22.434 CET] [debug] send_pointer_event 0, 1023, 767, 1
[0m[2021-03-21T13:06:22.435 CET] [debug] tests/x11/gnomecase/nautilus_cut_file.pm:28 called testapi::x11_start_program -> lib/susedistribution.pm:265 called susedistribution::init_desktop_runner -> lib/susedistribution.pm:180 called testapi::check_screen
[2021-03-21T13:06:22.435 CET] [debug] <<< testapi::check_screen(mustmatch="desktop-runner", timeout=30)
[37m[2021-03-21T13:06:22.600 CET] [debug] no match: 29.9s, best candidate: desktop-runner-gnome-3.16+-20150325 (0.00)
[0m[32m[2021-03-21T13:06:23.640 CET] [debug] >>> testapi::_handle_found_needle: found desktop-runner-gnome-3.36+-20200218, similarity 1.00 @ 348/311
[0m[2021-03-21T13:06:23.641 CET] [debug] tests/x11/gnomecase/nautilus_cut_file.pm:28 called testapi::x11_start_program -> lib/susedistribution.pm:265 called susedistribution::init_desktop_runner -> lib/susedistribution.pm:185 called testapi::wait_still_screen
[2021-03-21T13:06:23.641 CET] [debug] <<< testapi::wait_still_screen(similarity_level=47, timeout=30, stilltime=2)
[32m[2021-03-21T13:06:25.656 CET] [debug] >>> testapi::wait_still_screen: detected same image for 2 seconds, last detected similarity is 1000000
[0m[2021-03-21T13:06:25.657 CET] [debug] tests/x11/gnomecase/nautilus_cut_file.pm:28 called testapi::x11_start_program -> lib/susedistribution.pm:265 called susedistribution::init_desktop_runner -> lib/susedistribution.pm:201 called testapi::type_string
[2021-03-21T13:06:25.657 CET] [debug] <<< testapi::type_string(string="nautilus", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2021-03-21T13:06:25.930 CET] [debug] tests/x11/gnomecase/nautilus_cut_file.pm:28 called testapi::x11_start_program -> lib/susedistribution.pm:272 called testapi::wait_still_screen
[2021-03-21T13:06:25.930 CET] [debug] <<< testapi::wait_still_screen(similarity_level=47, stilltime=3, timeout=30)
[32m[2021-03-21T13:06:29.457 CET] [debug] >>> testapi::wait_still_screen: detected same image for 3 seconds, last detected similarity is 1000000
[0m[2021-03-21T13:06:29.543 CET] [debug] tests/x11/gnomecase/nautilus_cut_file.pm:28 called testapi::x11_start_program -> lib/susedistribution.pm:274 called testapi::send_key
[2021-03-21T13:06:29.543 CET] [debug] <<< testapi::send_key(key="ret", wait_screen_change=0, do_wait=0)
[2021-03-21T13:06:29.812 CET] [debug] tests/x11/gnomecase/nautilus_cut_file.pm:28 called testapi::x11_start_program -> lib/susedistribution.pm:283 called testapi::assert_screen
[2021-03-21T13:06:29.812 CET] [debug] <<< testapi::assert_screen(mustmatch=[
"nautilus",
"desktop-runner-border"
], timeout=30, no_wait=0)
[37m[2021-03-21T13:06:30.030 CET] [debug] no match: 29.9s, best candidate: nautilus-1-leap150-20171112 (0.00)
[0m[37m[2021-03-21T13:06:30.914 CET] [debug] no match: 28.9s, best candidate: nautilus-1-leap150-20171112 (0.00)
[0m[32m[2021-03-21T13:06:32.002 CET] [debug] >>> testapi::_handle_found_needle: found test-nautilus-1-20200422, similarity 1.00 @ 71/124
[0m[2021-03-21T13:06:32.003 CET] [debug] tests/x11/gnomecase/nautilus_cut_file.pm:29 called testapi::x11_start_program
[2021-03-21T13:06:32.003 CET] [debug] <<< testapi::x11_start_program(program="touch newfile", valid=0)
[2021-03-21T13:06:32.003 CET] [debug] tests/x11/gnomecase/nautilus_cut_file.pm:29 called testapi::x11_start_program -> lib/susedistribution.pm:265 called susedistribution::init_desktop_runner -> lib/susedistribution.pm:177 called testapi::send_key
[2021-03-21T13:06:32.003 CET] [debug] <<< testapi::send_key(key="alt-f2", wait_screen_change=0, do_wait=0)
[2021-03-21T13:06:32.345 CET] [debug] tests/x11/gnomecase/nautilus_cut_file.pm:29 called testapi::x11_start_program -> lib/susedistribution.pm:265 called susedistribution::init_desktop_runner -> lib/susedistribution.pm:179 called testapi::mouse_hide
[2021-03-21T13:06:32.345 CET] [debug] <<< testapi::mouse_hide(border_offset=200)
[37m[2021-03-21T13:06:32.346 CET] [debug] send_pointer_event 0, 1018, 762, 1
[0m[37m[2021-03-21T13:06:32.346 CET] [debug] mouse_move 1023, 767
[0m[37m[2021-03-21T13:06:32.346 CET] [debug] send_pointer_event 0, 1023, 767, 1
[0m[2021-03-21T13:06:32.347 CET] [debug] tests/x11/gnomecase/nautilus_cut_file.pm:29 called testapi::x11_start_program -> lib/susedistribution.pm:265 called susedistribution::init_desktop_runner -> lib/susedistribution.pm:180 called testapi::check_screen
[2021-03-21T13:06:32.347 CET] [debug] <<< testapi::check_screen(mustmatch="desktop-runner", timeout=30)
[32m[2021-03-21T13:06:33.053 CET] [debug] >>> testapi::_handle_found_needle: found desktop-runner-gnome-3.36+-20200218, similarity 0.99 @ 348/311
[0m[2021-03-21T13:06:33.054 CET] [debug] tests/x11/gnomecase/nautilus_cut_file.pm:29 called testapi::x11_start_program -> lib/susedistribution.pm:265 called susedistribution::init_desktop_runner -> lib/susedistribution.pm:185 called testapi::wait_still_screen
[2021-03-21T13:06:33.054 CET] [debug] <<< testapi::wait_still_screen(similarity_level=47, timeout=30, stilltime=2)
[32m[2021-03-21T13:06:35.071 CET] [debug] >>> testapi::wait_still_screen: detected same image for 2 seconds, last detected similarity is 1000000
[0m[2021-03-21T13:06:35.072 CET] [debug] tests/x11/gnomecase/nautilus_cut_file.pm:29 called testapi::x11_start_program -> lib/susedistribution.pm:265 called susedistribution::init_desktop_runner -> lib/susedistribution.pm:201 called testapi::type_string
[2021-03-21T13:06:35.072 CET] [debug] <<< testapi::type_string(string="touch newfile", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2021-03-21T13:06:35.516 CET] [debug] tests/x11/gnomecase/nautilus_cut_file.pm:29 called testapi::x11_start_program -> lib/susedistribution.pm:272 called testapi::wait_still_screen
[2021-03-21T13:06:35.516 CET] [debug] <<< testapi::wait_still_screen(stilltime=3, timeout=30, similarity_level=47)
[32m[2021-03-21T13:06:39.548 CET] [debug] >>> testapi::wait_still_screen: detected same image for 3 seconds, last detected similarity is 1000000
[0m[2021-03-21T13:06:39.628 CET] [debug] tests/x11/gnomecase/nautilus_cut_file.pm:29 called testapi::x11_start_program -> lib/susedistribution.pm:274 called testapi::send_key
[2021-03-21T13:06:39.628 CET] [debug] <<< testapi::send_key(key="ret", do_wait=0, wait_screen_change=0)
[2021-03-21T13:06:39.904 CET] [debug] tests/x11/gnomecase/nautilus_cut_file.pm:29 called testapi::x11_start_program -> lib/susedistribution.pm:277 called testapi::wait_still_screen
[2021-03-21T13:06:39.905 CET] [debug] <<< testapi::wait_still_screen(timeout=30, stilltime=3, similarity_level=45)
[32m[2021-03-21T13:06:43.434 CET] [debug] >>> testapi::wait_still_screen: detected same image for 3 seconds, last detected similarity is 1000000
[0m[2021-03-21T13:06:43.434 CET] [debug] tests/x11/gnomecase/nautilus_cut_file.pm:31 called testapi::send_key_until_needlematch
[2021-03-21T13:06:43.434 CET] [debug] <<< testapi::check_screen(mustmatch="nautilus-newfile-matched", timeout=1)
[37m[2021-03-21T13:06:43.873 CET] [debug] no match: 0.9s, best candidate: nautilus_cut_file-nautilus-newfile-matched-20180622 (0.00)
[0m[37m[2021-03-21T13:06:44.665 CET] [debug] no match: -0.1s, best candidate: nautilus_cut_file-nautilus-newfile-matched-20180622 (0.00)
[0m[32m[2021-03-21T13:06:44.844 CET] [debug] >>> testapi::_check_backend_response: match=nautilus-newfile-matched timed out after 1 (check_screen)
[0m[2021-03-21T13:06:44.869 CET] [debug] tests/x11/gnomecase/nautilus_cut_file.pm:31 called testapi::send_key_until_needlematch
[2021-03-21T13:06:44.869 CET] [debug] <<< testapi::wait_screen_change(timeout=10, similarity_level=50)
[2021-03-21T13:06:44.870 CET] [debug] tests/x11/gnomecase/nautilus_cut_file.pm:31 called testapi::send_key_until_needlematch
[2021-03-21T13:06:44.870 CET] [debug] <<< testapi::send_key(key="right", wait_screen_change=0, do_wait=0)
[37m[2021-03-21T13:06:45.141 CET] [debug] waiting for screen change: 0 1000000
[0m[37m[2021-03-21T13:06:45.643 CET] [debug] waiting for screen change: 0 46.0275270052546
[0m[32m[2021-03-21T13:06:45.644 CET] [debug] >>> testapi::wait_screen_change: screen change seen at 0
[0m[2021-03-21T13:06:45.644 CET] [debug] tests/x11/gnomecase/nautilus_cut_file.pm:31 called testapi::send_key_until_needlematch
[2021-03-21T13:06:45.644 CET] [debug] <<< testapi::check_screen(mustmatch="nautilus-newfile-matched", timeout=1)
[37m[2021-03-21T13:06:45.942 CET] [debug] no match: 0.9s, best candidate: nautilus_cut_file-nautilus-newfile-matched-20180622 (0.00)
[0m[37m[2021-03-21T13:06:46.861 CET] [debug] no match: -0.1s, best candidate: nautilus_cut_file-nautilus-newfile-matched-20180622 (0.00)
[0m[32m[2021-03-21T13:06:47.044 CET] [debug] >>> testapi::_check_backend_response: match=nautilus-newfile-matched timed out after 1 (check_screen)
[0m[2021-03-21T13:06:47.071 CET] [debug] tests/x11/gnomecase/nautilus_cut_file.pm:31 called testapi::send_key_until_needlematch
[2021-03-21T13:06:47.071 CET] [debug] <<< testapi::wait_screen_change(timeout=10, similarity_level=50)
[2021-03-21T13:06:47.072 CET] [debug] tests/x11/gnomecase/nautilus_cut_file.pm:31 called testapi::send_key_until_needlematch
[2021-03-21T13:06:47.072 CET] [debug] <<< testapi::send_key(key="right", do_wait=0, wait_screen_change=0)
[37m[2021-03-21T13:06:47.344 CET] [debug] waiting for screen change: 0 1000000
[0m[37m[2021-03-21T13:06:47.848 CET] [debug] waiting for screen change: 0 26.7565390186903
[0m[32m[2021-03-21T13:06:47.848 CET] [debug] >>> testapi::wait_screen_change: screen change seen at 0
[0m[2021-03-21T13:06:47.849 CET] [debug] tests/x11/gnomecase/nautilus_cut_file.pm:31 called testapi::send_key_until_needlematch
[2021-03-21T13:06:47.849 CET] [debug] <<< testapi::check_screen(mustmatch="nautilus-newfile-matched", timeout=1)
[37m[2021-03-21T13:06:48.146 CET] [debug] no match: 0.9s, best candidate: nautilus_cut_file-nautilus-newfile-matched-20180622 (0.00)
[0m[37m[2021-03-21T13:06:49.101 CET] [debug] no match: -0.1s, best candidate: nautilus_cut_file-nautilus-newfile-matched-20180622 (0.00)
[0m[32m[2021-03-21T13:06:49.268 CET] [debug] >>> testapi::_check_backend_response: match=nautilus-newfile-matched timed out after 1 (check_screen)
[0m[2021-03-21T13:06:49.294 CET] [debug] tests/x11/gnomecase/nautilus_cut_file.pm:31 called testapi::send_key_until_needlematch
[2021-03-21T13:06:49.294 CET] [debug] <<< testapi::wait_screen_change(timeout=10, similarity_level=50)
[2021-03-21T13:06:49.295 CET] [debug] tests/x11/gnomecase/nautilus_cut_file.pm:31 called testapi::send_key_until_needlematch
[2021-03-21T13:06:49.295 CET] [debug] <<< testapi::send_key(key="right", wait_screen_change=0, do_wait=0)
[37m[2021-03-21T13:06:49.568 CET] [debug] waiting for screen change: 0 1000000
[0m[37m[2021-03-21T13:06:50.070 CET] [debug] waiting for screen change: 1 24.209925066958
[0m[32m[2021-03-21T13:06:50.071 CET] [debug] >>> testapi::wait_screen_change: screen change seen at 1
[0m[2021-03-21T13:06:50.071 CET] [debug] tests/x11/gnomecase/nautilus_cut_file.pm:31 called testapi::send_key_until_needlematch
[2021-03-21T13:06:50.071 CET] [debug] <<< testapi::check_screen(mustmatch="nautilus-newfile-matched", timeout=1)
[37m[2021-03-21T13:06:50.341 CET] [debug] no match: 0.9s, best candidate: nautilus_cut_file-nautilus-newfile-matched-20180622 (0.00)
[0m[37m[2021-03-21T13:06:51.390 CET] [debug] no match: -0.1s, best candidate: nautilus_cut_file-nautilus-newfile-matched-20180622 (0.00)
[0m[32m[2021-03-21T13:06:51.577 CET] [debug] >>> testapi::_check_backend_response: match=nautilus-newfile-matched timed out after 1 (check_screen)
[0m[2021-03-21T13:06:51.610 CET] [debug] tests/x11/gnomecase/nautilus_cut_file.pm:31 called testapi::send_key_until_needlematch
[2021-03-21T13:06:51.611 CET] [debug] <<< testapi::wait_screen_change(timeout=10, similarity_level=50)
[2021-03-21T13:06:51.612 CET] [debug] tests/x11/gnomecase/nautilus_cut_file.pm:31 called testapi::send_key_until_needlematch
[2021-03-21T13:06:51.612 CET] [debug] <<< testapi::send_key(key="right", wait_screen_change=0, do_wait=0)
[37m[2021-03-21T13:06:51.884 CET] [debug] waiting for screen change: 0 1000000
[0m[37m[2021-03-21T13:06:52.387 CET] [debug] waiting for screen change: 1 23.7116059699355
[0m[32m[2021-03-21T13:06:52.387 CET] [debug] >>> testapi::wait_screen_change: screen change seen at 1
[0m[2021-03-21T13:06:52.387 CET] [debug] tests/x11/gnomecase/nautilus_cut_file.pm:31 called testapi::send_key_until_needlematch
[2021-03-21T13:06:52.387 CET] [debug] <<< testapi::check_screen(mustmatch="nautilus-newfile-matched", timeout=1)
[37m[2021-03-21T13:06:52.611 CET] [debug] no match: 0.9s, best candidate: nautilus_cut_file-nautilus-newfile-matched-20180622 (0.00)
[0m[37m[2021-03-21T13:06:53.617 CET] [debug] no match: -0.1s, best candidate: nautilus_cut_file-nautilus-newfile-matched-20180622 (0.00)
[0m[32m[2021-03-21T13:06:53.812 CET] [debug] >>> testapi::_check_backend_response: match=nautilus-newfile-matched timed out after 1 (check_screen)
[0m[2021-03-21T13:06:53.842 CET] [debug] tests/x11/gnomecase/nautilus_cut_file.pm:31 called testapi::send_key_until_needlematch
[2021-03-21T13:06:53.842 CET] [debug] <<< testapi::wait_screen_change(timeout=10, similarity_level=50)
[2021-03-21T13:06:53.843 CET] [debug] tests/x11/gnomecase/nautilus_cut_file.pm:31 called testapi::send_key_until_needlematch
[2021-03-21T13:06:53.843 CET] [debug] <<< testapi::send_key(key="right", wait_screen_change=0, do_wait=0)
[37m[2021-03-21T13:06:54.115 CET] [debug] waiting for screen change: 0 1000000
[0m[37m[2021-03-21T13:06:54.620 CET] [debug] waiting for screen change: 0 23.5484733270691
[0m[32m[2021-03-21T13:06:54.620 CET] [debug] >>> testapi::wait_screen_change: screen change seen at 0
[0m[2021-03-21T13:06:54.620 CET] [debug] tests/x11/gnomecase/nautilus_cut_file.pm:31 called testapi::send_key_until_needlematch
[2021-03-21T13:06:54.620 CET] [debug] <<< testapi::check_screen(mustmatch="nautilus-newfile-matched", timeout=1)
[37m[2021-03-21T13:06:54.907 CET] [debug] no match: 0.9s, best candidate: nautilus_cut_file-nautilus-newfile-matched-20180622 (0.00)
[0m[37m[2021-03-21T13:06:55.863 CET] [debug] no match: -0.1s, best candidate: nautilus_cut_file-nautilus-newfile-matched-20180622 (0.00)
[0m[32m[2021-03-21T13:06:56.090 CET] [debug] >>> testapi::_check_backend_response: match=nautilus-newfile-matched timed out after 1 (check_screen)
[0m[2021-03-21T13:06:56.135 CET] [debug] tests/x11/gnomecase/nautilus_cut_file.pm:31 called testapi::send_key_until_needlematch
[2021-03-21T13:06:56.135 CET] [debug] <<< testapi::wait_screen_change(timeout=10, similarity_level=50)
[2021-03-21T13:06:56.136 CET] [debug] tests/x11/gnomecase/nautilus_cut_file.pm:31 called testapi::send_key_until_needlematch
[2021-03-21T13:06:56.137 CET] [debug] <<< testapi::send_key(key="right", wait_screen_change=0, do_wait=0)
[37m[2021-03-21T13:06:56.408 CET] [debug] waiting for screen change: 0 1000000
[0m[37m[2021-03-21T13:06:56.912 CET] [debug] waiting for screen change: 0 23.8566060375104
[0m[32m[2021-03-21T13:06:56.912 CET] [debug] >>> testapi::wait_screen_change: screen change seen at 0
[0m[2021-03-21T13:06:56.912 CET] [debug] tests/x11/gnomecase/nautilus_cut_file.pm:31 called testapi::send_key_until_needlematch
[2021-03-21T13:06:56.912 CET] [debug] <<< testapi::check_screen(mustmatch="nautilus-newfile-matched", timeout=1)
[37m[2021-03-21T13:06:57.143 CET] [debug] no match: 0.9s, best candidate: nautilus_cut_file-nautilus-newfile-matched-20180622 (0.00)
[0m[37m[2021-03-21T13:06:58.145 CET] [debug] no match: -0.1s, best candidate: nautilus_cut_file-nautilus-newfile-matched-20180622 (0.00)
[0m[32m[2021-03-21T13:06:58.384 CET] [debug] >>> testapi::_check_backend_response: match=nautilus-newfile-matched timed out after 1 (check_screen)
[0m[2021-03-21T13:06:58.431 CET] [debug] tests/x11/gnomecase/nautilus_cut_file.pm:31 called testapi::send_key_until_needlematch
[2021-03-21T13:06:58.431 CET] [debug] <<< testapi::wait_screen_change(timeout=10, similarity_level=50)
[2021-03-21T13:06:58.432 CET] [debug] tests/x11/gnomecase/nautilus_cut_file.pm:31 called testapi::send_key_until_needlematch
[2021-03-21T13:06:58.433 CET] [debug] <<< testapi::send_key(key="right", do_wait=0, wait_screen_change=0)
[37m[2021-03-21T13:06:58.703 CET] [debug] waiting for screen change: 0 1000000
[0m[37m[2021-03-21T13:06:59.208 CET] [debug] waiting for screen change: 1 23.584297989199
[0m[32m[2021-03-21T13:06:59.208 CET] [debug] >>> testapi::wait_screen_change: screen change seen at 1
[0m[2021-03-21T13:06:59.208 CET] [debug] tests/x11/gnomecase/nautilus_cut_file.pm:31 called testapi::send_key_until_needlematch
[2021-03-21T13:06:59.208 CET] [debug] <<< testapi::check_screen(mustmatch="nautilus-newfile-matched", timeout=1)
[32m[2021-03-21T13:06:59.537 CET] [debug] >>> testapi::_handle_found_needle: found nautilus_cut_file-nautilus-newfile-matched-20200426, similarity 1.00 @ 475/263
[0m[2021-03-21T13:06:59.537 CET] [debug] tests/x11/gnomecase/nautilus_cut_file.pm:32 called testapi::send_key
[2021-03-21T13:06:59.538 CET] [debug] <<< testapi::send_key(key="ctrl-x", wait_screen_change=0, do_wait=0)
[2021-03-21T13:06:59.874 CET] [debug] tests/x11/gnomecase/nautilus_cut_file.pm:33 called testapi::send_key_until_needlematch
[2021-03-21T13:06:59.874 CET] [debug] <<< testapi::check_screen(mustmatch="nautilus-Downloads-matched", timeout=1)
[37m[2021-03-21T13:07:00.529 CET] [debug] no match: 0.6s, best candidate: nautilus_cut_file-nautilus-Downloads-matched-20180622 (0.00)
[0m[37m[2021-03-21T13:07:01.376 CET] [debug] no match: -0.4s, best candidate: nautilus_cut_file-nautilus-Downloads-matched-20180622 (0.00)
[0m[32m[2021-03-21T13:07:01.568 CET] [debug] >>> testapi::_check_backend_response: match=nautilus-Downloads-matched timed out after 1 (check_screen)
[0m[2021-03-21T13:07:01.597 CET] [debug] tests/x11/gnomecase/nautilus_cut_file.pm:33 called testapi::send_key_until_needlematch
[2021-03-21T13:07:01.597 CET] [debug] <<< testapi::wait_screen_change(timeout=10, similarity_level=50)
[2021-03-21T13:07:01.598 CET] [debug] tests/x11/gnomecase/nautilus_cut_file.pm:33 called testapi::send_key_until_needlematch
[2021-03-21T13:07:01.599 CET] [debug] <<< testapi::send_key(key="left", do_wait=0, wait_screen_change=0)
[37m[2021-03-21T13:07:01.871 CET] [debug] waiting for screen change: 0 1000000
[0m[37m[2021-03-21T13:07:02.375 CET] [debug] waiting for screen change: 1 23.4252630555742
[0m[32m[2021-03-21T13:07:02.375 CET] [debug] >>> testapi::wait_screen_change: screen change seen at 1
[0m[2021-03-21T13:07:02.375 CET] [debug] tests/x11/gnomecase/nautilus_cut_file.pm:33 called testapi::send_key_until_needlematch
[2021-03-21T13:07:02.376 CET] [debug] <<< testapi::check_screen(mustmatch="nautilus-Downloads-matched", timeout=1)
[37m[2021-03-21T13:07:02.659 CET] [debug] no match: 0.9s, best candidate: nautilus_cut_file-nautilus-Downloads-matched-20180622 (0.00)
[0m[37m[2021-03-21T13:07:03.594 CET] [debug] no match: -0.1s, best candidate: nautilus_cut_file-nautilus-Downloads-matched-20180622 (0.00)
[0m[32m[2021-03-21T13:07:03.770 CET] [debug] >>> testapi::_check_backend_response: match=nautilus-Downloads-matched timed out after 1 (check_screen)
[0m[2021-03-21T13:07:03.801 CET] [debug] tests/x11/gnomecase/nautilus_cut_file.pm:33 called testapi::send_key_until_needlematch
[2021-03-21T13:07:03.801 CET] [debug] <<< testapi::wait_screen_change(timeout=10, similarity_level=50)
[2021-03-21T13:07:03.802 CET] [debug] tests/x11/gnomecase/nautilus_cut_file.pm:33 called testapi::send_key_until_needlematch
[2021-03-21T13:07:03.802 CET] [debug] <<< testapi::send_key(key="left", wait_screen_change=0, do_wait=0)
[37m[2021-03-21T13:07:04.075 CET] [debug] waiting for screen change: 0 1000000
[0m[37m[2021-03-21T13:07:04.577 CET] [debug] waiting for screen change: 0 23.8566060375104
[0m[32m[2021-03-21T13:07:04.578 CET] [debug] >>> testapi::wait_screen_change: screen change seen at 0
[0m[2021-03-21T13:07:04.578 CET] [debug] tests/x11/gnomecase/nautilus_cut_file.pm:33 called testapi::send_key_until_needlematch
[2021-03-21T13:07:04.578 CET] [debug] <<< testapi::check_screen(mustmatch="nautilus-Downloads-matched", timeout=1)
[32m[2021-03-21T13:07:04.863 CET] [debug] >>> testapi::_handle_found_needle: found nautilus_cut_file-nautilus-Downloads-matched-20200426, similarity 1.00 @ 813/133
[0m[2021-03-21T13:07:04.863 CET] [debug] tests/x11/gnomecase/nautilus_cut_file.pm:34 called testapi::send_key
[2021-03-21T13:07:04.863 CET] [debug] <<< testapi::send_key(key="ret", wait_screen_change=0, do_wait=0)
[2021-03-21T13:07:05.134 CET] [debug] tests/x11/gnomecase/nautilus_cut_file.pm:36 called testapi::send_key
[2021-03-21T13:07:05.135 CET] [debug] <<< testapi::send_key(key="ctrl-v", do_wait=0, wait_screen_change=0)
[2021-03-21T13:07:05.471 CET] [debug] tests/x11/gnomecase/nautilus_cut_file.pm:38 called testapi::assert_screen
[2021-03-21T13:07:05.471 CET] [debug] <<< testapi::assert_screen(mustmatch=[
"nautilus-newfile-moved",
"nautilus-newfile-moved-no-focus"
], timeout=30)
[37m[2021-03-21T13:07:05.881 CET] [debug] no match: 29.8s, best candidate: nautilus-newfile-moved-no-focus-20200426 (0.83)
[0m[32m[2021-03-21T13:07:06.839 CET] [debug] >>> testapi::_handle_found_needle: found nautilus_cut_file-nautilus-newfile-moved_2-20200426, similarity 1.00 @ 102/125
[0m[2021-03-21T13:07:06.840 CET] [debug] tests/x11/gnomecase/nautilus_cut_file.pm:44 called testapi::send_key
[2021-03-21T13:07:06.840 CET] [debug] <<< testapi::send_key(key="alt-up", wait_screen_change=0, do_wait=0)
[2021-03-21T13:07:07.176 CET] [debug] tests/x11/gnomecase/nautilus_cut_file.pm:45 called testapi::assert_screen
[2021-03-21T13:07:07.176 CET] [debug] <<< testapi::assert_screen(mustmatch="nautilus-no-newfile", timeout=30)
[32m[2021-03-21T13:07:08.103 CET] [debug] >>> testapi::_handle_found_needle: found nautilus_cut_file-nautilus-no-newfile-20200426, similarity 1.00 @ 66/198
[0m[2021-03-21T13:07:08.103 CET] [debug] tests/x11/gnomecase/nautilus_cut_file.pm:47 called testapi::send_key
[2021-03-21T13:07:08.104 CET] [debug] <<< testapi::send_key(key="ctrl-w", do_wait=0, wait_screen_change=0)
[2021-03-21T13:07:08.440 CET] [debug] tests/x11/gnomecase/nautilus_cut_file.pm:50 called testapi::x11_start_program
[2021-03-21T13:07:08.440 CET] [debug] <<< testapi::x11_start_program(program="rm Downloads/newfile", valid=0)
[2021-03-21T13:07:08.441 CET] [debug] tests/x11/gnomecase/nautilus_cut_file.pm:50 called testapi::x11_start_program -> lib/susedistribution.pm:265 called susedistribution::init_desktop_runner -> lib/susedistribution.pm:177 called testapi::send_key
[2021-03-21T13:07:08.441 CET] [debug] <<< testapi::send_key(key="alt-f2", wait_screen_change=0, do_wait=0)
[2021-03-21T13:07:08.776 CET] [debug] tests/x11/gnomecase/nautilus_cut_file.pm:50 called testapi::x11_start_program -> lib/susedistribution.pm:265 called susedistribution::init_desktop_runner -> lib/susedistribution.pm:179 called testapi::mouse_hide
[2021-03-21T13:07:08.776 CET] [debug] <<< testapi::mouse_hide(border_offset=200)
[37m[2021-03-21T13:07:08.778 CET] [debug] send_pointer_event 0, 1018, 762, 1
[0m[37m[2021-03-21T13:07:08.778 CET] [debug] mouse_move 1023, 767
[0m[37m[2021-03-21T13:07:08.778 CET] [debug] send_pointer_event 0, 1023, 767, 1
[0m[2021-03-21T13:07:08.779 CET] [debug] tests/x11/gnomecase/nautilus_cut_file.pm:50 called testapi::x11_start_program -> lib/susedistribution.pm:265 called susedistribution::init_desktop_runner -> lib/susedistribution.pm:180 called testapi::check_screen
[2021-03-21T13:07:08.779 CET] [debug] <<< testapi::check_screen(mustmatch="desktop-runner", timeout=30)
[37m[2021-03-21T13:07:09.117 CET] [debug] no match: 29.9s, best candidate: desktop-runner-gnome-3.16+-20150325 (0.00)
[0m[32m[2021-03-21T13:07:10.047 CET] [debug] >>> testapi::_handle_found_needle: found desktop-runner-gnome-3.36+-20200218, similarity 1.00 @ 348/311
[0m[2021-03-21T13:07:10.048 CET] [debug] tests/x11/gnomecase/nautilus_cut_file.pm:50 called testapi::x11_start_program -> lib/susedistribution.pm:265 called susedistribution::init_desktop_runner -> lib/susedistribution.pm:185 called testapi::wait_still_screen
[2021-03-21T13:07:10.048 CET] [debug] <<< testapi::wait_still_screen(similarity_level=47, stilltime=2, timeout=30)
[32m[2021-03-21T13:07:12.068 CET] [debug] >>> testapi::wait_still_screen: detected same image for 2 seconds, last detected similarity is 1000000
[0m[2021-03-21T13:07:12.069 CET] [debug] tests/x11/gnomecase/nautilus_cut_file.pm:50 called testapi::x11_start_program -> lib/susedistribution.pm:265 called susedistribution::init_desktop_runner -> lib/susedistribution.pm:201 called testapi::type_string
[2021-03-21T13:07:12.069 CET] [debug] <<< testapi::type_string(string="rm Downloads/newfile", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2021-03-21T13:07:12.765 CET] [debug] tests/x11/gnomecase/nautilus_cut_file.pm:50 called testapi::x11_start_program -> lib/susedistribution.pm:272 called testapi::wait_still_screen
[2021-03-21T13:07:12.765 CET] [debug] <<< testapi::wait_still_screen(similarity_level=47, stilltime=3, timeout=30)
[32m[2021-03-21T13:07:16.293 CET] [debug] >>> testapi::wait_still_screen: detected same image for 3 seconds, last detected similarity is 1000000
[0m[2021-03-21T13:07:16.411 CET] [debug] tests/x11/gnomecase/nautilus_cut_file.pm:50 called testapi::x11_start_program -> lib/susedistribution.pm:274 called testapi::send_key
[2021-03-21T13:07:16.411 CET] [debug] <<< testapi::send_key(key="ret", wait_screen_change=0, do_wait=0)
[2021-03-21T13:07:16.679 CET] [debug] tests/x11/gnomecase/nautilus_cut_file.pm:50 called testapi::x11_start_program -> lib/susedistribution.pm:277 called testapi::wait_still_screen
[2021-03-21T13:07:16.680 CET] [debug] <<< testapi::wait_still_screen(timeout=30, stilltime=3, similarity_level=45)
[32m[2021-03-21T13:07:19.710 CET] [debug] >>> testapi::wait_still_screen: detected same image for 3 seconds, last detected similarity is 1000000
[0m[2021-03-21T13:07:19.710 CET] [debug] lib/x11test.pm:28 called testapi::assert_screen
[2021-03-21T13:07:19.710 CET] [debug] <<< testapi::assert_screen(mustmatch="generic-desktop", timeout=30)
[32m[2021-03-21T13:07:20.927 CET] [debug] >>> testapi::_handle_found_needle: found consoletest_finish-gnome-TW-20190522, similarity 1.00 @ 0/1
[0m[37m[2021-03-21T13:07:20.931 CET] [debug] ||| finished nautilus_cut_file x11/gnomecase at 2021-03-21 12:07:20 (58 s)
[0m[1;34m[2021-03-21T13:07:20.934 CET] [debug] ||| starting nautilus_permission tests/x11/gnomecase/nautilus_permission.pm
[0m[2021-03-21T13:07:20.935 CET] [debug] tests/x11/gnomecase/nautilus_permission.pm:31 called testapi::x11_start_program
[2021-03-21T13:07:20.935 CET] [debug] <<< testapi::x11_start_program(program="touch newfile", valid=0)
[2021-03-21T13:07:20.935 CET] [debug] tests/x11/gnomecase/nautilus_permission.pm:31 called testapi::x11_start_program -> lib/susedistribution.pm:265 called susedistribution::init_desktop_runner -> lib/susedistribution.pm:177 called testapi::send_key
[2021-03-21T13:07:20.935 CET] [debug] <<< testapi::send_key(key="alt-f2", wait_screen_change=0, do_wait=0)
[2021-03-21T13:07:21.271 CET] [debug] tests/x11/gnomecase/nautilus_permission.pm:31 called testapi::x11_start_program -> lib/susedistribution.pm:265 called susedistribution::init_desktop_runner -> lib/susedistribution.pm:179 called testapi::mouse_hide
[2021-03-21T13:07:21.271 CET] [debug] <<< testapi::mouse_hide(border_offset=200)
[37m[2021-03-21T13:07:21.272 CET] [debug] send_pointer_event 0, 1018, 762, 1
[0m[37m[2021-03-21T13:07:21.272 CET] [debug] mouse_move 1023, 767
[0m[37m[2021-03-21T13:07:21.273 CET] [debug] send_pointer_event 0, 1023, 767, 1
[0m[2021-03-21T13:07:21.273 CET] [debug] tests/x11/gnomecase/nautilus_permission.pm:31 called testapi::x11_start_program -> lib/susedistribution.pm:265 called susedistribution::init_desktop_runner -> lib/susedistribution.pm:180 called testapi::check_screen
[2021-03-21T13:07:21.273 CET] [debug] <<< testapi::check_screen(mustmatch="desktop-runner", timeout=30)
[37m[2021-03-21T13:07:21.548 CET] [debug] no match: 29.9s, best candidate: desktop-runner-gnome-3.16+-20150325 (0.00)
[0m[32m[2021-03-21T13:07:22.511 CET] [debug] >>> testapi::_handle_found_needle: found desktop-runner-gnome-3.36+-20200218, similarity 1.00 @ 348/311
[0m[2021-03-21T13:07:22.512 CET] [debug] tests/x11/gnomecase/nautilus_permission.pm:31 called testapi::x11_start_program -> lib/susedistribution.pm:265 called susedistribution::init_desktop_runner -> lib/susedistribution.pm:185 called testapi::wait_still_screen
[2021-03-21T13:07:22.512 CET] [debug] <<< testapi::wait_still_screen(similarity_level=47, timeout=30, stilltime=2)
[32m[2021-03-21T13:07:24.531 CET] [debug] >>> testapi::wait_still_screen: detected same image for 2 seconds, last detected similarity is 1000000
[0m[2021-03-21T13:07:24.531 CET] [debug] tests/x11/gnomecase/nautilus_permission.pm:31 called testapi::x11_start_program -> lib/susedistribution.pm:265 called susedistribution::init_desktop_runner -> lib/susedistribution.pm:201 called testapi::type_string
[2021-03-21T13:07:24.532 CET] [debug] <<< testapi::type_string(string="touch newfile", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2021-03-21T13:07:24.974 CET] [debug] tests/x11/gnomecase/nautilus_permission.pm:31 called testapi::x11_start_program -> lib/susedistribution.pm:272 called testapi::wait_still_screen
[2021-03-21T13:07:24.974 CET] [debug] <<< testapi::wait_still_screen(timeout=30, stilltime=3, similarity_level=47)
[32m[2021-03-21T13:07:29.005 CET] [debug] >>> testapi::wait_still_screen: detected same image for 3 seconds, last detected similarity is 1000000
[0m[2021-03-21T13:07:29.098 CET] [debug] tests/x11/gnomecase/nautilus_permission.pm:31 called testapi::x11_start_program -> lib/susedistribution.pm:274 called testapi::send_key
[2021-03-21T13:07:29.098 CET] [debug] <<< testapi::send_key(key="ret", do_wait=0, wait_screen_change=0)
[2021-03-21T13:07:29.376 CET] [debug] tests/x11/gnomecase/nautilus_permission.pm:31 called testapi::x11_start_program -> lib/susedistribution.pm:277 called testapi::wait_still_screen
[2021-03-21T13:07:29.376 CET] [debug] <<< testapi::wait_still_screen(similarity_level=45, timeout=30, stilltime=3)
[32m[2021-03-21T13:07:32.900 CET] [debug] >>> testapi::wait_still_screen: detected same image for 3 seconds, last detected similarity is 1000000
[0m[2021-03-21T13:07:32.900 CET] [debug] tests/x11/gnomecase/nautilus_permission.pm:32 called testapi::x11_start_program
[2021-03-21T13:07:32.900 CET] [debug] <<< testapi::x11_start_program(program="nautilus")
[2021-03-21T13:07:32.900 CET] [debug] tests/x11/gnomecase/nautilus_permission.pm:32 called testapi::x11_start_program -> lib/susedistribution.pm:265 called susedistribution::init_desktop_runner -> lib/susedistribution.pm:177 called testapi::send_key
[2021-03-21T13:07:32.900 CET] [debug] <<< testapi::send_key(key="alt-f2", do_wait=0, wait_screen_change=0)
[2021-03-21T13:07:33.236 CET] [debug] tests/x11/gnomecase/nautilus_permission.pm:32 called testapi::x11_start_program -> lib/susedistribution.pm:265 called susedistribution::init_desktop_runner -> lib/susedistribution.pm:179 called testapi::mouse_hide
[2021-03-21T13:07:33.236 CET] [debug] <<< testapi::mouse_hide(border_offset=200)
[37m[2021-03-21T13:07:33.237 CET] [debug] send_pointer_event 0, 1018, 762, 1
[0m[37m[2021-03-21T13:07:33.237 CET] [debug] mouse_move 1023, 767
[0m[37m[2021-03-21T13:07:33.237 CET] [debug] send_pointer_event 0, 1023, 767, 1
[0m[2021-03-21T13:07:33.238 CET] [debug] tests/x11/gnomecase/nautilus_permission.pm:32 called testapi::x11_start_program -> lib/susedistribution.pm:265 called susedistribution::init_desktop_runner -> lib/susedistribution.pm:180 called testapi::check_screen
[2021-03-21T13:07:33.238 CET] [debug] <<< testapi::check_screen(mustmatch="desktop-runner", timeout=30)
[37m[2021-03-21T13:07:33.423 CET] [debug] no match: 29.9s, best candidate: desktop-runner-gnome-3.16+-20150325 (0.00)
[0m[32m[2021-03-21T13:07:34.450 CET] [debug] >>> testapi::_handle_found_needle: found desktop-runner-gnome-3.36+-20200218, similarity 1.00 @ 348/311
[0m[2021-03-21T13:07:34.450 CET] [debug] tests/x11/gnomecase/nautilus_permission.pm:32 called testapi::x11_start_program -> lib/susedistribution.pm:265 called susedistribution::init_desktop_runner -> lib/susedistribution.pm:185 called testapi::wait_still_screen
[2021-03-21T13:07:34.450 CET] [debug] <<< testapi::wait_still_screen(similarity_level=47, timeout=30, stilltime=2)
[32m[2021-03-21T13:07:36.468 CET] [debug] >>> testapi::wait_still_screen: detected same image for 2 seconds, last detected similarity is 1000000
[0m[2021-03-21T13:07:36.468 CET] [debug] tests/x11/gnomecase/nautilus_permission.pm:32 called testapi::x11_start_program -> lib/susedistribution.pm:265 called susedistribution::init_desktop_runner -> lib/susedistribution.pm:201 called testapi::type_string
[2021-03-21T13:07:36.468 CET] [debug] <<< testapi::type_string(string="nautilus", max_interval=250, wait_screen_changes=0, wait_still_screen=0, timeout=30, similarity_level=47)
[2021-03-21T13:07:36.752 CET] [debug] tests/x11/gnomecase/nautilus_permission.pm:32 called testapi::x11_start_program -> lib/susedistribution.pm:272 called testapi::wait_still_screen
[2021-03-21T13:07:36.753 CET] [debug] <<< testapi::wait_still_screen(timeout=30, stilltime=3, similarity_level=47)
[32m[2021-03-21T13:07:40.782 CET] [debug] >>> testapi::wait_still_screen: detected same image for 3 seconds, last detected similarity is 1000000
[0m[2021-03-21T13:07:40.873 CET] [debug] tests/x11/gnomecase/nautilus_permission.pm:32 called testapi::x11_start_program -> lib/susedistribution.pm:274 called testapi::send_key
[2021-03-21T13:07:40.873 CET] [debug] <<< testapi::send_key(key="ret", wait_screen_change=0, do_wait=0)
[2021-03-21T13:07:41.148 CET] [debug] tests/x11/gnomecase/nautilus_permission.pm:32 called testapi::x11_start_program -> lib/susedistribution.pm:283 called testapi::assert_screen
[2021-03-21T13:07:41.149 CET] [debug] <<< testapi::assert_screen(mustmatch=[
"nautilus",
"desktop-runner-border"
], no_wait=0, timeout=30)
[37m[2021-03-21T13:07:41.457 CET] [debug] no match: 29.9s, best candidate: nautilus-1-leap150-20171112 (0.00)
[0m[37m[2021-03-21T13:07:42.214 CET] [debug] no match: 28.9s, best candidate: test-nautilus-1-20190502 (0.95)
[0m[32m[2021-03-21T13:07:43.353 CET] [debug] >>> testapi::_handle_found_needle: found test-nautilus-1-20200422, similarity 1.00 @ 71/124
[0m[2021-03-21T13:07:43.353 CET] [debug] tests/x11/gnomecase/nautilus_permission.pm:33 called testapi::send_key_until_needlematch
[2021-03-21T13:07:43.353 CET] [debug] <<< testapi::check_screen(mustmatch="nautilus-newfile-matched", timeout=1)
[37m[2021-03-21T13:07:44.455 CET] [debug] no match: 0.2s, best candidate: nautilus_cut_file-nautilus-newfile-matched-20180622 (0.00)
[0m[37m[2021-03-21T13:07:45.466 CET] [debug] no match: -0.8s, best candidate: nautilus_cut_file-nautilus-newfile-matched-20180622 (0.00)
[0m[32m[2021-03-21T13:07:45.710 CET] [debug] >>> testapi::_check_backend_response: match=nautilus-newfile-matched timed out after 1 (check_screen)
[0m[2021-03-21T13:07:45.754 CET] [debug] tests/x11/gnomecase/nautilus_permission.pm:33 called testapi::send_key_until_needlematch
[2021-03-21T13:07:45.755 CET] [debug] <<< testapi::wait_screen_change(timeout=10, similarity_level=50)
[2021-03-21T13:07:45.756 CET] [debug] tests/x11/gnomecase/nautilus_permission.pm:33 called testapi::send_key_until_needlematch
[2021-03-21T13:07:45.756 CET] [debug] <<< testapi::send_key(key="right", wait_screen_change=0, do_wait=0)
[37m[2021-03-21T13:07:46.026 CET] [debug] waiting for screen change: 0 1000000
[0m[37m[2021-03-21T13:07:46.531 CET] [debug] waiting for screen change: 0 1000000
[0m[37m[2021-03-21T13:07:47.035 CET] [debug] waiting for screen change: 1 1000000
[0m[37m[2021-03-21T13:07:47.539 CET] [debug] waiting for screen change: 1 1000000
[0m[37m[2021-03-21T13:07:48.043 CET] [debug] waiting for screen change: 2 45.5816898281825
[0m[32m[2021-03-21T13:07:48.043 CET] [debug] >>> testapi::wait_screen_change: screen change seen at 2
[0m[2021-03-21T13:07:48.043 CET] [debug] tests/x11/gnomecase/nautilus_permission.pm:33 called testapi::send_key_until_needlematch
[2021-03-21T13:07:48.044 CET] [debug] <<< testapi::check_screen(mustmatch="nautilus-newfile-matched", timeout=1)
[37m[2021-03-21T13:07:48.361 CET] [debug] no match: 0.9s, best candidate: nautilus_cut_file-nautilus-newfile-matched-20180622 (0.00)
[0m[37m[2021-03-21T13:07:49.405 CET] [debug] no match: -0.1s, best candidate: nautilus_cut_file-nautilus-newfile-matched-20180622 (0.00)
[0m[32m[2021-03-21T13:07:49.662 CET] [debug] >>> testapi::_check_backend_response: match=nautilus-newfile-matched timed out after 1 (check_screen)
[0m[2021-03-21T13:07:49.705 CET] [debug] tests/x11/gnomecase/nautilus_permission.pm:33 called testapi::send_key_until_needlematch
[2021-03-21T13:07:49.705 CET] [debug] <<< testapi::wait_screen_change(timeout=10, similarity_level=50)
[2021-03-21T13:07:49.707 CET] [debug] tests/x11/gnomecase/nautilus_permission.pm:33 called testapi::send_key_until_needlematch
[2021-03-21T13:07:49.707 CET] [debug] <<< testapi::send_key(key="right", wait_screen_change=0, do_wait=0)
[37m[2021-03-21T13:07:49.979 CET] [debug] waiting for screen change: 0 1000000
[0m[37m[2021-03-21T13:07:50.483 CET] [debug] waiting for screen change: 1 27.6256879952047
[0m[32m[2021-03-21T13:07:50.483 CET] [debug] >>> testapi::wait_screen_change: screen change seen at 1
[0m[2021-03-21T13:07:50.483 CET] [debug] tests/x11/gnomecase/nautilus_permission.pm:33 called testapi::send_key_until_needlematch
[2021-03-21T13:07:50.483 CET] [debug] <<< testapi::check_screen(mustmatch="nautilus-newfile-matched", timeout=1)
[37m[2021-03-21T13:07:50.836 CET] [debug] no match: 0.9s, best candidate: nautilus_cut_file-nautilus-newfile-matched-20180622 (0.00)
[0m[37m[2021-03-21T13:07:51.849 CET] [debug] no match: -0.1s, best candidate: nautilus_cut_file-nautilus-newfile-matched-20180622 (0.00)
[0m[32m[2021-03-21T13:07:52.073 CET] [debug] >>> testapi::_check_backend_response: match=nautilus-newfile-matched timed out after 1 (check_screen)
[0m[2021-03-21T13:07:52.111 CET] [debug] tests/x11/gnomecase/nautilus_permission.pm:33 called testapi::send_key_until_needlematch
[2021-03-21T13:07:52.111 CET] [debug] <<< testapi::wait_screen_change(timeout=10, similarity_level=50)
[2021-03-21T13:07:52.112 CET] [debug] tests/x11/gnomecase/nautilus_permission.pm:33 called testapi::send_key_until_needlematch
[2021-03-21T13:07:52.112 CET] [debug] <<< testapi::send_key(key="right", do_wait=0, wait_screen_change=0)
[37m[2021-03-21T13:07:52.385 CET] [debug] waiting for screen change: 0 1000000
[0m[37m[2021-03-21T13:07:52.888 CET] [debug] waiting for screen change: 0 24.209925066958
[0m[32m[2021-03-21T13:07:52.888 CET] [debug] >>> testapi::wait_screen_change: screen change seen at 0
[0m[2021-03-21T13:07:52.889 CET] [debug] tests/x11/gnomecase/nautilus_permission.pm:33 called testapi::send_key_until_needlematch
[2021-03-21T13:07:52.889 CET] [debug] <<< testapi::check_screen(mustmatch="nautilus-newfile-matched", timeout=1)
[37m[2021-03-21T13:07:53.184 CET] [debug] no match: 0.9s, best candidate: nautilus_cut_file-nautilus-newfile-matched-20180622 (0.00)
[0m[37m[2021-03-21T13:07:54.249 CET] [debug] no match: -0.1s, best candidate: nautilus_cut_file-nautilus-newfile-matched-20180622 (0.00)
[0m[32m[2021-03-21T13:07:54.491 CET] [debug] >>> testapi::_check_backend_response: match=nautilus-newfile-matched timed out after 1 (check_screen)
[0m[2021-03-21T13:07:54.518 CET] [debug] tests/x11/gnomecase/nautilus_permission.pm:33 called testapi::send_key_until_needlematch
[2021-03-21T13:07:54.518 CET] [debug] <<< testapi::wait_screen_change(timeout=10, similarity_level=50)
[2021-03-21T13:07:54.519 CET] [debug] tests/x11/gnomecase/nautilus_permission.pm:33 called testapi::send_key_until_needlematch
[2021-03-21T13:07:54.519 CET] [debug] <<< testapi::send_key(key="right", do_wait=0, wait_screen_change=0)
[37m[2021-03-21T13:07:54.790 CET] [debug] waiting for screen change: 0 1000000
[0m[37m[2021-03-21T13:07:55.294 CET] [debug] waiting for screen change: 1 23.7116059699355
[0m[32m[2021-03-21T13:07:55.294 CET] [debug] >>> testapi::wait_screen_change: screen change seen at 1
[0m[2021-03-21T13:07:55.295 CET] [debug] tests/x11/gnomecase/nautilus_permission.pm:33 called testapi::send_key_until_needlematch
[2021-03-21T13:07:55.295 CET] [debug] <<< testapi::check_screen(mustmatch="nautilus-newfile-matched", timeout=1)
[37m[2021-03-21T13:07:55.606 CET] [debug] no match: 0.9s, best candidate: nautilus_cut_file-nautilus-newfile-matched-20180622 (0.00)
[0m[37m[2021-03-21T13:07:56.679 CET] [debug] no match: -0.1s, best candidate: nautilus_cut_file-nautilus-newfile-matched-20180622 (0.00)
[0m[32m[2021-03-21T13:07:56.878 CET] [debug] >>> testapi::_check_backend_response: match=nautilus-newfile-matched timed out after 1 (check_screen)
[0m[2021-03-21T13:07:56.904 CET] [debug] tests/x11/gnomecase/nautilus_permission.pm:33 called testapi::send_key_until_needlematch
[2021-03-21T13:07:56.904 CET] [debug] <<< testapi::wait_screen_change(timeout=10, similarity_level=50)
[2021-03-21T13:07:56.905 CET] [debug] tests/x11/gnomecase/nautilus_permission.pm:33 called testapi::send_key_until_needlematch
[2021-03-21T13:07:56.905 CET] [debug] <<< testapi::send_key(key="right", wait_screen_change=0, do_wait=0)
[37m[2021-03-21T13:07:57.177 CET] [debug] waiting for screen change: 0 1000000
[0m[37m[2021-03-21T13:07:57.680 CET] [debug] waiting for screen change: 0 23.5484733270691
[0m[32m[2021-03-21T13:07:57.680 CET] [debug] >>> testapi::wait_screen_change: screen change seen at 0
[0m[2021-03-21T13:07:57.680 CET] [debug] tests/x11/gnomecase/nautilus_permission.pm:33 called testapi::send_key_until_needlematch
[2021-03-21T13:07:57.680 CET] [debug] <<< testapi::check_screen(mustmatch="nautilus-newfile-matched", timeout=1)
[37m[2021-03-21T13:07:57.901 CET] [debug] no match: 0.9s, best candidate: nautilus_cut_file-nautilus-newfile-matched-20180622 (0.00)
[0m[37m[2021-03-21T13:07:59.039 CET] [debug] no match: -0.1s, best candidate: nautilus_cut_file-nautilus-newfile-matched-20180622 (0.00)
[0m[32m[2021-03-21T13:07:59.271 CET] [debug] >>> testapi::_check_backend_response: match=nautilus-newfile-matched timed out after 1 (check_screen)
[0m[2021-03-21T13:07:59.301 CET] [debug] tests/x11/gnomecase/nautilus_permission.pm:33 called testapi::send_key_until_needlematch
[2021-03-21T13:07:59.301 CET] [debug] <<< testapi::wait_screen_change(timeout=10, similarity_level=50)
[2021-03-21T13:07:59.302 CET] [debug] tests/x11/gnomecase/nautilus_permission.pm:33 called testapi::send_key_until_needlematch
[2021-03-21T13:07:59.302 CET] [debug] <<< testapi::send_key(key="right", wait_screen_change=0, do_wait=0)
[37m[2021-03-21T13:07:59.575 CET] [debug] waiting for screen change: 0 1000000
[0m[37m[2021-03-21T13:08:00.077 CET] [debug] waiting for screen change: 1 23.8566060375104
[0m[32m[2021-03-21T13:08:00.077 CET] [debug] >>> testapi::wait_screen_change: screen change seen at 1
[0m[2021-03-21T13:08:00.078 CET] [debug] tests/x11/gnomecase/nautilus_permission.pm:33 called testapi::send_key_until_needlematch
[2021-03-21T13:08:00.078 CET] [debug] <<< testapi::check_screen(mustmatch="nautilus-newfile-matched", timeout=1)
[37m[2021-03-21T13:08:00.343 CET] [debug] no match: 0.9s, best candidate: nautilus_cut_file-nautilus-newfile-matched-20180622 (0.00)
[0m[37m[2021-03-21T13:08:01.311 CET] [debug] no match: -0.1s, best candidate: nautilus_cut_file-nautilus-newfile-matched-20180622 (0.00)
[0m[32m[2021-03-21T13:08:01.477 CET] [debug] >>> testapi::_check_backend_response: match=nautilus-newfile-matched timed out after 1 (check_screen)
[0m[2021-03-21T13:08:01.514 CET] [debug] tests/x11/gnomecase/nautilus_permission.pm:33 called testapi::send_key_until_needlematch
[2021-03-21T13:08:01.514 CET] [debug] <<< testapi::wait_screen_change(timeout=10, similarity_level=50)
[2021-03-21T13:08:01.515 CET] [debug] tests/x11/gnomecase/nautilus_permission.pm:33 called testapi::send_key_until_needlematch
[2021-03-21T13:08:01.516 CET] [debug] <<< testapi::send_key(key="right", wait_screen_change=0, do_wait=0)
[37m[2021-03-21T13:08:01.787 CET] [debug] waiting for screen change: 0 1000000
[0m[37m[2021-03-21T13:08:02.290 CET] [debug] waiting for screen change: 1 23.584297989199
[0m[32m[2021-03-21T13:08:02.290 CET] [debug] >>> testapi::wait_screen_change: screen change seen at 1
[0m[2021-03-21T13:08:02.290 CET] [debug] tests/x11/gnomecase/nautilus_permission.pm:33 called testapi::send_key_until_needlematch
[2021-03-21T13:08:02.290 CET] [debug] <<< testapi::check_screen(mustmatch="nautilus-newfile-matched", timeout=1)
[32m[2021-03-21T13:08:02.608 CET] [debug] >>> testapi::_handle_found_needle: found nautilus_cut_file-nautilus-newfile-matched-20200426, similarity 1.00 @ 475/263
[0m[2021-03-21T13:08:02.609 CET] [debug] tests/x11/gnomecase/nautilus_permission.pm:35 called testapi::assert_and_click
[2021-03-21T13:08:02.609 CET] [debug] <<< testapi::assert_screen(mustmatch="nautilus-newfile-matched", timeout=30)
[32m[2021-03-21T13:08:03.416 CET] [debug] >>> testapi::_handle_found_needle: found nautilus_cut_file-nautilus-newfile-matched-20200426, similarity 1.00 @ 475/263
[0m[2021-03-21T13:08:03.416 CET] [debug] tests/x11/gnomecase/nautilus_permission.pm:35 called testapi::assert_and_click
[2021-03-21T13:08:03.416 CET] [debug] <<< testapi::assert_and_click(mustmatch="nautilus-newfile-matched", button="right", timeout=30)
[37m[2021-03-21T13:08:03.418 CET] [debug] clicking at 519/327
[0m[2021-03-21T13:08:03.418 CET] [debug] tests/x11/gnomecase/nautilus_permission.pm:35 called testapi::assert_and_click
[2021-03-21T13:08:03.418 CET] [debug] <<< testapi::mouse_set(x=519, y=327)
[37m[2021-03-21T13:08:03.419 CET] [debug] mouse_move 519, 327
[0m[37m[2021-03-21T13:08:03.419 CET] [debug] send_pointer_event 0, 519, 327, 1
[0m[2021-03-21T13:08:03.420 CET] [debug] tests/x11/gnomecase/nautilus_permission.pm:35 called testapi::assert_and_click
[2021-03-21T13:08:03.420 CET] [debug] <<< testapi::mouse_click(button="right", cursor_down="0.15")
[37m[2021-03-21T13:08:03.421 CET] [debug] pointer_event 4 519, 327
[0m[37m[2021-03-21T13:08:03.421 CET] [debug] send_pointer_event 4, 519, 327, 1
[0m[37m[2021-03-21T13:08:03.572 CET] [debug] pointer_event 0 519, 327
[0m[37m[2021-03-21T13:08:03.572 CET] [debug] send_pointer_event 0, 519, 327, 1
[0m[2021-03-21T13:08:04.573 CET] [debug] tests/x11/gnomecase/nautilus_permission.pm:35 called testapi::assert_and_click
[2021-03-21T13:08:04.573 CET] [debug] <<< testapi::mouse_set(x=1023, y=767)
[37m[2021-03-21T13:08:04.574 CET] [debug] mouse_move 1023, 767
[0m[37m[2021-03-21T13:08:04.574 CET] [debug] send_pointer_event 0, 1023, 767, 1
[0m[2021-03-21T13:08:04.574 CET] [debug] tests/x11/gnomecase/nautilus_permission.pm:36 called testapi::record_soft_failure
[2021-03-21T13:08:04.575 CET] [debug] <<< testapi::record_soft_failure(reason="boo#1074057 qemu can not properly capture some keys in nautilus under GNOME wayland")
[2021-03-21T13:08:04.575 CET] [debug] tests/x11/gnomecase/nautilus_permission.pm:41 called testapi::assert_screen
[2021-03-21T13:08:04.575 CET] [debug] <<< testapi::assert_screen(mustmatch="nautilus-rightkey-menu", timeout=30)
[32m[2021-03-21T13:08:04.839 CET] [debug] >>> testapi::_handle_found_needle: found nautilus_permission-nautilus-rightkey-menu-20200426, similarity 1.00 @ 535/389
[0m[2021-03-21T13:08:04.839 CET] [debug] tests/x11/gnomecase/nautilus_permission.pm:42 called testapi::send_key
[2021-03-21T13:08:04.839 CET] [debug] <<< testapi::send_key(key="r", wait_screen_change=0, do_wait=0)
[2021-03-21T13:08:05.108 CET] [debug] tests/x11/gnomecase/nautilus_permission.pm:43 called testapi::assert_screen
[2021-03-21T13:08:05.108 CET] [debug] <<< testapi::assert_screen(mustmatch="nautilus-properties", timeout=30)
[32m[2021-03-21T13:08:06.030 CET] [debug] >>> testapi::_handle_found_needle: found nautilus_permission-nautilus-properties-20201120, similarity 1.00 @ 316/168
[0m[2021-03-21T13:08:06.030 CET] [debug] tests/x11/gnomecase/nautilus_permission.pm:44 called testapi::send_key
[2021-03-21T13:08:06.031 CET] [debug] <<< testapi::send_key(key="up", do_wait=0, wait_screen_change=0)
[2021-03-21T13:08:06.299 CET] [debug] tests/x11/gnomecase/nautilus_permission.pm:47 called testapi::send_key
[2021-03-21T13:08:06.300 CET] [debug] <<< testapi::send_key(key="up", wait_screen_change=0, do_wait=0)
[2021-03-21T13:08:06.568 CET] [debug] tests/x11/gnomecase/nautilus_permission.pm:48 called testapi::send_key
[2021-03-21T13:08:06.568 CET] [debug] <<< testapi::send_key(key="right", do_wait=0, wait_screen_change=0)
[2021-03-21T13:08:06.837 CET] [debug] tests/x11/gnomecase/nautilus_permission.pm:49 called testapi::send_key
[2021-03-21T13:08:06.837 CET] [debug] <<< testapi::send_key(key="tab", wait_screen_change=0, do_wait=0)
[2021-03-21T13:08:07.108 CET] [debug] tests/x11/gnomecase/nautilus_permission.pm:49 called testapi::send_key
[2021-03-21T13:08:07.108 CET] [debug] <<< testapi::send_key(key="tab", do_wait=0, wait_screen_change=0)
[2021-03-21T13:08:07.377 CET] [debug] tests/x11/gnomecase/nautilus_permission.pm:49 called testapi::send_key
[2021-03-21T13:08:07.377 CET] [debug] <<< testapi::send_key(key="tab", wait_screen_change=0, do_wait=0)
[2021-03-21T13:08:07.646 CET] [debug] tests/x11/gnomecase/nautilus_permission.pm:49 called testapi::send_key