Bug 818467

Summary: Improve libvirt debug capability
Product: Red Hat Enterprise Linux 6 Reporter: Alex Jia <ajia>
Component: libvirtAssignee: Laine Stump <laine>
Status: CLOSED ERRATA QA Contact: Virtualization Bugs <virt-bugs>
Severity: medium Docs Contact:
Priority: high    
Version: 6.3CC: acathrow, bili, dallan, dyasny, dyuan, mzhan, rwu, tzheng
Target Milestone: rc   
Target Release: ---   
Hardware: x86_64   
OS: Linux   
Whiteboard:
Fixed In Version: libvirt-0.10.0-0rc1.el6 Doc Type: Bug Fix
Doc Text:
Cause: Many external programs that are used by libvirt (e.g. qemu-kvm) produce useful error messages that were not passed on to the admin by libvirt, which instead would sometimes just report that a command had failed. Consequence: Sometimes a problem whose cause/resolution would have been trivial to discover by looking at the error output of a command, were instead very difficult to diagnose. Fix: If any external command run by libvirt exits with a failure, its stderr output will be captured and added to the system log as a libvirt error. Result: Many problems are now easier to diagnose, because better information is available.
Story Points: ---
Clone Of: Environment:
Last Closed: 2013-02-21 07:12:38 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Description Alex Jia 2012-05-03 07:39:38 UTC
Description of problem:
As usual, if /usr/sbin/qemu-kvm exists issues, libvirt will write 'qemu-kvm' return value instead of error message into libvirtd.log such as "status unexpected: exit status 127", it's not convenient to know a actual error for users/developers, the following is a real world example:

Users hasn't install 'usbredir' rpm package on the host(please don't consider yum installation in here, although yum can help resolve dependencies relationship issue sometimes), and then start libvirtd service or use other libvirt client to connect libvirtd such as virt-manger, libvirtd.log reports some error message as follows:

<snip>
2012-05-03 06:41:09.717+0000: 4407: error : virCommandWait:2308 : internal error Child process (LC_ALL=C PATH=/sbin:/usr/sbin:/bin:/usr/bin /usr/libexec/qemu-kvm -help) status unexpected: exit status 127
2012-05-03 06:41:09.728+0000: 4407: error : virCommandWait:2308 : internal error Child process (LC_ALL=C PATH=/sbin:/usr/sbin:/bin:/usr/bin /usr/libexec/qemu-kvm -help) status unexpected: exit status 127
2012-05-03 06:41:09.729+0000: 4407: debug : qemuCreateCapabilities:294 : Initialized caps for security driver "selinux" with DOI "0"
2012-05-03 06:41:09.747+0000: 4407: error : virDomainDefParseXML:8145 : unknown OS type hvm
</snip>

We don't know how to resolve the issue based on above libvirtd.log, however, it's very easy to debug it if you directly run /usr/sbin/qemu-kvm:

# /usr/libexec/qemu-kvm
/usr/libexec/qemu-kvm: symbol lookup error: /usr/libexec/qemu-kvm: undefined symbol: usbredirparser_send_filter_reject

Notes, the above error hints you missed usb network redirection protocol libraries. so everything is okay if you install 'usbredir' rpm on the host.

Version-Release number of selected component (if applicable):
# rpm -q libvirt qemu-kvm kernel
libvirt-0.9.10-16.el6.x86_64
qemu-kvm-0.12.1.2-2.286.el6.x86_64
kernel-2.6.32-220.2.1.el6.x86_64
kernel-2.6.32-184.el6.x86_64

How reproducible:
always.

Steps to Reproduce:
1. rpm install qemu-kvm and libvirt packages 
Notes, make sure 'usbredir' hasn't been installed on the host.

2. service libvirtd start or run virt-manger

3. see libvirtd.log or virt-manager error message
  
Actual results:
2012-05-03 06:41:09.637+0000: 4407: info : libvirt version: 0.9.10, package: 16.el6 (Red Hat, Inc. <http://bugzilla.redhat.com/bugzilla>, 2012-05-02-04:50:10, hs20-bc2-5.build.redhat.com)
2012-05-03 06:41:09.637+0000: 4407: info : qemudLoadDriverConfig:332 : Configured cgroup controller 'cpu'
2012-05-03 06:41:09.637+0000: 4407: info : qemudLoadDriverConfig:332 : Configured cgroup controller 'cpuacct'
2012-05-03 06:41:09.637+0000: 4407: info : qemudLoadDriverConfig:332 : Configured cgroup controller 'cpuset'
2012-05-03 06:41:09.637+0000: 4407: info : qemudLoadDriverConfig:332 : Configured cgroup controller 'memory'
2012-05-03 06:41:09.637+0000: 4407: info : qemudLoadDriverConfig:332 : Configured cgroup controller 'devices'
2012-05-03 06:41:09.637+0000: 4407: info : qemudLoadDriverConfig:332 : Configured cgroup controller 'blkio'
2012-05-03 06:41:09.717+0000: 4407: error : virCommandWait:2308 : internal error Child process (LC_ALL=C PATH=/sbin:/usr/sbin:/bin:/usr/bin /usr/libexec/qemu-kvm -help) status unexpected: exit status 127
2012-05-03 06:41:09.728+0000: 4407: error : virCommandWait:2308 : internal error Child process (LC_ALL=C PATH=/sbin:/usr/sbin:/bin:/usr/bin /usr/libexec/qemu-kvm -help) status unexpected: exit status 127
2012-05-03 06:41:09.729+0000: 4407: debug : qemuCreateCapabilities:294 : Initialized caps for security driver "selinux" with DOI "0"
2012-05-03 06:41:09.747+0000: 4407: error : virDomainDefParseXML:8145 : unknown OS type hvm
2012-05-03 06:41:09.747+0000: 4407: error : virDomainDefParseXML:8145 : unknown OS type hvm
2012-05-03 06:41:09.756+0000: 4407: debug : qemuDriverCloseCallbackRunAll:661 : conn=0x7f042c13a0e0
2012-05-03 06:41:09.756+0000: 4407: debug : qemuDriverCloseCallbackRunAll:661 : conn=0x7f042c06fc40
2012-05-03 06:43:31.351+0000: 4401: error : virCommandWait:2308 : internal error Child process (LC_ALL=C PATH=/sbin:/usr/sbin:/bin:/usr/bin /usr/libexec/qemu-kvm -help) status unexpected: exit status 127
2012-05-03 06:43:31.376+0000: 4401: error : virCommandWait:2308 : internal error Child process (LC_ALL=C PATH=/sbin:/usr/sbin:/bin:/usr/bin /usr/libexec/qemu-kvm -help) status unexpected: exit status 127
2012-05-03 06:43:31.377+0000: 4401: debug : qemuCreateCapabilities:294 : Initialized caps for security driver "selinux" with DOI "0"
2012-05-03 06:43:31.384+0000: 4396: debug : qemuDriverCloseCallbackRunAll:661 : conn=0x7f0428000ae0

Expected results:
Libvirt also raises qemu-kvm error message.

Additional info:
Although 'virsh capabilities' says the host missed virtualization capability(without <guest> element block), it's not easy to debug
a actual issue.

In addition, we also add '1:qemu' log filter into /etc/libvirt/libvirtd.conf.

Comment 3 Laine Stump 2012-08-07 00:43:25 UTC
I've sent a patch upstream which will include the output of stderr in the error log of any failed external command:

  https://www.redhat.com/archives/libvir-list/2012-August/msg00404.html

For example, I tried removing the usbredir rpm, and the following log message was generated when I tried to start a guest:

error : virCommandWait:2336 : internal error Child process (LC_ALL=C PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin /usr/bin/qemu-kvm -help) unexpected exit status 127: /usr/bin/qemu-kvm: error while loading shared libraries: libusbredirparser.so.0: cannot open shared object file: No such file or directory


(BTW, it takes some really explicit effort to install libvirt without its dependencies - even just using rpm rather than yum won't do it, you have to actually force rpm to ignore the dependencies. Because of that, my opinion is that anybody who ends up with a system broken in this way deserves it. However, the information is there, and could also be useful in other more legitimate situations, so it's still good to provide it.)

Comment 4 Laine Stump 2012-08-09 00:14:25 UTC
The following patch has been pushed to upstream libvirt, and will be in the next rebase:

commit b8c298d3019ffed3f93989314c90821ddbe47f83
Author: Laine Stump <laine>
Date:   Mon Aug 6 11:40:06 2012 -0400

    util: include stderr in log message when an external command fails
    
    This patch is in response to:
    
      https://bugzilla.redhat.com/show_bug.cgi?id=818467
    
    If a caller to virCommandRun doesn't ask for the exitstatus of the
    program it's running, the virCommand functions assume that they should
    log an error message and return failure if the exit code isn't
    0. However, only the commandline and exit status are logged, while
    potentially useful information sent by the program to stderr is
    discarded.
    
    Fortunately, virCommandRun is already checking if the caller had asked
    for stderr to be saved and, if not, sets things up to save it in
    *cmd->errbuf. This makes it fairly simple for virCommandWait to
    include *cmd->errbuf in the error log (there are still other callers
    that don't setup errbuf, and even virCommandRun won't set it up if the
    command is being daemonized, so we have to check that it's non-zero).

Comment 6 EricLee 2012-08-23 10:54:12 UTC
Verifying this bug in libvirt-0.10.0-0rc1.el6:

Do not install usbredir, restart libvirtd and check libvirtd.log at the same time, get error like:

2012-08-23 09:45:53.495+0000: 11237: error : virCommandWait:2332 : internal error Child process (LC_ALL=C PATH=/sbin:/usr/sbin:/bin:/usr/bin /usr/libexec/qemu-kvm -help) unexpected exit status 127: /usr/libexec/qemu-kvm: error while loading shared libraries: libusbredirparser.so.0: cannot open shared object file: No such file or directory

2012-08-23 09:45:53.497+0000: 11237: error : virCommandWait:2332 : internal error Child process (LC_ALL=C PATH=/sbin:/usr/sbin:/bin:/usr/bin /usr/libexec/qemu-kvm -help) unexpected exit status 127: /usr/libexec/qemu-kvm: error while loading shared libraries: libusbredirparser.so.0: cannot open shared object file: No such file or directory

are expected results.

And also get same error:
Error starting domain: internal error Child process (LC_ALL=C PATH=/sbin:/usr/sbin:/bin:/usr/bin /usr/libexec/qemu-kvm -help) unexpected exit status 127: /usr/libexec/qemu-kvm: error while loading shared libraries: libusbredirparser.so.0: cannot open shared object file: No such file or directory
using virt-manager to to connect libvirtd.

So moving to VERIFIED.

Comment 7 errata-xmlrpc 2013-02-21 07:12:38 UTC
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

http://rhn.redhat.com/errata/RHSA-2013-0276.html