Attachment 902418 Details for Bug 1104697 – vdsm

vdsm

vdsm.log.mst (text/plain), 76.50 KB, created by Markus Stockhausen on 2014-06-05 07:28:24 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: Markus Stockhausen

Created: 2014-06-05 07:28:24 UTC

Size: 76.50 KB

patch

obsolete

>Thread-20::DEBUG::2014-06-05 09:24:58,050::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-20::DEBUG::2014-06-05 09:24:58,058::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n557 bytes (557 B) copied, 0.000261295 s, 2.1 MB/s\n'; <rc> = 0
>Thread-19::DEBUG::2014-06-05 09:25:00,790::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtIB/2c51d320-88ce-4f23-8215-e15f55f66906/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-19::DEBUG::2014-06-05 09:25:00,798::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n644 bytes (644 B) copied, 0.000217707 s, 3.0 MB/s\n'; <rc> = 0
>Thread-27::DEBUG::2014-06-05 09:25:00,950::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtEXP/63041fa9-e093-4b44-b36f-f39f16d3974f/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-27::DEBUG::2014-06-05 09:25:00,961::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n363 bytes (363 B) copied, 0.000227196 s, 1.6 MB/s\n'; <rc> = 0
>Thread-32::DEBUG::2014-06-05 09:25:00,978::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-32::DEBUG::2014-06-05 09:25:00,985::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n557 bytes (557 B) copied, 0.000245901 s, 2.3 MB/s\n'; <rc> = 0
>Thread-21::DEBUG::2014-06-05 09:25:02,495::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtISO/bff3a2be-fdd9-4e37-b416-fa4ef7fafba2/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-21::DEBUG::2014-06-05 09:25:02,503::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n357 bytes (357 B) copied, 0.000267849 s, 1.3 MB/s\n'; <rc> = 0
>Thread-20::DEBUG::2014-06-05 09:25:08,068::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-20::DEBUG::2014-06-05 09:25:08,075::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n557 bytes (557 B) copied, 0.000309093 s, 1.8 MB/s\n'; <rc> = 0
>Thread-63529::DEBUG::2014-06-05 09:25:09,296::task::595::TaskManager.Task::(_updateState) Task=`c3673cde-b97c-4e4f-8179-0f7d730c31a5`::moving from state init -> state preparing
>Thread-63529::INFO::2014-06-05 09:25:09,297::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-63529::INFO::2014-06-05 09:25:09,297::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'2c51d320-88ce-4f23-8215-e15f55f66906': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000217707', 'lastCheck': '8.5', 'valid': True}, '965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000309093', 'lastCheck': '1.2', 'valid': True}, 'bff3a2be-fdd9-4e37-b416-fa4ef7fafba2': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000267849', 'lastCheck': '6.8', 'valid': True}, '63041fa9-e093-4b44-b36f-f39f16d3974f': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000227196', 'lastCheck': '8.3', 'valid': True}, '272ec473-6041-42ee-bd1a-732789dd18d4': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000245901', 'lastCheck': '8.3', 'valid': True}}
>Thread-63529::DEBUG::2014-06-05 09:25:09,297::task::1185::TaskManager.Task::(prepare) Task=`c3673cde-b97c-4e4f-8179-0f7d730c31a5`::finished: {'2c51d320-88ce-4f23-8215-e15f55f66906': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000217707', 'lastCheck': '8.5', 'valid': True}, '965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000309093', 'lastCheck': '1.2', 'valid': True}, 'bff3a2be-fdd9-4e37-b416-fa4ef7fafba2': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000267849', 'lastCheck': '6.8', 'valid': True}, '63041fa9-e093-4b44-b36f-f39f16d3974f': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000227196', 'lastCheck': '8.3', 'valid': True}, '272ec473-6041-42ee-bd1a-732789dd18d4': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000245901', 'lastCheck': '8.3', 'valid': True}}
>Thread-63529::DEBUG::2014-06-05 09:25:09,298::task::595::TaskManager.Task::(_updateState) Task=`c3673cde-b97c-4e4f-8179-0f7d730c31a5`::moving from state preparing -> state finished
>Thread-63529::DEBUG::2014-06-05 09:25:09,298::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-63529::DEBUG::2014-06-05 09:25:09,298::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-63529::DEBUG::2014-06-05 09:25:09,298::task::990::TaskManager.Task::(_decref) Task=`c3673cde-b97c-4e4f-8179-0f7d730c31a5`::ref 0 aborting False
>Thread-19::DEBUG::2014-06-05 09:25:10,811::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtIB/2c51d320-88ce-4f23-8215-e15f55f66906/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-19::DEBUG::2014-06-05 09:25:10,818::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n644 bytes (644 B) copied, 0.000339728 s, 1.9 MB/s\n'; <rc> = 0
>Thread-27::DEBUG::2014-06-05 09:25:10,979::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtEXP/63041fa9-e093-4b44-b36f-f39f16d3974f/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-27::DEBUG::2014-06-05 09:25:10,986::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n363 bytes (363 B) copied, 0.000137045 s, 2.6 MB/s\n'; <rc> = 0
>Thread-32::DEBUG::2014-06-05 09:25:10,999::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-32::DEBUG::2014-06-05 09:25:11,006::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n557 bytes (557 B) copied, 0.000194248 s, 2.9 MB/s\n'; <rc> = 0
>Thread-21::DEBUG::2014-06-05 09:25:12,515::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtISO/bff3a2be-fdd9-4e37-b416-fa4ef7fafba2/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-21::DEBUG::2014-06-05 09:25:12,522::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n357 bytes (357 B) copied, 0.000301082 s, 1.2 MB/s\n'; <rc> = 0
>Thread-69045::DEBUG::2014-06-05 09:25:13,834::BindingXMLRPC::1067::vds::(wrapper) client [192.168.11.43]::call vmGetStats with ('803870d2-e365-4ab4-bdcc-4c1d25a03944',) {}
>Thread-69045::DEBUG::2014-06-05 09:25:13,835::BindingXMLRPC::1074::vds::(wrapper) return vmGetStats with {'status': {'message': 'Virtual machine does not exist', 'code': 1}}
>Thread-69046::DEBUG::2014-06-05 09:25:13,890::BindingXMLRPC::1067::vds::(wrapper) client [192.168.11.43]::call vmMigrationCreate with ({'username': 'Unknown', 'acpiEnable': 'true', 'emulatedMachine': 'pc-1.0', 'afterMigrationStatus': '', 'guestFQDN': '', 'vmId': '803870d2-e365-4ab4-bdcc-4c1d25a03944', 'memGuaranteedSize': 2048, 'transparentHugePages': 'true', 'displaySecurePort': '5901', 'timeOffset': '14279', 'cpuType': 'Nehalem', 'smp': '2', 'migrationDest': 'libvirt', 'custom': {'device_966ade53-ddf1-4699-8061-59f976025a58device_1486a6a3-5a78-4214-a876-44cb899ad8abdevice_d59d8a87-96f1-444a-9c16-91aa8c07aa5ddevice_e254253c-092c-44f9-badc-4feb40a769dcdevice_f85b2abb-2ad2-431b-bf0a-d7ba4e7d763b': 'VmDevice {vmId=803870d2-e365-4ab4-bdcc-4c1d25a03944, deviceId=f85b2abb-2ad2-431b-bf0a-d7ba4e7d763b, device=virtio-serial, type=CONTROLLER, bootOrder=0, specParams={}, address={bus=0x00, domain=0x0000, type=pci, slot=0x05, function=0x0}, managed=false, plugged=true, readOnly=false, deviceAlias=virtio-serial0, customProperties={}, snapshotId=null}', 'device_966ade53-ddf1-4699-8061-59f976025a58device_1486a6a3-5a78-4214-a876-44cb899ad8abdevice_d59d8a87-96f1-444a-9c16-91aa8c07aa5d': 'VmDevice {vmId=803870d2-e365-4ab4-bdcc-4c1d25a03944, deviceId=d59d8a87-96f1-444a-9c16-91aa8c07aa5d, 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_966ade53-ddf1-4699-8061-59f976025a58device_1486a6a3-5a78-4214-a876-44cb899ad8abdevice_d59d8a87-96f1-444a-9c16-91aa8c07aa5ddevice_e254253c-092c-44f9-badc-4feb40a769dc': 'VmDevice {vmId=803870d2-e365-4ab4-bdcc-4c1d25a03944, deviceId=e254253c-092c-44f9-badc-4feb40a769dc, 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_966ade53-ddf1-4699-8061-59f976025a58': 'VmDevice {vmId=803870d2-e365-4ab4-bdcc-4c1d25a03944, deviceId=966ade53-ddf1-4699-8061-59f976025a58, 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}', 'device_966ade53-ddf1-4699-8061-59f976025a58device_1486a6a3-5a78-4214-a876-44cb899ad8ab': 'VmDevice {vmId=803870d2-e365-4ab4-bdcc-4c1d25a03944, deviceId=1486a6a3-5a78-4214-a876-44cb899ad8ab, 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}'}, 'vmType': 'kvm', 'spiceSslCipherSuite': 'DEFAULT', '_srcDomXML': "<domain type='kvm' id='33' xmlns:qemu='http://libvirt.org/schemas/domain/qemu/1.0'>\n  <name>colvm36</name>\n  <uuid>803870d2-e365-4ab4-bdcc-4c1d25a03944</uuid>\n  <memory unit='KiB'>3145728</memory>\n  <currentMemory unit='KiB'>3145728</currentMemory>\n  <memtune>\n    <min_guarantee unit='KiB'>2097152</min_guarantee>\n  </memtune>\n  <vcpu placement='static' current='2'>160</vcpu>\n  <cputune>\n    <shares>1020</shares>\n  </cputune>\n  <resource>\n    <partition>/machine</partition>\n  </resource>\n  <sysinfo type='smbios'>\n    <system>\n      <entry name='manufacturer'>oVirt</entry>\n      <entry name='product'>oVirt Node</entry>\n      <entry name='version'>20-3</entry>\n      <entry name='serial'>49434D53-0200-48D6-3000-D64830004AC9</entry>\n      <entry name='uuid'>803870d2-e365-4ab4-bdcc-4c1d25a03944</entry>\n    </system>\n  </sysinfo>\n  <os>\n    <type arch='x86_64' machine='pc-1.0'>hvm</type>\n    <smbios mode='sysinfo'/>\n  </os>\n  <features>\n    <acpi/>\n  </features>\n  <cpu mode='custom' match='exact'>\n    <model fallback='allow'>Nehalem</model>\n    <topology sockets='80' cores='2' threads='1'/>\n  </cpu>\n  <clock offset='variable' adjustment='7079' basis='utc'>\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/bin/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='file' device='disk' snapshot='no'>\n      <driver name='qemu' type='raw' cache='none' error_policy='stop' io='threads'/>\n      <source file='/rhev/data-center/mnt/10.10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/images/12843faf-ebbc-4732-b4e9-0bb2501c194f/04b45378-e7b8-4488-b48a-6b3fac1f18a4'>\n        <seclabel model='selinux' relabel='yes'/>\n      </source>\n      <target dev='vda' bus='virtio'/>\n      <serial>12843faf-ebbc-4732-b4e9-0bb2501c194f</serial>\n      <boot order='1'/>\n      <alias name='virtio-disk0'/>\n      <address type='pci' domain='0x0000' bus='0x00' slot='0x06' function='0x0'/>\n    </disk>\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    <controller type='usb' index='0'>\n      <alias name='usb0'/>\n      <address type='pci' domain='0x0000' bus='0x00' slot='0x01' function='0x2'/>\n    </controller>\n    <controller type='pci' index='0' model='pci-root'>\n      <alias name='pci.0'/>\n    </controller>\n    <interface type='bridge'>\n      <mac address='00:0c:29:05:09:1e'/>\n      <source bridge='ovirtmgmt'/>\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/803870d2-e365-4ab4-bdcc-4c1d25a03944.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/803870d2-e365-4ab4-bdcc-4c1d25a03944.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='5901' autoport='yes' keymap='en-us' passwdValidTo='2014-06-04T18:59:11' connected='keep'>\n      <listen type='network' address='192.168.11.43' network='vdsm-ovirtmgmt'/>\n      <channel name='main' mode='secure'/>\n      <channel name='display' mode='secure'/>\n      <channel name='inputs' mode='secure'/>\n      <channel name='cursor' mode='secure'/>\n      <channel name='playback' mode='secure'/>\n      <channel name='record' mode='secure'/>\n      <channel name='smartcard' mode='secure'/>\n      <channel name='usbredir' mode='secure'/>\n    </graphics>\n    <sound model='ac97'>\n      <alias name='sound0'/>\n      <address type='pci' domain='0x0000' bus='0x00' slot='0x04' function='0x0'/>\n    </sound>\n    <video>\n      <model type='qxl' ram='65536' vram='32768' heads='1'/>\n      <alias name='video0'/>\n      <address type='pci' domain='0x0000' bus='0x00' slot='0x02' function='0x0'/>\n    </video>\n    <memballoon model='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:c810,c980</label>\n    <imagelabel>system_u:object_r:svirt_image_t:s0:c810,c980</imagelabel>\n  </seclabel>\n  <qemu:commandline>\n    <qemu:env name='SPICE_DEBUG_ALLOW_MC' value='1'/>\n    <qemu:env name='SPICE_DEBUG_LEVEL' value='4'/>\n  </qemu:commandline>\n</domain>\n", 'memSize': 3072, 'elapsedTimeOffset': 63914.31065106392, 'vmName': 'colvm36', 'nice': '0', 'status': 'Up', 'clientIp': '', 'displayIp': '192.168.11.43', 'displayPort': '-1', 'smpCoresPerSocket': '2', 'smartcardEnable': 'false', 'spiceSecureChannels': 'smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard', 'nicModel': 'rtl8139,pv', 'keyboardLayout': 'en-us', 'kvmEnable': 'true', 'displayNetwork': 'ovirtmgmt', 'devices': [{'specParams': {}, 'alias': 'sound0', 'deviceId': '70e43d5b-6119-4204-a138-ef9a30dcb920', 'address': {'slot': '0x04', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'ac97', 'type': 'sound'}, {'target': 3145728, 'specParams': {'model': 'virtio'}, 'alias': 'balloon0', 'deviceId': '08fb1420-af65-452e-ab83-847a96a5090d', 'address': {'slot': '0x07', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'memballoon', 'type': 'balloon'}, {'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'}}, {'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': '32768', 'heads': '1'}, 'alias': 'video0', 'deviceId': '5ee02b8e-5916-4fce-89aa-ed26b2f939b5', 'address': {'slot': '0x02', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'qxl', 'type': 'video'}, {'nicModel': 'pv', 'macAddr': '00:0c:29:05:09:1e', 'linkActive': True, 'network': 'ovirtmgmt', 'specParams': {}, 'filter': 'vdsm-no-mac-spoofing', 'alias': 'net0', 'deviceId': '27b080c4-a9d0-479a-b0fe-de197c80af60', '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', 'specParams': {'path': ''}, 'readonly': 'True', 'deviceId': '6c0d02e8-d3ef-4b64-a5ab-74ebfbe9ea5e', 'address': {'bus': '1', 'controller': '0', 'type': 'drive', 'target': '0', 'unit': '0'}, 'device': 'cdrom', 'shared': 'false', 'path': '', 'type': 'disk'}, {'address': {'slot': '0x06', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'reqsize': '0', 'index': 0, 'iface': 'virtio', 'apparentsize': '26863764480', 'specParams': {}, 'imageID': '12843faf-ebbc-4732-b4e9-0bb2501c194f', 'readonly': 'False', 'shared': 'false', 'truesize': '27380420608', 'type': 'disk', 'domainID': '272ec473-6041-42ee-bd1a-732789dd18d4', 'volumeInfo': {'domainID': '272ec473-6041-42ee-bd1a-732789dd18d4', 'volType': 'path', 'leaseOffset': 0, 'volumeID': '04b45378-e7b8-4488-b48a-6b3fac1f18a4', 'leasePath': '/rhev/data-center/mnt/10.10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/images/12843faf-ebbc-4732-b4e9-0bb2501c194f/04b45378-e7b8-4488-b48a-6b3fac1f18a4.lease', 'imageID': '12843faf-ebbc-4732-b4e9-0bb2501c194f', 'path': '/rhev/data-center/mnt/10.10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/images/12843faf-ebbc-4732-b4e9-0bb2501c194f/04b45378-e7b8-4488-b48a-6b3fac1f18a4'}, 'format': 'raw', 'deviceId': '12843faf-ebbc-4732-b4e9-0bb2501c194f', 'poolID': '94ed7a19-fade-4bd6-83f2-2cbb2f730b95', 'device': 'disk', 'path': '/rhev/data-center/mnt/10.10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/images/12843faf-ebbc-4732-b4e9-0bb2501c194f/04b45378-e7b8-4488-b48a-6b3fac1f18a4', 'propagateErrors': 'off', 'optional': 'false', 'name': 'vda', 'bootOrder': '1', 'volumeID': '04b45378-e7b8-4488-b48a-6b3fac1f18a4', 'alias': 'virtio-disk0', 'volumeChain': [{'domainID': '272ec473-6041-42ee-bd1a-732789dd18d4', 'volType': 'path', 'leaseOffset': 0, 'volumeID': '04b45378-e7b8-4488-b48a-6b3fac1f18a4', 'leasePath': '/rhev/data-center/mnt/10.10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/images/12843faf-ebbc-4732-b4e9-0bb2501c194f/04b45378-e7b8-4488-b48a-6b3fac1f18a4.lease', 'imageID': '12843faf-ebbc-4732-b4e9-0bb2501c194f', 'path': '/rhev/data-center/mnt/10.10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/images/12843faf-ebbc-4732-b4e9-0bb2501c194f/04b45378-e7b8-4488-b48a-6b3fac1f18a4'}]}], 'maxVCpus': '160', 'guestIPs': '', 'display': 'qxl'},) {}
>Thread-69046::DEBUG::2014-06-05 09:25:13,890::API::523::vds::(migrationCreate) Migration create
>Thread-69046::INFO::2014-06-05 09:25:13,896::clientIF::366::vds::(createVm) vmContainerLock acquired by vm 803870d2-e365-4ab4-bdcc-4c1d25a03944
>Thread-69047::DEBUG::2014-06-05 09:25:13,901::vm::2238::vm.Vm::(_startUnderlyingVm) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Start
>Thread-69046::DEBUG::2014-06-05 09:25:13,901::clientIF::379::vds::(createVm) Total desktops after creation of 803870d2-e365-4ab4-bdcc-4c1d25a03944 is 1
>Thread-69047::DEBUG::2014-06-05 09:25:13,901::vm::2242::vm.Vm::(_startUnderlyingVm) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::_ongoingCreations acquired
>Thread-69046::DEBUG::2014-06-05 09:25:13,901::vm::5236::vm.Vm::(waitForMigrationDestinationPrepare) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::migration destination: waiting for VM creation
>Thread-69047::INFO::2014-06-05 09:25:13,901::vm::3112::vm.Vm::(_run) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::VM wrapper has started
>Thread-69046::DEBUG::2014-06-05 09:25:13,902::vm::5241::vm.Vm::(waitForMigrationDestinationPrepare) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::migration destination: waiting 36s for path preparation
>Thread-69047::WARNING::2014-06-05 09:25:13,902::vm::2058::vm.Vm::(buildConfDevices) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Unknown type found, device: '{'device': 'unix', 'alias': 'channel0', 'type': 'channel', 'address': {'bus': '0', 'controller': '0', 'type': 'virtio-serial', 'port': '1'}}' found
>Thread-69047::WARNING::2014-06-05 09:25:13,902::vm::2058::vm.Vm::(buildConfDevices) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Unknown type found, device: '{'device': 'unix', 'alias': 'channel1', 'type': 'channel', 'address': {'bus': '0', 'controller': '0', 'type': 'virtio-serial', 'port': '2'}}' found
>Thread-69047::WARNING::2014-06-05 09:25:13,903::vm::2058::vm.Vm::(buildConfDevices) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Unknown type found, device: '{'device': 'spicevmc', 'alias': 'channel2', 'type': 'channel', 'address': {'bus': '0', 'controller': '0', 'type': 'virtio-serial', 'port': '3'}}' found
>Thread-69047::DEBUG::2014-06-05 09:25:13,903::task::595::TaskManager.Task::(_updateState) Task=`f8a2bcee-962b-4839-82f3-0ef0438664f1`::moving from state init -> state preparing
>Thread-69047::INFO::2014-06-05 09:25:13,903::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='272ec473-6041-42ee-bd1a-732789dd18d4', spUUID='94ed7a19-fade-4bd6-83f2-2cbb2f730b95', imgUUID='12843faf-ebbc-4732-b4e9-0bb2501c194f', volUUID='04b45378-e7b8-4488-b48a-6b3fac1f18a4', options=None)
>Thread-69047::INFO::2014-06-05 09:25:13,905::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '27380420608', 'apparentsize': '26863764480'}
>Thread-69047::DEBUG::2014-06-05 09:25:13,905::task::1185::TaskManager.Task::(prepare) Task=`f8a2bcee-962b-4839-82f3-0ef0438664f1`::finished: {'truesize': '27380420608', 'apparentsize': '26863764480'}
>Thread-69047::DEBUG::2014-06-05 09:25:13,905::task::595::TaskManager.Task::(_updateState) Task=`f8a2bcee-962b-4839-82f3-0ef0438664f1`::moving from state preparing -> state finished
>Thread-69047::DEBUG::2014-06-05 09:25:13,905::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-69047::DEBUG::2014-06-05 09:25:13,905::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-69047::DEBUG::2014-06-05 09:25:13,905::task::990::TaskManager.Task::(_decref) Task=`f8a2bcee-962b-4839-82f3-0ef0438664f1`::ref 0 aborting False
>Thread-69047::INFO::2014-06-05 09:25:13,906::clientIF::324::vds::(prepareVolumePath) prepared volume path: 
>Thread-69047::DEBUG::2014-06-05 09:25:13,906::task::595::TaskManager.Task::(_updateState) Task=`5d3d4cc9-acbc-40fb-b1c6-2aa99ed83731`::moving from state init -> state preparing
>Thread-69047::INFO::2014-06-05 09:25:13,906::logUtils::44::dispatcher::(wrapper) Run and protect: prepareImage(sdUUID='272ec473-6041-42ee-bd1a-732789dd18d4', spUUID='94ed7a19-fade-4bd6-83f2-2cbb2f730b95', imgUUID='12843faf-ebbc-4732-b4e9-0bb2501c194f', leafUUID='04b45378-e7b8-4488-b48a-6b3fac1f18a4')
>Thread-69047::DEBUG::2014-06-05 09:25:13,906::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.272ec473-6041-42ee-bd1a-732789dd18d4`ReqID=`8e996383-3b0b-4d66-9d85-deb5e9ee620c`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '3238' at 'prepareImage'
>Thread-69047::DEBUG::2014-06-05 09:25:13,907::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.272ec473-6041-42ee-bd1a-732789dd18d4' for lock type 'shared'
>Thread-69047::DEBUG::2014-06-05 09:25:13,907::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.272ec473-6041-42ee-bd1a-732789dd18d4' is free. Now locking as 'shared' (1 active user)
>Thread-69047::DEBUG::2014-06-05 09:25:13,907::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.272ec473-6041-42ee-bd1a-732789dd18d4`ReqID=`8e996383-3b0b-4d66-9d85-deb5e9ee620c`::Granted request
>Thread-69047::DEBUG::2014-06-05 09:25:13,907::task::827::TaskManager.Task::(resourceAcquired) Task=`5d3d4cc9-acbc-40fb-b1c6-2aa99ed83731`::_resourcesAcquired: Storage.272ec473-6041-42ee-bd1a-732789dd18d4 (shared)
>Thread-69047::DEBUG::2014-06-05 09:25:13,907::task::990::TaskManager.Task::(_decref) Task=`5d3d4cc9-acbc-40fb-b1c6-2aa99ed83731`::ref 1 aborting False
>Thread-69047::WARNING::2014-06-05 09:25:13,909::fileUtils::167::Storage.fileUtils::(createdir) Dir /var/run/vdsm/storage/272ec473-6041-42ee-bd1a-732789dd18d4 already exists
>Thread-69047::DEBUG::2014-06-05 09:25:13,909::fileSD::480::Storage.StorageDomain::(createImageLinks) img run dir already exists: /var/run/vdsm/storage/272ec473-6041-42ee-bd1a-732789dd18d4/12843faf-ebbc-4732-b4e9-0bb2501c194f
>Thread-69047::DEBUG::2014-06-05 09:25:13,910::fileVolume::529::Storage.Volume::(validateVolumePath) validate path for 04b45378-e7b8-4488-b48a-6b3fac1f18a4
>Thread-69047::INFO::2014-06-05 09:25:13,912::logUtils::47::dispatcher::(wrapper) Run and protect: prepareImage, Return response: {'info': {'domainID': '272ec473-6041-42ee-bd1a-732789dd18d4', 'volType': 'path', 'leaseOffset': 0, 'path': '/rhev/data-center/mnt/10.10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/images/12843faf-ebbc-4732-b4e9-0bb2501c194f/04b45378-e7b8-4488-b48a-6b3fac1f18a4', 'volumeID': '04b45378-e7b8-4488-b48a-6b3fac1f18a4', 'leasePath': '/rhev/data-center/mnt/10.10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/images/12843faf-ebbc-4732-b4e9-0bb2501c194f/04b45378-e7b8-4488-b48a-6b3fac1f18a4.lease', 'imageID': '12843faf-ebbc-4732-b4e9-0bb2501c194f'}, 'path': '/rhev/data-center/mnt/10.10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/images/12843faf-ebbc-4732-b4e9-0bb2501c194f/04b45378-e7b8-4488-b48a-6b3fac1f18a4', 'imgVolumesInfo': [{'domainID': '272ec473-6041-42ee-bd1a-732789dd18d4', 'volType': 'path', 'leaseOffset': 0, 'path': '/rhev/data-center/mnt/10.10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/images/12843faf-ebbc-4732-b4e9-0bb2501c194f/04b45378-e7b8-4488-b48a-6b3fac1f18a4', 'volumeID': '04b45378-e7b8-4488-b48a-6b3fac1f18a4', 'leasePath': '/rhev/data-center/mnt/10.10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/images/12843faf-ebbc-4732-b4e9-0bb2501c194f/04b45378-e7b8-4488-b48a-6b3fac1f18a4.lease', 'imageID': '12843faf-ebbc-4732-b4e9-0bb2501c194f'}]}
>Thread-69047::DEBUG::2014-06-05 09:25:13,912::task::1185::TaskManager.Task::(prepare) Task=`5d3d4cc9-acbc-40fb-b1c6-2aa99ed83731`::finished: {'info': {'domainID': '272ec473-6041-42ee-bd1a-732789dd18d4', 'volType': 'path', 'leaseOffset': 0, 'path': '/rhev/data-center/mnt/10.10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/images/12843faf-ebbc-4732-b4e9-0bb2501c194f/04b45378-e7b8-4488-b48a-6b3fac1f18a4', 'volumeID': '04b45378-e7b8-4488-b48a-6b3fac1f18a4', 'leasePath': '/rhev/data-center/mnt/10.10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/images/12843faf-ebbc-4732-b4e9-0bb2501c194f/04b45378-e7b8-4488-b48a-6b3fac1f18a4.lease', 'imageID': '12843faf-ebbc-4732-b4e9-0bb2501c194f'}, 'path': '/rhev/data-center/mnt/10.10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/images/12843faf-ebbc-4732-b4e9-0bb2501c194f/04b45378-e7b8-4488-b48a-6b3fac1f18a4', 'imgVolumesInfo': [{'domainID': '272ec473-6041-42ee-bd1a-732789dd18d4', 'volType': 'path', 'leaseOffset': 0, 'path': '/rhev/data-center/mnt/10.10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/images/12843faf-ebbc-4732-b4e9-0bb2501c194f/04b45378-e7b8-4488-b48a-6b3fac1f18a4', 'volumeID': '04b45378-e7b8-4488-b48a-6b3fac1f18a4', 'leasePath': '/rhev/data-center/mnt/10.10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/images/12843faf-ebbc-4732-b4e9-0bb2501c194f/04b45378-e7b8-4488-b48a-6b3fac1f18a4.lease', 'imageID': '12843faf-ebbc-4732-b4e9-0bb2501c194f'}]}
>Thread-69047::DEBUG::2014-06-05 09:25:13,912::task::595::TaskManager.Task::(_updateState) Task=`5d3d4cc9-acbc-40fb-b1c6-2aa99ed83731`::moving from state preparing -> state finished
>Thread-69047::DEBUG::2014-06-05 09:25:13,912::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.272ec473-6041-42ee-bd1a-732789dd18d4': < ResourceRef 'Storage.272ec473-6041-42ee-bd1a-732789dd18d4', isValid: 'True' obj: 'None'>}
>Thread-69047::DEBUG::2014-06-05 09:25:13,912::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-69047::DEBUG::2014-06-05 09:25:13,912::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.272ec473-6041-42ee-bd1a-732789dd18d4'
>Thread-69047::DEBUG::2014-06-05 09:25:13,913::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.272ec473-6041-42ee-bd1a-732789dd18d4' (0 active users)
>Thread-69047::DEBUG::2014-06-05 09:25:13,913::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.272ec473-6041-42ee-bd1a-732789dd18d4' is free, finding out if anyone is waiting for it.
>Thread-69047::DEBUG::2014-06-05 09:25:13,913::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.272ec473-6041-42ee-bd1a-732789dd18d4', Clearing records.
>Thread-69047::DEBUG::2014-06-05 09:25:13,913::task::990::TaskManager.Task::(_decref) Task=`5d3d4cc9-acbc-40fb-b1c6-2aa99ed83731`::ref 0 aborting False
>Thread-69047::INFO::2014-06-05 09:25:13,913::clientIF::324::vds::(prepareVolumePath) prepared volume path: /rhev/data-center/mnt/10.10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/images/12843faf-ebbc-4732-b4e9-0bb2501c194f/04b45378-e7b8-4488-b48a-6b3fac1f18a4
>Thread-69047::DEBUG::2014-06-05 09:25:13,917::vm::2259::vm.Vm::(_startUnderlyingVm) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::_ongoingCreations released
>Thread-69047::DEBUG::2014-06-05 09:25:13,924::vm::3697::vm.Vm::(_waitForIncomingMigrationFinish) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Waiting 21600 seconds for end of migration
>Thread-69046::DEBUG::2014-06-05 09:25:13,925::API::536::vds::(migrationCreate) Destination VM creation succeeded
>Thread-69046::DEBUG::2014-06-05 09:25:13,925::BindingXMLRPC::1074::vds::(wrapper) return vmMigrationCreate with {'status': {'message': 'Done', 'code': 0}, 'migrationPort': 0, 'params': {'guestFQDN': '', 'acpiEnable': 'true', 'emulatedMachine': 'pc-1.0', 'afterMigrationStatus': '', 'pid': '0', 'memGuaranteedSize': 2048, 'transparentHugePages': 'true', 'displaySecurePort': '-1', 'timeOffset': '14279', 'cpuType': 'Nehalem', 'custom': {'device_966ade53-ddf1-4699-8061-59f976025a58device_1486a6a3-5a78-4214-a876-44cb899ad8abdevice_d59d8a87-96f1-444a-9c16-91aa8c07aa5ddevice_e254253c-092c-44f9-badc-4feb40a769dcdevice_f85b2abb-2ad2-431b-bf0a-d7ba4e7d763b': 'VmDevice {vmId=803870d2-e365-4ab4-bdcc-4c1d25a03944, deviceId=f85b2abb-2ad2-431b-bf0a-d7ba4e7d763b, device=virtio-serial, type=CONTROLLER, bootOrder=0, specParams={}, address={bus=0x00, domain=0x0000, type=pci, slot=0x05, function=0x0}, managed=false, plugged=true, readOnly=false, deviceAlias=virtio-serial0, customProperties={}, snapshotId=null}', 'device_966ade53-ddf1-4699-8061-59f976025a58device_1486a6a3-5a78-4214-a876-44cb899ad8abdevice_d59d8a87-96f1-444a-9c16-91aa8c07aa5d': 'VmDevice {vmId=803870d2-e365-4ab4-bdcc-4c1d25a03944, deviceId=d59d8a87-96f1-444a-9c16-91aa8c07aa5d, 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_966ade53-ddf1-4699-8061-59f976025a58device_1486a6a3-5a78-4214-a876-44cb899ad8abdevice_d59d8a87-96f1-444a-9c16-91aa8c07aa5ddevice_e254253c-092c-44f9-badc-4feb40a769dc': 'VmDevice {vmId=803870d2-e365-4ab4-bdcc-4c1d25a03944, deviceId=e254253c-092c-44f9-badc-4feb40a769dc, 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_966ade53-ddf1-4699-8061-59f976025a58': 'VmDevice {vmId=803870d2-e365-4ab4-bdcc-4c1d25a03944, deviceId=966ade53-ddf1-4699-8061-59f976025a58, 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}', 'device_966ade53-ddf1-4699-8061-59f976025a58device_1486a6a3-5a78-4214-a876-44cb899ad8ab': 'VmDevice {vmId=803870d2-e365-4ab4-bdcc-4c1d25a03944, deviceId=1486a6a3-5a78-4214-a876-44cb899ad8ab, 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}'}, 'migrationDest': 'libvirt', 'smp': '2', 'vmType': 'kvm', 'spiceSslCipherSuite': 'DEFAULT', 'memSize': 3072, 'vmName': 'colvm36', 'nice': '0', 'username': 'Unknown', 'vmId': '803870d2-e365-4ab4-bdcc-4c1d25a03944', 'displayIp': '192.168.11.42', 'keyboardLayout': 'en-us', 'displayPort': '-1', 'guestIPs': '', 'smartcardEnable': 'false', 'spiceSecureChannels': 'smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard', 'nicModel': 'rtl8139,pv', 'smpCoresPerSocket': '2', 'kvmEnable': 'true', 'displayNetwork': 'ovirtmgmt', 'devices': [{'specParams': {}, 'alias': 'sound0', 'deviceId': '70e43d5b-6119-4204-a138-ef9a30dcb920', 'address': {'slot': '0x04', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'ac97', 'type': 'sound'}, {'target': 3145728, 'specParams': {'model': 'virtio'}, 'alias': 'balloon0', 'deviceId': '08fb1420-af65-452e-ab83-847a96a5090d', 'address': {'slot': '0x07', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'memballoon', 'type': 'balloon'}, {'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'}}, {'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': '32768', 'heads': '1'}, 'alias': 'video0', 'deviceId': '5ee02b8e-5916-4fce-89aa-ed26b2f939b5', 'address': {'slot': '0x02', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'qxl', 'type': 'video'}, {'nicModel': 'pv', 'macAddr': '00:0c:29:05:09:1e', 'linkActive': True, 'network': 'ovirtmgmt', 'specParams': {}, 'filter': 'vdsm-no-mac-spoofing', 'alias': 'net0', 'deviceId': '27b080c4-a9d0-479a-b0fe-de197c80af60', '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', 'specParams': {'path': ''}, 'readonly': 'True', 'deviceId': '6c0d02e8-d3ef-4b64-a5ab-74ebfbe9ea5e', 'address': {'bus': '1', 'controller': '0', 'type': 'drive', 'target': '0', 'unit': '0'}, 'device': 'cdrom', 'shared': 'false', 'path': '', 'type': 'disk'}, {'address': {'slot': '0x06', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'reqsize': '0', 'index': 0, 'iface': 'virtio', 'apparentsize': '26863764480', 'specParams': {}, 'imageID': '12843faf-ebbc-4732-b4e9-0bb2501c194f', 'readonly': 'False', 'shared': 'false', 'truesize': '27380420608', 'type': 'disk', 'domainID': '272ec473-6041-42ee-bd1a-732789dd18d4', 'volumeInfo': {'domainID': '272ec473-6041-42ee-bd1a-732789dd18d4', 'volType': 'path', 'leaseOffset': 0, 'path': '/rhev/data-center/mnt/10.10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/images/12843faf-ebbc-4732-b4e9-0bb2501c194f/04b45378-e7b8-4488-b48a-6b3fac1f18a4', 'volumeID': '04b45378-e7b8-4488-b48a-6b3fac1f18a4', 'leasePath': '/rhev/data-center/mnt/10.10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/images/12843faf-ebbc-4732-b4e9-0bb2501c194f/04b45378-e7b8-4488-b48a-6b3fac1f18a4.lease', 'imageID': '12843faf-ebbc-4732-b4e9-0bb2501c194f'}, 'format': 'raw', 'deviceId': '12843faf-ebbc-4732-b4e9-0bb2501c194f', 'poolID': '94ed7a19-fade-4bd6-83f2-2cbb2f730b95', 'device': 'disk', 'path': '/rhev/data-center/mnt/10.10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/images/12843faf-ebbc-4732-b4e9-0bb2501c194f/04b45378-e7b8-4488-b48a-6b3fac1f18a4', 'propagateErrors': 'off', 'optional': 'false', 'name': 'vda', 'bootOrder': '1', 'volumeID': '04b45378-e7b8-4488-b48a-6b3fac1f18a4', 'alias': 'virtio-disk0', 'volumeChain': [{'domainID': '272ec473-6041-42ee-bd1a-732789dd18d4', 'volType': 'path', 'leaseOffset': 0, 'path': '/rhev/data-center/mnt/10.10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/images/12843faf-ebbc-4732-b4e9-0bb2501c194f/04b45378-e7b8-4488-b48a-6b3fac1f18a4', 'volumeID': '04b45378-e7b8-4488-b48a-6b3fac1f18a4', 'leasePath': '/rhev/data-center/mnt/10.10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/images/12843faf-ebbc-4732-b4e9-0bb2501c194f/04b45378-e7b8-4488-b48a-6b3fac1f18a4.lease', 'imageID': '12843faf-ebbc-4732-b4e9-0bb2501c194f'}]}], 'status': 'Migration Destination', 'maxVCpus': '160', 'clientIp': '', 'display': 'qxl'}}
>libvirtEventLoop::DEBUG::2014-06-05 09:25:14,410::vm::5151::vm.Vm::(_onLibvirtLifecycleEvent) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::event Started detail 1 opaque None
>Thread-63529::DEBUG::2014-06-05 09:25:15,399::BindingXMLRPC::1067::vds::(wrapper) client [192.168.11.2]::call vmGetStats with ('803870d2-e365-4ab4-bdcc-4c1d25a03944',) {} flowID [160ca2e5]
>Thread-63529::DEBUG::2014-06-05 09:25:15,400::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.11.42', 'displayPort': '-1', 'displaySecurePort': '-1', 'timeOffset': '14279', 'kvmEnable': 'true', 'network': {}, 'vmId': '803870d2-e365-4ab4-bdcc-4c1d25a03944', 'displayType': 'qxl', 'disks': {}, 'monitorResponse': '0', 'elapsedTime': '63915', 'vmType': 'kvm', 'clientIp': ''}]}
>Thread-20::DEBUG::2014-06-05 09:25:18,086::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-20::DEBUG::2014-06-05 09:25:18,093::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n557 bytes (557 B) copied, 0.000296059 s, 1.9 MB/s\n'; <rc> = 0
>Thread-63529::DEBUG::2014-06-05 09:25:18,431::BindingXMLRPC::1067::vds::(wrapper) client [192.168.11.2]::call vmGetStats with ('803870d2-e365-4ab4-bdcc-4c1d25a03944',) {} flowID [619d876a]
>Thread-63529::DEBUG::2014-06-05 09:25:18,432::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.11.42', 'displayPort': '-1', 'displaySecurePort': '-1', 'timeOffset': '14279', 'kvmEnable': 'true', 'network': {}, 'vmId': '803870d2-e365-4ab4-bdcc-4c1d25a03944', 'displayType': 'qxl', 'disks': {}, 'monitorResponse': '0', 'elapsedTime': '63918', 'vmType': 'kvm', 'clientIp': ''}]}
>libvirtEventLoop::DEBUG::2014-06-05 09:25:20,126::vm::5151::vm.Vm::(_onLibvirtLifecycleEvent) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::event Resumed detail 0 opaque None
>libvirtEventLoop::DEBUG::2014-06-05 09:25:20,127::vm::5151::vm.Vm::(_onLibvirtLifecycleEvent) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::event Resumed detail 1 opaque None
>Thread-69047::DEBUG::2014-06-05 09:25:20,150::vm::5007::vm.Vm::(_getUnderlyingDriveInfo) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Looking for drive with attributes {'name': u'hdc', 'bootOrder': '', 'boot': [], 'readonly': True, 'address': {u'bus': u'1', u'controller': u'0', u'type': u'drive', u'target': u'0', u'unit': u'0'}, 'path': '', 'type': u'cdrom'}
>Thread-69047::DEBUG::2014-06-05 09:25:20,150::vm::5028::vm.Vm::(_getUnderlyingDriveInfo) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Matched {'name': (u'hdc', u'hdc'), 'bootOrder': ('', None), 'boot': ([], None), 'readonly': (True, True), 'address': ({u'bus': u'1', u'controller': u'0', u'type': u'drive', u'target': u'0', u'unit': u'0'}, {u'bus': u'1', u'controller': u'0', u'type': u'drive', u'target': u'0', u'unit': u'0'}), 'path': ('', ''), 'type': (u'cdrom', u'cdrom')}
>Thread-69047::DEBUG::2014-06-05 09:25:20,150::vm::5047::vm.Vm::(_getUnderlyingDriveInfo) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Matched {'name': (u'hdc', u'hdc'), 'bootOrder': ('', None), 'boot': ([], None), 'readonly': (True, 'True'), 'address': ({u'bus': u'1', u'controller': u'0', u'type': u'drive', u'target': u'0', u'unit': u'0'}, {u'bus': u'1', u'controller': u'0', u'type': u'drive', u'target': u'0', u'unit': u'0'}), 'path': ('', ''), 'type': (u'cdrom', 'disk')}
>Thread-69047::DEBUG::2014-06-05 09:25:20,150::vm::5007::vm.Vm::(_getUnderlyingDriveInfo) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Looking for drive with attributes {'name': u'vda', 'bootOrder': u'1', 'boot': [<DOM Element: boot at 0x7f1658204c68>], 'readonly': False, 'address': {u'slot': u'0x06', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, 'path': u'/rhev/data-center/mnt/10.10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/images/12843faf-ebbc-4732-b4e9-0bb2501c194f/04b45378-e7b8-4488-b48a-6b3fac1f18a4', 'type': u'disk'}
>Thread-69047::DEBUG::2014-06-05 09:25:20,151::vm::5028::vm.Vm::(_getUnderlyingDriveInfo) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Matched {'name': (u'vda', u'vda'), 'bootOrder': (u'1', u'1'), 'boot': ([<DOM Element: boot at 0x7f1658204c68>], None), 'readonly': (False, False), 'address': ({u'slot': u'0x06', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, {u'slot': u'0x06', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}), 'path': (u'/rhev/data-center/mnt/10.10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/images/12843faf-ebbc-4732-b4e9-0bb2501c194f/04b45378-e7b8-4488-b48a-6b3fac1f18a4', '/rhev/data-center/mnt/10.10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/images/12843faf-ebbc-4732-b4e9-0bb2501c194f/04b45378-e7b8-4488-b48a-6b3fac1f18a4'), 'type': (u'disk', u'disk')}
>Thread-69047::DEBUG::2014-06-05 09:25:20,151::vm::5047::vm.Vm::(_getUnderlyingDriveInfo) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Matched {'name': (u'vda', u'vda'), 'bootOrder': (u'1', u'1'), 'boot': ([<DOM Element: boot at 0x7f1658204c68>], None), 'readonly': (False, 'False'), 'address': ({u'slot': u'0x06', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, {u'slot': u'0x06', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}), 'path': (u'/rhev/data-center/mnt/10.10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/images/12843faf-ebbc-4732-b4e9-0bb2501c194f/04b45378-e7b8-4488-b48a-6b3fac1f18a4', '/rhev/data-center/mnt/10.10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/images/12843faf-ebbc-4732-b4e9-0bb2501c194f/04b45378-e7b8-4488-b48a-6b3fac1f18a4'), 'type': (u'disk', 'disk')}
>Thread-69047::DEBUG::2014-06-05 09:25:20,216::sampling::285::vm.Vm::(start) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Start statistics collection
>Thread-69049::DEBUG::2014-06-05 09:25:20,217::sampling::314::vm.Vm::(run) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Stats thread started
>Thread-69049::DEBUG::2014-06-05 09:25:20,218::task::595::TaskManager.Task::(_updateState) Task=`cb4c6e7f-1e87-42d2-bd58-ac906d3bbdce`::moving from state init -> state preparing
>Thread-69049::INFO::2014-06-05 09:25:20,218::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='272ec473-6041-42ee-bd1a-732789dd18d4', spUUID='94ed7a19-fade-4bd6-83f2-2cbb2f730b95', imgUUID='12843faf-ebbc-4732-b4e9-0bb2501c194f', volUUID='04b45378-e7b8-4488-b48a-6b3fac1f18a4', options=None)
>Thread-69049::INFO::2014-06-05 09:25:20,220::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '27380420608', 'apparentsize': '26863764480'}
>Thread-69047::DEBUG::2014-06-05 09:25:20,220::vmChannels::194::vds::(register) Add fileno 27 to listener's channels.
>Thread-69049::DEBUG::2014-06-05 09:25:20,220::task::1185::TaskManager.Task::(prepare) Task=`cb4c6e7f-1e87-42d2-bd58-ac906d3bbdce`::finished: {'truesize': '27380420608', 'apparentsize': '26863764480'}
>Thread-69049::DEBUG::2014-06-05 09:25:20,220::task::595::TaskManager.Task::(_updateState) Task=`cb4c6e7f-1e87-42d2-bd58-ac906d3bbdce`::moving from state preparing -> state finished
>Thread-69049::DEBUG::2014-06-05 09:25:20,221::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-69049::DEBUG::2014-06-05 09:25:20,221::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-69049::DEBUG::2014-06-05 09:25:20,221::task::990::TaskManager.Task::(_decref) Task=`cb4c6e7f-1e87-42d2-bd58-ac906d3bbdce`::ref 0 aborting False
>Thread-69047::DEBUG::2014-06-05 09:25:20,239::vm::3744::vm.Vm::(_waitForIncomingMigrationFinish) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::End of migration
>VM Channels Listener::DEBUG::2014-06-05 09:25:20,821::vmChannels::102::vds::(_do_add_channels) fileno 27 was added to unconnected channels.
>VM Channels Listener::DEBUG::2014-06-05 09:25:20,821::vmChannels::128::vds::(_handle_unconnected) Trying to connect fileno 27.
>VM Channels Listener::DEBUG::2014-06-05 09:25:20,822::guestIF::194::vm.Vm::(_connect) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Attempting connection to /var/lib/libvirt/qemu/channels/803870d2-e365-4ab4-bdcc-4c1d25a03944.com.redhat.rhevm.vdsm
>VM Channels Listener::DEBUG::2014-06-05 09:25:20,822::guestIF::197::vm.Vm::(_connect) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Connected to /var/lib/libvirt/qemu/channels/803870d2-e365-4ab4-bdcc-4c1d25a03944.com.redhat.rhevm.vdsm
>VM Channels Listener::DEBUG::2014-06-05 09:25:20,822::vmChannels::144::vds::(_handle_unconnected) Connecting to fileno 27 succeeded.
>Thread-19::DEBUG::2014-06-05 09:25:20,832::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtIB/2c51d320-88ce-4f23-8215-e15f55f66906/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-19::DEBUG::2014-06-05 09:25:20,840::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n644 bytes (644 B) copied, 0.000209395 s, 3.1 MB/s\n'; <rc> = 0
>Thread-27::DEBUG::2014-06-05 09:25:20,999::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtEXP/63041fa9-e093-4b44-b36f-f39f16d3974f/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-27::DEBUG::2014-06-05 09:25:21,007::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n363 bytes (363 B) copied, 0.000240446 s, 1.5 MB/s\n'; <rc> = 0
>Thread-32::DEBUG::2014-06-05 09:25:21,020::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-32::DEBUG::2014-06-05 09:25:21,028::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n557 bytes (557 B) copied, 0.000241353 s, 2.3 MB/s\n'; <rc> = 0
>Thread-63529::DEBUG::2014-06-05 09:25:21,461::BindingXMLRPC::1067::vds::(wrapper) client [192.168.11.2]::call vmGetStats with ('803870d2-e365-4ab4-bdcc-4c1d25a03944',) {} flowID [638a3b4c]
>Thread-63529::DEBUG::2014-06-05 09:25:21,462::vm::587::vm.Vm::(_getCpuStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::CPU stats not available: 'NoneType' object has no attribute '__getitem__'
>Thread-63529::DEBUG::2014-06-05 09:25:21,462::vm::623::vm.Vm::(_getNetworkStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Network stats not available
>Thread-63529::DEBUG::2014-06-05 09:25:21,462::vm::645::vm.Vm::(_getDiskStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk hdc stats not available
>Thread-63529::DEBUG::2014-06-05 09:25:21,462::vm::645::vm.Vm::(_getDiskStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk vda stats not available
>Thread-63529::DEBUG::2014-06-05 09:25:21,462::vm::684::vm.Vm::(_getDiskLatency) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk hdc latency not available
>Thread-63529::DEBUG::2014-06-05 09:25:21,463::vm::684::vm.Vm::(_getDiskLatency) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk vda latency not available
>Thread-63529::DEBUG::2014-06-05 09:25:21,464::BindingXMLRPC::1074::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Up', 'username': 'Unknown', 'memUsage': '0', 'acpiEnable': 'true', 'guestFQDN': '', 'pid': '5002', 'displayIp': '192.168.11.42', 'displayPort': '-1', 'session': 'Unknown', 'displaySecurePort': u'5900', 'timeOffset': '14279', 'hash': '-2832807100151321570', 'balloonInfo': {'balloon_max': '3145728', 'balloon_target': '3145728', 'balloon_cur': '3145728', 'balloon_min': '2097152'}, 'clientIp': '', 'kvmEnable': 'true', 'network': {u'vnet0': {'state': 'unknown', 'macAddr': '00:0c:29:05:09:1e', 'speed': '1000', 'name': u'vnet0'}}, 'vmId': '803870d2-e365-4ab4-bdcc-4c1d25a03944', 'displayType': 'qxl', 'cpuUser': '0.00', 'disks': {u'vda': {'truesize': '27380420608', 'apparentsize': '26863764480', 'imageID': '12843faf-ebbc-4732-b4e9-0bb2501c194f'}, u'hdc': {'truesize': '0', 'apparentsize': '0'}}, 'monitorResponse': '0', 'statsAge': '1.24', 'elapsedTime': '63921', 'vmType': 'kvm', 'cpuSys': '0.00', 'guestCPUCount': -1, 'appsList': [], 'guestIPs': ''}]}
>Thread-21::DEBUG::2014-06-05 09:25:22,532::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtISO/bff3a2be-fdd9-4e37-b416-fa4ef7fafba2/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-21::DEBUG::2014-06-05 09:25:22,539::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n357 bytes (357 B) copied, 0.000244986 s, 1.5 MB/s\n'; <rc> = 0
>GuestMonitor-colvm36::DEBUG::2014-06-05 09:25:23,287::vm::587::vm.Vm::(_getCpuStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::CPU stats not available: 'NoneType' object has no attribute '__getitem__'
>GuestMonitor-colvm36::DEBUG::2014-06-05 09:25:23,287::vm::623::vm.Vm::(_getNetworkStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Network stats not available
>GuestMonitor-colvm36::DEBUG::2014-06-05 09:25:23,288::vm::645::vm.Vm::(_getDiskStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk hdc stats not available
>GuestMonitor-colvm36::DEBUG::2014-06-05 09:25:23,288::vm::645::vm.Vm::(_getDiskStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk vda stats not available
>GuestMonitor-colvm36::DEBUG::2014-06-05 09:25:23,288::vm::684::vm.Vm::(_getDiskLatency) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk hdc latency not available
>GuestMonitor-colvm36::DEBUG::2014-06-05 09:25:23,288::vm::684::vm.Vm::(_getDiskLatency) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk vda latency not available
>GuestMonitor-colvm36::DEBUG::2014-06-05 09:25:23,290::vm::587::vm.Vm::(_getCpuStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::CPU stats not available: 'NoneType' object has no attribute '__getitem__'
>GuestMonitor-colvm36::DEBUG::2014-06-05 09:25:23,290::vm::623::vm.Vm::(_getNetworkStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Network stats not available
>GuestMonitor-colvm36::DEBUG::2014-06-05 09:25:23,290::vm::645::vm.Vm::(_getDiskStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk hdc stats not available
>GuestMonitor-colvm36::DEBUG::2014-06-05 09:25:23,290::vm::645::vm.Vm::(_getDiskStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk vda stats not available
>GuestMonitor-colvm36::DEBUG::2014-06-05 09:25:23,290::vm::684::vm.Vm::(_getDiskLatency) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk hdc latency not available
>GuestMonitor-colvm36::DEBUG::2014-06-05 09:25:23,291::vm::684::vm.Vm::(_getDiskLatency) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk vda latency not available
>Thread-63529::DEBUG::2014-06-05 09:25:24,578::task::595::TaskManager.Task::(_updateState) Task=`600e4f4d-d996-485d-9936-dc89e6936a39`::moving from state init -> state preparing
>Thread-63529::INFO::2014-06-05 09:25:24,578::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-63529::INFO::2014-06-05 09:25:24,579::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'2c51d320-88ce-4f23-8215-e15f55f66906': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000209395', 'lastCheck': '3.7', 'valid': True}, '965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000296059', 'lastCheck': '6.5', 'valid': True}, 'bff3a2be-fdd9-4e37-b416-fa4ef7fafba2': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000244986', 'lastCheck': '2.0', 'valid': True}, '63041fa9-e093-4b44-b36f-f39f16d3974f': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000240446', 'lastCheck': '3.6', 'valid': True}, '272ec473-6041-42ee-bd1a-732789dd18d4': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000241353', 'lastCheck': '3.5', 'valid': True}}
>Thread-63529::DEBUG::2014-06-05 09:25:24,579::task::1185::TaskManager.Task::(prepare) Task=`600e4f4d-d996-485d-9936-dc89e6936a39`::finished: {'2c51d320-88ce-4f23-8215-e15f55f66906': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000209395', 'lastCheck': '3.7', 'valid': True}, '965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000296059', 'lastCheck': '6.5', 'valid': True}, 'bff3a2be-fdd9-4e37-b416-fa4ef7fafba2': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000244986', 'lastCheck': '2.0', 'valid': True}, '63041fa9-e093-4b44-b36f-f39f16d3974f': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000240446', 'lastCheck': '3.6', 'valid': True}, '272ec473-6041-42ee-bd1a-732789dd18d4': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000241353', 'lastCheck': '3.5', 'valid': True}}
>Thread-63529::DEBUG::2014-06-05 09:25:24,579::task::595::TaskManager.Task::(_updateState) Task=`600e4f4d-d996-485d-9936-dc89e6936a39`::moving from state preparing -> state finished
>Thread-63529::DEBUG::2014-06-05 09:25:24,579::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-63529::DEBUG::2014-06-05 09:25:24,579::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-63529::DEBUG::2014-06-05 09:25:24,580::task::990::TaskManager.Task::(_decref) Task=`600e4f4d-d996-485d-9936-dc89e6936a39`::ref 0 aborting False
>Thread-63529::DEBUG::2014-06-05 09:25:24,619::vm::587::vm.Vm::(_getCpuStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::CPU stats not available: 'NoneType' object has no attribute '__getitem__'
>Thread-63529::DEBUG::2014-06-05 09:25:24,619::vm::623::vm.Vm::(_getNetworkStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Network stats not available
>Thread-63529::DEBUG::2014-06-05 09:25:24,619::vm::645::vm.Vm::(_getDiskStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk hdc stats not available
>Thread-63529::DEBUG::2014-06-05 09:25:24,619::vm::645::vm.Vm::(_getDiskStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk vda stats not available
>Thread-63529::DEBUG::2014-06-05 09:25:24,619::vm::684::vm.Vm::(_getDiskLatency) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk hdc latency not available
>Thread-63529::DEBUG::2014-06-05 09:25:24,619::vm::684::vm.Vm::(_getDiskLatency) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk vda latency not available
>Thread-63529::DEBUG::2014-06-05 09:25:26,066::BindingXMLRPC::1067::vds::(wrapper) client [192.168.11.2]::call vmSetTicket with ('803870d2-e365-4ab4-bdcc-4c1d25a03944', 'gJieYGoA6mDb', '120', 'disconnect', {'userName': 'Stockhausen', 'userId': 'b6b1f9f8-7030-4ea6-9653-9345860d58a9'}) {} flowID [62bb6fba]
>Thread-63529::DEBUG::2014-06-05 09:25:26,080::BindingXMLRPC::1074::vds::(wrapper) return vmSetTicket with {'status': {'message': 'Done', 'code': 0}}
>Thread-20::DEBUG::2014-06-05 09:25:28,105::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-20::DEBUG::2014-06-05 09:25:28,113::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n557 bytes (557 B) copied, 0.000276277 s, 2.0 MB/s\n'; <rc> = 0
>GuestMonitor-colvm36::DEBUG::2014-06-05 09:25:28,297::vm::587::vm.Vm::(_getCpuStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::CPU stats not available: 'NoneType' object has no attribute '__getitem__'
>GuestMonitor-colvm36::DEBUG::2014-06-05 09:25:28,297::vm::623::vm.Vm::(_getNetworkStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Network stats not available
>GuestMonitor-colvm36::DEBUG::2014-06-05 09:25:28,297::vm::645::vm.Vm::(_getDiskStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk hdc stats not available
>GuestMonitor-colvm36::DEBUG::2014-06-05 09:25:28,298::vm::645::vm.Vm::(_getDiskStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk vda stats not available
>GuestMonitor-colvm36::DEBUG::2014-06-05 09:25:28,298::vm::684::vm.Vm::(_getDiskLatency) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk hdc latency not available
>GuestMonitor-colvm36::DEBUG::2014-06-05 09:25:28,298::vm::684::vm.Vm::(_getDiskLatency) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk vda latency not available
>GuestMonitor-colvm36::DEBUG::2014-06-05 09:25:28,299::vm::587::vm.Vm::(_getCpuStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::CPU stats not available: 'NoneType' object has no attribute '__getitem__'
>GuestMonitor-colvm36::DEBUG::2014-06-05 09:25:28,300::vm::623::vm.Vm::(_getNetworkStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Network stats not available
>GuestMonitor-colvm36::DEBUG::2014-06-05 09:25:28,300::vm::645::vm.Vm::(_getDiskStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk hdc stats not available
>GuestMonitor-colvm36::DEBUG::2014-06-05 09:25:28,300::vm::645::vm.Vm::(_getDiskStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk vda stats not available
>GuestMonitor-colvm36::DEBUG::2014-06-05 09:25:28,300::vm::684::vm.Vm::(_getDiskLatency) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk hdc latency not available
>GuestMonitor-colvm36::DEBUG::2014-06-05 09:25:28,300::vm::684::vm.Vm::(_getDiskLatency) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk vda latency not available
>Thread-19::DEBUG::2014-06-05 09:25:30,853::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtIB/2c51d320-88ce-4f23-8215-e15f55f66906/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-19::DEBUG::2014-06-05 09:25:30,860::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n644 bytes (644 B) copied, 0.000216338 s, 3.0 MB/s\n'; <rc> = 0
>Thread-27::DEBUG::2014-06-05 09:25:31,020::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtEXP/63041fa9-e093-4b44-b36f-f39f16d3974f/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-27::DEBUG::2014-06-05 09:25:31,028::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n363 bytes (363 B) copied, 0.000282369 s, 1.3 MB/s\n'; <rc> = 0
>Thread-32::DEBUG::2014-06-05 09:25:31,040::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-32::DEBUG::2014-06-05 09:25:31,047::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n557 bytes (557 B) copied, 0.000206051 s, 2.7 MB/s\n'; <rc> = 0
>libvirtEventLoop::DEBUG::2014-06-05 09:25:32,342::clientIF::555::vm.Vm::(dispatchLibvirtEvents) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::graphics event phase 0 localAddr {'node': '192.168.11.42', 'service': '', 'family': 0} remoteAddr {'node': '192.168.10.181', 'service': '', 'family': 0}authScheme  subject []
>Thread-21::DEBUG::2014-06-05 09:25:32,548::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtISO/bff3a2be-fdd9-4e37-b416-fa4ef7fafba2/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-21::DEBUG::2014-06-05 09:25:32,556::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n357 bytes (357 B) copied, 0.000283246 s, 1.3 MB/s\n'; <rc> = 0
>GuestMonitor-colvm36::DEBUG::2014-06-05 09:25:33,307::vm::587::vm.Vm::(_getCpuStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::CPU stats not available: 'NoneType' object has no attribute '__getitem__'
>GuestMonitor-colvm36::DEBUG::2014-06-05 09:25:33,307::vm::623::vm.Vm::(_getNetworkStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Network stats not available
>GuestMonitor-colvm36::DEBUG::2014-06-05 09:25:33,307::vm::645::vm.Vm::(_getDiskStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk hdc stats not available
>GuestMonitor-colvm36::DEBUG::2014-06-05 09:25:33,308::vm::645::vm.Vm::(_getDiskStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk vda stats not available
>GuestMonitor-colvm36::DEBUG::2014-06-05 09:25:33,308::vm::684::vm.Vm::(_getDiskLatency) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk hdc latency not available
>GuestMonitor-colvm36::DEBUG::2014-06-05 09:25:33,308::vm::684::vm.Vm::(_getDiskLatency) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk vda latency not available
>GuestMonitor-colvm36::DEBUG::2014-06-05 09:25:33,310::vm::587::vm.Vm::(_getCpuStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::CPU stats not available: 'NoneType' object has no attribute '__getitem__'
>GuestMonitor-colvm36::DEBUG::2014-06-05 09:25:33,310::vm::623::vm.Vm::(_getNetworkStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Network stats not available
>GuestMonitor-colvm36::DEBUG::2014-06-05 09:25:33,310::vm::645::vm.Vm::(_getDiskStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk hdc stats not available
>GuestMonitor-colvm36::DEBUG::2014-06-05 09:25:33,310::vm::645::vm.Vm::(_getDiskStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk vda stats not available
>GuestMonitor-colvm36::DEBUG::2014-06-05 09:25:33,310::vm::684::vm.Vm::(_getDiskLatency) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk hdc latency not available
>GuestMonitor-colvm36::DEBUG::2014-06-05 09:25:33,310::vm::684::vm.Vm::(_getDiskLatency) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk vda latency not available
>libvirtEventLoop::DEBUG::2014-06-05 09:25:33,594::clientIF::555::vm.Vm::(dispatchLibvirtEvents) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::graphics event phase 1 localAddr {'node': '192.168.11.42', 'service': '', 'family': 0} remoteAddr {'node': '192.168.10.181', 'service': '', 'family': 0}authScheme spice subject []
>libvirtEventLoop::DEBUG::2014-06-05 09:25:33,733::clientIF::555::vm.Vm::(dispatchLibvirtEvents) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::graphics event phase 0 localAddr {'node': '192.168.11.42', 'service': '', 'family': 0} remoteAddr {'node': '192.168.10.181', 'service': '', 'family': 0}authScheme  subject []
>libvirtEventLoop::DEBUG::2014-06-05 09:25:33,733::clientIF::555::vm.Vm::(dispatchLibvirtEvents) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::graphics event phase 0 localAddr {'node': '192.168.11.42', 'service': '', 'family': 0} remoteAddr {'node': '192.168.10.181', 'service': '', 'family': 0}authScheme  subject []
>libvirtEventLoop::DEBUG::2014-06-05 09:25:33,734::clientIF::555::vm.Vm::(dispatchLibvirtEvents) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::graphics event phase 0 localAddr {'node': '192.168.11.42', 'service': '', 'family': 0} remoteAddr {'node': '192.168.10.181', 'service': '', 'family': 0}authScheme  subject []
>libvirtEventLoop::DEBUG::2014-06-05 09:25:33,906::clientIF::555::vm.Vm::(dispatchLibvirtEvents) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::graphics event phase 1 localAddr {'node': '192.168.11.42', 'service': '', 'family': 0} remoteAddr {'node': '192.168.10.181', 'service': '', 'family': 0}authScheme spice subject []
>libvirtEventLoop::DEBUG::2014-06-05 09:25:33,907::clientIF::555::vm.Vm::(dispatchLibvirtEvents) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::graphics event phase 1 localAddr {'node': '192.168.11.42', 'service': '', 'family': 0} remoteAddr {'node': '192.168.10.181', 'service': '', 'family': 0}authScheme spice subject []
>libvirtEventLoop::DEBUG::2014-06-05 09:25:33,911::clientIF::555::vm.Vm::(dispatchLibvirtEvents) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::graphics event phase 1 localAddr {'node': '192.168.11.42', 'service': '', 'family': 0} remoteAddr {'node': '192.168.10.181', 'service': '', 'family': 0}authScheme spice subject []
>Thread-20::DEBUG::2014-06-05 09:25:38,124::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.251:_var_nas1_OVirtIB/965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-20::DEBUG::2014-06-05 09:25:38,132::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n557 bytes (557 B) copied, 0.00024035 s, 2.3 MB/s\n'; <rc> = 0
>GuestMonitor-colvm36::DEBUG::2014-06-05 09:25:38,313::vm::645::vm.Vm::(_getDiskStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk hdc stats not available
>GuestMonitor-colvm36::DEBUG::2014-06-05 09:25:38,313::vm::645::vm.Vm::(_getDiskStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk vda stats not available
>GuestMonitor-colvm36::DEBUG::2014-06-05 09:25:38,313::vm::684::vm.Vm::(_getDiskLatency) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk hdc latency not available
>GuestMonitor-colvm36::DEBUG::2014-06-05 09:25:38,313::vm::684::vm.Vm::(_getDiskLatency) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk vda latency not available
>GuestMonitor-colvm36::DEBUG::2014-06-05 09:25:38,315::vm::645::vm.Vm::(_getDiskStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk hdc stats not available
>GuestMonitor-colvm36::DEBUG::2014-06-05 09:25:38,315::vm::645::vm.Vm::(_getDiskStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk vda stats not available
>GuestMonitor-colvm36::DEBUG::2014-06-05 09:25:38,315::vm::684::vm.Vm::(_getDiskLatency) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk hdc latency not available
>GuestMonitor-colvm36::DEBUG::2014-06-05 09:25:38,315::vm::684::vm.Vm::(_getDiskLatency) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk vda latency not available
>Thread-63529::DEBUG::2014-06-05 09:25:39,759::task::595::TaskManager.Task::(_updateState) Task=`442197c4-4efc-4bee-bb98-18aab59f9cf6`::moving from state init -> state preparing
>Thread-63529::INFO::2014-06-05 09:25:39,759::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-63529::INFO::2014-06-05 09:25:39,759::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'2c51d320-88ce-4f23-8215-e15f55f66906': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000216338', 'lastCheck': '8.9', 'valid': True}, '965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.00024035', 'lastCheck': '1.6', 'valid': True}, 'bff3a2be-fdd9-4e37-b416-fa4ef7fafba2': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000283246', 'lastCheck': '7.2', 'valid': True}, '63041fa9-e093-4b44-b36f-f39f16d3974f': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000282369', 'lastCheck': '8.7', 'valid': True}, '272ec473-6041-42ee-bd1a-732789dd18d4': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000206051', 'lastCheck': '8.7', 'valid': True}}
>Thread-63529::DEBUG::2014-06-05 09:25:39,760::task::1185::TaskManager.Task::(prepare) Task=`442197c4-4efc-4bee-bb98-18aab59f9cf6`::finished: {'2c51d320-88ce-4f23-8215-e15f55f66906': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000216338', 'lastCheck': '8.9', 'valid': True}, '965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.00024035', 'lastCheck': '1.6', 'valid': True}, 'bff3a2be-fdd9-4e37-b416-fa4ef7fafba2': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000283246', 'lastCheck': '7.2', 'valid': True}, '63041fa9-e093-4b44-b36f-f39f16d3974f': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000282369', 'lastCheck': '8.7', 'valid': True}, '272ec473-6041-42ee-bd1a-732789dd18d4': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000206051', 'lastCheck': '8.7', 'valid': True}}
>Thread-63529::DEBUG::2014-06-05 09:25:39,760::task::595::TaskManager.Task::(_updateState) Task=`442197c4-4efc-4bee-bb98-18aab59f9cf6`::moving from state preparing -> state finished
>Thread-63529::DEBUG::2014-06-05 09:25:39,760::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-63529::DEBUG::2014-06-05 09:25:39,760::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-63529::DEBUG::2014-06-05 09:25:39,760::task::990::TaskManager.Task::(_decref) Task=`442197c4-4efc-4bee-bb98-18aab59f9cf6`::ref 0 aborting False
>Thread-63529::DEBUG::2014-06-05 09:25:39,799::vm::645::vm.Vm::(_getDiskStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk hdc stats not available
>Thread-63529::DEBUG::2014-06-05 09:25:39,799::vm::645::vm.Vm::(_getDiskStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk vda stats not available
>Thread-63529::DEBUG::2014-06-05 09:25:39,799::vm::684::vm.Vm::(_getDiskLatency) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk hdc latency not available
>Thread-63529::DEBUG::2014-06-05 09:25:39,799::vm::684::vm.Vm::(_getDiskLatency) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk vda latency not available
>Thread-19::DEBUG::2014-06-05 09:25:40,864::domainMonitor::192::Storage.DomainMonitorThread::(_monitorDomain) Refreshing domain 2c51d320-88ce-4f23-8215-e15f55f66906
>Thread-19::DEBUG::2014-06-05 09:25:40,877::fileSD::150::Storage.StorageDomain::(__init__) Reading domain in path /rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtIB/2c51d320-88ce-4f23-8215-e15f55f66906
>Thread-19::DEBUG::2014-06-05 09:25:40,878::persistentDict::192::Storage.PersistentDict::(__init__) Created a persistent dict with FileMetadataRW backend
>Thread-19::DEBUG::2014-06-05 09:25:40,884::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=colnas03_IB', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=3', 'POOL_DESCRIPTION=Collogia', 'POOL_DOMAINS=272ec473-6041-42ee-bd1a-732789dd18d4:Active,965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545:Active,2c51d320-88ce-4f23-8215-e15f55f66906:Active,63041fa9-e093-4b44-b36f-f39f16d3974f:Active,bff3a2be-fdd9-4e37-b416-fa4ef7fafba2:Active', 'POOL_SPM_ID=4', 'POOL_SPM_LVER=1', 'POOL_UUID=94ed7a19-fade-4bd6-83f2-2cbb2f730b95', 'REMOTE_PATH=10.10.30.253:/var/nas3/OVirtIB', 'ROLE=Master', 'SDUUID=2c51d320-88ce-4f23-8215-e15f55f66906', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=97f4583421c0b9df2159556471857e406bb3a50c']
>Thread-19::DEBUG::2014-06-05 09:25:40,886::fileSD::609::Storage.StorageDomain::(imageGarbageCollector) Removing remnants of deleted images []
>Thread-19::INFO::2014-06-05 09:25:40,886::sd::383::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace 2c51d320-88ce-4f23-8215-e15f55f66906_imageNS already registered
>Thread-19::INFO::2014-06-05 09:25:40,886::sd::391::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace 2c51d320-88ce-4f23-8215-e15f55f66906_volumeNS already registered
>Thread-19::DEBUG::2014-06-05 09:25:40,899::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtIB/2c51d320-88ce-4f23-8215-e15f55f66906/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-19::DEBUG::2014-06-05 09:25:40,908::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n644 bytes (644 B) copied, 0.000195794 s, 3.3 MB/s\n'; <rc> = 0
>Thread-27::DEBUG::2014-06-05 09:25:41,041::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtEXP/63041fa9-e093-4b44-b36f-f39f16d3974f/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-27::DEBUG::2014-06-05 09:25:41,048::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n363 bytes (363 B) copied, 0.000239555 s, 1.5 MB/s\n'; <rc> = 0
>Thread-32::DEBUG::2014-06-05 09:25:41,061::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.252:_var_nas2_OVirtIB/272ec473-6041-42ee-bd1a-732789dd18d4/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-32::DEBUG::2014-06-05 09:25:41,069::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n557 bytes (557 B) copied, 0.000214012 s, 2.6 MB/s\n'; <rc> = 0
>Thread-21::DEBUG::2014-06-05 09:25:42,567::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd iflag=direct if=/rhev/data-center/mnt/10.10.30.253:_var_nas3_OVirtISO/bff3a2be-fdd9-4e37-b416-fa4ef7fafba2/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-21::DEBUG::2014-06-05 09:25:42,575::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n357 bytes (357 B) copied, 0.000238642 s, 1.5 MB/s\n'; <rc> = 0
>GuestMonitor-colvm36::DEBUG::2014-06-05 09:25:43,322::vm::645::vm.Vm::(_getDiskStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk hdc stats not available
>GuestMonitor-colvm36::DEBUG::2014-06-05 09:25:43,323::vm::645::vm.Vm::(_getDiskStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk vda stats not available
>GuestMonitor-colvm36::DEBUG::2014-06-05 09:25:43,323::vm::684::vm.Vm::(_getDiskLatency) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk hdc latency not available
>GuestMonitor-colvm36::DEBUG::2014-06-05 09:25:43,323::vm::684::vm.Vm::(_getDiskLatency) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk vda latency not available
>GuestMonitor-colvm36::DEBUG::2014-06-05 09:25:43,324::vm::645::vm.Vm::(_getDiskStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk hdc stats not available
>GuestMonitor-colvm36::DEBUG::2014-06-05 09:25:43,325::vm::645::vm.Vm::(_getDiskStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk vda stats not available
>GuestMonitor-colvm36::DEBUG::2014-06-05 09:25:43,325::vm::684::vm.Vm::(_getDiskLatency) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk hdc latency not available
>GuestMonitor-colvm36::DEBUG::2014-06-05 09:25:43,325::vm::684::vm.Vm::(_getDiskLatency) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk vda latency not available

Actions: View

Attachments on bug 1104697: 902192 | 902193 | 902418 | 902559 | 902561 | 907289 | 908784 | 908785