[libvirt] [BUG?] qemu was accidently killed by libvirtd after we restart libvirtd by service command

17 Dec 2015

      Hi all,

We came across a problem, qemu was accidently killed by libvirtd after we restart libvirtd by service command.
Steps to reproduce:
1） Attach net device to VM by 'virsh attach-device' command
2） Detach the net device that added before by 'virsh detach-device' command
3) Do the above two steps repeatedly, and at the same time, we restart libvirtd daemon.
And then we have chance to find that, after libvirtd is restarted at one time, qemu is killed accidently.

The libvirt log message is：
[2015-12-17 11:34:36]: libvirtd : 216046: info : libvirt version: 1.2.17
[2015-12-17 11:34:36]: libvirtd : 216046: warning : virDriverLoadModule:65 : Module /usr/lib64/libvirt/connection-driver/libvirt_driver_nwfilter.so not accessible
[2015-12-17 11:34:36]: libvirtd : 216046: info : virNetlinkEventServiceStart:662 : starting netlink event service with protocol 0
[2015-12-17 11:34:36]: libvirtd : 216046: info : virNetlinkEventServiceStart:712 : set netlink socket big buffer size
[2015-12-17 11:34:36]: libvirtd : 216046: info : virNetlinkEventServiceStart:662 : starting netlink event service with protocol 15
[2015-12-17 11:34:36]: libvirtd : 216046: info : virNetlinkEventServiceStart:712 : set netlink socket big buffer size
[2015-12-17 11:34:36]: libvirtd : 216079: error : dnsmasqCapsRefreshInternal:741 : Cannot check dnsmasq binary /usr/sbin/dnsmasq: No such file or directory
[2015-12-17 11:34:36]: libvirtd : 216079: info : networkReloadFirewallRules:1861 : Reloading iptables rules
[2015-12-17 11:34:36]: libvirtd : 216079: info : networkRefreshDaemons:1830 : Refreshing network daemons
[2015-12-17 11:34:36]: libvirtd : 216079: error : virNodeSuspendSupportsTarget:332 : internal error: Cannot probe for supported suspend types
[2015-12-17 11:34:36]: libvirtd : 216079: warning : virQEMUCapsInit:1037 : Failed to get host power management capabilities
[2015-12-17 11:34:36]: libvirtd : 216079: info : virDomainObjListLoadAllConfigs:23039 : Scanning for configs in /var/run/libvirt/qemu
[2015-12-17 11:34:36]: libvirtd : 216079: info : virDomainObjListLoadAllConfigs:23063 : Loading config file 'VMName.xml'
[2015-12-17 11:34:36]: libvirtd : 216079: info : virDomainObjListLoadAllConfigs:23063 : Loading config file 'VMName2.xml'
[2015-12-17 11:34:36]: libvirtd : 216079: info : virDomainObjListLoadAllConfigs:23063 : Loading config file 'VMName3.xml'
[2015-12-17 11:34:36]: libvirtd : 216079: info : virDomainObjListLoadAllConfigs:23039 : Scanning for configs in /etc/libvirt/qemu
[2015-12-17 11:34:36]: libvirtd : 216079: info : virDomainObjListLoadAllConfigs:23063 : Loading config file 'VMName.xml'
[2015-12-17 11:34:36]: libvirtd : 216079: info : virDomainObjListLoadAllConfigs:23063 : Loading config file 'VMName2.xml'
[2015-12-17 11:34:36]: libvirtd : 216079: info : virDomainObjListLoadAllConfigs:23063 : Loading config file 'VMName3.xml'
[2015-12-17 11:34:36]: libvirtd : 216079: info : qemuDomainSnapshotLoad:490 : Scanning for snapshots for domain VMName in /var/lib/libvirt/qemu/snapshot/VMName
[2015-12-17 11:34:36]: libvirtd : 216079: info : qemuDomainSnapshotLoad:490 : Scanning for snapshots for domain VMName2 in /var/lib/libvirt/qemu/snapshot/VMName2
[2015-12-17 11:34:36]: libvirtd : 216079: info : qemuDomainSnapshotLoad:490 : Scanning for snapshots for domain VMName3 in /var/lib/libvirt/qemu/snapshot/VMName3
[2015-12-17 11:34:36]: libvirtd : 216047: info : remoteDispatchDomainDetachDevice:4105 : Domain is detached a device by client: 127.0.0.1;0
[2015-12-17 11:34:36]: libvirtd : 216050: info : remoteDispatchDomainDetachDevice:4105 : Domain is detached a device by client: 127.0.0.1;0
[2015-12-17 11:34:36]: libvirtd : 216047: info : virDomainDetachDevice:8508 : enter virDomainDetachDevice domainname=VMName2, xml= <interface type='bridge'>^M
   <source bridge='br-1'/>^M
           <mac address='00:16:3e:76:85:17'/>^M
<virtualport type='openvswitch' />^M
       <model type='virtio'/>^M
</interface>^M
^M

[2015-12-17 11:34:36]: libvirtd : 216050: info : virDomainDetachDevice:8508 : enter virDomainDetachDevice domainname=VMName, xml= <interface type='bridge'>^M
   <source bridge='br-1'/>^M
           <mac address='00:16:3e:76:85:15'/>^M
2015-12-17 11:34:36]: libvirtd : 216095: error : qemuMonitorJSONCheckError:380 : internal error: unable to execute QEMU command 'netdev_del': Device 'hostnet5' not found
[2015-12-17 11:34:36]: libvirtd : 216096: error : qemuMonitorJSONCheckError:380 : internal error: unable to execute QEMU command 'netdev_del': Device 'hostnet2' not found
[2015-12-17 11:34:36]: libvirtd : 216097: error : qemuMonitorJSONCheckError:380 : internal error: unable to execute QEMU command 'netdev_del': Device 'hostnet1' not found
[2015-12-17 11:34:37]: libvirtd : 216095: info : virSecurityDACRestoreSecurityFileLabelInternal:325 : Restoring DAC user and group on '/data/suse11_sp3_64_1'
[2015-12-17 11:34:37]: libvirtd : 216095: info : virSecurityDACSetOwnershipInternal:248 : Setting DAC user and group on '/data/suse11_sp3_64_1' to '0:0'
[2015-12-17 11:34:37]: libvirtd : 216096: info : virSecurityDACRestoreSecurityFileLabelInternal:325 : Restoring DAC user and group on '/data/suse11_sp3_64_2'
[2015-12-17 11:34:37]: libvirtd : 216096: info : virSecurityDACSetOwnershipInternal:248 : Setting DAC user and group on '/data/suse11_sp3_64_2' to '0:0'
[2015-12-17 11:34:37]: libvirtd : 216095: info : qemuProcessStop:5720 : VM 'VMName' is dying,remove vBMC
[2015-12-17 11:34:37]: libvirtd : 216095: error : rtev_vBMC_send:209 : Failed to remove domain vBMC bind path for 33ae1cb0-c451-4620-8cee-1bbddd124b82, errno is 2
[2015-12-17 11:34:37]: libvirtd : 216050: info : remoteDispatchDomainAttachDevice:2855 : Domain is attached a device by client: 127.0.0.1;0
[2015-12-17 11:34:37]: libvirtd : 216050: info : virDomainAttachDevice:8390 : enter virDomainAttachDevice domainname=VMName, xml=<interface type='bridge'>^M

The VM's qemu log is:
[2015-12-17 11:34:30] handle_qmp_command:5115 qmp_cmd_name: device_del, qmp_cmd_arguments: {"id": "net4"}
[2015-12-17 11:34:30] virtio_set_status:524 virtio-net device status is 1 that means ACKNOWLEDGE
[2015-12-17 11:34:30] virtio_set_status:524 virtio-net device status is 1 that means ACKNOWLEDGE
[2015-12-17 11:34:30] virtio_pci_device_unplugged:966 virtio-net
[2015-12-17 11:34:30] monitor_qapi_event_emit:483 {"timestamp": {"seconds": 1450352070, "microseconds": 402473}, "event": "DEVICE_DELETED", "data": {"path": "/machine/peripheral/net4/virtio-backend"}}
[2015-12-17 11:34:30] monitor_qapi_event_emit:483 {"timestamp": {"seconds": 1450352070, "microseconds": 402586}, "event": "DEVICE_DELETED", "data": {"device": "net4", "path": "/machine/peripheral/net4"}}
[2015-12-17 11:34:30] handle_qmp_command:5115 qmp_cmd_name: netdev_del, qmp_cmd_arguments: {"id": "hostnet4"}
[2015-12-17 11:34:30] handle_qmp_command:5115 qmp_cmd_name: qom-list, qmp_cmd_arguments: {"path": "/machine/peripheral"}
---------------------------------------------- At this time, We restart libvirtd just right ------------------------------------------------------------
[2015-12-17 11:34:30] handle_qmp_command:5115 qmp_cmd_name: device_del, qmp_cmd_arguments: {"id": "net5"}
[2015-12-17 11:34:30] virtio_set_status:524 virtio-net device status is 1 that means ACKNOWLEDGE
[2015-12-17 11:34:30] virtio_set_status:524 virtio-net device status is 1 that means ACKNOWLEDGE
[2015-12-17 11:34:30] virtio_pci_device_unplugged:966 virtio-net
[2015-12-17 11:34:30] monitor_qapi_event_emit:483 {"timestamp": {"seconds": 1450352070, "microseconds": 810030}, "event": "DEVICE_DELETED", "data": {"path": "/machine/peripheral/net5/virtio-backend"}}
[2015-12-17 11:34:30] monitor_qapi_event_emit:483 {"timestamp": {"seconds": 1450352070, "microseconds": 810150}, "event": "DEVICE_DELETED", "data": {"device": "net5", "path": "/machine/peripheral/net5"}}
[2015-12-17 11:34:30] handle_qmp_command:5115 qmp_cmd_name: netdev_del, qmp_cmd_arguments: {"id": "hostnet5"}
[2015-12-17 11:34:35] send_control_event:225 virtio serial port 2 send control message event = 6, value = 0
[2015-12-17 11:34:36] handle_qmp_command:5105 qmp_cmd_name: qmp_capabilities
[2015-12-17 11:34:36] handle_qmp_command:5105 qmp_cmd_name: query-commands
[2015-12-17 11:34:36] handle_qmp_command:5115 qmp_cmd_name: add-fd, qmp_cmd_arguments: {"fdset-id": 0, "opaque": "/dev/null"}
[2015-12-17 11:34:36] handle_qmp_command:5115 qmp_cmd_name: block-commit, qmp_cmd_arguments: {"device": "bogus"}
[2015-12-17 11:34:36] handle_qmp_command:5105 qmp_cmd_name: query-events
[2015-12-17 11:34:36] send_control_event:225 virtio serial port 2 send control message event = 6, value = 1
[2015-12-17 11:34:36] handle_qmp_command:5105 qmp_cmd_name: query-status
[2015-12-17 11:34:36] handle_qmp_command:5105 qmp_cmd_name: query-block
[2015-12-17 11:34:36] handle_qmp_command:5105 qmp_cmd_name: query-chardev
[2015-12-17 11:34:36] handle_qmp_command:5115 qmp_cmd_name: qom-list, qmp_cmd_arguments: {"path": "/machine/peripheral"}
[2015-12-17 11:34:36] handle_qmp_command:5115 qmp_cmd_name: netdev_del, qmp_cmd_arguments: {"id": "hostnet5"}
[2015-12-17 11:34:36]: shutting down
[2015-12-17 11:34:36] send_control_event:225 virtio serial port 2 send control message event = 6, value = 0
qemu: terminating on signal 15 from pid 216046(libvirtd)
[2015-12-17 11:34:36] monitor_qapi_event_emit:483 {"timestamp": {"seconds": 1450352076, "microseconds": 267427}, "event": "SHUTDOWN"}
[2015-12-17 11:34:36] monitor_qapi_event_emit:483 {"timestamp": {"seconds": 1450352076, "microseconds": 267773}, "event": "DEVICE_TRAY_MOVED", "data": {"device": "drive-ide0-0-1", "tray-open": true}}

We have analyzed this problem, and thought it was triggered by the inconsistent state for the net device
between qemu and the new libvirtd.
After libvirtd is started, it will connect to qemu, and updates the devices state by command 'qom-list',
and also it will read the configure information from XML stored.
The codes call process is:
qemuProcessReconnect
   ->qemuProcessUpdateDevices
        ->if (qemuDomainUpdateDeviceList(driver, vm, QEMU_ASYNC_JOB_NONE) < 0)
        ->if ((tmp = old)) {
         while (*tmp) {
             if (!virStringArrayHasString(priv->qemuDevices, *tmp) &&
                 virDomainDefFindDevice(vm->def, *tmp, &dev, false) == 0 &&
                 qemuDomainRemoveDevice(driver, vm, &dev) < 0) {
                 goto cleanup;  --->If we fail here, it will return -1; and it will call
                                    qemuProcessStop() in qemuProcessReconnect to kill VM.
             }
             tmp++;
         }
     }
It is a little hard to reproduce this problem, we can reproduce it in a special way:
1) Attach a net device by virsh command
2) Stop libvirtd
3) Detach the net device by directly send qmp command to QEMU though the monitor, just like:
# ./qmp-shell /var/lib/libvirt/qemu/redhat.monitor
Welcome to the QMP low-level shell!
Connected to QEMU 2.3.0

(QEMU) qom-list path=/machine/peripheral
{u'return': [{u'type': u'child<virtio-net-pci>', u'name': u'net1'}, {u'type': u'child<cirrus-vga>', u'name': u'video0'}, {u'type': u'child<usb-tablet>', u'name': u'input0'}, {u'type': u'child<isa-serial>', u'name': u'serial0'}, {u'type': u'child<virtio-net-pci>', u'name': u'net0'}, {u'type': u'child<scsi-hd>', u'name': u'scsi0-0-0-0'}, {u'type': u'child<virtio-scsi-pci>', u'name': u'scsi0'}, {u'type': u'child<piix3-usb-uhci>', u'name': u'usb'}, {u'type': u'string', u'name': u'type'}]}
(QEMU) device_del id=net1
{u'return': {}}
(QEMU) netdev_del id=hostnet1
{u'return': {}}
4) Restart libvirtd daemon and then you will found that qemu is killed by libvirtd.

The main reason for the inconsistent state is, we accidently restarted libvirtd before it finished treating
'detach device' work.
It seems a little violent to kill such VM directly.
Can we just do the unfinished cleanup work for the VM after libvirtd is starting ?
(IMHO, we can't ensure not to restart libvirtd while it is treating the detach device work.)

Thanks.
zhanghailiang

Hailiang Zhang

Laine Stump

tags

participants (2)