Login
[x]
Log in using an account from:
Fedora Account System
Red Hat Associate
Red Hat Customer
Or login using a Red Hat Bugzilla account
Forgot Password
Login:
Hide Forgot
Create an Account
Red Hat Bugzilla – Attachment 907354 Details for
Bug 1107835
Windows XP VM hangs after live migration
[?]
New
Simple Search
Advanced Search
My Links
Browse
Requests
Reports
Current State
Search
Tabular reports
Graphical reports
Duplicates
Other Reports
User Changes
Plotly Reports
Bug Status
Bug Severity
Non-Defaults
|
Product Dashboard
Help
Page Help!
Bug Writing Guidelines
What's new
Browser Support Policy
5.0.4.rh83 Release notes
FAQ
Guides index
User guide
Web Services
Contact
Legal
This site requires JavaScript to be enabled to function correctly, please enable it.
vdsm.log
vdsm.mst.log (text/plain), 98.94 KB, created by
Markus Stockhausen
on 2014-06-10 18:28:33 UTC
(
hide
)
Description:
vdsm.log
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
You cannot view the attachment while viewing its details because your browser does not support IFRAMEs.
View the attachment on a separate page
.
View Attachment As Raw
Actions:
View
Attachments on
bug 1107835
: 907354 |
907359
|
907818