[2023-07-11T11:50:19.702359+03:00] [info] +++ setup notes +++
[2023-07-11T11:50:19.703330+03:00] [info] Running on server-10-1-x86-64-minimal-20230706.localdomain:1 (Linux 6.1.37-std-def-alt1 #1 SMP PREEMPT_DYNAMIC Sat Jul 1 15:16:07 UTC 2023 x86_64)
[2023-07-11T11:50:19.724175+03:00] [debug] +++ worker notes +++
[2023-07-11T11:50:20.360197+03:00] [debug] [pid:89677] Current version is unknown [interface v38]
[2023-07-11T11:50:20.400450+03:00] [debug] [pid:89677] git hash in kworkstation: ee116389803f6727f0483f9ce869641f42cade38
given is experimental at kworkstation/lib/x11_console.pm line 33.
when is experimental at kworkstation/lib/x11_console.pm line 34.
when is experimental at kworkstation/lib/x11_console.pm line 43.
when is experimental at kworkstation/lib/x11_console.pm line 56.
Use of uninitialized value $home in string ne at /usr/share/perl5/Inline.pm line 1375.
Subroutine new redefined at kworkstation/lib/altdistribution.pm line 24.
Subroutine init redefined at kworkstation/lib/altdistribution.pm line 31.
Subroutine x11_start_program redefined at kworkstation/lib/altdistribution.pm line 37.
Subroutine init_consoles redefined at kworkstation/lib/altdistribution.pm line 55.
Subroutine script_run redefined at kworkstation/lib/altdistribution.pm line 66.
Subroutine default_virtual_login redefined at kworkstation/lib/altdistribution.pm line 109.
Subroutine default_tty_login redefined at kworkstation/lib/altdistribution.pm line 117.
Subroutine activate_console redefined at kworkstation/lib/altdistribution.pm line 125.
Subroutine console_selected redefined at kworkstation/lib/altdistribution.pm line 142.
Subroutine become_root redefined at kworkstation/lib/altdistribution.pm line 162.
Subroutine script_sudo redefined at kworkstation/lib/altdistribution.pm line 201.
Subroutine ensure_installed redefined at kworkstation/lib/altdistribution.pm line 253.
[2023-07-11T11:50:20.687303+03:00] [debug] [pid:89677] scheduling t01_update_system /tests/plasma5-breeze/t01_update_system.py
Subroutine t02_plasma5_breeze_theme::run redefined at (eval 199) line 1.
Subroutine t02_plasma5_breeze_theme::test_flags redefined at (eval 200) line 1.
[2023-07-11T11:50:20.693420+03:00] [debug] [pid:89677] scheduling t02_plasma5_breeze_theme /tests/plasma5-breeze/t02_plasma5_breeze_theme.py
Subroutine t03_plasma5_breeze_twilight_theme::run redefined at (eval 208) line 1.
Subroutine t03_plasma5_breeze_twilight_theme::test_flags redefined at (eval 209) line 1.
[2023-07-11T11:50:20.698606+03:00] [debug] [pid:89677] scheduling t03_plasma5_breeze_twilight_theme /tests/plasma5-breeze/t03_plasma5_breeze_twilight_theme.py
Subroutine t04_plasma5_breeze_dark_theme::run redefined at (eval 217) line 1.
Subroutine t04_plasma5_breeze_dark_theme::test_flags redefined at (eval 218) line 1.
[2023-07-11T11:50:20.703296+03:00] [debug] [pid:89677] scheduling t04_plasma5_breeze_dark_theme /tests/plasma5-breeze/t04_plasma5_breeze_dark_theme.py
[2023-07-11T11:50:20.721531+03:00] [info] [pid:89692] cmdsrv: daemon reachable under http://*:20013/5S1nVYrywY7BNu52/
[2023-07-11T11:50:20.726880+03:00] [info] [pid:89692] Listening at "http://[::]:20013"
Web application available at http://[::]:20013
[2023-07-11T11:50:20.742854+03:00] [debug] [pid:89677] git hash in kworkstation/needles: ee116389803f6727f0483f9ce869641f42cade38
[2023-07-11T11:50:20.743311+03:00] [debug] [pid:89677] init needles from kworkstation/needles
[2023-07-11T11:50:20.887182+03:00] [debug] [pid:89677] loaded 979 needles
[2023-07-11T11:50:21.037322+03:00] [debug] [pid:89677] 89677: channel_out 15, channel_in 14
[2023-07-11T11:50:21.111648+03:00] [debug] [pid:89715] 89715: cmdpipe 13, rsppipe 16
[2023-07-11T11:50:21.111859+03:00] [debug] [pid:89715] started mgmt loop with pid 89715
[2023-07-11T11:50:21.169173+03:00] [debug] [pid:89715] qemu version detected: 8.0.0
[2023-07-11T11:50:21.173486+03:00] [debug] [pid:89715] running `/usr/bin/chattr +C /var/lib/openqa/pool/1/raid`
[2023-07-11T11:50:21.190066+03:00] [debug] [pid:89715] Command `/usr/bin/chattr +C /var/lib/openqa/pool/1/raid` terminated with 1
/usr/bin/chattr: Operation not supported while setting flags on /var/lib/openqa/pool/1/raid
[2023-07-11T11:50:21.190431+03:00] [debug] [pid:89715] Configuring storage controllers and block devices
[2023-07-11T11:50:21.191905+03:00] [debug] [pid:89715] running `/usr/bin/qemu-img info --output=json /var/lib/openqa/pool/1/alt-kworkstation-10.1-update-x86-64.qcow2`
[2023-07-11T11:50:21.218366+03:00] [debug] [pid:89715] Initializing block device images
[2023-07-11T11:50:21.218963+03:00] [debug] [pid:89715] running `/usr/bin/qemu-img create -f qcow2 -F qcow2 -b /var/lib/openqa/pool/1/alt-kworkstation-10.1-update-x86-64.qcow2 /var/lib/openqa/pool/1/raid/hd0-overlay0 32212254720`
[2023-07-11T11:50:21.253445+03:00] [debug] [pid:89715] Formatting '/var/lib/openqa/pool/1/raid/hd0-overlay0', fmt=qcow2 cluster_size=65536 extended_l2=off compression_type=zlib size=32212254720 backing_file=/var/lib/openqa/pool/1/alt-kworkstation-10.1-update-x86-64.qcow2 backing_fmt=qcow2 lazy_refcounts=off refcount_bits=16
[2023-07-11T11:50:21.253682+03:00] [debug] [pid:89715] init_blockdev_images: Finished creating block devices
[2023-07-11T11:50:21.256663+03:00] [debug] [pid:89715] starting: /usr/bin/qemu-system-x86_64 -device virtio-vga,edid=on,xres=1024,yres=768 -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.fdtypeA=none -m 3072 -cpu qemu64 -netdev user,id=qanet0 -device virtio-net,netdev=qanet0,mac=52:54:00:12:34:56 -object rng-random,filename=/dev/urandom,id=rng0 -device virtio-rng-pci,rng=rng0 -boot order=c -device qemu-xhci -device usb-tablet -smp 1 -enable-kvm -no-shutdown -vnc :91,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 pipe,id=virtio_console_user,path=virtio_console_user,logfile=virtio_console_user.log,logappend=on -device virtconsole,chardev=virtio_console_user,name=org.openqa.console.virtio_console_user -chardev socket,path=qmp_socket,server=on,wait=off,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/1/raid/hd0-overlay0,cache.no-flush=on -blockdev driver=qcow2,node-name=hd0-overlay0,file=hd0-overlay0-file,cache.no-flush=on,discard=unmap -device virtio-blk,id=hd0-device,drive=hd0-overlay0,bootindex=0,serial=hd0
[2023-07-11T11:50:21.266428+03:00] [debug] [pid:89715] Waiting for 0 attempts
[2023-07-11T11:50:22.268085+03:00] [debug] [pid:89715] Waiting for 1 attempts
[2023-07-11T11:50:23.269172+03:00] [debug] [pid:89715] Finished after 2 attempts
[2023-07-11T11:50:23.304363+03:00] [debug] [pid:89715] Establishing VNC connection to localhost:5991
[2023-07-11T11:50:23.363152+03:00] [debug] [pid:89715] pointer type 0 0 640 480 -257
[2023-07-11T11:50:23.363418+03:00] [debug] [pid:89715] led state 0 1 1 -261
[2023-07-11T11:50:23.380006+03:00] [debug] [pid:89715] Start CPU
[2023-07-11T11:50:23.380697+03:00] [debug] [pid:89715] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"36186","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"5991","websocket":false}},"event":"VNC_CONNECTED","timestamp":{"microseconds":306969,"seconds":1689065423}}
[2023-07-11T11:50:23.381003+03:00] [debug] [pid:89715] EVENT {"data":{"client":{"family":"ipv4","host":"127.0.0.1","service":"36186","websocket":false},"server":{"auth":"none","family":"ipv4","host":"0.0.0.0","service":"5991","websocket":false}},"event":"VNC_INITIALIZED","timestamp":{"microseconds":310309,"seconds":1689065423}}
[2023-07-11T11:50:23.381691+03:00] [debug] [pid:89715] EVENT {"event":"RESUME","timestamp":{"microseconds":381037,"seconds":1689065423}}
GOT GO
[2023-07-11T11:50:23.397566+03:00] [debug] [pid:89715] QEMU: QEMU emulator version 8.0.0 (qemu-8.0.0-alt3)
[2023-07-11T11:50:23.397720+03:00] [debug] [pid:89715] QEMU: Copyright (c) 2003-2022 Fabrice Bellard and the QEMU Project developers
[2023-07-11T11:50:23.406936+03:00] [debug] [pid:89700] Snapshots are supported
[2023-07-11T11:50:23.410677+03:00] [debug] [pid:89700] ||| starting t01_update_system /tests/plasma5-breeze/t01_update_system.py
[2023-07-11T11:50:23.415427+03:00] [debug] [pid:89700]
[2023-07-11T11:50:23.416252+03:00] [debug] [pid:89700] <<< testapi::x11_start_program(program="systemsettings")
[2023-07-11T11:50:23.416769+03:00] [debug] [pid:89700] lib/altdistribution.pm:40 called testapi::send_key
[2023-07-11T11:50:23.417034+03:00] [debug] [pid:89700] <<< testapi::send_key(key="alt-f2", wait_screen_change=0)
[2023-07-11T11:50:23.760278+03:00] [debug] [pid:89700] lib/altdistribution.pm:41 called testapi::wait_still_screen
[2023-07-11T11:50:23.760710+03:00] [debug] [pid:89700] <<< testapi::wait_still_screen(stilltime=2, timeout=5, similarity_level=47)
[2023-07-11T11:50:29.146177+03:00] [debug] [pid:89700] >>> testapi::wait_still_screen: wait_still_screen timed out after 5.16230607032776 seconds, last detected similarity is 47.0182047332022
[2023-07-11T11:50:29.146389+03:00] [debug] [pid:89700] lib/altdistribution.pm:42 called testapi::send_key
[2023-07-11T11:50:29.146531+03:00] [debug] [pid:89700] <<< testapi::send_key(key="backspace", wait_screen_change=0)
[2023-07-11T11:50:29.419099+03:00] [debug] [pid:89700] lib/altdistribution.pm:43 called testapi::wait_still_screen
[2023-07-11T11:50:29.419613+03:00] [debug] [pid:89700] <<< testapi::wait_still_screen(stilltime=2, timeout=5, similarity_level=47)
[2023-07-11T11:50:31.459500+03:00] [debug] [pid:89700] >>> testapi::wait_still_screen: detected same image for 2 seconds (2.02708506584167 s elapsed), last detected similarity is 1000000
[2023-07-11T11:50:31.460060+03:00] [debug] [pid:89700] lib/altdistribution.pm:44 called testapi::assert_screen
[2023-07-11T11:50:31.460520+03:00] [debug] [pid:89700] <<< testapi::assert_screen(mustmatch="desktop_runner_kworkstation_KDE", timeout=30)
[2023-07-11T11:50:31.513781+03:00] [debug] [pid:89715] no match: 29.9s, best candidate: desktop_runner_kworkstation_KDE_p10 (0.00)
[2023-07-11T11:50:32.466087+03:00] [debug] [pid:89715] no change: 28.9s
[2023-07-11T11:50:32.476607+03:00] [debug] [pid:89715] no match: 28.9s, best candidate: desktop_runner_kworkstation_KDE_p10 (0.00)
[2023-07-11T11:50:33.467358+03:00] [debug] [pid:89715] no change: 27.9s
[2023-07-11T11:50:33.476196+03:00] [debug] [pid:89715] no match: 27.9s, best candidate: desktop_runner_kworkstation_KDE_p10 (0.00)
[2023-07-11T11:50:34.468137+03:00] [debug] [pid:89715] no change: 26.9s
[2023-07-11T11:50:34.477598+03:00] [debug] [pid:89715] no match: 26.9s, best candidate: desktop_runner_kworkstation_KDE_p10 (0.00)
[2023-07-11T11:50:35.536338+03:00] [debug] [pid:89715] no match: 25.9s, best candidate: desktop_runner_kworkstation_KDE_p10 (0.00)
[2023-07-11T11:50:36.470777+03:00] [debug] [pid:89715] no change: 24.9s
[2023-07-11T11:50:36.481065+03:00] [debug] [pid:89715] no match: 24.9s, best candidate: desktop_runner_kworkstation_KDE_p10 (0.00)
[2023-07-11T11:50:37.472309+03:00] [debug] [pid:89715] no change: 23.9s
[2023-07-11T11:50:37.484262+03:00] [debug] [pid:89715] no match: 23.9s, best candidate: desktop_runner_kworkstation_KDE_p10 (0.00)
[2023-07-11T11:50:38.473178+03:00] [debug] [pid:89715] no change: 22.9s
[2023-07-11T11:50:38.481884+03:00] [debug] [pid:89715] no match: 22.9s, best candidate: desktop_runner_kworkstation_KDE_p10 (0.00)
[2023-07-11T11:50:39.474678+03:00] [debug] [pid:89715] no change: 21.9s
[2023-07-11T11:50:39.483354+03:00] [debug] [pid:89715] no match: 21.9s, best candidate: desktop_runner_kworkstation_KDE_p10 (0.00)
[2023-07-11T11:50:40.544161+03:00] [debug] [pid:89715] no match: 20.9s, best candidate: desktop_runner_kworkstation_KDE_p10 (0.00)
[2023-07-11T11:50:41.477205+03:00] [debug] [pid:89715] no change: 19.9s
[2023-07-11T11:50:41.485865+03:00] [debug] [pid:89715] no match: 19.9s, best candidate: desktop_runner_kworkstation_KDE_p10 (0.00)
[2023-07-11T11:50:42.478295+03:00] [debug] [pid:89715] no change: 18.9s
[2023-07-11T11:50:42.489182+03:00] [debug] [pid:89715] no match: 18.9s, best candidate: desktop_runner_kworkstation_KDE_p10 (0.00)
[2023-07-11T11:50:43.480451+03:00] [debug] [pid:89715] no change: 17.9s
[2023-07-11T11:50:43.489770+03:00] [debug] [pid:89715] no match: 17.9s, best candidate: desktop_runner_kworkstation_KDE_p10 (0.00)
[2023-07-11T11:50:44.484355+03:00] [debug] [pid:89715] no change: 16.9s
[2023-07-11T11:50:44.496363+03:00] [debug] [pid:89715] no match: 16.9s, best candidate: desktop_runner_kworkstation_KDE_p10 (0.00)
[2023-07-11T11:50:45.549303+03:00] [debug] [pid:89715] no match: 15.9s, best candidate: desktop_runner_kworkstation_KDE_p10 (0.00)
[2023-07-11T11:50:46.490068+03:00] [debug] [pid:89715] no change: 14.9s
[2023-07-11T11:50:46.501867+03:00] [debug] [pid:89715] no match: 14.9s, best candidate: desktop_runner_kworkstation_KDE_p10 (0.00)
[2023-07-11T11:50:47.490958+03:00] [debug] [pid:89715] no change: 13.9s
[2023-07-11T11:50:47.507356+03:00] [debug] [pid:89715] no match: 13.9s, best candidate: desktop_runner_kworkstation_KDE_p10 (0.00)
[2023-07-11T11:50:48.488660+03:00] [debug] [pid:89715] no change: 12.9s
[2023-07-11T11:50:48.497342+03:00] [debug] [pid:89715] no match: 12.9s, best candidate: desktop_runner_kworkstation_KDE_p10 (0.00)
[2023-07-11T11:50:49.490582+03:00] [debug] [pid:89715] no change: 11.9s
[2023-07-11T11:50:49.499386+03:00] [debug] [pid:89715] no match: 11.9s, best candidate: desktop_runner_kworkstation_KDE_p10 (0.00)
[2023-07-11T11:50:50.560162+03:00] [debug] [pid:89715] no match: 10.9s, best candidate: desktop_runner_kworkstation_KDE_p10 (0.00)
[2023-07-11T11:50:51.494779+03:00] [debug] [pid:89715] no change: 9.9s
[2023-07-11T11:50:51.505101+03:00] [debug] [pid:89715] no match: 9.9s, best candidate: desktop_runner_kworkstation_KDE_p10 (0.00)
[2023-07-11T11:50:52.496538+03:00] [debug] [pid:89715] no change: 8.9s
[2023-07-11T11:50:52.507764+03:00] [debug] [pid:89715] no match: 8.9s, best candidate: desktop_runner_kworkstation_KDE_p10 (0.00)
[2023-07-11T11:50:53.497070+03:00] [debug] [pid:89715] no change: 7.9s
[2023-07-11T11:50:53.505700+03:00] [debug] [pid:89715] no match: 7.9s, best candidate: desktop_runner_kworkstation_KDE_p10 (0.00)
[2023-07-11T11:50:54.498768+03:00] [debug] [pid:89715] no change: 6.9s
[2023-07-11T11:50:54.507488+03:00] [debug] [pid:89715] no match: 6.9s, best candidate: desktop_runner_kworkstation_KDE_p10 (0.00)
[2023-07-11T11:50:55.586493+03:00] [debug] [pid:89715] no match: 5.9s, best candidate: desktop_runner_kworkstation_KDE_p10 (0.00)
[2023-07-11T11:50:56.496418+03:00] [debug] [pid:89715] no change: 4.9s
[2023-07-11T11:50:56.505181+03:00] [debug] [pid:89715] no match: 4.9s, best candidate: desktop_runner_kworkstation_KDE_p10 (0.00)
[2023-07-11T11:50:57.497806+03:00] [debug] [pid:89715] no change: 3.9s
[2023-07-11T11:50:57.507524+03:00] [debug] [pid:89715] no match: 3.9s, best candidate: desktop_runner_kworkstation_KDE_p10 (0.00)
[2023-07-11T11:50:58.498586+03:00] [debug] [pid:89715] no change: 2.9s
[2023-07-11T11:50:58.507742+03:00] [debug] [pid:89715] no match: 2.9s, best candidate: desktop_runner_kworkstation_KDE_p10 (0.00)
[2023-07-11T11:50:59.499784+03:00] [debug] [pid:89715] no change: 1.9s
[2023-07-11T11:50:59.509538+03:00] [debug] [pid:89715] no match: 1.9s, best candidate: desktop_runner_kworkstation_KDE_p10 (0.00)
[2023-07-11T11:51:00.574412+03:00] [debug] [pid:89715] no match: 0.9s, best candidate: desktop_runner_kworkstation_KDE_p10 (0.00)
[2023-07-11T11:51:01.577363+03:00] [debug] [pid:89715] no match: -0.1s, best candidate: desktop_runner_kworkstation_KDE_p10 (0.00)
[2023-07-11T11:51:01.925006+03:00] [debug] [pid:89700] >>> testapi::_check_backend_response: match=desktop_runner_kworkstation_KDE timed out after 30 (assert_screen)
[2023-07-11T11:51:01.968454+03:00] [info] [pid:89700] ::: basetest::runtest: # Test died: no candidate needle with tag(s) 'desktop_runner_kworkstation_KDE' matched
[2023-07-11T11:51:01.983662+03:00] [debug] [pid:89700] ||| finished t01_update_system breeze (runtime: 38 s)
[2023-07-11T11:51:01.983761+03:00] [debug] [pid:89700] ||| post fail hooks runtime: 0 s
[2023-07-11T11:51:01.984312+03:00] [debug] [pid:89700] stopping overall test execution after a fatal test failure
[2023-07-11T11:51:01.986187+03:00] [debug] [pid:89677] stopping autotest process 89700
[2023-07-11T11:51:01.998331+03:00] [debug] [pid:89677] [autotest] process exited: 0
[2023-07-11T11:51:02.099510+03:00] [debug] [pid:89677] done with autotest process
[2023-07-11T11:51:02.100913+03:00] [debug] [pid:89677] stopping command server 89692 because test execution ended
[2023-07-11T11:51:02.101212+03:00] [debug] [pid:89677] isotovideo: informing websocket clients before stopping command server: http://127.0.0.1:20013/5S1nVYrywY7BNu52/broadcast
[2023-07-11T11:51:02.785744+03:00] [debug] [pid:89677] commands process exited: 0
[2023-07-11T11:51:02.886675+03:00] [debug] [pid:89677] done with command server
[2023-07-11T11:51:02.886876+03:00] [debug] [pid:89677] isotovideo done
[2023-07-11T11:51:02.889925+03:00] [debug] [pid:89715] QEMU status is not 'shutdown', it is 'running'
[2023-07-11T11:51:02.890707+03:00] [debug] [pid:89677] backend shutdown state:
[2023-07-11T11:51:02.892401+03:00] [info] [pid:89715] ::: OpenQA::Qemu::Proc::save_state: Saving QEMU state to qemu_state.json
[2023-07-11T11:51:03.948098+03:00] [debug] [pid:89715] Passing remaining frames to the video encoder
[2023-07-11T11:51:04.030736+03:00] [debug] [pid:89715] Waiting for video encoder to finalize the video
[2023-07-11T11:51:04.031034+03:00] [debug] [pid:89715] The built-in video encoder (pid 89730) terminated
[2023-07-11T11:51:04.032671+03:00] [debug] [pid:89715] QEMU: qemu-system-x86_64: terminating on signal 15 from pid 89715 (/usr/bin/isotovideo: backend)
[2023-07-11T11:51:04.035785+03:00] [debug] [pid:89715] sending magic and exit
[2023-07-11T11:51:04.036832+03:00] [debug] [pid:89677] received magic close
[2023-07-11T11:51:04.048276+03:00] [debug] [pid:89677] backend process exited: 0
[2023-07-11T11:51:04.151192+03:00] [debug] [pid:89677] stopping backend process 89715
[2023-07-11T11:51:04.151405+03:00] [debug] [pid:89677] done with backend process
89677: EXIT 0
[2023-07-11T11:51:04.210978+03:00] [info] Isotovideo exit status: 0
[2023-07-11T11:51:04.250634+03:00] [info] +++ worker notes +++
[2023-07-11T11:51:04.251081+03:00] [info] End time: 2023-07-11 08:51:04
[2023-07-11T11:51:04.251294+03:00] [info] Result: done
[2023-07-11T11:51:04.272489+03:00] [info] Uploading video.ogv
[2023-07-11T11:51:04.337661+03:00] [info] Uploading autoinst-log.txt
At the same time, it writes that it launches the first test but executes the commands of the last test
if (get_var('TEST'), 'plasma5_breeze') {
loadtest('plasma5-breeze/t01_update_system.py');
loadtest('plasma5-breeze/t02_plasma5_breeze_theme.py');
loadtest('plasma5-breeze/t03_plasma5_breeze_twilight_theme.py');
loadtest('plasma5-breeze/t04_plasma5_breeze_dark_theme.py');
}