Re: [Users] ovirt 3.2 migrations failing

from source: [root@d0lppn032 vdsm]# egrep 'Thread-30209|Thread-30210' /var/log/vdsm/vdsm.log Thread-30209::DEBUG::2013-01-09 07:49:08,543::BindingXMLRPC::908::vds::(wrapper) client [10.32.0.21]::call vmMigrate with ({'src': 'd0lppn032.skopos.me', 'dst': 'd0lppn031.skopos.me:54321', 'vmId': 'e00adf83-78d2-4f65-a259-0e01680f57fd', 'method': 'online'},) {} flowID [343d5f4c] Thread-30209::DEBUG::2013-01-09 07:49:08,543::API::435::vds::(migrate) {'src': 'd0lppn032.skopos.me', 'dst': 'd0lppn031.skopos.me:54321', 'vmId': 'e00adf83-78d2-4f65-a259-0e01680f57fd', 'method': 'online'} Thread-30210::DEBUG::2013-01-09 07:49:08,544::vm::139::vm.Vm::(_setupVdsConnection) vmId=`e00adf83-78d2-4f65-a259-0e01680f57fd`::Destination server is: d0lppn031.skopos.me:54321 Thread-30210::DEBUG::2013-01-09 07:49:08,545::vm::141::vm.Vm::(_setupVdsConnection) vmId=`e00adf83-78d2-4f65-a259-0e01680f57fd`::Initiating connection with destination Thread-30209::DEBUG::2013-01-09 07:49:08,545::BindingXMLRPC::915::vds::(wrapper) return vmMigrate with {'status': {'message': 'Migration process starting', 'code': 0}} Thread-30210::DEBUG::2013-01-09 07:49:08,614::libvirtvm::298::vm.Vm::(_getDiskLatency) vmId=`e00adf83-78d2-4f65-a259-0e01680f57fd`::Disk vda latency not available Thread-30210::DEBUG::2013-01-09 07:49:08,659::vm::190::vm.Vm::(_prepareGuest) vmId=`e00adf83-78d2-4f65-a259-0e01680f57fd`::migration Process begins Thread-30210::DEBUG::2013-01-09 07:49:08,751::vm::261::vm.Vm::(run) vmId=`e00adf83-78d2-4f65-a259-0e01680f57fd`::migration semaphore acquired Thread-30210::DEBUG::2013-01-09 07:49:09,168::libvirtvm::469::vm.Vm::(_startUnderlyingMigration) vmId=`e00adf83-78d2-4f65-a259-0e01680f57fd`::starting migration to qemu+tls://d0lppn031.skopos.me/system Thread-30210::DEBUG::2013-01-09 07:49:09,230::libvirtvm::370::vm.Vm::(cancel) vmId=`e00adf83-78d2-4f65-a259-0e01680f57fd`::canceling migration downtime thread Thread-30210::DEBUG::2013-01-09 07:49:09,231::libvirtvm::429::vm.Vm::(stop) vmId=`e00adf83-78d2-4f65-a259-0e01680f57fd`::stopping migration monitor thread Thread-30210::ERROR::2013-01-09 07:49:09,232::vm::196::vm.Vm::(_recover) vmId=`e00adf83-78d2-4f65-a259-0e01680f57fd`::operation failed: Failed to connect to remote libvirt URI qemu+tls://d0lppn031.skopos.me/system Thread-30210::ERROR::2013-01-09 07:49:09,374::vm::284::vm.Vm::(run) vmId=`e00adf83-78d2-4f65-a259-0e01680f57fd`::Failed to migrate and from destination: [root@d0lppn031 vdsm]# egrep 'Thread-40128|Thread-40129' /var/log/vdsm/vdsm.log Thread-40128::DEBUG::2013-01-09 07:49:08,943::BindingXMLRPC::908::vds::(wrapper) client [10.32.0.32]::call vmMigrationCreate with ({'username': 'root', 'acpiEnable': 'true', 'emulatedMachine': 'pc', 'afterMigrationStatus': 'Up', 'vmId': 'e00adf83-78d2-4f65-a259-0e01680f57fd', 'transparentHugePages': 'true', 'displaySecurePort': '5901', 'timeOffset': 1, 'cpuType': 'SandyBridge', 'custom': {}, 'migrationDest': 'libvirt', 'smp': '4', 'vmType': 'kvm', 'spiceSslCipherSuite': 'DEFAULT', '_srcDomXML': "<domain type='kvm' id='2'>\n <name>d0lpvf051</name>\n <uuid>e00adf83-78d2-4f65-a259-0e01680f57fd</uuid>\n <memory unit='KiB'>4194304</memory>\n <currentMemory unit='KiB'>4194304</currentMemory>\n <vcpu placement='static'>4</vcpu>\n <cputune>\n <shares>1020</shares>\n </cputune>\n <sysinfo type='smbios'>\n <system>\n <entry name='manufacturer'>oVirt</entry>\n <entry name='product'>oVirt Node</entry>\n <entry name='version'>6-3.el6.centos.9</entry>\n <entry name='serial'>4C4C4544-004D-4E10-8036-B3C04F575731</entry>\n <entry name='uuid'>e00adf83-78d2-4f65-a259-0e01680f57fd</entry>\n </system>\n </sysinfo>\n <os>\n <type arch='x86_64' machine='rhel6.3.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'>SandyBridge</model>\n <topology sockets='4' cores='1' threads='1'/>\n </cpu>\n <clock offset='variable' adjustment='1'>\n <timer name='rtc' tickpolicy='catchup'/>\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='qcow2' cache='none' error_policy='stop' io='native'/>\n <source dev='/rhev/data-center/fdab6642-8928-43d5-8ca1-b68792d70729/d668d949-42f5-4 9a3-b33f-0b174ac226c5/images/0a9e06f9-2e85-4410-930d-7e381128c212/93410a32- 21d8-498c-b12a-efb43a2ef881'/>\n <target dev='vda' bus='virtio'/>\n <serial>0a9e06f9-2e85-4410-930d-7e381128c212</serial>\n <alias name='virtio-disk0'/>\n <address type='pci' domain='0x0000' bus='0x00' slot='0x06' function='0x0'/>\n </disk>\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 <controller type='virtio-serial' index='0'>\n <alias name='virtio-serial0'/>\n <address type='pci' domain='0x0000' bus='0x00' slot='0x05' function='0x0'/>\n </controller>\n <interface type='bridge'>\n <mac address='00:1a:4a:20:00:9e'/>\n <source bridge='ovirtmgmt'/>\n <target dev='vnet0'/>\n <model type='virtio'/>\n <filterref filter='vdsm-no-mac-spoofing'/>\n <alias name='net0'/>\n <address type='pci' domain='0x0000' bus='0x00' slot='0x03' function='0x0'/>\n </interface>\n <interface type='bridge'>\n <mac address='00:1a:4a:20:00:9f'/>\n <source bridge='ovirtmgmt'/>\n <target dev='vnet1'/>\n <model type='virtio'/>\n <filterref filter='vdsm-no-mac-spoofing'/>\n <alias name='net1'/>\n <address type='pci' domain='0x0000' bus='0x00' slot='0x04' function='0x0'/>\n </interface>\n <console type='pty' tty='/dev/pts/1'>\n <source path='/dev/pts/1'/>\n <target type='virtio' port='0'/>\n <alias name='console0'/>\n </console>\n <channel type='unix'>\n <source mode='bind' path='/var/lib/libvirt/qemu/channels/d0lpvf051.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/d0lpvf051.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' port='5900' tlsPort='5901' autoport='yes' listen='0' keymap='en-us' passwdValidTo='2013-01-09T00:22:14' connected='keep'>\n <listen type='address' address='0'/>\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' vram='65536' 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='none'/>\n</domain>\n", 'memSize': 4096, 'elapsedTimeOffset': 48875.878304004669, 'vmName': 'd0lpvf051', 'nice': '0', 'status': 'Up', 'clientIp': '', 'displayIp': '0', 'displayPort': '5900', 'smpCoresPerSocket': '1', 'smartcardEnable': 'false', 'guestIPs': '10.32.0.51', 'nicModel': 'rtl8139,pv', 'keyboardLayout': 'en-us', 'kvmEnable': 'true', 'pitReinjection': 'false', 'devices': [{'specParams': {'vram': '65536'}, 'alias': 'video0', 'deviceId': '99c46e79-710c-4f60-87eb-904fa496f0a7', 'address': {'slot': '0x02', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'qxl', 'type': 'video'}, {'nicModel': 'pv', 'macAddr': '00:1a:4a:20:00:9e', 'network': 'ovirtmgmt', 'alias': 'net0', 'filter': 'vdsm-no-mac-spoofing', 'specParams': {}, 'deviceId': '054f3e29-d531-438b-8d1c-09cbed863bea', 'address': {'slot': '0x03', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'bridge', 'type': 'interface', 'name': 'vnet0'}, {'nicModel': 'pv', 'macAddr': '00:1a:4a:20:00:9f', 'network': 'ovirtmgmt', 'alias': 'net1', 'filter': 'vdsm-no-mac-spoofing', 'specParams': {}, 'deviceId': '48ff9261-fbd8-4f0f-a823-4c6451226b95', 'address': {'slot': '0x04', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'bridge', 'type': 'interface', 'name': 'vnet1'}, {'target': 4194304, 'specParams': {'model': 'virtio'}, 'alias': 'balloon0', 'deviceId': 'df32c652-f9c6-42db-ae88-579ee90aa714', 'address': {'slot': '0x07', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'memballoon', 'type': 'balloon'}, {'index': '2', 'iface': 'ide', 'name': 'hdc', 'alias': 'ide0-1-0', 'shared': 'false', 'specParams': {'path': ''}, 'readonly': 'True', 'deviceId': '62d5042c-3b75-4cb3-b175-373f66c7356b', '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'}, 'index': 0, 'iface': 'virtio', 'apparentsize': '4294967296', 'alias': 'virtio-disk0', 'imageID': '0a9e06f9-2e85-4410-930d-7e381128c212', 'readonly': 'False', 'shared': 'false', 'truesize': '4294967296', 'type': 'disk', 'domainID': 'd668d949-42f5-49a3-b33f-0b174ac226c5', 'reqsize': '0', 'format': 'cow', 'deviceId': '0a9e06f9-2e85-4410-930d-7e381128c212', 'poolID': 'fdab6642-8928-43d5-8ca1-b68792d70729', 'device': 'disk', 'path': '/rhev/data-center/fdab6642-8928-43d5-8ca1-b68792d70729/d668d949-42f5-49a3- b33f-0b174ac226c5/images/0a9e06f9-2e85-4410-930d-7e381128c212/93410a32-21d8 -498c-b12a-efb43a2ef881', 'propagateErrors': 'off', 'optional': 'false', 'name': 'vda', 'volumeID': '93410a32-21d8-498c-b12a-efb43a2ef881', 'specParams': {}, 'volumeChain': [{'path': '/rhev/data-center/fdab6642-8928-43d5-8ca1-b68792d70729/d668d949-42f5-49a3- b33f-0b174ac226c5/images/0a9e06f9-2e85-4410-930d-7e381128c212/93410a32-21d8 -498c-b12a-efb43a2ef881', 'domainID': 'd668d949-42f5-49a3-b33f-0b174ac226c5', 'volumeID': '93410a32-21d8-498c-b12a-efb43a2ef881', 'imageID': '0a9e06f9-2e85-4410-930d-7e381128c212'}]}, {'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': 'virtio-serial', 'alias': 'virtio-serial0', 'type': 'controller', 'address': {'slot': '0x05', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}}, {'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'}}], 'spiceSecureChannels': 'smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard', 'display': 'qxl'},) {} Thread-40128::DEBUG::2013-01-09 07:49:08,943::API::470::vds::(migrationCreate) Migration create Thread-40128::INFO::2013-01-09 07:49:08,944::API::607::vds::(_getNetworkIp) network None: using 0 Thread-40128::INFO::2013-01-09 07:49:08,944::clientIF::334::vds::(createVm) vmContainerLock acquired by vm e00adf83-78d2-4f65-a259-0e01680f57fd Thread-40129::DEBUG::2013-01-09 07:49:08,952::vm::651::vm.Vm::(_startUnderlyingVm) vmId=`e00adf83-78d2-4f65-a259-0e01680f57fd`::Start Thread-40128::DEBUG::2013-01-09 07:49:08,953::clientIF::348::vds::(createVm) Total desktops after creation of e00adf83-78d2-4f65-a259-0e01680f57fd is 1 Thread-40128::DEBUG::2013-01-09 07:49:08,954::libvirtvm::2921::vm.Vm::(waitForMigrationDestinationPrepare) vmId=`e00adf83-78d2-4f65-a259-0e01680f57fd`::migration destination: waiting for VM creation Thread-40129::DEBUG::2013-01-09 07:49:08,954::vm::655::vm.Vm::(_startUnderlyingVm) vmId=`e00adf83-78d2-4f65-a259-0e01680f57fd`::_ongoingCreations acquired Thread-40129::INFO::2013-01-09 07:49:08,955::libvirtvm::1430::vm.Vm::(_run) vmId=`e00adf83-78d2-4f65-a259-0e01680f57fd`::VM wrapper has started Thread-40128::DEBUG::2013-01-09 07:49:08,955::libvirtvm::2927::vm.Vm::(waitForMigrationDestinationPrepare) vmId=`e00adf83-78d2-4f65-a259-0e01680f57fd`::migration destination: waiting 36s for path preparation Thread-40129::WARNING::2013-01-09 07:49:08,955::vm::455::vm.Vm::(getConfDevices) vmId=`e00adf83-78d2-4f65-a259-0e01680f57fd`::Unknown type found, device: '{'device': 'unix', 'alias': 'channel0', 'type': 'channel', 'address': {'bus': '0', 'controller': '0', 'type': 'virtio-serial', 'port': '1'}}' found Thread-40129::WARNING::2013-01-09 07:49:08,956::vm::455::vm.Vm::(getConfDevices) vmId=`e00adf83-78d2-4f65-a259-0e01680f57fd`::Unknown type found, device: '{'device': 'unix', 'alias': 'channel1', 'type': 'channel', 'address': {'bus': '0', 'controller': '0', 'type': 'virtio-serial', 'port': '2'}}' found Thread-40129::WARNING::2013-01-09 07:49:08,957::vm::455::vm.Vm::(getConfDevices) vmId=`e00adf83-78d2-4f65-a259-0e01680f57fd`::Unknown type found, device: '{'device': 'spicevmc', 'alias': 'channel2', 'type': 'channel', 'address': {'bus': '0', 'controller': '0', 'type': 'virtio-serial', 'port': '3'}}' found Thread-40129::DEBUG::2013-01-09 07:49:08,958::task::568::TaskManager.Task::(_updateState) Task=`fce2eb32-aa53-4742-962d-11a07cc9f06d`::moving from state init -> state preparing Thread-40129::INFO::2013-01-09 07:49:08,958::logUtils::41::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='d668d949-42f5-49a3-b33f-0b174ac226c5', spUUID='fdab6642-8928-43d5-8ca1-b68792d70729', imgUUID='0a9e06f9-2e85-4410-930d-7e381128c212', volUUID='93410a32-21d8-498c-b12a-efb43a2ef881', options=None) Thread-40129::INFO::2013-01-09 07:49:08,959::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '5368709120', 'apparentsize': '5368709120'} Thread-40129::DEBUG::2013-01-09 07:49:08,959::task::1151::TaskManager.Task::(prepare) Task=`fce2eb32-aa53-4742-962d-11a07cc9f06d`::finished: {'truesize': '5368709120', 'apparentsize': '5368709120'} Thread-40129::DEBUG::2013-01-09 07:49:08,959::task::568::TaskManager.Task::(_updateState) Task=`fce2eb32-aa53-4742-962d-11a07cc9f06d`::moving from state preparing -> state finished Thread-40129::DEBUG::2013-01-09 07:49:08,960::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-40129::DEBUG::2013-01-09 07:49:08,960::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-40129::DEBUG::2013-01-09 07:49:08,960::task::957::TaskManager.Task::(_decref) Task=`fce2eb32-aa53-4742-962d-11a07cc9f06d`::ref 0 aborting False Thread-40129::INFO::2013-01-09 07:49:08,961::clientIF::316::vds::(prepareVolumePath) prepared volume path: Thread-40129::DEBUG::2013-01-09 07:49:08,961::task::568::TaskManager.Task::(_updateState) Task=`d6ca414a-5a97-47a2-a2ec-ea3acd992aca`::moving from state init -> state preparing Thread-40129::INFO::2013-01-09 07:49:08,961::logUtils::41::dispatcher::(wrapper) Run and protect: prepareImage(sdUUID='d668d949-42f5-49a3-b33f-0b174ac226c5', spUUID='fdab6642-8928-43d5-8ca1-b68792d70729', imgUUID='0a9e06f9-2e85-4410-930d-7e381128c212', volUUID='93410a32-21d8-498c-b12a-efb43a2ef881') Thread-40129::DEBUG::2013-01-09 07:49:08,962::resourceManager::190::ResourceManager.Request::(__init__) ResName=`Storage.d668d949-42f5-49a3-b33f-0b174ac226c5`ReqID=`4261e498-e720- 42fd-8e48-ab390bd84a29`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '189' at '__init__' Thread-40129::DEBUG::2013-01-09 07:49:08,962::resourceManager::504::ResourceManager::(registerResource) Trying to register resource 'Storage.d668d949-42f5-49a3-b33f-0b174ac226c5' for lock type 'shared' Thread-40129::DEBUG::2013-01-09 07:49:08,963::resourceManager::547::ResourceManager::(registerResource) Resource 'Storage.d668d949-42f5-49a3-b33f-0b174ac226c5' is free. Now locking as 'shared' (1 active user) Thread-40129::DEBUG::2013-01-09 07:49:08,963::resourceManager::227::ResourceManager.Request::(grant) ResName=`Storage.d668d949-42f5-49a3-b33f-0b174ac226c5`ReqID=`4261e498-e720- 42fd-8e48-ab390bd84a29`::Granted request Thread-40129::DEBUG::2013-01-09 07:49:08,964::task::794::TaskManager.Task::(resourceAcquired) Task=`d6ca414a-5a97-47a2-a2ec-ea3acd992aca`::_resourcesAcquired: Storage.d668d949-42f5-49a3-b33f-0b174ac226c5 (shared) Thread-40129::DEBUG::2013-01-09 07:49:08,964::task::957::TaskManager.Task::(_decref) Task=`d6ca414a-5a97-47a2-a2ec-ea3acd992aca`::ref 1 aborting False Thread-40129::DEBUG::2013-01-09 07:49:08,965::lvm::409::OperationMutex::(_reloadlvs) Operation 'lvm reload operation' got the operation mutex Thread-40129::DEBUG::2013-01-09 07:49:08,965::misc::84::Storage.Misc.excCmd::(<lambda>) '/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 filter = [ \\"a%36090a028108c8e5dca0e950a0000e01a%\\", \\"r%.*%\\" ] } global { locking_type=1 prioritise_write_locks=1 wait_for_locks=1 } backup { retain_min = 50 retain_days = 0 } " --noheadings --units b --nosuffix --separator | -o uuid,name,vg_name,attr,size,seg_start_pe,devices,tags d668d949-42f5-49a3-b33f-0b174ac226c5' (cwd None) Thread-40129::DEBUG::2013-01-09 07:49:09,081::misc::84::Storage.Misc.excCmd::(<lambda>) SUCCESS: <err> = ''; <rc> = 0 Thread-40129::DEBUG::2013-01-09 07:49:09,094::lvm::442::OperationMutex::(_reloadlvs) Operation 'lvm reload operation' released the operation mutex Thread-40129::DEBUG::2013-01-09 07:49:09,106::misc::84::Storage.Misc.excCmd::(<lambda>) '/bin/dd iflag=direct skip=4 bs=512 if=/dev/d668d949-42f5-49a3-b33f-0b174ac226c5/metadata count=1' (cwd None) Thread-40129::DEBUG::2013-01-09 07:49:09,125::misc::84::Storage.Misc.excCmd::(<lambda>) SUCCESS: <err> = '1+0 records in\n1+0 records out\n512 bytes (512 B) copied, 0.00859049 s, 59.6 kB/s\n'; <rc> = 0 Thread-40129::DEBUG::2013-01-09 07:49:09,126::misc::325::Storage.Misc::(validateDDBytes) err: ['1+0 records in', '1+0 records out', '512 bytes (512 B) copied, 0.00859049 s, 59.6 kB/s'], size: 512 Thread-40129::INFO::2013-01-09 07:49:09,126::image::344::Storage.Image::(getChain) sdUUID=d668d949-42f5-49a3-b33f-0b174ac226c5 imgUUID=0a9e06f9-2e85-4410-930d-7e381128c212 chain=[<storage.blockVolume.BlockVolume object at 0x7f5760041490>] Thread-40129::INFO::2013-01-09 07:49:09,127::logUtils::44::dispatcher::(wrapper) Run and protect: prepareImage, Return response: {'path': '/rhev/data-center/fdab6642-8928-43d5-8ca1-b68792d70729/d668d949-42f5-49a3- b33f-0b174ac226c5/images/0a9e06f9-2e85-4410-930d-7e381128c212/93410a32-21d8 -498c-b12a-efb43a2ef881', 'chain': [{'path': '/rhev/data-center/fdab6642-8928-43d5-8ca1-b68792d70729/d668d949-42f5-49a3- b33f-0b174ac226c5/images/0a9e06f9-2e85-4410-930d-7e381128c212/93410a32-21d8 -498c-b12a-efb43a2ef881', 'domainID': 'd668d949-42f5-49a3-b33f-0b174ac226c5', 'volumeID': '93410a32-21d8-498c-b12a-efb43a2ef881', 'imageID': '0a9e06f9-2e85-4410-930d-7e381128c212'}]} Thread-40129::DEBUG::2013-01-09 07:49:09,128::task::1151::TaskManager.Task::(prepare) Task=`d6ca414a-5a97-47a2-a2ec-ea3acd992aca`::finished: {'path': '/rhev/data-center/fdab6642-8928-43d5-8ca1-b68792d70729/d668d949-42f5-49a3- b33f-0b174ac226c5/images/0a9e06f9-2e85-4410-930d-7e381128c212/93410a32-21d8 -498c-b12a-efb43a2ef881', 'chain': [{'path': '/rhev/data-center/fdab6642-8928-43d5-8ca1-b68792d70729/d668d949-42f5-49a3- b33f-0b174ac226c5/images/0a9e06f9-2e85-4410-930d-7e381128c212/93410a32-21d8 -498c-b12a-efb43a2ef881', 'domainID': 'd668d949-42f5-49a3-b33f-0b174ac226c5', 'volumeID': '93410a32-21d8-498c-b12a-efb43a2ef881', 'imageID': '0a9e06f9-2e85-4410-930d-7e381128c212'}]} Thread-40129::DEBUG::2013-01-09 07:49:09,128::task::568::TaskManager.Task::(_updateState) Task=`d6ca414a-5a97-47a2-a2ec-ea3acd992aca`::moving from state preparing -> state finished Thread-40129::DEBUG::2013-01-09 07:49:09,128::resourceManager::830::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.d668d949-42f5-49a3-b33f-0b174ac226c5': < ResourceRef 'Storage.d668d949-42f5-49a3-b33f-0b174ac226c5', isValid: 'True' obj: 'None'>} Thread-40129::DEBUG::2013-01-09 07:49:09,129::resourceManager::864::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-40129::DEBUG::2013-01-09 07:49:09,129::resourceManager::557::ResourceManager::(releaseResource) Trying to release resource 'Storage.d668d949-42f5-49a3-b33f-0b174ac226c5' Thread-40129::DEBUG::2013-01-09 07:49:09,130::resourceManager::573::ResourceManager::(releaseResource) Released resource 'Storage.d668d949-42f5-49a3-b33f-0b174ac226c5' (0 active users) Thread-40129::DEBUG::2013-01-09 07:49:09,130::resourceManager::578::ResourceManager::(releaseResource) Resource 'Storage.d668d949-42f5-49a3-b33f-0b174ac226c5' is free, finding out if anyone is waiting for it. Thread-40129::DEBUG::2013-01-09 07:49:09,131::resourceManager::585::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.d668d949-42f5-49a3-b33f-0b174ac226c5', Clearing records. Thread-40129::DEBUG::2013-01-09 07:49:09,131::task::957::TaskManager.Task::(_decref) Task=`d6ca414a-5a97-47a2-a2ec-ea3acd992aca`::ref 0 aborting False Thread-40129::INFO::2013-01-09 07:49:09,131::clientIF::316::vds::(prepareVolumePath) prepared volume path: /rhev/data-center/fdab6642-8928-43d5-8ca1-b68792d70729/d668d949-42f5-49a3-b 33f-0b174ac226c5/images/0a9e06f9-2e85-4410-930d-7e381128c212/93410a32-21d8- 498c-b12a-efb43a2ef881 Thread-40128::DEBUG::2013-01-09 07:49:09,145::API::483::vds::(migrationCreate) Destination VM creation succeeded Thread-40129::DEBUG::2013-01-09 07:49:09,144::vm::672::vm.Vm::(_startUnderlyingVm) vmId=`e00adf83-78d2-4f65-a259-0e01680f57fd`::_ongoingCreations released Thread-40128::DEBUG::2013-01-09 07:49:09,147::BindingXMLRPC::915::vds::(wrapper) return vmMigrationCreate with {'status': {'message': 'Done', 'code': 0}, 'migrationPort': 0, 'params': {'status': 'Migration Destination', 'acpiEnable': 'true', 'emulatedMachine': 'pc', 'afterMigrationStatus': 'Up', 'spiceSecureChannels': 'smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard', 'pid': '0', 'transparentHugePages': 'true', 'displaySecurePort': '-1', 'timeOffset': 1, 'cpuType': 'SandyBridge', 'smp': '4', 'migrationDest': 'libvirt', 'custom': {}, 'vmType': 'kvm', 'spiceSslCipherSuite': 'DEFAULT', 'memSize': 4096, 'vmName': 'd0lpvf051', 'nice': '0', 'username': 'root', 'vmId': 'e00adf83-78d2-4f65-a259-0e01680f57fd', 'displayIp': '0', 'keyboardLayout': 'en-us', 'displayPort': '-1', 'smartcardEnable': 'false', 'guestIPs': '10.32.0.51', 'nicModel': 'rtl8139,pv', 'smpCoresPerSocket': '1', 'kvmEnable': 'true', 'pitReinjection': 'false', 'devices': [{'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': 'virtio-serial', 'alias': 'virtio-serial0', 'type': 'controller', 'address': {'slot': '0x05', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}}, {'specParams': {'vram': '65536'}, 'alias': 'video0', 'deviceId': '99c46e79-710c-4f60-87eb-904fa496f0a7', 'address': {'slot': '0x02', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'qxl', 'type': 'video'}, {'nicModel': 'pv', 'macAddr': '00:1a:4a:20:00:9e', 'network': 'ovirtmgmt', 'alias': 'net0', 'filter': 'vdsm-no-mac-spoofing', 'specParams': {}, 'deviceId': '054f3e29-d531-438b-8d1c-09cbed863bea', 'address': {'slot': '0x03', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'bridge', 'type': 'interface', 'name': 'vnet0'}, {'nicModel': 'pv', 'macAddr': '00:1a:4a:20:00:9f', 'network': 'ovirtmgmt', 'alias': 'net1', 'filter': 'vdsm-no-mac-spoofing', 'specParams': {}, 'deviceId': '48ff9261-fbd8-4f0f-a823-4c6451226b95', 'address': {'slot': '0x04', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'bridge', 'type': 'interface', 'name': 'vnet1'}, {'target': 4194304, 'specParams': {'model': 'virtio'}, 'alias': 'balloon0', 'deviceId': 'df32c652-f9c6-42db-ae88-579ee90aa714', 'address': {'slot': '0x07', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'memballoon', 'type': 'balloon'}, {'index': '2', 'iface': 'ide', 'name': 'hdc', 'alias': 'ide0-1-0', 'shared': 'false', 'specParams': {'path': ''}, 'readonly': 'True', 'deviceId': '62d5042c-3b75-4cb3-b175-373f66c7356b', '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'}, 'index': 0, 'iface': 'virtio', 'apparentsize': '5368709120', 'alias': 'virtio-disk0', 'imageID': '0a9e06f9-2e85-4410-930d-7e381128c212', 'readonly': 'False', 'shared': 'false', 'truesize': '5368709120', 'type': 'disk', 'domainID': 'd668d949-42f5-49a3-b33f-0b174ac226c5', 'reqsize': '0', 'format': 'cow', 'deviceId': '0a9e06f9-2e85-4410-930d-7e381128c212', 'poolID': 'fdab6642-8928-43d5-8ca1-b68792d70729', 'device': 'disk', 'path': '/rhev/data-center/fdab6642-8928-43d5-8ca1-b68792d70729/d668d949-42f5-49a3- b33f-0b174ac226c5/images/0a9e06f9-2e85-4410-930d-7e381128c212/93410a32-21d8 -498c-b12a-efb43a2ef881', 'propagateErrors': 'off', 'optional': 'false', 'name': 'vda', 'volumeID': '93410a32-21d8-498c-b12a-efb43a2ef881', 'specParams': {}, 'volumeChain': [{'path': '/rhev/data-center/fdab6642-8928-43d5-8ca1-b68792d70729/d668d949-42f5-49a3- b33f-0b174ac226c5/images/0a9e06f9-2e85-4410-930d-7e381128c212/93410a32-21d8 -498c-b12a-efb43a2ef881', 'domainID': 'd668d949-42f5-49a3-b33f-0b174ac226c5', 'volumeID': '93410a32-21d8-498c-b12a-efb43a2ef881', 'imageID': '0a9e06f9-2e85-4410-930d-7e381128c212'}]}, {'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'}}], 'clientIp': '', 'display': 'qxl'}} Thread-40129::DEBUG::2013-01-09 07:49:09,148::libvirtvm::1751::vm.Vm::(_waitForIncomingMigrationFinish) vmId=`e00adf83-78d2-4f65-a259-0e01680f57fd`::Waiting 300 seconds for end of migration Thread-40129::ERROR::2013-01-09 07:49:09,310::vm::696::vm.Vm::(_startUnderlyingVm) vmId=`e00adf83-78d2-4f65-a259-0e01680f57fd`::The vm start process failed Thread-40129::DEBUG::2013-01-09 07:49:09,311::vm::1045::vm.Vm::(setDownStatus) vmId=`e00adf83-78d2-4f65-a259-0e01680f57fd`::Changed state to Down: Domain not found: no domain with matching uuid 'e00adf83-78d2-4f65-a259-0e01680f57fd' thank you for your help! jonathan On 1/9/13 1:18 AM, "Haim Ateya" <hateya(a)redhat.com&gt; wrote: ________________________________ This is a PRIVATE message. If you are not the intended recipient, please delete without copying and kindly advise us by e-mail of the mistake in delivery. NOTE: Regardless of content, this e-mail shall not operate to bind SKOPOS to any order or other contract unless pursuant to explicit written agreement or government initiative expressly permitting the use of e-mail for such purpose.