Bug 603266

This request was evaluated by Red Hat Product Management for inclusion in a Red
Hat Enterprise Linux major release.  Product Management has requested further
review of this request by Red Hat Engineering, for potential inclusion in a Red
Hat Enterprise Linux Major release.  This request is not yet committed for
inclusion.

The error message from qemu is quite cryptic since it doesn't give us the reason for this failure. However, the behavior is expected since qemu is run under qemu user while you created that file as root. Since qemu is not allowed to write to such file, it fails to start.

If you don't express any disagreement, I'll close this as not a bug soon. Or perhaps we could move this bug to qemu to improve the error message.

I think if there is a specified file exists, the contents of log file should be replaced with new console output. If you think it's qemu issue, could move it to qemu. Thanks

Moving to qemu; we should get a reason for the failure, but otherwise I agree that this is expected behavior.

# rpm -q qemu-kvm
qemu-kvm-0.12.1.2-2.77.el6.x86_64

# ls -l /tmp/demo.log
-rw-r--r--. 1 qemu qemu 0 Jun 17 22:20 /tmp/demo.log

# LIBVIRT_DEBUG=1 virsh start demo
------ snip ------
22:24:59.416: debug : virDomainLookupByName:2127 : conn=0xe98f40, name=demo
22:24:59.416: debug : remoteIO:9748 : Do proc=23 serial=3 length=36 wait=(nil)
22:24:59.416: debug : remoteIO:9823 : We have the buck 23 0xe9c570 0xe9c570
22:24:59.416: debug : remoteIODecodeMessageLength:9179 : Got length, now need 84 total (80 more)
22:24:59.416: debug : remoteIOEventLoop:9674 : Giving up the buck 23 0xe9c570 (nil)
22:24:59.416: debug : remoteIO:9854 : All done with our call 23 (nil) 0xe9c570
22:24:59.416: debug : virGetDomain:383 : New hash entry 0xe98580
22:24:59.416: debug : virDomainGetID:2775 : domain=0xe98580
22:24:59.416: debug : virDomainCreate:4863 : domain=0xe98580
22:24:59.416: debug : remoteIO:9748 : Do proc=9 serial=4 length=56 wait=(nil)
22:24:59.416: debug : remoteIO:9823 : We have the buck 9 0xe9c800 0xe9c800
22:24:59.746: debug : remoteIODecodeMessageLength:9179 : Got length, now need 296 total (292 more)
22:24:59.747: debug : remoteIOEventLoop:9674 : Giving up the buck 9 0xe9c800 (nil)
22:24:59.747: debug : remoteIO:9854 : All done with our call 9 (nil) 0xe9c800
22:24:59.747: debug : virDomainGetName:2681 : domain=0xe98580
error: Failed to start domain demo
22:24:59.747: debug : virDomainFree:2215 : domain=0xe98580
22:24:59.747: debug : virUnrefDomain:462 : unref domain 0xe98580 demo 1
22:24:59.747: debug : virReleaseDomain:414 : release domain 0xe98580 demo
22:24:59.747: debug : virReleaseDomain:432 : unref connection 0xe98f40 2
error: internal error Process exited while reading console log output: chardev: opening backend "file" failed


22:24:59.747: debug : virConnectClose:1497 : conn=0xe98f40
22:24:59.747: debug : virUnrefConnect:294 : unref connection 0xe98f40 1
22:24:59.747: debug : remoteIO:9748 : Do proc=2 serial=5 length=28 wait=(nil)
22:24:59.747: debug : remoteIO:9823 : We have the buck 2 0xe9c870 0xe9c870
22:24:59.748: debug : remoteIODecodeMessageLength:9179 : Got length, now need 56 total (52 more)
22:24:59.748: debug : remoteIOEventLoop:9674 : Giving up the buck 2 0xe9c870 (nil)
22:24:59.748: debug : remoteIO:9854 : All done with our call 2 (nil) 0xe9c870
22:24:59.748: debug : virReleaseConnect:249 : release connection 0xe98f40

As Daniel pointed, ideally libvirt would be pre-creating those files with appropriate ownership and selinux label, which gets complicated with stuff like root-squashed nfs so it seems more like a longer term goal... I'll file a separate bug to track it.

FYI getting libvirt to pre-create and set selinux labels on serial log files is being tracked in https://bugzilla.redhat.com/show_bug.cgi?id=585249

Ah, I didn't notice it existed... I closed the BZ I created as a duplicate of the older one.

This issue has been proposed when we are only considering blocker
issues in the current Red Hat Enterprise Linux release. It has
been denied for the current Red Hat Enterprise Linux release.

** If you would still like this issue considered for the current
release, ask your support representative to file as a blocker on
your behalf. Otherwise ask that it be considered for the next
Red Hat Enterprise Linux release. **

Upstream fix posted http://lists.nongnu.org/archive/html/qemu-devel/2012-02/msg00714.html

Let's hope it gets accepted.

I took a look at Markus's series and here are my thoughts.

For upstream, making chardev open use error_set() shouldn't be difficult, as most errors are open() failures. It might get a little more difficult to report the sockets errors correctly, but it's all doable and I can work on that.

Now, I'm not sure how difficult it would be to backport this to 6.4. That series is going to touch a lot of code and it might depend on errors infra bits that haven't been backported yet. This can double the effort to fix this downstream.

My advice to this bz is to move it to 7.0.

This bug has been mostly addressed in upstream, meanwhile. There are now two ways to create chardevs in qemu, the QAPI way and the legacy way.

typedef struct CharDriver {
    const char *name;
    /* old, pre qapi */
    CharDriverState *(*open)(QemuOpts *opts);
    /* new, qapi-based */
    ChardevBackendKind kind;
    void (*parse)(QemuOpts *opts, ChardevBackend *backend, Error **errp);
} CharDriver;


The QAPI way has builtin error propagation support. Such chardev drivers are registered with register_char_driver_qapi(), and the parse() member function that is set up with the register_char_driver_qapi()() call has an "Error **errp" parameter.

The function qemu_chr_new_from_opts() -- which looks like the main entry point for creating chardev *instances* -- uses the chardev type's parse() member (ie. the new API) when open() (ie. the old API) is absent. When using parse(), errors are propagated nicely. For example:

  touch testfile
  chmod a-w testfile
  /usr/libexec/qemu-kvm -chardev file,id=f0,path=testfile

qemu-kvm: -chardev file,id=f0,path=testfile: Could not open 'testfile': Permission denied

(Tested with qemu-kvm-1.5.3-69.el7.x86_64.)

So, we need to look for chardev types that still use the old API -- those aren't registered with register_char_driver_qapi() but with register_char_driver().

I can find two callers:

qemu-char.c:    register_char_driver("socket", qemu_chr_open_socket);
qemu-char.c:    register_char_driver("udp", qemu_chr_open_udp);

Both qemu_chr_open_socket() and qemu_chr_open_udp() already handle Errors internally. They correctly collect errors propagated up to them, and then deal with them locally, because the open() interface cannot propagate the error further.

In addition, the "local way" that both qemu_chr_open_socket() and qemu_chr_open_udp() deal with the errors that have been propagated to them, is a call to qerror_report_err(). Which means that the error will be reported through the monitor.

commit 87d5f24f3f5edc4b69d071d5966cea0aec7b571d
Author: Paolo Bonzini <pbonzini>
Date:   Tue Oct 2 09:16:49 2012 +0200

    qemu-char: ask and print error information from qemu-sockets

commit 58a3714c529b1b97ee078ea25b58f731aabcbfff
Author: Gerd Hoffmann <kraxel>
Date:   Mon Jun 24 08:39:55 2013 +0200

    qemu-char: report udp backend errors

RHEL-7.0 contains both patches. The first fix is part of upstream v1.3.0. The second fix has been released in upstream v1.6.0, but it also has been cherry-picked to RHEL, as RHEL-7 commit ecf98a56 (for bug 922010).