Project

General

Custom queries

Profile

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 "

Added by okurz almost 3 years ago. Updated over 2 years ago.

Status:
New
Priority:
Low
Assignee:
-
Category:
Regressions/Crashes
Target version:
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%

Actions #2

Updated by tinita almost 3 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.

Actions #3

Updated by okurz almost 3 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

Actions #4

Updated by livdywan over 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

Also available in: Atom PDF