Project

General

Profile

Actions
Copy link

action #40046

closed

[tools] qemu errors do not seem to show up anymore in the logfile

Added by okurz over 5 years ago. Updated over 5 years ago.

Status:
Resolved
Priority:
High
Assignee:
rpalethorpe
Category:
Regressions/Crashes
Target version:
-
Start date:
2018-08-21
Due date:
% Done:

0%

Estimated time:

Description

Observation

https://openqa.opensuse.org/tests/739252/file/autoinst-log.txt shows

Attempt 0 at /usr/lib/os-autoinst/osutils.pm line 131.
Attempt 1 at /usr/lib/os-autoinst/osutils.pm line 131.
Attempt 2 at /usr/lib/os-autoinst/osutils.pm line 131.
Attempt 3 at /usr/lib/os-autoinst/osutils.pm line 131.
Attempt 4 at /usr/lib/os-autoinst/osutils.pm line 131.
Attempt 5 at /usr/lib/os-autoinst/osutils.pm line 131.
Attempt 6 at /usr/lib/os-autoinst/osutils.pm line 131.
Attempt 7 at /usr/lib/os-autoinst/osutils.pm line 131.
Attempt 8 at /usr/lib/os-autoinst/osutils.pm line 131.
Attempt 9 at /usr/lib/os-autoinst/osutils.pm line 131.
Attempt 10 at /usr/lib/os-autoinst/osutils.pm line 131.
Attempt 11 at /usr/lib/os-autoinst/osutils.pm line 131.
Attempt 12 at /usr/lib/os-autoinst/osutils.pm line 131.
Attempt 13 at /usr/lib/os-autoinst/osutils.pm line 131.
Attempt 14 at /usr/lib/os-autoinst/osutils.pm line 131.
Attempt 15 at /usr/lib/os-autoinst/osutils.pm line 131.
Attempt 16 at /usr/lib/os-autoinst/osutils.pm line 131.
Attempt 17 at /usr/lib/os-autoinst/osutils.pm line 131.
Attempt 18 at /usr/lib/os-autoinst/osutils.pm line 131.
Attempt 19 at /usr/lib/os-autoinst/osutils.pm line 131.
DIE can't open qmp at /usr/lib/os-autoinst/OpenQA/Qemu/Proc.pm line 392.

 at /usr/lib/os-autoinst/backend/baseclass.pm line 80.
    backend::baseclass::die_handler('can\'t open qmp at /usr/lib/os-autoinst/OpenQA/Qemu/Proc.pm l...') called at /usr/lib/os-autoinst/OpenQA/Qemu/Proc.pm line 392
    OpenQA::Qemu::Proc::__ANON__() called at /usr/lib/os-autoinst/osutils.pm line 136
    osutils::attempt('HASH(0x1001351f9d8)') called at /usr/lib/os-autoinst/OpenQA/Qemu/Proc.pm line 394
    OpenQA::Qemu::Proc::connect_qmp('OpenQA::Qemu::Proc=HASH(0x1001318fb88)') called at /usr/lib/os-autoinst/backend/qemu.pm line 841
    backend::qemu::start_qemu('backend::qemu=HASH(0x10013047988)') called at /usr/lib/os-autoinst/backend/qemu.pm line 117
    backend::qemu::do_start_vm('backend::qemu=HASH(0x10013047988)') called at /usr/lib/os-autoinst/backend/baseclass.pm line 319
    backend::baseclass::start_vm('backend::qemu=HASH(0x10013047988)', undef) called at /usr/lib/os-autoinst/backend/baseclass.pm line 75
    backend::baseclass::handle_command('backend::qemu=HASH(0x10013047988)', 'HASH(0x10013507560)') called at /usr/lib/os-autoinst/backend/baseclass.pm line 487
    backend::baseclass::check_socket('backend::qemu=HASH(0x10013047988)', 'IO::Handle=GLOB(0x1001307b220)') called at /usr/lib/os-autoinst/backend/qemu.pm line 1004
    backend::qemu::check_socket('backend::qemu=HASH(0x10013047988)', 'IO::Handle=GLOB(0x1001307b220)', 0) called at /usr/lib/os-autoinst/backend/baseclass.pm line 246
    eval {...} called at /usr/lib/os-autoinst/backend/baseclass.pm line 156
    backend::baseclass::run_capture_loop('backend::qemu=HASH(0x10013047988)') called at /usr/lib/os-autoinst/backend/baseclass.pm line 129
    backend::baseclass::run('backend::qemu=HASH(0x10013047988)', 13, 16) called at /usr/lib/os-autoinst/backend/driver.pm line 77
    backend::driver::__ANON__('Mojo::IOLoop::ReadWriteProcess=HASH(0x100130343c8)') called at /usr/lib/perl5/vendor_perl/5.18.2/Mojo/IOLoop/ReadWriteProcess.pm line 325
    eval {...} called at /usr/lib/perl5/vendor_perl/5.18.2/Mojo/IOLoop/ReadWriteProcess.pm line 325
    Mojo::IOLoop::ReadWriteProcess::_fork('Mojo::IOLoop::ReadWriteProcess=HASH(0x100130343c8)', 'CODE(0x1000de5fa38)') called at /usr/lib/perl5/vendor_perl/5.18.2/Mojo/IOLoop/ReadWriteProcess.pm line 476
    Mojo::IOLoop::ReadWriteProcess::start('Mojo::IOLoop::ReadWriteProcess=HASH(0x100130343c8)') called at /usr/lib/os-autoinst/backend/driver.pm line 79
    backend::driver::start('backend::driver=HASH(0x10011526a70)') called at /usr/lib/os-autoinst/backend/driver.pm line 50
    backend::driver::new('backend::driver', 'qemu') called at /usr/bin/isotovideo line 199
    main::init_backend() called at /usr/bin/isotovideo line 267
last frame
[2018-08-20T21:40:28.0147 UTC] [debug] QEMU: QEMU emulator version 2.9.1(openSUSE Leap 42.3)
[2018-08-20T21:40:28.0147 UTC] [debug] QEMU: Copyright (c) 2003-2017 Fabrice Bellard and the QEMU Project developers
[2018-08-20T21:40:28.0147 UTC] [debug] QEMU: [2018-08-20T21:40:09.0113 UTC] [debug] starting: /usr/bin/qemu-system-ppc64 -g 1024x768 -vga std -chardev ringbuf,id=serial0,logfile=serial0,logappend=on -serial chardev:serial0 -soundhw ac97 -global isa-fdc.driveA= -m 4096 -machine usb=off -cpu host -netdev user,id=qanet0 -device virtio-net,netdev=qanet0,mac=52:54:00:12:34:56 -boot once=d,menu=on,splash-time=5000 -device nec-usb-xhci -device usb-tablet -device usb-kbd -smp 1,threads=1 -enable-kvm -no-shutdown -vnc :92,share=force-shared -chardev socket,path=qmp_socket,server,nowait,id=qmp_socket,logfile=qmp_socket.log,logappend=on -qmp chardev:qmp_socket -S -device virtio-scsi-pci,id=scsi0 -blockdev driver=file,node-name=hd0-file,filename=/var/lib/openqa/pool/2/raid/hd0,cache.no-flush=on -blockdev driver=qcow2,node-name=hd0,file=hd0-file,cache.no-flush=on -device virtio-blk,id=hd0-device,drive=hd0,serial=hd0 -blockde

but not the actual problem anymore which is "Permission denied" when trying to access /dev/kvm. This worked in the past.

Expected result

Real error messages from qemu should show up in the output. Maybe stderr is not catched anymore?

Related issues 2 (0 open — 2 closed)

Related to openQA Project - action #40031: [tools][opensuse][ppc64le] DIE can't open qmp - all ppc64le openSUSE jobs incompleteResolvedokurz2018-08-21

Actions
Copied from openQA Project - action #40034: [tools] logline including qemu parameters is split over two entriesRejected2018-08-21

Actions
Actions
Copy link
 #1

Updated by okurz over 5 years ago

  • Copied from action #40034: [tools] logline including qemu parameters is split over two entries added
Actions
Copy link
 #2

Updated by okurz over 5 years ago

  • Related to action #40031: [tools][opensuse][ppc64le] DIE can't open qmp - all ppc64le openSUSE jobs incomplete added
Actions
Copy link
 #3

Updated by rpalethorpe over 5 years ago

It appears that we set separate_err to zero and the library code for this looks correct.

It will probably help to move the call to diag out of the sub process, so it at least does not get two timestamps. Also we may be nesting calls to Mojo log which is almost certainly bad and we may be mixing Perl buffered output with QEMU output.

Actions
Copy link
 #4

Updated by rpalethorpe over 5 years ago

  • Status changed from New to Feedback

Looks like this reverts to almost the old behaviour: https://github.com/os-autoinst/os-autoinst/pull/1015

The chronological order of the log entries is slightly different than from before (if the process starts successfully), but that probably requires a bigger more intrusive fix and the old behaviour was confusing anyway. The output of QEMU is not written to the log at the time it actually occurs.

Actions
Copy link
 #5

Updated by rpalethorpe over 5 years ago

  • Status changed from Feedback to Resolved
Actions
Copy link

Also available in: Atom PDF