864427 – libvirtd sometimes sets SELinux labels on console sockets after qemu has started running

Bug 864427 - libvirtd sometimes sets SELinux labels on console sockets after qemu has started running

Summary: libvirtd sometimes sets SELinux labels on console sockets after qemu has star...

Keywords:
Status:	CLOSED NOTABUG
Alias:	None
Product:	Virtualization Tools
Classification:	Community
Component:	libguestfs
Sub Component:
Version:	unspecified
Hardware:	Unspecified
OS:	Unspecified
Priority:	unspecified
Severity:	unspecified
Target Milestone:	---
Assignee:	Richard W.M. Jones
QA Contact:
Docs Contact:
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+	depends on / blocked

Reported:	2012-10-09 12:23 UTC by Richard W.M. Jones
Modified:	2012-10-10 10:25 UTC (History)
CC List:	11 users (show)
Fixed In Version:
Doc Type:	Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed:	2012-10-10 10:25:27 UTC
Embargoed:
Dependent Products:

Attachments	(Terms of Use)
libvirtd.log (xz-compressed) (2.43 MB, application/x-xz) 2012-10-09 12:23 UTC, Richard W.M. Jones	no flags	Details
View All

Description Richard W.M. Jones 2012-10-09 12:23:00 UTC

Created attachment 624058 [details]
libvirtd.log (xz-compressed)

Description of problem:

libguestfs test suite sometimes (but not always) fails
in the parallel test-launch-race.pl script.  Examining
libvirtd.log (attached) appears to show libvirtd trying to
set the SELinux label on the console socket after qemu has
started running, and therefore after qemu has failed and
the console socket has been deleted.

Obviously libvirtd should set it before qemu starts running.

In the attached file, look at:

/tmp/whenjobs4dd17406bcb80d1544f4dc7708c03ebc/libguestfs-1.19.49/tmp/M9ZRm53mhB/libguestfs56NJGt/console.sock

and notice when qemu runs relative to when libvirtd tries
to set a label on the socket.

Version-Release number of selected component (if applicable):

libvirt-0.10.2-3.fc19.x86_64
selinux-policy-3.11.1-25.fc18.noarch
SELinux is enforcing

How reproducible:

Unknown, but rare.

Steps to Reproduce:
1. Unknown.

Comment 1 Daniel Berrangé 2012-10-09 13:26:28 UTC

I don't think the description is correct.

The relevant subset of the logs appears to be this:

2012-10-09 11:29:37.450+0000: 21643: debug : qemuProcessStart:3592 : Building emulator command line
2012-10-09 11:29:37.450+0000: 21643: debug : qemuBuildCommandLine:4462 : conn=0x7f00e4001450 driver=0x7f00e80a0f10 def=0x7f00c4004350 mon=0x7f00c40053f0 json=1 caps=0x7f00c4007440 migrateFrom=(null) migrateFD=-1 snapshot=(nil) vmop=0
2012-10-09 11:29:37.450+0000: 21643: debug : cpuDataFree:212 : arch=x86_64, data=(nil)
2012-10-09 11:29:37.453+0000: 21643: warning : qemuDomainObjTaint:1364 : Domain id=144 name='guestfs-jndtm3deo2z0o46v' uuid=63092298-5e9e-aa5a-2294-2b89d9345f5b is tainted: custom-argv
2012-10-09 11:29:37.453+0000: 21643: debug : qemuProcessStart:3637 : Clear emulator capabilities: 1
2012-10-09 11:29:37.453+0000: 21643: debug : virCommandRequireHandshake:2503 : Transfer handshake wait=23 notify=24, keep handshake wait=22 notify=25
2012-10-09 11:29:37.453+0000: 21643: debug : virCommandRunAsync:2224 : About to run LC_ALL=C LD_LIBRARY_PATH=/tmp/whenjobse4288aaad5f4966e9294f3e9e01bf3f6/build-test/src/.libs:/tmp/whenjobse4288aaad5f4966e9294f3e9e01bf3f6/build-test/gobject/.libs:/tmp/whenjobse4288aaad5f4966e9
294f3e9e01bf3f6/build-test/ruby/ext/guestfs PATH=/usr/local/bin:/bin:/usr/bin:/usr/local/sbin:/usr/sbin:/home/rjones/.local/bin:/home/rjones/bin HOME=/home/rjones USER=rjones LOGNAME=rjones TMPDIR=/tmp/whenjobs4dd17406bcb80d1544f4dc7708c03ebc/libguestfs-1.19.49/tmp /bin/qemu-k
vm -name guestfs-jndtm3deo2z0o46v -S -M pc-1.2 -enable-kvm -m 500 -smp 1,sockets=1,cores=1,threads=1 -uuid 63092298-5e9e-aa5a-2294-2b89d9345f5b -nographic -no-user-config -nodefaults -chardev socket,id=charmonitor,path=/home/rjones/.config/libvirt/qemu/lib/guestfs-jndtm3deo2z0
o46v.monitor,server,nowait -mon chardev=charmonitor,id=monitor,mode=control -rtc base=utc -no-reboot -no-shutdown -no-acpi -kernel /tmp/whenjobs4dd17406bcb80d1544f4dc7708c03ebc/libguestfs-1.19.49/tmp/.guestfs-1000/kernel.12900 -initrd /tmp/whenjobs4dd17406bcb80d1544f4dc7708c03
ebc/libguestfs-1.19.49/tmp/.guestfs-1000/initrd.12900 -append 'panic=1 console=ttyS0 udevtimeout=600 no_timer_check acpi=off printk.time=1 cgroup_disable=memory root=/dev/sdb selinux=0  TERM=screen ' -device virtio-scsi-pci,id=scsi0,bus=pci.0,addr=0x3 -device piix3-usb-uhci,id
=usb,bus=pci.0,addr=0x1.0x2 -device virtio-serial-pci,id=virtio-serial0,bus=pci.0,addr=0x4 -drive file=/tmp/whenjobs4dd17406bcb80d1544f4dc7708c03ebc/libguestfs-1.19.49/tests/qemu/test1.img,if=none,id=drive-scsi0-0-0-0,format=raw,cache=none -device scsi-hd,bus=scsi0.0,channel=0
,scsi-id=0,lun=0,drive=drive-scsi0-0-0-0,id=scsi0-0-0-0,bootindex=1 -drive file=/tmp/whenjobs4dd17406bcb80d1544f4dc7708c03ebc/libguestfs-1.19.49/tmp/libguestfsgxB8pA/snapshot1,if=none,id=drive-scsi0-0-1-0,format=qcow2,cache=unsafe -device scsi-hd,bus=scsi0.0,channel=0,scsi-id=
1,lun=0,drive=drive-scsi0-0-1-0,id=scsi0-0-1-0 -chardev socket,id=charserial0,path=/tmp/whenjobs4dd17406bcb80d1544f4dc7708c03ebc/libguestfs-1.19.49/tmp/libguestfsgxB8pA/console.sock -device isa-serial,chardev=charserial0,id=serial0 -chardev socket,id=charchannel0,path=/tmp/whe
njobs4dd17406bcb80d1544f4dc7708c03ebc/libguestfs-1.19.49/tmp/libguestfsgxB8pA/guestfsd.sock -device virtserialport,bus=virtio-serial0.0,nr=1,chardev=charchannel0,id=channel0,name=org.libguestfs.channel.0 -device virtio-balloon-pci,id=balloon0,bus=pci.0,addr=0x5
2012-10-09 11:29:37.462+0000: 21643: debug : virFileClose:72 : Closed fd 26
2012-10-09 11:29:37.462+0000: 21643: debug : virCommandRunAsync:2242 : Command result 0, with PID 12965
2012-10-09 11:29:37.462+0000: 21643: debug : virFileClose:72 : Closed fd 23
2012-10-09 11:29:37.462+0000: 21643: debug : virFileClose:72 : Closed fd 24
2012-10-09 11:29:37.477+0000: 21643: debug : virCommandRun:2040 : Result status 0, stdout: '(null)' stderr: '(null)'
2012-10-09 11:29:37.477+0000: 21643: debug : virFileClose:72 : Closed fd 23
2012-10-09 11:29:37.477+0000: 21643: debug : qemuProcessStart:3684 : Writing early domain status to disk
2012-10-09 11:29:37.477+0000: 21643: debug : virFileClose:72 : Closed fd 23
2012-10-09 11:29:37.478+0000: 21643: debug : qemuProcessStart:3689 : Waiting for handshake from child
2012-10-09 11:29:37.478+0000: 21643: debug : virCommandHandshakeWait:2536 : Wait for handshake on 22
2012-10-09 11:29:37.484+0000: 21643: debug : virFileClose:72 : Closed fd 22
2012-10-09 11:29:37.484+0000: 21643: debug : qemuProcessStart:3694 : Setting domain security labels
2012-10-09 11:29:37.485+0000: 21643: info : virSecuritySELinuxSetFileconHelper:754 : Setting SELinux context on '/tmp/whenjobs4dd17406bcb80d1544f4dc7708c03ebc/libguestfs-1.19.49/tests/qemu/test1.img' to 'unconfined_u:object_r:svirt_image_t:s0:c316,c943'
2012-10-09 11:29:37.489+0000: 21643: debug : virFileClose:72 : Closed fd 22
2012-10-09 11:29:37.489+0000: 21643: info : virSecuritySELinuxSetFileconHelper:754 : Setting SELinux context on '/tmp/whenjobs4dd17406bcb80d1544f4dc7708c03ebc/libguestfs-1.19.49/tmp/libguestfsgxB8pA/snapshot1' to 'system_u:object_r:svirt_image_t:s0'
2012-10-09 11:29:37.491+0000: 21643: debug : virFileClose:72 : Closed fd 22
2012-10-09 11:29:37.491+0000: 21643: info : virSecuritySELinuxSetFileconHelper:754 : Setting SELinux context on '/tmp/whenjobs4dd17406bcb80d1544f4dc7708c03ebc/libguestfs-1.19.49/tmp/.guestfs-1000/root.12900' to 'system_u:object_r:virt_content_t:s0'
2012-10-09 11:29:37.492+0000: 21643: debug : virFileClose:72 : Closed fd 22
2012-10-09 11:29:37.492+0000: 21643: info : virSecuritySELinuxSetFileconHelper:754 : Setting SELinux context on '/tmp/whenjobs4dd17406bcb80d1544f4dc7708c03ebc/libguestfs-1.19.49/tmp/libguestfsgxB8pA/console.sock' to 'unconfined_u:object_r:svirt_image_t:s0:c316,c943'
2012-10-09 11:29:37.493+0000: 21643: info : virSecuritySELinuxSetFileconHelper:754 : Setting SELinux context on '/tmp/whenjobs4dd17406bcb80d1544f4dc7708c03ebc/libguestfs-1.19.49/tmp/libguestfsgxB8pA/guestfsd.sock' to 'unconfined_u:object_r:svirt_image_t:s0:c316,c943'
2012-10-09 11:29:37.493+0000: 21643: info : virSecuritySELinuxSetFileconHelper:754 : Setting SELinux context on '/tmp/whenjobs4dd17406bcb80d1544f4dc7708c03ebc/libguestfs-1.19.49/tmp/.guestfs-1000/kernel.12900' to 'system_u:object_r:virt_content_t:s0'
2012-10-09 11:29:37.494+0000: 21643: info : virSecuritySELinuxSetFileconHelper:754 : Setting SELinux context on '/tmp/whenjobs4dd17406bcb80d1544f4dc7708c03ebc/libguestfs-1.19.49/tmp/.guestfs-1000/initrd.12900' to 'system_u:object_r:virt_content_t:s0'
2012-10-09 11:29:37.494+0000: 21643: debug : qemuProcessStart:3723 : Labelling done, completing handshake to child
2012-10-09 11:29:37.494+0000: 21643: debug : virCommandHandshakeNotify:2603 : Notify handshake on 25
2012-10-09 11:29:37.494+0000: 21643: debug : virFileClose:72 : Closed fd 25
2012-10-09 11:29:37.494+0000: 21643: debug : qemuProcessStart:3727 : Handshake complete, child running
2012-10-09 11:29:37.494+0000: 21643: debug : qemuProcessStart:3738 : Waiting for monitor to show up


The logs might be mis-leading you, because there is a 2-way handshake in the startup process.

 1. Libvirt forks a child process
 2. Child does some basic init and then performs a handshake with libvirtd and waits
 3. libvirtd now sets security labelling and the performs a handshake with the child process
 4. Child process completes the handshake and exec's QEMU

So you are correct that we fork() the child before running labelling, but the handshake means we don't actually exec() QEMU until the handshake is complete. The SELinux domain transition does not occur until the exec() phase.

Comment 2 Richard W.M. Jones 2012-10-09 13:52:26 UTC

Re-assign to libguestfs.  No idea why though ..

Comment 3 Richard W.M. Jones 2012-10-10 10:25:27 UTC

Closing ... I've opened a new bug to track the libguestfs
issue that I see:

https://bugzilla.redhat.com/show_bug.cgi?id=864871

Note You need to log in before you can comment on or make changes to this bug.