Description of problem: Create a VM from vm-template-fedora either via UI or via Cli, the VMI is keeping restarting. It does not happen if it's a Cirros VM. Is it the fedora container image issue? $ oc logs virt-launcher-fedora30-n2t6x -c compute {"component":"virt-launcher","level":"info","msg":"Collected all requested hook sidecar sockets","pos":"manager.go:68","timestamp":"2019-12-05T02:38:52.044015Z"} {"component":"virt-launcher","level":"info","msg":"Sorted all collected sidecar sockets per hook point based on their priority and name: map[]","pos":"manager.go:71","timestamp":"2019-12-05T02:38:52.044136Z"} {"component":"virt-launcher","level":"info","msg":"Watchdog file created at /var/run/kubevirt/watchdog-files/openshift-cnv_fedora30","pos":"virt-launcher.go:142","timestamp":"2019-12-05T02:38:52.045204Z"} {"component":"virt-launcher","level":"info","msg":"Connecting to libvirt daemon: qemu:///system","pos":"libvirt.go:354","timestamp":"2019-12-05T02:38:52.057380Z"} {"component":"virt-launcher","level":"info","msg":"Connecting to libvirt daemon failed: virError(Code=38, Domain=7, Message='Failed to connect socket to '/var/run/libvirt/libvirt-sock': No such file or directory')","pos":"libvirt.go:362","timestamp":"2019-12-05T02:38:52.057919Z"} {"component":"virt-launcher","level":"info","msg":"libvirt version: 5.6.0, package: 6.module+el8.1.0+4244+9aa4e6bb (Red Hat, Inc. \u003chttp://bugzilla.redhat.com/bugzilla\u003e, 2019-09-19-17:11:14, )","subcomponent":"libvirt","thread":"42","timestamp":"2019-12-05T02:38:52.158000Z"} {"component":"virt-launcher","level":"info","msg":"hostname: fedora30","subcomponent":"libvirt","thread":"42","timestamp":"2019-12-05T02:38:52.158000Z"} {"component":"virt-launcher","level":"error","msg":"internal error: Unable to get DBus system bus connection: Failed to connect to socket /run/dbus/system_bus_socket: No such file or directory","pos":"virDBusGetSystemBus:110","subcomponent":"libvirt","thread":"42","timestamp":"2019-12-05T02:38:52.158000Z"} {"component":"virt-launcher","level":"error","msg":"internal error: Unable to get DBus system bus connection: Failed to connect to socket /run/dbus/system_bus_socket: No such file or directory","pos":"virDBusGetSystemBus:110","subcomponent":"libvirt","thread":"42","timestamp":"2019-12-05T02:38:52.171000Z"} {"component":"virt-launcher","level":"warning","msg":"DBus not available, disabling firewalld support in bridge_network_driver: internal error: Unable to get DBus system bus connection: Failed to connect to socket /run/dbus/system_bus_socket: No such file or directory","pos":"networkStateInitialize:828","subcomponent":"libvirt","thread":"42","timestamp":"2019-12-05T02:38:52.172000Z"} {"component":"virt-launcher","level":"error","msg":"internal error: Child process (/usr/sbin/dmidecode -q -t 0,1,2,3,4,17) unexpected exit status 1: /dev/mem: No such file or directory","pos":"virCommandWait:2796","subcomponent":"libvirt","thread":"42","timestamp":"2019-12-05T02:38:52.206000Z"} {"component":"virt-launcher","level":"error","msg":"Failed to open config space file '/sys/bus/pci/devices/0000:00:00.0/config': Read-only file system","pos":"virPCIDeviceConfigOpen:305","subcomponent":"libvirt","thread":"46","timestamp":"2019-12-05T02:38:52.215000Z"} {"component":"virt-launcher","level":"error","msg":"Failed to open config space file '/sys/bus/pci/devices/0000:00:01.0/config': Read-only file system","pos":"virPCIDeviceConfigOpen:305","subcomponent":"libvirt","thread":"46","timestamp":"2019-12-05T02:38:52.216000Z"} {"component":"virt-launcher","level":"error","msg":"Failed to open config space file '/sys/bus/pci/devices/0000:00:01.1/config': Read-only file system","pos":"virPCIDeviceConfigOpen:305","subcomponent":"libvirt","thread":"46","timestamp":"2019-12-05T02:38:52.216000Z"} {"component":"virt-launcher","level":"error","msg":"Failed to open config space file '/sys/bus/pci/devices/0000:00:01.2/config': Read-only file system","pos":"virPCIDeviceConfigOpen:305","subcomponent":"libvirt","thread":"46","timestamp":"2019-12-05T02:38:52.217000Z"} {"component":"virt-launcher","level":"error","msg":"Failed to open config space file '/sys/bus/pci/devices/0000:00:01.3/config': Read-only file system","pos":"virPCIDeviceConfigOpen:305","subcomponent":"libvirt","thread":"46","timestamp":"2019-12-05T02:38:52.218000Z"} {"component":"virt-launcher","level":"error","msg":"Failed to open config space file '/sys/bus/pci/devices/0000:00:02.0/config': Read-only file system","pos":"virPCIDeviceConfigOpen:305","subcomponent":"libvirt","thread":"46","timestamp":"2019-12-05T02:38:52.221000Z"} {"component":"virt-launcher","level":"error","msg":"Failed to open config space file '/sys/bus/pci/devices/0000:00:03.0/config': Read-only file system","pos":"virPCIDeviceConfigOpen:305","subcomponent":"libvirt","thread":"46","timestamp":"2019-12-05T02:38:52.225000Z"} {"component":"virt-launcher","level":"error","msg":"Failed to open config space file '/sys/bus/pci/devices/0000:00:04.0/config': Read-only file system","pos":"virPCIDeviceConfigOpen:305","subcomponent":"libvirt","thread":"46","timestamp":"2019-12-05T02:38:52.225000Z"} {"component":"virt-launcher","level":"error","msg":"Failed to open config space file '/sys/bus/pci/devices/0000:00:05.0/config': Read-only file system","pos":"virPCIDeviceConfigOpen:305","subcomponent":"libvirt","thread":"46","timestamp":"2019-12-05T02:38:52.226000Z"} {"component":"virt-launcher","level":"error","msg":"Failed to open config space file '/sys/bus/pci/devices/0000:00:06.0/config': Read-only file system","pos":"virPCIDeviceConfigOpen:305","subcomponent":"libvirt","thread":"46","timestamp":"2019-12-05T02:38:52.227000Z"} {"component":"virt-launcher","level":"error","msg":"Failed to open config space file '/sys/bus/pci/devices/0000:00:07.0/config': Read-only file system","pos":"virPCIDeviceConfigOpen:305","subcomponent":"libvirt","thread":"46","timestamp":"2019-12-05T02:38:52.228000Z"} {"component":"virt-launcher","level":"error","msg":"Failed to open config space file '/sys/bus/pci/devices/0000:00:08.0/config': Read-only file system","pos":"virPCIDeviceConfigOpen:305","subcomponent":"libvirt","thread":"46","timestamp":"2019-12-05T02:38:52.228000Z"} {"component":"virt-launcher","level":"error","msg":"Failed to open config space file '/sys/bus/pci/devices/0000:00:09.0/config': Read-only file system","pos":"virPCIDeviceConfigOpen:305","subcomponent":"libvirt","thread":"46","timestamp":"2019-12-05T02:38:52.228000Z"} {"component":"virt-launcher","level":"error","msg":"Failed to open config space file '/sys/bus/pci/devices/0000:00:0a.0/config': Read-only file system","pos":"virPCIDeviceConfigOpen:305","subcomponent":"libvirt","thread":"46","timestamp":"2019-12-05T02:38:52.229000Z"} {"component":"virt-launcher","level":"error","msg":"Failed to open config space file '/sys/bus/pci/devices/0000:00:0b.0/config': Read-only file system","pos":"virPCIDeviceConfigOpen:305","subcomponent":"libvirt","thread":"46","timestamp":"2019-12-05T02:38:52.229000Z"} {"component":"virt-launcher","level":"error","msg":"Failed to open config space file '/sys/bus/pci/devices/0000:00:0c.0/config': Read-only file system","pos":"virPCIDeviceConfigOpen:305","subcomponent":"libvirt","thread":"46","timestamp":"2019-12-05T02:38:52.230000Z"} {"component":"virt-launcher","level":"info","msg":"Connected to libvirt daemon","pos":"libvirt.go:370","timestamp":"2019-12-05T02:38:52.559896Z"} {"component":"virt-launcher","level":"info","msg":"Registered libvirt event notify callback","pos":"client.go:292","timestamp":"2019-12-05T02:38:52.564266Z"} {"component":"virt-launcher","level":"info","msg":"Marked as ready","pos":"virt-launcher.go:72","timestamp":"2019-12-05T02:38:52.564697Z"} {"component":"virt-launcher","kind":"","level":"info","msg":"Executing PreStartHook on VMI pod environment","name":"fedora30","namespace":"openshift-cnv","pos":"manager.go:733","timestamp":"2019-12-05T02:38:55.362622Z","uid":"9ca8d488-0287-4727-b4b7-24e87cfffb86"} {"component":"virt-launcher","kind":"","level":"info","msg":"Starting PreCloudInitIso hook","name":"fedora30","namespace":"openshift-cnv","pos":"manager.go:742","timestamp":"2019-12-05T02:38:55.362682Z","uid":"9ca8d488-0287-4727-b4b7-24e87cfffb86"} {"component":"virt-launcher","level":"info","msg":"generated nocloud iso file /var/run/kubevirt-ephemeral-disks/cloud-init-data/openshift-cnv/fedora30/noCloud.iso","pos":"cloud-init.go:444","timestamp":"2019-12-05T02:38:55.369424Z"} {"component":"virt-launcher","kind":"","level":"info","msg":"masquerade pod interface: VIF: { Name: eth0, IP: 10.0.2.2, Mask: ffffff00, MAC: 02:00:00:4b:48:7a, Gateway: 10.0.2.1, MTU: 1400}","name":"fedora30","namespace":"openshift-cnv","pos":"podinterface.go:446","timestamp":"2019-12-05T02:38:55.417095Z","uid":"9ca8d488-0287-4727-b4b7-24e87cfffb86"} {"component":"virt-launcher","level":"info","msg":"Found nameservers in /etc/resolv.conf: \ufffd\u001e\u0000\n","pos":"converter.go:1491","timestamp":"2019-12-05T02:38:55.417245Z"} {"component":"virt-launcher","level":"info","msg":"Found search domains in /etc/resolv.conf: openshift-cnv.svc.cluster.local svc.cluster.local cluster.local openstacklocal","pos":"converter.go:1492","timestamp":"2019-12-05T02:38:55.417276Z"} {"component":"virt-launcher","level":"info","msg":"Starting SingleClientDHCPServer","pos":"dhcp.go:64","timestamp":"2019-12-05T02:38:55.417427Z"} {"component":"virt-launcher","level":"info","msg":"Driver cache mode for /var/run/kubevirt-ephemeral-disks/disk-data/containerdisk/disk.qcow2 set to none","pos":"converter.go:174","timestamp":"2019-12-05T02:38:55.433605Z"} {"component":"virt-launcher","level":"info","msg":"Driver cache mode for /var/run/kubevirt-ephemeral-disks/cloud-init-data/openshift-cnv/fedora30/noCloud.iso set to none","pos":"converter.go:174","timestamp":"2019-12-05T02:38:55.433671Z"} {"component":"virt-launcher","kind":"","level":"info","msg":"Domain defined.","name":"fedora30","namespace":"openshift-cnv","pos":"manager.go:993","timestamp":"2019-12-05T02:38:55.440369Z","uid":"9ca8d488-0287-4727-b4b7-24e87cfffb86"} {"component":"virt-launcher","level":"info","msg":"DomainLifecycle event 0 with reason 0 received","pos":"client.go:257","timestamp":"2019-12-05T02:38:55.440523Z"} {"component":"virt-launcher","level":"error","msg":"internal error: Unable to get DBus system bus connection: Failed to connect to socket /run/dbus/system_bus_socket: No such file or directory","pos":"virDBusGetSystemBus:110","subcomponent":"libvirt","thread":"29","timestamp":"2019-12-05T02:38:55.445000Z"} {"component":"virt-launcher","level":"warning","msg":"Failed to send audit message virt=kvm vm=\"openshift-cnv_fedora30\" uuid=2b875431-d438-53e2-bcf1-d3c27729be0d vm-ctx=+107:+107 img-ctx=+107:+107 model=dac: Permission denied","pos":"virAuditSend:142","subcomponent":"libvirt","thread":"29","timestamp":"2019-12-05T02:38:55.446000Z"} {"component":"virt-launcher","level":"warning","msg":"Failed to send audit message virt=kvm resrc=net reason=open vm=\"openshift-cnv_fedora30\" uuid=2b875431-d438-53e2-bcf1-d3c27729be0d net=02:00:00:4b:48:7a path=\"/dev/net/tun\" rdev=0A:C8: Permission denied","pos":"virAuditSend:142","subcomponent":"libvirt","thread":"29","timestamp":"2019-12-05T02:38:55.479000Z"} {"component":"virt-launcher","level":"warning","msg":"Failed to send audit message virt=kvm resrc=net reason=open vm=\"openshift-cnv_fedora30\" uuid=2b875431-d438-53e2-bcf1-d3c27729be0d net=02:00:00:4b:48:7a path=\"/dev/vhost-net\" rdev=0A:EE: Permission denied","pos":"virAuditSend:142","subcomponent":"libvirt","thread":"29","timestamp":"2019-12-05T02:38:55.479000Z"} {"component":"virt-launcher","level":"error","msg":"At least one cgroup controller is required: No such device or address","pos":"virCgroupDetect:420","subcomponent":"libvirt","thread":"29","timestamp":"2019-12-05T02:38:55.488000Z"} {"component":"virt-launcher","level":"info","msg":"kubevirt domain status: Paused(3):StartingUp(11)","pos":"client.go:180","timestamp":"2019-12-05T02:38:55.493529Z"} {"component":"virt-launcher","level":"info","msg":"Detected domain with UUID 2b875431-d438-53e2-bcf1-d3c27729be0d","pos":"virt-launcher.go:233","timestamp":"2019-12-05T02:38:55.497192Z"} {"component":"virt-launcher","level":"info","msg":"Monitoring loop: rate 1s start timeout 5m0s","pos":"monitor.go:237","timestamp":"2019-12-05T02:38:55.497244Z"} {"component":"virt-launcher","level":"info","msg":"processed event","pos":"client.go:242","timestamp":"2019-12-05T02:38:55.498199Z"} {"component":"virt-launcher","level":"info","msg":"GuestAgentLifecycle event state 2 with reason 1 received","pos":"client.go:275","timestamp":"2019-12-05T02:38:55.652032Z"} {"component":"virt-launcher","level":"info","msg":"kubevirt domain status: Paused(3):StartingUp(11)","pos":"client.go:180","timestamp":"2019-12-05T02:38:55.665395Z"} {"component":"virt-launcher","level":"info","msg":"processed event","pos":"client.go:242","timestamp":"2019-12-05T02:38:55.669421Z"} {"component":"virt-launcher","level":"info","msg":"DomainLifecycle event 4 with reason 0 received","pos":"client.go:257","timestamp":"2019-12-05T02:38:55.930413Z"} {"component":"virt-launcher","level":"warning","msg":"Failed to send audit message virt=kvm resrc=disk reason=start vm=\"openshift-cnv_fedora30\" uuid=2b875431-d438-53e2-bcf1-d3c27729be0d old-disk=\"?\" new-disk=\"/var/run/kubevirt-ephemeral-disks/disk-data/containerdisk/disk.qcow2\": Permission denied","pos":"virAuditSend:142","subcomponent":"libvirt","thread":"29","timestamp":"2019-12-05T02:38:55.931000Z"} {"component":"virt-launcher","level":"warning","msg":"Failed to send audit message virt=kvm resrc=disk reason=start vm=\"openshift-cnv_fedora30\" uuid=2b875431-d438-53e2-bcf1-d3c27729be0d old-disk=\"?\" new-disk=\"/var/run/kubevirt-ephemeral-disks/cloud-init-data/openshift-cnv/fedora30/noCloud.iso\": Permission denied","pos":"virAuditSend:142","subcomponent":"libvirt","thread":"29","timestamp":"2019-12-05T02:38:55.931000Z"} {"component":"virt-launcher","level":"warning","msg":"Failed to send audit message virt=kvm resrc=net reason=start vm=\"openshift-cnv_fedora30\" uuid=2b875431-d438-53e2-bcf1-d3c27729be0d old-net=\"?\" new-net=\"02:00:00:4b:48:7a\": Permission denied","pos":"virAuditSend:142","subcomponent":"libvirt","thread":"29","timestamp":"2019-12-05T02:38:55.931000Z"} {"component":"virt-launcher","level":"warning","msg":"Failed to send audit message virt=kvm resrc=chardev reason=start vm=\"openshift-cnv_fedora30\" uuid=2b875431-d438-53e2-bcf1-d3c27729be0d old-chardev=\"?\" new-chardev=\"/var/run/kubevirt-private/9ca8d488-0287-4727-b4b7-24e87cfffb86/virt-serial0\": Permission denied","pos":"virAuditSend:142","subcomponent":"libvirt","thread":"29","timestamp":"2019-12-05T02:38:55.931000Z"} {"component":"virt-launcher","level":"warning","msg":"Failed to send audit message virt=kvm resrc=chardev reason=start vm=\"openshift-cnv_fedora30\" uuid=2b875431-d438-53e2-bcf1-d3c27729be0d old-chardev=\"?\" new-chardev=\"/var/lib/libvirt/qemu/channel/target/domain-1-openshift-cnv_fedora/org.qemu.guest_agent.0\": Permission denied","pos":"virAuditSend:142","subcomponent":"libvirt","thread":"29","timestamp":"2019-12-05T02:38:55.931000Z"} {"component":"virt-launcher","level":"warning","msg":"Failed to send audit message virt=kvm resrc=rng reason=start vm=\"openshift-cnv_fedora30\" uuid=2b875431-d438-53e2-bcf1-d3c27729be0d old-rng=\"?\" new-rng=\"/dev/urandom\": Permission denied","pos":"virAuditSend:142","subcomponent":"libvirt","thread":"29","timestamp":"2019-12-05T02:38:55.931000Z"} {"component":"virt-launcher","level":"warning","msg":"Failed to send audit message virt=kvm resrc=mem reason=start vm=\"openshift-cnv_fedora30\" uuid=2b875431-d438-53e2-bcf1-d3c27729be0d old-mem=0 new-mem=1953792: Permission denied","pos":"virAuditSend:142","subcomponent":"libvirt","thread":"29","timestamp":"2019-12-05T02:38:55.931000Z"} {"component":"virt-launcher","level":"warning","msg":"Failed to send audit message virt=kvm resrc=vcpu reason=start vm=\"openshift-cnv_fedora30\" uuid=2b875431-d438-53e2-bcf1-d3c27729be0d old-vcpu=0 new-vcpu=4: Permission denied","pos":"virAuditSend:142","subcomponent":"libvirt","thread":"29","timestamp":"2019-12-05T02:38:55.931000Z"} {"component":"virt-launcher","level":"warning","msg":"Failed to send audit message virt=kvm resrc=iothread reason=start vm=\"openshift-cnv_fedora30\" uuid=2b875431-d438-53e2-bcf1-d3c27729be0d old-iothread=0 new-iothread=1: Permission denied","pos":"virAuditSend:142","subcomponent":"libvirt","thread":"29","timestamp":"2019-12-05T02:38:55.931000Z"} {"component":"virt-launcher","level":"warning","msg":"Failed to send audit message virt=kvm op=start reason=booted vm=\"openshift-cnv_fedora30\" uuid=2b875431-d438-53e2-bcf1-d3c27729be0d vm-pid=104: Permission denied","pos":"virAuditSend:142","subcomponent":"libvirt","thread":"29","timestamp":"2019-12-05T02:38:55.931000Z"} {"component":"virt-launcher","level":"info","msg":"DomainLifecycle event 2 with reason 0 received","pos":"client.go:257","timestamp":"2019-12-05T02:38:55.932019Z"} {"component":"virt-launcher","kind":"","level":"info","msg":"Domain started.","name":"fedora30","namespace":"openshift-cnv","pos":"manager.go:1024","timestamp":"2019-12-05T02:38:55.932915Z","uid":"9ca8d488-0287-4727-b4b7-24e87cfffb86"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"fedora30","namespace":"openshift-cnv","pos":"server.go:167","timestamp":"2019-12-05T02:38:55.934047Z","uid":"9ca8d488-0287-4727-b4b7-24e87cfffb86"} {"component":"virt-launcher","level":"info","msg":"kubevirt domain status: Running(1):Unknown(1)","pos":"client.go:180","timestamp":"2019-12-05T02:38:55.934775Z"} {"component":"virt-launcher","level":"info","msg":"processed event","pos":"client.go:242","timestamp":"2019-12-05T02:38:55.935989Z"} {"component":"virt-launcher","level":"info","msg":"kubevirt domain status: Running(1):Unknown(1)","pos":"client.go:180","timestamp":"2019-12-05T02:38:55.937894Z"} {"component":"virt-launcher","level":"info","msg":"processed event","pos":"client.go:242","timestamp":"2019-12-05T02:38:55.938996Z"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"fedora30","namespace":"openshift-cnv","pos":"server.go:167","timestamp":"2019-12-05T02:38:55.989015Z","uid":"9ca8d488-0287-4727-b4b7-24e87cfffb86"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"fedora30","namespace":"openshift-cnv","pos":"server.go:167","timestamp":"2019-12-05T02:38:56.000325Z","uid":"9ca8d488-0287-4727-b4b7-24e87cfffb86"} {"component":"virt-launcher","level":"info","msg":"Found PID for 2b875431-d438-53e2-bcf1-d3c27729be0d: 104","pos":"monitor.go:206","timestamp":"2019-12-05T02:38:56.499160Z"} [cnv-qe-jenkins@cnv-executor-guohua ~]$ oc logs virt-launcher-fedora30-n2t6x -c compute {"component":"virt-launcher","level":"info","msg":"Collected all requested hook sidecar sockets","pos":"manager.go:68","timestamp":"2019-12-05T02:38:52.044015Z"} {"component":"virt-launcher","level":"info","msg":"Sorted all collected sidecar sockets per hook point based on their priority and name: map[]","pos":"manager.go:71","timestamp":"2019-12-05T02:38:52.044136Z"} {"component":"virt-launcher","level":"info","msg":"Watchdog file created at /var/run/kubevirt/watchdog-files/openshift-cnv_fedora30","pos":"virt-launcher.go:142","timestamp":"2019-12-05T02:38:52.045204Z"} {"component":"virt-launcher","level":"info","msg":"Connecting to libvirt daemon: qemu:///system","pos":"libvirt.go:354","timestamp":"2019-12-05T02:38:52.057380Z"} {"component":"virt-launcher","level":"info","msg":"Connecting to libvirt daemon failed: virError(Code=38, Domain=7, Message='Failed to connect socket to '/var/run/libvirt/libvirt-sock': No such file or directory')","pos":"libvirt.go:362","timestamp":"2019-12-05T02:38:52.057919Z"} {"component":"virt-launcher","level":"info","msg":"libvirt version: 5.6.0, package: 6.module+el8.1.0+4244+9aa4e6bb (Red Hat, Inc. \u003chttp://bugzilla.redhat.com/bugzilla\u003e, 2019-09-19-17:11:14, )","subcomponent":"libvirt","thread":"42","timestamp":"2019-12-05T02:38:52.158000Z"} {"component":"virt-launcher","level":"info","msg":"hostname: fedora30","subcomponent":"libvirt","thread":"42","timestamp":"2019-12-05T02:38:52.158000Z"} {"component":"virt-launcher","level":"error","msg":"internal error: Unable to get DBus system bus connection: Failed to connect to socket /run/dbus/system_bus_socket: No such file or directory","pos":"virDBusGetSystemBus:110","subcomponent":"libvirt","thread":"42","timestamp":"2019-12-05T02:38:52.158000Z"} {"component":"virt-launcher","level":"error","msg":"internal error: Unable to get DBus system bus connection: Failed to connect to socket /run/dbus/system_bus_socket: No such file or directory","pos":"virDBusGetSystemBus:110","subcomponent":"libvirt","thread":"42","timestamp":"2019-12-05T02:38:52.171000Z"} {"component":"virt-launcher","level":"warning","msg":"DBus not available, disabling firewalld support in bridge_network_driver: internal error: Unable to get DBus system bus connection: Failed to connect to socket /run/dbus/system_bus_socket: No such file or directory","pos":"networkStateInitialize:828","subcomponent":"libvirt","thread":"42","timestamp":"2019-12-05T02:38:52.172000Z"} {"component":"virt-launcher","level":"error","msg":"internal error: Child process (/usr/sbin/dmidecode -q -t 0,1,2,3,4,17) unexpected exit status 1: /dev/mem: No such file or directory","pos":"virCommandWait:2796","subcomponent":"libvirt","thread":"42","timestamp":"2019-12-05T02:38:52.206000Z"} {"component":"virt-launcher","level":"error","msg":"Failed to open config space file '/sys/bus/pci/devices/0000:00:00.0/config': Read-only file system","pos":"virPCIDeviceConfigOpen:305","subcomponent":"libvirt","thread":"46","timestamp":"2019-12-05T02:38:52.215000Z"} {"component":"virt-launcher","level":"error","msg":"Failed to open config space file '/sys/bus/pci/devices/0000:00:01.0/config': Read-only file system","pos":"virPCIDeviceConfigOpen:305","subcomponent":"libvirt","thread":"46","timestamp":"2019-12-05T02:38:52.216000Z"} {"component":"virt-launcher","level":"error","msg":"Failed to open config space file '/sys/bus/pci/devices/0000:00:01.1/config': Read-only file system","pos":"virPCIDeviceConfigOpen:305","subcomponent":"libvirt","thread":"46","timestamp":"2019-12-05T02:38:52.216000Z"} {"component":"virt-launcher","level":"error","msg":"Failed to open config space file '/sys/bus/pci/devices/0000:00:01.2/config': Read-only file system","pos":"virPCIDeviceConfigOpen:305","subcomponent":"libvirt","thread":"46","timestamp":"2019-12-05T02:38:52.217000Z"} {"component":"virt-launcher","level":"error","msg":"Failed to open config space file '/sys/bus/pci/devices/0000:00:01.3/config': Read-only file system","pos":"virPCIDeviceConfigOpen:305","subcomponent":"libvirt","thread":"46","timestamp":"2019-12-05T02:38:52.218000Z"} {"component":"virt-launcher","level":"error","msg":"Failed to open config space file '/sys/bus/pci/devices/0000:00:02.0/config': Read-only file system","pos":"virPCIDeviceConfigOpen:305","subcomponent":"libvirt","thread":"46","timestamp":"2019-12-05T02:38:52.221000Z"} {"component":"virt-launcher","level":"error","msg":"Failed to open config space file '/sys/bus/pci/devices/0000:00:03.0/config': Read-only file system","pos":"virPCIDeviceConfigOpen:305","subcomponent":"libvirt","thread":"46","timestamp":"2019-12-05T02:38:52.225000Z"} {"component":"virt-launcher","level":"error","msg":"Failed to open config space file '/sys/bus/pci/devices/0000:00:04.0/config': Read-only file system","pos":"virPCIDeviceConfigOpen:305","subcomponent":"libvirt","thread":"46","timestamp":"2019-12-05T02:38:52.225000Z"} {"component":"virt-launcher","level":"error","msg":"Failed to open config space file '/sys/bus/pci/devices/0000:00:05.0/config': Read-only file system","pos":"virPCIDeviceConfigOpen:305","subcomponent":"libvirt","thread":"46","timestamp":"2019-12-05T02:38:52.226000Z"} {"component":"virt-launcher","level":"error","msg":"Failed to open config space file '/sys/bus/pci/devices/0000:00:06.0/config': Read-only file system","pos":"virPCIDeviceConfigOpen:305","subcomponent":"libvirt","thread":"46","timestamp":"2019-12-05T02:38:52.227000Z"} {"component":"virt-launcher","level":"error","msg":"Failed to open config space file '/sys/bus/pci/devices/0000:00:07.0/config': Read-only file system","pos":"virPCIDeviceConfigOpen:305","subcomponent":"libvirt","thread":"46","timestamp":"2019-12-05T02:38:52.228000Z"} {"component":"virt-launcher","level":"error","msg":"Failed to open config space file '/sys/bus/pci/devices/0000:00:08.0/config': Read-only file system","pos":"virPCIDeviceConfigOpen:305","subcomponent":"libvirt","thread":"46","timestamp":"2019-12-05T02:38:52.228000Z"} {"component":"virt-launcher","level":"error","msg":"Failed to open config space file '/sys/bus/pci/devices/0000:00:09.0/config': Read-only file system","pos":"virPCIDeviceConfigOpen:305","subcomponent":"libvirt","thread":"46","timestamp":"2019-12-05T02:38:52.228000Z"} {"component":"virt-launcher","level":"error","msg":"Failed to open config space file '/sys/bus/pci/devices/0000:00:0a.0/config': Read-only file system","pos":"virPCIDeviceConfigOpen:305","subcomponent":"libvirt","thread":"46","timestamp":"2019-12-05T02:38:52.229000Z"} {"component":"virt-launcher","level":"error","msg":"Failed to open config space file '/sys/bus/pci/devices/0000:00:0b.0/config': Read-only file system","pos":"virPCIDeviceConfigOpen:305","subcomponent":"libvirt","thread":"46","timestamp":"2019-12-05T02:38:52.229000Z"} {"component":"virt-launcher","level":"error","msg":"Failed to open config space file '/sys/bus/pci/devices/0000:00:0c.0/config': Read-only file system","pos":"virPCIDeviceConfigOpen:305","subcomponent":"libvirt","thread":"46","timestamp":"2019-12-05T02:38:52.230000Z"} {"component":"virt-launcher","level":"info","msg":"Connected to libvirt daemon","pos":"libvirt.go:370","timestamp":"2019-12-05T02:38:52.559896Z"} {"component":"virt-launcher","level":"info","msg":"Registered libvirt event notify callback","pos":"client.go:292","timestamp":"2019-12-05T02:38:52.564266Z"} {"component":"virt-launcher","level":"info","msg":"Marked as ready","pos":"virt-launcher.go:72","timestamp":"2019-12-05T02:38:52.564697Z"} {"component":"virt-launcher","kind":"","level":"info","msg":"Executing PreStartHook on VMI pod environment","name":"fedora30","namespace":"openshift-cnv","pos":"manager.go:733","timestamp":"2019-12-05T02:38:55.362622Z","uid":"9ca8d488-0287-4727-b4b7-24e87cfffb86"} {"component":"virt-launcher","kind":"","level":"info","msg":"Starting PreCloudInitIso hook","name":"fedora30","namespace":"openshift-cnv","pos":"manager.go:742","timestamp":"2019-12-05T02:38:55.362682Z","uid":"9ca8d488-0287-4727-b4b7-24e87cfffb86"} {"component":"virt-launcher","level":"info","msg":"generated nocloud iso file /var/run/kubevirt-ephemeral-disks/cloud-init-data/openshift-cnv/fedora30/noCloud.iso","pos":"cloud-init.go:444","timestamp":"2019-12-05T02:38:55.369424Z"} {"component":"virt-launcher","kind":"","level":"info","msg":"masquerade pod interface: VIF: { Name: eth0, IP: 10.0.2.2, Mask: ffffff00, MAC: 02:00:00:4b:48:7a, Gateway: 10.0.2.1, MTU: 1400}","name":"fedora30","namespace":"openshift-cnv","pos":"podinterface.go:446","timestamp":"2019-12-05T02:38:55.417095Z","uid":"9ca8d488-0287-4727-b4b7-24e87cfffb86"} {"component":"virt-launcher","level":"info","msg":"Found nameservers in /etc/resolv.conf: \ufffd\u001e\u0000\n","pos":"converter.go:1491","timestamp":"2019-12-05T02:38:55.417245Z"} {"component":"virt-launcher","level":"info","msg":"Found search domains in /etc/resolv.conf: openshift-cnv.svc.cluster.local svc.cluster.local cluster.local openstacklocal","pos":"converter.go:1492","timestamp":"2019-12-05T02:38:55.417276Z"} {"component":"virt-launcher","level":"info","msg":"Starting SingleClientDHCPServer","pos":"dhcp.go:64","timestamp":"2019-12-05T02:38:55.417427Z"} {"component":"virt-launcher","level":"info","msg":"Driver cache mode for /var/run/kubevirt-ephemeral-disks/disk-data/containerdisk/disk.qcow2 set to none","pos":"converter.go:174","timestamp":"2019-12-05T02:38:55.433605Z"} {"component":"virt-launcher","level":"info","msg":"Driver cache mode for /var/run/kubevirt-ephemeral-disks/cloud-init-data/openshift-cnv/fedora30/noCloud.iso set to none","pos":"converter.go:174","timestamp":"2019-12-05T02:38:55.433671Z"} {"component":"virt-launcher","kind":"","level":"info","msg":"Domain defined.","name":"fedora30","namespace":"openshift-cnv","pos":"manager.go:993","timestamp":"2019-12-05T02:38:55.440369Z","uid":"9ca8d488-0287-4727-b4b7-24e87cfffb86"} {"component":"virt-launcher","level":"info","msg":"DomainLifecycle event 0 with reason 0 received","pos":"client.go:257","timestamp":"2019-12-05T02:38:55.440523Z"} {"component":"virt-launcher","level":"error","msg":"internal error: Unable to get DBus system bus connection: Failed to connect to socket /run/dbus/system_bus_socket: No such file or directory","pos":"virDBusGetSystemBus:110","subcomponent":"libvirt","thread":"29","timestamp":"2019-12-05T02:38:55.445000Z"} {"component":"virt-launcher","level":"warning","msg":"Failed to send audit message virt=kvm vm=\"openshift-cnv_fedora30\" uuid=2b875431-d438-53e2-bcf1-d3c27729be0d vm-ctx=+107:+107 img-ctx=+107:+107 model=dac: Permission denied","pos":"virAuditSend:142","subcomponent":"libvirt","thread":"29","timestamp":"2019-12-05T02:38:55.446000Z"} {"component":"virt-launcher","level":"warning","msg":"Failed to send audit message virt=kvm resrc=net reason=open vm=\"openshift-cnv_fedora30\" uuid=2b875431-d438-53e2-bcf1-d3c27729be0d net=02:00:00:4b:48:7a path=\"/dev/net/tun\" rdev=0A:C8: Permission denied","pos":"virAuditSend:142","subcomponent":"libvirt","thread":"29","timestamp":"2019-12-05T02:38:55.479000Z"} {"component":"virt-launcher","level":"warning","msg":"Failed to send audit message virt=kvm resrc=net reason=open vm=\"openshift-cnv_fedora30\" uuid=2b875431-d438-53e2-bcf1-d3c27729be0d net=02:00:00:4b:48:7a path=\"/dev/vhost-net\" rdev=0A:EE: Permission denied","pos":"virAuditSend:142","subcomponent":"libvirt","thread":"29","timestamp":"2019-12-05T02:38:55.479000Z"} {"component":"virt-launcher","level":"error","msg":"At least one cgroup controller is required: No such device or address","pos":"virCgroupDetect:420","subcomponent":"libvirt","thread":"29","timestamp":"2019-12-05T02:38:55.488000Z"} {"component":"virt-launcher","level":"info","msg":"kubevirt domain status: Paused(3):StartingUp(11)","pos":"client.go:180","timestamp":"2019-12-05T02:38:55.493529Z"} {"component":"virt-launcher","level":"info","msg":"Detected domain with UUID 2b875431-d438-53e2-bcf1-d3c27729be0d","pos":"virt-launcher.go:233","timestamp":"2019-12-05T02:38:55.497192Z"} {"component":"virt-launcher","level":"info","msg":"Monitoring loop: rate 1s start timeout 5m0s","pos":"monitor.go:237","timestamp":"2019-12-05T02:38:55.497244Z"} {"component":"virt-launcher","level":"info","msg":"processed event","pos":"client.go:242","timestamp":"2019-12-05T02:38:55.498199Z"} {"component":"virt-launcher","level":"info","msg":"GuestAgentLifecycle event state 2 with reason 1 received","pos":"client.go:275","timestamp":"2019-12-05T02:38:55.652032Z"} {"component":"virt-launcher","level":"info","msg":"kubevirt domain status: Paused(3):StartingUp(11)","pos":"client.go:180","timestamp":"2019-12-05T02:38:55.665395Z"} {"component":"virt-launcher","level":"info","msg":"processed event","pos":"client.go:242","timestamp":"2019-12-05T02:38:55.669421Z"} {"component":"virt-launcher","level":"info","msg":"DomainLifecycle event 4 with reason 0 received","pos":"client.go:257","timestamp":"2019-12-05T02:38:55.930413Z"} {"component":"virt-launcher","level":"warning","msg":"Failed to send audit message virt=kvm resrc=disk reason=start vm=\"openshift-cnv_fedora30\" uuid=2b875431-d438-53e2-bcf1-d3c27729be0d old-disk=\"?\" new-disk=\"/var/run/kubevirt-ephemeral-disks/disk-data/containerdisk/disk.qcow2\": Permission denied","pos":"virAuditSend:142","subcomponent":"libvirt","thread":"29","timestamp":"2019-12-05T02:38:55.931000Z"} {"component":"virt-launcher","level":"warning","msg":"Failed to send audit message virt=kvm resrc=disk reason=start vm=\"openshift-cnv_fedora30\" uuid=2b875431-d438-53e2-bcf1-d3c27729be0d old-disk=\"?\" new-disk=\"/var/run/kubevirt-ephemeral-disks/cloud-init-data/openshift-cnv/fedora30/noCloud.iso\": Permission denied","pos":"virAuditSend:142","subcomponent":"libvirt","thread":"29","timestamp":"2019-12-05T02:38:55.931000Z"} {"component":"virt-launcher","level":"warning","msg":"Failed to send audit message virt=kvm resrc=net reason=start vm=\"openshift-cnv_fedora30\" uuid=2b875431-d438-53e2-bcf1-d3c27729be0d old-net=\"?\" new-net=\"02:00:00:4b:48:7a\": Permission denied","pos":"virAuditSend:142","subcomponent":"libvirt","thread":"29","timestamp":"2019-12-05T02:38:55.931000Z"} {"component":"virt-launcher","level":"warning","msg":"Failed to send audit message virt=kvm resrc=chardev reason=start vm=\"openshift-cnv_fedora30\" uuid=2b875431-d438-53e2-bcf1-d3c27729be0d old-chardev=\"?\" new-chardev=\"/var/run/kubevirt-private/9ca8d488-0287-4727-b4b7-24e87cfffb86/virt-serial0\": Permission denied","pos":"virAuditSend:142","subcomponent":"libvirt","thread":"29","timestamp":"2019-12-05T02:38:55.931000Z"} {"component":"virt-launcher","level":"warning","msg":"Failed to send audit message virt=kvm resrc=chardev reason=start vm=\"openshift-cnv_fedora30\" uuid=2b875431-d438-53e2-bcf1-d3c27729be0d old-chardev=\"?\" new-chardev=\"/var/lib/libvirt/qemu/channel/target/domain-1-openshift-cnv_fedora/org.qemu.guest_agent.0\": Permission denied","pos":"virAuditSend:142","subcomponent":"libvirt","thread":"29","timestamp":"2019-12-05T02:38:55.931000Z"} {"component":"virt-launcher","level":"warning","msg":"Failed to send audit message virt=kvm resrc=rng reason=start vm=\"openshift-cnv_fedora30\" uuid=2b875431-d438-53e2-bcf1-d3c27729be0d old-rng=\"?\" new-rng=\"/dev/urandom\": Permission denied","pos":"virAuditSend:142","subcomponent":"libvirt","thread":"29","timestamp":"2019-12-05T02:38:55.931000Z"} {"component":"virt-launcher","level":"warning","msg":"Failed to send audit message virt=kvm resrc=mem reason=start vm=\"openshift-cnv_fedora30\" uuid=2b875431-d438-53e2-bcf1-d3c27729be0d old-mem=0 new-mem=1953792: Permission denied","pos":"virAuditSend:142","subcomponent":"libvirt","thread":"29","timestamp":"2019-12-05T02:38:55.931000Z"} {"component":"virt-launcher","level":"warning","msg":"Failed to send audit message virt=kvm resrc=vcpu reason=start vm=\"openshift-cnv_fedora30\" uuid=2b875431-d438-53e2-bcf1-d3c27729be0d old-vcpu=0 new-vcpu=4: Permission denied","pos":"virAuditSend:142","subcomponent":"libvirt","thread":"29","timestamp":"2019-12-05T02:38:55.931000Z"} {"component":"virt-launcher","level":"warning","msg":"Failed to send audit message virt=kvm resrc=iothread reason=start vm=\"openshift-cnv_fedora30\" uuid=2b875431-d438-53e2-bcf1-d3c27729be0d old-iothread=0 new-iothread=1: Permission denied","pos":"virAuditSend:142","subcomponent":"libvirt","thread":"29","timestamp":"2019-12-05T02:38:55.931000Z"} {"component":"virt-launcher","level":"warning","msg":"Failed to send audit message virt=kvm op=start reason=booted vm=\"openshift-cnv_fedora30\" uuid=2b875431-d438-53e2-bcf1-d3c27729be0d vm-pid=104: Permission denied","pos":"virAuditSend:142","subcomponent":"libvirt","thread":"29","timestamp":"2019-12-05T02:38:55.931000Z"} {"component":"virt-launcher","level":"info","msg":"DomainLifecycle event 2 with reason 0 received","pos":"client.go:257","timestamp":"2019-12-05T02:38:55.932019Z"} {"component":"virt-launcher","kind":"","level":"info","msg":"Domain started.","name":"fedora30","namespace":"openshift-cnv","pos":"manager.go:1024","timestamp":"2019-12-05T02:38:55.932915Z","uid":"9ca8d488-0287-4727-b4b7-24e87cfffb86"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"fedora30","namespace":"openshift-cnv","pos":"server.go:167","timestamp":"2019-12-05T02:38:55.934047Z","uid":"9ca8d488-0287-4727-b4b7-24e87cfffb86"} {"component":"virt-launcher","level":"info","msg":"kubevirt domain status: Running(1):Unknown(1)","pos":"client.go:180","timestamp":"2019-12-05T02:38:55.934775Z"} {"component":"virt-launcher","level":"info","msg":"processed event","pos":"client.go:242","timestamp":"2019-12-05T02:38:55.935989Z"} {"component":"virt-launcher","level":"info","msg":"kubevirt domain status: Running(1):Unknown(1)","pos":"client.go:180","timestamp":"2019-12-05T02:38:55.937894Z"} {"component":"virt-launcher","level":"info","msg":"processed event","pos":"client.go:242","timestamp":"2019-12-05T02:38:55.938996Z"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"fedora30","namespace":"openshift-cnv","pos":"server.go:167","timestamp":"2019-12-05T02:38:55.989015Z","uid":"9ca8d488-0287-4727-b4b7-24e87cfffb86"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"fedora30","namespace":"openshift-cnv","pos":"server.go:167","timestamp":"2019-12-05T02:38:56.000325Z","uid":"9ca8d488-0287-4727-b4b7-24e87cfffb86"} {"component":"virt-launcher","level":"info","msg":"Found PID for 2b875431-d438-53e2-bcf1-d3c27729be0d: 104","pos":"monitor.go:206","timestamp":"2019-12-05T02:38:56.499160Z"} Version-Release number of selected component (if applicable): v2.2.0-10 How reproducible: 100% Steps to Reproduce: 1. Create a vm from vm-template-fedora 2. Monitor it's status 3. Actual results: It's keeping restarting Expected results: It running normally Additional info: However, create a cirros VM does not see this. $ oc logs virt-launcher-vm-cirros-ckdh8 -c compute {"component":"virt-launcher","level":"info","msg":"Collected all requested hook sidecar sockets","pos":"manager.go:68","timestamp":"2019-12-05T02:47:22.427264Z"} {"component":"virt-launcher","level":"info","msg":"Sorted all collected sidecar sockets per hook point based on their priority and name: map[]","pos":"manager.go:71","timestamp":"2019-12-05T02:47:22.427392Z"} {"component":"virt-launcher","level":"info","msg":"Watchdog file created at /var/run/kubevirt/watchdog-files/openshift-cnv_vm-cirros","pos":"virt-launcher.go:142","timestamp":"2019-12-05T02:47:22.428497Z"} {"component":"virt-launcher","level":"info","msg":"Connecting to libvirt daemon: qemu:///system","pos":"libvirt.go:354","timestamp":"2019-12-05T02:47:22.438904Z"} {"component":"virt-launcher","level":"info","msg":"Connecting to libvirt daemon failed: virError(Code=38, Domain=7, Message='Failed to connect socket to '/var/run/libvirt/libvirt-sock': No such file or directory')","pos":"libvirt.go:362","timestamp":"2019-12-05T02:47:22.439504Z"} {"component":"virt-launcher","level":"info","msg":"libvirt version: 5.6.0, package: 6.module+el8.1.0+4244+9aa4e6bb (Red Hat, Inc. \u003chttp://bugzilla.redhat.com/bugzilla\u003e, 2019-09-19-17:11:14, )","subcomponent":"libvirt","thread":"42","timestamp":"2019-12-05T02:47:22.560000Z"} {"component":"virt-launcher","level":"info","msg":"hostname: vm-cirros","subcomponent":"libvirt","thread":"42","timestamp":"2019-12-05T02:47:22.560000Z"} {"component":"virt-launcher","level":"error","msg":"internal error: Unable to get DBus system bus connection: Failed to connect to socket /run/dbus/system_bus_socket: No such file or directory","pos":"virDBusGetSystemBus:110","subcomponent":"libvirt","thread":"42","timestamp":"2019-12-05T02:47:22.560000Z"} {"component":"virt-launcher","level":"error","msg":"internal error: Unable to get DBus system bus connection: Failed to connect to socket /run/dbus/system_bus_socket: No such file or directory","pos":"virDBusGetSystemBus:110","subcomponent":"libvirt","thread":"42","timestamp":"2019-12-05T02:47:22.576000Z"} {"component":"virt-launcher","level":"warning","msg":"DBus not available, disabling firewalld support in bridge_network_driver: internal error: Unable to get DBus system bus connection: Failed to connect to socket /run/dbus/system_bus_socket: No such file or directory","pos":"networkStateInitialize:828","subcomponent":"libvirt","thread":"42","timestamp":"2019-12-05T02:47:22.576000Z"} {"component":"virt-launcher","level":"error","msg":"internal error: Child process (/usr/sbin/dmidecode -q -t 0,1,2,3,4,17) unexpected exit status 1: /dev/mem: No such file or directory","pos":"virCommandWait:2796","subcomponent":"libvirt","thread":"42","timestamp":"2019-12-05T02:47:22.610000Z"} {"component":"virt-launcher","level":"error","msg":"Failed to open config space file '/sys/bus/pci/devices/0000:00:00.0/config': Read-only file system","pos":"virPCIDeviceConfigOpen:305","subcomponent":"libvirt","thread":"46","timestamp":"2019-12-05T02:47:22.627000Z"} {"component":"virt-launcher","level":"error","msg":"Failed to open config space file '/sys/bus/pci/devices/0000:00:01.0/config': Read-only file system","pos":"virPCIDeviceConfigOpen:305","subcomponent":"libvirt","thread":"46","timestamp":"2019-12-05T02:47:22.627000Z"} {"component":"virt-launcher","level":"error","msg":"Failed to open config space file '/sys/bus/pci/devices/0000:00:01.1/config': Read-only file system","pos":"virPCIDeviceConfigOpen:305","subcomponent":"libvirt","thread":"46","timestamp":"2019-12-05T02:47:22.627000Z"} {"component":"virt-launcher","level":"error","msg":"Failed to open config space file '/sys/bus/pci/devices/0000:00:01.2/config': Read-only file system","pos":"virPCIDeviceConfigOpen:305","subcomponent":"libvirt","thread":"46","timestamp":"2019-12-05T02:47:22.628000Z"} {"component":"virt-launcher","level":"error","msg":"Failed to open config space file '/sys/bus/pci/devices/0000:00:01.3/config': Read-only file system","pos":"virPCIDeviceConfigOpen:305","subcomponent":"libvirt","thread":"46","timestamp":"2019-12-05T02:47:22.630000Z"} {"component":"virt-launcher","level":"error","msg":"Failed to open config space file '/sys/bus/pci/devices/0000:00:02.0/config': Read-only file system","pos":"virPCIDeviceConfigOpen:305","subcomponent":"libvirt","thread":"46","timestamp":"2019-12-05T02:47:22.634000Z"} {"component":"virt-launcher","level":"error","msg":"Failed to open config space file '/sys/bus/pci/devices/0000:00:03.0/config': Read-only file system","pos":"virPCIDeviceConfigOpen:305","subcomponent":"libvirt","thread":"46","timestamp":"2019-12-05T02:47:22.638000Z"} {"component":"virt-launcher","level":"error","msg":"Failed to open config space file '/sys/bus/pci/devices/0000:00:04.0/config': Read-only file system","pos":"virPCIDeviceConfigOpen:305","subcomponent":"libvirt","thread":"46","timestamp":"2019-12-05T02:47:22.639000Z"} {"component":"virt-launcher","level":"error","msg":"Failed to open config space file '/sys/bus/pci/devices/0000:00:05.0/config': Read-only file system","pos":"virPCIDeviceConfigOpen:305","subcomponent":"libvirt","thread":"46","timestamp":"2019-12-05T02:47:22.640000Z"} {"component":"virt-launcher","level":"error","msg":"Failed to open config space file '/sys/bus/pci/devices/0000:00:06.0/config': Read-only file system","pos":"virPCIDeviceConfigOpen:305","subcomponent":"libvirt","thread":"46","timestamp":"2019-12-05T02:47:22.640000Z"} {"component":"virt-launcher","level":"error","msg":"Failed to open config space file '/sys/bus/pci/devices/0000:00:07.0/config': Read-only file system","pos":"virPCIDeviceConfigOpen:305","subcomponent":"libvirt","thread":"46","timestamp":"2019-12-05T02:47:22.640000Z"} {"component":"virt-launcher","level":"error","msg":"Failed to open config space file '/sys/bus/pci/devices/0000:00:08.0/config': Read-only file system","pos":"virPCIDeviceConfigOpen:305","subcomponent":"libvirt","thread":"46","timestamp":"2019-12-05T02:47:22.640000Z"} {"component":"virt-launcher","level":"error","msg":"Failed to open config space file '/sys/bus/pci/devices/0000:00:09.0/config': Read-only file system","pos":"virPCIDeviceConfigOpen:305","subcomponent":"libvirt","thread":"46","timestamp":"2019-12-05T02:47:22.641000Z"} {"component":"virt-launcher","level":"error","msg":"Failed to open config space file '/sys/bus/pci/devices/0000:00:0a.0/config': Read-only file system","pos":"virPCIDeviceConfigOpen:305","subcomponent":"libvirt","thread":"46","timestamp":"2019-12-05T02:47:22.641000Z"} {"component":"virt-launcher","level":"error","msg":"Failed to open config space file '/sys/bus/pci/devices/0000:00:0b.0/config': Read-only file system","pos":"virPCIDeviceConfigOpen:305","subcomponent":"libvirt","thread":"46","timestamp":"2019-12-05T02:47:22.642000Z"} {"component":"virt-launcher","level":"error","msg":"Failed to open config space file '/sys/bus/pci/devices/0000:00:0c.0/config': Read-only file system","pos":"virPCIDeviceConfigOpen:305","subcomponent":"libvirt","thread":"46","timestamp":"2019-12-05T02:47:22.642000Z"} {"component":"virt-launcher","level":"info","msg":"Connected to libvirt daemon","pos":"libvirt.go:370","timestamp":"2019-12-05T02:47:22.941973Z"} {"component":"virt-launcher","level":"info","msg":"Registered libvirt event notify callback","pos":"client.go:292","timestamp":"2019-12-05T02:47:22.946931Z"} {"component":"virt-launcher","level":"info","msg":"Marked as ready","pos":"virt-launcher.go:72","timestamp":"2019-12-05T02:47:22.947355Z"} {"component":"virt-launcher","kind":"","level":"info","msg":"Executing PreStartHook on VMI pod environment","name":"vm-cirros","namespace":"openshift-cnv","pos":"manager.go:733","timestamp":"2019-12-05T02:47:27.848836Z","uid":"23b9f432-3407-40bc-8b8d-3f859f4305a2"} {"component":"virt-launcher","kind":"","level":"info","msg":"Starting PreCloudInitIso hook","name":"vm-cirros","namespace":"openshift-cnv","pos":"manager.go:742","timestamp":"2019-12-05T02:47:27.848956Z","uid":"23b9f432-3407-40bc-8b8d-3f859f4305a2"} {"component":"virt-launcher","level":"info","msg":"generated nocloud iso file /var/run/kubevirt-ephemeral-disks/cloud-init-data/openshift-cnv/vm-cirros/noCloud.iso","pos":"cloud-init.go:444","timestamp":"2019-12-05T02:47:27.868494Z"} {"component":"virt-launcher","level":"info","msg":"updated MAC for eth0 interface: old: 0a:58:0a:83:00:38 -\u003e new: 0a:58:0a:54:9f:51","pos":"common.go:255","timestamp":"2019-12-05T02:47:27.877402Z"} {"component":"virt-launcher","kind":"","level":"info","msg":"bridge pod interface: VIF: { Name: eth0, IP: 10.131.0.56, Mask: fffffe00, MAC: 0a:58:0a:83:00:38, Gateway: 10.131.0.1, MTU: 1400}","name":"vm-cirros","namespace":"openshift-cnv","pos":"podinterface.go:258","timestamp":"2019-12-05T02:47:27.893454Z","uid":"23b9f432-3407-40bc-8b8d-3f859f4305a2"} {"component":"virt-launcher","level":"info","msg":"Found nameservers in /etc/resolv.conf: \ufffd\u001e\u0000\n","pos":"converter.go:1491","timestamp":"2019-12-05T02:47:27.893629Z"} {"component":"virt-launcher","level":"info","msg":"Found search domains in /etc/resolv.conf: openshift-cnv.svc.cluster.local svc.cluster.local cluster.local openstacklocal","pos":"converter.go:1492","timestamp":"2019-12-05T02:47:27.893669Z"} {"component":"virt-launcher","level":"info","msg":"Starting SingleClientDHCPServer","pos":"dhcp.go:64","timestamp":"2019-12-05T02:47:27.894213Z"} {"component":"virt-launcher","level":"info","msg":"Driver cache mode for /var/run/kubevirt-ephemeral-disks/disk-data/containerdisk/disk.qcow2 set to none","pos":"converter.go:174","timestamp":"2019-12-05T02:47:27.908099Z"} {"component":"virt-launcher","level":"info","msg":"Driver cache mode for /var/run/kubevirt-ephemeral-disks/cloud-init-data/openshift-cnv/vm-cirros/noCloud.iso set to none","pos":"converter.go:174","timestamp":"2019-12-05T02:47:27.908177Z"} {"component":"virt-launcher","kind":"","level":"info","msg":"Domain defined.","name":"vm-cirros","namespace":"openshift-cnv","pos":"manager.go:993","timestamp":"2019-12-05T02:47:27.915959Z","uid":"23b9f432-3407-40bc-8b8d-3f859f4305a2"} {"component":"virt-launcher","level":"info","msg":"DomainLifecycle event 0 with reason 0 received","pos":"client.go:257","timestamp":"2019-12-05T02:47:27.916274Z"} {"component":"virt-launcher","level":"error","msg":"internal error: Unable to get DBus system bus connection: Failed to connect to socket /run/dbus/system_bus_socket: No such file or directory","pos":"virDBusGetSystemBus:110","subcomponent":"libvirt","thread":"28","timestamp":"2019-12-05T02:47:27.919000Z"} {"component":"virt-launcher","level":"warning","msg":"Failed to send audit message virt=kvm vm=\"openshift-cnv_vm-cirros\" uuid=0d2a2043-41c0-59c3-9b17-025022203668 vm-ctx=+107:+107 img-ctx=+107:+107 model=dac: Permission denied","pos":"virAuditSend:142","subcomponent":"libvirt","thread":"28","timestamp":"2019-12-05T02:47:27.919000Z"} {"component":"virt-launcher","level":"warning","msg":"Failed to send audit message virt=kvm resrc=net reason=open vm=\"openshift-cnv_vm-cirros\" uuid=0d2a2043-41c0-59c3-9b17-025022203668 net=0a:58:0a:83:00:38 path=\"/dev/net/tun\" rdev=0A:C8: Permission denied","pos":"virAuditSend:142","subcomponent":"libvirt","thread":"28","timestamp":"2019-12-05T02:47:27.947000Z"} {"component":"virt-launcher","level":"warning","msg":"Failed to send audit message virt=kvm resrc=net reason=open vm=\"openshift-cnv_vm-cirros\" uuid=0d2a2043-41c0-59c3-9b17-025022203668 net=0a:58:0a:83:00:38 path=\"/dev/vhost-net\" rdev=0A:EE: Permission denied","pos":"virAuditSend:142","subcomponent":"libvirt","thread":"28","timestamp":"2019-12-05T02:47:27.947000Z"} {"component":"virt-launcher","level":"error","msg":"At least one cgroup controller is required: No such device or address","pos":"virCgroupDetect:420","subcomponent":"libvirt","thread":"28","timestamp":"2019-12-05T02:47:27.960000Z"} {"component":"virt-launcher","level":"info","msg":"kubevirt domain status: Paused(3):StartingUp(11)","pos":"client.go:180","timestamp":"2019-12-05T02:47:27.994845Z"} {"component":"virt-launcher","level":"info","msg":"Detected domain with UUID 0d2a2043-41c0-59c3-9b17-025022203668","pos":"virt-launcher.go:233","timestamp":"2019-12-05T02:47:27.997265Z"} {"component":"virt-launcher","level":"info","msg":"Monitoring loop: rate 1s start timeout 5m0s","pos":"monitor.go:237","timestamp":"2019-12-05T02:47:27.997332Z"} {"component":"virt-launcher","level":"info","msg":"processed event","pos":"client.go:242","timestamp":"2019-12-05T02:47:27.998102Z"} {"component":"virt-launcher","level":"info","msg":"GuestAgentLifecycle event state 2 with reason 1 received","pos":"client.go:275","timestamp":"2019-12-05T02:47:28.081562Z"} {"component":"virt-launcher","level":"info","msg":"kubevirt domain status: Paused(3):StartingUp(11)","pos":"client.go:180","timestamp":"2019-12-05T02:47:28.085411Z"} {"component":"virt-launcher","level":"info","msg":"processed event","pos":"client.go:242","timestamp":"2019-12-05T02:47:28.086665Z"} {"component":"virt-launcher","level":"info","msg":"DomainLifecycle event 4 with reason 0 received","pos":"client.go:257","timestamp":"2019-12-05T02:47:28.364458Z"} {"component":"virt-launcher","level":"warning","msg":"Failed to send audit message virt=kvm resrc=disk reason=start vm=\"openshift-cnv_vm-cirros\" uuid=0d2a2043-41c0-59c3-9b17-025022203668 old-disk=\"?\" new-disk=\"/var/run/kubevirt-ephemeral-disks/disk-data/containerdisk/disk.qcow2\": Permission denied","pos":"virAuditSend:142","subcomponent":"libvirt","thread":"28","timestamp":"2019-12-05T02:47:28.365000Z"} {"component":"virt-launcher","level":"warning","msg":"Failed to send audit message virt=kvm resrc=disk reason=start vm=\"openshift-cnv_vm-cirros\" uuid=0d2a2043-41c0-59c3-9b17-025022203668 old-disk=\"?\" new-disk=\"/var/run/kubevirt-ephemeral-disks/cloud-init-data/openshift-cnv/vm-cirros/noCloud.iso\": Permission denied","pos":"virAuditSend:142","subcomponent":"libvirt","thread":"28","timestamp":"2019-12-05T02:47:28.365000Z"} {"component":"virt-launcher","level":"warning","msg":"Failed to send audit message virt=kvm resrc=net reason=start vm=\"openshift-cnv_vm-cirros\" uuid=0d2a2043-41c0-59c3-9b17-025022203668 old-net=\"?\" new-net=\"0a:58:0a:83:00:38\": Permission denied","pos":"virAuditSend:142","subcomponent":"libvirt","thread":"28","timestamp":"2019-12-05T02:47:28.365000Z"} {"component":"virt-launcher","level":"warning","msg":"Failed to send audit message virt=kvm resrc=chardev reason=start vm=\"openshift-cnv_vm-cirros\" uuid=0d2a2043-41c0-59c3-9b17-025022203668 old-chardev=\"?\" new-chardev=\"/var/run/kubevirt-private/23b9f432-3407-40bc-8b8d-3f859f4305a2/virt-serial0\": Permission denied","pos":"virAuditSend:142","subcomponent":"libvirt","thread":"28","timestamp":"2019-12-05T02:47:28.365000Z"} {"component":"virt-launcher","level":"warning","msg":"Failed to send audit message virt=kvm resrc=chardev reason=start vm=\"openshift-cnv_vm-cirros\" uuid=0d2a2043-41c0-59c3-9b17-025022203668 old-chardev=\"?\" new-chardev=\"/var/lib/libvirt/qemu/channel/target/domain-1-openshift-cnv_vm-cir/org.qemu.guest_agent.0\": Permission denied","pos":"virAuditSend:142","subcomponent":"libvirt","thread":"28","timestamp":"2019-12-05T02:47:28.365000Z"} {"component":"virt-launcher","level":"warning","msg":"Failed to send audit message virt=kvm resrc=mem reason=start vm=\"openshift-cnv_vm-cirros\" uuid=0d2a2043-41c0-59c3-9b17-025022203668 old-mem=0 new-mem=63488: Permission denied","pos":"virAuditSend:142","subcomponent":"libvirt","thread":"28","timestamp":"2019-12-05T02:47:28.365000Z"} {"component":"virt-launcher","level":"warning","msg":"Failed to send audit message virt=kvm resrc=vcpu reason=start vm=\"openshift-cnv_vm-cirros\" uuid=0d2a2043-41c0-59c3-9b17-025022203668 old-vcpu=0 new-vcpu=1: Permission denied","pos":"virAuditSend:142","subcomponent":"libvirt","thread":"28","timestamp":"2019-12-05T02:47:28.365000Z"} {"component":"virt-launcher","level":"warning","msg":"Failed to send audit message virt=kvm resrc=iothread reason=start vm=\"openshift-cnv_vm-cirros\" uuid=0d2a2043-41c0-59c3-9b17-025022203668 old-iothread=0 new-iothread=1: Permission denied","pos":"virAuditSend:142","subcomponent":"libvirt","thread":"28","timestamp":"2019-12-05T02:47:28.365000Z"} {"component":"virt-launcher","level":"warning","msg":"Failed to send audit message virt=kvm op=start reason=booted vm=\"openshift-cnv_vm-cirros\" uuid=0d2a2043-41c0-59c3-9b17-025022203668 vm-pid=96: Permission denied","pos":"virAuditSend:142","subcomponent":"libvirt","thread":"28","timestamp":"2019-12-05T02:47:28.365000Z"} {"component":"virt-launcher","level":"info","msg":"DomainLifecycle event 2 with reason 0 received","pos":"client.go:257","timestamp":"2019-12-05T02:47:28.365772Z"} {"component":"virt-launcher","kind":"","level":"info","msg":"Domain started.","name":"vm-cirros","namespace":"openshift-cnv","pos":"manager.go:1024","timestamp":"2019-12-05T02:47:28.366708Z","uid":"23b9f432-3407-40bc-8b8d-3f859f4305a2"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"vm-cirros","namespace":"openshift-cnv","pos":"server.go:167","timestamp":"2019-12-05T02:47:28.368405Z","uid":"23b9f432-3407-40bc-8b8d-3f859f4305a2"} {"component":"virt-launcher","level":"info","msg":"kubevirt domain status: Running(1):Unknown(1)","pos":"client.go:180","timestamp":"2019-12-05T02:47:28.368706Z"} {"component":"virt-launcher","level":"info","msg":"processed event","pos":"client.go:242","timestamp":"2019-12-05T02:47:28.370365Z"} {"component":"virt-launcher","level":"info","msg":"kubevirt domain status: Running(1):Unknown(1)","pos":"client.go:180","timestamp":"2019-12-05T02:47:28.371989Z"} {"component":"virt-launcher","level":"info","msg":"processed event","pos":"client.go:242","timestamp":"2019-12-05T02:47:28.373068Z"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"vm-cirros","namespace":"openshift-cnv","pos":"server.go:167","timestamp":"2019-12-05T02:47:28.420609Z","uid":"23b9f432-3407-40bc-8b8d-3f859f4305a2"} {"component":"virt-launcher","kind":"","level":"info","msg":"Synced vmi","name":"vm-cirros","namespace":"openshift-cnv","pos":"server.go:167","timestamp":"2019-12-05T02:47:28.435194Z","uid":"23b9f432-3407-40bc-8b8d-3f859f4305a2"} {"component":"virt-launcher","level":"info","msg":"Found PID for 0d2a2043-41c0-59c3-9b17-025022203668: 96","pos":"monitor.go:206","timestamp":"2019-12-05T02:47:29.003038Z"}
Guohua, is the cirros vm also a container disk in your test env? And: Is there any other VMI affected by this bug?
(In reply to Fabian Deutsch from comment #1) > Guohua, is the cirros vm also a container disk in your test env? Yes， the cirros vm is also using a container disk. > > And: Is there any other VMI affected by this bug? I only see the fedora vm is affected. The vmi is keeping restarting because it's crashed which can be reading in the logs, but not clear enough to me.
After play with this issue several hours, find out how to reproduce the bug. The root cause is the CPU Core cannot be configured to >=2. Create a VM by using https://raw.githubusercontent.com/kubevirt/kubevirt/master/examples/vm-template-fedora.yaml: - if the CPU core is 1, the VM runs normally. - if the CPU core >=2, the VM is keeping restarting
Does this only affect the Fedora VM or some other VM as well?
It affects the Fedora and RHEL VM, not cirros VM.
Guohua, can you post information about the nodes in your cluster? `oc get node -o yaml`
Created attachment 1644253 [details] node.yaml
Reproduced on my env with 4 CPUs (using the above template)
Roman, can you take a look?
Not reproduced on my system (Performance system), VMS from the template above with 2,4,6, 8 and 10 cores are running without restart.
Ok, so I think we need more background info from a system where this happens. What I want to check is the following: 1) How packed is the node? -> `oc describe node <nodename>` 2) Is the VM requesting as many cores from the node as it has virtual cores? -> need the VMI spec of a running fedora VM 2.1) If it does not have more virtual cores than CPUs, do we consume more than we request (e.g. virt-launcher overhead calculations wrong)? 2.2) If we don't use more CPU than requested, are we in the "Burstable" or "Guaranteed" Qos? 2.3) Does the VMI just get evicted? -> `oc get events <vm-namespace> 2.4) If in the "Burstabel" QoS class, are we just the most likely eviciton target for kubelet because of a too tight packed node? -> kubelet logs from the node So here at one glance what we would need: 1) VMI spec of the running/crashing VM 2) `oc decsribe node <nodename>` 3) kubelet logs 4) oc get events <vm-namespace>
Created attachment 1645720 [details] kubelet.logs Retrieve kubelet logs on the node via 'journalctl -u kubelet --since "2019-12-17"'
Ok, I see ``` spec: domain: cpu: cores: 2 ``` and ``` resources: requests: cpu: 100m memory: 2Gi ``` THe `cpu: 100m` is probably from the cluster-default. Can you explicitly provide ``` resources: requests: cpu: "2" memory: 2Gi ``` I am pretty confident that it would then not go away. The Fedora VM has almost no CPU reserved, and makes heavy use of the two cores which it has. As a result it is the first target for evictions, because it is for sure the biggest consumer over its limits. This behaviour is ok and not a bug. It is also not a bug that the cpu count can be set independent of requests. Normally you set `requests.cpu` to `2` and leave `domain.cpu.cores` completely alone, or set it to the same number if you want two cores in the guest plus two reserved guests. Setting `cpu.cores` alone or to a higher number than `requests.cpu` is a way to do overcommit. So two questions: 1) Can you try setting `requests.cpu` to `2` and check if the VM is stable then? 2) How did you create the VM? Let's ensure that we create them the way which we intended to.
Answer question 2) firstly: - Create the VM from UI can see this issue - Create the VM from cli via `$ oc process -f vm-template-fedora.yaml -p NAME=fedora -p CPU_CORES=2 -p MEMORY=2Gi | oc create -f -` can see the issue as well.
> Answer question 2) firstly: > - Create the VM from UI can see this issue > - Create the VM from cli via `$ oc process -f vm-template-fedora.yaml -p NAME=fedora -p CPU_CORES=2 -p MEMORY=2Gi | oc create -f -` can see the issue as well. Makes sense. I think in both flows the template is used. Is this a template shipped in CNV? Do other templates also not set `requests.cpu`? If `requests.cpu` is not set, you are from the CNV/kubevirt perspective intentionally over-committing. Our VMs fall in this configuration into the "Burstable" QoS class, so they are not the top priority for evictions, but since the VMs are the only workload on the node, they will be the first ones which are evicted in this case.
The VMI is still keeping restarting with resources: requests: cpu: "2" memory: 4Gi
Ok, so let's look at a few more things: * virt-handler logs and * virt-controller logs
Created attachment 1645966 [details] virt-handler and virt-controller logs
A cirros VM runs normally with below content + 2 CPU, but Fedora and RHEL VM not. ``` resources: requests: cpu: 100m memory: 2Gi ```
So the investigation of the sytem showed that qemu crashes. The error is this: ``` 2019-12-18T09:50:38.541852Z qemu-kvm: could not enable queue qemu-kvm: /builddir/build/BUILD/qemu-4.1.0/hw/net/virtio-net.c:650: virtio_net_set_queues: Assertion `!r' failed. 2019-12-18 09:50:39.554+0000: shutting down, reason=crashed command terminated with exit code 137 ``` I checked selinux, and I found: ``` type=AVC msg=audit(1576662638.540:8152): avc: denied { attach_queue } for pid=795330 comm=43505520312F4B564D scontext=system_u:system_r:virt_launcher.process:s0:c135,c769 tcontext=system_u:system_r:virt_launcher.process:s0:c135,c769 tclass=tun_socket permissive=0 ``` I guess we did not catch that on the tier 1 CNV test runs, because the multi-core tests were disabled, since the QE environments have only 3.5 schedulable cores.
The VM can start fine if `networkInterfaceMultiqueue` is set to `false`. Fabian, let me know if we want a fix for 2.3.
https://github.com/kubevirt/kubevirt/pull/2941
The PR should solve the issue. I could not verify it.
Israel, can you please confirm that the workaround in comment #23 works? This would help us to understand if there is a workaround, and can help us to decide if we live with the workaround, or want to take trhe fix in comment #24. Does this bug also affect Windows VMs?
W/A from upper comment worked for fedora vm. Windows vm with 4 CPU works ok, but the template doesn't have the "networkInterfaceMultiqueue" by default. if trying to edit vm and add it, editor gives error.
small update: issue was reproduced on windows vm after changing interface type to virtio (default is e1000e) and adding "networkInterfaceMultiqueue: true"
Comment 29 is not to bad, because it is not a default path. Moving it back to POST and keeping it on high, as it affects RHEL (a supported guest).
Can confirm that https://github.com/kubevirt/kubevirt/pull/2941 fixes the issue. Will backport it when merged.
Backported with https://github.com/kubevirt/kubevirt/pull/2957. Needs a rebuild.
verified on: oc version Client Version: v4.3.0 Server Version: 4.3.0-0.nightly-2020-01-14-043441 Kubernetes Version: v1.16.2 checked with fedora and windows 10 vms. networkInterfaceMultiqueue: true tested 3 times with different cpu cores, sockets and threads values. all vms boot normally and no crashes/reboot/etc. observed after 10+ minutes
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. https://access.redhat.com/errata/RHEA-2020:0307