Actions
action #108575
open[sporadic] os-autoinst: t/18-qemu-options.t fails with "Fatal error in command `/usr/bin/chattr.*No such file or directory "
Start date:
2022-03-18
Due date:
% Done:
0%
Estimated time:
Description
Observation¶
In https://github.com/os-autoinst/os-autoinst/pull/1986 in https://github.com/os-autoinst/os-autoinst/runs/5471333173?check_suite_focus=true I have seen the error
7:
7: # Failed test 'Supported machines listed'
7: # at ./18-qemu-options.t line 82.
7: # 'Subroutine JSON::PP::Boolean::(++ redefined at /usr/lib/perl5/5.26.1/overload.pm line 48.
7: # Subroutine JSON::PP::Boolean::(-- redefined at /usr/lib/perl5/5.26.1/overload.pm line 48.
7: # Subroutine JSON::PP::Boolean::(0+ redefined at /usr/lib/perl5/5.26.1/overload.pm line 48.
7: # [2022-03-08T21:27:15.409475Z] [debug] Current version is c896b72d50129eeceed7ee0e010f4228f1c37578 [interface v25]
7: # [2022-03-08T21:27:15.413684Z] [debug] Setting forced test parameter QEMU_DISABLE_SNAPSHOTS -> 1
7: # [2022-03-08T21:27:15.421609Z] [debug] git hash in /opt/t/data/tests: c896b72d50129eeceed7ee0e010f4228f1c37578
7: # [2022-03-08T21:27:15.421997Z] [info] ::: OpenQA::Isotovideo::Utils::load_test_schedule: Enforced test schedule by 'SCHEDULE' variable in action
7: # [2022-03-08T21:27:15.433454Z] [debug] scheduling noop tests/noop.pm
7: # [2022-03-08T21:27:15.511143Z] [debug] git hash in /opt/t/data/tests/needles: c896b72d50129eeceed7ee0e010f4228f1c37578
7: # [2022-03-08T21:27:15.511457Z] [debug] init needles from /opt/t/data/tests/needles
7: # [2022-03-08T21:27:15.511170Z] [info] cmdsrv: daemon reachable under http://*:15223/vugxZhIhId/
7: # [2022-03-08T21:27:15.513657Z] [debug] loaded 4 needles
7: # [2022-03-08T21:27:15.515283Z] [info] Listening at "http://[::]:15223"
7: # Web application available at http://[::]:15223
7: # [2022-03-08T21:27:15.517321Z] [debug] Blocking SIGCHLD and SIGTERM
7: # [2022-03-08T21:27:15.539185Z] [debug] Unblocking SIGCHLD and SIGTERM
7: # [2022-03-08T21:27:15.677678Z] [debug] 2201: channel_out 17, channel_in 16
7: # [2022-03-08T21:27:15.677687Z] [debug] Blocking SIGCHLD and SIGTERM
7: # [2022-03-08T21:27:15.701103Z] [debug] Unblocking SIGCHLD and SIGTERM
7: # [2022-03-08T21:27:15.703584Z] [debug] 2212: cmdpipe 15, rsppipe 18
7: # [2022-03-08T21:27:15.704033Z] [debug] started mgmt loop with pid 2212
7: # [2022-03-08T21:27:15.734599Z] [debug] qemu version detected: 5.2.0
7: # [2022-03-08T21:27:15.736332Z] [debug] running `/usr/bin/chattr +C /tmp/18-qemu-options.t-33Vk/pool/raid`
7: # [2022-03-08T21:27:15.742945Z] [debug] Fatal error in command `/usr/bin/chattr +C /tmp/18-qemu-options.t-33Vk/pool/raid`: open3: exec of /usr/bin/chattr +C /tmp/18-qemu-options.t-33Vk/pool/raid failed: No such file or directory at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/IOLoop/ReadWriteProcess.pm line 127.
7: #
7: # [2022-03-08T21:27:15.743148Z] [debug] Configuring storage controllers and block devices
7: # [2022-03-08T21:27:15.744082Z] [debug] running `/usr/bin/qemu-img info --output=json /opt/t/data/Core-7.2.iso`
I am always very confused by this "Subroutine JSON::PP::Boolean::(++" stuff which I repeatedly see in CI tests but never locally. It looks like the root cause problem is "chattr" failing but I am not even sure about this because then the test just continues but then fails at a later step and I don't know why.
Reproducible¶
So far I have seen this only in this way in os-autoinst CI once.
Running locally runs=100 count_fail_ratio prove -I. t/18-qemu-options.t there was only one unrelated failure
## Run 47
t/18-qemu-options.t .. 2/?
# Failed test 'swtpm default device created'
# at t/18-qemu-options.t line 142.
# '[2022-03-18T14:51:53.373182+01:00] [debug] Current version is 2ca6c5f7ce952d52c21208581394a8e3175bd67b [interface v25]
# [2022-03-18T14:51:53.377558+01:00] [debug] Setting forced test parameter QEMU_DISABLE_SNAPSHOTS -> 1
# [2022-03-18T14:51:53.385989+01:00] [debug] git hash in /home/okurz/local/os-autoinst/os-autoinst/t/data/tests: 2ca6c5f7ce952d52c21208581394a8e3175bd67b
# [2022-03-18T14:51:53.386440+01:00] [info] ::: OpenQA::Isotovideo::Utils::load_test_schedule: Enforced test schedule by 'SCHEDULE' variable in action
# [2022-03-18T14:51:53.397167+01:00] [debug] scheduling noop tests/noop.pm
# [2022-03-18T14:51:53.491286+01:00] [info] cmdsrv: daemon reachable under http://*:15223/pQUEHKjJRG/
# [2022-03-18T14:51:53.494164+01:00] [info] Listening at "http://[::]:15223"
# Web application available at http://[::]:15223
# [2022-03-18T14:51:53.494760+01:00] [debug] git hash in /home/okurz/local/os-autoinst/os-autoinst/t/data/tests/needles: 2ca6c5f7ce952d52c21208581394a8e3175bd67b
# [2022-03-18T14:51:53.494989+01:00] [debug] init needles from /home/okurz/local/os-autoinst/os-autoinst/t/data/tests/needles
# [2022-03-18T14:51:53.496802+01:00] [debug] loaded 4 needles
# [2022-03-18T14:51:53.499908+01:00] [debug] Blocking SIGCHLD and SIGTERM
# [2022-03-18T14:51:53.548360+01:00] [debug] Unblocking SIGCHLD and SIGTERM
# [2022-03-18T14:51:53.743466+01:00] [debug] Blocking SIGCHLD and SIGTERM
# [2022-03-18T14:51:53.743540+01:00] [debug] 20805: channel_out 17, channel_in 16
# [2022-03-18T14:51:53.777334+01:00] [debug] Unblocking SIGCHLD and SIGTERM
# [2022-03-18T14:51:53.781505+01:00] [debug] 20828: cmdpipe 15, rsppipe 18
# [2022-03-18T14:51:53.781809+01:00] [debug] started mgmt loop with pid 20828
# [2022-03-18T14:51:53.875284+01:00] [debug] qemu version detected: 5.2.0
# [2022-03-18T14:51:53.878060+01:00] [debug] running `/usr/bin/chattr +C /tmp/18-qemu-options.t-3DwH/pool/raid`
# [2022-03-18T14:51:53.897911+01:00] [debug] Command `/usr/bin/chattr +C /tmp/18-qemu-options.t-3DwH/pool/raid` terminated with 0
# [2022-03-18T14:51:53.898227+01:00] [debug] Configuring storage controllers and block devices
# [2022-03-18T14:51:53.899555+01:00] [debug] running `/usr/bin/qemu-img info --output=json /home/okurz/local/os-autoinst/os-autoinst/t/data/Core-7.2.iso`
# [2022-03-18T14:51:53.998725+01:00] [debug] Initializing block device images
# [2022-03-18T14:51:53.999546+01:00] [debug] running `/usr/bin/qemu-img create -f qcow2 /tmp/18-qemu-options.t-3DwH/pool/raid/hd0 10G`
# [2022-03-18T14:51:54.090683+01:00] [debug] Formatting '/tmp/18-qemu-options.t-3DwH/pool/raid/hd0', fmt=qcow2 cluster_size=65536 extended_l2=off compression_type=zlib size=10737418240 lazy_refcounts=off refcount_bits=16
# [2022-03-18T14:51:54.090939+01:00] [debug] running `/usr/bin/qemu-img create -f qcow2 -F raw -b /home/okurz/local/os-autoinst/os-autoinst/t/data/Core-7.2.iso /tmp/18-qemu-options.t-3DwH/pool/raid/cd0-overlay0 11116544`
# [2022-03-18T14:51:54.191157+01:00] [debug] Formatting '/tmp/18-qemu-options.t-3DwH/pool/raid/cd0-overlay0', fmt=qcow2 cluster_size=65536 extended_l2=off compression_type=zlib size=11116544 backing_file=/home/okurz/local/os-autoinst/os-autoinst/t/data/Core-7.2.iso backing_fmt=raw lazy_refcounts=off refcount_bits=16
# [2022-03-18T14:51:54.191408+01:00] [debug] init_blockdev_images: Finished creating block devices
# [2022-03-18T14:51:54.193434+01:00] [debug] starting: /usr/bin/qemu-system-i386 -chardev ringbuf,id=serial0,logfile=serial0,logappend=on -serial chardev:serial0 -audiodev none,id=snd0 -device intel-hda -device hda-output,audiodev=snd0 -m 1024 -netdev user,id=qanet0 -device virtio-net,netdev=qanet0,mac=52:54:00:12:34:56 -chardev socket,id=chrtpm,path=/tmp/mytpm4/swtpm-sock -tpmdev emulator,id=tpm0,chardev=chrtpm -device tpm-tis,tpmdev=tpm0 -boot once=d -smp 1 -enable-kvm -no-shutdown -vnc :90,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_console1,path=virtio_console1,logfile=virtio_console1.log,logappend=on -device virtconsole,chardev=virtio_console1,name=org.openqa.console.virtio_console1 -chardev socket,path=qmp_socket,server=on,wait=off,id=qmp_socket,logfile=qmp_socket.log,logappend=on -qmp chardev:qmp_socket -S -blockdev driver=file,node-name=hd0-file,filename=/tmp/18-qemu-options.t-3DwH/pool/raid/hd0,cache.no-flush=on -blockdev driver=qcow2,node-name=hd0,file=hd0-file,cache.no-flush=on -device ide-hd,id=hd0-device,drive=hd0,serial=hd0 -blockdev driver=file,node-name=cd0-overlay0-file,filename=/tmp/18-qemu-options.t-3DwH/pool/raid/cd0-overlay0,cache.no-flush=on -blockdev driver=qcow2,node-name=cd0-overlay0,file=cd0-overlay0-file,cache.no-flush=on -device ide-cd,id=cd0-device,drive=cd0-overlay0,serial=cd0
# [2022-03-18T14:51:54.199396+01:00] [info] ::: backend::qemu::start_qemu: Not connecting to QEMU as requested by QEMU_ONLY_EXEC
# GOT GO
#
# [2022-03-18T14:51:54.203383+01:00] [debug] Snapshots are not supported
# [2022-03-18T14:51:54.205432+01:00] [debug] ||| starting noop tests/noop.pm
# [2022-03-18T14:51:54.214281+01:00] [debug] ||| finished noop tests (runtime: 0 s)
# [2022-03-18T14:51:54.219399+01:00] [debug] stopping autotest process 20814
# [2022-03-18T14:51:54.227220+01:00] [debug] [autotest] process exited: 0
# [2022-03-18T14:51:54.327806+01:00] [debug] done with autotest process
# [2022-03-18T14:51:54.328370+01:00] [debug] stopping command server 20811 because test execution ended
# [2022-03-18T14:51:54.328461+01:00] [debug] isotovideo: informing websocket clients before stopping command server: http://127.0.0.1:15223/pQUEHKjJRG/broadcast
# [2022-03-18T14:51:54.343331+01:00] [debug] commands process exited: 0
# [2022-03-18T14:51:54.443846+01:00] [debug] done with command server
# [2022-03-18T14:51:54.443980+01:00] [debug] isotovideo done
# [2022-03-18T14:51:54.444637+01:00] [info] ::: backend::qemu::handle_qmp_command: Skipping the following qmp_command because QEMU_ONLY_EXEC is enabled:
# {"execute":"query-status"}
#
# [2022-03-18T14:51:54.444926+01:00] [info] ::: backend::baseclass::die_handler: Backend process died, backend errors are reported below in the following lines:
# Can't use an undefined value as a HASH reference at /home/okurz/local/os-autoinst/os-autoinst/t/../backend/qemu.pm line 1055.
# [2022-03-18T14:51:54.445413+01:00] [info] ::: OpenQA::Qemu::Proc::save_state: Saving QEMU state to qemu_state.json
# [2022-03-18T14:51:55.468955+01:00] [debug] Passing remaining frames to the video encoder
# [2022-03-18T14:51:55.560853+01:00] [debug] Waiting for video encoder to finalize the video
# [2022-03-18T14:51:55.560980+01:00] [debug] The built-in video encoder (pid 20842) terminated
# [2022-03-18T14:51:55.562375+01:00] [debug] QEMU: QEMU emulator version 5.2.0 (SUSE Linux Enterprise 15)
# [2022-03-18T14:51:55.562461+01:00] [debug] QEMU: Copyright (c) 2003-2020 Fabrice Bellard and the QEMU Project developers
# [2022-03-18T14:51:55.562558+01:00] [debug] QEMU: qemu-system-i386: terminating on signal 15 from pid 20828 (/home/okurz/local/os-autoinst/os-autoinst/t/../isotovideo: backend)
# [2022-03-18T14:51:55.563835+01:00] [debug] sending magic and exit
# [2022-03-18T14:51:55.564135+01:00] [debug] received magic close
# [2022-03-18T14:51:55.568271+01:00] [debug] backend process exited: 0
# [2022-03-18T14:51:55.668749+01:00] [debug] backend shutdown state: ?
# [2022-03-18T14:51:55.670174+01:00] [debug] stopping backend process 20828
# [2022-03-18T14:51:55.670341+01:00] [debug] done with backend process
# 20805: EXIT 0
# '
# doesn't match '(?^u:swtpm socket --tpmstate dir=/tmp/mytpm4 --ctrl type=unixio,path=/tmp/mytpm4/swtpm-sock --log level=20 -d --tpm2)'
# Looks like you failed 1 test of 14.
t/18-qemu-options.t .. 3/?
# Failed test 'qemu_tpm_option'
# at t/18-qemu-options.t line 151.
# Looks like you failed 1 test of 4.
t/18-qemu-options.t .. Dubious, test returned 1 (wstat 256, 0x100)
Failed 1/4 subtests
Test Summary Report
-------------------
t/18-qemu-options.t (Wstat: 256 Tests: 4 Failed: 1)
Failed test: 3
Non-zero exit status: 1
Files=1, Tests=4, 33 wallclock secs ( 0.14 usr 0.01 sys + 25.43 cusr 11.73 csys = 37.31 CPU)
Result: FAIL
so locally a fail ratio of < 1%
Updated by tinita about 2 years ago
The JSON::PP::Boolean warnings can be ignored. It's caused by Cpanel::JSON::XS defining the same overloads and newer versions of JSON::PP prevent the warnings.
Look into our openQA Makefile for -mJSON::PP for a way to prevent the warning.
Updated by okurz about 2 years ago
tinita is helping to get the JSON::PP::Boolean warnings out of the way first: https://github.com/os-autoinst/os-autoinst/pull/2005
Updated by livdywan almost 2 years ago
I don't see the original issue anymore. What I currently see is this:
$ cmake --build build -t test-perl-testsuite TESTS="t/18-qemu-options.t"
Failed test 'Supported machines not listed'
at t/18-qemu-options.t line 78.
[...]
matches '(?^u:Supported machines are\:)'
Looks like you failed 1 test of 14.
Actions