Bug 1302088

Summary: Booting VM sometimes hangs entire system (Rawhide)
Product: [Fedora] Fedora Reporter: Adam Williamson <awilliam>
Component: kernelAssignee: Kernel Maintainer List <kernel-maint>
Status: CLOSED WORKSFORME QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: urgent Docs Contact:
Priority: unspecified    
Version: 24CC: awilliam, berrange, crobinso, gansalmon, itamar, jonathan, kernel-maint, madhu.chinakonda, mchehab, virt-maint
Target Milestone: ---   
Target Release: ---   
Hardware: x86_64   
OS: Linux   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2016-03-17 16:04:18 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:

Description Adam Williamson 2016-01-26 18:10:53 UTC 
I apologize for the rather vague report, but I've seen this happen several times now and I can't seem to get a definite handle on it, so I thought it best to report it and see whether you folks have an idea what to do next. (It's very likely not really a virt-manager issue, but I didn't know where else to start).

I run Rawhide on my main system, and use virt-manager to run VMs for testing stuff. It seems like at least four times recently I've tried to boot a VM in virt-manager and it has hung the entire system apparently permanently; the cursor still moves but I can't interact with anything or switch to a VT, and the system doesn't respond to ssh connections, I have to hit the reset switch.

I think, but can't absolutely swear, that this has never happened the *first* time I try to boot a specific VM during a session; it happens on a second or later attempt to boot the same VM.

I'm currently using kernel 4.5.0-0.rc0.git1.2.fc24.x86_64 , I can't use a current kernel because of https://bugzilla.redhat.com/show_bug.cgi?id=1301099 . Otherwise the system is fully up to date with today's Rawhide.

Here's what I have in the journal around the time of one such occurrence, minus a bunch of GTK+ logspam:

Jan 26 10:02:05 adam.happyassassin.net kernel: br1: port 2(vnet0) entered disabled state
Jan 26 10:02:05 adam.happyassassin.net audit: ANOM_PROMISCUOUS dev=vnet0 prom=0 old_prom=256 auid=4294967295 uid=107 gid=107 ses=4294967295
Jan 26 10:02:05 adam.happyassassin.net avahi-daemon[1195]: Interface vnet0.IPv6 no longer relevant for mDNS.
Jan 26 10:02:05 adam.happyassassin.net kernel: device vnet0 left promiscuous mode
Jan 26 10:02:05 adam.happyassassin.net kernel: br1: port 2(vnet0) entered disabled state
Jan 26 10:02:05 adam.happyassassin.net avahi-daemon[1195]: Leaving mDNS multicast group on interface vnet0.IPv6 with address fe80::fc54:ff:fe83:8067.
Jan 26 10:02:05 adam.happyassassin.net avahi-daemon[1195]: Withdrawing address record for fe80::fc54:ff:fe83:8067 on vnet0.
Jan 26 10:02:05 adam.happyassassin.net NetworkManager[1322]: <info>  (vnet0): device state change: activated -> unmanaged (reason 'unmanaged') [100 10 3]
Jan 26 10:02:05 adam.happyassassin.net NetworkManager[1322]: <info>  (br1): bridge port vnet0 was detached
Jan 26 10:02:05 adam.happyassassin.net NetworkManager[1322]: <info>  (vnet0): released from master device br1
Jan 26 10:02:05 adam.happyassassin.net org.gnome.Shell.desktop[2142]: Gjs-Message: JS LOG: Removing a network device that was not added
Jan 26 10:02:05 adam.happyassassin.net audit[1]: USER_AVC pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='Unknown permission stop for class system exe="/usr/lib/systemd/systemd" sauid=0 hostname=? addr=? terminal=?'
Jan 26 10:02:05 adam.happyassassin.net audit[1]: USER_AVC pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='Unknown permission stop for class system exe="/usr/lib/systemd/systemd" sauid=0 hostname=? addr=? terminal=?'
Jan 26 10:02:05 adam.happyassassin.net systemd-machined[5817]: Machine qemu-desktop_test_1 terminated.
Jan 26 10:02:05 adam.happyassassin.net org.gnome.Shell.desktop[2790]: Gjs-Message: JS LOG: Removing a network device that was not added
Jan 26 10:02:05 adam.happyassassin.net sssd_be[1235]: GSSAPI client step 1
Jan 26 10:02:05 adam.happyassassin.net sssd_be[1235]: GSSAPI client step 1
Jan 26 10:02:05 adam.happyassassin.net sssd_be[1235]: GSSAPI client step 1
Jan 26 10:02:05 adam.happyassassin.net audit[1571]: VIRT_CONTROL pid=1571 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:virtd_t:s0-s0:c0.c1023 msg='virt=kvm op=stop reason=destroyed vm="desktop_test_1" uuid=ce7ea685-96bd-4497-ba7a-ec224ab0b9e4 vm-pid=-1 exe="/usr/sbin/libvirtd" hostname=? addr=? terminal=? res=success'
Jan 26 10:02:06 adam.happyassassin.net sssd_be[1235]: GSSAPI client step 2
Jan 26 10:02:10 adam.happyassassin.net org.gnome.OnlineAccounts[2569]: (goa-daemon:2907): GoaBackend-WARNING **: secret_password_lookup_sync() returned NULL
Jan 26 10:02:11 adam.happyassassin.net audit[1571]: VIRT_MACHINE_ID pid=1571 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:virtd_t:s0-s0:c0.c1023 msg='virt=kvm vm="desktop_test_1" uuid=ce7ea685-96bd-4497-ba7a-ec224ab0b9e4 vm-ctx=system_u:system_r:svirt_t:s0:c663,c802 img-ctx=system_u:object_r:svirt_image_t:s0:c663,c802 model=selinux exe="/usr/sbin/libvirtd" hostname=? addr=? terminal=? res=success'
Jan 26 10:02:11 adam.happyassassin.net audit[1571]: VIRT_MACHINE_ID pid=1571 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:virtd_t:s0-s0:c0.c1023 msg='virt=kvm vm="desktop_test_1" uuid=ce7ea685-96bd-4497-ba7a-ec224ab0b9e4 vm-ctx=+107:+107 img-ctx=+107:+107 model=dac exe="/usr/sbin/libvirtd" hostname=? addr=? terminal=? res=success'
Jan 26 10:02:11 adam.happyassassin.net NetworkManager[1322]: <info>  (vnet0): new Tun device (/org/freedesktop/NetworkManager/Devices/6)
Jan 26 10:02:11 adam.happyassassin.net audit: ANOM_PROMISCUOUS dev=vnet0 prom=256 old_prom=0 auid=4294967295 uid=0 gid=0 ses=4294967295
Jan 26 10:02:11 adam.happyassassin.net kernel: device vnet0 entered promiscuous mode
Jan 26 10:02:11 adam.happyassassin.net audit[1571]: VIRT_RESOURCE pid=1571 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:virtd_t:s0-s0:c0.c1023 msg='virt=kvm resrc=net reason=open vm="desktop_test_1" uuid=ce7ea685-96bd-4497-ba7a-ec224ab0b9e4 net=52:54:00:83:80:67 path="/dev/net/tun" rdev=0A:C8 exe="/usr/sbin/libvirtd" hostname=? addr=? terminal=? res=success'
Jan 26 10:02:11 adam.happyassassin.net NetworkManager[1322]: <info>  (vnet0): device state change: unmanaged -> unavailable (reason 'connection-assumed') [10 20 41]
Jan 26 10:02:11 adam.happyassassin.net kernel: br1: port 2(vnet0) entered forwarding state
Jan 26 10:02:11 adam.happyassassin.net kernel: br1: port 2(vnet0) entered forwarding state
Jan 26 10:02:11 adam.happyassassin.net NetworkManager[1322]: <info>  keyfile: add connection in-memory (316c5e8f-7803-458f-ba19-16b8568c0b79,"vnet0")
Jan 26 10:02:11 adam.happyassassin.net NetworkManager[1322]: <info>  (vnet0): device state change: unavailable -> disconnected (reason 'connection-assumed') [20 30 41]
Jan 26 10:02:11 adam.happyassassin.net NetworkManager[1322]: <info>  (vnet0): Activation: starting connection 'vnet0' (316c5e8f-7803-458f-ba19-16b8568c0b79)
Jan 26 10:02:11 adam.happyassassin.net org.gnome.Shell.desktop[2142]: (gnome-shell:2142): libnm-glib-WARNING **: replace_settings: error updating connection /org/freedesktop/NetworkManager/Settings/6 settings: (3) connection.type: requires presence of 'tun' setting in the connection
Jan 26 10:02:11 adam.happyassassin.net org.freedesktop.Telepathy.AccountManager[2569]: (process:2901): libnm-glib-WARNING **: replace_settings: error updating connection /org/freedesktop/NetworkManager/Settings/6 settings: (3) connection.type: requires presence of 'tun' setting in the connection
Jan 26 10:02:11 adam.happyassassin.net org.gnome.Shell.desktop[2142]: (gnome-shell:2142): libnm-glib-WARNING **: replace_settings: error updating connection /org/freedesktop/NetworkManager/Settings/6 settings: (3) connection.type: requires presence of 'tun' setting in the connection
Jan 26 10:02:11 adam.happyassassin.net org.freedesktop.Telepathy.AccountManager[2569]: (process:2901): libnm-glib-WARNING **: replace_settings: error updating connection /org/freedesktop/NetworkManager/Settings/6 settings: (3) connection.type: requires presence of 'tun' setting in the connection
Jan 26 10:02:11 adam.happyassassin.net org.gnome.Shell.desktop[2142]: (gnome-shell:2142): libnm-glib-WARNING **: replace_settings: error updating connection /org/freedesktop/NetworkManager/Settings/6 settings: (3) connection.type: requires presence of 'tun' setting in the connection
Jan 26 10:02:11 adam.happyassassin.net org.gnome.Shell.desktop[2790]: (gnome-shell:2790): libnm-glib-WARNING **: replace_settings: error updating connection /org/freedesktop/NetworkManager/Settings/6 settings: (3) connection.type: requires presence of 'tun' setting in the connection
Jan 26 10:02:11 adam.happyassassin.net org.gnome.Shell.desktop[2790]: (gnome-shell:2790): libnm-glib-WARNING **: replace_settings: error updating connection /org/freedesktop/NetworkManager/Settings/6 settings: (3) connection.type: requires presence of 'tun' setting in the connection
Jan 26 10:02:11 adam.happyassassin.net org.gnome.Shell.desktop[2790]: (gnome-shell:2790): libnm-glib-WARNING **: replace_settings: error updating connection /org/freedesktop/NetworkManager/Settings/6 settings: (3) connection.type: requires presence of 'tun' setting in the connection
Jan 26 10:02:11 adam.happyassassin.net NetworkManager[1322]: <info>  (vnet0): device state change: disconnected -> prepare (reason 'none') [30 40 0]
Jan 26 10:02:11 adam.happyassassin.net NetworkManager[1322]: <info>  (vnet0): device state change: prepare -> config (reason 'none') [40 50 0]
Jan 26 10:02:11 adam.happyassassin.net NetworkManager[1322]: <info>  (vnet0): device state change: config -> ip-config (reason 'none') [50 70 0]
Jan 26 10:02:11 adam.happyassassin.net NetworkManager[1322]: <info>  (br1): bridge port vnet0 was attached
Jan 26 10:02:11 adam.happyassassin.net NetworkManager[1322]: <info>  (vnet0): Activation: connection 'vnet0' enslaved, continuing activation
Jan 26 10:02:11 adam.happyassassin.net NetworkManager[1322]: <info>  (vnet0): device state change: ip-config -> secondaries (reason 'none') [70 90 0]
Jan 26 10:02:11 adam.happyassassin.net NetworkManager[1322]: <info>  (vnet0): device state change: secondaries -> activated (reason 'none') [90 100 0]
Jan 26 10:02:11 adam.happyassassin.net audit[1571]: VIRT_RESOURCE pid=1571 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:virtd_t:s0-s0:c0.c1023 msg='virt=kvm resrc=net reason=open vm="desktop_test_1" uuid=ce7ea685-96bd-4497-ba7a-ec224ab0b9e4 net=52:54:00:83:80:67 path="/dev/vhost-net" rdev=0A:EE exe="/usr/sbin/libvirtd" hostname=? addr=? terminal=? res=success'
Jan 26 10:02:11 adam.happyassassin.net audit[1]: USER_AVC pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='Unknown permission start for class system exe="/usr/lib/systemd/systemd" sauid=0 hostname=? addr=? terminal=?'
Jan 26 10:02:11 adam.happyassassin.net audit[1]: USER_AVC pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='Unknown permission start for class system exe="/usr/lib/systemd/systemd" sauid=0 hostname=? addr=? terminal=?'
Jan 26 10:02:11 adam.happyassassin.net systemd-machined[5817]: New machine qemu-desktop_test_1.
Jan 26 10:02:11 adam.happyassassin.net NetworkManager[1322]: <info>  (vnet0): Activation: successful, device activated.
Jan 26 10:02:11 adam.happyassassin.net org.freedesktop.Telepathy.AccountManager[2569]: (process:2901): libnm-glib-WARNING **: replace_settings: error updating connection /org/freedesktop/NetworkManager/Settings/6 settings: (3) connection.type: requires presence of 'tun' setting in the connection
Jan 26 10:02:11 adam.happyassassin.net org.freedesktop.Telepathy.AccountManager[2569]: (process:2901): libnm-glib-WARNING **: replace_settings: error updating connection /org/freedesktop/NetworkManager/Settings/6 settings: (3) connection.type: requires presence of 'tun' setting in the connection
Jan 26 10:02:11 adam.happyassassin.net systemd[1]: Started Virtual Machine qemu-desktop_test_1.
Jan 26 10:02:11 adam.happyassassin.net org.gnome.Shell.desktop[2790]: (gnome-shell:2790): libnm-glib-WARNING **: replace_settings: error updating connection /org/freedesktop/NetworkManager/Settings/6 settings: (3) connection.type: requires presence of 'tun' setting in the connection
Jan 26 10:02:11 adam.happyassassin.net org.gnome.Shell.desktop[2790]: (gnome-shell:2790): libnm-glib-WARNING **: replace_settings: error updating connection /org/freedesktop/NetworkManager/Settings/6 settings: (3) connection.type: requires presence of 'tun' setting in the connection
Jan 26 10:02:11 adam.happyassassin.net org.gnome.Shell.desktop[2790]: (gnome-shell:2790): libnm-glib-WARNING **: replace_settings: error updating connection /org/freedesktop/NetworkManager/Settings/6 settings: (3) connection.type: requires presence of 'tun' setting in the connection
Jan 26 10:02:11 adam.happyassassin.net org.gnome.Shell.desktop[2142]: (gnome-shell:2142): libnm-glib-WARNING **: replace_settings: error updating connection /org/freedesktop/NetworkManager/Settings/6 settings: (3) connection.type: requires presence of 'tun' setting in the connection
Jan 26 10:02:11 adam.happyassassin.net org.gnome.Shell.desktop[2142]: (gnome-shell:2142): libnm-glib-WARNING **: replace_settings: error updating connection /org/freedesktop/NetworkManager/Settings/6 settings: (3) connection.type: requires presence of 'tun' setting in the connection
Jan 26 10:02:11 adam.happyassassin.net org.gnome.Shell.desktop[2142]: (gnome-shell:2142): libnm-glib-WARNING **: replace_settings: error updating connection /org/freedesktop/NetworkManager/Settings/6 settings: (3) connection.type: requires presence of 'tun' setting in the connection
Jan 26 10:02:11 adam.happyassassin.net audit[1571]: VIRT_RESOURCE pid=1571 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:virtd_t:s0-s0:c0.c1023 msg='virt=kvm resrc=cgroup reason=deny vm="desktop_test_1" uuid=ce7ea685-96bd-4497-ba7a-ec224ab0b9e4 cgroup="/sys/fs/cgroup/devices/machine.slice/machine-qemu\x2ddesktop_test_1.scope/" class=all exe="/usr/sbin/libvirtd" hostname=? addr=? terminal=? res=success'
Jan 26 10:02:11 adam.happyassassin.net audit[1571]: VIRT_RESOURCE pid=1571 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:virtd_t:s0-s0:c0.c1023 msg='virt=kvm resrc=cgroup reason=allow vm="desktop_test_1" uuid=ce7ea685-96bd-4497-ba7a-ec224ab0b9e4 cgroup="/sys/fs/cgroup/devices/machine.slice/machine-qemu\x2ddesktop_test_1.scope/" class=path path="/share/data/isos/24/nightlies/Rawhide_20160126_generic_i686_boot.iso" rdev=? acl=r exe="/usr/sbin/libvirtd" hostname=? addr=? terminal=? res=success'
Jan 26 10:02:11 adam.happyassassin.net audit[1571]: VIRT_RESOURCE pid=1571 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:virtd_t:s0-s0:c0.c1023 msg='virt=kvm resrc=cgroup reason=allow vm="desktop_test_1" uuid=ce7ea685-96bd-4497-ba7a-ec224ab0b9e4 cgroup="/sys/fs/cgroup/devices/machine.slice/machine-qemu\x2ddesktop_test_1.scope/" class=path path="/share/data/isos/vms/desktop_test_1.qcow2" rdev=? acl=rw exe="/usr/sbin/libvirtd" hostname=? addr=? terminal=? res=success'
Jan 26 10:02:11 adam.happyassassin.net audit[1571]: VIRT_RESOURCE pid=1571 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:virtd_t:s0-s0:c0.c1023 msg='virt=kvm resrc=cgroup reason=allow vm="desktop_test_1" uuid=ce7ea685-96bd-4497-ba7a-ec224ab0b9e4 cgroup="/sys/fs/cgroup/devices/machine.slice/machine-qemu\x2ddesktop_test_1.scope/" class=major category=pty maj=88 acl=rw exe="/usr/sbin/libvirtd" hostname=? addr=? terminal=? res=success'
Comment 1 Cole Robinson 2016-01-27 14:57:59 UTC 
I haven't heard anything. I assume it's a kernel issue if things fall over that spectacularly. Once that other kernel bug is fixed can you report results with rc1 or later?
Comment 2 Jan Kurik 2016-02-24 15:29:56 UTC 
This bug appears to have been reported against 'rawhide' during the Fedora 24 development cycle.
Changing version to '24'.

More information and reason for this action is here:
https://fedoraproject.org/wiki/Fedora_Program_Management/HouseKeeping/Fedora24#Rawhide_Rebase
Comment 3 Cole Robinson 2016-03-16 22:04:32 UTC 
adam still seeing this with latest kernels?
Comment 4 Adam Williamson 2016-03-17 16:04:18 UTC 
No, not recently...let's say it's fixed. (where's the "magic pixies" resolution?)