1 | [2025-06-22T21:39:42.266303Z] [info] +++ setup notes +++ |
2 | [2025-06-22T21:39:42.267616Z] [info] Running on openqa-p09-worker01.iad2.fedoraproject.org:7 (Linux 6.14.6-300.fc42.ppc64le #1 SMP Fri May 9 19:45:15 UTC 2025 ppc64le) |
3 | [2025-06-22T21:39:42.287024Z] [debug] +++ worker notes +++ |
4 | [2025-06-22T21:39:43.111696Z] [debug] [pid:3976291] Current version is 5 [interface v44] |
5 | [2025-06-22T21:39:43.129106Z] [debug] [pid:3976291] git hash in 'fedora': e2f89158268bd7c360bf4500ea2953902c2784ec |
6 | [2025-06-22T21:39:43.145517Z] [debug] [pid:3976291] git url in 'fedora': "https://pagure.io/fedora-qa/os-autoinst-distri-fedora.git" |
7 | Smartmatch is deprecated at fedora/main.pm line 204. |
8 | [2025-06-22T21:39:43.200448Z] [debug] [pid:3976291] scheduling _console_wait_login tests/_console_wait_login.pm |
9 | [2025-06-22T21:39:43.204672Z] [debug] [pid:3976291] scheduling _post_network_static tests/_post_network_static.pm |
10 | [2025-06-22T21:39:43.206511Z] [debug] [pid:3976291] scheduling _advisory_update tests/_advisory_update.pm |
11 | [2025-06-22T21:39:43.208299Z] [debug] [pid:3976291] scheduling _console_wait_login_2 tests/_console_wait_login_2.pm |
12 | [2025-06-22T21:39:43.210251Z] [debug] [pid:3976291] scheduling server_remote_logging_server tests/server_remote_logging_server.pm |
13 | [2025-06-22T21:39:43.212013Z] [debug] [pid:3976291] scheduling _advisory_post tests/_advisory_post.pm |
14 | [2025-06-22T21:39:43.220578Z] [info] [pid:3976316] cmdsrv: daemon reachable under http://*:20073/abIgiZXltTnoUdfi/ |
15 | [2025-06-22T21:39:43.222200Z] [debug] [pid:3976291] git hash in 'fedora/needles': e2f89158268bd7c360bf4500ea2953902c2784ec |
16 | [2025-06-22T21:39:43.222390Z] [debug] [pid:3976291] git url in 'fedora/needles': "UNKNOWN (no .git found)" |
17 | [2025-06-22T21:39:43.222462Z] [info] [pid:3976316] Listening at "http://[::]:20073" |
18 | [2025-06-22T21:39:43.222537Z] [debug] [pid:3976291] init needles from fedora/needles |
19 | Web application available at http://[::]:20073 |
20 | [2025-06-22T21:39:49.544636Z] [debug] [pid:3976291] loaded 3683 needles |
21 | [2025-06-22T21:39:49.792088Z] [debug] [pid:3976291] 3976291: channel_out 15, channel_in 14 |
22 | [2025-06-22T21:39:49.978784Z] [debug] [pid:3976728] 3976728: cmdpipe 13, rsppipe 16 |
23 | [2025-06-22T21:39:49.978972Z] [debug] [pid:3976728] started mgmt loop with pid 3976728 |
24 | [2025-06-22T21:39:50.256002Z] [debug] [pid:3976728] Launching external video encoder: ffmpeg -y -hide_banner -nostats -r 24 -f image2pipe -vcodec ppm -i - -pix_fmt yuv420p -c:v libsvtav1 -crf 50 -preset 7 'video.webm' |
25 | [2025-06-22T21:39:50.296216Z] [debug] [pid:3976728] qemu version detected: 9.2.4 |
26 | [2025-06-22T21:39:50.298043Z] [debug] [pid:3976728] running `/usr/bin/chattr +C /var/lib/openqa/pool/7/raid` |
27 | [2025-06-22T21:39:50.305347Z] [debug] [pid:3976728] Command `/usr/bin/chattr +C /var/lib/openqa/pool/7/raid` terminated with 0 |
28 | [2025-06-22T21:39:50.305481Z] [debug] [pid:3976728] Configuring storage controllers and block devices |
29 | [2025-06-22T21:39:50.306012Z] [debug] [pid:3976728] running `/usr/bin/qemu-img info --output=json /var/lib/openqa/pool/7/disk_f43_server_5_ppc64le.qcow2` |
30 | [2025-06-22T21:39:50.319461Z] [debug] [pid:3976728] Initializing block device images |
31 | [2025-06-22T21:39:50.319741Z] [debug] [pid:3976728] running `/usr/bin/qemu-img create -f qcow2 -F qcow2 -b /var/lib/openqa/pool/7/disk_f43_server_5_ppc64le.qcow2 /var/lib/openqa/pool/7/raid/hd0-overlay0 9663676416` |
32 | [2025-06-22T21:39:52.118025Z] [debug] [pid:3976728] Formatting '/var/lib/openqa/pool/7/raid/hd0-overlay0', fmt=qcow2 cluster_size=65536 extended_l2=off compression_type=zlib size=9663676416 backing_file=/var/lib/openqa/pool/7/disk_f43_server_5_ppc64le.qcow2 backing_fmt=qcow2 lazy_refcounts=off refcount_bits=16 |
33 | [2025-06-22T21:39:52.118217Z] [debug] [pid:3976728] running `/usr/bin/qemu-img create -f qcow2 /var/lib/openqa/pool/7/raid/hd1 10G` |
34 | [2025-06-22T21:39:52.900582Z] [debug] [pid:3976728] Formatting '/var/lib/openqa/pool/7/raid/hd1', fmt=qcow2 cluster_size=65536 extended_l2=off compression_type=zlib size=10737418240 lazy_refcounts=off refcount_bits=16 |
35 | [2025-06-22T21:39:52.900766Z] [debug] [pid:3976728] init_blockdev_images: Finished creating block devices |
36 | [2025-06-22T21:39:52.902978Z] [debug] [pid:3976728] starting: /usr/bin/qemu-system-ppc64 -device VGA,edid=on,xres=1024,yres=768 -g 1024x768 -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 4096 -machine usb=off -cpu host -netdev tap,id=qanet0,ifname=tap6,script=no,downscript=no -device virtio-net,netdev=qanet0,mac=52:54:00:12:00:e5 -object rng-random,filename=/dev/urandom,id=rng0 -device virtio-rng-pci,rng=rng0 -boot order=c -device nec-usb-xhci -device usb-tablet -device usb-kbd -smp 1 -enable-kvm -no-shutdown -vnc :97,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/7/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 -blockdev driver=file,node-name=hd1-file,filename=/var/lib/openqa/pool/7/raid/hd1,cache.no-flush=on -blockdev driver=qcow2,node-name=hd1,file=hd1-file,cache.no-flush=on,discard=unmap -device virtio-blk,id=hd1-device,drive=hd1,serial=hd1 |
37 | [2025-06-22T21:39:52.909470Z] [debug] [pid:3976728] Waiting for 0 attempts |
38 | [2025-06-22T21:39:53.911041Z] [debug] [pid:3976728] Waiting for 1 attempts |
39 | [2025-06-22T21:39:54.912017Z] [debug] [pid:3976728] Finished after 2 attempts |
40 | [2025-06-22T21:39:54.935386Z] [debug] [pid:3976728] Establishing VNC connection to localhost:5997 |
41 | [2025-06-22T21:39:54.987775Z] [debug] [pid:3976728] pointer type 1 0 640 480 -257 |
42 | [2025-06-22T21:39:54.987894Z] [debug] [pid:3976728] led state 0 1 1 -261 |
43 | [2025-06-22T21:39:54.996495Z] [info] [pid:3976728] ::: backend::baseclass::die_handler: Backend process died, backend errors are reported below in the following lines: |
44 | Open vSwitch command 'set_vlan' with arguments 'tap6 333' failed: org.freedesktop.DBus.Error.NoReply: Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken. |
45 | |
46 | [2025-06-22T21:39:54.996849Z] [info] [pid:3976728] ::: OpenQA::Qemu::Proc::save_state: Saving QEMU state to qemu_state.json |
47 | [2025-06-22T21:39:56.092968Z] [debug] [pid:3976728] Passing remaining frames to the video encoder |
48 | Input #0, image2pipe, from 'fd:': |
49 | Duration: N/A, bitrate: N/A |
50 | Stream #0:0: Video: ppm, rgb24, 1024x768, 24 fps, 24 tbr, 24 tbn |
51 | Stream mapping: |
52 | Stream #0:0 -> #0:0 (ppm (native) -> av1 (libsvtav1)) |
53 | Svt[info]: ------------------------------------------- |
54 | Svt[info]: SVT [version]: SVT-AV1 Encoder Lib v2.3.0 |
55 | Svt[info]: SVT [build] : GCC 15.0.1 20250204 (Red Hat 15.0.1-0) 64 bit |
56 | Svt[info]: LIB Build date: Feb 8 2025 00:00:00 |
57 | Svt[info]: ------------------------------------------- |
58 | Svt[info]: Level of Parallelism: 6 |
59 | Svt[info]: Number of PPCS 305 |
60 | Svt[info]: [asm level on system : up to c] |
61 | Svt[info]: [asm level selected : up to c] |
62 | Svt[info]: ------------------------------------------- |
63 | Svt[info]: SVT [config]: main profile tier (auto) level (auto) |
64 | Svt[info]: SVT [config]: width / height / fps numerator / fps denominator : 1024 / 768 / 24 / 1 |
65 | Svt[info]: SVT [config]: bit-depth / color format : 8 / YUV420 |
66 | Svt[info]: SVT [config]: preset / tune / pred struct : 7 / PSNR / random access |
67 | Svt[info]: SVT [config]: gop size / mini-gop size / key-frame type : 161 / 32 / key frame |
68 | Svt[info]: SVT [config]: BRC mode / rate factor : CRF / 50 |
69 | Svt[info]: SVT [config]: AQ mode / variance boost : 2 / 0 |
70 | Svt[info]: ------------------------------------------- |
71 | Output #0, webm, to 'video.webm': |
72 | Metadata: |
73 | encoder : Lavf61.7.100 |
74 | Stream #0:0: Video: av1, yuv420p(tv, progressive), 1024x768, q=2-31, 24 fps, 1k tbn |
75 | Metadata: |
76 | encoder : Lavc61.19.101 libsvtav1 |
77 | [out#0/webm @ 0x154ab4dc0] video:0KiB audio:0KiB subtitle:0KiB other streams:0KiB global headers:0KiB muxing overhead: 391.111111% |
78 | frame= 1 fps=0.0 q=44.0 Lsize= 1KiB time=00:00:00.00 bitrate=N/A speed= 0x |
79 | [2025-06-22T21:39:56.648229Z] [debug] [pid:3976728] Waiting for video encoder to finalize the video |
80 | [2025-06-22T21:39:56.648405Z] [debug] [pid:3976728] The built-in video encoder (pid 3976979) terminated |
81 | [2025-06-22T21:39:56.648482Z] [debug] [pid:3976728] The external video encoder (pid 3976978) terminated |
82 | [2025-06-22T21:39:56.650018Z] [debug] [pid:3976728] QEMU: QEMU emulator version 9.2.4 (qemu-9.2.4-1.fc42) |
83 | [2025-06-22T21:39:56.650101Z] [debug] [pid:3976728] QEMU: Copyright (c) 2003-2024 Fabrice Bellard and the QEMU Project developers |
84 | [2025-06-22T21:39:56.650181Z] [debug] [pid:3976728] QEMU: qemu-system-ppc64: terminating on signal 15 from pid 3976728 (/usr/bin/isotovideo: backend) |
85 | [2025-06-22T21:39:56.651441Z] [debug] [pid:3976728] sending magic and exit |
86 | [2025-06-22T21:39:56.651781Z] [debug] [pid:3976291] received magic close |
87 | [2025-06-22T21:39:56.655301Z] [debug] [pid:3976291] backend process exited: 0 |
88 | [2025-06-22T21:39:56.755696Z] [warn] [pid:3976291] !!! main: failed to start VM at /usr/lib/os-autoinst/backend/driver.pm line 104. |
89 | |
90 | [2025-06-22T21:39:56.756109Z] [debug] [pid:3976291] stopping command server 3976316 because test execution ended through exception |
91 | [2025-06-22T21:39:56.956582Z] [debug] [pid:3976291] done with command server |
92 | [2025-06-22T21:39:56.956694Z] [debug] [pid:3976291] stopping autotest process 3976571 |
93 | [2025-06-22T21:39:56.956937Z] [debug] [pid:3976571] autotest received signal TERM |
94 | [2025-06-22T21:39:57.157155Z] [debug] [pid:3976291] done with autotest process |
95 | 3976291: EXIT 1 |
96 | [2025-06-22T21:39:57.177053Z] [info] Isotovideo exit status: 1 |
97 | [2025-06-22T21:39:57.195668Z] [info] +++ worker notes +++ |
98 | [2025-06-22T21:39:57.195867Z] [info] End time: 2025-06-22 21:39:57 |
99 | [2025-06-22T21:39:57.196002Z] [info] Result: died |
100 | [2025-06-22T21:39:57.205141Z] [info] Uploading video.webm |
101 | [2025-06-22T21:39:57.231775Z] [info] Uploading autoinst-log.txt |
102 | |