Hello,
I've just reinstall a host (ovirt-node2) and now I am unable to
create/migrate vm on this host.
In attachment, the log from the destination server (ovirt-node2).
Any help will be appreciated.
James
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}}
_______________________________________________
Users mailing list
Users@ovirt.org
http://lists.ovirt.org/mailman/listinfo/users
