Attachment 907354 Details for Bug 1107835 – vdsm.log

vdsm.log

vdsm.mst.log (text/plain), 98.94 KB, created by Markus Stockhausen on 2014-06-10 18:28:33 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: Markus Stockhausen

Created: 2014-06-10 18:28:33 UTC

Size: 98.94 KB

patch

obsolete

>Thread-13::INFO::2014-06-10 20:24:16,520::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'2c51d320-88ce-4f23-8215-e15f55f66906': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.00036835', 'lastCheck': '2.5', 'valid': True}, '965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.0018198', 'lastCheck': '2.1', 'valid': True}, 'bff3a2be-fdd9-4e37-b416-fa4ef7fafba2': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.00214507', 'lastCheck': '5.9', 'valid': True}, '63041fa9-e093-4b44-b36f-f39f16d3974f': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.00750344', 'lastCheck': '4.5', 'valid': True}, '272ec473-6041-42ee-bd1a-732789dd18d4': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000206186', 'lastCheck': '1.8', 'valid': True}}
>Thread-13::DEBUG::2014-06-10 20:24:16,521::task::1185::TaskManager.Task::(prepare) Task=`6f278411-362f-4807-9feb-c2fe15f08117`::finished: {'2c51d320-88ce-4f23-8215-e15f55f66906': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.00036835', 'lastCheck': '2.5', 'valid': True}, '965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.0018198', 'lastCheck': '2.1', 'valid': True}, 'bff3a2be-fdd9-4e37-b416-fa4ef7fafba2': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.00214507', 'lastCheck': '5.9', 'valid': True}, '63041fa9-e093-4b44-b36f-f39f16d3974f': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.00750344', 'lastCheck': '4.5', 'valid': True}, '272ec473-6041-42ee-bd1a-732789dd18d4': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000206186', 'lastCheck': '1.8', 'valid': True}}
>Thread-13::DEBUG::2014-06-10 20:24:16,521::task::595::TaskManager.Task::(_updateState) Task=`6f278411-362f-4807-9feb-c2fe15f08117`::moving from state preparing -> state finished
>Thread-13::DEBUG::2014-06-10 20:24:16,521::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-13::DEBUG::2014-06-10 20:24:16,521::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-13::DEBUG::2014-06-10 20:24:16,521::task::990::TaskManager.Task::(_decref) Task=`6f278411-362f-4807-9feb-c2fe15f08117`::ref 0 aborting False
>Thread-21::DEBUG::2014-06-10 20:24:20,657::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-10 20:24:20,665::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n357 bytes (357 B) copied, 0.000955792 s, 374 kB/s\n'; <rc> = 0
>Thread-26::DEBUG::2014-06-10 20:24:22,022::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-26::DEBUG::2014-06-10 20:24:22,035::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n363 bytes (363 B) copied, 0.006099 s, 59.5 kB/s\n'; <rc> = 0
>Thread-19::DEBUG::2014-06-10 20:24:24,018::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-10 20:24:24,025::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n644 bytes (644 B) copied, 0.000417493 s, 1.5 MB/s\n'; <rc> = 0
>Thread-20::DEBUG::2014-06-10 20:24:24,401::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-10 20:24:24,409::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n557 bytes (557 B) copied, 0.000838349 s, 664 kB/s\n'; <rc> = 0
>Thread-33::DEBUG::2014-06-10 20:24:24,742::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-33::DEBUG::2014-06-10 20:24:24,749::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n557 bytes (557 B) copied, 0.000560353 s, 994 kB/s\n'; <rc> = 0
>Thread-7283::DEBUG::2014-06-10 20:24:27,837::BindingXMLRPC::1067::vds::(wrapper) client [192.168.11.42]::call vmGetStats with ('803870d2-e365-4ab4-bdcc-4c1d25a03944',) {}
>Thread-7283::DEBUG::2014-06-10 20:24:27,837::BindingXMLRPC::1074::vds::(wrapper) return vmGetStats with {'status': {'message': 'Virtual machine does not exist', 'code': 1}}
>Thread-7284::DEBUG::2014-06-10 20:24:27,889::BindingXMLRPC::1067::vds::(wrapper) client [192.168.11.42]::call vmMigrationCreate with ({'username': 'Unknown', 'acpiEnable': 'true', 'emulatedMachine': 'pc-1.0', 'afterMigrationStatus': '', 'guestFQDN': '', 'vmId': '803870d2-e365-4ab4-bdcc-4c1d25a03944', 'memGuaranteedSize': 2048, 'transparentHugePages': 'true', 'displaySecurePort': '5900', 'timeOffset': '10770', 'cpuType': 'Nehalem', 'custom': {'device_27b30e7a-1d68-4850-bdac-7867f017b422device_59f41dec-1a72-4898-bd62-2f851b66e1aadevice_6f95c5f0-91a1-46f4-9d4d-8a14559e357fdevice_bbb7f170-ca8d-453b-83ac-75244498d6ad': 'VmDevice {vmId=803870d2-e365-4ab4-bdcc-4c1d25a03944, deviceId=bbb7f170-ca8d-453b-83ac-75244498d6ad, 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_27b30e7a-1d68-4850-bdac-7867f017b422device_59f41dec-1a72-4898-bd62-2f851b66e1aa': 'VmDevice {vmId=803870d2-e365-4ab4-bdcc-4c1d25a03944, deviceId=59f41dec-1a72-4898-bd62-2f851b66e1aa, device=virtio-serial, type=CONTROLLER, bootOrder=0, specParams={}, address={bus=0x00, domain=0x0000, type=pci, slot=0x03, function=0x0}, managed=false, plugged=true, readOnly=false, deviceAlias=virtio-serial0, customProperties={}, snapshotId=null}', 'device_27b30e7a-1d68-4850-bdac-7867f017b422device_59f41dec-1a72-4898-bd62-2f851b66e1aadevice_6f95c5f0-91a1-46f4-9d4d-8a14559e357f': 'VmDevice {vmId=803870d2-e365-4ab4-bdcc-4c1d25a03944, deviceId=6f95c5f0-91a1-46f4-9d4d-8a14559e357f, 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_27b30e7a-1d68-4850-bdac-7867f017b422device_59f41dec-1a72-4898-bd62-2f851b66e1aadevice_6f95c5f0-91a1-46f4-9d4d-8a14559e357fdevice_bbb7f170-ca8d-453b-83ac-75244498d6addevice_ee66c5ab-3eb8-4e7b-bb54-da9bdcedc24c': 'VmDevice {vmId=803870d2-e365-4ab4-bdcc-4c1d25a03944, deviceId=ee66c5ab-3eb8-4e7b-bb54-da9bdcedc24c, 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_27b30e7a-1d68-4850-bdac-7867f017b422': 'VmDevice {vmId=803870d2-e365-4ab4-bdcc-4c1d25a03944, deviceId=27b30e7a-1d68-4850-bdac-7867f017b422, 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}'}, 'migrationDest': 'libvirt', 'smp': '2', 'vmType': 'kvm', 'spiceSslCipherSuite': 'DEFAULT', '_srcDomXML': "<domain type='kvm' id='35' 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='160' cores='1' threads='1'/>\n  </cpu>\n  <clock offset='variable' adjustment='7170' 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='vnet0'/>\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='5900' autoport='yes' listen='0' keymap='de' passwdValidTo='2014-06-10T18:25:44' connected='keep'>\n      <listen type='address' address='0'/>\n      <channel name='main' mode='secure'/>\n      <channel name='display' mode='secure'/>\n      <channel name='inputs' mode='secure'/>\n      <channel name='cursor' mode='secure'/>\n      <channel name='playback' mode='secure'/>\n      <channel name='record' mode='secure'/>\n      <channel name='smartcard' mode='secure'/>\n      <channel name='usbredir' mode='secure'/>\n    </graphics>\n    <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='none'>\n      <alias name='balloon0'/>\n    </memballoon>\n  </devices>\n  <seclabel type='dynamic' model='selinux' relabel='yes'>\n    <label>system_u:system_r:svirt_t:s0:c95,c819</label>\n    <imagelabel>system_u:object_r:svirt_image_t:s0:c95,c819</imagelabel>\n  </seclabel>\n  <qemu:commandline>\n    <qemu:env name='SPICE_DEBUG_ALLOW_MC' value='1'/>\n  </qemu:commandline>\n</domain>\n", 'memSize': 3072, 'elapsedTimeOffset': 646.4357590675354, 'vmName': 'colvm36', 'nice': '0', 'status': 'Up', 'displayIp': '0', 'displayPort': '-1', 'smpCoresPerSocket': '1', 'smartcardEnable': 'false', 'guestIPs': '', 'nicModel': 'rtl8139,pv', 'keyboardLayout': 'de', 'kvmEnable': 'true', 'spiceSecureChannels': 'smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard', 'devices': [{'specParams': {}, 'alias': 'sound0', 'deviceId': '474bd71a-d040-4b6c-9262-b2e1840aa446', 'address': {'slot': '0x04', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'ac97', 'type': 'sound'}, {'device': 'memballoon', 'specParams': {'model': 'none'}, 'type': 'balloon', 'target': 3145728, 'alias': 'balloon0'}, {'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': '6547c5ca-f1ac-4943-95dc-e0835d7db296', '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': 'vnet0'}, {'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', 'clientIp': '', 'display': 'qxl'},) {}
>Thread-7284::DEBUG::2014-06-10 20:24:27,889::API::523::vds::(migrationCreate) Migration create
>Thread-7284::INFO::2014-06-10 20:24:27,893::API::668::vds::(_getNetworkIp) network None: using 0
>Thread-7284::INFO::2014-06-10 20:24:27,893::clientIF::366::vds::(createVm) vmContainerLock acquired by vm 803870d2-e365-4ab4-bdcc-4c1d25a03944
>Thread-7284::DEBUG::2014-06-10 20:24:27,898::clientIF::379::vds::(createVm) Total desktops after creation of 803870d2-e365-4ab4-bdcc-4c1d25a03944 is 1
>Thread-7285::DEBUG::2014-06-10 20:24:27,898::vm::2238::vm.Vm::(_startUnderlyingVm) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Start
>Thread-7284::DEBUG::2014-06-10 20:24:27,898::vm::5236::vm.Vm::(waitForMigrationDestinationPrepare) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::migration destination: waiting for VM creation
>Thread-7285::DEBUG::2014-06-10 20:24:27,898::vm::2242::vm.Vm::(_startUnderlyingVm) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::_ongoingCreations acquired
>Thread-7285::INFO::2014-06-10 20:24:27,898::vm::3112::vm.Vm::(_run) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::VM wrapper has started
>Thread-7284::DEBUG::2014-06-10 20:24:27,898::vm::5241::vm.Vm::(waitForMigrationDestinationPrepare) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::migration destination: waiting 36s for path preparation
>Thread-7285::WARNING::2014-06-10 20:24:27,899::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-7285::WARNING::2014-06-10 20:24:27,899::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-7285::WARNING::2014-06-10 20:24:27,899::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-7285::DEBUG::2014-06-10 20:24:27,900::task::595::TaskManager.Task::(_updateState) Task=`1b4b6b71-c9c4-4283-9697-8e7f65ec4f3d`::moving from state init -> state preparing
>Thread-7285::INFO::2014-06-10 20:24:27,900::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-7285::INFO::2014-06-10 20:24:27,902::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '27380420608', 'apparentsize': '26863764480'}
>Thread-7285::DEBUG::2014-06-10 20:24:27,902::task::1185::TaskManager.Task::(prepare) Task=`1b4b6b71-c9c4-4283-9697-8e7f65ec4f3d`::finished: {'truesize': '27380420608', 'apparentsize': '26863764480'}
>Thread-7285::DEBUG::2014-06-10 20:24:27,902::task::595::TaskManager.Task::(_updateState) Task=`1b4b6b71-c9c4-4283-9697-8e7f65ec4f3d`::moving from state preparing -> state finished
>Thread-7285::DEBUG::2014-06-10 20:24:27,903::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-7285::DEBUG::2014-06-10 20:24:27,903::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-7285::DEBUG::2014-06-10 20:24:27,903::task::990::TaskManager.Task::(_decref) Task=`1b4b6b71-c9c4-4283-9697-8e7f65ec4f3d`::ref 0 aborting False
>Thread-7285::INFO::2014-06-10 20:24:27,903::clientIF::324::vds::(prepareVolumePath) prepared volume path: 
>Thread-7285::DEBUG::2014-06-10 20:24:27,903::task::595::TaskManager.Task::(_updateState) Task=`7fbbfcf9-a34d-4017-a990-01a6cd42d18c`::moving from state init -> state preparing
>Thread-7285::INFO::2014-06-10 20:24:27,903::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-7285::DEBUG::2014-06-10 20:24:27,905::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.272ec473-6041-42ee-bd1a-732789dd18d4`ReqID=`2ba5bfae-359d-403d-bb97-0e5d5ca9a4e8`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '3238' at 'prepareImage'
>Thread-7285::DEBUG::2014-06-10 20:24:27,905::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.272ec473-6041-42ee-bd1a-732789dd18d4' for lock type 'shared'
>Thread-7285::DEBUG::2014-06-10 20:24:27,905::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.272ec473-6041-42ee-bd1a-732789dd18d4' is free. Now locking as 'shared' (1 active user)
>Thread-7285::DEBUG::2014-06-10 20:24:27,905::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.272ec473-6041-42ee-bd1a-732789dd18d4`ReqID=`2ba5bfae-359d-403d-bb97-0e5d5ca9a4e8`::Granted request
>Thread-7285::DEBUG::2014-06-10 20:24:27,905::task::827::TaskManager.Task::(resourceAcquired) Task=`7fbbfcf9-a34d-4017-a990-01a6cd42d18c`::_resourcesAcquired: Storage.272ec473-6041-42ee-bd1a-732789dd18d4 (shared)
>Thread-7285::DEBUG::2014-06-10 20:24:27,905::task::990::TaskManager.Task::(_decref) Task=`7fbbfcf9-a34d-4017-a990-01a6cd42d18c`::ref 1 aborting False
>Thread-7285::WARNING::2014-06-10 20:24:27,907::fileUtils::167::Storage.fileUtils::(createdir) Dir /var/run/vdsm/storage/272ec473-6041-42ee-bd1a-732789dd18d4 already exists
>Thread-7285::DEBUG::2014-06-10 20:24:27,907::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-7285::DEBUG::2014-06-10 20:24:27,908::fileVolume::529::Storage.Volume::(validateVolumePath) validate path for 04b45378-e7b8-4488-b48a-6b3fac1f18a4
>Thread-7285::INFO::2014-06-10 20:24:27,910::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-7285::DEBUG::2014-06-10 20:24:27,910::task::1185::TaskManager.Task::(prepare) Task=`7fbbfcf9-a34d-4017-a990-01a6cd42d18c`::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-7285::DEBUG::2014-06-10 20:24:27,910::task::595::TaskManager.Task::(_updateState) Task=`7fbbfcf9-a34d-4017-a990-01a6cd42d18c`::moving from state preparing -> state finished
>Thread-7285::DEBUG::2014-06-10 20:24:27,910::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-7285::DEBUG::2014-06-10 20:24:27,910::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-7285::DEBUG::2014-06-10 20:24:27,910::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.272ec473-6041-42ee-bd1a-732789dd18d4'
>Thread-7285::DEBUG::2014-06-10 20:24:27,911::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.272ec473-6041-42ee-bd1a-732789dd18d4' (0 active users)
>Thread-7285::DEBUG::2014-06-10 20:24:27,911::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.272ec473-6041-42ee-bd1a-732789dd18d4' is free, finding out if anyone is waiting for it.
>Thread-7285::DEBUG::2014-06-10 20:24:27,911::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.272ec473-6041-42ee-bd1a-732789dd18d4', Clearing records.
>Thread-7285::DEBUG::2014-06-10 20:24:27,911::task::990::TaskManager.Task::(_decref) Task=`7fbbfcf9-a34d-4017-a990-01a6cd42d18c`::ref 0 aborting False
>Thread-7285::INFO::2014-06-10 20:24:27,911::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-7285::DEBUG::2014-06-10 20:24:27,915::vm::2259::vm.Vm::(_startUnderlyingVm) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::_ongoingCreations released
>Thread-7285::DEBUG::2014-06-10 20:24:27,923::vm::3697::vm.Vm::(_waitForIncomingMigrationFinish) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Waiting 21600 seconds for end of migration
>Thread-7284::DEBUG::2014-06-10 20:24:27,924::API::536::vds::(migrationCreate) Destination VM creation succeeded
>Thread-7284::DEBUG::2014-06-10 20:24:27,924::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': '10770', 'cpuType': 'Nehalem', 'smp': '2', 'migrationDest': 'libvirt', 'custom': {'device_27b30e7a-1d68-4850-bdac-7867f017b422device_59f41dec-1a72-4898-bd62-2f851b66e1aadevice_6f95c5f0-91a1-46f4-9d4d-8a14559e357fdevice_bbb7f170-ca8d-453b-83ac-75244498d6ad': 'VmDevice {vmId=803870d2-e365-4ab4-bdcc-4c1d25a03944, deviceId=bbb7f170-ca8d-453b-83ac-75244498d6ad, 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_27b30e7a-1d68-4850-bdac-7867f017b422device_59f41dec-1a72-4898-bd62-2f851b66e1aa': 'VmDevice {vmId=803870d2-e365-4ab4-bdcc-4c1d25a03944, deviceId=59f41dec-1a72-4898-bd62-2f851b66e1aa, device=virtio-serial, type=CONTROLLER, bootOrder=0, specParams={}, address={bus=0x00, domain=0x0000, type=pci, slot=0x03, function=0x0}, managed=false, plugged=true, readOnly=false, deviceAlias=virtio-serial0, customProperties={}, snapshotId=null}', 'device_27b30e7a-1d68-4850-bdac-7867f017b422device_59f41dec-1a72-4898-bd62-2f851b66e1aadevice_6f95c5f0-91a1-46f4-9d4d-8a14559e357f': 'VmDevice {vmId=803870d2-e365-4ab4-bdcc-4c1d25a03944, deviceId=6f95c5f0-91a1-46f4-9d4d-8a14559e357f, 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_27b30e7a-1d68-4850-bdac-7867f017b422device_59f41dec-1a72-4898-bd62-2f851b66e1aadevice_6f95c5f0-91a1-46f4-9d4d-8a14559e357fdevice_bbb7f170-ca8d-453b-83ac-75244498d6addevice_ee66c5ab-3eb8-4e7b-bb54-da9bdcedc24c': 'VmDevice {vmId=803870d2-e365-4ab4-bdcc-4c1d25a03944, deviceId=ee66c5ab-3eb8-4e7b-bb54-da9bdcedc24c, 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_27b30e7a-1d68-4850-bdac-7867f017b422': 'VmDevice {vmId=803870d2-e365-4ab4-bdcc-4c1d25a03944, deviceId=27b30e7a-1d68-4850-bdac-7867f017b422, 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}'}, 'vmType': 'kvm', 'spiceSslCipherSuite': 'DEFAULT', 'memSize': 3072, 'vmName': 'colvm36', 'nice': '0', 'username': 'Unknown', 'clientIp': '', 'vmId': '803870d2-e365-4ab4-bdcc-4c1d25a03944', 'displayIp': '0', 'keyboardLayout': 'de', 'displayPort': '-1', 'smartcardEnable': 'false', 'spiceSecureChannels': 'smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard', 'nicModel': 'rtl8139,pv', 'smpCoresPerSocket': '1', 'kvmEnable': 'true', 'devices': [{'specParams': {}, 'alias': 'sound0', 'deviceId': '474bd71a-d040-4b6c-9262-b2e1840aa446', 'address': {'slot': '0x04', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'ac97', 'type': 'sound'}, {'device': 'memballoon', 'specParams': {'model': 'none'}, 'type': 'balloon', 'target': 3145728, 'alias': 'balloon0'}, {'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': '6547c5ca-f1ac-4943-95dc-e0835d7db296', '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': 'vnet0'}, {'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', 'guestIPs': '', 'display': 'qxl'}}
>libvirtEventLoop::DEBUG::2014-06-10 20:24:28,406::vm::5151::vm.Vm::(_onLibvirtLifecycleEvent) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::event Started detail 1 opaque None
>Thread-13::DEBUG::2014-06-10 20:24:28,632::BindingXMLRPC::1067::vds::(wrapper) client [192.168.11.2]::call vmGetStats with ('803870d2-e365-4ab4-bdcc-4c1d25a03944',) {} flowID [369628]
>Thread-13::DEBUG::2014-06-10 20:24:28,633::BindingXMLRPC::1074::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Migration Destination', 'hash': '0', 'acpiEnable': 'true', 'pid': '0', 'displayIp': '0', 'displayPort': '-1', 'displaySecurePort': '-1', 'timeOffset': '10770', 'kvmEnable': 'true', 'network': {}, 'vmId': '803870d2-e365-4ab4-bdcc-4c1d25a03944', 'displayType': 'qxl', 'disks': {}, 'monitorResponse': '0', 'elapsedTime': '647', 'vmType': 'kvm', 'clientIp': ''}]}
>Thread-21::DEBUG::2014-06-10 20:24:30,674::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-10 20:24:30,682::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n357 bytes (357 B) copied, 0.000543093 s, 657 kB/s\n'; <rc> = 0
>Thread-13::DEBUG::2014-06-10 20:24:31,659::task::595::TaskManager.Task::(_updateState) Task=`dc34dc0b-c719-4cfe-a9bd-63be06057820`::moving from state init -> state preparing
>Thread-13::INFO::2014-06-10 20:24:31,659::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-13::INFO::2014-06-10 20:24:31,660::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'2c51d320-88ce-4f23-8215-e15f55f66906': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000417493', 'lastCheck': '7.6', 'valid': True}, '965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000838349', 'lastCheck': '7.2', 'valid': True}, 'bff3a2be-fdd9-4e37-b416-fa4ef7fafba2': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000543093', 'lastCheck': '1.0', 'valid': True}, '63041fa9-e093-4b44-b36f-f39f16d3974f': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.006099', 'lastCheck': '9.6', 'valid': True}, '272ec473-6041-42ee-bd1a-732789dd18d4': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000560353', 'lastCheck': '6.9', 'valid': True}}
>Thread-13::DEBUG::2014-06-10 20:24:31,660::task::1185::TaskManager.Task::(prepare) Task=`dc34dc0b-c719-4cfe-a9bd-63be06057820`::finished: {'2c51d320-88ce-4f23-8215-e15f55f66906': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000417493', 'lastCheck': '7.6', 'valid': True}, '965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000838349', 'lastCheck': '7.2', 'valid': True}, 'bff3a2be-fdd9-4e37-b416-fa4ef7fafba2': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000543093', 'lastCheck': '1.0', 'valid': True}, '63041fa9-e093-4b44-b36f-f39f16d3974f': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.006099', 'lastCheck': '9.6', 'valid': True}, '272ec473-6041-42ee-bd1a-732789dd18d4': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000560353', 'lastCheck': '6.9', 'valid': True}}
>Thread-13::DEBUG::2014-06-10 20:24:31,660::task::595::TaskManager.Task::(_updateState) Task=`dc34dc0b-c719-4cfe-a9bd-63be06057820`::moving from state preparing -> state finished
>Thread-13::DEBUG::2014-06-10 20:24:31,660::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-13::DEBUG::2014-06-10 20:24:31,660::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-13::DEBUG::2014-06-10 20:24:31,661::task::990::TaskManager.Task::(_decref) Task=`dc34dc0b-c719-4cfe-a9bd-63be06057820`::ref 0 aborting False
>Thread-26::DEBUG::2014-06-10 20:24:32,046::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-26::DEBUG::2014-06-10 20:24:32,058::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n363 bytes (363 B) copied, 0.00354833 s, 102 kB/s\n'; <rc> = 0
>Thread-19::DEBUG::2014-06-10 20:24:34,042::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-10 20:24:34,051::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n644 bytes (644 B) copied, 0.000303911 s, 2.1 MB/s\n'; <rc> = 0
>Thread-20::DEBUG::2014-06-10 20:24:34,421::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-10 20:24:34,474::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n557 bytes (557 B) copied, 0.00175465 s, 317 kB/s\n'; <rc> = 0
>Thread-13::DEBUG::2014-06-10 20:24:34,748::BindingXMLRPC::1067::vds::(wrapper) client [192.168.11.2]::call vmGetStats with ('803870d2-e365-4ab4-bdcc-4c1d25a03944',) {} flowID [271a978a]
>Thread-13::DEBUG::2014-06-10 20:24:34,748::BindingXMLRPC::1074::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Migration Destination', 'hash': '0', 'acpiEnable': 'true', 'pid': '0', 'displayIp': '0', 'displayPort': '-1', 'displaySecurePort': '-1', 'timeOffset': '10770', 'kvmEnable': 'true', 'network': {}, 'vmId': '803870d2-e365-4ab4-bdcc-4c1d25a03944', 'displayType': 'qxl', 'disks': {}, 'monitorResponse': '0', 'elapsedTime': '653', 'vmType': 'kvm', 'clientIp': ''}]}
>Thread-33::DEBUG::2014-06-10 20:24:34,761::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-33::DEBUG::2014-06-10 20:24:34,772::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n557 bytes (557 B) copied, 0.00355766 s, 157 kB/s\n'; <rc> = 0
>Thread-13::DEBUG::2014-06-10 20:24:37,777::BindingXMLRPC::1067::vds::(wrapper) client [192.168.11.2]::call vmGetStats with ('803870d2-e365-4ab4-bdcc-4c1d25a03944',) {} flowID [6fb1e89e]
>Thread-13::DEBUG::2014-06-10 20:24:37,777::BindingXMLRPC::1074::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Migration Destination', 'hash': '0', 'acpiEnable': 'true', 'pid': '0', 'displayIp': '0', 'displayPort': '-1', 'displaySecurePort': '-1', 'timeOffset': '10770', 'kvmEnable': 'true', 'network': {}, 'vmId': '803870d2-e365-4ab4-bdcc-4c1d25a03944', 'displayType': 'qxl', 'disks': {}, 'monitorResponse': '0', 'elapsedTime': '656', 'vmType': 'kvm', 'clientIp': ''}]}
>Thread-21::DEBUG::2014-06-10 20:24:40,694::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-10 20:24:40,704::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n357 bytes (357 B) copied, 0.00143282 s, 249 kB/s\n'; <rc> = 0
>Thread-13::DEBUG::2014-06-10 20:24:40,810::BindingXMLRPC::1067::vds::(wrapper) client [192.168.11.2]::call vmGetStats with ('803870d2-e365-4ab4-bdcc-4c1d25a03944',) {} flowID [8b65f64]
>Thread-13::DEBUG::2014-06-10 20:24:40,810::BindingXMLRPC::1074::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Migration Destination', 'hash': '0', 'acpiEnable': 'true', 'pid': '0', 'displayIp': '0', 'displayPort': '-1', 'displaySecurePort': '-1', 'timeOffset': '10770', 'kvmEnable': 'true', 'network': {}, 'vmId': '803870d2-e365-4ab4-bdcc-4c1d25a03944', 'displayType': 'qxl', 'disks': {}, 'monitorResponse': '0', 'elapsedTime': '659', 'vmType': 'kvm', 'clientIp': ''}]}
>Thread-26::DEBUG::2014-06-10 20:24:42,068::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-26::DEBUG::2014-06-10 20:24:42,080::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n363 bytes (363 B) copied, 0.00127959 s, 284 kB/s\n'; <rc> = 0
>Thread-13::DEBUG::2014-06-10 20:24:43,840::BindingXMLRPC::1067::vds::(wrapper) client [192.168.11.2]::call vmGetStats with ('803870d2-e365-4ab4-bdcc-4c1d25a03944',) {} flowID [360cd320]
>Thread-13::DEBUG::2014-06-10 20:24:43,840::BindingXMLRPC::1074::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Migration Destination', 'hash': '0', 'acpiEnable': 'true', 'pid': '0', 'displayIp': '0', 'displayPort': '-1', 'displaySecurePort': '-1', 'timeOffset': '10770', 'kvmEnable': 'true', 'network': {}, 'vmId': '803870d2-e365-4ab4-bdcc-4c1d25a03944', 'displayType': 'qxl', 'disks': {}, 'monitorResponse': '0', 'elapsedTime': '662', 'vmType': 'kvm', 'clientIp': ''}]}
>Thread-19::DEBUG::2014-06-10 20:24:44,065::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-10 20:24:44,073::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n644 bytes (644 B) copied, 0.000300663 s, 2.1 MB/s\n'; <rc> = 0
>Thread-20::DEBUG::2014-06-10 20:24:44,486::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-10 20:24:44,494::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n557 bytes (557 B) copied, 0.000220531 s, 2.5 MB/s\n'; <rc> = 0
>Thread-33::DEBUG::2014-06-10 20:24:44,784::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-33::DEBUG::2014-06-10 20:24:44,793::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n557 bytes (557 B) copied, 0.00118447 s, 470 kB/s\n'; <rc> = 0
>Thread-13::DEBUG::2014-06-10 20:24:46,873::task::595::TaskManager.Task::(_updateState) Task=`e733873b-3e63-4cec-a535-cffbaa983952`::moving from state init -> state preparing
>Thread-13::INFO::2014-06-10 20:24:46,873::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-13::INFO::2014-06-10 20:24:46,874::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'2c51d320-88ce-4f23-8215-e15f55f66906': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000300663', 'lastCheck': '2.8', 'valid': True}, '965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000220531', 'lastCheck': '2.4', 'valid': True}, 'bff3a2be-fdd9-4e37-b416-fa4ef7fafba2': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.00143282', 'lastCheck': '6.2', 'valid': True}, '63041fa9-e093-4b44-b36f-f39f16d3974f': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.00127959', 'lastCheck': '4.8', 'valid': True}, '272ec473-6041-42ee-bd1a-732789dd18d4': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.00118447', 'lastCheck': '2.1', 'valid': True}}
>Thread-13::DEBUG::2014-06-10 20:24:46,874::task::1185::TaskManager.Task::(prepare) Task=`e733873b-3e63-4cec-a535-cffbaa983952`::finished: {'2c51d320-88ce-4f23-8215-e15f55f66906': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000300663', 'lastCheck': '2.8', 'valid': True}, '965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000220531', 'lastCheck': '2.4', 'valid': True}, 'bff3a2be-fdd9-4e37-b416-fa4ef7fafba2': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.00143282', 'lastCheck': '6.2', 'valid': True}, '63041fa9-e093-4b44-b36f-f39f16d3974f': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.00127959', 'lastCheck': '4.8', 'valid': True}, '272ec473-6041-42ee-bd1a-732789dd18d4': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.00118447', 'lastCheck': '2.1', 'valid': True}}
>Thread-13::DEBUG::2014-06-10 20:24:46,874::task::595::TaskManager.Task::(_updateState) Task=`e733873b-3e63-4cec-a535-cffbaa983952`::moving from state preparing -> state finished
>Thread-13::DEBUG::2014-06-10 20:24:46,874::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-13::DEBUG::2014-06-10 20:24:46,874::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-13::DEBUG::2014-06-10 20:24:46,875::task::990::TaskManager.Task::(_decref) Task=`e733873b-3e63-4cec-a535-cffbaa983952`::ref 0 aborting False
>Thread-13::DEBUG::2014-06-10 20:24:49,946::BindingXMLRPC::1067::vds::(wrapper) client [192.168.11.2]::call vmGetStats with ('803870d2-e365-4ab4-bdcc-4c1d25a03944',) {} flowID [1ca7c558]
>Thread-13::DEBUG::2014-06-10 20:24:49,947::BindingXMLRPC::1074::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Migration Destination', 'hash': '0', 'acpiEnable': 'true', 'pid': '0', 'displayIp': '0', 'displayPort': '-1', 'displaySecurePort': '-1', 'timeOffset': '10770', 'kvmEnable': 'true', 'network': {}, 'vmId': '803870d2-e365-4ab4-bdcc-4c1d25a03944', 'displayType': 'qxl', 'disks': {}, 'monitorResponse': '0', 'elapsedTime': '668', 'vmType': 'kvm', 'clientIp': ''}]}
>libvirtEventLoop::DEBUG::2014-06-10 20:24:50,032::vm::5151::vm.Vm::(_onLibvirtLifecycleEvent) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::event Resumed detail 0 opaque None
>libvirtEventLoop::DEBUG::2014-06-10 20:24:50,033::vm::5151::vm.Vm::(_onLibvirtLifecycleEvent) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::event Resumed detail 1 opaque None
>Thread-7285::DEBUG::2014-06-10 20:24:50,055::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-7285::DEBUG::2014-06-10 20:24:50,055::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-7285::DEBUG::2014-06-10 20:24:50,056::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-7285::DEBUG::2014-06-10 20:24:50,056::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 0x7f9d282949e0>], '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-7285::DEBUG::2014-06-10 20:24:50,056::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 0x7f9d282949e0>], 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-7285::DEBUG::2014-06-10 20:24:50,057::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 0x7f9d282949e0>], 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-7285::DEBUG::2014-06-10 20:24:50,105::sampling::285::vm.Vm::(start) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Start statistics collection
>Thread-7287::DEBUG::2014-06-10 20:24:50,106::sampling::314::vm.Vm::(run) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Stats thread started
>Thread-7287::DEBUG::2014-06-10 20:24:50,107::task::595::TaskManager.Task::(_updateState) Task=`a4529ad1-da70-4fca-8942-ea341f4e963b`::moving from state init -> state preparing
>Thread-7287::INFO::2014-06-10 20:24:50,107::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-7285::DEBUG::2014-06-10 20:24:50,108::vmChannels::194::vds::(register) Add fileno 72 to listener's channels.
>Thread-7287::INFO::2014-06-10 20:24:50,109::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '27380420608', 'apparentsize': '26863764480'}
>Thread-7287::DEBUG::2014-06-10 20:24:50,109::task::1185::TaskManager.Task::(prepare) Task=`a4529ad1-da70-4fca-8942-ea341f4e963b`::finished: {'truesize': '27380420608', 'apparentsize': '26863764480'}
>Thread-7287::DEBUG::2014-06-10 20:24:50,109::task::595::TaskManager.Task::(_updateState) Task=`a4529ad1-da70-4fca-8942-ea341f4e963b`::moving from state preparing -> state finished
>Thread-7287::DEBUG::2014-06-10 20:24:50,109::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-7287::DEBUG::2014-06-10 20:24:50,110::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-7287::DEBUG::2014-06-10 20:24:50,110::task::990::TaskManager.Task::(_decref) Task=`a4529ad1-da70-4fca-8942-ea341f4e963b`::ref 0 aborting False
>Thread-7285::DEBUG::2014-06-10 20:24:50,130::vm::3744::vm.Vm::(_waitForIncomingMigrationFinish) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::End of migration
>VM Channels Listener::DEBUG::2014-06-10 20:24:50,713::vmChannels::102::vds::(_do_add_channels) fileno 72 was added to unconnected channels.
>VM Channels Listener::DEBUG::2014-06-10 20:24:50,714::vmChannels::128::vds::(_handle_unconnected) Trying to connect fileno 72.
>Thread-21::DEBUG::2014-06-10 20:24:50,714::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)
>VM Channels Listener::DEBUG::2014-06-10 20:24:50,715::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-10 20:24:50,722::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-10 20:24:50,722::vmChannels::144::vds::(_handle_unconnected) Connecting to fileno 72 succeeded.
>Thread-21::DEBUG::2014-06-10 20:24:50,724::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n357 bytes (357 B) copied, 0.000587132 s, 608 kB/s\n'; <rc> = 0
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:24:51,499::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-10 20:24:51,499::vm::623::vm.Vm::(_getNetworkStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Network stats not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:24:51,499::vm::645::vm.Vm::(_getDiskStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk hdc stats not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:24:51,499::vm::645::vm.Vm::(_getDiskStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk vda stats not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:24:51,500::vm::684::vm.Vm::(_getDiskLatency) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk hdc latency not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:24:51,500::vm::684::vm.Vm::(_getDiskLatency) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk vda latency not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:24:51,500::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-10 20:24:51,501::vm::623::vm.Vm::(_getNetworkStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Network stats not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:24:51,501::vm::645::vm.Vm::(_getDiskStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk hdc stats not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:24:51,501::vm::645::vm.Vm::(_getDiskStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk vda stats not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:24:51,501::vm::684::vm.Vm::(_getDiskLatency) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk hdc latency not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:24:51,501::vm::684::vm.Vm::(_getDiskLatency) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk vda latency not available
>Thread-26::DEBUG::2014-06-10 20:24:52,092::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-26::DEBUG::2014-06-10 20:24:52,099::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n363 bytes (363 B) copied, 0.000402204 s, 903 kB/s\n'; <rc> = 0
>Thread-13::DEBUG::2014-06-10 20:24:52,975::BindingXMLRPC::1067::vds::(wrapper) client [192.168.11.2]::call vmGetStats with ('803870d2-e365-4ab4-bdcc-4c1d25a03944',) {} flowID [70fdbcde]
>Thread-13::DEBUG::2014-06-10 20:24:52,975::vm::587::vm.Vm::(_getCpuStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::CPU stats not available: 'NoneType' object has no attribute '__getitem__'
>Thread-13::DEBUG::2014-06-10 20:24:52,976::vm::623::vm.Vm::(_getNetworkStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Network stats not available
>Thread-13::DEBUG::2014-06-10 20:24:52,976::vm::645::vm.Vm::(_getDiskStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk hdc stats not available
>Thread-13::DEBUG::2014-06-10 20:24:52,976::vm::645::vm.Vm::(_getDiskStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk vda stats not available
>Thread-13::DEBUG::2014-06-10 20:24:52,976::vm::684::vm.Vm::(_getDiskLatency) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk hdc latency not available
>Thread-13::DEBUG::2014-06-10 20:24:52,976::vm::684::vm.Vm::(_getDiskLatency) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk vda latency not available
>Thread-13::DEBUG::2014-06-10 20:24:52,977::BindingXMLRPC::1074::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Up', 'username': 'Unknown', 'memUsage': '0', 'acpiEnable': 'true', 'guestFQDN': '', 'pid': '6951', 'displayIp': '0', 'displayPort': '-1', 'session': 'Unknown', 'displaySecurePort': u'5900', 'timeOffset': '10770', 'hash': '-8956191300606272352', 'balloonInfo': {}, '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': '0.83', 'elapsedTime': '671', 'vmType': 'kvm', 'cpuSys': '0.00', 'guestCPUCount': -1, 'appsList': [], 'guestIPs': ''}]}
>Thread-19::DEBUG::2014-06-10 20:24:54,089::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-10 20:24:54,104::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n644 bytes (644 B) copied, 0.000744912 s, 865 kB/s\n'; <rc> = 0
>Thread-20::DEBUG::2014-06-10 20:24:54,506::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-10 20:24:54,513::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n557 bytes (557 B) copied, 0.000454234 s, 1.2 MB/s\n'; <rc> = 0
>Thread-33::DEBUG::2014-06-10 20:24:54,806::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-33::DEBUG::2014-06-10 20:24:54,816::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n557 bytes (557 B) copied, 0.00132066 s, 422 kB/s\n'; <rc> = 0
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:24:56,507::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-10 20:24:56,507::vm::623::vm.Vm::(_getNetworkStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Network stats not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:24:56,508::vm::645::vm.Vm::(_getDiskStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk hdc stats not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:24:56,508::vm::645::vm.Vm::(_getDiskStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk vda stats not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:24:56,508::vm::684::vm.Vm::(_getDiskLatency) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk hdc latency not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:24:56,508::vm::684::vm.Vm::(_getDiskLatency) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk vda latency not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:24:56,508::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-10 20:24:56,509::vm::623::vm.Vm::(_getNetworkStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Network stats not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:24:56,509::vm::645::vm.Vm::(_getDiskStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk hdc stats not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:24:56,509::vm::645::vm.Vm::(_getDiskStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk vda stats not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:24:56,509::vm::684::vm.Vm::(_getDiskLatency) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk hdc latency not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:24:56,509::vm::684::vm.Vm::(_getDiskLatency) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk vda latency not available
>Thread-21::DEBUG::2014-06-10 20:25:00,733::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-10 20:25:00,740::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n357 bytes (357 B) copied, 0.000320952 s, 1.1 MB/s\n'; <rc> = 0
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:25:01,516::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-10 20:25:01,516::vm::623::vm.Vm::(_getNetworkStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Network stats not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:25:01,516::vm::645::vm.Vm::(_getDiskStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk hdc stats not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:25:01,516::vm::645::vm.Vm::(_getDiskStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk vda stats not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:25:01,517::vm::684::vm.Vm::(_getDiskLatency) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk hdc latency not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:25:01,517::vm::684::vm.Vm::(_getDiskLatency) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk vda latency not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:25:01,517::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-10 20:25:01,517::vm::623::vm.Vm::(_getNetworkStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Network stats not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:25:01,517::vm::645::vm.Vm::(_getDiskStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk hdc stats not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:25:01,518::vm::645::vm.Vm::(_getDiskStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk vda stats not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:25:01,518::vm::684::vm.Vm::(_getDiskLatency) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk hdc latency not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:25:01,518::vm::684::vm.Vm::(_getDiskLatency) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk vda latency not available
>Thread-26::DEBUG::2014-06-10 20:25:02,112::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-26::DEBUG::2014-06-10 20:25:02,119::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n363 bytes (363 B) copied, 0.000311461 s, 1.2 MB/s\n'; <rc> = 0
>Thread-13::DEBUG::2014-06-10 20:25:02,153::task::595::TaskManager.Task::(_updateState) Task=`9be51ebc-1ebd-41b4-81a1-0c8e31ad50c3`::moving from state init -> state preparing
>Thread-13::INFO::2014-06-10 20:25:02,154::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-13::INFO::2014-06-10 20:25:02,154::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'2c51d320-88ce-4f23-8215-e15f55f66906': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000744912', 'lastCheck': '8.0', 'valid': True}, '965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000454234', 'lastCheck': '7.6', 'valid': True}, 'bff3a2be-fdd9-4e37-b416-fa4ef7fafba2': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000320952', 'lastCheck': '1.4', 'valid': True}, '63041fa9-e093-4b44-b36f-f39f16d3974f': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000311461', 'lastCheck': '0.0', 'valid': True}, '272ec473-6041-42ee-bd1a-732789dd18d4': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.00132066', 'lastCheck': '7.3', 'valid': True}}
>Thread-13::DEBUG::2014-06-10 20:25:02,154::task::1185::TaskManager.Task::(prepare) Task=`9be51ebc-1ebd-41b4-81a1-0c8e31ad50c3`::finished: {'2c51d320-88ce-4f23-8215-e15f55f66906': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000744912', 'lastCheck': '8.0', 'valid': True}, '965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000454234', 'lastCheck': '7.6', 'valid': True}, 'bff3a2be-fdd9-4e37-b416-fa4ef7fafba2': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000320952', 'lastCheck': '1.4', 'valid': True}, '63041fa9-e093-4b44-b36f-f39f16d3974f': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000311461', 'lastCheck': '0.0', 'valid': True}, '272ec473-6041-42ee-bd1a-732789dd18d4': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.00132066', 'lastCheck': '7.3', 'valid': True}}
>Thread-13::DEBUG::2014-06-10 20:25:02,154::task::595::TaskManager.Task::(_updateState) Task=`9be51ebc-1ebd-41b4-81a1-0c8e31ad50c3`::moving from state preparing -> state finished
>Thread-13::DEBUG::2014-06-10 20:25:02,154::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-13::DEBUG::2014-06-10 20:25:02,155::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-13::DEBUG::2014-06-10 20:25:02,155::task::990::TaskManager.Task::(_decref) Task=`9be51ebc-1ebd-41b4-81a1-0c8e31ad50c3`::ref 0 aborting False
>Thread-13::DEBUG::2014-06-10 20:25:02,188::vm::587::vm.Vm::(_getCpuStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::CPU stats not available: 'NoneType' object has no attribute '__getitem__'
>Thread-13::DEBUG::2014-06-10 20:25:02,188::vm::623::vm.Vm::(_getNetworkStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Network stats not available
>Thread-13::DEBUG::2014-06-10 20:25:02,188::vm::645::vm.Vm::(_getDiskStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk hdc stats not available
>Thread-13::DEBUG::2014-06-10 20:25:02,188::vm::645::vm.Vm::(_getDiskStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk vda stats not available
>Thread-13::DEBUG::2014-06-10 20:25:02,189::vm::684::vm.Vm::(_getDiskLatency) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk hdc latency not available
>Thread-13::DEBUG::2014-06-10 20:25:02,189::vm::684::vm.Vm::(_getDiskLatency) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk vda latency not available
>Thread-19::DEBUG::2014-06-10 20:25:04,117::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-10 20:25:04,124::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n644 bytes (644 B) copied, 0.000699202 s, 921 kB/s\n'; <rc> = 0
>Thread-20::DEBUG::2014-06-10 20:25:04,525::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-10 20:25:04,532::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n557 bytes (557 B) copied, 0.000177557 s, 3.1 MB/s\n'; <rc> = 0
>Thread-33::DEBUG::2014-06-10 20:25:04,828::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-33::DEBUG::2014-06-10 20:25:04,836::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n557 bytes (557 B) copied, 0.00105856 s, 526 kB/s\n'; <rc> = 0
>Thread-13::DEBUG::2014-06-10 20:25:05,536::BindingXMLRPC::1067::vds::(wrapper) client [192.168.11.2]::call vmSetTicket with ('803870d2-e365-4ab4-bdcc-4c1d25a03944', 'c1So3rMWhSqI', '120', 'disconnect', {'userName': 'Stockhausen', 'userId': 'b6b1f9f8-7030-4ea6-9653-9345860d58a9'}) {} flowID [23837f5f]
>Thread-13::DEBUG::2014-06-10 20:25:05,577::BindingXMLRPC::1074::vds::(wrapper) return vmSetTicket with {'status': {'message': 'Done', 'code': 0}}
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:25:06,524::vm::645::vm.Vm::(_getDiskStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk hdc stats not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:25:06,524::vm::645::vm.Vm::(_getDiskStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk vda stats not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:25:06,524::vm::684::vm.Vm::(_getDiskLatency) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk hdc latency not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:25:06,524::vm::684::vm.Vm::(_getDiskLatency) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk vda latency not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:25:06,525::vm::645::vm.Vm::(_getDiskStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk hdc stats not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:25:06,525::vm::645::vm.Vm::(_getDiskStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk vda stats not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:25:06,525::vm::684::vm.Vm::(_getDiskLatency) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk hdc latency not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:25:06,525::vm::684::vm.Vm::(_getDiskLatency) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk vda latency not available
>libvirtEventLoop::DEBUG::2014-06-10 20:25:09,229::clientIF::555::vm.Vm::(dispatchLibvirtEvents) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::graphics event phase 0 localAddr {'node': '192.168.11.43', 'service': '', 'family': 0} remoteAddr {'node': '10.150.2.97', 'service': '', 'family': 0}authScheme  subject []
>Thread-21::DEBUG::2014-06-10 20:25:10,751::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-10 20:25:10,765::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n357 bytes (357 B) copied, 0.00668355 s, 53.4 kB/s\n'; <rc> = 0
>libvirtEventLoop::DEBUG::2014-06-10 20:25:11,163::clientIF::555::vm.Vm::(dispatchLibvirtEvents) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::graphics event phase 1 localAddr {'node': '192.168.11.43', 'service': '', 'family': 0} remoteAddr {'node': '10.150.2.97', 'service': '', 'family': 0}authScheme spice subject []
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:25:11,531::vm::645::vm.Vm::(_getDiskStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk hdc stats not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:25:11,531::vm::645::vm.Vm::(_getDiskStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk vda stats not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:25:11,531::vm::684::vm.Vm::(_getDiskLatency) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk hdc latency not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:25:11,531::vm::684::vm.Vm::(_getDiskLatency) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk vda latency not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:25:11,532::vm::645::vm.Vm::(_getDiskStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk hdc stats not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:25:11,532::vm::645::vm.Vm::(_getDiskStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk vda stats not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:25:11,532::vm::684::vm.Vm::(_getDiskLatency) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk hdc latency not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:25:11,532::vm::684::vm.Vm::(_getDiskLatency) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk vda latency not available
>Thread-26::DEBUG::2014-06-10 20:25:12,129::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-26::DEBUG::2014-06-10 20:25:12,135::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n363 bytes (363 B) copied, 0.000160456 s, 2.3 MB/s\n'; <rc> = 0
>libvirtEventLoop::DEBUG::2014-06-10 20:25:13,560::clientIF::555::vm.Vm::(dispatchLibvirtEvents) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::graphics event phase 0 localAddr {'node': '192.168.11.43', 'service': '', 'family': 0} remoteAddr {'node': '10.150.2.97', 'service': '', 'family': 0}authScheme  subject []
>libvirtEventLoop::DEBUG::2014-06-10 20:25:13,561::clientIF::555::vm.Vm::(dispatchLibvirtEvents) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::graphics event phase 0 localAddr {'node': '192.168.11.43', 'service': '', 'family': 0} remoteAddr {'node': '10.150.2.97', 'service': '', 'family': 0}authScheme  subject []
>libvirtEventLoop::DEBUG::2014-06-10 20:25:13,565::clientIF::555::vm.Vm::(dispatchLibvirtEvents) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::graphics event phase 0 localAddr {'node': '192.168.11.43', 'service': '', 'family': 0} remoteAddr {'node': '10.150.2.97', 'service': '', 'family': 0}authScheme  subject []
>libvirtEventLoop::DEBUG::2014-06-10 20:25:14,024::clientIF::555::vm.Vm::(dispatchLibvirtEvents) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::graphics event phase 1 localAddr {'node': '192.168.11.43', 'service': '', 'family': 0} remoteAddr {'node': '10.150.2.97', 'service': '', 'family': 0}authScheme spice subject []
>libvirtEventLoop::DEBUG::2014-06-10 20:25:14,033::clientIF::555::vm.Vm::(dispatchLibvirtEvents) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::graphics event phase 1 localAddr {'node': '192.168.11.43', 'service': '', 'family': 0} remoteAddr {'node': '10.150.2.97', 'service': '', 'family': 0}authScheme spice subject []
>libvirtEventLoop::DEBUG::2014-06-10 20:25:14,076::clientIF::555::vm.Vm::(dispatchLibvirtEvents) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::graphics event phase 1 localAddr {'node': '192.168.11.43', 'service': '', 'family': 0} remoteAddr {'node': '10.150.2.97', 'service': '', 'family': 0}authScheme spice subject []
>Thread-19::DEBUG::2014-06-10 20:25:14,136::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-10 20:25:14,143::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n644 bytes (644 B) copied, 0.00025773 s, 2.5 MB/s\n'; <rc> = 0
>Thread-20::DEBUG::2014-06-10 20:25:14,544::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-10 20:25:14,554::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n557 bytes (557 B) copied, 0.000209186 s, 2.7 MB/s\n'; <rc> = 0
>Thread-33::DEBUG::2014-06-10 20:25:14,848::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-33::DEBUG::2014-06-10 20:25:14,865::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n557 bytes (557 B) copied, 0.000504014 s, 1.1 MB/s\n'; <rc> = 0
>libvirtEventLoop::DEBUG::2014-06-10 20:25:15,374::clientIF::555::vm.Vm::(dispatchLibvirtEvents) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::graphics event phase 0 localAddr {'node': '192.168.11.43', 'service': '', 'family': 0} remoteAddr {'node': '10.150.2.97', 'service': '', 'family': 0}authScheme  subject []
>libvirtEventLoop::DEBUG::2014-06-10 20:25:15,374::clientIF::555::vm.Vm::(dispatchLibvirtEvents) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::graphics event phase 0 localAddr {'node': '192.168.11.43', 'service': '', 'family': 0} remoteAddr {'node': '10.150.2.97', 'service': '', 'family': 0}authScheme  subject []
>libvirtEventLoop::DEBUG::2014-06-10 20:25:15,918::clientIF::555::vm.Vm::(dispatchLibvirtEvents) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::graphics event phase 1 localAddr {'node': '192.168.11.43', 'service': '', 'family': 0} remoteAddr {'node': '10.150.2.97', 'service': '', 'family': 0}authScheme spice subject []
>libvirtEventLoop::DEBUG::2014-06-10 20:25:15,940::clientIF::555::vm.Vm::(dispatchLibvirtEvents) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::graphics event phase 1 localAddr {'node': '192.168.11.43', 'service': '', 'family': 0} remoteAddr {'node': '10.150.2.97', 'service': '', 'family': 0}authScheme spice subject []
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:25:16,538::vm::645::vm.Vm::(_getDiskStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk hdc stats not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:25:16,538::vm::645::vm.Vm::(_getDiskStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk vda stats not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:25:16,539::vm::684::vm.Vm::(_getDiskLatency) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk hdc latency not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:25:16,539::vm::684::vm.Vm::(_getDiskLatency) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk vda latency not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:25:16,539::vm::645::vm.Vm::(_getDiskStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk hdc stats not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:25:16,539::vm::645::vm.Vm::(_getDiskStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk vda stats not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:25:16,540::vm::684::vm.Vm::(_getDiskLatency) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk hdc latency not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:25:16,540::vm::684::vm.Vm::(_getDiskLatency) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk vda latency not available
>Thread-13::DEBUG::2014-06-10 20:25:17,304::task::595::TaskManager.Task::(_updateState) Task=`88847c94-f265-4348-9f54-8ba8752d07f2`::moving from state init -> state preparing
>Thread-13::INFO::2014-06-10 20:25:17,304::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-13::INFO::2014-06-10 20:25:17,304::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'2c51d320-88ce-4f23-8215-e15f55f66906': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.00025773', 'lastCheck': '3.2', 'valid': True}, '965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000209186', 'lastCheck': '2.7', 'valid': True}, 'bff3a2be-fdd9-4e37-b416-fa4ef7fafba2': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.00668355', 'lastCheck': '6.5', 'valid': True}, '63041fa9-e093-4b44-b36f-f39f16d3974f': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000160456', 'lastCheck': '5.2', 'valid': True}, '272ec473-6041-42ee-bd1a-732789dd18d4': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000504014', 'lastCheck': '2.4', 'valid': True}}
>Thread-13::DEBUG::2014-06-10 20:25:17,304::task::1185::TaskManager.Task::(prepare) Task=`88847c94-f265-4348-9f54-8ba8752d07f2`::finished: {'2c51d320-88ce-4f23-8215-e15f55f66906': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.00025773', 'lastCheck': '3.2', 'valid': True}, '965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000209186', 'lastCheck': '2.7', 'valid': True}, 'bff3a2be-fdd9-4e37-b416-fa4ef7fafba2': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.00668355', 'lastCheck': '6.5', 'valid': True}, '63041fa9-e093-4b44-b36f-f39f16d3974f': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000160456', 'lastCheck': '5.2', 'valid': True}, '272ec473-6041-42ee-bd1a-732789dd18d4': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000504014', 'lastCheck': '2.4', 'valid': True}}
>Thread-13::DEBUG::2014-06-10 20:25:17,304::task::595::TaskManager.Task::(_updateState) Task=`88847c94-f265-4348-9f54-8ba8752d07f2`::moving from state preparing -> state finished
>Thread-13::DEBUG::2014-06-10 20:25:17,305::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-13::DEBUG::2014-06-10 20:25:17,305::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-13::DEBUG::2014-06-10 20:25:17,305::task::990::TaskManager.Task::(_decref) Task=`88847c94-f265-4348-9f54-8ba8752d07f2`::ref 0 aborting False
>Thread-13::DEBUG::2014-06-10 20:25:17,337::vm::645::vm.Vm::(_getDiskStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk hdc stats not available
>Thread-13::DEBUG::2014-06-10 20:25:17,338::vm::645::vm.Vm::(_getDiskStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk vda stats not available
>Thread-13::DEBUG::2014-06-10 20:25:17,338::vm::684::vm.Vm::(_getDiskLatency) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk hdc latency not available
>Thread-13::DEBUG::2014-06-10 20:25:17,338::vm::684::vm.Vm::(_getDiskLatency) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk vda latency not available
>VM Channels Listener::DEBUG::2014-06-10 20:25:20,761::vmChannels::91::vds::(_handle_timeouts) Timeout on fileno 72.
>Thread-21::DEBUG::2014-06-10 20:25:20,775::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-10 20:25:20,784::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n357 bytes (357 B) copied, 0.00309727 s, 115 kB/s\n'; <rc> = 0
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:25:21,545::vm::645::vm.Vm::(_getDiskStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk hdc stats not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:25:21,545::vm::645::vm.Vm::(_getDiskStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk vda stats not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:25:21,546::vm::684::vm.Vm::(_getDiskLatency) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk hdc latency not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:25:21,546::vm::684::vm.Vm::(_getDiskLatency) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk vda latency not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:25:21,546::vm::645::vm.Vm::(_getDiskStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk hdc stats not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:25:21,547::vm::645::vm.Vm::(_getDiskStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk vda stats not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:25:21,547::vm::684::vm.Vm::(_getDiskLatency) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk hdc latency not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:25:21,547::vm::684::vm.Vm::(_getDiskLatency) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk vda latency not available
>Thread-26::DEBUG::2014-06-10 20:25:22,147::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-26::DEBUG::2014-06-10 20:25:22,153::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n363 bytes (363 B) copied, 0.000161599 s, 2.2 MB/s\n'; <rc> = 0
>Thread-19::DEBUG::2014-06-10 20:25:24,157::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-10 20:25:24,164::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n644 bytes (644 B) copied, 0.00048684 s, 1.3 MB/s\n'; <rc> = 0
>Thread-20::DEBUG::2014-06-10 20:25:24,566::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-10 20:25:24,574::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n557 bytes (557 B) copied, 0.000224649 s, 2.5 MB/s\n'; <rc> = 0
>Thread-33::DEBUG::2014-06-10 20:25:24,877::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-33::DEBUG::2014-06-10 20:25:24,885::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n557 bytes (557 B) copied, 0.000273307 s, 2.0 MB/s\n'; <rc> = 0
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:25:26,553::vm::645::vm.Vm::(_getDiskStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk hdc stats not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:25:26,553::vm::645::vm.Vm::(_getDiskStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk vda stats not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:25:26,553::vm::684::vm.Vm::(_getDiskLatency) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk hdc latency not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:25:26,553::vm::684::vm.Vm::(_getDiskLatency) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk vda latency not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:25:26,554::vm::645::vm.Vm::(_getDiskStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk hdc stats not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:25:26,554::vm::645::vm.Vm::(_getDiskStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk vda stats not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:25:26,554::vm::684::vm.Vm::(_getDiskLatency) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk hdc latency not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:25:26,554::vm::684::vm.Vm::(_getDiskLatency) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk vda latency not available
>Thread-21::DEBUG::2014-06-10 20:25:30,794::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-10 20:25:30,800::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n357 bytes (357 B) copied, 0.000163948 s, 2.2 MB/s\n'; <rc> = 0
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:25:31,560::vm::645::vm.Vm::(_getDiskStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk hdc stats not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:25:31,560::vm::645::vm.Vm::(_getDiskStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk vda stats not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:25:31,561::vm::684::vm.Vm::(_getDiskLatency) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk hdc latency not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:25:31,561::vm::684::vm.Vm::(_getDiskLatency) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk vda latency not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:25:31,561::vm::645::vm.Vm::(_getDiskStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk hdc stats not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:25:31,561::vm::645::vm.Vm::(_getDiskStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk vda stats not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:25:31,562::vm::684::vm.Vm::(_getDiskLatency) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk hdc latency not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:25:31,562::vm::684::vm.Vm::(_getDiskLatency) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk vda latency not available
>Thread-26::DEBUG::2014-06-10 20:25:32,163::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-26::DEBUG::2014-06-10 20:25:32,171::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n363 bytes (363 B) copied, 0.00117161 s, 310 kB/s\n'; <rc> = 0
>Thread-13::DEBUG::2014-06-10 20:25:32,544::task::595::TaskManager.Task::(_updateState) Task=`21d39615-dbb9-4c22-943d-c8c58d61b57a`::moving from state init -> state preparing
>Thread-13::INFO::2014-06-10 20:25:32,544::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-13::INFO::2014-06-10 20:25:32,545::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'2c51d320-88ce-4f23-8215-e15f55f66906': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.00048684', 'lastCheck': '8.4', 'valid': True}, '965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000224649', 'lastCheck': '8.0', 'valid': True}, 'bff3a2be-fdd9-4e37-b416-fa4ef7fafba2': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000163948', 'lastCheck': '1.7', 'valid': True}, '63041fa9-e093-4b44-b36f-f39f16d3974f': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.00117161', 'lastCheck': '0.4', 'valid': True}, '272ec473-6041-42ee-bd1a-732789dd18d4': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000273307', 'lastCheck': '7.7', 'valid': True}}
>Thread-13::DEBUG::2014-06-10 20:25:32,545::task::1185::TaskManager.Task::(prepare) Task=`21d39615-dbb9-4c22-943d-c8c58d61b57a`::finished: {'2c51d320-88ce-4f23-8215-e15f55f66906': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.00048684', 'lastCheck': '8.4', 'valid': True}, '965ca3b6-4f9c-4e81-b6e8-5ed4a9e58545': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000224649', 'lastCheck': '8.0', 'valid': True}, 'bff3a2be-fdd9-4e37-b416-fa4ef7fafba2': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000163948', 'lastCheck': '1.7', 'valid': True}, '63041fa9-e093-4b44-b36f-f39f16d3974f': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.00117161', 'lastCheck': '0.4', 'valid': True}, '272ec473-6041-42ee-bd1a-732789dd18d4': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000273307', 'lastCheck': '7.7', 'valid': True}}
>Thread-13::DEBUG::2014-06-10 20:25:32,545::task::595::TaskManager.Task::(_updateState) Task=`21d39615-dbb9-4c22-943d-c8c58d61b57a`::moving from state preparing -> state finished
>Thread-13::DEBUG::2014-06-10 20:25:32,545::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-13::DEBUG::2014-06-10 20:25:32,545::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-13::DEBUG::2014-06-10 20:25:32,546::task::990::TaskManager.Task::(_decref) Task=`21d39615-dbb9-4c22-943d-c8c58d61b57a`::ref 0 aborting False
>Thread-13::DEBUG::2014-06-10 20:25:32,620::vm::645::vm.Vm::(_getDiskStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk hdc stats not available
>Thread-13::DEBUG::2014-06-10 20:25:32,621::vm::645::vm.Vm::(_getDiskStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk vda stats not available
>Thread-13::DEBUG::2014-06-10 20:25:32,621::vm::684::vm.Vm::(_getDiskLatency) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk hdc latency not available
>Thread-13::DEBUG::2014-06-10 20:25:32,621::vm::684::vm.Vm::(_getDiskLatency) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk vda latency not available
>Thread-19::DEBUG::2014-06-10 20:25:34,178::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-10 20:25:34,185::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n644 bytes (644 B) copied, 0.000237506 s, 2.7 MB/s\n'; <rc> = 0
>Thread-20::DEBUG::2014-06-10 20:25:34,586::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-10 20:25:34,593::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n557 bytes (557 B) copied, 0.000299351 s, 1.9 MB/s\n'; <rc> = 0
>Thread-33::DEBUG::2014-06-10 20:25:34,897::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-33::DEBUG::2014-06-10 20:25:34,904::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n557 bytes (557 B) copied, 0.000468182 s, 1.2 MB/s\n'; <rc> = 0
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:25:36,568::vm::645::vm.Vm::(_getDiskStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk hdc stats not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:25:36,568::vm::645::vm.Vm::(_getDiskStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk vda stats not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:25:36,568::vm::684::vm.Vm::(_getDiskLatency) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk hdc latency not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:25:36,568::vm::684::vm.Vm::(_getDiskLatency) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk vda latency not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:25:36,569::vm::645::vm.Vm::(_getDiskStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk hdc stats not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:25:36,569::vm::645::vm.Vm::(_getDiskStats) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk vda stats not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:25:36,569::vm::684::vm.Vm::(_getDiskLatency) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk hdc latency not available
>GuestMonitor-colvm36::DEBUG::2014-06-10 20:25:36,569::vm::684::vm.Vm::(_getDiskLatency) vmId=`803870d2-e365-4ab4-bdcc-4c1d25a03944`::Disk vda latency not available

Actions: View

Attachments on bug 1107835: 907354 | 907359 | 907818