QA » openQA Project

PR was merged

https://build.opensuse.org/package/live_build_log/devel:openQA/os-autoinst/SLE_15/ppc64le is a consequence of your PR . Would be great if you can fix this:

[  218s] qemu-img command failed at /home/abuild/rpmbuild/BUILD/os-autoinst-4.6.1585236593.c963e140/OpenQA/Qemu/Proc.pm line 142.
[  218s]  at 18-qemu.t line 17.
[  218s]    main::__ANON__("qemu-img command failed at /home/abuild/rpmbuild/BUILD/os-aut"...) called at /home/abuild/rpmbuild/BUILD/os-autoinst-4.6.1585236593.c963e140/OpenQA/Qemu/Proc.pm line 142
[  218s]    OpenQA::Qemu::Proc::get_img_json_field(OpenQA::Qemu::Proc=HASH(0x10030338de0), "data/Core-7.2.iso", "virtual-size") called at /home/abuild/rpmbuild/BUILD/os-autoinst-4.6.1585236593.c963e140/OpenQA/Qemu/Proc.pm line 150
[  218s]    OpenQA::Qemu::Proc::get_img_size(OpenQA::Qemu::Proc=HASH(0x10030338de0), "data/Core-7.2.iso") called at /home/abuild/rpmbuild/BUILD/os-autoinst-4.6.1585236593.c963e140/OpenQA/Qemu/Proc.pm line 213
[  218s]    OpenQA::Qemu::Proc::configure_blockdevs(OpenQA::Qemu::Proc=HASH(0x10030338de0), "disk", "raid", HASH(0x1002e456870)) called at 18-qemu.t line 304
[  218s] qemu-img command failed at /home/abuild/rpmbuild/BUILD/os-autoinst-4.6.1585236593.c963e140/OpenQA/Qemu/Proc.pm line 142.
[  218s] 
[  218s] #   Failed test 'no (unexpected) warnings (via END block)'
[  218s] #   at /usr/lib/perl5/5.26.1/Test/Builder.pm line 135.
[  218s] # Tests were run but no plan was declared and done_testing() was not seen.
[  218s] # Looks like your test exited with 9 just after 29.
[  218s] 18-qemu.t .............................. 
[  218s] Dubious, test returned 9 (wstat 2304, 0x900)

I branched the OBS package and added some debugging, and now it's passing...

I was able to reproduce it with debugging:

[  445s] OpenQA::Qemu::Proc:142 $rc = \1;
[  445s] OpenQA::Qemu::Proc:143 $json = \'{
[  445s]     "virtual-size": 11116544,
[  445s]     "filename": "data/Core-7.2.iso",
[  445s]     "format": "raw",
[  445s]     "actual-size": 11132928,
[  445s]     "dirty-flag": false
[  445s] }';
[  445s] qemu-img command failed at /home/abuild/rpmbuild/BUILD/os-autoinst-4.6.1585240449.ef38ab09/OpenQA/Qemu/Proc.pm line 144.
[  445s]  at 18-qemu.t line 17.
[  445s]    main::__ANON__("qemu-img command failed at /home/abuild/rpmbuild/BUILD/os-aut"...) called at /home/abuild/rpmbuild/BUILD/os-autoinst-4.6.1585240449.ef38ab09/OpenQA/Qemu/Proc.pm line 144
[  445s]    OpenQA::Qemu::Proc::get_img_json_field(OpenQA::Qemu::Proc=HASH(0x10020bed9c8), "data/Core-7.2.iso", "virtual-size") called at /home/abuild/rpmbuild/BUILD/os-autoinst-4.6.1585240449.ef38ab09/OpenQA/Qemu/Proc.pm line 152
[  445s]    OpenQA::Qemu::Proc::get_img_size(OpenQA::Qemu::Proc=HASH(0x10020bed9c8), "data/Core-7.2.iso") called at /home/abuild/rpmbuild/BUILD/os-autoinst-4.6.1585240449.ef38ab09/OpenQA/Qemu/Proc.pm line 215
[  445s]    OpenQA::Qemu::Proc::configure_blockdevs(OpenQA::Qemu::Proc=HASH(0x10020bed9c8), "disk", "raid", HASH(0x10020b2bf30)) called at 18-qemu.t line 304
[  445s] qemu-img command failed at /home/abuild/rpmbuild/BUILD/os-autoinst-4.6.1585240449.ef38ab09/OpenQA/Qemu/Proc.pm line 144.
[  445s] 

That means, we get a non-zero exit code, but apparently the command was executed successfully.

The exit code comes from Mojo::IOLoop::ReadWriteProcess, maybe it has a bug?

I suggest to revert my PR and check via regex if we got JSON back or not. Not nice, but I see no quick solution.

PR reverted.
Second PR was merged: https://github.com/os-autoinst/os-autoinst/pull/1372

hm, can you please check https://openqa.opensuse.org/tests/1215921 ? It says

[2020-03-27T21:11:33.105 CET] [debug] Current version is 4.6.1585251444.36bb1cf8 [interface v20]
…
[2020-03-27T21:11:34.644 CET] [debug] running /usr/bin/qemu-img info --output=json /var/lib/openqa/pool/8/openqa1-opensuse
[2020-03-27T21:11:34.662 CET] [debug] qemu-img: Could not open '/var/lib/openqa/pool/8/openqa1-opensuse': A regular file was expected by the 'file' driver, but something else was given
[2020-03-27T21:11:34.662 CET] [debug] Backend process died, backend errors are reported below in the following lines:
malformed JSON string, neither tag, array, object, number, string or atom, at character offset 0 (before "qemu-img: Could not ...") at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/JSON.pm line 39.

As specified in the version string os-autoinst was running at 36bb1cf8 which includes your commit ad2f0588 but still there is "malformed JSON". I don't understand that, do you?

perl -e 'use Mojo::JSON "decode_json"; eval { decode_json(['foo']) }; print "OUT: $@"'

shows correctly

OUT: malformed JSON string, neither tag, array, object, number, string or atom, at character offset 0 (before "(end of string)") at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/JSON.pm line 39.

but

isotovideo -d iso=/dev/shm/ flavor=DVD casedir=/var/lib/openqa/tests/opensuse

yields

[2020-03-30T15:56:19.881 CEST] [debug] qemu-img: Could not open '/dev/shm/': A regular file was expected by the 'file' driver, but something else was given
[2020-03-30T15:56:19.881 CEST] [debug] Backend process died, backend errors are reported below in the following lines:
malformed JSON string, neither tag, array, object, number, string or atom, at character offset 0 (before "qemu-img: Could not ...") at /usr/lib/perl5/vendor_perl/5.26.1/Mojo/JSON.pm line 39.

Looks like the output from decode_json can not be properly caught here and is printed before eval returns.

Mojo::JSON::decode_json shows

 44 sub decode_json {
 45   my $err = _decode(\my $value, shift);
 46   return defined $err ? croak $err : $value;
 47 }

so I guess the "croak" is handled differently depending on how the pipes for setup are setup?

Please see https://github.com/os-autoinst/os-autoinst/pull/1376 where I try to address this now.