Bug 954248

Summary:	error/debug messages throw out when start guest with static label + relabel='no' and libvirtd log_level=1
Product:	Red Hat Enterprise Linux 6	Reporter:	yanbing du <ydu>
Component:	libvirt	Assignee:	Jiri Denemark <jdenemar>
Status:	CLOSED ERRATA	QA Contact:	Virtualization Bugs <virt-bugs>
Severity:	medium	Docs Contact:
Priority:	medium
Version:	6.4	CC:	acathrow, bili, cwei, dallan, dyuan, gsun, jdenemar, lnovich, mzhan, zhwang
Target Milestone:	rc	Keywords:	Upstream
Target Release:	---
Hardware:	Unspecified
OS:	Unspecified
Whiteboard:
Fixed In Version:	libvirt-0.10.2-19.el6	Doc Type:	Bug Fix
Doc Text:		Story Points:	---
Clone Of:	954247	Environment:
Last Closed:	2013-11-21 08:59:05 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:
Bug Depends On:	954247
Bug Blocks:

Description yanbing du 2013-04-22 04:08:43 UTC

+++ This bug was initially created as a clone of Bug #954247 +++

Description of problem:
Config libvirtd log_level=1, and set lable for a guest with static type 
<seclabel>, and relabel='no', when start the guest, error/debug messages 
throw out.
If set log_level=3, then this bug gone.


Version-Release number of selected component (if applicable):
libvirt-1.0.4-1.el7.x86_64
libvirt-0.10.2-18.el6_4.4.x86_64

How reproducible:
100%

Steps to Reproduce:
1. Config libvirtd log level:

log_level = 1
log_outputs="1:file:/var/log/libvirt/libvirtd.log"

2. Make sure selinux is enforcing.
3. Config the <seclabel> element, and start it.
......
   <seclabel type='static' model='selinux' relabel='ynoes'>
     <label>system_u:system_r:svirt_t:s0:c392,c662</label>
   </seclabel>
......
On rhel7 host:
# virsh start kvm-rhel6.4-x86_64-qcow2-virtio
error: Failed to start domain kvm-rhel6.4-x86_64-qcow2-virtio
error: internal error process exited while connecting to monitor: 2013-04-19 10:36:20.886+0000: 3635: debug : virFileClose:72 : Closed fd 23
2013-04-19 10:36:20.886+0000: 3635: debug : virFileClose:72 : Closed fd 30
2013-04-19 10:36:20.888+0000: 3635: debug : virFileClose:72 : Closed fd 3
2013-04-19 10:36:20.888+0000: 3636: debug : virExec:602 : Run hook 0x7fca68d9b630 0x7fca6e0953a0
2013-04-19 10:36:20.888+0000: 3636: debug : qemuProcessHook:2505 : Obtaining domain lock
2013-04-19 10:36:20.888+0000: 3636: debug : virSecuritySELinuxSetSecuritySocketLabel:2016 : Setting VM kvm-rhel6.4-x86_64-qcow2-virtio socket context system_u:system_r:svirt_t:s0:c392,c662
2013-04-19 10:36:20.888+0000: 3636: debug : virDomainLockProcessStart:170 : plugin=0x7fca6001e0d0 dom=0x7fca602df720 paused=1 fd=0x7fca6e094f4c
2013-04-19 10:36:20.888+0000: 3636: debug : virDomainLockManagerNew:128 : plugin=0x7fca6001e0d0 dom=0x7fca602df720 withResources=1
2013-04-19 10:36:20.888+0000: 3636: debug : virLockManagerPluginGetDriver:297 : plugin=0x7fca6001e0d0
20


On rhel6 host:
# virsh start kvm-rhel6.4-x86_64-qcow2-virtio
error: Failed to start domain kvm-rhel6.4-x86_64-qcow2-virtio
error: internal error process exited while connecting to monitor: 2013-04-19 10:42:30.147+0000: 19121: debug : virFileClose:72 : Closed fd 21
2013-04-19 10:42:30.147+0000: 19121: debug : virFileClose:72 : Closed fd 28
2013-04-19 10:42:30.147+0000: 19121: debug : virFileClose:72 : Closed fd 3
char device redirected to /dev/pts/1
qemu-kvm: -drive file=/var/lib/libvirt/images/kvm-rhel6.4-x86_64-qcow2.img,if=none,id=drive-virtio-disk0,format=qcow2,cache=none: could not open disk image /var/lib/libvirt/images/kvm-rhel6.4-x86_64-qcow2.img: Permission denied

4. If set log_level = 3, and restart libvirtd:
On rhel7 host:
# virsh start kvm-rhel6.4-x86_64-qcow2-virtio
error: Failed to start domain kvm-rhel6.4-x86_64-qcow2-virtio
error: internal error process exited while connecting to monitor: char device redirected to /dev/pts/3 (label charserial0)
qemu-kvm: -drive file=/var/lib/libvirt/images/kvm-rhel6.4-x86_64-qcow2.img,if=none,id=drive-virtio-disk0,format=qcow2,cache=none: could not open disk image /var/lib/libvirt/images/kvm-rhel6.4-x86_64-qcow2.img: Permission denied

On rhel6 host:
# virsh start kvm-rhel6.4-x86_64-qcow2-virtio
error: Failed to start domain kvm-rhel6.4-x86_64-qcow2-virtio
error: internal error process exited while connecting to monitor: char device redirected to /dev/pts/1
qemu-kvm: -drive file=/var/lib/libvirt/images/kvm-rhel6.4-x86_64-qcow2.img,if=none,id=drive-virtio-disk0,format=qcow2,cache=none: could not open disk image /var/lib/libvirt/images/kvm-rhel6.4-x86_64-qcow2.img: Permission denied

  
Actual results:
Step4 outputs are expected results, but step3 need fix

Expected results:
Step3 output should like steps4's

Additional info:

Comment 2 Jiri Denemark 2013-04-22 18:31:12 UTC

Fixed upstream by v1.0.4-232-ge4bdba8 and v1.0.4-233-g6d1b3ed:

commit 6d1b3edc6e3e86567bd88b3e5157a88e49f1b118
Author: Jiri Denemark <jdenemar>
Date:   Mon Apr 22 18:20:21 2013 +0200

    qemu: Ignore libvirt logs when reading QEMU error output
    
    When QEMU fails to start, libvirt read its error output and reports it
    back in an error message. However, when libvirtd is configured to log
    debug messages, one would get the following unhelpful garbage:
    
        virsh # start cd
        error: Failed to start domain cd
        error: internal error process exited while connecting to monitor: \
          2013-04-22 14:24:54.214+0000: 2194219: debug : virFileClose:72 : \
          Closed fd 21
        2013-04-22 14:24:54.214+0000: 2194219: debug : virFileClose:72 : \
          Closed fd 27
        2013-04-22 14:24:54.215+0000: 2194219: debug : virFileClose:72 : \
          Closed fd 3
        2013-04-22 14:24:54.215+0000: 2194220: debug : virExec:602 : Run \
          hook 0x7feb8f600bf0 0x7feb86ef9300
        2013-04-22 14:24:54.215+0000: 2194220: debug : qemuProcessHook:2507 \
          : Obtaining domain lock
        2013-04-22 14:24:54.216+0000: 2194220: debug : \
          virDomainLockProcessStart:170 : plugin=0x7feb780261f0 \
          dom=0x7feb7802a360 paused=1 fd=0x7feb86ef8ec4
        2013-04-22 14:24:54.216+0000: 2194220: debug : \
          virDomainLockManagerNew:128 : plugin=0x7feb780261f0 \
          dom=0x7feb7802a360 withResources=1
        2013-04-22 14:24:54.216+0000: 2194220: debug : \
          virLockManagerPluginGetDriver:297 : plugin=0x7feb780261f0
        2013-04-22 14:24:54.216+0000: 2194220: debug : \
          virLockManagerNew:321 : driver=0x7feb8ef08640 type=0 nparams=5 \
          params=0x7feb86ef8d60 flags=0
        2013-04-22 14:24:54.216+000
    
    instead of (the output with this patch applied):
    
        virsh # start cd
        error: Reconnected to the hypervisor
        error: Failed to start domain cd
        error: internal error process exited while connecting to monitor: \
          char device redirected to /dev/pts/33 (label charserial0)
        qemu-system-x86_64: -drive file=/home/vm/systemrescuecd-x86-1.2.0.\
          iso,if=none,id=drive-ide0-1-0,readonly=on,format=raw,cache=none: \
          could not open disk image /home/vm/systemrescuecd-x86-1.2.0.iso: \
          Permission denied

commit e4bdba8d7f86d2b0ea224b64e336b36ef52f6276
Author: Jiri Denemark <jdenemar>
Date:   Mon Apr 22 18:16:57 2013 +0200

    qemu: Move QEMU log reading into a separate function

Comment 9 Jiri Denemark 2013-06-26 13:08:38 UTC

Backported and sent for review:
http://post-office.corp.redhat.com/archives/rhvirt-patches/2013-June/msg00651.html

Comment 11 yanbing du 2013-07-09 09:36:29 UTC

Hi Jiri,
I'm testing this bug with libvirt-0.10.2-19.el6.x86_64, following the reproduce steps, when start a domain, libvirt reprot:
# virsh start test-vm
error: Failed to start domain test-vm
error: internal error Process exited while reading console log output: 

I think this's inappropriate, as all qemu logs are shielded, what do you think?

Comment 12 yanbing du 2013-08-28 09:00:42 UTC

Test with latest libvirt, when start domain fail, the qemu message can output, so this bug can move to VERIFIED.

# rpm -q libvirt
libvirt-0.10.2-23.el6.x86_64

# virsh start a
error: Failed to start domain a
error: internal error Process exited while reading console log output: char device redirected to /dev/pts/4
qemu-kvm: -drive file=/var/lib/libvirt/images/kvm-rhel6.4-x86_64-qcow2.img,if=none,id=drive-ide0-0-0,format=qcow2,cache=none: could not open disk image /var/lib/libvirt/images/kvm-rhel6.4-x86_64-qcow2.img: Permission denied

Comment 13 Martin Kletzander 2013-11-11 12:48:01 UTC

*** Bug 864773 has been marked as a duplicate of this bug. ***

Comment 15 errata-xmlrpc 2013-11-21 08:59:05 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/RHBA-2013-1581.html