[ovirt-users] Live migration fails - domain not found -
Markus Stockhausen
stockhausen at collogia.de
Wed Mar 18 13:06:24 EDT 2015
Hi,
although we already upgraded several hypervisor nodes to Ovirt 3.5.1
the newest upgrade has left the host in a very strang state. We did:
- Host was removed from cluster
- Ovirt 3.5 repo was activated on host
- Host was "reinstalled" from enging
And we got:
- A host that is active and looks nice in the engine
- We can start/stop VMs on the host
- But we cannot live migrate machines to (or even away from) the host
Attached vdsm/libvirt/engine logs. Timestamps do not match as we
created them individually during different runs.
Somhow lost ...
Markus
*****************************
libvirt on target host:
2015-03-18 16:18:48.691+0000: 2093: debug : qemuMonitorJSONCommandWithFd:286 : Send command '{"execute":"qmp_capabilities","id":"libvirt-1"}' for write with FD -1
2015-03-18 16:18:48.691+0000: 2092: debug : qemuMonitorJSONIOProcessLine:179 : Line [{"QMP": {"version": {"qemu": {"micro": 2, "minor": 1, "major": 2}, "package": ""}, "capabilities": []}}]
2015-03-18 16:18:48.691+0000: 2092: debug : qemuMonitorJSONIOProcess:248 : Total used 105 bytes out of 105 available in buffer
2015-03-18 16:18:48.692+0000: 2092: debug : qemuMonitorJSONIOProcessLine:179 : Line [{"return": {}, "id": "libvirt-1"}]
2015-03-18 16:18:48.692+0000: 2092: debug : qemuMonitorJSONIOProcessLine:199 : QEMU_MONITOR_RECV_REPLY: mon=0x7fb40c017670 reply={"return": {}, "id": "libvirt-1"}
2015-03-18 16:18:48.692+0000: 2092: debug : qemuMonitorJSONIOProcess:248 : Total used 35 bytes out of 35 available in buffer
2015-03-18 16:18:48.692+0000: 2093: debug : qemuMonitorJSONCommandWithFd:291 : Receive command reply ret=0 rxObject=0x7fb445fbdb10
2015-03-18 16:18:48.692+0000: 2093: debug : qemuMonitorJSONCommandWithFd:286 : Send command '{"execute":"query-chardev","id":"libvirt-2"}' for write with FD -1
2015-03-18 16:18:48.693+0000: 2092: debug : qemuMonitorJSONIOProcessLine:179 : Line [{"return": [{"frontend-open": false, "filename": "spicevmc", "label": "charchannel2"}, {"frontend-open": false, "filename": "unix:/var/lib/libvirt/qemu/channels/d2d8bdfd-99a6-41c0-84e7-26e1d6a6057b.org.qemu.guest_agent.0,server", "label": "charchannel1"}, {"frontend-open": false, "filename": "unix:/var/lib/libvirt/qemu/channels/d2d8bdfd-99a6-41c0-84e7-26e1d6a6057b.com.redhat.rhevm.vdsm,server", "label": "charchannel0"}, {"frontend-open": true, "filename": "unix:/var/lib/libvirt/qemu/colvm60.monitor,server", "label": "charmonitor"}], "id": "libvirt-2"}]
2015-03-18 16:18:48.693+0000: 2092: debug : qemuMonitorJSONIOProcessLine:199 : QEMU_MONITOR_RECV_REPLY: mon=0x7fb40c017670 reply={"return": [{"frontend-open": false, "filename": "spicevmc", "label": "charchannel2"}, {"frontend-open": false, "filename": "unix:/var/lib/libvirt/qemu/channels/d2d8bdfd-99a6-41c0-84e7-26e1d6a6057b.org.qemu.guest_agent.0,server", "label": "charchannel1"}, {"frontend-open": false, "filename": "unix:/var/lib/libvirt/qemu/channels/d2d8bdfd-99a6-41c0-84e7-26e1d6a6057b.com.redhat.rhevm.vdsm,server", "label": "charchannel0"}, {"frontend-open": true, "filename": "unix:/var/lib/libvirt/qemu/colvm60.monitor,server", "label": "charmonitor"}], "id": "libvirt-2"}
2015-03-18 16:18:48.693+0000: 2092: debug : qemuMonitorJSONIOProcess:248 : Total used 559 bytes out of 559 available in buffer
2015-03-18 16:18:48.693+0000: 2093: debug : qemuMonitorJSONCommandWithFd:291 : Receive command reply ret=0 rxObject=0x7fb445ffe110
2015-03-18 16:18:48.694+0000: 2093: debug : qemuMonitorJSONCommandWithFd:286 : Send command '{"execute":"qom-list","arguments":{"path":"/machine/unattached/device[0]"},"id":"libvirt-3"}' for write with FD -1
2015-03-18 16:18:48.694+0000: 2092: debug : qemuMonitorJSONIOProcess:248 : Total used 0 bytes out of 1023 available in buffer
2015-03-18 16:18:48.695+0000: 2092: debug : qemuMonitorJSONIOProcessLine:179 : Line [{"return": [{"name": "apic", "type": "child<kvm-apic>"}, {"name": "filtered-features", "type": "X86CPUFeatureWordInfo"}, {"name": "feature-words", "type": "X86CPUFeatureWordInfo"}, {"name": "apic-id", "type": "int"}, {"name": "tsc-frequency", "type": "int"}, {"name": "model-id", "type": "string"}, {"name": "vendor", "type": "string"}, {"name": "xlevel", "type": "int"}, {"name": "level", "type": "int"}, {"name": "stepping", "type": "int"}, {"name": "model", "type": "int"}, {"name": "family", "type": "int"}, {"name": "parent_bus", "type": "link<bus>"}, {"name": "kvm", "type": "bool"}, {"name": "enforce", "type": "bool"}, {"name": "check", "type": "bool"}, {"name": "hv-time", "type": "bool"}, {"name": "hv-vapic", "type": "bool"}, {"name": "hv-relaxed", "type": "bool"}, {"name": "hv-spinlocks", "type": "int"}, {"name": "pmu", "type": "bool"}, {"name": "hotplugged", "type": "bool"}, {"name": "hotpluggable", "type": "bool"}, {"name": "realized", "type": "bool"}, {"name": "type", "type": "string"}], "id": "libvirt-3"}]
2015-03-18 16:18:48.695+0000: 2092: debug : qemuMonitorJSONIOProcessLine:199 : QEMU_MONITOR_RECV_REPLY: mon=0x7fb40c017670 reply={"return": [{"name": "apic", "type": "child<kvm-apic>"}, {"name": "filtered-features", "type": "X86CPUFeatureWordInfo"}, {"name": "feature-words", "type": "X86CPUFeatureWordInfo"}, {"name": "apic-id", "type": "int"}, {"name": "tsc-frequency", "type": "int"}, {"name": "model-id", "type": "string"}, {"name": "vendor", "type": "string"}, {"name": "xlevel", "type": "int"}, {"name": "level", "type": "int"}, {"name": "stepping", "type": "int"}, {"name": "model", "type": "int"}, {"name": "family", "type": "int"}, {"name": "parent_bus", "type": "link<bus>"}, {"name": "kvm", "type": "bool"}, {"name": "enforce", "type": "bool"}, {"name": "check", "type": "bool"}, {"name": "hv-time", "type": "bool"}, {"name": "hv-vapic", "type": "bool"}, {"name": "hv-relaxed", "type": "bool"}, {"name": "hv-spinlocks", "type": "int"}, {"name": "pmu", "type": "bool"}, {"name": "hotplugged", "type": "bool"}, {"name": "hotpluggable", "type": "bool"}, {"name": "realized", "type": "bool"}, {"name": "type", "type": "string"}], "id": "libvirt-3"}
2015-03-18 16:18:48.695+0000: 2092: debug : qemuMonitorJSONIOProcess:248 : Total used 1028 bytes out of 1028 available in buffer
2015-03-18 16:18:48.695+0000: 2093: debug : qemuMonitorJSONCommandWithFd:291 : Receive command reply ret=0 rxObject=0x7fb445fbe980
2015-03-18 16:18:48.695+0000: 2093: debug : qemuMonitorJSONCommandWithFd:286 : Send command '{"execute":"qom-get","arguments":{"path":"/machine/unattached/device[0]","property":"feature-words"},"id":"libvirt-4"}' for write with FD -1
2015-03-18 16:18:48.696+0000: 2092: debug : qemuMonitorJSONIOProcessLine:179 : Line [{"return": [{"cpuid-register": "EDX", "cpuid-input-eax": 2147483658, "features": 0}, {"cpuid-register": "EAX", "cpuid-input-eax": 1073741825, "features": 16777337}, {"cpuid-register": "EDX", "cpuid-input-eax": 3221225473, "features": 0}, {"cpuid-register": "EDX", "cpuid-input-eax": 2147483655, "features": 0}, {"cpuid-register": "ECX", "cpuid-input-eax": 2147483649, "features": 1}, {"cpuid-register": "EDX", "cpuid-input-eax": 2147483649, "features": 537921536}, {"cpuid-register": "EBX", "cpuid-input-ecx": 0, "cpuid-input-eax": 7, "features": 0}, {"cpuid-register": "ECX", "cpuid-input-eax": 1, "features": 2157453825}, {"cpuid-register": "EDX", "cpuid-input-eax": 1, "features": 126614525}], "id": "libvirt-4"}]
2015-03-18 16:18:48.696+0000: 2092: debug : qemuMonitorJSONIOProcessLine:199 : QEMU_MONITOR_RECV_REPLY: mon=0x7fb40c017670 reply={"return": [{"cpuid-register": "EDX", "cpuid-input-eax": 2147483658, "features": 0}, {"cpuid-register": "EAX", "cpuid-input-eax": 1073741825, "features": 16777337}, {"cpuid-register": "EDX", "cpuid-input-eax": 3221225473, "features": 0}, {"cpuid-register": "EDX", "cpuid-input-eax": 2147483655, "features": 0}, {"cpuid-register": "ECX", "cpuid-input-eax": 2147483649, "features": 1}, {"cpuid-register": "EDX", "cpuid-input-eax": 2147483649, "features": 537921536}, {"cpuid-register": "EBX", "cpuid-input-ecx": 0, "cpuid-input-eax": 7, "features": 0}, {"cpuid-register": "ECX", "cpuid-input-eax": 1, "features": 2157453825}, {"cpuid-register": "EDX", "cpuid-input-eax": 1, "features": 126614525}], "id": "libvirt-4"}
2015-03-18 16:18:48.696+0000: 2092: debug : qemuMonitorJSONIOProcess:248 : Total used 717 bytes out of 717 available in buffer
2015-03-18 16:18:48.696+0000: 2093: debug : qemuMonitorJSONCommandWithFd:291 : Receive command reply ret=0 rxObject=0x7fb445ffe550
2015-03-18 16:18:48.696+0000: 2093: debug : qemuMonitorJSONCommandWithFd:286 : Send command '{"execute":"query-cpus","id":"libvirt-5"}' for write with FD -1
2015-03-18 16:18:48.697+0000: 2092: debug : qemuMonitorJSONIOProcessLine:179 : Line [{"return": [{"current": true, "CPU": 0, "pc": 4294967280, "halted": false, "thread_id": 5826}, {"current": false, "CPU": 1, "pc": 4294967280, "halted": false, "thread_id": 5827}], "id": "libvirt-5"}]
2015-03-18 16:18:48.697+0000: 2092: debug : qemuMonitorJSONIOProcessLine:199 : QEMU_MONITOR_RECV_REPLY: mon=0x7fb40c017670 reply={"return": [{"current": true, "CPU": 0, "pc": 4294967280, "halted": false, "thread_id": 5826}, {"current": false, "CPU": 1, "pc": 4294967280, "halted": false, "thread_id": 5827}], "id": "libvirt-5"}
2015-03-18 16:18:48.698+0000: 2092: debug : qemuMonitorJSONIOProcess:248 : Total used 200 bytes out of 200 available in buffer
2015-03-18 16:18:48.698+0000: 2093: debug : qemuMonitorJSONCommandWithFd:291 : Receive command reply ret=0 rxObject=0x7fb445faf560
2015-03-18 16:18:48.698+0000: 2093: debug : qemuMonitorJSONCommandWithFd:286 : Send command '{"execute":"query-iothreads","id":"libvirt-6"}' for write with FD -1
2015-03-18 16:18:48.698+0000: 2092: debug : qemuMonitorJSONIOProcessLine:179 : Line [{"return": [], "id": "libvirt-6"}]
2015-03-18 16:18:48.699+0000: 2092: debug : qemuMonitorJSONIOProcessLine:199 : QEMU_MONITOR_RECV_REPLY: mon=0x7fb40c017670 reply={"return": [], "id": "libvirt-6"}
2015-03-18 16:18:48.699+0000: 2092: debug : qemuMonitorJSONIOProcess:248 : Total used 35 bytes out of 35 available in buffer
2015-03-18 16:18:48.699+0000: 2093: debug : qemuMonitorJSONCommandWithFd:291 : Receive command reply ret=0 rxObject=0x7fb445fbb970
2015-03-18 16:18:48.701+0000: 2093: debug : qemuMonitorJSONCommandWithFd:286 : Send command '{"execute":"set_password","arguments":{"protocol":"spice","password":"*****","connected":"keep"},"id":"libvirt-7"}' for write with FD -1
2015-03-18 16:18:48.703+0000: 2092: debug : qemuMonitorJSONIOProcessLine:179 : Line [{"return": {}, "id": "libvirt-7"}]
2015-03-18 16:18:48.703+0000: 2092: debug : qemuMonitorJSONIOProcessLine:199 : QEMU_MONITOR_RECV_REPLY: mon=0x7fb40c017670 reply={"return": {}, "id": "libvirt-7"}
2015-03-18 16:18:48.703+0000: 2092: debug : qemuMonitorJSONIOProcess:248 : Total used 35 bytes out of 35 available in buffer
2015-03-18 16:18:48.703+0000: 2093: debug : qemuMonitorJSONCommandWithFd:291 : Receive command reply ret=0 rxObject=0x7fb445fafe90
2015-03-18 16:18:48.703+0000: 2093: debug : qemuMonitorJSONCommandWithFd:286 : Send command '{"execute":"expire_password","arguments":{"protocol":"spice","time":"now"},"id":"libvirt-8"}' for write with FD -1
2015-03-18 16:18:48.704+0000: 2092: debug : qemuMonitorJSONIOProcessLine:179 : Line [{"return": {}, "id": "libvirt-8"}]
2015-03-18 16:18:48.704+0000: 2092: debug : qemuMonitorJSONIOProcessLine:199 : QEMU_MONITOR_RECV_REPLY: mon=0x7fb40c017670 reply={"return": {}, "id": "libvirt-8"}
2015-03-18 16:18:48.704+0000: 2092: debug : qemuMonitorJSONIOProcess:248 : Total used 35 bytes out of 35 available in buffer
2015-03-18 16:18:48.704+0000: 2093: debug : qemuMonitorJSONCommandWithFd:291 : Receive command reply ret=0 rxObject=0x7fb445fbe350
2015-03-18 16:18:48.704+0000: 2093: debug : qemuMonitorJSONCommandWithFd:286 : Send command '{"execute":"qom-list","arguments":{"path":"/machine/peripheral"},"id":"libvirt-9"}' for write with FD -1
2015-03-18 16:18:48.705+0000: 2092: debug : qemuMonitorJSONIOProcessLine:179 : Line [{"return": [{"name": "sound0-codec0", "type": "child<hda-duplex>"}, {"name": "sound0", "type": "child<intel-hda>"}, {"name": "video0", "type": "child<qxl-vga>"}, {"name": "channel2", "type": "child<virtserialport>"}, {"name": "channel1", "type": "child<virtserialport>"}, {"name": "channel0", "type": "child<virtserialport>"}, {"name": "net0", "type": "child<virtio-net-pci>"}, {"name": "virtio-disk0", "type": "child<virtio-blk-pci>"}, {"name": "ide0-1-0", "type": "child<ide-cd>"}, {"name": "virtio-serial0", "type": "child<virtio-serial-pci>"}, {"name": "scsi0", "type": "child<virtio-scsi-pci>"}, {"name": "usb", "type": "child<piix3-usb-uhci>"}, {"name": "type", "type": "string"}], "id": "libvirt-9"}]
2015-03-18 16:18:48.705+0000: 2092: debug : qemuMonitorJSONIOProcessLine:199 : QEMU_MONITOR_RECV_REPLY: mon=0x7fb40c017670 reply={"return": [{"name": "sound0-codec0", "type": "child<hda-duplex>"}, {"name": "sound0", "type": "child<intel-hda>"}, {"name": "video0", "type": "child<qxl-vga>"}, {"name": "channel2", "type": "child<virtserialport>"}, {"name": "channel1", "type": "child<virtserialport>"}, {"name": "channel0", "type": "child<virtserialport>"}, {"name": "net0", "type": "child<virtio-net-pci>"}, {"name": "virtio-disk0", "type": "child<virtio-blk-pci>"}, {"name": "ide0-1-0", "type": "child<ide-cd>"}, {"name": "virtio-serial0", "type": "child<virtio-serial-pci>"}, {"name": "scsi0", "type": "child<virtio-scsi-pci>"}, {"name": "usb", "type": "child<piix3-usb-uhci>"}, {"name": "type", "type": "string"}], "id": "libvirt-9"}
2015-03-18 16:18:48.705+0000: 2092: debug : qemuMonitorJSONIOProcess:248 : Total used 708 bytes out of 708 available in buffer
2015-03-18 16:18:48.705+0000: 2093: debug : qemuMonitorJSONCommandWithFd:291 : Receive command reply ret=0 rxObject=0x7fb445fbcc60
2015-03-18 16:18:48.706+0000: 2093: debug : qemuMonitorJSONCommandWithFd:286 : Send command '{"execute":"balloon","arguments":{"value":4294967296},"id":"libvirt-10"}' for write with FD -1
2015-03-18 16:18:48.706+0000: 2092: debug : qemuMonitorJSONIOProcessLine:179 : Line [{"id": "libvirt-10", "error": {"class": "DeviceNotActive", "desc": "No balloon device has been activated"}}]
2015-03-18 16:18:48.706+0000: 2092: debug : qemuMonitorJSONIOProcessLine:199 : QEMU_MONITOR_RECV_REPLY: mon=0x7fb40c017670 reply={"id": "libvirt-10", "error": {"class": "DeviceNotActive", "desc": "No balloon device has been activated"}}
2015-03-18 16:18:48.706+0000: 2092: debug : qemuMonitorJSONIOProcess:248 : Total used 109 bytes out of 109 available in buffer
2015-03-18 16:18:48.706+0000: 2093: debug : qemuMonitorJSONCommandWithFd:291 : Receive command reply ret=0 rxObject=0x7fb445fae850
2015-03-18 16:18:48.710+0000: 2093: debug : qemuMonitorJSONCommandWithFd:286 : Send command '{"execute":"query-migrate-capabilities","id":"libvirt-11"}' for write with FD -1
2015-03-18 16:18:48.711+0000: 2092: debug : qemuMonitorJSONIOProcessLine:179 : Line [{"return": [{"state": false, "capability": "xbzrle"}, {"state": false, "capability": "rdma-pin-all"}, {"state": false, "capability": "auto-converge"}, {"state": false, "capability": "zero-blocks"}], "id": "libvirt-11"}]
2015-03-18 16:18:48.711+0000: 2092: debug : qemuMonitorJSONIOProcessLine:199 : QEMU_MONITOR_RECV_REPLY: mon=0x7fb40c017670 reply={"return": [{"state": false, "capability": "xbzrle"}, {"state": false, "capability": "rdma-pin-all"}, {"state": false, "capability": "auto-converge"}, {"state": false, "capability": "zero-blocks"}], "id": "libvirt-11"}
2015-03-18 16:18:48.711+0000: 2092: debug : qemuMonitorJSONIOProcess:248 : Total used 220 bytes out of 220 available in buffer
2015-03-18 16:18:48.711+0000: 2093: debug : qemuMonitorJSONCommandWithFd:291 : Receive command reply ret=0 rxObject=0x7fb446051a80
2015-03-18 16:18:48.711+0000: 2093: debug : qemuMonitorJSONCommandWithFd:286 : Send command '{"execute":"migrate-set-capabilities","arguments":{"capabilities":[{"capability":"xbzrle","state":false}]},"id":"libvirt-12"}' for write with FD -1
2015-03-18 16:18:48.713+0000: 2092: debug : qemuMonitorJSONIOProcessLine:179 : Line [{"return": {}, "id": "libvirt-12"}]
2015-03-18 16:18:48.713+0000: 2092: debug : qemuMonitorJSONIOProcessLine:199 : QEMU_MONITOR_RECV_REPLY: mon=0x7fb40c017670 reply={"return": {}, "id": "libvirt-12"}
2015-03-18 16:18:48.713+0000: 2092: debug : qemuMonitorJSONIOProcess:248 : Total used 36 bytes out of 36 available in buffer
2015-03-18 16:18:48.713+0000: 2093: debug : qemuMonitorJSONCommandWithFd:291 : Receive command reply ret=0 rxObject=0x7fb445fae7a0
2015-03-18 16:18:48.713+0000: 2093: debug : qemuMonitorJSONCommandWithFd:286 : Send command '{"execute":"query-migrate-capabilities","id":"libvirt-13"}' for write with FD -1
2015-03-18 16:18:48.714+0000: 2092: debug : qemuMonitorJSONIOProcessLine:179 : Line [{"return": [{"state": false, "capability": "xbzrle"}, {"state": false, "capability": "rdma-pin-all"}, {"state": false, "capability": "auto-converge"}, {"state": false, "capability": "zero-blocks"}], "id": "libvirt-13"}]
2015-03-18 16:18:48.714+0000: 2092: debug : qemuMonitorJSONIOProcessLine:199 : QEMU_MONITOR_RECV_REPLY: mon=0x7fb40c017670 reply={"return": [{"state": false, "capability": "xbzrle"}, {"state": false, "capability": "rdma-pin-all"}, {"state": false, "capability": "auto-converge"}, {"state": false, "capability": "zero-blocks"}], "id": "libvirt-13"}
2015-03-18 16:18:48.714+0000: 2092: debug : qemuMonitorJSONIOProcess:248 : Total used 220 bytes out of 220 available in buffer
2015-03-18 16:18:48.714+0000: 2093: debug : qemuMonitorJSONCommandWithFd:291 : Receive command reply ret=0 rxObject=0x7fb446051a80
2015-03-18 16:18:48.714+0000: 2093: debug : qemuMonitorJSONCommandWithFd:286 : Send command '{"execute":"migrate-set-capabilities","arguments":{"capabilities":[{"capability":"rdma-pin-all","state":false}]},"id":"libvirt-14"}' for write with FD -1
2015-03-18 16:18:48.715+0000: 2092: debug : qemuMonitorJSONIOProcessLine:179 : Line [{"return": {}, "id": "libvirt-14"}]
2015-03-18 16:18:48.715+0000: 2092: debug : qemuMonitorJSONIOProcessLine:199 : QEMU_MONITOR_RECV_REPLY: mon=0x7fb40c017670 reply={"return": {}, "id": "libvirt-14"}
2015-03-18 16:18:48.715+0000: 2092: debug : qemuMonitorJSONIOProcess:248 : Total used 36 bytes out of 36 available in buffer
2015-03-18 16:18:48.715+0000: 2093: debug : qemuMonitorJSONCommandWithFd:291 : Receive command reply ret=0 rxObject=0x7fb445fbd2b0
2015-03-18 16:18:52.109+0000: 2093: error : virDBusCall:1537 : Fehler vom Service: TerminateMachine: No such file or directory
**************************************
vdsm log on target:
Thread-580::DEBUG::2015-03-18 17:49:06,252::stompReactor::163::yajsonrpc.StompServer::(send) Sending response
Thread-46::DEBUG::2015-03-18 17:49:06,294::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /usr/bin/dd if=/rhev/data-center/mnt/10.10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-46::DEBUG::2015-03-18 17:49:06,301::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n557 bytes (557 B) copied, 0.000317456 s, 1.8 MB/s\n'; <rc> = 0
Thread-38::DEBUG::2015-03-18 17:49:06,919::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /usr/bin/dd if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtIB/2c51d320-88ce-4f23-8215-e15f55f66906/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-33::DEBUG::2015-03-18 17:49:06,920::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /usr/bin/dd if=/rhev/data-center/mnt/10.10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-38::DEBUG::2015-03-18 17:49:06,932::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n644 bytes (644 B) copied, 0.000132903 s, 4.8 MB/s\n'; <rc> = 0
Thread-33::DEBUG::2015-03-18 17:49:06,933::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n644 bytes (644 B) copied, 0.000209828 s, 3.1 MB/s\n'; <rc> = 0
JsonRpc (StompReactor)::DEBUG::2015-03-18 17:49:09,272::stompReactor::98::Broker.StompAdapter::(handle_frame) Handling message <StompFrame command='SEND'>
JsonRpcServer::DEBUG::2015-03-18 17:49:09,274::__init__::506::jsonrpc.JsonRpcServer::(serve_requests) Waiting for request
Thread-581::DEBUG::2015-03-18 17:49:09,276::stompReactor::163::yajsonrpc.StompServer::(send) Sending response
JsonRpc (StompReactor)::DEBUG::2015-03-18 17:49:12,293::stompReactor::98::Broker.StompAdapter::(handle_frame) Handling message <StompFrame command='SEND'>
JsonRpcServer::DEBUG::2015-03-18 17:49:12,294::__init__::506::jsonrpc.JsonRpcServer::(serve_requests) Waiting for request
Thread-582::DEBUG::2015-03-18 17:49:12,296::task::595::Storage.TaskManager.Task::(_updateState) Task=`96a50a35-2ac9-44eb-b616-a4d7e76f5db8`::moving from state init -> state preparing
Thread-582::INFO::2015-03-18 17:49:12,302::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-582::INFO::2015-03-18 17:49:12,302::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'bff3a2be-fdd9-4e37-b416-fa4ef7fafba2': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.00030443', 'lastCheck': '6.1', 'valid': True}, '965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000209828', 'lastCheck': '5.4', 'valid': True}, '2c51d320-88ce-4f23-8215-e15f55f66906': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000132903', 'lastCheck': '5.4', 'valid': True}, '63041fa9-e093-4b44-b36f-f39f16d3974f': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000308898', 'lastCheck': '6.1', 'valid': True}, '272ec473-6041-42ee-bd1a-732789dd18d4': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000317456', 'lastCheck': '6.0', 'valid': True}}
Thread-582::DEBUG::2015-03-18 17:49:12,302::task::1191::Storage.TaskManager.Task::(prepare) Task=`96a50a35-2ac9-44eb-b616-a4d7e76f5db8`::finished: {'bff3a2be-fdd9-4e37-b416-fa4ef7fafba2': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.00030443', 'lastCheck': '6.1', 'valid': True}, '965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000209828', 'lastCheck': '5.4', 'valid': True}, '2c51d320-88ce-4f23-8215-e15f55f66906': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000132903', 'lastCheck': '5.4', 'valid': True}, '63041fa9-e093-4b44-b36f-f39f16d3974f': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000308898', 'lastCheck': '6.1', 'valid': True}, '272ec473-6041-42ee-bd1a-732789dd18d4': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000317456', 'lastCheck': '6.0', 'valid': True}}
Thread-582::DEBUG::2015-03-18 17:49:12,302::task::595::Storage.TaskManager.Task::(_updateState) Task=`96a50a35-2ac9-44eb-b616-a4d7e76f5db8`::moving from state preparing -> state finished
Thread-582::DEBUG::2015-03-18 17:49:12,303::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-582::DEBUG::2015-03-18 17:49:12,303::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-582::DEBUG::2015-03-18 17:49:12,303::task::993::Storage.TaskManager.Task::(_decref) Task=`96a50a35-2ac9-44eb-b616-a4d7e76f5db8`::ref 0 aborting False
Thread-582::DEBUG::2015-03-18 17:49:12,305::stompReactor::163::yajsonrpc.StompServer::(send) Sending response
JsonRpc (StompReactor)::DEBUG::2015-03-18 17:49:12,345::stompReactor::98::Broker.StompAdapter::(handle_frame) Handling message <StompFrame command='SEND'>
JsonRpcServer::DEBUG::2015-03-18 17:49:12,347::__init__::506::jsonrpc.JsonRpcServer::(serve_requests) Waiting for request
Thread-583::DEBUG::2015-03-18 17:49:12,348::stompReactor::163::yajsonrpc.StompServer::(send) Sending response
Detector thread::DEBUG::2015-03-18 17:49:13,490::protocoldetector::187::vds.MultiProtocolAcceptor::(_add_connection) Adding connection from 192.168.11.43:37057
Detector thread::DEBUG::2015-03-18 17:49:13,499::protocoldetector::201::vds.MultiProtocolAcceptor::(_remove_connection) Connection removed from 192.168.11.43:37057
Detector thread::DEBUG::2015-03-18 17:49:13,500::protocoldetector::246::vds.MultiProtocolAcceptor::(_handle_connection_read) Detected protocol xml from 192.168.11.43:37057
Detector thread::DEBUG::2015-03-18 17:49:13,500::BindingXMLRPC::1173::XmlDetector::(handleSocket) xml over http detected from ('192.168.11.43', 37057)
Thread-584::DEBUG::2015-03-18 17:49:13,502::BindingXMLRPC::1133::vds::(wrapper) client [192.168.11.43]::call vmGetStats with ('d2d8bdfd-99a6-41c0-84e7-26e1d6a6057b',) {}
Thread-584::DEBUG::2015-03-18 17:49:13,503::BindingXMLRPC::1140::vds::(wrapper) return vmGetStats with {'status': {'message': 'Virtual machine does not exist', 'code': 1}}
Detector thread::DEBUG::2015-03-18 17:49:13,534::protocoldetector::187::vds.MultiProtocolAcceptor::(_add_connection) Adding connection from 192.168.11.43:37058
Detector thread::DEBUG::2015-03-18 17:49:13,543::protocoldetector::201::vds.MultiProtocolAcceptor::(_remove_connection) Connection removed from 192.168.11.43:37058
Detector thread::DEBUG::2015-03-18 17:49:13,544::protocoldetector::246::vds.MultiProtocolAcceptor::(_handle_connection_read) Detected protocol xml from 192.168.11.43:37058
Detector thread::DEBUG::2015-03-18 17:49:13,544::BindingXMLRPC::1173::XmlDetector::(handleSocket) xml over http detected from ('192.168.11.43', 37058)
Thread-585::DEBUG::2015-03-18 17:49:13,557::BindingXMLRPC::1133::vds::(wrapper) client [192.168.11.43]::call vmMigrationCreate with ({'guestFQDN': 'colvm60.collogia.de', 'acpiEnable': 'true', 'emulatedMachine': 'pc-1.0', 'afterMigrationStatus': '', 'vmId': 'd2d8bdfd-99a6-41c0-84e7-26e1d6a6057b', 'memGuaranteedSize': 4096, 'transparentHugePages': 'true', 'displaySecurePort': '5902', 'spiceSslCipherSuite': 'DEFAULT', 'cpuType': 'Nehalem', 'smp': '2', 'pauseCode': 'NOERR', 'migrationDest': 'libvirt', 'smartcardEnable': 'false', 'hypervEnable': 'true', 'custom': {'device_86204f23-f278-4937-85c7-81696db7c90cdevice_e8a3825b-d5b7-4007-a4d7-0e4eec94771bdevice_622098c3-ebed-4f48-b33f-125fcb757ed6device_7cd98734-54cb-4963-96a3-ab85e48bcc8a': 'VmDevice {vmId=d2d8bdfd-99a6-41c0-84e7-26e1d6a6057b, deviceId=7cd98734-54cb-4963-96a3-ab85e48bcc8a, device=spicevmc, type=CHANNEL, bootOrder=0, specParams={}, address={port=3, bus=0, controller=0, type=virtio-serial}, managed=false, plugged=true, readOnly=false, deviceAlias=channel2, customProperties={}, snapshotId=null, logicalName=null}', 'device_86204f23-f278-4937-85c7-81696db7c90cdevice_e8a3825b-d5b7-4007-a4d7-0e4eec94771bdevice_622098c3-ebed-4f48-b33f-125fcb757ed6': 'VmDevice {vmId=d2d8bdfd-99a6-41c0-84e7-26e1d6a6057b, deviceId=622098c3-ebed-4f48-b33f-125fcb757ed6, device=unix, type=CHANNEL, bootOrder=0, specParams={}, address={port=2, bus=0, controller=0, type=virtio-serial}, managed=false, plugged=true, readOnly=false, deviceAlias=channel1, customProperties={}, snapshotId=null, logicalName=null}', 'device_86204f23-f278-4937-85c7-81696db7c90c': 'VmDevice {vmId=d2d8bdfd-99a6-41c0-84e7-26e1d6a6057b, deviceId=86204f23-f278-4937-85c7-81696db7c90c, device=ide, type=CONTROLLER, bootOrder=0, specParams={}, address={bus=0x00, domain=0x0000, type=pci, slot=0x01, function=0x1}, managed=false, plugged=true, readOnly=false, deviceAlias=ide0, customProperties={}, snapshotId=null, logicalName=null}', 'device_86204f23-f278-4937-85c7-81696db7c90cdevice_e8a3825b-d5b7-4007-a4d7-0e4eec94771b': 'VmDevice {vmId=d2d8bdfd-99a6-41c0-84e7-26e1d6a6057b, deviceId=e8a3825b-d5b7-4007-a4d7-0e4eec94771b, device=unix, type=CHANNEL, bootOrder=0, specParams={}, address={port=1, bus=0, controller=0, type=virtio-serial}, managed=false, plugged=true, readOnly=false, deviceAlias=channel0, customProperties={}, snapshotId=null, logicalName=null}'}, 'vmType': 'kvm', '_srcDomXML': "<domain type='kvm' id='29' xmlns:qemu='http://libvirt.org/schemas/domain/qemu/1.0'>\n <name>colvm60</name>\n <uuid>d2d8bdfd-99a6-41c0-84e7-26e1d6a6057b</uuid>\n <memory unit='KiB'>4194304</memory>\n <currentMemory unit='KiB'>4194304</currentMemory>\n <vcpu placement='static' current='2'>16</vcpu>\n <cputune>\n <shares>1020</shares>\n </cputune>\n <resource>\n <partition>/machine</partition>\n </resource>\n <sysinfo type='smbios'>\n <system>\n <entry name='manufacturer'>oVirt</entry>\n <entry name='product'>oVirt Node</entry>\n <entry name='version'>20-3</entry>\n <entry name='serial'>49434D53-0200-48D6-3000-D6483000EEC8</entry>\n <entry name='uuid'>d2d8bdfd-99a6-41c0-84e7-26e1d6a6057b</entry>\n </system>\n </sysinfo>\n <os>\n <type arch='x86_64' machine='pc-1.0'>hvm</type>\n <smbios mode='sysinfo'/>\n </os>\n <features>\n <acpi/>\n <hyperv>\n <relaxed state='on'/>\n </hyperv>\n </features>\n <cpu mode='custom' match='exact'>\n <model fallback='allow'>Nehalem</model>\n <topology sockets='16' cores='1' threads='1'/>\n </cpu>\n <clock offset='variable' adjustment='3600' basis='utc'>\n <timer name='rtc' tickpolicy='catchup' track='guest'/>\n <timer name='pit' tickpolicy='delay'/>\n </clock>\n <on_poweroff>destroy</on_poweroff>\n <on_reboot>restart</on_reboot>\n <on_crash>destroy</on_crash>\n <devices>\n <emulator>/usr/bin/qemu-kvm</emulator>\n <disk type='file' device='cdrom'>\n <driver name='qemu' type='raw'/>\n <source startupPolicy='optional'/>\n <backingStore/>\n <target dev='hdc' bus='ide'/>\n <readonly/>\n <serial></serial>\n <alias name='ide0-1-0'/>\n <address type='drive' controller='0' bus='1' target='0' unit='0'/>\n </disk>\n <disk type='file' device='disk' snapshot='no'>\n <driver name='qemu' type='raw' cache='none' error_policy='stop' io='threads'/>\n <source file='/rhev/data-center/94ed7a19-fade-4bd6-83f2-2cbb2f730b95/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/images/422a4486-6642-41ae-bb1d-b6a955550689/26b4c1e3-faf8-4fb3-b662-da6a55a3d8f2'>\n <seclabel model='selinux' labelskip='yes'/>\n </source>\n <backingStore/>\n <target dev='vda' bus='virtio'/>\n <serial>422a4486-6642-41ae-bb1d-b6a955550689</serial>\n <boot order='1'/>\n <alias name='virtio-disk0'/>\n <address type='pci' domain='0x0000' bus='0x00' slot='0x07' function='0x0'/>\n </disk>\n <controller type='scsi' index='0' model='virtio-scsi'>\n <alias name='scsi0'/>\n <address type='pci' domain='0x0000' bus='0x00' slot='0x05' function='0x0'/>\n </controller>\n <controller type='virtio-serial' index='0' ports='16'>\n <alias name='virtio-serial0'/>\n <address type='pci' domain='0x0000' bus='0x00' slot='0x06' function='0x0'/>\n </controller>\n <controller type='usb' index='0'>\n <alias name='usb0'/>\n <address type='pci' domain='0x0000' bus='0x00' slot='0x01' function='0x2'/>\n </controller>\n <controller type='pci' index='0' model='pci-root'>\n <alias name='pci.0'/>\n </controller>\n <controller type='ide' index='0'>\n <alias name='ide0'/>\n <address type='pci' domain='0x0000' bus='0x00' slot='0x01' function='0x1'/>\n </controller>\n <interface type='bridge'>\n <mac address='00:0c:29:7a:94:f1'/>\n <source bridge='ovirtmgmt'/>\n <bandwidth>\n </bandwidth>\n <target dev='vnet2'/>\n <model type='virtio'/>\n <filterref filter='vdsm-no-mac-spoofing'/>\n <link state='up'/>\n <boot order='2'/>\n <alias name='net0'/>\n <address type='pci' domain='0x0000' bus='0x00' slot='0x03' function='0x0'/>\n </interface>\n <channel type='unix'>\n <source mode='bind' path='/var/lib/libvirt/qemu/channels/d2d8bdfd-99a6-41c0-84e7-26e1d6a6057b.com.redhat.rhevm.vdsm'/>\n <target type='virtio' name='com.redhat.rhevm.vdsm'/>\n <alias name='channel0'/>\n <address type='virtio-serial' controller='0' bus='0' port='1'/>\n </channel>\n <channel type='unix'>\n <source mode='bind' path='/var/lib/libvirt/qemu/channels/d2d8bdfd-99a6-41c0-84e7-26e1d6a6057b.org.qemu.guest_agent.0'/>\n <target type='virtio' name='org.qemu.guest_agent.0'/>\n <alias name='channel1'/>\n <address type='virtio-serial' controller='0' bus='0' port='2'/>\n </channel>\n <channel type='spicevmc'>\n <target type='virtio' name='com.redhat.spice.0'/>\n <alias name='channel2'/>\n <address type='virtio-serial' controller='0' bus='0' port='3'/>\n </channel>\n <input type='mouse' bus='ps2'/>\n <input type='keyboard' bus='ps2'/>\n <graphics type='spice' tlsPort='5902' autoport='yes' keymap='de' passwdValidTo='1970-01-01T00:00:01' connected='keep'>\n <listen type='network' address='192.168.11.43' network='vdsm-ovirtmgmt'/>\n <channel name='main' mode='secure'/>\n <channel name='display' mode='secure'/>\n <channel name='inputs' mode='secure'/>\n <channel name='cursor' mode='secure'/>\n <channel name='playback' mode='secure'/>\n <channel name='record' mode='secure'/>\n <channel name='smartcard' mode='secure'/>\n <channel name='usbredir' mode='secure'/>\n </graphics>\n <sound model='ich6'>\n <alias name='sound0'/>\n <address type='pci' domain='0x0000' bus='0x00' slot='0x04' function='0x0'/>\n </sound>\n <video>\n <model type='qxl' ram='65536' vram='32768' heads='1'/>\n <alias name='video0'/>\n <address type='pci' domain='0x0000' bus='0x00' slot='0x02' function='0x0'/>\n </video>\n <memballoon model='none'>\n <alias name='balloon0'/>\n </memballoon>\n </devices>\n <seclabel type='dynamic' model='selinux' relabel='yes'>\n <label>system_u:system_r:svirt_t:s0:c356,c730</label>\n <imagelabel>system_u:object_r:svirt_image_t:s0:c356,c730</imagelabel>\n </seclabel>\n <qemu:commandline>\n <qemu:env name='SPICE_DEBUG_ALLOW_MC' value='1'/>\n </qemu:commandline>\n</domain>\n", 'memSize': 4096, 'smpCoresPerSocket': '1', 'vmName': 'colvm60', 'nice': '0', 'username': '', 'clientIp': '', 'bootMenuEnable': 'false', 'copyPasteEnable': 'true', 'displayIp': '192.168.11.43', 'keyboardLayout': 'de', 'displayPort': '-1', 'guestDiskMapping': {}, 'spiceSecureChannels': 'smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard', 'fileTransferEnable': 'true', 'nicModel': 'rtl8139,pv', 'elapsedTimeOffset': 4043.6238191127777, 'kvmEnable': 'true', 'displayNetwork': 'ovirtmgmt', 'devices': [{'alias': 'sound0', 'specParams': {}, 'deviceId': 'c0611af3-b676-4b7b-a794-1cea5f54e1db', 'address': {'slot': '0x04', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'ich6', 'type': 'sound'}, {'device': 'memballoon', 'specParams': {'model': 'none'}, 'type': 'balloon', 'alias': 'balloon0'}, {'index': '0', 'alias': 'scsi0', 'specParams': {}, 'deviceId': 'b0b3dbb0-dc4e-423c-8a56-9f06136db4d7', 'address': {'slot': '0x05', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'scsi', 'model': 'virtio-scsi', 'type': 'controller'}, {'alias': 'virtio-serial0', 'specParams': {}, 'deviceId': '7ea156ea-94bf-4bc3-bbd6-302b646cd596', 'address': {'slot': '0x06', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'virtio-serial', 'type': 'controller'}, {'alias': 'video0', 'specParams': {'vram': '32768', 'heads': '1'}, 'deviceId': '417a36be-98c1-4af7-950a-df13388c9e4d', 'address': {'slot': '0x02', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'qxl', 'type': 'video'}, {'device': 'spice', 'specParams': {'copyPasteEnable': 'true', 'displayNetwork': 'ovirtmgmt', 'keyMap': 'de', 'displayIp': '192.168.11.43', 'spiceSecureChannels': 'smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard'}, 'type': 'graphics', 'tlsPort': '5902'}, {'nicModel': 'pv', 'macAddr': '00:0c:29:7a:94:f1', 'linkActive': True, 'network': 'ovirtmgmt', 'alias': 'net0', 'bootOrder': '2', 'filter': 'vdsm-no-mac-spoofing', 'specParams': {'inbound': {}, 'outbound': {}}, 'deviceId': 'd8694952-f28d-4e97-a1d5-506daf4cc282', 'address': {'slot': '0x03', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'bridge', 'type': 'interface', 'name': 'vnet2'}, {'index': '2', 'iface': 'ide', 'name': 'hdc', 'alias': 'ide0-1-0', 'specParams': {'path': ''}, 'readonly': 'True', 'deviceId': '855a5a5b-7e9a-4e94-b1f0-7d8c26552503', 'address': {'bus': '1', 'controller': '0', 'type': 'drive', 'target': '0', 'unit': '0'}, 'device': 'cdrom', 'shared': 'false', 'path': '', 'type': 'disk'}, {'poolID': '94ed7a19-fade-4bd6-83f2-2cbb2f730b95', 'reqsize': '0', 'index': 0, 'iface': 'virtio', 'apparentsize': '48318382080', 'alias': 'virtio-disk0', 'imageID': '422a4486-6642-41ae-bb1d-b6a955550689', 'readonly': 'False', 'shared': 'false', 'truesize': '38062170112', 'type': 'disk', 'domainID': '965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545', 'volumeInfo': {'domainID': '965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545', 'volType': 'path', 'leaseOffset': 0, 'volumeID': '26b4c1e3-faf8-4fb3-b662-da6a55a3d8f2', 'leasePath': '/rhev/data-center/mnt/10.10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/images/422a4486-6642-41ae-bb1d-b6a955550689/26b4c1e3-faf8-4fb3-b662-da6a55a3d8f2.lease', 'imageID': '422a4486-6642-41ae-bb1d-b6a955550689', 'path': '/rhev/data-center/mnt/10.10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/images/422a4486-6642-41ae-bb1d-b6a955550689/26b4c1e3-faf8-4fb3-b662-da6a55a3d8f2'}, 'format': 'raw', 'deviceId': '422a4486-6642-41ae-bb1d-b6a955550689', 'address': {'slot': '0x07', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'disk', 'path': '/rhev/data-center/94ed7a19-fade-4bd6-83f2-2cbb2f730b95/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/images/422a4486-6642-41ae-bb1d-b6a955550689/26b4c1e3-faf8-4fb3-b662-da6a55a3d8f2', 'propagateErrors': 'off', 'optional': 'false', 'name': 'vda', 'bootOrder': '1', 'volumeID': '26b4c1e3-faf8-4fb3-b662-da6a55a3d8f2', 'specParams': {}, 'volumeChain': [{'domainID': '965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545', 'volType': 'path', 'leaseOffset': 0, 'volumeID': '26b4c1e3-faf8-4fb3-b662-da6a55a3d8f2', 'leasePath': '/rhev/data-center/mnt/10.10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/images/422a4486-6642-41ae-bb1d-b6a955550689/26b4c1e3-faf8-4fb3-b662-da6a55a3d8f2.lease', 'imageID': '422a4486-6642-41ae-bb1d-b6a955550689', 'path': '/rhev/data-center/mnt/10.10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/images/422a4486-6642-41ae-bb1d-b6a955550689/26b4c1e3-faf8-4fb3-b662-da6a55a3d8f2'}]}, {'device': 'usb', 'alias': 'usb0', 'type': 'controller', 'address': {'slot': '0x01', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x2'}}, {'device': 'ide', 'alias': 'ide0', 'type': 'controller', 'address': {'slot': '0x01', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x1'}}, {'device': 'unix', 'alias': 'channel0', 'type': 'channel', 'address': {'bus': '0', 'controller': '0', 'type': 'virtio-serial', 'port': '1'}}, {'device': 'unix', 'alias': 'channel1', 'type': 'channel', 'address': {'bus': '0', 'controller': '0', 'type': 'virtio-serial', 'port': '2'}}, {'device': 'spicevmc', 'alias': 'channel2', 'type': 'channel', 'address': {'bus': '0', 'controller': '0', 'type': 'virtio-serial', 'port': '3'}}], 'status': 'Up', 'timeOffset': '3600', 'maxVCpus': '16', 'guestIPs': '192.168.10.70', 'display': 'qxl'},) {}
Thread-585::DEBUG::2015-03-18 17:49:13,557::API::545::vds::(migrationCreate) Migration create
Thread-585::INFO::2015-03-18 17:49:13,558::clientIF::394::vds::(createVm) vmContainerLock acquired by vm d2d8bdfd-99a6-41c0-84e7-26e1d6a6057b
Thread-585::DEBUG::2015-03-18 17:49:13,570::clientIF::407::vds::(createVm) Total desktops after creation of d2d8bdfd-99a6-41c0-84e7-26e1d6a6057b is 1
Thread-586::DEBUG::2015-03-18 17:49:13,570::vm::2264::vm.Vm::(_startUnderlyingVm) vmId=`d2d8bdfd-99a6-41c0-84e7-26e1d6a6057b`::Start
Thread-586::DEBUG::2015-03-18 17:49:13,572::vm::2268::vm.Vm::(_startUnderlyingVm) vmId=`d2d8bdfd-99a6-41c0-84e7-26e1d6a6057b`::_ongoingCreations acquired
Thread-585::DEBUG::2015-03-18 17:49:13,572::vm::5658::vm.Vm::(waitForMigrationDestinationPrepare) vmId=`d2d8bdfd-99a6-41c0-84e7-26e1d6a6057b`::migration destination: waiting for VM creation
Thread-586::INFO::2015-03-18 17:49:13,573::vm::3261::vm.Vm::(_run) vmId=`d2d8bdfd-99a6-41c0-84e7-26e1d6a6057b`::VM wrapper has started
Thread-585::DEBUG::2015-03-18 17:49:13,574::vm::5663::vm.Vm::(waitForMigrationDestinationPrepare) vmId=`d2d8bdfd-99a6-41c0-84e7-26e1d6a6057b`::migration destination: waiting 36s for path preparation
Thread-586::WARNING::2015-03-18 17:49:13,575::vm::2056::vm.Vm::(buildConfDevices) vmId=`d2d8bdfd-99a6-41c0-84e7-26e1d6a6057b`::Unknown type found, device: '{'device': 'unix', 'alias': 'channel0', 'type': 'channel', 'address': {'bus': '0', 'controller': '0', 'type': 'virtio-serial', 'port': '1'}}' found
Thread-586::WARNING::2015-03-18 17:49:13,577::vm::2056::vm.Vm::(buildConfDevices) vmId=`d2d8bdfd-99a6-41c0-84e7-26e1d6a6057b`::Unknown type found, device: '{'device': 'unix', 'alias': 'channel1', 'type': 'channel', 'address': {'bus': '0', 'controller': '0', 'type': 'virtio-serial', 'port': '2'}}' found
Thread-586::WARNING::2015-03-18 17:49:13,577::vm::2056::vm.Vm::(buildConfDevices) vmId=`d2d8bdfd-99a6-41c0-84e7-26e1d6a6057b`::Unknown type found, device: '{'device': 'spicevmc', 'alias': 'channel2', 'type': 'channel', 'address': {'bus': '0', 'controller': '0', 'type': 'virtio-serial', 'port': '3'}}' found
Thread-586::DEBUG::2015-03-18 17:49:13,578::task::595::Storage.TaskManager.Task::(_updateState) Task=`44202a8b-c821-4571-8aab-0f8615914544`::moving from state init -> state preparing
Thread-586::INFO::2015-03-18 17:49:13,578::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545', spUUID='94ed7a19-fade-4bd6-83f2-2cbb2f730b95', imgUUID='422a4486-6642-41ae-bb1d-b6a955550689', volUUID='26b4c1e3-faf8-4fb3-b662-da6a55a3d8f2', options=None)
Thread-586::INFO::2015-03-18 17:49:13,582::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '38062174208', 'apparentsize': '48318382080'}
Thread-586::DEBUG::2015-03-18 17:49:13,582::task::1191::Storage.TaskManager.Task::(prepare) Task=`44202a8b-c821-4571-8aab-0f8615914544`::finished: {'truesize': '38062174208', 'apparentsize': '48318382080'}
Thread-586::DEBUG::2015-03-18 17:49:13,582::task::595::Storage.TaskManager.Task::(_updateState) Task=`44202a8b-c821-4571-8aab-0f8615914544`::moving from state preparing -> state finished
Thread-586::DEBUG::2015-03-18 17:49:13,582::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-586::DEBUG::2015-03-18 17:49:13,582::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-586::DEBUG::2015-03-18 17:49:13,583::task::993::Storage.TaskManager.Task::(_decref) Task=`44202a8b-c821-4571-8aab-0f8615914544`::ref 0 aborting False
Thread-586::INFO::2015-03-18 17:49:13,583::clientIF::335::vds::(prepareVolumePath) prepared volume path:
Thread-586::DEBUG::2015-03-18 17:49:13,583::task::595::Storage.TaskManager.Task::(_updateState) Task=`b4c42055-c38b-4427-90ad-a00120f4d5ee`::moving from state init -> state preparing
Thread-586::INFO::2015-03-18 17:49:13,583::logUtils::44::dispatcher::(wrapper) Run and protect: prepareImage(sdUUID='965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545', spUUID='94ed7a19-fade-4bd6-83f2-2cbb2f730b95', imgUUID='422a4486-6642-41ae-bb1d-b6a955550689', leafUUID='26b4c1e3-faf8-4fb3-b662-da6a55a3d8f2')
Thread-586::DEBUG::2015-03-18 17:49:13,584::resourceManager::198::Storage.ResourceManager.Request::(__init__) ResName=`Storage.965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545`ReqID=`bc4409f2-3b01-4467-998e-a29bee2de906`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '3201' at 'prepareImage'
Thread-586::DEBUG::2015-03-18 17:49:13,584::resourceManager::542::Storage.ResourceManager::(registerResource) Trying to register resource 'Storage.965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545' for lock type 'shared'
Thread-586::DEBUG::2015-03-18 17:49:13,585::resourceManager::601::Storage.ResourceManager::(registerResource) Resource 'Storage.965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545' is free. Now locking as 'shared' (1 active user)
Thread-586::DEBUG::2015-03-18 17:49:13,585::resourceManager::238::Storage.ResourceManager.Request::(grant) ResName=`Storage.965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545`ReqID=`bc4409f2-3b01-4467-998e-a29bee2de906`::Granted request
Thread-586::DEBUG::2015-03-18 17:49:13,585::task::827::Storage.TaskManager.Task::(resourceAcquired) Task=`b4c42055-c38b-4427-90ad-a00120f4d5ee`::_resourcesAcquired: Storage.965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545 (shared)
Thread-586::DEBUG::2015-03-18 17:49:13,585::task::993::Storage.TaskManager.Task::(_decref) Task=`b4c42055-c38b-4427-90ad-a00120f4d5ee`::ref 1 aborting False
Thread-586::DEBUG::2015-03-18 17:49:13,613::fileSD::499::Storage.StorageDomain::(activateVolumes) Fixing permissions on /rhev/data-center/mnt/10.10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/images/422a4486-6642-41ae-bb1d-b6a955550689/26b4c1e3-faf8-4fb3-b662-da6a55a3d8f2
Thread-586::DEBUG::2015-03-18 17:49:13,615::fileUtils::142::Storage.fileUtils::(createdir) Creating directory: /var/run/vdsm/storage/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545
Thread-586::WARNING::2015-03-18 17:49:13,615::fileUtils::149::Storage.fileUtils::(createdir) Dir /var/run/vdsm/storage/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545 already exists
Thread-586::DEBUG::2015-03-18 17:49:13,615::fileSD::474::Storage.StorageDomain::(createImageLinks) Creating symlink from /rhev/data-center/mnt/10.10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/images/422a4486-6642-41ae-bb1d-b6a955550689 to /var/run/vdsm/storage/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/422a4486-6642-41ae-bb1d-b6a955550689
Thread-586::DEBUG::2015-03-18 17:49:13,615::fileSD::479::Storage.StorageDomain::(createImageLinks) img run dir already exists: /var/run/vdsm/storage/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/422a4486-6642-41ae-bb1d-b6a955550689
Thread-586::DEBUG::2015-03-18 17:49:13,618::fileVolume::529::Storage.Volume::(validateVolumePath) validate path for 26b4c1e3-faf8-4fb3-b662-da6a55a3d8f2
Thread-586::INFO::2015-03-18 17:49:13,621::logUtils::47::dispatcher::(wrapper) Run and protect: prepareImage, Return response: {'info': {'domainID': '965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545', 'volType': 'path', 'leaseOffset': 0, 'path': u'/rhev/data-center/mnt/10.10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/images/422a4486-6642-41ae-bb1d-b6a955550689/26b4c1e3-faf8-4fb3-b662-da6a55a3d8f2', 'volumeID': u'26b4c1e3-faf8-4fb3-b662-da6a55a3d8f2', 'leasePath': u'/rhev/data-center/mnt/10.10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/images/422a4486-6642-41ae-bb1d-b6a955550689/26b4c1e3-faf8-4fb3-b662-da6a55a3d8f2.lease', 'imageID': '422a4486-6642-41ae-bb1d-b6a955550689'}, 'path': u'/rhev/data-center/94ed7a19-fade-4bd6-83f2-2cbb2f730b95/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/images/422a4486-6642-41ae-bb1d-b6a955550689/26b4c1e3-faf8-4fb3-b662-da6a55a3d8f2', 'imgVolumesInfo': [{'domainID': '965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545', 'volType': 'path', 'leaseOffset': 0, 'path': u'/rhev/data-center/mnt/10.10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/images/422a4486-6642-41ae-bb1d-b6a955550689/26b4c1e3-faf8-4fb3-b662-da6a55a3d8f2', 'volumeID': u'26b4c1e3-faf8-4fb3-b662-da6a55a3d8f2', 'leasePath': u'/rhev/data-center/mnt/10.10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/images/422a4486-6642-41ae-bb1d-b6a955550689/26b4c1e3-faf8-4fb3-b662-da6a55a3d8f2.lease', 'imageID': '422a4486-6642-41ae-bb1d-b6a955550689'}]}
Thread-586::DEBUG::2015-03-18 17:49:13,621::task::1191::Storage.TaskManager.Task::(prepare) Task=`b4c42055-c38b-4427-90ad-a00120f4d5ee`::finished: {'info': {'domainID': '965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545', 'volType': 'path', 'leaseOffset': 0, 'path': u'/rhev/data-center/mnt/10.10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/images/422a4486-6642-41ae-bb1d-b6a955550689/26b4c1e3-faf8-4fb3-b662-da6a55a3d8f2', 'volumeID': u'26b4c1e3-faf8-4fb3-b662-da6a55a3d8f2', 'leasePath': u'/rhev/data-center/mnt/10.10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/images/422a4486-6642-41ae-bb1d-b6a955550689/26b4c1e3-faf8-4fb3-b662-da6a55a3d8f2.lease', 'imageID': '422a4486-6642-41ae-bb1d-b6a955550689'}, 'path': u'/rhev/data-center/94ed7a19-fade-4bd6-83f2-2cbb2f730b95/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/images/422a4486-6642-41ae-bb1d-b6a955550689/26b4c1e3-faf8-4fb3-b662-da6a55a3d8f2', 'imgVolumesInfo': [{'domainID': '965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545', 'volType': 'path', 'leaseOffset': 0, 'path': u'/rhev/data-center/mnt/10.10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/images/422a4486-6642-41ae-bb1d-b6a955550689/26b4c1e3-faf8-4fb3-b662-da6a55a3d8f2', 'volumeID': u'26b4c1e3-faf8-4fb3-b662-da6a55a3d8f2', 'leasePath': u'/rhev/data-center/mnt/10.10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/images/422a4486-6642-41ae-bb1d-b6a955550689/26b4c1e3-faf8-4fb3-b662-da6a55a3d8f2.lease', 'imageID': '422a4486-6642-41ae-bb1d-b6a955550689'}]}
Thread-586::DEBUG::2015-03-18 17:49:13,622::task::595::Storage.TaskManager.Task::(_updateState) Task=`b4c42055-c38b-4427-90ad-a00120f4d5ee`::moving from state preparing -> state finished
Thread-586::DEBUG::2015-03-18 17:49:13,622::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545': < ResourceRef 'Storage.965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545', isValid: 'True' obj: 'None'>}
Thread-586::DEBUG::2015-03-18 17:49:13,622::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-586::DEBUG::2015-03-18 17:49:13,622::resourceManager::616::Storage.ResourceManager::(releaseResource) Trying to release resource 'Storage.965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545'
Thread-586::DEBUG::2015-03-18 17:49:13,622::resourceManager::635::Storage.ResourceManager::(releaseResource) Released resource 'Storage.965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545' (0 active users)
Thread-586::DEBUG::2015-03-18 17:49:13,623::resourceManager::641::Storage.ResourceManager::(releaseResource) Resource 'Storage.965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545' is free, finding out if anyone is waiting for it.
Thread-586::DEBUG::2015-03-18 17:49:13,623::resourceManager::649::Storage.ResourceManager::(releaseResource) No one is waiting for resource 'Storage.965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545', Clearing records.
Thread-586::DEBUG::2015-03-18 17:49:13,623::task::993::Storage.TaskManager.Task::(_decref) Task=`b4c42055-c38b-4427-90ad-a00120f4d5ee`::ref 0 aborting False
Thread-586::INFO::2015-03-18 17:49:13,623::clientIF::335::vds::(prepareVolumePath) prepared volume path: /rhev/data-center/94ed7a19-fade-4bd6-83f2-2cbb2f730b95/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/images/422a4486-6642-41ae-bb1d-b6a955550689/26b4c1e3-faf8-4fb3-b662-da6a55a3d8f2
Thread-586::DEBUG::2015-03-18 17:49:13,633::vm::1058::vm.Vm::(__init__) vmId=`d2d8bdfd-99a6-41c0-84e7-26e1d6a6057b`::Ignoring param (target, 4194304) in BalloonDevice
Thread-586::DEBUG::2015-03-18 17:49:13,633::vm::2294::vm.Vm::(_startUnderlyingVm) vmId=`d2d8bdfd-99a6-41c0-84e7-26e1d6a6057b`::_ongoingCreations released
Thread-586::DEBUG::2015-03-18 17:49:13,634::vm::4128::vm.Vm::(_waitForUnderlyingMigration) vmId=`d2d8bdfd-99a6-41c0-84e7-26e1d6a6057b`::Waiting 21600 seconds for end of migration
Thread-585::ERROR::2015-03-18 17:49:13,634::vm::5638::vm.Vm::(_updateDevicesDomxmlCache) vmId=`d2d8bdfd-99a6-41c0-84e7-26e1d6a6057b`::Alias not found for device type graphics during migration at destination host
Thread-585::DEBUG::2015-03-18 17:49:13,649::API::558::vds::(migrationCreate) Destination VM creation succeeded
Thread-585::DEBUG::2015-03-18 17:49:13,649::BindingXMLRPC::1140::vds::(wrapper) return vmMigrationCreate with {'status': {'message': 'Done', 'code': 0}, 'migrationPort': 0, 'params': {'username': '', 'acpiEnable': 'true', 'emulatedMachine': 'pc-1.0', 'afterMigrationStatus': '', 'pid': '0', 'memGuaranteedSize': 4096, 'transparentHugePages': 'true', 'displaySecurePort': '-1', 'spiceSslCipherSuite': 'DEFAULT', 'cpuType': 'Nehalem', 'custom': {'device_86204f23-f278-4937-85c7-81696db7c90cdevice_e8a3825b-d5b7-4007-a4d7-0e4eec94771bdevice_622098c3-ebed-4f48-b33f-125fcb757ed6': 'VmDevice {vmId=d2d8bdfd-99a6-41c0-84e7-26e1d6a6057b, deviceId=622098c3-ebed-4f48-b33f-125fcb757ed6, device=unix, type=CHANNEL, bootOrder=0, specParams={}, address={port=2, bus=0, controller=0, type=virtio-serial}, managed=false, plugged=true, readOnly=false, deviceAlias=channel1, customProperties={}, snapshotId=null, logicalName=null}', 'device_86204f23-f278-4937-85c7-81696db7c90cdevice_e8a3825b-d5b7-4007-a4d7-0e4eec94771b': 'VmDevice {vmId=d2d8bdfd-99a6-41c0-84e7-26e1d6a6057b, deviceId=e8a3825b-d5b7-4007-a4d7-0e4eec94771b, device=unix, type=CHANNEL, bootOrder=0, specParams={}, address={port=1, bus=0, controller=0, type=virtio-serial}, managed=false, plugged=true, readOnly=false, deviceAlias=channel0, customProperties={}, snapshotId=null, logicalName=null}', 'device_86204f23-f278-4937-85c7-81696db7c90c': 'VmDevice {vmId=d2d8bdfd-99a6-41c0-84e7-26e1d6a6057b, deviceId=86204f23-f278-4937-85c7-81696db7c90c, device=ide, type=CONTROLLER, bootOrder=0, specParams={}, address={bus=0x00, domain=0x0000, type=pci, slot=0x01, function=0x1}, managed=false, plugged=true, readOnly=false, deviceAlias=ide0, customProperties={}, snapshotId=null, logicalName=null}', 'device_86204f23-f278-4937-85c7-81696db7c90cdevice_e8a3825b-d5b7-4007-a4d7-0e4eec94771bdevice_622098c3-ebed-4f48-b33f-125fcb757ed6device_7cd98734-54cb-4963-96a3-ab85e48bcc8a': 'VmDevice {vmId=d2d8bdfd-99a6-41c0-84e7-26e1d6a6057b, deviceId=7cd98734-54cb-4963-96a3-ab85e48bcc8a, device=spicevmc, type=CHANNEL, bootOrder=0, specParams={}, address={port=3, bus=0, controller=0, type=virtio-serial}, managed=false, plugged=true, readOnly=false, deviceAlias=channel2, customProperties={}, snapshotId=null, logicalName=null}'}, 'pauseCode': 'NOERR', 'migrationDest': 'libvirt', 'hypervEnable': 'true', 'smp': '2', 'vmType': 'kvm', 'memSize': 4096, 'smpCoresPerSocket': '1', 'vmName': 'colvm60', 'nice': '0', 'guestFQDN': 'colvm60.collogia.de', 'bootMenuEnable': 'false', 'guestDiskMapping': {}, 'vmId': 'd2d8bdfd-99a6-41c0-84e7-26e1d6a6057b', 'copyPasteEnable': 'true', 'displayIp': '192.168.11.46', 'displayPort': '-1', 'guestIPs': '192.168.10.70', 'smartcardEnable': 'false', 'spiceSecureChannels': 'smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard', 'fileTransferEnable': 'true', 'nicModel': 'rtl8139,pv', 'keyboardLayout': 'de', 'kvmEnable': 'true', 'displayNetwork': 'ovirtmgmt', 'devices': [{'specParams': {}, 'alias': 'sound0', 'deviceId': 'c0611af3-b676-4b7b-a794-1cea5f54e1db', 'address': {'slot': '0x04', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'ich6', 'type': 'sound'}, {'device': 'memballoon', 'specParams': {'model': 'none'}, 'type': 'balloon', 'alias': 'balloon0'}, {'index': '0', 'alias': 'scsi0', 'specParams': {}, 'deviceId': 'b0b3dbb0-dc4e-423c-8a56-9f06136db4d7', 'address': {'slot': '0x05', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'scsi', 'model': 'virtio-scsi', 'type': 'controller'}, {'specParams': {}, 'alias': 'virtio-serial0', 'deviceId': '7ea156ea-94bf-4bc3-bbd6-302b646cd596', 'address': {'slot': '0x06', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'virtio-serial', 'type': 'controller'}, {'specParams': {'vram': '32768', 'heads': '1'}, 'alias': 'video0', 'deviceId': '417a36be-98c1-4af7-950a-df13388c9e4d', 'address': {'slot': '0x02', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'qxl', 'type': 'video'}, {'device': 'spice', 'specParams': {'spiceSecureChannels': 'smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard', 'copyPasteEnable': 'true', 'keyMap': 'de', 'displayIp': '192.168.11.43', 'displayNetwork': 'ovirtmgmt'}, 'type': 'graphics', 'tlsPort': '5902'}, {'nicModel': 'pv', 'macAddr': '00:0c:29:7a:94:f1', 'linkActive': True, 'network': 'ovirtmgmt', 'specParams': {'inbound': {}, 'outbound': {}}, 'bootOrder': '2', 'filter': 'vdsm-no-mac-spoofing', 'alias': 'net0', 'deviceId': 'd8694952-f28d-4e97-a1d5-506daf4cc282', 'address': {'slot': '0x03', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'bridge', 'type': 'interface', 'name': 'vnet2'}, {'index': '2', 'iface': 'ide', 'name': 'hdc', 'alias': 'ide0-1-0', 'specParams': {'path': ''}, 'readonly': 'True', 'deviceId': '855a5a5b-7e9a-4e94-b1f0-7d8c26552503', 'address': {'bus': '1', 'controller': '0', 'type': 'drive', 'target': '0', 'unit': '0'}, 'device': 'cdrom', 'shared': 'false', 'path': '', 'type': 'disk'}, {'poolID': '94ed7a19-fade-4bd6-83f2-2cbb2f730b95', 'volumeInfo': {'domainID': '965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545', 'volType': 'path', 'leaseOffset': 0, 'volumeID': '26b4c1e3-faf8-4fb3-b662-da6a55a3d8f2', 'leasePath': '/rhev/data-center/mnt/10.10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/images/422a4486-6642-41ae-bb1d-b6a955550689/26b4c1e3-faf8-4fb3-b662-da6a55a3d8f2.lease', 'imageID': '422a4486-6642-41ae-bb1d-b6a955550689', 'path': '/rhev/data-center/mnt/10.10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/images/422a4486-6642-41ae-bb1d-b6a955550689/26b4c1e3-faf8-4fb3-b662-da6a55a3d8f2'}, 'index': 0, 'iface': 'virtio', 'apparentsize': '48318382080', 'specParams': {}, 'imageID': '422a4486-6642-41ae-bb1d-b6a955550689', 'readonly': 'False', 'shared': 'false', 'truesize': '38062170112', 'type': 'disk', 'domainID': '965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545', 'reqsize': '0', 'format': 'raw', 'deviceId': '422a4486-6642-41ae-bb1d-b6a955550689', 'address': {'slot': '0x07', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'disk', 'path': '/rhev/data-center/94ed7a19-fade-4bd6-83f2-2cbb2f730b95/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/images/422a4486-6642-41ae-bb1d-b6a955550689/26b4c1e3-faf8-4fb3-b662-da6a55a3d8f2', 'propagateErrors': 'off', 'optional': 'false', 'name': 'vda', 'bootOrder': '1', 'volumeID': '26b4c1e3-faf8-4fb3-b662-da6a55a3d8f2', 'alias': 'virtio-disk0', 'volumeChain': [{'domainID': '965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545', 'volType': 'path', 'leaseOffset': 0, 'volumeID': '26b4c1e3-faf8-4fb3-b662-da6a55a3d8f2', 'leasePath': '/rhev/data-center/mnt/10.10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/images/422a4486-6642-41ae-bb1d-b6a955550689/26b4c1e3-faf8-4fb3-b662-da6a55a3d8f2.lease', 'imageID': '422a4486-6642-41ae-bb1d-b6a955550689', 'path': '/rhev/data-center/mnt/10.10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/images/422a4486-6642-41ae-bb1d-b6a955550689/26b4c1e3-faf8-4fb3-b662-da6a55a3d8f2'}]}, {'device': 'usb', 'alias': 'usb0', 'type': 'controller', 'address': {'slot': '0x01', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x2'}}, {'device': 'ide', 'alias': 'ide0', 'type': 'controller', 'address': {'slot': '0x01', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x1'}}, {'device': 'unix', 'alias': 'channel0', 'type': 'channel', 'address': {'bus': '0', 'controller': '0', 'type': 'virtio-serial', 'port': '1'}}, {'device': 'unix', 'alias': 'channel1', 'type': 'channel', 'address': {'bus': '0', 'controller': '0', 'type': 'virtio-serial', 'port': '2'}}, {'device': 'spicevmc', 'alias': 'channel2', 'type': 'channel', 'address': {'bus': '0', 'controller': '0', 'type': 'virtio-serial', 'port': '3'}}], 'status': 'Migration Destination', 'timeOffset': '3600', 'maxVCpus': '16', 'clientIp': '', 'display': 'qxl'}}
libvirtEventLoop::DEBUG::2015-03-18 17:49:14,221::vm::5571::vm.Vm::(_onLibvirtLifecycleEvent) vmId=`d2d8bdfd-99a6-41c0-84e7-26e1d6a6057b`::event Started detail 1 opaque None
JsonRpc (StompReactor)::DEBUG::2015-03-18 17:49:15,424::stompReactor::98::Broker.StompAdapter::(handle_frame) Handling message <StompFrame command='SEND'>
JsonRpcServer::DEBUG::2015-03-18 17:49:15,425::__init__::506::jsonrpc.JsonRpcServer::(serve_requests) Waiting for request
Thread-588::DEBUG::2015-03-18 17:49:15,427::stompReactor::163::yajsonrpc.StompServer::(send) Sending response
JsonRpc (StompReactor)::DEBUG::2015-03-18 17:49:15,432::stompReactor::98::Broker.StompAdapter::(handle_frame) Handling message <StompFrame command='SEND'>
JsonRpcServer::DEBUG::2015-03-18 17:49:15,434::__init__::506::jsonrpc.JsonRpcServer::(serve_requests) Waiting for request
Thread-589::DEBUG::2015-03-18 17:49:15,436::stompReactor::163::yajsonrpc.StompServer::(send) Sending response
Thread-32::DEBUG::2015-03-18 17:49:16,182::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /usr/bin/dd if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtISO/bff3a2be-fdd9-4e37-b416-fa4ef7fafba2/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-32::DEBUG::2015-03-18 17:49:16,189::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n357 bytes (357 B) copied, 0.000303553 s, 1.2 MB/s\n'; <rc> = 0
Thread-41::DEBUG::2015-03-18 17:49:16,193::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /usr/bin/dd if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtEXP/63041fa9-e093-4b44-b36f-f39f16d3974f/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-41::DEBUG::2015-03-18 17:49:16,200::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n363 bytes (363 B) copied, 0.000328831 s, 1.1 MB/s\n'; <rc> = 0
Thread-46::DEBUG::2015-03-18 17:49:16,305::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /usr/bin/dd if=/rhev/data-center/mnt/10.10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-46::DEBUG::2015-03-18 17:49:16,311::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n557 bytes (557 B) copied, 0.000287691 s, 1.9 MB/s\n'; <rc> = 0
Thread-38::DEBUG::2015-03-18 17:49:16,946::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /usr/bin/dd if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtIB/2c51d320-88ce-4f23-8215-e15f55f66906/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-33::DEBUG::2015-03-18 17:49:16,946::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /usr/bin/dd if=/rhev/data-center/mnt/10.10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-38::DEBUG::2015-03-18 17:49:16,956::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n644 bytes (644 B) copied, 0.00027901 s, 2.3 MB/s\n'; <rc> = 0
Thread-33::DEBUG::2015-03-18 17:49:16,958::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n644 bytes (644 B) copied, 0.000852178 s, 756 kB/s\n'; <rc> = 0
libvirtEventLoop::DEBUG::2015-03-18 17:49:17,619::vm::5571::vm.Vm::(_onLibvirtLifecycleEvent) vmId=`d2d8bdfd-99a6-41c0-84e7-26e1d6a6057b`::event Stopped detail 5 opaque None
libvirtEventLoop::INFO::2015-03-18 17:49:17,619::vm::2366::vm.Vm::(_onQemuDeath) vmId=`d2d8bdfd-99a6-41c0-84e7-26e1d6a6057b`::underlying process disconnected
libvirtEventLoop::INFO::2015-03-18 17:49:17,620::vm::4952::vm.Vm::(releaseVm) vmId=`d2d8bdfd-99a6-41c0-84e7-26e1d6a6057b`::Release VM resources
libvirtEventLoop::DEBUG::2015-03-18 17:49:17,623::task::595::Storage.TaskManager.Task::(_updateState) Task=`e0d01cc9-0a30-4b30-a163-0bb123aa9be2`::moving from state init -> state preparing
Thread-586::DEBUG::2015-03-18 17:49:17,624::libvirtconnection::143::root::(wrapper) Unknown libvirterror: ecode: 42 edom: 10 level: 2 message: Domain nicht gefunden: Keine Domain mit ?bereinstimmender UUID 'd2d8bdfd-99a6-41c0-84e7-26e1d6a6057b'
libvirtEventLoop::INFO::2015-03-18 17:49:17,624::logUtils::44::dispatcher::(wrapper) Run and protect: teardownImage(sdUUID='965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545', spUUID='94ed7a19-fade-4bd6-83f2-2cbb2f730b95', imgUUID='422a4486-6642-41ae-bb1d-b6a955550689', volUUID=None)
Thread-586::ERROR::2015-03-18 17:49:17,625::vm::2325::vm.Vm::(_startUnderlyingVm) vmId=`d2d8bdfd-99a6-41c0-84e7-26e1d6a6057b`::Failed to start a migration destination vm
Traceback (most recent call last):
File "/usr/share/vdsm/virt/vm.py", line 2298, in _startUnderlyingVm
self._completeIncomingMigration()
File "/usr/share/vdsm/virt/vm.py", line 4107, in _completeIncomingMigration
self._incomingMigrationFinished.isSet(), usedTimeout)
File "/usr/share/vdsm/virt/vm.py", line 4160, in _attachLibvirtDomainAfterMigration
raise MigrationError(e.get_error_message())
MigrationError: Domain nicht gefunden: Keine Domain mit ?bereinstimmender UUID 'd2d8bdfd-99a6-41c0-84e7-26e1d6a6057b'
libvirtEventLoop::DEBUG::2015-03-18 17:49:17,627::resourceManager::198::Storage.ResourceManager.Request::(__init__) ResName=`Storage.965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545`ReqID=`2ec4cc19-966e-4269-a6fc-bb3cf7a519b2`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '3253' at 'teardownImage'
libvirtEventLoop::DEBUG::2015-03-18 17:49:17,629::resourceManager::542::Storage.ResourceManager::(registerResource) Trying to register resource 'Storage.965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545' for lock type 'shared'
Detector thread::DEBUG::2015-03-18 17:49:17,629::protocoldetector::187::vds.MultiProtocolAcceptor::(_add_connection) Adding connection from 192.168.11.43:37061
Thread-586::DEBUG::2015-03-18 17:49:17,632::vm::2786::vm.Vm::(setDownStatus) vmId=`d2d8bdfd-99a6-41c0-84e7-26e1d6a6057b`::Changed state to Down: VM failed to migrate (code=8)
libvirtEventLoop::DEBUG::2015-03-18 17:49:17,632::resourceManager::601::Storage.ResourceManager::(registerResource) Resource 'Storage.965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545' is free. Now locking as 'shared' (1 active user)
libvirtEventLoop::DEBUG::2015-03-18 17:49:17,634::resourceManager::238::Storage.ResourceManager.Request::(grant) ResName=`Storage.965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545`ReqID=`2ec4cc19-966e-4269-a6fc-bb3cf7a519b2`::Granted request
libvirtEventLoop::DEBUG::2015-03-18 17:49:17,638::task::827::Storage.TaskManager.Task::(resourceAcquired) Task=`e0d01cc9-0a30-4b30-a163-0bb123aa9be2`::_resourcesAcquired: Storage.965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545 (shared)
libvirtEventLoop::DEBUG::2015-03-18 17:49:17,638::task::993::Storage.TaskManager.Task::(_decref) Task=`e0d01cc9-0a30-4b30-a163-0bb123aa9be2`::ref 1 aborting False
libvirtEventLoop::INFO::2015-03-18 17:49:17,638::logUtils::47::dispatcher::(wrapper) Run and protect: teardownImage, Return response: None
libvirtEventLoop::DEBUG::2015-03-18 17:49:17,638::task::1191::Storage.TaskManager.Task::(prepare) Task=`e0d01cc9-0a30-4b30-a163-0bb123aa9be2`::finished: None
libvirtEventLoop::DEBUG::2015-03-18 17:49:17,638::task::595::Storage.TaskManager.Task::(_updateState) Task=`e0d01cc9-0a30-4b30-a163-0bb123aa9be2`::moving from state preparing -> state finished
libvirtEventLoop::DEBUG::2015-03-18 17:49:17,639::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545': < ResourceRef 'Storage.965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545', isValid: 'True' obj: 'None'>}
libvirtEventLoop::DEBUG::2015-03-18 17:49:17,639::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
libvirtEventLoop::DEBUG::2015-03-18 17:49:17,639::resourceManager::616::Storage.ResourceManager::(releaseResource) Trying to release resource 'Storage.965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545'
libvirtEventLoop::DEBUG::2015-03-18 17:49:17,639::resourceManager::635::Storage.ResourceManager::(releaseResource) Released resource 'Storage.965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545' (0 active users)
libvirtEventLoop::DEBUG::2015-03-18 17:49:17,640::resourceManager::641::Storage.ResourceManager::(releaseResource) Resource 'Storage.965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545' is free, finding out if anyone is waiting for it.
libvirtEventLoop::DEBUG::2015-03-18 17:49:17,640::resourceManager::649::Storage.ResourceManager::(releaseResource) No one is waiting for resource 'Storage.965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545', Clearing records.
libvirtEventLoop::DEBUG::2015-03-18 17:49:17,640::task::993::Storage.TaskManager.Task::(_decref) Task=`e0d01cc9-0a30-4b30-a163-0bb123aa9be2`::ref 0 aborting False
libvirtEventLoop::WARNING::2015-03-18 17:49:17,640::utils::129::root::(rmFile) File: /var/lib/libvirt/qemu/channels/d2d8bdfd-99a6-41c0-84e7-26e1d6a6057b.com.redhat.rhevm.vdsm already removed
libvirtEventLoop::WARNING::2015-03-18 17:49:17,641::utils::129::root::(rmFile) File: /var/lib/libvirt/qemu/channels/d2d8bdfd-99a6-41c0-84e7-26e1d6a6057b.org.qemu.guest_agent.0 already removed
libvirtEventLoop::DEBUG::2015-03-18 17:49:17,641::task::595::Storage.TaskManager.Task::(_updateState) Task=`d02609f6-313a-45b7-b6fc-97c296f7456d`::moving from state init -> state preparing
libvirtEventLoop::INFO::2015-03-18 17:49:17,641::logUtils::44::dispatcher::(wrapper) Run and protect: inappropriateDevices(thiefId='d2d8bdfd-99a6-41c0-84e7-26e1d6a6057b')
Detector thread::DEBUG::2015-03-18 17:49:17,642::protocoldetector::201::vds.MultiProtocolAcceptor::(_remove_connection) Connection removed from 192.168.11.43:37061
Detector thread::DEBUG::2015-03-18 17:49:17,642::protocoldetector::246::vds.MultiProtocolAcceptor::(_handle_connection_read) Detected protocol xml from 192.168.11.43:37061
libvirtEventLoop::INFO::2015-03-18 17:49:17,642::logUtils::47::dispatcher::(wrapper) Run and protect: inappropriateDevices, Return response: None
Detector thread::DEBUG::2015-03-18 17:49:17,643::BindingXMLRPC::1173::XmlDetector::(handleSocket) xml over http detected from ('192.168.11.43', 37061)
libvirtEventLoop::DEBUG::2015-03-18 17:49:17,644::task::1191::Storage.TaskManager.Task::(prepare) Task=`d02609f6-313a-45b7-b6fc-97c296f7456d`::finished: None
libvirtEventLoop::DEBUG::2015-03-18 17:49:17,646::task::595::Storage.TaskManager.Task::(_updateState) Task=`d02609f6-313a-45b7-b6fc-97c296f7456d`::moving from state preparing -> state finished
libvirtEventLoop::DEBUG::2015-03-18 17:49:17,647::resourceManager::940::Storage.ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-590::DEBUG::2015-03-18 17:49:17,648::BindingXMLRPC::1133::vds::(wrapper) client [192.168.11.43]::call vmDestroy with ('d2d8bdfd-99a6-41c0-84e7-26e1d6a6057b',) {}
libvirtEventLoop::DEBUG::2015-03-18 17:49:17,648::resourceManager::977::Storage.ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-590::INFO::2015-03-18 17:49:17,649::API::332::vds::(destroy) vmContainerLock acquired by vm d2d8bdfd-99a6-41c0-84e7-26e1d6a6057b
libvirtEventLoop::DEBUG::2015-03-18 17:49:17,650::task::993::Storage.TaskManager.Task::(_decref) Task=`d02609f6-313a-45b7-b6fc-97c296f7456d`::ref 0 aborting False
Thread-590::DEBUG::2015-03-18 17:49:17,651::vm::5026::vm.Vm::(destroy) vmId=`d2d8bdfd-99a6-41c0-84e7-26e1d6a6057b`::destroy Called
libvirtEventLoop::WARNING::2015-03-18 17:49:17,651::vm::1953::vm.Vm::(_set_lastStatus) vmId=`d2d8bdfd-99a6-41c0-84e7-26e1d6a6057b`::trying to set state to Down when already Down
Thread-590::DEBUG::2015-03-18 17:49:17,653::vm::5020::vm.Vm::(deleteVm) vmId=`d2d8bdfd-99a6-41c0-84e7-26e1d6a6057b`::Total desktops after destroy of d2d8bdfd-99a6-41c0-84e7-26e1d6a6057b is 0
Thread-590::DEBUG::2015-03-18 17:49:17,653::BindingXMLRPC::1140::vds::(wrapper) return vmDestroy with {'status': {'message': 'Machine destroyed', 'code': 0}}
JsonRpc (StompReactor)::DEBUG::2015-03-18 17:49:18,463::stompReactor::98::Broker.StompAdapter::(handle_frame) Handling message <StompFrame command='SEND'>
JsonRpcServer::DEBUG::2015-03-18 17:49:18,465::__init__::506::jsonrpc.JsonRpcServer::(serve_requests) Waiting for request
Thread-591::DEBUG::2015-03-18 17:49:18,466::stompReactor::163::yajsonrpc.StompServer::(send) Sending response
JsonRpc (StompReactor)::DEBUG::2015-03-18 17:49:21,487::stompReactor::98::Broker.StompAdapter::(handle_frame) Handling message <StompFrame command='SEND'>
JsonRpcServer::DEBUG::2015-03-18 17:49:21,489::__init__::506::jsonrpc.JsonRpcServer::(serve_requests) Waiting for request
Thread-592::DEBUG::2015-03-18 17:49:21,491::stompReactor::163::yajsonrpc.StompServer::(send) Sending response
JsonRpc (StompReactor)::DEBUG::2015-03-18 17:49:24,669::stompReactor::98::Broker.StompAdapter::(handle_frame) Handling message <StompFrame command='SEND'>
JsonRpcServer::DEBUG::2015-03-18 17:49:24,671::__init__::506::jsonrpc.JsonRpcServer::(serve_requests) Waiting for request
Thread-593::DEBUG::2015-03-18 17:49:24,673::stompReactor::163::yajsonrpc.StompServer::(send) Sending response
Thread-32::DEBUG::2015-03-18 17:49:26,195::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /usr/bin/dd if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtISO/bff3a2be-fdd9-4e37-b416-fa4ef7fafba2/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-32::DEBUG::2015-03-18 17:49:26,202::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n357 bytes (357 B) copied, 0.000315366 s, 1.1 MB/s\n'; <rc> = 0
Thread-41::DEBUG::2015-03-18 17:49:26,206::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /usr/bin/dd if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtEXP/63041fa9-e093-4b44-b36f-f39f16d3974f/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-41::DEBUG::2015-03-18 17:49:26,213::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n363 bytes (363 B) copied, 0.000316359 s, 1.1 MB/s\n'; <rc> = 0
Thread-46::DEBUG::2015-03-18 17:49:26,315::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /usr/bin/dd if=/rhev/data-center/mnt/10.10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-46::DEBUG::2015-03-18 17:49:26,322::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n557 bytes (557 B) copied, 0.00033809 s, 1.6 MB/s\n'; <rc> = 0
Thread-38::DEBUG::2015-03-18 17:49:26,968::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /usr/bin/dd if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtIB/2c51d320-88ce-4f23-8215-e15f55f66906/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-33::DEBUG::2015-03-18 17:49:26,974::fileSD::261::Storage.Misc.excCmd::(getReadDelay) /usr/bin/dd if=/rhev/data-center/mnt/10.10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1 (cwd None)
Thread-38::DEBUG::2015-03-18 17:49:26,975::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n644 bytes (644 B) copied, 0.000260734 s, 2.5 MB/s\n'; <rc> = 0
Thread-33::DEBUG::2015-03-18 17:49:26,983::fileSD::261::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n644 bytes (644 B) copied, 0.000209731 s, 3.1 MB/s\n'; <rc> = 0
******************************************
engine log:
2015-03-18 17:15:28,051 INFO [org.ovirt.engine.core.bll.RefreshHostCapabilitiesCommand] (org.ovirt.thread.pool-8-thread-20) [6a89c3bd] Before acquiring lock in order to prevent monitoring for host colovn06 from data-center Collogia
2015-03-18 17:15:28,052 INFO [org.ovirt.engine.core.bll.RefreshHostCapabilitiesCommand] (org.ovirt.thread.pool-8-thread-20) [6a89c3bd] Lock acquired, from now a monitoring of host will be skipped for host colovn06 from data-center Collogia
2015-03-18 17:15:28,174 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.GetHardwareInfoVDSCommand] (org.ovirt.thread.pool-8-thread-20) [6a89c3bd] START, GetHardwareInfoVDSCommand(HostName = colovn06, HostId = 68963fb8-b386-4f5c-a88f-a7952bac78a3, vds=Host[colovn06,68963fb8-b386-4f5c-a88f-a7952bac78a3]), log id: 6e4d23dc
2015-03-18 17:15:28,180 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.GetHardwareInfoVDSCommand] (org.ovirt.thread.pool-8-thread-20) [6a89c3bd] FINISH, GetHardwareInfoVDSCommand, log id: 6e4d23dc
2015-03-18 17:15:28,273 INFO [org.ovirt.engine.core.bll.HandleVdsCpuFlagsOrClusterChangedCommand] (org.ovirt.thread.pool-8-thread-20) [2e2d467b] Running command: HandleVdsCpuFlagsOrClusterChangedCommand internal: true. Entities affected : ID: 68963fb8-b386-4f5c-a88f-a7952bac78a3 Type: VDS
2015-03-18 17:15:28,300 INFO [org.ovirt.engine.core.bll.HandleVdsVersionCommand] (org.ovirt.thread.pool-8-thread-20) [57ded262] Running command: HandleVdsVersionCommand internal: true. Entities affected : ID: 68963fb8-b386-4f5c-a88f-a7952bac78a3 Type: VDS
2015-03-18 17:15:28,303 INFO [org.ovirt.engine.core.bll.RefreshHostCapabilitiesCommand] (org.ovirt.thread.pool-8-thread-20) [57ded262] Refresh host capabilities finished. Lock released. Monitoring can run now for host colovn06 from data-center Collogia
2015-03-18 17:15:28,313 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (org.ovirt.thread.pool-8-thread-20) [57ded262] Correlation ID: 6a89c3bd, Call Stack: null, Custom Event ID: -1, Message: Successfully refreshed the capabilities of host colovn06.
2015-03-18 17:15:28,314 INFO [org.ovirt.engine.core.bll.RefreshHostCapabilitiesCommand] (org.ovirt.thread.pool-8-thread-20) [57ded262] Lock freed to object EngineLock [exclusiveLocks= key: 68963fb8-b386-4f5c-a88f-a7952bac78a3 value: VDS
, sharedLocks= ]
2015-03-18 17:18:47,844 INFO [org.ovirt.engine.core.bll.MigrateVmToServerCommand] (ajp--127.0.0.1-8702-8) [2dd847cf] Lock Acquired to object EngineLock [exclusiveLocks= key: d2d8bdfd-99a6-41c0-84e7-26e1d6a6057b value: VM
, sharedLocks= ]
2015-03-18 17:18:48,125 INFO [org.ovirt.engine.core.bll.MigrateVmToServerCommand] (org.ovirt.thread.pool-8-thread-30) [2dd847cf] Running command: MigrateVmToServerCommand internal: false. Entities affected : ID: d2d8bdfd-99a6-41c0-84e7-26e1d6a6057b Type: VMAction group MIGRATE_VM with role type USER, ID: d2d8bdfd-99a6-41c0-84e7-26e1d6a6057b Type: VMAction group EDIT_VM_PROPERTIES with role type USER, ID: 77ec9f6d-a0be-46f5-a2d0-6002f097e587 Type: VdsGroupsAction group CREATE_VM with role type USER
2015-03-18 17:18:48,261 INFO [org.ovirt.engine.core.vdsbroker.MigrateVDSCommand] (org.ovirt.thread.pool-8-thread-30) [2dd847cf] START, MigrateVDSCommand(HostName = colovn03, HostId = 708845a9-8b82-4d22-97e7-3a907f3005d5, vmId=d2d8bdfd-99a6-41c0-84e7-26e1d6a6057b, srcHost=192.168.11.43, dstVdsId=68963fb8-b386-4f5c-a88f-a7952bac78a3, dstHost=192.168.11.46:54321, migrationMethod=ONLINE, tunnelMigration=false, migrationDowntime=0), log id: 71fe79b2
2015-03-18 17:18:48,275 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.MigrateBrokerVDSCommand] (org.ovirt.thread.pool-8-thread-30) [2dd847cf] START, MigrateBrokerVDSCommand(HostName = colovn03, HostId = 708845a9-8b82-4d22-97e7-3a907f3005d5, vmId=d2d8bdfd-99a6-41c0-84e7-26e1d6a6057b, srcHost=192.168.11.43, dstVdsId=68963fb8-b386-4f5c-a88f-a7952bac78a3, dstHost=192.168.11.46:54321, migrationMethod=ONLINE, tunnelMigration=false, migrationDowntime=0), log id: 3496db06
2015-03-18 17:18:48,294 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.MigrateBrokerVDSCommand] (org.ovirt.thread.pool-8-thread-30) [2dd847cf] FINISH, MigrateBrokerVDSCommand, log id: 3496db06
2015-03-18 17:18:48,321 INFO [org.ovirt.engine.core.vdsbroker.MigrateVDSCommand] (org.ovirt.thread.pool-8-thread-30) [2dd847cf] FINISH, MigrateVDSCommand, return: MigratingFrom, log id: 71fe79b2
2015-03-18 17:18:48,339 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (org.ovirt.thread.pool-8-thread-30) [2dd847cf] Correlation ID: 2dd847cf, Job ID: 89ee5f05-f210-4700-9cc3-ae1efdc54a8d, Call Stack: null, Custom Event ID: -1, Message: Migration started (VM: colvm60, Source: colovn03, Destination: colovn06, User: stockhausen at collogia.de).
2015-03-18 17:18:51,160 INFO [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (DefaultQuartzScheduler_Worker-60) RefreshVmList vm id d2d8bdfd-99a6-41c0-84e7-26e1d6a6057b is migrating to vds colovn06 ignoring it in the refresh until migration is done
2015-03-18 17:18:52,591 INFO [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (DefaultQuartzScheduler_Worker-28) [5059f179] VM colvm60 d2d8bdfd-99a6-41c0-84e7-26e1d6a6057b moved from MigratingFrom --> Up
2015-03-18 17:18:52,594 INFO [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (DefaultQuartzScheduler_Worker-28) [5059f179] Adding VM d2d8bdfd-99a6-41c0-84e7-26e1d6a6057b to re-run list
2015-03-18 17:18:52,613 ERROR [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (DefaultQuartzScheduler_Worker-28) [5059f179] Rerun vm d2d8bdfd-99a6-41c0-84e7-26e1d6a6057b. Called from vds colovn03
2015-03-18 17:18:52,677 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.MigrateStatusVDSCommand] (org.ovirt.thread.pool-8-thread-27) [5059f179] START, MigrateStatusVDSCommand(HostName = colovn03, HostId = 708845a9-8b82-4d22-97e7-3a907f3005d5, vmId=d2d8bdfd-99a6-41c0-84e7-26e1d6a6057b), log id: 20cb664b
2015-03-18 17:18:52,683 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.MigrateStatusVDSCommand] (org.ovirt.thread.pool-8-thread-27) [5059f179] Failed in MigrateStatusVDS method
2015-03-18 17:18:52,684 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.MigrateStatusVDSCommand] (org.ovirt.thread.pool-8-thread-27) [5059f179] Command org.ovirt.engine.core.vdsbroker.vdsbroker.MigrateStatusVDSCommand return value
StatusOnlyReturnForXmlRpc [mStatus=StatusForXmlRpc [mCode=12, mMessage=Fatal error during migration]]
2015-03-18 17:18:52,686 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.MigrateStatusVDSCommand] (org.ovirt.thread.pool-8-thread-27) [5059f179] HostName = colovn03
2015-03-18 17:18:52,687 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.MigrateStatusVDSCommand] (org.ovirt.thread.pool-8-thread-27) [5059f179] Command MigrateStatusVDSCommand(HostName = colovn03, HostId = 708845a9-8b82-4d22-97e7-3a907f3005d5, vmId=d2d8bdfd-99a6-41c0-84e7-26e1d6a6057b) execution failed. Exception: VDSErrorException: VDSGenericException: VDSErrorException: Failed to MigrateStatusVDS, error = Fatal error during migration, code = 12
2015-03-18 17:18:52,690 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.MigrateStatusVDSCommand] (org.ovirt.thread.pool-8-thread-27) [5059f179] FINISH, MigrateStatusVDSCommand, log id: 20cb664b
2015-03-18 17:18:52,705 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (org.ovirt.thread.pool-8-thread-27) [5059f179] Correlation ID: 2dd847cf, Job ID: 89ee5f05-f210-4700-9cc3-ae1efdc54a8d, Call Stack: null, Custom Event ID: -1, Message: Migration failed due to Error: Fatal error during migration (VM: colvm60, Source: colovn03, Destination: colovn06).
2015-03-18 17:18:52,729 INFO [org.ovirt.engine.core.bll.MigrateVmToServerCommand] (org.ovirt.thread.pool-8-thread-27) [5059f179] Lock freed to object EngineLock [exclusiveLocks= key: d2d8bdfd-99a6-41c0-84e7-26e1d6a6057b value: VM
, sharedLocks= ]
-------------- next part --------------
An embedded and charset-unspecified text was scrubbed...
Name: InterScan_Disclaimer.txt
URL: <http://lists.ovirt.org/pipermail/users/attachments/20150318/9de4a9b5/attachment-0001.txt>
More information about the Users
mailing list