Project

General

Profile

action #64854

coordination #39719: [saga][epic] Detection of "known failures" for stable tests, easy test results review and easy tracking of known issues

coordination #62420: [epic] Distinguish all types of incompletes

qemu-img error message is incorrectly tried to be parsed as JSON auto_review:"malformed JSON string"

Added by okurz about 1 year ago. Updated about 1 year ago.

Status:
Resolved
Priority:
High
Assignee:
Category:
Concrete Bugs
Target version:
Start date:
2020-03-26
Due date:
% Done:

0%

Estimated time:
Difficulty:

Description

Observation

https://openqa.opensuse.org/tests/1214224 is incomplete with

[2020-03-26T10:30:40.005 CET] [debug] running /usr/bin/qemu-img info --output=json openSUSE_Krypton.x86_64-5.12.80-Build16.72.iso
[2020-03-26T10:30:40.013 CET] [debug] qemu-img: Could not open 'openSUSE_Krypton.x86_64-5.12.80-Build16.72.iso': Could not open 'openSUSE_Krypton.x86_64-5.12.80-Build16.72.iso': No such file or directory
[2020-03-26T10:30:40.013 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.

while the root cause of the iso image not being existant is one issue this ticket should focus on incorrect parsing of a simple error string as JSON.

Acceptance criteria

  • AC1: An error string from qemu-img is not causing an error trying to parse as JSON

Suggestions

  • Check where the output of qemu-img is gathered and how it could end up being parsed as JSON
  • Ensure that only valid JSON output if any is tried to be parsed as JSON, probably in the qemu backend
  • Ensure the error message is output in a way that is readable by human: As the output of qemu-img is already correctly shown in the output maybe it is as easy as not trying to parse anything and return with an error code without trying to do more

History

#1 Updated by tinita about 1 year ago

  • Status changed from Workable to In Progress
  • Assignee set to tinita
  • Target version set to Current Sprint

#2 Updated by tinita about 1 year ago

  • Status changed from In Progress to Feedback

#3 Updated by tinita about 1 year ago

PR was merged

#4 Updated by okurz about 1 year ago

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)

#5 Updated by tinita about 1 year ago

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

#6 Updated by tinita about 1 year ago

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.

#7 Updated by tinita about 1 year ago

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

#8 Updated by okurz about 1 year ago

  • Copied to action #64917: auto_review:"(?s)qemu-img.*runcmd.*failed with exit code 1" sometimes but no apparent error message added

#9 Updated by okurz about 1 year ago

  • Copied to deleted (action #64917: auto_review:"(?s)qemu-img.*runcmd.*failed with exit code 1" sometimes but no apparent error message)

#10 Updated by okurz about 1 year ago

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?

#11 Updated by okurz about 1 year ago

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.

#12 Updated by okurz about 1 year ago

  • Subject changed from qemu-img error message is incorrectly tried to be parsed as JSON to qemu-img error message is incorrectly tried to be parsed as JSON auto_review:"malformed JSON string"

#13 Updated by okurz about 1 year ago

  • Status changed from Feedback to Resolved

PR merged, I installed the updated version on os-autoinst already and triggered a test job explicitly for verification but I think we can't easily reproduce a failure that would use the new kind of error message. I tried multiple approaches which all could not trigger that message so I would just call this as "Resolved" after having verified in production that the code change does not fail due to other reasons.

Also available in: Atom PDF