action #108575
Updated by okurz about 2 years ago
## 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%