Thread-57::DEBUG::2014-11-13 17:36:26,669::BindingXMLRPC::1067::vds::(wrapper) client [192.168.111.101]::call vmMigrationCreate with ({'guestFQDN': 'puppetdb.example.com', 'acpiEnable': 'true', 'emulatedMachine': 'rhel6.5.0', 'afterMigrationStatus': '', 'spiceSecureChannels': 'smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard', 'vmId': '0fdea856-9aec-4300-8d88-4cfd330cf4ff', 'memGuaranteedSize': 2048, 'transparentHugePages': 'true', 'displaySecurePort': '5902', 'spiceSslCipherSuite': 'DEFAULT', 'cpuType': 'Westmere', 'smp': '1', 'pauseCode': 'NOERR', 'migrationDest': 'libvirt', 'numaTune': {'nodeset': '1,0', 'mode': 'interleave'}, 'custom': {'device_e10694e6-667b-41ef-aba6-697fd45e7960device_de79bf09-c5e0-4f4e-9b6d-188ee7178793device_4ecc434d-6d65-4771-9638-c78339d6feb9': 'VmDevice {vmId=0fdea856-9aec-4300-8d88-4cfd330cf4ff, deviceId=4ecc434d-6d65-4771-9638-c78339d6feb9, 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}', 'device_e10694e6-667b-41ef-aba6-697fd45e7960device_de79bf09-c5e0-4f4e-9b6d-188ee7178793device_4ecc434d-6d65-4771-9638-c78339d6feb9device_5d4760e6-a49b-4a24-9daf-84fd119bcbd5': 'VmDevice {vmId=0fdea856-9aec-4300-8d88-4cfd330cf4ff, deviceId=5d4760e6-a49b-4a24-9daf-84fd119bcbd5, 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}', 'device_e10694e6-667b-41ef-aba6-697fd45e7960': 'VmDevice {vmId=0fdea856-9aec-4300-8d88-4cfd330cf4ff, deviceId=e10694e6-667b-41ef-aba6-697fd45e7960, 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}', 'device_e10694e6-667b-41ef-aba6-697fd45e7960device_de79bf09-c5e0-4f4e-9b6d-188ee7178793': 'VmDevice {vmId=0fdea856-9aec-4300-8d88-4cfd330cf4ff, deviceId=de79bf09-c5e0-4f4e-9b6d-188ee7178793, 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}'}, 'vmType': 'kvm', '_srcDomXML': "<domain type='kvm' id='13'>\n  <name>puppetdb</name>\n  <uuid>0fdea856-9aec-4300-8d88-4cfd330cf4ff</uuid>\n  <memory unit='KiB'>2097152</memory>\n  <currentMemory unit='KiB'>2097152</currentMemory>\n  <vcpu placement='static' current='1'>16</vcpu>\n  <cputune>\n    <shares>1020</shares>\n    <period>1000</period>\n    <quota>-1</quota>\n  </cputune>\n  <numatune>\n    <memory mode='interleave' nodeset='0-1'/>\n  </numatune>\n  <sysinfo type='smbios'>\n    <system>\n      <entry name='manufacturer'>oVirt</entry>\n      <entry name='product'>oVirt Node</entry>\n      <entry name='version'>6.6-1</entry>\n      <entry name='serial'>4C4C4544-0035-5310-8038-C7C04F39354A</entry>\n      <entry name='uuid'>0fdea856-9aec-4300-8d88-4cfd330cf4ff</entry>\n    </system>\n  </sysinfo>\n  <os>\n    <type arch='x86_64' machine='rhel6.5.0'>hvm</type>\n    <boot dev='hd'/>\n    <smbios mode='sysinfo'/>\n  </os>\n  <features>\n    <acpi/>\n  </features>\n  <cpu mode='custom' match='exact'>\n    <model fallback='allow'>Westmere</model>\n    <topology sockets='16' cores='1' threads='1'/>\n  </cpu>\n  <clock offset='variable' adjustment='0' basis='utc'>\n    <timer name='rtc' tickpolicy='catchup'/>\n    <timer name='pit' tickpolicy='delay'/>\n    <timer name='hpet' present='no'/>\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/libexec/qemu-kvm</emulator>\n    <disk type='file' device='cdrom'>\n      <driver name='qemu' type='raw'/>\n      <source startupPolicy='optional'/>\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='block' device='disk' snapshot='no'>\n      <driver name='qemu' type='raw' cache='none' error_policy='stop' io='native'/>\n      <source dev='/rhev/data-center/23a2d807-70ab-49ad-a1d2-3f16458c44ea/3dd1756b-97f5-465a-995b-b7dc91046f3b/images/0e710a40-017b-4547-9b47-49524777d0d4/85d91525-5fad-4d19-9aed-b4aa93af0d7f'/>\n      <target dev='vda' bus='virtio'/>\n      <serial>0e710a40-017b-4547-9b47-49524777d0d4</serial>\n      <alias name='virtio-disk0'/>\n      <address type='pci' domain='0x0000' bus='0x00' slot='0x06' 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='0x04' 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='0x05' 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='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:1a:4a:7c:94:87'/>\n      <source bridge='net17'/>\n      <bandwidth>\n      </bandwidth>\n      <target dev='vnet1'/>\n      <model type='virtio'/>\n      <filterref filter='vdsm-no-mac-spoofing'/>\n      <link state='up'/>\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/0fdea856-9aec-4300-8d88-4cfd330cf4ff.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/0fdea856-9aec-4300-8d88-4cfd330cf4ff.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    <graphics type='spice' tlsPort='5902' autoport='yes' keymap='en-us' passwdValidTo='1970-01-01T00:00:01'>\n      <listen type='network' address='192.168.111.101' 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    <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='virtio'>\n      <alias name='balloon0'/>\n      <address type='pci' domain='0x0000' bus='0x00' slot='0x07' function='0x0'/>\n    </memballoon>\n  </devices>\n  <seclabel type='dynamic' model='selinux' relabel='yes'>\n    <label>system_u:system_r:svirt_t:s0:c656,c983</label>\n    <imagelabel>system_u:object_r:svirt_image_t:s0:c656,c983</imagelabel>\n  </seclabel>\n</domain>\n", 'memSize': 2048, 'smpCoresPerSocket': '1', 'vmName': 'puppetdb', 'nice': '0', 'username': 'None', 'bootMenuEnable': 'false', 'copyPasteEnable': 'true', 'displayIp': '192.168.111.101', 'keyboardLayout': 'en-us', 'displayPort': '-1', 'smartcardEnable': 'false', 'clientIp': '', 'fileTransferEnable': 'true', 'nicModel': 'rtl8139,pv', 'elapsedTimeOffset': 5698.6938869953156, 'kvmEnable': 'true', 'pitReinjection': 'false', 'displayNetwork': 'ovirtmgmt', 'devices': [{'target': 2097152, 'specParams': {'model': 'virtio'}, 'alias': 'balloon0', 'deviceId': '8159e614-2ad3-41a1-961d-ba046a609942', 'address': {'slot': '0x07', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'memballoon', 'type': 'balloon'}, {'index': '0', 'alias': 'scsi0', 'specParams': {}, 'deviceId': '8013dd09-45a6-4c62-a529-7ec1e79e4961', 'address': {'slot': '0x04', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'scsi', 'model': 'virtio-scsi', 'type': 'controller'}, {'specParams': {}, 'alias': 'virtio-serial0', 'deviceId': '76fa2cee-8c48-4b83-a451-11297c3a934e', 'address': {'slot': '0x05', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'virtio-serial', 'type': 'controller'}, {'specParams': {'vram': '32768', 'ram': '65536', 'heads': '1'}, 'alias': 'video0', 'deviceId': '6dd2ec1b-27cf-4669-9f93-efbc99dcab4f', 'address': {'slot': '0x02', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'qxl', 'type': 'video'}, {'device': 'spice', 'specParams': {'displayNetwork': 'ovirtmgmt', 'spiceSecureChannels': 'smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard', 'keyMap': 'en-us', 'displayIp': '192.168.111.101', 'copyPasteEnable': 'true'}, 'type': 'graphics', 'tlsPort': '5902'}, {'nicModel': 'pv', 'macAddr': '00:1a:4a:7c:94:87', 'linkActive': True, 'network': 'net17', 'specParams': {'inbound': {}, 'outbound': {}}, 'filter': 'vdsm-no-mac-spoofing', 'alias': 'net0', 'deviceId': 'eab61bc6-ef45-4381-b58f-f4a1f074f765', 'address': {'slot': '0x03', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'bridge', 'type': 'interface', 'name': 'vnet1'}, {'index': '2', 'iface': 'ide', 'name': 'hdc', 'alias': 'ide0-1-0', 'shared': 'false', 'specParams': {'path': ''}, 'readonly': 'True', 'deviceId': '04c6c9bb-f6e7-48df-b447-c7c7f67d1ecf', 'address': {'bus': '1', 'controller': '0', 'type': 'drive', 'target': '0', 'unit': '0'}, 'device': 'cdrom', 'path': '', 'type': 'disk'}, {'address': {'slot': '0x06', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'reqsize': '0', 'index': 0, 'iface': 'virtio', 'apparentsize': '53687091200', 'specParams': {}, 'imageID': '0e710a40-017b-4547-9b47-49524777d0d4', 'readonly': 'False', 'shared': 'false', 'truesize': '53687091200', 'type': 'disk', 'domainID': '3dd1756b-97f5-465a-995b-b7dc91046f3b', 'volumeInfo': {'domainID': '3dd1756b-97f5-465a-995b-b7dc91046f3b', 'volType': 'path', 'leaseOffset': 111149056, 'volumeID': '85d91525-5fad-4d19-9aed-b4aa93af0d7f', 'leasePath': '/dev/3dd1756b-97f5-465a-995b-b7dc91046f3b/leases', 'imageID': '0e710a40-017b-4547-9b47-49524777d0d4', 'path': '/rhev/data-center/mnt/blockSD/3dd1756b-97f5-465a-995b-b7dc91046f3b/images/0e710a40-017b-4547-9b47-49524777d0d4/85d91525-5fad-4d19-9aed-b4aa93af0d7f'}, 'format': 'raw', 'deviceId': '0e710a40-017b-4547-9b47-49524777d0d4', 'poolID': '23a2d807-70ab-49ad-a1d2-3f16458c44ea', 'device': 'disk', 'path': '/rhev/data-center/23a2d807-70ab-49ad-a1d2-3f16458c44ea/3dd1756b-97f5-465a-995b-b7dc91046f3b/images/0e710a40-017b-4547-9b47-49524777d0d4/85d91525-5fad-4d19-9aed-b4aa93af0d7f', 'propagateErrors': 'off', 'optional': 'false', 'name': 'vda', 'volumeID': '85d91525-5fad-4d19-9aed-b4aa93af0d7f', 'alias': 'virtio-disk0', 'volumeChain': [{'domainID': '3dd1756b-97f5-465a-995b-b7dc91046f3b', 'volType': 'path', 'leaseOffset': 111149056, 'volumeID': '85d91525-5fad-4d19-9aed-b4aa93af0d7f', 'leasePath': '/dev/3dd1756b-97f5-465a-995b-b7dc91046f3b/leases', 'imageID': '0e710a40-017b-4547-9b47-49524777d0d4', 'path': '/rhev/data-center/mnt/blockSD/3dd1756b-97f5-465a-995b-b7dc91046f3b/images/0e710a40-017b-4547-9b47-49524777d0d4/85d91525-5fad-4d19-9aed-b4aa93af0d7f'}]}, {'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': '0', 'maxVCpus': '16', 'guestIPs': '193.55.176.34', 'display': 'qxl'},) {}
Thread-57::DEBUG::2014-11-13 17:36:26,669::API::522::vds::(migrationCreate) Migration create
Thread-57::INFO::2014-11-13 17:36:26,674::clientIF::363::vds::(createVm) vmContainerLock acquired by vm 0fdea856-9aec-4300-8d88-4cfd330cf4ff
Thread-57::DEBUG::2014-11-13 17:36:26,681::clientIF::376::vds::(createVm) Total desktops after creation of 0fdea856-9aec-4300-8d88-4cfd330cf4ff is 1
Thread-58::DEBUG::2014-11-13 17:36:26,681::vm::2294::vm.Vm::(_startUnderlyingVm) vmId=`0fdea856-9aec-4300-8d88-4cfd330cf4ff`::Start
Thread-57::DEBUG::2014-11-13 17:36:26,682::vm::5289::vm.Vm::(waitForMigrationDestinationPrepare) vmId=`0fdea856-9aec-4300-8d88-4cfd330cf4ff`::migration destination: waiting for VM creation
Thread-58::DEBUG::2014-11-13 17:36:26,684::vm::2298::vm.Vm::(_startUnderlyingVm) vmId=`0fdea856-9aec-4300-8d88-4cfd330cf4ff`::_ongoingCreations acquired
Thread-58::INFO::2014-11-13 17:36:26,684::vm::3179::vm.Vm::(_run) vmId=`0fdea856-9aec-4300-8d88-4cfd330cf4ff`::VM wrapper has started
Thread-57::DEBUG::2014-11-13 17:36:26,684::vm::5294::vm.Vm::(waitForMigrationDestinationPrepare) vmId=`0fdea856-9aec-4300-8d88-4cfd330cf4ff`::migration destination: waiting 36s for path preparation
Thread-58::WARNING::2014-11-13 17:36:26,686::vm::2114::vm.Vm::(buildConfDevices) vmId=`0fdea856-9aec-4300-8d88-4cfd330cf4ff`::Unknown type found, device: '{'device': 'spice', 'specParams': {'displayNetwork': 'ovirtmgmt', 'spiceSecureChannels': 'smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard', 'keyMap': 'en-us', 'displayIp': '192.168.111.101', 'copyPasteEnable': 'true'}, 'type': 'graphics', 'tlsPort': '5902'}' found
Thread-58::WARNING::2014-11-13 17:36:26,687::vm::2114::vm.Vm::(buildConfDevices) vmId=`0fdea856-9aec-4300-8d88-4cfd330cf4ff`::Unknown type found, device: '{'device': 'unix', 'alias': 'channel0', 'type': 'channel', 'address': {'bus': '0', 'controller': '0', 'type': 'virtio-serial', 'port': '1'}}' found
Thread-58::WARNING::2014-11-13 17:36:26,687::vm::2114::vm.Vm::(buildConfDevices) vmId=`0fdea856-9aec-4300-8d88-4cfd330cf4ff`::Unknown type found, device: '{'device': 'unix', 'alias': 'channel1', 'type': 'channel', 'address': {'bus': '0', 'controller': '0', 'type': 'virtio-serial', 'port': '2'}}' found
Thread-58::WARNING::2014-11-13 17:36:26,688::vm::2114::vm.Vm::(buildConfDevices) vmId=`0fdea856-9aec-4300-8d88-4cfd330cf4ff`::Unknown type found, device: '{'device': 'spicevmc', 'alias': 'channel2', 'type': 'channel', 'address': {'bus': '0', 'controller': '0', 'type': 'virtio-serial', 'port': '3'}}' found
Thread-58::DEBUG::2014-11-13 17:36:26,688::task::595::TaskManager.Task::(_updateState) Task=`da3103ea-23cc-41f2-9be5-1d72091f3ef5`::moving from state init -> state preparing
Thread-58::INFO::2014-11-13 17:36:26,688::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='3dd1756b-97f5-465a-995b-b7dc91046f3b', spUUID='23a2d807-70ab-49ad-a1d2-3f16458c44ea', imgUUID='0e710a40-017b-4547-9b47-49524777d0d4', volUUID='85d91525-5fad-4d19-9aed-b4aa93af0d7f', options=None)
Thread-58::DEBUG::2014-11-13 17:36:26,689::lvm::427::OperationMutex::(_reloadlvs) Operation 'lvm reload operation' got the operation mutex
Thread-58::DEBUG::2014-11-13 17:36:26,689::lvm::296::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm lvs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ \'a|/dev/mapper/mpathb|\', \'r|.*|\' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1  use_lvmetad=0 }  backup {  retain_min = 50  retain_days = 0 } " --noheadings --units b --nosuffix --separator | -o uuid,name,vg_name,attr,size,seg_start_pe,devices,tags 3dd1756b-97f5-465a-995b-b7dc91046f3b' (cwd None)
Thread-58::DEBUG::2014-11-13 17:36:26,891::lvm::296::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
Thread-58::DEBUG::2014-11-13 17:36:26,900::lvm::462::Storage.LVM::(_reloadlvs) lvs reloaded
Thread-58::DEBUG::2014-11-13 17:36:26,900::lvm::462::OperationMutex::(_reloadlvs) Operation 'lvm reload operation' released the operation mutex
Thread-58::INFO::2014-11-13 17:36:26,900::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '53687091200', 'apparentsize': '53687091200'}
Thread-58::DEBUG::2014-11-13 17:36:26,900::task::1185::TaskManager.Task::(prepare) Task=`da3103ea-23cc-41f2-9be5-1d72091f3ef5`::finished: {'truesize': '53687091200', 'apparentsize': '53687091200'}
Thread-58::DEBUG::2014-11-13 17:36:26,901::task::595::TaskManager.Task::(_updateState) Task=`da3103ea-23cc-41f2-9be5-1d72091f3ef5`::moving from state preparing -> state finished
Thread-58::DEBUG::2014-11-13 17:36:26,901::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-58::DEBUG::2014-11-13 17:36:26,901::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-58::DEBUG::2014-11-13 17:36:26,901::task::990::TaskManager.Task::(_decref) Task=`da3103ea-23cc-41f2-9be5-1d72091f3ef5`::ref 0 aborting False
Thread-58::INFO::2014-11-13 17:36:26,901::clientIF::321::vds::(prepareVolumePath) prepared volume path: 
Thread-58::DEBUG::2014-11-13 17:36:26,902::task::595::TaskManager.Task::(_updateState) Task=`b9f3fa37-1e62-494b-89f4-71321b34963e`::moving from state init -> state preparing
Thread-58::INFO::2014-11-13 17:36:26,902::logUtils::44::dispatcher::(wrapper) Run and protect: prepareImage(sdUUID='3dd1756b-97f5-465a-995b-b7dc91046f3b', spUUID='23a2d807-70ab-49ad-a1d2-3f16458c44ea', imgUUID='0e710a40-017b-4547-9b47-49524777d0d4', leafUUID='85d91525-5fad-4d19-9aed-b4aa93af0d7f')
Thread-58::DEBUG::2014-11-13 17:36:26,902::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.3dd1756b-97f5-465a-995b-b7dc91046f3b`ReqID=`600b4dbe-2226-4c5e-8717-225738cd69f8`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '3248' at 'prepareImage'
Thread-58::DEBUG::2014-11-13 17:36:26,903::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.3dd1756b-97f5-465a-995b-b7dc91046f3b' for lock type 'shared'
Thread-58::DEBUG::2014-11-13 17:36:26,903::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.3dd1756b-97f5-465a-995b-b7dc91046f3b' is free. Now locking as 'shared' (1 active user)
Thread-58::DEBUG::2014-11-13 17:36:26,903::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.3dd1756b-97f5-465a-995b-b7dc91046f3b`ReqID=`600b4dbe-2226-4c5e-8717-225738cd69f8`::Granted request
Thread-58::DEBUG::2014-11-13 17:36:26,903::task::827::TaskManager.Task::(resourceAcquired) Task=`b9f3fa37-1e62-494b-89f4-71321b34963e`::_resourcesAcquired: Storage.3dd1756b-97f5-465a-995b-b7dc91046f3b (shared)
Thread-58::DEBUG::2014-11-13 17:36:26,904::task::990::TaskManager.Task::(_decref) Task=`b9f3fa37-1e62-494b-89f4-71321b34963e`::ref 1 aborting False
Thread-58::DEBUG::2014-11-13 17:36:26,904::lvm::427::OperationMutex::(_reloadlvs) Operation 'lvm reload operation' got the operation mutex
Thread-58::DEBUG::2014-11-13 17:36:26,904::lvm::296::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm lvs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ \'a|/dev/mapper/mpathb|\', \'r|.*|\' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1  use_lvmetad=0 }  backup {  retain_min = 50  retain_days = 0 } " --noheadings --units b --nosuffix --separator | -o uuid,name,vg_name,attr,size,seg_start_pe,devices,tags 3dd1756b-97f5-465a-995b-b7dc91046f3b' (cwd None)
Thread-14::DEBUG::2014-11-13 17:36:26,964::blockSD::600::Storage.Misc.excCmd::(getReadDelay) '/bin/dd if=/dev/3dd1756b-97f5-465a-995b-b7dc91046f3b/metadata iflag=direct of=/dev/null bs=4096 count=1' (cwd None)
Thread-14::DEBUG::2014-11-13 17:36:26,972::blockSD::600::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000475681 s, 8.6 MB/s\n'; <rc> = 0
Thread-13::DEBUG::2014-11-13 17:36:27,013::BindingXMLRPC::1067::vds::(wrapper) client [192.168.111.100]::call vmGetStats with ('0fdea856-9aec-4300-8d88-4cfd330cf4ff',) {}
Thread-13::DEBUG::2014-11-13 17:36:27,013::BindingXMLRPC::1074::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Migration Destination', 'hash': '0', 'acpiEnable': 'true', 'pid': '0', 'displayIp': '192.168.111.102', 'displayPort': '-1', 'displaySecurePort': '-1', 'timeOffset': '0', 'pauseCode': 'NOERR', 'kvmEnable': 'true', 'network': {}, 'vmId': '0fdea856-9aec-4300-8d88-4cfd330cf4ff', 'displayType': 'qxl', 'disks': {}, 'monitorResponse': '0', 'elapsedTime': '5699', 'vmType': 'kvm', 'clientIp': ''}]}
Thread-58::DEBUG::2014-11-13 17:36:27,088::lvm::296::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
Thread-58::DEBUG::2014-11-13 17:36:27,097::lvm::462::Storage.LVM::(_reloadlvs) lvs reloaded
Thread-58::DEBUG::2014-11-13 17:36:27,097::lvm::462::OperationMutex::(_reloadlvs) Operation 'lvm reload operation' released the operation mutex
Thread-58::DEBUG::2014-11-13 17:36:27,098::lvm::296::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm lvchange --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ \'a|/dev/mapper/mpathb|\', \'r|.*|\' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1  use_lvmetad=0 }  backup {  retain_min = 50  retain_days = 0 } " --autobackup n --available y 3dd1756b-97f5-465a-995b-b7dc91046f3b/85d91525-5fad-4d19-9aed-b4aa93af0d7f' (cwd None)
Thread-58::DEBUG::2014-11-13 17:36:27,533::lvm::296::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
Thread-58::DEBUG::2014-11-13 17:36:27,533::lvm::513::OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-58::DEBUG::2014-11-13 17:36:27,533::lvm::525::OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-58::WARNING::2014-11-13 17:36:27,534::fileUtils::167::Storage.fileUtils::(createdir) Dir /var/run/vdsm/storage/3dd1756b-97f5-465a-995b-b7dc91046f3b/0e710a40-017b-4547-9b47-49524777d0d4 already exists
Thread-58::DEBUG::2014-11-13 17:36:27,534::blockSD::1086::Storage.StorageDomain::(createImageLinks) img run vol already exists: /var/run/vdsm/storage/3dd1756b-97f5-465a-995b-b7dc91046f3b/0e710a40-017b-4547-9b47-49524777d0d4/85d91525-5fad-4d19-9aed-b4aa93af0d7f
Thread-58::DEBUG::2014-11-13 17:36:27,534::blockSD::1058::Storage.StorageDomain::(linkBCImage) path to image directory already exists: /rhev/data-center/mnt/blockSD/3dd1756b-97f5-465a-995b-b7dc91046f3b/images/0e710a40-017b-4547-9b47-49524777d0d4
Thread-58::DEBUG::2014-11-13 17:36:27,535::lvm::427::OperationMutex::(_reloadlvs) Operation 'lvm reload operation' got the operation mutex
Thread-58::DEBUG::2014-11-13 17:36:27,536::lvm::296::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm lvs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ \'a|/dev/mapper/mpathb|\', \'r|.*|\' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1  use_lvmetad=0 }  backup {  retain_min = 50  retain_days = 0 } " --noheadings --units b --nosuffix --separator | -o uuid,name,vg_name,attr,size,seg_start_pe,devices,tags 3dd1756b-97f5-465a-995b-b7dc91046f3b' (cwd None)
Thread-58::DEBUG::2014-11-13 17:36:27,742::lvm::296::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
Thread-58::DEBUG::2014-11-13 17:36:27,751::lvm::462::Storage.LVM::(_reloadlvs) lvs reloaded
Thread-58::DEBUG::2014-11-13 17:36:27,751::lvm::462::OperationMutex::(_reloadlvs) Operation 'lvm reload operation' released the operation mutex
Thread-58::INFO::2014-11-13 17:36:27,752::logUtils::47::dispatcher::(wrapper) Run and protect: prepareImage, Return response: {'info': {'domainID': '3dd1756b-97f5-465a-995b-b7dc91046f3b', 'volType': 'path', 'leaseOffset': 111149056, 'path': '/rhev/data-center/mnt/blockSD/3dd1756b-97f5-465a-995b-b7dc91046f3b/images/0e710a40-017b-4547-9b47-49524777d0d4/85d91525-5fad-4d19-9aed-b4aa93af0d7f', 'volumeID': '85d91525-5fad-4d19-9aed-b4aa93af0d7f', 'leasePath': '/dev/3dd1756b-97f5-465a-995b-b7dc91046f3b/leases', 'imageID': '0e710a40-017b-4547-9b47-49524777d0d4'}, 'path': '/rhev/data-center/mnt/blockSD/3dd1756b-97f5-465a-995b-b7dc91046f3b/images/0e710a40-017b-4547-9b47-49524777d0d4/85d91525-5fad-4d19-9aed-b4aa93af0d7f', 'imgVolumesInfo': [{'domainID': '3dd1756b-97f5-465a-995b-b7dc91046f3b', 'volType': 'path', 'leaseOffset': 111149056, 'path': '/rhev/data-center/mnt/blockSD/3dd1756b-97f5-465a-995b-b7dc91046f3b/images/0e710a40-017b-4547-9b47-49524777d0d4/85d91525-5fad-4d19-9aed-b4aa93af0d7f', 'volumeID': '85d91525-5fad-4d19-9aed-b4aa93af0d7f', 'leasePath': '/dev/3dd1756b-97f5-465a-995b-b7dc91046f3b/leases', 'imageID': '0e710a40-017b-4547-9b47-49524777d0d4'}]}
Thread-58::DEBUG::2014-11-13 17:36:27,752::task::1185::TaskManager.Task::(prepare) Task=`b9f3fa37-1e62-494b-89f4-71321b34963e`::finished: {'info': {'domainID': '3dd1756b-97f5-465a-995b-b7dc91046f3b', 'volType': 'path', 'leaseOffset': 111149056, 'path': '/rhev/data-center/mnt/blockSD/3dd1756b-97f5-465a-995b-b7dc91046f3b/images/0e710a40-017b-4547-9b47-49524777d0d4/85d91525-5fad-4d19-9aed-b4aa93af0d7f', 'volumeID': '85d91525-5fad-4d19-9aed-b4aa93af0d7f', 'leasePath': '/dev/3dd1756b-97f5-465a-995b-b7dc91046f3b/leases', 'imageID': '0e710a40-017b-4547-9b47-49524777d0d4'}, 'path': '/rhev/data-center/mnt/blockSD/3dd1756b-97f5-465a-995b-b7dc91046f3b/images/0e710a40-017b-4547-9b47-49524777d0d4/85d91525-5fad-4d19-9aed-b4aa93af0d7f', 'imgVolumesInfo': [{'domainID': '3dd1756b-97f5-465a-995b-b7dc91046f3b', 'volType': 'path', 'leaseOffset': 111149056, 'path': '/rhev/data-center/mnt/blockSD/3dd1756b-97f5-465a-995b-b7dc91046f3b/images/0e710a40-017b-4547-9b47-49524777d0d4/85d91525-5fad-4d19-9aed-b4aa93af0d7f', 'volumeID': '85d91525-5fad-4d19-9aed-b4aa93af0d7f', 'leasePath': '/dev/3dd1756b-97f5-465a-995b-b7dc91046f3b/leases', 'imageID': '0e710a40-017b-4547-9b47-49524777d0d4'}]}
Thread-58::DEBUG::2014-11-13 17:36:27,752::task::595::TaskManager.Task::(_updateState) Task=`b9f3fa37-1e62-494b-89f4-71321b34963e`::moving from state preparing -> state finished
Thread-58::DEBUG::2014-11-13 17:36:27,753::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.3dd1756b-97f5-465a-995b-b7dc91046f3b': < ResourceRef 'Storage.3dd1756b-97f5-465a-995b-b7dc91046f3b', isValid: 'True' obj: 'None'>}
Thread-58::DEBUG::2014-11-13 17:36:27,753::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-58::DEBUG::2014-11-13 17:36:27,753::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.3dd1756b-97f5-465a-995b-b7dc91046f3b'
Thread-58::DEBUG::2014-11-13 17:36:27,753::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.3dd1756b-97f5-465a-995b-b7dc91046f3b' (0 active users)
Thread-58::DEBUG::2014-11-13 17:36:27,754::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.3dd1756b-97f5-465a-995b-b7dc91046f3b' is free, finding out if anyone is waiting for it.
Thread-58::DEBUG::2014-11-13 17:36:27,754::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.3dd1756b-97f5-465a-995b-b7dc91046f3b', Clearing records.
Thread-58::DEBUG::2014-11-13 17:36:27,754::task::990::TaskManager.Task::(_decref) Task=`b9f3fa37-1e62-494b-89f4-71321b34963e`::ref 0 aborting False
Thread-58::INFO::2014-11-13 17:36:27,754::clientIF::321::vds::(prepareVolumePath) prepared volume path: /rhev/data-center/mnt/blockSD/3dd1756b-97f5-465a-995b-b7dc91046f3b/images/0e710a40-017b-4547-9b47-49524777d0d4/85d91525-5fad-4d19-9aed-b4aa93af0d7f
Thread-58::DEBUG::2014-11-13 17:36:27,761::vm::2315::vm.Vm::(_startUnderlyingVm) vmId=`0fdea856-9aec-4300-8d88-4cfd330cf4ff`::_ongoingCreations released
Thread-58::DEBUG::2014-11-13 17:36:27,763::vm::3764::vm.Vm::(_waitForIncomingMigrationFinish) vmId=`0fdea856-9aec-4300-8d88-4cfd330cf4ff`::Waiting 21600 seconds for end of migration
Thread-57::ERROR::2014-11-13 17:36:27,762::vm::5269::vm.Vm::(_updateDevicesDomxmlCache) vmId=`0fdea856-9aec-4300-8d88-4cfd330cf4ff`::Alias not found for device type general during migration at destination host
Thread-57::DEBUG::2014-11-13 17:36:27,773::API::535::vds::(migrationCreate) Destination VM creation succeeded
Thread-57::DEBUG::2014-11-13 17:36:27,773::BindingXMLRPC::1074::vds::(wrapper) return vmMigrationCreate with {'status': {'message': 'Done', 'code': 0}, 'migrationPort': 0, 'params': {'username': 'None', 'acpiEnable': 'true', 'emulatedMachine': 'rhel6.5.0', 'afterMigrationStatus': '', 'pid': '0', 'memGuaranteedSize': 2048, 'transparentHugePages': 'true', 'displaySecurePort': '-1', 'spiceSslCipherSuite': 'DEFAULT', 'cpuType': 'Westmere', 'custom': {'device_e10694e6-667b-41ef-aba6-697fd45e7960device_de79bf09-c5e0-4f4e-9b6d-188ee7178793device_4ecc434d-6d65-4771-9638-c78339d6feb9': 'VmDevice {vmId=0fdea856-9aec-4300-8d88-4cfd330cf4ff, deviceId=4ecc434d-6d65-4771-9638-c78339d6feb9, 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}', 'device_e10694e6-667b-41ef-aba6-697fd45e7960device_de79bf09-c5e0-4f4e-9b6d-188ee7178793device_4ecc434d-6d65-4771-9638-c78339d6feb9device_5d4760e6-a49b-4a24-9daf-84fd119bcbd5': 'VmDevice {vmId=0fdea856-9aec-4300-8d88-4cfd330cf4ff, deviceId=5d4760e6-a49b-4a24-9daf-84fd119bcbd5, 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}', 'device_e10694e6-667b-41ef-aba6-697fd45e7960': 'VmDevice {vmId=0fdea856-9aec-4300-8d88-4cfd330cf4ff, deviceId=e10694e6-667b-41ef-aba6-697fd45e7960, 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}', 'device_e10694e6-667b-41ef-aba6-697fd45e7960device_de79bf09-c5e0-4f4e-9b6d-188ee7178793': 'VmDevice {vmId=0fdea856-9aec-4300-8d88-4cfd330cf4ff, deviceId=de79bf09-c5e0-4f4e-9b6d-188ee7178793, 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}'}, 'pauseCode': 'NOERR', 'migrationDest': 'libvirt', 'numaTune': {'nodeset': '1,0', 'mode': 'interleave'}, 'smp': '1', 'vmType': 'kvm', 'memSize': 2048, 'smpCoresPerSocket': '1', 'vmName': 'puppetdb', 'nice': '0', 'guestFQDN': 'puppetdb.example.com', 'bootMenuEnable': 'false', 'vmId': '0fdea856-9aec-4300-8d88-4cfd330cf4ff', 'copyPasteEnable': 'true', 'displayIp': '192.168.111.102', 'displayPort': '-1', 'guestIPs': '193.55.176.34', 'smartcardEnable': 'false', 'clientIp': '', 'fileTransferEnable': 'true', 'nicModel': 'rtl8139,pv', 'keyboardLayout': 'en-us', 'kvmEnable': 'true', 'pitReinjection': 'false', 'displayNetwork': 'ovirtmgmt', 'devices': [{'target': 2097152, 'specParams': {'model': 'virtio'}, 'alias': 'balloon0', 'deviceId': '8159e614-2ad3-41a1-961d-ba046a609942', 'address': {'slot': '0x07', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'memballoon', 'type': 'balloon'}, {'device': 'spice', 'specParams': {'displayNetwork': 'ovirtmgmt', 'spiceSecureChannels': 'smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard', 'keyMap': 'en-us', 'displayIp': '192.168.111.101', 'copyPasteEnable': 'true'}, 'type': 'graphics', 'tlsPort': '5902'}, {'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'}}, {'index': '0', 'alias': 'scsi0', 'specParams': {}, 'deviceId': '8013dd09-45a6-4c62-a529-7ec1e79e4961', 'address': {'slot': '0x04', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'scsi', 'model': 'virtio-scsi', 'type': 'controller'}, {'specParams': {}, 'alias': 'virtio-serial0', 'deviceId': '76fa2cee-8c48-4b83-a451-11297c3a934e', 'address': {'slot': '0x05', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'virtio-serial', 'type': 'controller'}, {'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'}}, {'specParams': {'vram': '32768', 'ram': '65536', 'heads': '1'}, 'alias': 'video0', 'deviceId': '6dd2ec1b-27cf-4669-9f93-efbc99dcab4f', 'address': {'slot': '0x02', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'qxl', 'type': 'video'}, {'nicModel': 'pv', 'macAddr': '00:1a:4a:7c:94:87', 'linkActive': True, 'network': 'net17', 'specParams': {'inbound': {}, 'outbound': {}}, 'filter': 'vdsm-no-mac-spoofing', 'alias': 'net0', 'deviceId': 'eab61bc6-ef45-4381-b58f-f4a1f074f765', 'address': {'slot': '0x03', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'bridge', 'type': 'interface', 'name': 'vnet1'}, {'index': '2', 'iface': 'ide', 'name': 'hdc', 'alias': 'ide0-1-0', 'shared': 'false', 'specParams': {'path': ''}, 'readonly': 'True', 'deviceId': '04c6c9bb-f6e7-48df-b447-c7c7f67d1ecf', 'address': {'bus': '1', 'controller': '0', 'type': 'drive', 'target': '0', 'unit': '0'}, 'device': 'cdrom', 'path': '', 'type': 'disk'}, {'address': {'slot': '0x06', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'reqsize': '0', 'index': 0, 'iface': 'virtio', 'apparentsize': '53687091200', 'specParams': {}, 'imageID': '0e710a40-017b-4547-9b47-49524777d0d4', 'readonly': 'False', 'shared': 'false', 'truesize': '53687091200', 'type': 'disk', 'domainID': '3dd1756b-97f5-465a-995b-b7dc91046f3b', 'volumeInfo': {'domainID': '3dd1756b-97f5-465a-995b-b7dc91046f3b', 'volType': 'path', 'leaseOffset': 111149056, 'path': '/rhev/data-center/mnt/blockSD/3dd1756b-97f5-465a-995b-b7dc91046f3b/images/0e710a40-017b-4547-9b47-49524777d0d4/85d91525-5fad-4d19-9aed-b4aa93af0d7f', 'volumeID': '85d91525-5fad-4d19-9aed-b4aa93af0d7f', 'leasePath': '/dev/3dd1756b-97f5-465a-995b-b7dc91046f3b/leases', 'imageID': '0e710a40-017b-4547-9b47-49524777d0d4'}, 'format': 'raw', 'deviceId': '0e710a40-017b-4547-9b47-49524777d0d4', 'poolID': '23a2d807-70ab-49ad-a1d2-3f16458c44ea', 'device': 'disk', 'path': '/rhev/data-center/mnt/blockSD/3dd1756b-97f5-465a-995b-b7dc91046f3b/images/0e710a40-017b-4547-9b47-49524777d0d4/85d91525-5fad-4d19-9aed-b4aa93af0d7f', 'propagateErrors': 'off', 'optional': 'false', 'name': 'vda', 'volumeID': '85d91525-5fad-4d19-9aed-b4aa93af0d7f', 'alias': 'virtio-disk0', 'volumeChain': [{'domainID': '3dd1756b-97f5-465a-995b-b7dc91046f3b', 'volType': 'path', 'leaseOffset': 111149056, 'path': '/rhev/data-center/mnt/blockSD/3dd1756b-97f5-465a-995b-b7dc91046f3b/images/0e710a40-017b-4547-9b47-49524777d0d4/85d91525-5fad-4d19-9aed-b4aa93af0d7f', 'volumeID': '85d91525-5fad-4d19-9aed-b4aa93af0d7f', 'leasePath': '/dev/3dd1756b-97f5-465a-995b-b7dc91046f3b/leases', 'imageID': '0e710a40-017b-4547-9b47-49524777d0d4'}]}], 'status': 'Migration Destination', 'timeOffset': '0', 'maxVCpus': '16', 'spiceSecureChannels': 'smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard', 'display': 'qxl'}}
Thread-60::DEBUG::2014-11-13 17:36:28,313::BindingXMLRPC::1067::vds::(wrapper) client [192.168.111.101]::call vmDestroy with ('0fdea856-9aec-4300-8d88-4cfd330cf4ff',) {}
Thread-60::INFO::2014-11-13 17:36:28,314::API::326::vds::(destroy) vmContainerLock acquired by vm 0fdea856-9aec-4300-8d88-4cfd330cf4ff
Thread-60::DEBUG::2014-11-13 17:36:28,314::vm::4717::vm.Vm::(destroy) vmId=`0fdea856-9aec-4300-8d88-4cfd330cf4ff`::destroy Called
Thread-60::INFO::2014-11-13 17:36:28,314::vm::4663::vm.Vm::(releaseVm) vmId=`0fdea856-9aec-4300-8d88-4cfd330cf4ff`::Release VM resources
Thread-60::DEBUG::2014-11-13 17:36:28,315::task::595::TaskManager.Task::(_updateState) Task=`751e106d-1c16-47a0-89a9-db396cec079b`::moving from state init -> state preparing
Thread-60::INFO::2014-11-13 17:36:28,315::logUtils::44::dispatcher::(wrapper) Run and protect: teardownImage(sdUUID='3dd1756b-97f5-465a-995b-b7dc91046f3b', spUUID='23a2d807-70ab-49ad-a1d2-3f16458c44ea', imgUUID='0e710a40-017b-4547-9b47-49524777d0d4', volUUID=None)
Thread-60::DEBUG::2014-11-13 17:36:28,316::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.3dd1756b-97f5-465a-995b-b7dc91046f3b`ReqID=`f362c7c5-6fa3-4ad0-914d-dc3c293c65f5`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '3296' at 'teardownImage'
Thread-60::DEBUG::2014-11-13 17:36:28,316::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.3dd1756b-97f5-465a-995b-b7dc91046f3b' for lock type 'shared'
Thread-58::DEBUG::2014-11-13 17:36:28,316::libvirtconnection::124::root::(wrapper) Unknown libvirterror: ecode: 42 edom: 10 level: 2 message: Domain not found: no domain with matching uuid '0fdea856-9aec-4300-8d88-4cfd330cf4ff'
Thread-60::DEBUG::2014-11-13 17:36:28,317::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.3dd1756b-97f5-465a-995b-b7dc91046f3b' is free. Now locking as 'shared' (1 active user)
Thread-60::DEBUG::2014-11-13 17:36:28,318::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.3dd1756b-97f5-465a-995b-b7dc91046f3b`ReqID=`f362c7c5-6fa3-4ad0-914d-dc3c293c65f5`::Granted request
Thread-60::DEBUG::2014-11-13 17:36:28,319::task::827::TaskManager.Task::(resourceAcquired) Task=`751e106d-1c16-47a0-89a9-db396cec079b`::_resourcesAcquired: Storage.3dd1756b-97f5-465a-995b-b7dc91046f3b (shared)
Thread-60::DEBUG::2014-11-13 17:36:28,319::task::990::TaskManager.Task::(_decref) Task=`751e106d-1c16-47a0-89a9-db396cec079b`::ref 1 aborting False
Thread-60::DEBUG::2014-11-13 17:36:28,320::lvm::427::OperationMutex::(_reloadlvs) Operation 'lvm reload operation' got the operation mutex
Thread-60::DEBUG::2014-11-13 17:36:28,320::lvm::296::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm lvs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ \'a|/dev/mapper/mpathb|\', \'r|.*|\' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1  use_lvmetad=0 }  backup {  retain_min = 50  retain_days = 0 } " --noheadings --units b --nosuffix --separator | -o uuid,name,vg_name,attr,size,seg_start_pe,devices,tags 3dd1756b-97f5-465a-995b-b7dc91046f3b' (cwd None)
Thread-58::ERROR::2014-11-13 17:36:28,318::vm::2341::vm.Vm::(_startUnderlyingVm) vmId=`0fdea856-9aec-4300-8d88-4cfd330cf4ff`::The vm start process failed
Traceback (most recent call last):
  File "/usr/share/vdsm/vm.py", line 2319, in _startUnderlyingVm
    self._waitForIncomingMigrationFinish()
  File "/usr/share/vdsm/vm.py", line 3771, in _waitForIncomingMigrationFinish
    self._connection.lookupByUUIDString(self.id),
  File "/usr/lib64/python2.6/site-packages/vdsm/libvirtconnection.py", line 92, in wrapper
    ret = f(*args, **kwargs)
  File "/usr/lib64/python2.6/site-packages/libvirt.py", line 2902, in lookupByUUIDString
    if ret is None:raise libvirtError('virDomainLookupByUUIDString() failed', conn=self)
libvirtError: Domain not found: no domain with matching uuid '0fdea856-9aec-4300-8d88-4cfd330cf4ff'
Thread-58::DEBUG::2014-11-13 17:36:28,329::vm::2783::vm.Vm::(setDownStatus) vmId=`0fdea856-9aec-4300-8d88-4cfd330cf4ff`::Changed state to Down: Domain not found: no domain with matching uuid '0fdea856-9aec-4300-8d88-4cfd330cf4ff'
Thread-60::DEBUG::2014-11-13 17:36:28,528::lvm::296::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
Thread-60::DEBUG::2014-11-13 17:36:28,537::lvm::462::Storage.LVM::(_reloadlvs) lvs reloaded
Thread-60::DEBUG::2014-11-13 17:36:28,537::lvm::462::OperationMutex::(_reloadlvs) Operation 'lvm reload operation' released the operation mutex
Thread-60::DEBUG::2014-11-13 17:36:28,538::lvm::296::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm lvchange --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ \'a|/dev/mapper/mpathb|\', \'r|.*|\' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1  use_lvmetad=0 }  backup {  retain_min = 50  retain_days = 0 } " --autobackup n --available n 3dd1756b-97f5-465a-995b-b7dc91046f3b/85d91525-5fad-4d19-9aed-b4aa93af0d7f' (cwd None)
Thread-60::DEBUG::2014-11-13 17:36:28,803::lvm::296::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
Thread-60::DEBUG::2014-11-13 17:36:28,803::lvm::513::OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-60::DEBUG::2014-11-13 17:36:28,804::lvm::525::OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-60::INFO::2014-11-13 17:36:28,804::logUtils::47::dispatcher::(wrapper) Run and protect: teardownImage, Return response: None
Thread-60::DEBUG::2014-11-13 17:36:28,804::task::1185::TaskManager.Task::(prepare) Task=`751e106d-1c16-47a0-89a9-db396cec079b`::finished: None
Thread-60::DEBUG::2014-11-13 17:36:28,804::task::595::TaskManager.Task::(_updateState) Task=`751e106d-1c16-47a0-89a9-db396cec079b`::moving from state preparing -> state finished
Thread-60::DEBUG::2014-11-13 17:36:28,805::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.3dd1756b-97f5-465a-995b-b7dc91046f3b': < ResourceRef 'Storage.3dd1756b-97f5-465a-995b-b7dc91046f3b', isValid: 'True' obj: 'None'>}
Thread-60::DEBUG::2014-11-13 17:36:28,805::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-60::DEBUG::2014-11-13 17:36:28,805::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.3dd1756b-97f5-465a-995b-b7dc91046f3b'
Thread-60::DEBUG::2014-11-13 17:36:28,805::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.3dd1756b-97f5-465a-995b-b7dc91046f3b' (0 active users)
Thread-60::DEBUG::2014-11-13 17:36:28,806::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.3dd1756b-97f5-465a-995b-b7dc91046f3b' is free, finding out if anyone is waiting for it.
Thread-60::DEBUG::2014-11-13 17:36:28,806::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.3dd1756b-97f5-465a-995b-b7dc91046f3b', Clearing records.
Thread-60::DEBUG::2014-11-13 17:36:28,806::task::990::TaskManager.Task::(_decref) Task=`751e106d-1c16-47a0-89a9-db396cec079b`::ref 0 aborting False
Thread-60::WARNING::2014-11-13 17:36:28,808::utils::129::root::(rmFile) File: /var/lib/libvirt/qemu/channels/0fdea856-9aec-4300-8d88-4cfd330cf4ff.com.redhat.rhevm.vdsm already removed
Thread-60::WARNING::2014-11-13 17:36:28,809::utils::129::root::(rmFile) File: /var/lib/libvirt/qemu/channels/0fdea856-9aec-4300-8d88-4cfd330cf4ff.org.qemu.guest_agent.0 already removed
Thread-60::DEBUG::2014-11-13 17:36:28,809::task::595::TaskManager.Task::(_updateState) Task=`d62f9da2-e26f-475f-ab9f-3f6c9291879c`::moving from state init -> state preparing
Thread-60::INFO::2014-11-13 17:36:28,809::logUtils::44::dispatcher::(wrapper) Run and protect: inappropriateDevices(thiefId='0fdea856-9aec-4300-8d88-4cfd330cf4ff')
Thread-60::INFO::2014-11-13 17:36:28,812::logUtils::47::dispatcher::(wrapper) Run and protect: inappropriateDevices, Return response: None
Thread-60::DEBUG::2014-11-13 17:36:28,812::task::1185::TaskManager.Task::(prepare) Task=`d62f9da2-e26f-475f-ab9f-3f6c9291879c`::finished: None
Thread-60::DEBUG::2014-11-13 17:36:28,812::task::595::TaskManager.Task::(_updateState) Task=`d62f9da2-e26f-475f-ab9f-3f6c9291879c`::moving from state preparing -> state finished
Thread-60::DEBUG::2014-11-13 17:36:28,812::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-60::DEBUG::2014-11-13 17:36:28,812::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-60::DEBUG::2014-11-13 17:36:28,813::task::990::TaskManager.Task::(_decref) Task=`d62f9da2-e26f-475f-ab9f-3f6c9291879c`::ref 0 aborting False
Thread-60::DEBUG::2014-11-13 17:36:28,813::vm::4711::vm.Vm::(deleteVm) vmId=`0fdea856-9aec-4300-8d88-4cfd330cf4ff`::Total desktops after destroy of 0fdea856-9aec-4300-8d88-4cfd330cf4ff is 0
Thread-60::DEBUG::2014-11-13 17:36:28,813::BindingXMLRPC::1074::vds::(wrapper) return vmDestroy with {'status': {'message': 'Machine destroyed', 'code': 0}}
Thread-15::DEBUG::2014-11-13 17:36:31,625::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/bin/dd if=/rhev/data-center/mnt/ovirt-engine.example.com:_var_lib_exports_iso/f11059d3-e676-489c-9730-39392debac74/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1' (cwd None)
Thread-15::DEBUG::2014-11-13 17:36:31,634::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n376 bytes (376 B) copied, 0.000451855 s, 832 kB/s\n'; <rc> = 0
Thread-13::DEBUG::2014-11-13 17:36:36,114::task::595::TaskManager.Task::(_updateState) Task=`d8d5eef4-7781-4aec-a927-e3084265dd6f`::moving from state init -> state preparing
Thread-13::INFO::2014-11-13 17:36:36,114::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-13::INFO::2014-11-13 17:36:36,114::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'3dd1756b-97f5-465a-995b-b7dc91046f3b': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000475681', 'lastCheck': '9.1', 'valid': True}, u'f11059d3-e676-489c-9730-39392debac74': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000451855', 'lastCheck': '4.5', 'valid': True}}
Thread-13::DEBUG::2014-11-13 17:36:36,114::task::1185::TaskManager.Task::(prepare) Task=`d8d5eef4-7781-4aec-a927-e3084265dd6f`::finished: {u'3dd1756b-97f5-465a-995b-b7dc91046f3b': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000475681', 'lastCheck': '9.1', 'valid': True}, u'f11059d3-e676-489c-9730-39392debac74': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000451855', 'lastCheck': '4.5', 'valid': True}}
Thread-13::DEBUG::2014-11-13 17:36:36,115::task::595::TaskManager.Task::(_updateState) Task=`d8d5eef4-7781-4aec-a927-e3084265dd6f`::moving from state preparing -> state finished
Thread-13::DEBUG::2014-11-13 17:36:36,115::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-13::DEBUG::2014-11-13 17:36:36,115::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-13::DEBUG::2014-11-13 17:36:36,115::task::990::TaskManager.Task::(_decref) Task=`d8d5eef4-7781-4aec-a927-e3084265dd6f`::ref 0 aborting False
Thread-14::DEBUG::2014-11-13 17:36:36,976::blockSD::600::Storage.Misc.excCmd::(getReadDelay) '/bin/dd if=/dev/3dd1756b-97f5-465a-995b-b7dc91046f3b/metadata iflag=direct of=/dev/null bs=4096 count=1' (cwd None)
Thread-14::DEBUG::2014-11-13 17:36:36,984::blockSD::600::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000729035 s, 5.6 MB/s\n'; <rc> = 0
Thread-15::DEBUG::2014-11-13 17:36:41,643::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/bin/dd if=/rhev/data-center/mnt/ovirt-engine.example.com:_var_lib_exports_iso/f11059d3-e676-489c-9730-39392debac74/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1' (cwd None)
Thread-15::DEBUG::2014-11-13 17:36:41,651::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n376 bytes (376 B) copied, 0.000512759 s, 733 kB/s\n'; <rc> = 0
Thread-14::DEBUG::2014-11-13 17:36:46,989::blockSD::600::Storage.Misc.excCmd::(getReadDelay) '/bin/dd if=/dev/3dd1756b-97f5-465a-995b-b7dc91046f3b/metadata iflag=direct of=/dev/null bs=4096 count=1' (cwd None)
Thread-14::DEBUG::2014-11-13 17:36:46,996::blockSD::600::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000607105 s, 6.7 MB/s\n'; <rc> = 0
Thread-13::DEBUG::2014-11-13 17:36:51,358::task::595::TaskManager.Task::(_updateState) Task=`c6bd6847-efde-4166-83aa-6e0652e7e452`::moving from state init -> state preparing
Thread-13::INFO::2014-11-13 17:36:51,359::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-13::INFO::2014-11-13 17:36:51,359::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'3dd1756b-97f5-465a-995b-b7dc91046f3b': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000607105', 'lastCheck': '4.4', 'valid': True}, u'f11059d3-e676-489c-9730-39392debac74': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000512759', 'lastCheck': '9.7', 'valid': True}}
Thread-13::DEBUG::2014-11-13 17:36:51,359::task::1185::TaskManager.Task::(prepare) Task=`c6bd6847-efde-4166-83aa-6e0652e7e452`::finished: {u'3dd1756b-97f5-465a-995b-b7dc91046f3b': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000607105', 'lastCheck': '4.4', 'valid': True}, u'f11059d3-e676-489c-9730-39392debac74': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000512759', 'lastCheck': '9.7', 'valid': True}}
Thread-13::DEBUG::2014-11-13 17:36:51,359::task::595::TaskManager.Task::(_updateState) Task=`c6bd6847-efde-4166-83aa-6e0652e7e452`::moving from state preparing -> state finished
Thread-13::DEBUG::2014-11-13 17:36:51,360::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-13::DEBUG::2014-11-13 17:36:51,360::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-13::DEBUG::2014-11-13 17:36:51,360::task::990::TaskManager.Task::(_decref) Task=`c6bd6847-efde-4166-83aa-6e0652e7e452`::ref 0 aborting False
Thread-15::DEBUG::2014-11-13 17:36:51,657::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/bin/dd if=/rhev/data-center/mnt/ovirt-engine.example.com:_var_lib_exports_iso/f11059d3-e676-489c-9730-39392debac74/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1' (cwd None)
Thread-15::DEBUG::2014-11-13 17:36:51,665::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n376 bytes (376 B) copied, 0.000486254 s, 773 kB/s\n'; <rc> = 0
Thread-14::DEBUG::2014-11-13 17:36:57,001::blockSD::600::Storage.Misc.excCmd::(getReadDelay) '/bin/dd if=/dev/3dd1756b-97f5-465a-995b-b7dc91046f3b/metadata iflag=direct of=/dev/null bs=4096 count=1' (cwd None)
Thread-14::DEBUG::2014-11-13 17:36:57,008::blockSD::600::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000507557 s, 8.1 MB/s\n'; <rc> = 0
Thread-15::DEBUG::2014-11-13 17:37:01,671::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/bin/dd if=/rhev/data-center/mnt/ovirt-engine.example.com:_var_lib_exports_iso/f11059d3-e676-489c-9730-39392debac74/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1' (cwd None)
Thread-15::DEBUG::2014-11-13 17:37:01,678::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n376 bytes (376 B) copied, 0.000551213 s, 682 kB/s\n'; <rc> = 0
Thread-13::DEBUG::2014-11-13 17:37:06,594::task::595::TaskManager.Task::(_updateState) Task=`756192fc-d3d5-4e96-bdb8-50c2a3f19acf`::moving from state init -> state preparing
Thread-13::INFO::2014-11-13 17:37:06,595::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-13::INFO::2014-11-13 17:37:06,595::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'3dd1756b-97f5-465a-995b-b7dc91046f3b': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000507557', 'lastCheck': '9.6', 'valid': True}, u'f11059d3-e676-489c-9730-39392debac74': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000551213', 'lastCheck': '4.9', 'valid': True}}