[Qemu-devel] [Bug 1731957] [NEW] qemu-kvm exits with console permission problems

[Vladislav Belogrudov]

Public bug reported:

# rpm -qa | grep qemu
qemu-img-ev-2.9.0-16.el7_4.8.1.x86_64
qemu-kvm-ev-2.9.0-16.el7_4.8.1.x86_64
ipxe-roms-qemu-20170123-1.git4e85b27.el7_4.1.noarch
libvirt-daemon-driver-qemu-3.2.0-14.el7_4.3.x86_64
qemu-kvm-common-ev-2.9.0-16.el7_4.8.1.x86_64

qemu.conf:
stdio_handler = "file"

libvirtd runs as root with '/usr/sbin/libvirtd --listen'

we run openstack, it creates an instance like this:

2017-11-13 15:17:14.143+0000: starting up libvirt version: 3.2.0, package: 
14.el7_4.3 (Unknown, 2017-09-05-02:55:29, x86-ol7-builder
-02.us.oracle.com), qemu version: 2.9.0(qemu-kvm-ev-2.9.0-16.el7_4.8.1), 
hostname: compute6
LC_ALL=C PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin 
HOME=/root QEMU_AUDIO_DRV=none /usr/libexec/qemu-kvm -name 
guest=instance-00000016,debug-threads=on -S -object 
secret,id=masterKey0,format=raw,file=/var/lib/libvirt/qemu/domain-1-instance-00000016/master-key.aes
 -machine pc-i440fx-rhel7.4.0,accel=kvm,usb=off,dump-guest-core=off -cpu 
Haswell-noTSX,vme=on,ss=on,f16c=on,rdrand=on,hypervisor=on,arat=on,tsc_adjust=on,xsaveopt=on,abm=on,invpcid=off
 -m 64 -realtime mlock=off -smp 1,sockets=1,cores=1,threads=1 -uuid 
48ea957f-6fbc-4b43-83c8-8c5e83a2ffdf -smbios 'type=1,manufacturer=OpenStack 
Foundation,product=OpenStack 
Nova,version=13.0.0,serial=de115ee2-a86f-432d-96fe-bec91b0a5748,uuid=48ea957f-6fbc-4b43-83c8-8c5e83a2ffdf,family=Virtual
 Machine' -no-user-config -nodefaults -chardev 
socket,id=charmonitor,path=/var/lib/libvirt/qemu/domain-1-instance-00000016/monitor.sock,server,nowait
 -mon chardev=charmonitor,id=monitor,mode=control -rtc base=utc,driftfix=slew 
-global kvm-pit.lost_tick_policy=delay -no-hpet -no-shutdown -boot
 strict=on -device piix3-usb-uhci,id=usb,bus=pci.0,addr=0x1.0x2 -drive 
file=/var/lib/nova/instances/48ea957f-6fbc-4b43-83c8-8c5e83a2ffdf/disk,format=qcow2,if=none,id=drive-virtio-disk0,cache=none
 -device 
virtio-blk-pci,scsi=off,bus=pci.0,addr=0x4,drive=drive-virtio-disk0,id=virtio-disk0,bootindex=1
 -netdev tap,fd=26,id=hostnet0,vhost=on,vhostfd=27 -device 
virtio-net-pci,netdev=hostnet0,id=net0,mac=fa:16:3e:bf:f5:40,bus=pci.0,addr=0x3 
-chardev 
pty,id=charserial0,logfile=/var/lib/nova/instances/48ea957f-6fbc-4b43-83c8-8c5e83
a2ffdf/console.log,logappend=off -device 
isa-serial,chardev=charserial0,id=serial0 -device 
usb-tablet,id=input0,bus=usb.0,port=1 -vnc 0.0.0.0:1 -k en-us -device 
cirrus-vga,id=video0,bus=pci.0,addr=0x2 -device 
virtio-balloon-pci,id=balloon0,bus=pci.0,addr=0x5 -msg 
timestamp=on

With older qemu like 2.5 or 2.6 console log belongs to qemu:qemu and the 
process starts successfully.
With 2.9 it fails and console.log is left root:root :

2017-11-13 15:17:14.173+0000: 26010: debug : qemuProcessHook:2738 : Hook 
complete ret=0
2017-11-13 15:17:14.173+0000: 26010: debug : virExec:699 : Done hook 0
2017-11-13 15:17:14.173+0000: 26010: debug : virExec:736 : Setting child 
uid:gid to 42427:42427 with caps 0
2017-11-13 15:17:14.173+0000: 26010: debug : virCommandHandshakeChild:435 : 
Notifying parent for handshake start on 29
2017-11-13 15:17:14.173+0000: 26010: debug : virCommandHandshakeChild:443 : 
Waiting on parent for handshake complete on 30
2017-11-13 15:17:14.192+0000: 26010: debug : virFileClose:110 : Closed fd 29
2017-11-13 15:17:14.192+0000: 26010: debug : virFileClose:110 : Closed fd 30
2017-11-13 15:17:14.192+0000: 26010: debug : virCommandHandshakeChild:463 : 
Handshake with parent is done
2017-11-13T15:17:14.232713Z qemu-kvm: -chardev 
pty,id=charserial0,logfile=/var/lib/nova/instances/48ea957f-6fbc-4b43-83c8-8c5e83a2ffdf/console.log,logappend=off:
 Unable to open logfile 
/var/lib/nova/instances/48ea957f-6fbc-4b43-83c8-8c5e83a2ffdf/console.log: 
Permission denied
2017-11-13 15:17:14.321+0000: shutting down, reason=failed

** Affects: qemu
     Importance: Undecided
         Status: New

-- 
You received this bug notification because you are a member of qemu-
devel-ml, which is subscribed to QEMU.
https://bugs.launchpad.net/bugs/1731957

Title:
  qemu-kvm exits with console permission problems

Status in QEMU:
  New

Bug description:
  # rpm -qa | grep qemu
  qemu-img-ev-2.9.0-16.el7_4.8.1.x86_64
  qemu-kvm-ev-2.9.0-16.el7_4.8.1.x86_64
  ipxe-roms-qemu-20170123-1.git4e85b27.el7_4.1.noarch
  libvirt-daemon-driver-qemu-3.2.0-14.el7_4.3.x86_64
  qemu-kvm-common-ev-2.9.0-16.el7_4.8.1.x86_64

  qemu.conf:
  stdio_handler = "file"

  libvirtd runs as root with '/usr/sbin/libvirtd --listen'

  we run openstack, it creates an instance like this:

  2017-11-13 15:17:14.143+0000: starting up libvirt version: 3.2.0, package: 
14.el7_4.3 (Unknown, 2017-09-05-02:55:29, x86-ol7-builder
  -02.us.oracle.com), qemu version: 2.9.0(qemu-kvm-ev-2.9.0-16.el7_4.8.1), 
hostname: compute6
  LC_ALL=C PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin 
HOME=/root QEMU_AUDIO_DRV=none /usr/libexec/qemu-kvm -name 
guest=instance-00000016,debug-threads=on -S -object 
secret,id=masterKey0,format=raw,file=/var/lib/libvirt/qemu/domain-1-instance-00000016/master-key.aes
 -machine pc-i440fx-rhel7.4.0,accel=kvm,usb=off,dump-guest-core=off -cpu 
Haswell-noTSX,vme=on,ss=on,f16c=on,rdrand=on,hypervisor=on,arat=on,tsc_adjust=on,xsaveopt=on,abm=on,invpcid=off
 -m 64 -realtime mlock=off -smp 1,sockets=1,cores=1,threads=1 -uuid 
48ea957f-6fbc-4b43-83c8-8c5e83a2ffdf -smbios 'type=1,manufacturer=OpenStack 
Foundation,product=OpenStack 
Nova,version=13.0.0,serial=de115ee2-a86f-432d-96fe-bec91b0a5748,uuid=48ea957f-6fbc-4b43-83c8-8c5e83a2ffdf,family=Virtual
 Machine' -no-user-config -nodefaults -chardev 
socket,id=charmonitor,path=/var/lib/libvirt/qemu/domain-1-instance-00000016/monitor.sock,server,nowait
 -mon chardev=charmonitor,id=monitor,mode=control -rtc base=utc,driftfix=slew 
-global kvm-pit.lost_tick_policy=delay -no-hpet -no-shutdown -boot
   strict=on -device piix3-usb-uhci,id=usb,bus=pci.0,addr=0x1.0x2 -drive 
file=/var/lib/nova/instances/48ea957f-6fbc-4b43-83c8-8c5e83a2ffdf/disk,format=qcow2,if=none,id=drive-virtio-disk0,cache=none
 -device 
virtio-blk-pci,scsi=off,bus=pci.0,addr=0x4,drive=drive-virtio-disk0,id=virtio-disk0,bootindex=1
 -netdev tap,fd=26,id=hostnet0,vhost=on,vhostfd=27 -device 
virtio-net-pci,netdev=hostnet0,id=net0,mac=fa:16:3e:bf:f5:40,bus=pci.0,addr=0x3 
-chardev 
pty,id=charserial0,logfile=/var/lib/nova/instances/48ea957f-6fbc-4b43-83c8-8c5e83
  a2ffdf/console.log,logappend=off -device 
isa-serial,chardev=charserial0,id=serial0 -device 
usb-tablet,id=input0,bus=usb.0,port=1 -vnc 0.0.0.0:1 -k en-us -device 
cirrus-vga,id=video0,bus=pci.0,addr=0x2 -device 
virtio-balloon-pci,id=balloon0,bus=pci.0,addr=0x5 -msg 
  timestamp=on

  With older qemu like 2.5 or 2.6 console log belongs to qemu:qemu and the 
process starts successfully.
  With 2.9 it fails and console.log is left root:root :

  2017-11-13 15:17:14.173+0000: 26010: debug : qemuProcessHook:2738 : Hook 
complete ret=0
  2017-11-13 15:17:14.173+0000: 26010: debug : virExec:699 : Done hook 0
  2017-11-13 15:17:14.173+0000: 26010: debug : virExec:736 : Setting child 
uid:gid to 42427:42427 with caps 0
  2017-11-13 15:17:14.173+0000: 26010: debug : virCommandHandshakeChild:435 : 
Notifying parent for handshake start on 29
  2017-11-13 15:17:14.173+0000: 26010: debug : virCommandHandshakeChild:443 : 
Waiting on parent for handshake complete on 30
  2017-11-13 15:17:14.192+0000: 26010: debug : virFileClose:110 : Closed fd 29
  2017-11-13 15:17:14.192+0000: 26010: debug : virFileClose:110 : Closed fd 30
  2017-11-13 15:17:14.192+0000: 26010: debug : virCommandHandshakeChild:463 : 
Handshake with parent is done
  2017-11-13T15:17:14.232713Z qemu-kvm: -chardev 
pty,id=charserial0,logfile=/var/lib/nova/instances/48ea957f-6fbc-4b43-83c8-8c5e83a2ffdf/console.log,logappend=off:
 Unable to open logfile 
/var/lib/nova/instances/48ea957f-6fbc-4b43-83c8-8c5e83a2ffdf/console.log: 
Permission denied
  2017-11-13 15:17:14.321+0000: shutting down, reason=failed

To manage notifications about this bug go to:
https://bugs.launchpad.net/qemu/+bug/1731957/+subscriptions