action #132656
Updated by okurz 10 months ago
## Observation When running Python tests, openQA skips all but the last one. {{collapse(autoinst-log) ~~~ [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 {{collapse(main.pm) ~~~ 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'); } ~~~ }} no problem with perl tests problem only for python tests ## Acceptance criteria - **AC1:** Multiple Python-based test modules are covered by unit tests and working - **AC2:** Confirmed to work on live instance ## Suggestions * Add an automated test in os-autoinst to load two test modules with python * It is still clear from instructions on http://open.qa/docs how python test modules should be created