Attachment 876363 Details for Bug 1076457 – vdsm log of host

vdsm log of host

vdsm.log (text/x-log), 182.80 KB, created by Lukas Svaty on 2014-03-19 14:19:21 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: Lukas Svaty

Created: 2014-03-19 14:19:21 UTC

Size: 182.80 KB

patch

obsolete

>Thread-71::DEBUG::2014-03-19 15:11:53,185::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.34.63.202:_mnt_export_nfs_lv3_lsvaty_nfs01/4cd91baa-e6dd-4d84-a89d-89fc458f15a9/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-71::DEBUG::2014-03-19 15:11:53,191::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n476 bytes (476 B) copied, 0.000259338 s, 1.8 MB/s\n'; <rc> = 0
>Thread-2636::DEBUG::2014-03-19 15:11:55,042::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-2636::INFO::2014-03-19 15:11:55,042::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-2636::INFO::2014-03-19 15:11:55,054::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 2, 'spmStatus': 'SPM', 'spmLver': 5L}}
>Thread-3118::DEBUG::2014-03-19 15:11:55,059::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-3118::INFO::2014-03-19 15:11:55,059::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3118::INFO::2014-03-19 15:11:55,061::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9:Active', 'master_uuid': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9', 'version': '3', 'spm_id': 2, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'4cd91baa-e6dd-4d84-a89d-89fc458f15a9': {'status': 'Active', 'diskfree': '282360545280', 'isoprefix': '', 'alerts': [], 'disktotal': '422758580224', 'version': 3}}}
>Thread-2636::DEBUG::2014-03-19 15:12:01,053::BindingXMLRPC::1067::vds::(wrapper) client [10.34.63.60]::call vmCreate with ({'acpiEnable': 'true', 'emulatedMachine': 'rhel6.5.0', 'vmId': 'e6b03061-7a3b-46f4-9fff-a786b9d501d9', 'memGuaranteedSize': 1024, 'spiceSslCipherSuite': 'DEFAULT', 'timeOffset': '-18000', 'cpuType': 'Westmere', 'smp': '1', 'custom': {'device_2d4f6e90-aa6b-4b59-b313-8c3fa14cbe86device_ce77fb27-41b9-4a4c-9659-2d226a58d7f6device_09027724-cc97-4dfa-b3b3-dfa474f449fbdevice_9e0cfb96-3240-4a93-96f2-bcd19f26c2bd': 'VmDevice {vmId=e6b03061-7a3b-46f4-9fff-a786b9d501d9, deviceId=9e0cfb96-3240-4a93-96f2-bcd19f26c2bd, 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_2d4f6e90-aa6b-4b59-b313-8c3fa14cbe86': 'VmDevice {vmId=e6b03061-7a3b-46f4-9fff-a786b9d501d9, deviceId=2d4f6e90-aa6b-4b59-b313-8c3fa14cbe86, device=ide, type=CONTROLLER, bootOrder=0, specParams={}, address={bus=0x00, domain=0x0000, type=pci, slot=0x01, function=0x1}, managed=false, plugged=true, readOnly=false, deviceAlias=ide0, customProperties={}, snapshotId=null}', 'device_2d4f6e90-aa6b-4b59-b313-8c3fa14cbe86device_ce77fb27-41b9-4a4c-9659-2d226a58d7f6': 'VmDevice {vmId=e6b03061-7a3b-46f4-9fff-a786b9d501d9, deviceId=ce77fb27-41b9-4a4c-9659-2d226a58d7f6, device=virtio-serial, type=CONTROLLER, bootOrder=0, specParams={}, address={bus=0x00, domain=0x0000, type=pci, slot=0x05, function=0x0}, managed=false, plugged=true, readOnly=false, deviceAlias=virtio-serial0, customProperties={}, snapshotId=null}', 'device_2d4f6e90-aa6b-4b59-b313-8c3fa14cbe86device_ce77fb27-41b9-4a4c-9659-2d226a58d7f6device_09027724-cc97-4dfa-b3b3-dfa474f449fbdevice_9e0cfb96-3240-4a93-96f2-bcd19f26c2bddevice_bf0c72ef-38a1-458c-8a3c-63d8947bfd62': 'VmDevice {vmId=e6b03061-7a3b-46f4-9fff-a786b9d501d9, deviceId=bf0c72ef-38a1-458c-8a3c-63d8947bfd62, 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_2d4f6e90-aa6b-4b59-b313-8c3fa14cbe86device_ce77fb27-41b9-4a4c-9659-2d226a58d7f6device_09027724-cc97-4dfa-b3b3-dfa474f449fb': 'VmDevice {vmId=e6b03061-7a3b-46f4-9fff-a786b9d501d9, deviceId=09027724-cc97-4dfa-b3b3-dfa474f449fb, device=unix, type=CHANNEL, bootOrder=0, specParams={}, address={port=1, bus=0, controller=0, type=virtio-serial}, managed=false, plugged=true, readOnly=false, deviceAlias=channel0, customProperties={}, snapshotId=null}'}, 'vmType': 'kvm', 'memSize': 1024, 'smpCoresPerSocket': '1', 'vmName': 'a', 'nice': '0', 'smartcardEnable': 'false', 'keyboardLayout': 'en-us', 'kvmEnable': 'true', 'transparentHugePages': 'true', 'devices': [{'device': 'qxl', 'specParams': {'vram': '32768', 'heads': '1'}, 'type': 'video', 'deviceId': '778f48bd-1404-4af6-bc06-7b16dfd51258', 'address': {'slot': '0x02', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}}, {'index': '2', 'iface': 'ide', 'address': {'bus': '1', 'controller': '0', 'type': 'drive', 'target': '0', 'unit': '0'}, 'specParams': {'path': ''}, 'readonly': 'true', 'deviceId': 'f8630c8b-192d-4f0c-b77c-20376b8d9b88', 'path': '', 'device': 'cdrom', 'shared': 'false', 'type': 'disk'}, {'index': 0, 'iface': 'virtio', 'format': 'cow', 'bootOrder': '1', 'poolID': '00000002-0002-0002-0002-000000000394', 'volumeID': '2fbe976c-ab19-4bfb-9fce-94af66388c2e', 'imageID': '746db1d5-a195-4dc1-833b-77c2a46f1a22', 'specParams': {}, 'readonly': 'false', 'domainID': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9', 'optional': 'false', 'deviceId': '746db1d5-a195-4dc1-833b-77c2a46f1a22', 'address': {'slot': '0x06', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'disk', 'shared': 'false', 'propagateErrors': 'off', 'type': 'disk'}, {'iface': 'virtio', 'format': 'raw', 'type': 'disk', 'poolID': '00000002-0002-0002-0002-000000000394', 'volumeID': '5037acb2-df07-45c2-909f-044acb0611ec', 'imageID': 'efd305ae-6a25-4f32-88fe-b8930849c936', 'specParams': {}, 'readonly': 'false', 'domainID': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9', 'deviceId': 'efd305ae-6a25-4f32-88fe-b8930849c936', 'address': {'slot': '0x08', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'disk', 'shared': 'false', 'propagateErrors': 'off', 'optional': 'false'}, {'nicModel': 'pv', 'macAddr': '00:1a:4a:30:54:9c', 'linkActive': 'true', 'network': 'rhevm', 'filter': 'vdsm-no-mac-spoofing', 'specParams': {}, 'deviceId': '921515b8-8d80-4fb0-989b-ace2415fb852', 'address': {'slot': '0x03', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'bridge', 'type': 'interface'}, {'device': 'memballoon', 'specParams': {'model': 'virtio'}, 'type': 'balloon', 'deviceId': '37f8db04-6037-4eeb-a924-6a0e9dceb2d9'}, {'index': '0', 'specParams': {}, 'deviceId': '46c536cf-5e66-4209-b379-b570c15b9a82', 'address': {'slot': '0x04', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'scsi', 'model': 'virtio-scsi', 'type': 'controller'}], 'maxVCpus': '160', 'spiceSecureChannels': 'smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard', 'display': 'qxl'},) {} flowID [52715af2]
>Thread-2636::INFO::2014-03-19 15:12:01,055::API::668::vds::(_getNetworkIp) network None: using 0
>Thread-2636::INFO::2014-03-19 15:12:01,055::clientIF::366::vds::(createVm) vmContainerLock acquired by vm e6b03061-7a3b-46f4-9fff-a786b9d501d9
>Thread-3122::DEBUG::2014-03-19 15:12:01,057::vm::2242::vm.Vm::(_startUnderlyingVm) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Start
>Thread-2636::DEBUG::2014-03-19 15:12:01,057::clientIF::379::vds::(createVm) Total desktops after creation of e6b03061-7a3b-46f4-9fff-a786b9d501d9 is 1
>Thread-3122::DEBUG::2014-03-19 15:12:01,058::vm::2246::vm.Vm::(_startUnderlyingVm) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::_ongoingCreations acquired
>Thread-2636::DEBUG::2014-03-19 15:12:01,058::BindingXMLRPC::1074::vds::(wrapper) return vmCreate with {'status': {'message': 'Done', 'code': 0}, 'vmList': {'status': 'WaitForLaunch', 'acpiEnable': 'true', 'emulatedMachine': 'rhel6.5.0', 'vmId': 'e6b03061-7a3b-46f4-9fff-a786b9d501d9', 'pid': '0', 'memGuaranteedSize': 1024, 'timeOffset': '-18000', 'keyboardLayout': 'en-us', 'displayPort': '-1', 'displaySecurePort': '-1', 'spiceSslCipherSuite': 'DEFAULT', 'cpuType': 'Westmere', 'custom': {'device_2d4f6e90-aa6b-4b59-b313-8c3fa14cbe86device_ce77fb27-41b9-4a4c-9659-2d226a58d7f6device_09027724-cc97-4dfa-b3b3-dfa474f449fbdevice_9e0cfb96-3240-4a93-96f2-bcd19f26c2bd': 'VmDevice {vmId=e6b03061-7a3b-46f4-9fff-a786b9d501d9, deviceId=9e0cfb96-3240-4a93-96f2-bcd19f26c2bd, 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_2d4f6e90-aa6b-4b59-b313-8c3fa14cbe86': 'VmDevice {vmId=e6b03061-7a3b-46f4-9fff-a786b9d501d9, deviceId=2d4f6e90-aa6b-4b59-b313-8c3fa14cbe86, device=ide, type=CONTROLLER, bootOrder=0, specParams={}, address={bus=0x00, domain=0x0000, type=pci, slot=0x01, function=0x1}, managed=false, plugged=true, readOnly=false, deviceAlias=ide0, customProperties={}, snapshotId=null}', 'device_2d4f6e90-aa6b-4b59-b313-8c3fa14cbe86device_ce77fb27-41b9-4a4c-9659-2d226a58d7f6': 'VmDevice {vmId=e6b03061-7a3b-46f4-9fff-a786b9d501d9, deviceId=ce77fb27-41b9-4a4c-9659-2d226a58d7f6, device=virtio-serial, type=CONTROLLER, bootOrder=0, specParams={}, address={bus=0x00, domain=0x0000, type=pci, slot=0x05, function=0x0}, managed=false, plugged=true, readOnly=false, deviceAlias=virtio-serial0, customProperties={}, snapshotId=null}', 'device_2d4f6e90-aa6b-4b59-b313-8c3fa14cbe86device_ce77fb27-41b9-4a4c-9659-2d226a58d7f6device_09027724-cc97-4dfa-b3b3-dfa474f449fbdevice_9e0cfb96-3240-4a93-96f2-bcd19f26c2bddevice_bf0c72ef-38a1-458c-8a3c-63d8947bfd62': 'VmDevice {vmId=e6b03061-7a3b-46f4-9fff-a786b9d501d9, deviceId=bf0c72ef-38a1-458c-8a3c-63d8947bfd62, 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_2d4f6e90-aa6b-4b59-b313-8c3fa14cbe86device_ce77fb27-41b9-4a4c-9659-2d226a58d7f6device_09027724-cc97-4dfa-b3b3-dfa474f449fb': 'VmDevice {vmId=e6b03061-7a3b-46f4-9fff-a786b9d501d9, deviceId=09027724-cc97-4dfa-b3b3-dfa474f449fb, 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}'}, 'clientIp': '', 'nicModel': 'rtl8139,pv', 'smartcardEnable': 'false', 'kvmEnable': 'true', 'transparentHugePages': 'true', 'devices': [{'device': 'qxl', 'specParams': {'vram': '32768', 'heads': '1'}, 'type': 'video', 'deviceId': '778f48bd-1404-4af6-bc06-7b16dfd51258', 'address': {'slot': '0x02', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}}, {'index': '2', 'iface': 'ide', 'address': {'bus': '1', 'controller': '0', 'type': 'drive', 'target': '0', 'unit': '0'}, 'specParams': {'path': ''}, 'readonly': 'true', 'deviceId': 'f8630c8b-192d-4f0c-b77c-20376b8d9b88', 'path': '', 'device': 'cdrom', 'shared': 'false', 'type': 'disk'}, {'index': 0, 'iface': 'virtio', 'format': 'cow', 'bootOrder': '1', 'poolID': '00000002-0002-0002-0002-000000000394', 'volumeID': '2fbe976c-ab19-4bfb-9fce-94af66388c2e', 'imageID': '746db1d5-a195-4dc1-833b-77c2a46f1a22', 'specParams': {}, 'readonly': 'false', 'domainID': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9', 'optional': 'false', 'deviceId': '746db1d5-a195-4dc1-833b-77c2a46f1a22', 'address': {'slot': '0x06', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'disk', 'shared': 'false', 'propagateErrors': 'off', 'type': 'disk'}, {'iface': 'virtio', 'format': 'raw', 'type': 'disk', 'poolID': '00000002-0002-0002-0002-000000000394', 'volumeID': '5037acb2-df07-45c2-909f-044acb0611ec', 'imageID': 'efd305ae-6a25-4f32-88fe-b8930849c936', 'specParams': {}, 'readonly': 'false', 'domainID': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9', 'deviceId': 'efd305ae-6a25-4f32-88fe-b8930849c936', 'address': {'slot': '0x08', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'disk', 'shared': 'false', 'propagateErrors': 'off', 'optional': 'false'}, {'nicModel': 'pv', 'macAddr': '00:1a:4a:30:54:9c', 'linkActive': 'true', 'network': 'rhevm', 'filter': 'vdsm-no-mac-spoofing', 'specParams': {}, 'deviceId': '921515b8-8d80-4fb0-989b-ace2415fb852', 'address': {'slot': '0x03', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'bridge', 'type': 'interface'}, {'device': 'memballoon', 'specParams': {'model': 'virtio'}, 'type': 'balloon', 'deviceId': '37f8db04-6037-4eeb-a924-6a0e9dceb2d9'}, {'index': '0', 'specParams': {}, 'deviceId': '46c536cf-5e66-4209-b379-b570c15b9a82', 'address': {'slot': '0x04', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'scsi', 'model': 'virtio-scsi', 'type': 'controller'}], 'smp': '1', 'vmType': 'kvm', 'memSize': 1024, 'displayIp': '0', 'maxVCpus': '160', 'spiceSecureChannels': 'smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard', 'smpCoresPerSocket': '1', 'vmName': 'a', 'display': 'qxl', 'nice': '0'}}
>Thread-3122::INFO::2014-03-19 15:12:01,058::vm::3097::vm.Vm::(_run) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::VM wrapper has started
>Thread-3122::INFO::2014-03-19 15:12:01,059::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='4cd91baa-e6dd-4d84-a89d-89fc458f15a9', spUUID='00000002-0002-0002-0002-000000000394', imgUUID='746db1d5-a195-4dc1-833b-77c2a46f1a22', volUUID='2fbe976c-ab19-4bfb-9fce-94af66388c2e', options=None)
>Thread-3122::INFO::2014-03-19 15:12:01,061::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '88940544', 'apparentsize': '88997888'}
>Thread-3122::INFO::2014-03-19 15:12:01,061::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='4cd91baa-e6dd-4d84-a89d-89fc458f15a9', spUUID='00000002-0002-0002-0002-000000000394', imgUUID='efd305ae-6a25-4f32-88fe-b8930849c936', volUUID='5037acb2-df07-45c2-909f-044acb0611ec', options=None)
>Thread-3122::INFO::2014-03-19 15:12:01,062::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '6442455040', 'apparentsize': '6442450944'}
>Thread-3122::INFO::2014-03-19 15:12:01,063::clientIF::324::vds::(prepareVolumePath) prepared volume path:
>Thread-3122::INFO::2014-03-19 15:12:01,063::logUtils::44::dispatcher::(wrapper) Run and protect: prepareImage(sdUUID='4cd91baa-e6dd-4d84-a89d-89fc458f15a9', spUUID='00000002-0002-0002-0002-000000000394', imgUUID='746db1d5-a195-4dc1-833b-77c2a46f1a22', leafUUID='2fbe976c-ab19-4bfb-9fce-94af66388c2e')
>Thread-3122::WARNING::2014-03-19 15:12:01,067::fileUtils::167::Storage.fileUtils::(createdir) Dir /var/run/vdsm/storage/4cd91baa-e6dd-4d84-a89d-89fc458f15a9 already exists
>Thread-3122::DEBUG::2014-03-19 15:12:01,068::fileSD::446::Storage.StorageDomain::(createImageLinks) img run dir already exists: /var/run/vdsm/storage/4cd91baa-e6dd-4d84-a89d-89fc458f15a9/746db1d5-a195-4dc1-833b-77c2a46f1a22
>Thread-3122::DEBUG::2014-03-19 15:12:01,068::fileVolume::529::Storage.Volume::(validateVolumePath) validate path for 2fbe976c-ab19-4bfb-9fce-94af66388c2e
>Thread-3122::DEBUG::2014-03-19 15:12:01,069::fileVolume::529::Storage.Volume::(validateVolumePath) validate path for d4c57797-a344-4079-92cf-2e07e0aced30
>Thread-3122::INFO::2014-03-19 15:12:01,070::logUtils::47::dispatcher::(wrapper) Run and protect: prepareImage, Return response: {'info': {'domainID': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9', 'volType': 'path', 'leaseOffset': 0, 'path': '/rhev/data-center/mnt/10.34.63.202:_mnt_export_nfs_lv3_lsvaty_nfs01/4cd91baa-e6dd-4d84-a89d-89fc458f15a9/images/746db1d5-a195-4dc1-833b-77c2a46f1a22/2fbe976c-ab19-4bfb-9fce-94af66388c2e', 'volumeID': '2fbe976c-ab19-4bfb-9fce-94af66388c2e', 'leasePath': '/rhev/data-center/mnt/10.34.63.202:_mnt_export_nfs_lv3_lsvaty_nfs01/4cd91baa-e6dd-4d84-a89d-89fc458f15a9/images/746db1d5-a195-4dc1-833b-77c2a46f1a22/2fbe976c-ab19-4bfb-9fce-94af66388c2e.lease', 'imageID': '746db1d5-a195-4dc1-833b-77c2a46f1a22'}, 'path': '/rhev/data-center/mnt/10.34.63.202:_mnt_export_nfs_lv3_lsvaty_nfs01/4cd91baa-e6dd-4d84-a89d-89fc458f15a9/images/746db1d5-a195-4dc1-833b-77c2a46f1a22/2fbe976c-ab19-4bfb-9fce-94af66388c2e', 'imgVolumesInfo': [{'domainID': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9', 'volType': 'path', 'leaseOffset': 0, 'path': '/rhev/data-center/mnt/10.34.63.202:_mnt_export_nfs_lv3_lsvaty_nfs01/4cd91baa-e6dd-4d84-a89d-89fc458f15a9/images/746db1d5-a195-4dc1-833b-77c2a46f1a22/2fbe976c-ab19-4bfb-9fce-94af66388c2e', 'volumeID': '2fbe976c-ab19-4bfb-9fce-94af66388c2e', 'leasePath': '/rhev/data-center/mnt/10.34.63.202:_mnt_export_nfs_lv3_lsvaty_nfs01/4cd91baa-e6dd-4d84-a89d-89fc458f15a9/images/746db1d5-a195-4dc1-833b-77c2a46f1a22/2fbe976c-ab19-4bfb-9fce-94af66388c2e.lease', 'imageID': '746db1d5-a195-4dc1-833b-77c2a46f1a22'}, {'domainID': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9', 'volType': 'path', 'leaseOffset': 0, 'path': '/rhev/data-center/mnt/10.34.63.202:_mnt_export_nfs_lv3_lsvaty_nfs01/4cd91baa-e6dd-4d84-a89d-89fc458f15a9/images/746db1d5-a195-4dc1-833b-77c2a46f1a22/d4c57797-a344-4079-92cf-2e07e0aced30', 'volumeID': 'd4c57797-a344-4079-92cf-2e07e0aced30', 'leasePath': '/rhev/data-center/mnt/10.34.63.202:_mnt_export_nfs_lv3_lsvaty_nfs01/4cd91baa-e6dd-4d84-a89d-89fc458f15a9/images/746db1d5-a195-4dc1-833b-77c2a46f1a22/d4c57797-a344-4079-92cf-2e07e0aced30.lease', 'imageID': '746db1d5-a195-4dc1-833b-77c2a46f1a22'}]}
>Thread-3122::INFO::2014-03-19 15:12:01,071::clientIF::324::vds::(prepareVolumePath) prepared volume path: /rhev/data-center/mnt/10.34.63.202:_mnt_export_nfs_lv3_lsvaty_nfs01/4cd91baa-e6dd-4d84-a89d-89fc458f15a9/images/746db1d5-a195-4dc1-833b-77c2a46f1a22/2fbe976c-ab19-4bfb-9fce-94af66388c2e
>Thread-3122::INFO::2014-03-19 15:12:01,071::logUtils::44::dispatcher::(wrapper) Run and protect: prepareImage(sdUUID='4cd91baa-e6dd-4d84-a89d-89fc458f15a9', spUUID='00000002-0002-0002-0002-000000000394', imgUUID='efd305ae-6a25-4f32-88fe-b8930849c936', leafUUID='5037acb2-df07-45c2-909f-044acb0611ec')
>Thread-3122::WARNING::2014-03-19 15:12:01,074::fileUtils::167::Storage.fileUtils::(createdir) Dir /var/run/vdsm/storage/4cd91baa-e6dd-4d84-a89d-89fc458f15a9 already exists
>Thread-3122::DEBUG::2014-03-19 15:12:01,074::fileSD::446::Storage.StorageDomain::(createImageLinks) img run dir already exists: /var/run/vdsm/storage/4cd91baa-e6dd-4d84-a89d-89fc458f15a9/efd305ae-6a25-4f32-88fe-b8930849c936
>Thread-3122::DEBUG::2014-03-19 15:12:01,075::fileVolume::529::Storage.Volume::(validateVolumePath) validate path for 5037acb2-df07-45c2-909f-044acb0611ec
>Thread-3122::INFO::2014-03-19 15:12:01,075::logUtils::47::dispatcher::(wrapper) Run and protect: prepareImage, Return response: {'info': {'domainID': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9', 'volType': 'path', 'leaseOffset': 0, 'path': '/rhev/data-center/mnt/10.34.63.202:_mnt_export_nfs_lv3_lsvaty_nfs01/4cd91baa-e6dd-4d84-a89d-89fc458f15a9/images/efd305ae-6a25-4f32-88fe-b8930849c936/5037acb2-df07-45c2-909f-044acb0611ec', 'volumeID': '5037acb2-df07-45c2-909f-044acb0611ec', 'leasePath': '/rhev/data-center/mnt/10.34.63.202:_mnt_export_nfs_lv3_lsvaty_nfs01/4cd91baa-e6dd-4d84-a89d-89fc458f15a9/images/efd305ae-6a25-4f32-88fe-b8930849c936/5037acb2-df07-45c2-909f-044acb0611ec.lease', 'imageID': 'efd305ae-6a25-4f32-88fe-b8930849c936'}, 'path': '/rhev/data-center/mnt/10.34.63.202:_mnt_export_nfs_lv3_lsvaty_nfs01/4cd91baa-e6dd-4d84-a89d-89fc458f15a9/images/efd305ae-6a25-4f32-88fe-b8930849c936/5037acb2-df07-45c2-909f-044acb0611ec', 'imgVolumesInfo': [{'domainID': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9', 'volType': 'path', 'leaseOffset': 0, 'path': '/rhev/data-center/mnt/10.34.63.202:_mnt_export_nfs_lv3_lsvaty_nfs01/4cd91baa-e6dd-4d84-a89d-89fc458f15a9/images/efd305ae-6a25-4f32-88fe-b8930849c936/5037acb2-df07-45c2-909f-044acb0611ec', 'volumeID': '5037acb2-df07-45c2-909f-044acb0611ec', 'leasePath': '/rhev/data-center/mnt/10.34.63.202:_mnt_export_nfs_lv3_lsvaty_nfs01/4cd91baa-e6dd-4d84-a89d-89fc458f15a9/images/efd305ae-6a25-4f32-88fe-b8930849c936/5037acb2-df07-45c2-909f-044acb0611ec.lease', 'imageID': 'efd305ae-6a25-4f32-88fe-b8930849c936'}]}
>Thread-3122::INFO::2014-03-19 15:12:01,076::clientIF::324::vds::(prepareVolumePath) prepared volume path: /rhev/data-center/mnt/10.34.63.202:_mnt_export_nfs_lv3_lsvaty_nfs01/4cd91baa-e6dd-4d84-a89d-89fc458f15a9/images/efd305ae-6a25-4f32-88fe-b8930849c936/5037acb2-df07-45c2-909f-044acb0611ec
>Thread-3122::DEBUG::2014-03-19 15:12:01,085::vm::3136::vm.Vm::(_run) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::<?xml version="1.0" encoding="utf-8"?>
><domain type="kvm">
>	<name>a</name>
>	<uuid>e6b03061-7a3b-46f4-9fff-a786b9d501d9</uuid>
>	<memory>1048576</memory>
>	<currentMemory>1048576</currentMemory>
>	<vcpu current="1">160</vcpu>
>	<memtune>
>		<min_guarantee>1048576</min_guarantee>
>	</memtune>
>	<devices>
>		<channel type="unix">
>			<target name="com.redhat.rhevm.vdsm" type="virtio"/>
>			<source mode="bind" path="/var/lib/libvirt/qemu/channels/e6b03061-7a3b-46f4-9fff-a786b9d501d9.com.redhat.rhevm.vdsm"/>
>		</channel>
>		<channel type="unix">
>			<target name="org.qemu.guest_agent.0" type="virtio"/>
>			<source mode="bind" path="/var/lib/libvirt/qemu/channels/e6b03061-7a3b-46f4-9fff-a786b9d501d9.org.qemu.guest_agent.0"/>
>		</channel>
>		<input bus="ps2" type="mouse"/>
>		<channel type="spicevmc">
>			<target name="com.redhat.spice.0" type="virtio"/>
>		</channel>
>		<graphics autoport="yes" keymap="en-us" listen="0" passwd="*****" passwdValidTo="1970-01-01T00:00:01" port="-1" tlsPort="-1" type="spice">
>			<channel mode="secure" name="main"/>
>			<channel mode="secure" name="inputs"/>
>			<channel mode="secure" name="cursor"/>
>			<channel mode="secure" name="playback"/>
>			<channel mode="secure" name="record"/>
>			<channel mode="secure" name="display"/>
>			<channel mode="secure" name="usbredir"/>
>			<channel mode="secure" name="smartcard"/>
>		</graphics>
>		<memballoon model="virtio"/>
>		<controller index="0" model="virtio-scsi" type="scsi">
>			<address bus="0x00" domain="0x0000" function="0x0" slot="0x04" type="pci"/>
>		</controller>
>		<video>
>			<address bus="0x00" domain="0x0000" function="0x0" slot="0x02" type="pci"/>
>			<model heads="1" type="qxl" vram="32768"/>
>		</video>
>		<interface type="bridge">
>			<address bus="0x00" domain="0x0000" function="0x0" slot="0x03" type="pci"/>
>			<mac address="00:1a:4a:30:54:9c"/>
>			<model type="virtio"/>
>			<source bridge="rhevm"/>
>			<filterref filter="vdsm-no-mac-spoofing"/>
>			<link state="up"/>
>		</interface>
>		<disk device="cdrom" snapshot="no" type="file">
>			<address bus="1" controller="0" target="0" type="drive" unit="0"/>
>			<source file="" startupPolicy="optional"/>
>			<target bus="ide" dev="hdc"/>
>			<readonly/>
>			<serial/>
>		</disk>
>		<disk device="disk" snapshot="no" type="file">
>			<address bus="0x00" domain="0x0000" function="0x0" slot="0x06" type="pci"/>
>			<source file="/rhev/data-center/mnt/10.34.63.202:_mnt_export_nfs_lv3_lsvaty_nfs01/4cd91baa-e6dd-4d84-a89d-89fc458f15a9/images/746db1d5-a195-4dc1-833b-77c2a46f1a22/2fbe976c-ab19-4bfb-9fce-94af66388c2e"/>
>			<target bus="virtio" dev="vda"/>
>			<serial>746db1d5-a195-4dc1-833b-77c2a46f1a22</serial>
>			<boot order="1"/>
>			<driver cache="none" error_policy="stop" io="threads" name="qemu" type="qcow2"/>
>		</disk>
>		<disk device="disk" snapshot="no" type="file">
>			<address bus="0x00" domain="0x0000" function="0x0" slot="0x08" type="pci"/>
>			<source file="/rhev/data-center/mnt/10.34.63.202:_mnt_export_nfs_lv3_lsvaty_nfs01/4cd91baa-e6dd-4d84-a89d-89fc458f15a9/images/efd305ae-6a25-4f32-88fe-b8930849c936/5037acb2-df07-45c2-909f-044acb0611ec"/>
>			<target bus="virtio" dev="vdb"/>
>			<serial>efd305ae-6a25-4f32-88fe-b8930849c936</serial>
>			<driver cache="none" error_policy="stop" io="threads" name="qemu" type="raw"/>
>		</disk>
>	</devices>
>	<os>
>		<type arch="x86_64" machine="rhel6.5.0">hvm</type>
>		<smbios mode="sysinfo"/>
>	</os>
>	<sysinfo type="smbios">
>		<system>
>			<entry name="manufacturer">oVirt</entry>
>			<entry name="product">oVirt Node</entry>
>			<entry name="version">6Server-6.5.0.1.el6</entry>
>			<entry name="serial">4C4C4544-0034-5310-8052-B2C04F4A354A</entry>
>			<entry name="uuid">e6b03061-7a3b-46f4-9fff-a786b9d501d9</entry>
>		</system>
>	</sysinfo>
>	<clock adjustment="-18000" offset="variable">
>		<timer name="rtc" tickpolicy="catchup"/>
>	</clock>
>	<features>
>		<acpi/>
>	</features>
>	<cpu match="exact">
>		<model>Westmere</model>
>		<topology cores="1" sockets="160" threads="1"/>
>	</cpu>
></domain>
>
>libvirtEventLoop::DEBUG::2014-03-19 15:12:01,634::vm::5130::vm.Vm::(_onLibvirtLifecycleEvent) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::event Started detail 0 opaque None
>Thread-3122::DEBUG::2014-03-19 15:12:01,653::vm::4986::vm.Vm::(_getUnderlyingDriveInfo) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::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-3122::DEBUG::2014-03-19 15:12:01,653::vm::5007::vm.Vm::(_getUnderlyingDriveInfo) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::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-3122::DEBUG::2014-03-19 15:12:01,653::vm::5026::vm.Vm::(_getUnderlyingDriveInfo) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::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-3122::DEBUG::2014-03-19 15:12:01,654::vm::4986::vm.Vm::(_getUnderlyingDriveInfo) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Looking for drive with attributes {'name': u'vda', 'bootOrder': u'1', 'boot': [<DOM Element: boot at 0x7f64842894d0>], '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.34.63.202:_mnt_export_nfs_lv3_lsvaty_nfs01/4cd91baa-e6dd-4d84-a89d-89fc458f15a9/images/746db1d5-a195-4dc1-833b-77c2a46f1a22/2fbe976c-ab19-4bfb-9fce-94af66388c2e', 'type': u'disk'}
>Thread-3122::DEBUG::2014-03-19 15:12:01,654::vm::5007::vm.Vm::(_getUnderlyingDriveInfo) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Matched {'name': (u'vda', u'vda'), 'bootOrder': (u'1', u'1'), 'boot': ([<DOM Element: boot at 0x7f64842894d0>], 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.34.63.202:_mnt_export_nfs_lv3_lsvaty_nfs01/4cd91baa-e6dd-4d84-a89d-89fc458f15a9/images/746db1d5-a195-4dc1-833b-77c2a46f1a22/2fbe976c-ab19-4bfb-9fce-94af66388c2e', '/rhev/data-center/mnt/10.34.63.202:_mnt_export_nfs_lv3_lsvaty_nfs01/4cd91baa-e6dd-4d84-a89d-89fc458f15a9/images/746db1d5-a195-4dc1-833b-77c2a46f1a22/2fbe976c-ab19-4bfb-9fce-94af66388c2e'), 'type': (u'disk', u'disk')}
>Thread-3122::DEBUG::2014-03-19 15:12:01,654::vm::5026::vm.Vm::(_getUnderlyingDriveInfo) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Matched {'name': (u'vda', u'vda'), 'bootOrder': (u'1', u'1'), 'boot': ([<DOM Element: boot at 0x7f64842894d0>], 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.34.63.202:_mnt_export_nfs_lv3_lsvaty_nfs01/4cd91baa-e6dd-4d84-a89d-89fc458f15a9/images/746db1d5-a195-4dc1-833b-77c2a46f1a22/2fbe976c-ab19-4bfb-9fce-94af66388c2e', '/rhev/data-center/mnt/10.34.63.202:_mnt_export_nfs_lv3_lsvaty_nfs01/4cd91baa-e6dd-4d84-a89d-89fc458f15a9/images/746db1d5-a195-4dc1-833b-77c2a46f1a22/2fbe976c-ab19-4bfb-9fce-94af66388c2e'), 'type': (u'disk', 'disk')}
>Thread-3122::DEBUG::2014-03-19 15:12:01,655::vm::4986::vm.Vm::(_getUnderlyingDriveInfo) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Looking for drive with attributes {'name': u'vdb', 'bootOrder': '', 'boot': [], 'readonly': False, 'address': {u'slot': u'0x08', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, 'path': u'/rhev/data-center/mnt/10.34.63.202:_mnt_export_nfs_lv3_lsvaty_nfs01/4cd91baa-e6dd-4d84-a89d-89fc458f15a9/images/efd305ae-6a25-4f32-88fe-b8930849c936/5037acb2-df07-45c2-909f-044acb0611ec', 'type': u'disk'}
>Thread-3122::DEBUG::2014-03-19 15:12:01,655::vm::5007::vm.Vm::(_getUnderlyingDriveInfo) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Matched {'name': (u'vdb', u'vdb'), 'bootOrder': ('', None), 'boot': ([], None), 'readonly': (False, False), 'address': ({u'slot': u'0x08', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, {u'slot': u'0x08', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}), 'path': (u'/rhev/data-center/mnt/10.34.63.202:_mnt_export_nfs_lv3_lsvaty_nfs01/4cd91baa-e6dd-4d84-a89d-89fc458f15a9/images/efd305ae-6a25-4f32-88fe-b8930849c936/5037acb2-df07-45c2-909f-044acb0611ec', '/rhev/data-center/mnt/10.34.63.202:_mnt_export_nfs_lv3_lsvaty_nfs01/4cd91baa-e6dd-4d84-a89d-89fc458f15a9/images/efd305ae-6a25-4f32-88fe-b8930849c936/5037acb2-df07-45c2-909f-044acb0611ec'), 'type': (u'disk', u'disk')}
>Thread-3122::DEBUG::2014-03-19 15:12:01,655::vm::5026::vm.Vm::(_getUnderlyingDriveInfo) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Matched {'name': (u'vdb', u'vdb'), 'bootOrder': ('', None), 'boot': ([], None), 'readonly': (False, 'False'), 'address': ({u'slot': u'0x08', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, {u'slot': u'0x08', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}), 'path': (u'/rhev/data-center/mnt/10.34.63.202:_mnt_export_nfs_lv3_lsvaty_nfs01/4cd91baa-e6dd-4d84-a89d-89fc458f15a9/images/efd305ae-6a25-4f32-88fe-b8930849c936/5037acb2-df07-45c2-909f-044acb0611ec', '/rhev/data-center/mnt/10.34.63.202:_mnt_export_nfs_lv3_lsvaty_nfs01/4cd91baa-e6dd-4d84-a89d-89fc458f15a9/images/efd305ae-6a25-4f32-88fe-b8930849c936/5037acb2-df07-45c2-909f-044acb0611ec'), 'type': (u'disk', 'disk')}
>Thread-3122::DEBUG::2014-03-19 15:12:01,691::sampling::285::vm.Vm::(start) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Start statistics collection
>Thread-3124::DEBUG::2014-03-19 15:12:01,691::sampling::314::vm.Vm::(run) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Stats thread started
>Thread-3124::INFO::2014-03-19 15:12:01,692::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='4cd91baa-e6dd-4d84-a89d-89fc458f15a9', spUUID='00000002-0002-0002-0002-000000000394', imgUUID='746db1d5-a195-4dc1-833b-77c2a46f1a22', volUUID='2fbe976c-ab19-4bfb-9fce-94af66388c2e', options=None)
>Thread-3124::INFO::2014-03-19 15:12:01,694::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '88940544', 'apparentsize': '88997888'}
>Thread-3122::DEBUG::2014-03-19 15:12:01,694::vmChannels::194::vds::(register) Add fileno 40 to listener's channels.
>Thread-3124::INFO::2014-03-19 15:12:01,695::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='4cd91baa-e6dd-4d84-a89d-89fc458f15a9', spUUID='00000002-0002-0002-0002-000000000394', imgUUID='efd305ae-6a25-4f32-88fe-b8930849c936', volUUID='5037acb2-df07-45c2-909f-044acb0611ec', options=None)
>Thread-3124::INFO::2014-03-19 15:12:01,697::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '6442455040', 'apparentsize': '6442450944'}
>Thread-3122::WARNING::2014-03-19 15:12:01,697::vm::3661::vm.Vm::(_readPauseCode) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::_readPauseCode unsupported by libvirt vm
>Thread-3122::DEBUG::2014-03-19 15:12:01,749::vm::2263::vm.Vm::(_startUnderlyingVm) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::_ongoingCreations released
>VM Channels Listener::DEBUG::2014-03-19 15:12:01,885::vmChannels::102::vds::(_do_add_channels) fileno 40 was added to unconnected channels.
>VM Channels Listener::DEBUG::2014-03-19 15:12:01,885::vmChannels::128::vds::(_handle_unconnected) Trying to connect fileno 40.
>VM Channels Listener::DEBUG::2014-03-19 15:12:01,886::guestIF::147::vm.Vm::(_connect) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Attempting connection to /var/lib/libvirt/qemu/channels/e6b03061-7a3b-46f4-9fff-a786b9d501d9.com.redhat.rhevm.vdsm
>VM Channels Listener::DEBUG::2014-03-19 15:12:01,887::guestIF::150::vm.Vm::(_connect) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Connected to /var/lib/libvirt/qemu/channels/e6b03061-7a3b-46f4-9fff-a786b9d501d9.com.redhat.rhevm.vdsm
>VM Channels Listener::DEBUG::2014-03-19 15:12:01,887::vmChannels::144::vds::(_handle_unconnected) Connecting to fileno 40 succeeded.
>Thread-2636::INFO::2014-03-19 15:12:02,002::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-2636::INFO::2014-03-19 15:12:02,002::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'4cd91baa-e6dd-4d84-a89d-89fc458f15a9': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000259338', 'lastCheck': '8.8', 'valid': True}}
>Thread-2636::DEBUG::2014-03-19 15:12:02,023::vm::587::vm.Vm::(_getCpuStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::CPU stats not available: 'NoneType' object is unsubscriptable
>Thread-2636::DEBUG::2014-03-19 15:12:02,023::vm::623::vm.Vm::(_getNetworkStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Network stats not available
>Thread-2636::DEBUG::2014-03-19 15:12:02,023::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk hdc stats not available
>Thread-2636::DEBUG::2014-03-19 15:12:02,023::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vda stats not available
>Thread-2636::DEBUG::2014-03-19 15:12:02,023::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vdb stats not available
>Thread-2636::DEBUG::2014-03-19 15:12:02,023::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk hdc latency not available
>Thread-2636::DEBUG::2014-03-19 15:12:02,023::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vda latency not available
>Thread-2636::DEBUG::2014-03-19 15:12:02,024::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vdb latency not available
>Thread-71::DEBUG::2014-03-19 15:12:03,199::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.34.63.202:_mnt_export_nfs_lv3_lsvaty_nfs01/4cd91baa-e6dd-4d84-a89d-89fc458f15a9/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-71::DEBUG::2014-03-19 15:12:03,205::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n476 bytes (476 B) copied, 0.000238241 s, 2.0 MB/s\n'; <rc> = 0
>Thread-2636::DEBUG::2014-03-19 15:12:05,086::BindingXMLRPC::1067::vds::(wrapper) client [10.34.63.60]::call vmGetStats with ('e6b03061-7a3b-46f4-9fff-a786b9d501d9',) {}
>Thread-2636::DEBUG::2014-03-19 15:12:05,086::vm::587::vm.Vm::(_getCpuStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::CPU stats not available: 'NoneType' object is unsubscriptable
>Thread-2636::DEBUG::2014-03-19 15:12:05,087::vm::623::vm.Vm::(_getNetworkStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Network stats not available
>Thread-2636::DEBUG::2014-03-19 15:12:05,087::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk hdc stats not available
>Thread-2636::DEBUG::2014-03-19 15:12:05,087::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vda stats not available
>Thread-2636::DEBUG::2014-03-19 15:12:05,087::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vdb stats not available
>Thread-2636::DEBUG::2014-03-19 15:12:05,087::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk hdc latency not available
>Thread-2636::DEBUG::2014-03-19 15:12:05,087::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vda latency not available
>Thread-2636::DEBUG::2014-03-19 15:12:05,087::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vdb latency not available
>Thread-2636::DEBUG::2014-03-19 15:12:05,088::BindingXMLRPC::1074::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Powering up', 'username': 'Unknown', 'memUsage': '0', 'acpiEnable': 'true', 'guestFQDN': '', 'pid': '12262', 'displayIp': '0', 'displayPort': u'5900', 'session': 'Unknown', 'displaySecurePort': u'5901', 'timeOffset': '-18000', 'hash': '671271088921175215', 'balloonInfo': {'balloon_max': '1048576', 'balloon_target': '1048576', 'balloon_cur': '1048576', 'balloon_min': '1048576'}, 'pauseCode': 'NOERR', 'clientIp': '', 'kvmEnable': 'true', 'network': {u'vnet0': {'state': 'unknown', 'macAddr': '00:1a:4a:30:54:9c', 'speed': '1000', 'name': u'vnet0'}}, 'vmId': 'e6b03061-7a3b-46f4-9fff-a786b9d501d9', 'displayType': 'qxl', 'cpuUser': '0.00', 'disks': {u'vda': {'truesize': '88940544', 'apparentsize': '88997888', 'imageID': '746db1d5-a195-4dc1-833b-77c2a46f1a22'}, u'vdb': {'truesize': '6442455040', 'apparentsize': '6442450944', 'imageID': 'efd305ae-6a25-4f32-88fe-b8930849c936'}, u'hdc': {'truesize': '0', 'apparentsize': '0'}}, 'monitorResponse': '0', 'statsAge': '1.30', 'elapsedTime': '4', 'vmType': 'kvm', 'cpuSys': '0.00', 'appsList': [], 'guestIPs': ''}]}
>Thread-3125::DEBUG::2014-03-19 15:12:05,102::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-3125::INFO::2014-03-19 15:12:05,102::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3125::INFO::2014-03-19 15:12:05,121::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 2, 'spmStatus': 'SPM', 'spmLver': 5L}}
>Thread-3118::DEBUG::2014-03-19 15:12:05,166::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-3118::INFO::2014-03-19 15:12:05,166::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3118::INFO::2014-03-19 15:12:05,168::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9:Active', 'master_uuid': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9', 'version': '3', 'spm_id': 2, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'4cd91baa-e6dd-4d84-a89d-89fc458f15a9': {'status': 'Active', 'diskfree': '282360545280', 'isoprefix': '', 'alerts': [], 'disktotal': '422758580224', 'version': 3}}}
>GuestMonitor-a::DEBUG::2014-03-19 15:12:05,489::vm::587::vm.Vm::(_getCpuStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::CPU stats not available: 'NoneType' object is unsubscriptable
>GuestMonitor-a::DEBUG::2014-03-19 15:12:05,490::vm::623::vm.Vm::(_getNetworkStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Network stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:05,490::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk hdc stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:05,490::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vda stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:05,490::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vdb stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:05,490::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk hdc latency not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:05,490::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vda latency not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:05,490::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vdb latency not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:05,491::vm::587::vm.Vm::(_getCpuStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::CPU stats not available: 'NoneType' object is unsubscriptable
>GuestMonitor-a::DEBUG::2014-03-19 15:12:05,491::vm::623::vm.Vm::(_getNetworkStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Network stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:05,491::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk hdc stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:05,492::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vda stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:05,492::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vdb stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:05,492::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk hdc latency not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:05,492::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vda latency not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:05,492::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vdb latency not available
>Thread-3125::DEBUG::2014-03-19 15:12:08,110::BindingXMLRPC::1067::vds::(wrapper) client [10.34.63.60]::call vmGetStats with ('e6b03061-7a3b-46f4-9fff-a786b9d501d9',) {}
>Thread-3125::DEBUG::2014-03-19 15:12:08,111::vm::587::vm.Vm::(_getCpuStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::CPU stats not available: 'NoneType' object is unsubscriptable
>Thread-3125::DEBUG::2014-03-19 15:12:08,111::vm::623::vm.Vm::(_getNetworkStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Network stats not available
>Thread-3125::DEBUG::2014-03-19 15:12:08,111::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk hdc stats not available
>Thread-3125::DEBUG::2014-03-19 15:12:08,111::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vda stats not available
>Thread-3125::DEBUG::2014-03-19 15:12:08,111::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vdb stats not available
>Thread-3125::DEBUG::2014-03-19 15:12:08,111::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk hdc latency not available
>Thread-3125::DEBUG::2014-03-19 15:12:08,111::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vda latency not available
>Thread-3125::DEBUG::2014-03-19 15:12:08,112::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vdb latency not available
>Thread-3125::DEBUG::2014-03-19 15:12:08,116::BindingXMLRPC::1074::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Powering up', 'username': 'Unknown', 'memUsage': '0', 'acpiEnable': 'true', 'guestFQDN': '', 'pid': '12262', 'displayIp': '0', 'displayPort': u'5900', 'session': 'Unknown', 'displaySecurePort': u'5901', 'timeOffset': '-18000', 'hash': '671271088921175215', 'balloonInfo': {'balloon_max': '1048576', 'balloon_target': '1048576', 'balloon_cur': '1048576', 'balloon_min': '1048576'}, 'pauseCode': 'NOERR', 'clientIp': '', 'kvmEnable': 'true', 'network': {u'vnet0': {'state': 'unknown', 'macAddr': '00:1a:4a:30:54:9c', 'speed': '1000', 'name': u'vnet0'}}, 'vmId': 'e6b03061-7a3b-46f4-9fff-a786b9d501d9', 'displayType': 'qxl', 'cpuUser': '0.00', 'disks': {u'vda': {'truesize': '88940544', 'apparentsize': '88997888', 'imageID': '746db1d5-a195-4dc1-833b-77c2a46f1a22'}, u'vdb': {'truesize': '6442455040', 'apparentsize': '6442450944', 'imageID': 'efd305ae-6a25-4f32-88fe-b8930849c936'}, u'hdc': {'truesize': '0', 'apparentsize': '0'}}, 'monitorResponse': '0', 'statsAge': '0.33', 'elapsedTime': '7', 'vmType': 'kvm', 'cpuSys': '0.00', 'appsList': [], 'guestIPs': ''}]}
>GuestMonitor-a::DEBUG::2014-03-19 15:12:10,496::vm::587::vm.Vm::(_getCpuStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::CPU stats not available: 'NoneType' object is unsubscriptable
>GuestMonitor-a::DEBUG::2014-03-19 15:12:10,497::vm::623::vm.Vm::(_getNetworkStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Network stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:10,497::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk hdc stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:10,497::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vda stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:10,497::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vdb stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:10,497::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk hdc latency not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:10,497::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vda latency not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:10,498::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vdb latency not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:10,498::vm::587::vm.Vm::(_getCpuStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::CPU stats not available: 'NoneType' object is unsubscriptable
>GuestMonitor-a::DEBUG::2014-03-19 15:12:10,499::vm::623::vm.Vm::(_getNetworkStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Network stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:10,499::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk hdc stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:10,499::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vda stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:10,499::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vdb stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:10,499::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk hdc latency not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:10,499::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vda latency not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:10,499::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vdb latency not available
>Thread-3125::DEBUG::2014-03-19 15:12:11,136::BindingXMLRPC::1067::vds::(wrapper) client [10.34.63.60]::call vmGetStats with ('e6b03061-7a3b-46f4-9fff-a786b9d501d9',) {}
>Thread-3125::DEBUG::2014-03-19 15:12:11,136::vm::587::vm.Vm::(_getCpuStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::CPU stats not available: 'NoneType' object is unsubscriptable
>Thread-3125::DEBUG::2014-03-19 15:12:11,137::vm::623::vm.Vm::(_getNetworkStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Network stats not available
>Thread-3125::DEBUG::2014-03-19 15:12:11,137::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk hdc stats not available
>Thread-3125::DEBUG::2014-03-19 15:12:11,137::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vda stats not available
>Thread-3125::DEBUG::2014-03-19 15:12:11,137::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vdb stats not available
>Thread-3125::DEBUG::2014-03-19 15:12:11,137::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk hdc latency not available
>Thread-3125::DEBUG::2014-03-19 15:12:11,137::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vda latency not available
>Thread-3125::DEBUG::2014-03-19 15:12:11,137::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vdb latency not available
>Thread-3125::DEBUG::2014-03-19 15:12:11,138::BindingXMLRPC::1074::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Powering up', 'username': 'Unknown', 'memUsage': '0', 'acpiEnable': 'true', 'guestFQDN': '', 'pid': '12262', 'displayIp': '0', 'displayPort': u'5900', 'session': 'Unknown', 'displaySecurePort': u'5901', 'timeOffset': '-18000', 'hash': '671271088921175215', 'balloonInfo': {'balloon_max': '1048576', 'balloon_target': '1048576', 'balloon_cur': '1048576', 'balloon_min': '1048576'}, 'pauseCode': 'NOERR', 'clientIp': '', 'kvmEnable': 'true', 'network': {u'vnet0': {'state': 'unknown', 'macAddr': '00:1a:4a:30:54:9c', 'speed': '1000', 'name': u'vnet0'}}, 'vmId': 'e6b03061-7a3b-46f4-9fff-a786b9d501d9', 'displayType': 'qxl', 'cpuUser': '0.00', 'disks': {u'vda': {'truesize': '88940544', 'apparentsize': '88997888', 'imageID': '746db1d5-a195-4dc1-833b-77c2a46f1a22'}, u'vdb': {'truesize': '6442455040', 'apparentsize': '6442450944', 'imageID': 'efd305ae-6a25-4f32-88fe-b8930849c936'}, u'hdc': {'truesize': '0', 'apparentsize': '0'}}, 'monitorResponse': '0', 'statsAge': '1.35', 'elapsedTime': '10', 'vmType': 'kvm', 'cpuSys': '0.00', 'appsList': [], 'guestIPs': ''}]}
>Thread-71::DEBUG::2014-03-19 15:12:13,215::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.34.63.202:_mnt_export_nfs_lv3_lsvaty_nfs01/4cd91baa-e6dd-4d84-a89d-89fc458f15a9/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-71::DEBUG::2014-03-19 15:12:13,222::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n476 bytes (476 B) copied, 0.000224057 s, 2.1 MB/s\n'; <rc> = 0
>Thread-3125::DEBUG::2014-03-19 15:12:14,159::BindingXMLRPC::1067::vds::(wrapper) client [10.34.63.60]::call vmGetStats with ('e6b03061-7a3b-46f4-9fff-a786b9d501d9',) {}
>Thread-3125::DEBUG::2014-03-19 15:12:14,159::vm::587::vm.Vm::(_getCpuStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::CPU stats not available: 'NoneType' object is unsubscriptable
>Thread-3125::DEBUG::2014-03-19 15:12:14,159::vm::623::vm.Vm::(_getNetworkStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Network stats not available
>Thread-3125::DEBUG::2014-03-19 15:12:14,160::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk hdc stats not available
>Thread-3125::DEBUG::2014-03-19 15:12:14,160::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vda stats not available
>Thread-3125::DEBUG::2014-03-19 15:12:14,160::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vdb stats not available
>Thread-3125::DEBUG::2014-03-19 15:12:14,160::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk hdc latency not available
>Thread-3125::DEBUG::2014-03-19 15:12:14,160::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vda latency not available
>Thread-3125::DEBUG::2014-03-19 15:12:14,160::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vdb latency not available
>Thread-3125::DEBUG::2014-03-19 15:12:14,161::BindingXMLRPC::1074::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Powering up', 'username': 'Unknown', 'memUsage': '0', 'acpiEnable': 'true', 'guestFQDN': '', 'pid': '12262', 'displayIp': '0', 'displayPort': u'5900', 'session': 'Unknown', 'displaySecurePort': u'5901', 'timeOffset': '-18000', 'hash': '671271088921175215', 'balloonInfo': {'balloon_max': '1048576', 'balloon_target': '1048576', 'balloon_cur': '1048576', 'balloon_min': '1048576'}, 'pauseCode': 'NOERR', 'clientIp': '', 'kvmEnable': 'true', 'network': {u'vnet0': {'state': 'unknown', 'macAddr': '00:1a:4a:30:54:9c', 'speed': '1000', 'name': u'vnet0'}}, 'vmId': 'e6b03061-7a3b-46f4-9fff-a786b9d501d9', 'displayType': 'qxl', 'cpuUser': '0.00', 'disks': {u'vda': {'truesize': '88940544', 'apparentsize': '88997888', 'imageID': '746db1d5-a195-4dc1-833b-77c2a46f1a22'}, u'vdb': {'truesize': '6442455040', 'apparentsize': '6442450944', 'imageID': 'efd305ae-6a25-4f32-88fe-b8930849c936'}, u'hdc': {'truesize': '0', 'apparentsize': '0'}}, 'monitorResponse': '0', 'statsAge': '0.38', 'elapsedTime': '13', 'vmType': 'kvm', 'cpuSys': '0.00', 'appsList': [], 'guestIPs': ''}]}
>Thread-3125::DEBUG::2014-03-19 15:12:15,186::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-3125::INFO::2014-03-19 15:12:15,187::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3125::INFO::2014-03-19 15:12:15,198::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 2, 'spmStatus': 'SPM', 'spmLver': 5L}}
>Thread-3118::DEBUG::2014-03-19 15:12:15,243::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-3118::INFO::2014-03-19 15:12:15,244::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3118::INFO::2014-03-19 15:12:15,247::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9:Active', 'master_uuid': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9', 'version': '3', 'spm_id': 2, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'4cd91baa-e6dd-4d84-a89d-89fc458f15a9': {'status': 'Active', 'diskfree': '282360545280', 'isoprefix': '', 'alerts': [], 'disktotal': '422758580224', 'version': 3}}}
>GuestMonitor-a::DEBUG::2014-03-19 15:12:15,504::vm::587::vm.Vm::(_getCpuStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::CPU stats not available: 'NoneType' object is unsubscriptable
>GuestMonitor-a::DEBUG::2014-03-19 15:12:15,504::vm::623::vm.Vm::(_getNetworkStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Network stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:15,504::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk hdc stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:15,504::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vda stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:15,504::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vdb stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:15,504::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk hdc latency not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:15,505::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vda latency not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:15,505::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vdb latency not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:15,505::vm::587::vm.Vm::(_getCpuStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::CPU stats not available: 'NoneType' object is unsubscriptable
>GuestMonitor-a::DEBUG::2014-03-19 15:12:15,506::vm::623::vm.Vm::(_getNetworkStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Network stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:15,506::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk hdc stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:15,506::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vda stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:15,506::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vdb stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:15,506::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk hdc latency not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:15,506::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vda latency not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:15,506::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vdb latency not available
>Thread-3125::INFO::2014-03-19 15:12:17,179::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-3125::INFO::2014-03-19 15:12:17,179::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'4cd91baa-e6dd-4d84-a89d-89fc458f15a9': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000224057', 'lastCheck': '4.0', 'valid': True}}
>Thread-3125::DEBUG::2014-03-19 15:12:17,197::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk hdc stats not available
>Thread-3125::DEBUG::2014-03-19 15:12:17,197::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vda stats not available
>Thread-3125::DEBUG::2014-03-19 15:12:17,197::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vdb stats not available
>Thread-3125::DEBUG::2014-03-19 15:12:17,197::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk hdc latency not available
>Thread-3125::DEBUG::2014-03-19 15:12:17,197::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vda latency not available
>Thread-3125::DEBUG::2014-03-19 15:12:17,197::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vdb latency not available
>Thread-3125::DEBUG::2014-03-19 15:12:20,246::BindingXMLRPC::1067::vds::(wrapper) client [10.34.63.60]::call vmGetStats with ('e6b03061-7a3b-46f4-9fff-a786b9d501d9',) {}
>Thread-3125::DEBUG::2014-03-19 15:12:20,247::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk hdc stats not available
>Thread-3125::DEBUG::2014-03-19 15:12:20,247::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vda stats not available
>Thread-3125::DEBUG::2014-03-19 15:12:20,247::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vdb stats not available
>Thread-3125::DEBUG::2014-03-19 15:12:20,247::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk hdc latency not available
>Thread-3125::DEBUG::2014-03-19 15:12:20,247::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vda latency not available
>Thread-3125::DEBUG::2014-03-19 15:12:20,247::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vdb latency not available
>Thread-3125::DEBUG::2014-03-19 15:12:20,248::BindingXMLRPC::1074::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Powering up', 'username': 'Unknown', 'memUsage': '0', 'acpiEnable': 'true', 'guestFQDN': '', 'pid': '12262', 'displayIp': '0', 'displayPort': u'5900', 'session': 'Unknown', 'displaySecurePort': u'5901', 'timeOffset': '-18000', 'hash': '671271088921175215', 'balloonInfo': {'balloon_max': '1048576', 'balloon_target': '1048576', 'balloon_cur': '1048576', 'balloon_min': '1048576'}, 'pauseCode': 'NOERR', 'clientIp': '', 'kvmEnable': 'true', 'network': {u'vnet0': {'macAddr': '00:1a:4a:30:54:9c', 'rxDropped': '0', 'rxErrors': '0', 'txDropped': '0', 'txRate': '0.0', 'rxRate': '0.0', 'txErrors': '0', 'state': 'unknown', 'speed': '1000', 'name': u'vnet0'}}, 'vmId': 'e6b03061-7a3b-46f4-9fff-a786b9d501d9', 'displayType': 'qxl', 'cpuUser': '42.94', 'disks': {u'vda': {'truesize': '88940544', 'apparentsize': '88997888', 'imageID': '746db1d5-a195-4dc1-833b-77c2a46f1a22'}, u'vdb': {'truesize': '6442455040', 'apparentsize': '6442450944', 'imageID': 'efd305ae-6a25-4f32-88fe-b8930849c936'}, u'hdc': {'truesize': '0', 'apparentsize': '0'}}, 'monitorResponse': '0', 'statsAge': '0.46', 'elapsedTime': '19', 'vmType': 'kvm', 'cpuSys': '27.51', 'appsList': [], 'guestIPs': ''}]}
>GuestMonitor-a::DEBUG::2014-03-19 15:12:20,509::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk hdc stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:20,509::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vda stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:20,509::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vdb stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:20,509::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk hdc latency not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:20,509::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vda latency not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:20,510::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vdb latency not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:20,511::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk hdc stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:20,511::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vda stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:20,511::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vdb stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:20,511::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk hdc latency not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:20,511::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vda latency not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:20,511::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vdb latency not available
>Thread-71::DEBUG::2014-03-19 15:12:23,230::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.34.63.202:_mnt_export_nfs_lv3_lsvaty_nfs01/4cd91baa-e6dd-4d84-a89d-89fc458f15a9/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-71::DEBUG::2014-03-19 15:12:23,237::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n476 bytes (476 B) copied, 0.00017991 s, 2.6 MB/s\n'; <rc> = 0
>Thread-3125::DEBUG::2014-03-19 15:12:23,278::BindingXMLRPC::1067::vds::(wrapper) client [10.34.63.60]::call vmGetStats with ('e6b03061-7a3b-46f4-9fff-a786b9d501d9',) {}
>Thread-3125::DEBUG::2014-03-19 15:12:23,278::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk hdc stats not available
>Thread-3125::DEBUG::2014-03-19 15:12:23,279::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vda stats not available
>Thread-3125::DEBUG::2014-03-19 15:12:23,279::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vdb stats not available
>Thread-3125::DEBUG::2014-03-19 15:12:23,279::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk hdc latency not available
>Thread-3125::DEBUG::2014-03-19 15:12:23,279::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vda latency not available
>Thread-3125::DEBUG::2014-03-19 15:12:23,279::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vdb latency not available
>Thread-3125::DEBUG::2014-03-19 15:12:23,280::BindingXMLRPC::1074::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Powering up', 'username': 'Unknown', 'memUsage': '0', 'acpiEnable': 'true', 'guestFQDN': '', 'pid': '12262', 'displayIp': '0', 'displayPort': u'5900', 'session': 'Unknown', 'displaySecurePort': u'5901', 'timeOffset': '-18000', 'hash': '671271088921175215', 'balloonInfo': {'balloon_max': '1048576', 'balloon_target': '1048576', 'balloon_cur': '1048576', 'balloon_min': '1048576'}, 'pauseCode': 'NOERR', 'clientIp': '', 'kvmEnable': 'true', 'network': {u'vnet0': {'macAddr': '00:1a:4a:30:54:9c', 'rxDropped': '0', 'rxErrors': '0', 'txDropped': '0', 'txRate': '0.0', 'rxRate': '0.0', 'txErrors': '0', 'state': 'unknown', 'speed': '1000', 'name': u'vnet0'}}, 'vmId': 'e6b03061-7a3b-46f4-9fff-a786b9d501d9', 'displayType': 'qxl', 'cpuUser': '42.94', 'disks': {u'vda': {'truesize': '88940544', 'apparentsize': '88997888', 'imageID': '746db1d5-a195-4dc1-833b-77c2a46f1a22'}, u'vdb': {'truesize': '6442455040', 'apparentsize': '6442450944', 'imageID': 'efd305ae-6a25-4f32-88fe-b8930849c936'}, u'hdc': {'truesize': '0', 'apparentsize': '0'}}, 'monitorResponse': '0', 'statsAge': '1.49', 'elapsedTime': '22', 'vmType': 'kvm', 'cpuSys': '27.51', 'appsList': [], 'guestIPs': ''}]}
>VM Channels Listener::DEBUG::2014-03-19 15:12:24,405::guestIF::209::vm.Vm::(_handleMessage) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::username: u'None'
>VM Channels Listener::DEBUG::2014-03-19 15:12:24,663::guestIF::209::vm.Vm::(_handleMessage) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::username: u'None'
>Thread-3125::DEBUG::2014-03-19 15:12:25,288::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-3125::INFO::2014-03-19 15:12:25,288::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3125::INFO::2014-03-19 15:12:25,299::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 2, 'spmStatus': 'SPM', 'spmLver': 5L}}
>Thread-3118::DEBUG::2014-03-19 15:12:25,304::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-3118::INFO::2014-03-19 15:12:25,304::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3118::INFO::2014-03-19 15:12:25,307::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9:Active', 'master_uuid': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9', 'version': '3', 'spm_id': 2, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'4cd91baa-e6dd-4d84-a89d-89fc458f15a9': {'status': 'Active', 'diskfree': '282360545280', 'isoprefix': '', 'alerts': [], 'disktotal': '422758580224', 'version': 3}}}
>GuestMonitor-a::DEBUG::2014-03-19 15:12:25,517::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk hdc stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:25,518::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vda stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:25,518::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vdb stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:25,518::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk hdc latency not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:25,518::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vda latency not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:25,518::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vdb latency not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:25,519::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk hdc stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:25,519::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vda stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:25,519::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vdb stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:25,519::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk hdc latency not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:25,519::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vda latency not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:25,520::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vdb latency not available
>Thread-3125::DEBUG::2014-03-19 15:12:26,307::BindingXMLRPC::1067::vds::(wrapper) client [10.34.63.60]::call vmGetStats with ('e6b03061-7a3b-46f4-9fff-a786b9d501d9',) {}
>Thread-3125::DEBUG::2014-03-19 15:12:26,308::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk hdc stats not available
>Thread-3125::DEBUG::2014-03-19 15:12:26,308::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vda stats not available
>Thread-3125::DEBUG::2014-03-19 15:12:26,308::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vdb stats not available
>Thread-3125::DEBUG::2014-03-19 15:12:26,308::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk hdc latency not available
>Thread-3125::DEBUG::2014-03-19 15:12:26,308::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vda latency not available
>Thread-3125::DEBUG::2014-03-19 15:12:26,308::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vdb latency not available
>Thread-3125::DEBUG::2014-03-19 15:12:26,309::BindingXMLRPC::1074::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'username': u'None', 'memUsage': '0', 'acpiEnable': 'true', 'guestFQDN': u'localhost.localdomain', 'pid': '12262', 'session': 'Unknown', 'displaySecurePort': u'5901', 'timeOffset': '-18000', 'balloonInfo': {'balloon_max': '1048576', 'balloon_target': '1048576', 'balloon_cur': '1048576', 'balloon_min': '1048576'}, 'pauseCode': 'NOERR', 'disksUsage': [{u'path': u'/', u'total': '3525586944', u'used': '1355542528', u'fs': u'ext4'}, {u'path': u'/boot', u'total': '507744256', u'used': '35372032', u'fs': u'ext4'}, {u'path': u'/home', u'total': '178723840', u'used': '5783552', u'fs': u'ext4'}], 'network': {u'vnet0': {'macAddr': '00:1a:4a:30:54:9c', 'rxDropped': '0', 'rxErrors': '0', 'txDropped': '0', 'txRate': '0.0', 'rxRate': '0.0', 'txErrors': '0', 'state': 'unknown', 'speed': '1000', 'name': u'vnet0'}}, 'vmType': 'kvm', 'guestName': u'localhost.localdomain', 'elapsedTime': '25', 'memoryStats': {}, 'cpuSys': '27.51', 'appsList': [u'kernel-2.6.32-431.el6'], 'guestOs': u'2.6.32-431.el6.x86_64', 'displayType': 'qxl', 'status': 'Up', 'hash': '671271088921175215', 'vmId': 'e6b03061-7a3b-46f4-9fff-a786b9d501d9', 'displayIp': '0', 'displayPort': u'5900', 'clientIp': '', 'kvmEnable': 'true', 'disks': {u'vda': {'truesize': '88940544', 'apparentsize': '88997888', 'imageID': '746db1d5-a195-4dc1-833b-77c2a46f1a22'}, u'vdb': {'truesize': '6442455040', 'apparentsize': '6442450944', 'imageID': 'efd305ae-6a25-4f32-88fe-b8930849c936'}, u'hdc': {'truesize': '0', 'apparentsize': '0'}}, 'monitorResponse': '0', 'statsAge': '0.52', 'cpuUser': '42.94', 'lastLogin': 1395238344.4050529, 'guestIPs': u'10.34.60.180', 'netIfaces': [{u'hw': u'00:1a:4a:30:54:9c', u'name': u'eth0', u'inet': [u'10.34.60.180'], u'inet6': []}]}]}
>GuestMonitor-a::DEBUG::2014-03-19 15:12:30,525::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk hdc stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:30,526::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vda stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:30,526::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vdb stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:30,526::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk hdc latency not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:30,526::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vda latency not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:30,526::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vdb latency not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:30,527::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk hdc stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:30,527::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vda stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:30,527::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vdb stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:30,527::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk hdc latency not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:30,527::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vda latency not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:30,528::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vdb latency not available
>Thread-3125::INFO::2014-03-19 15:12:32,352::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-3125::INFO::2014-03-19 15:12:32,353::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'4cd91baa-e6dd-4d84-a89d-89fc458f15a9': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.00017991', 'lastCheck': '9.1', 'valid': True}}
>Thread-3125::DEBUG::2014-03-19 15:12:32,366::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk hdc stats not available
>Thread-3125::DEBUG::2014-03-19 15:12:32,366::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vda stats not available
>Thread-3125::DEBUG::2014-03-19 15:12:32,366::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vdb stats not available
>Thread-3125::DEBUG::2014-03-19 15:12:32,367::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk hdc latency not available
>Thread-3125::DEBUG::2014-03-19 15:12:32,367::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vda latency not available
>Thread-3125::DEBUG::2014-03-19 15:12:32,367::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vdb latency not available
>Thread-71::DEBUG::2014-03-19 15:12:33,245::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.34.63.202:_mnt_export_nfs_lv3_lsvaty_nfs01/4cd91baa-e6dd-4d84-a89d-89fc458f15a9/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-71::DEBUG::2014-03-19 15:12:33,251::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n476 bytes (476 B) copied, 0.00028466 s, 1.7 MB/s\n'; <rc> = 0
>Thread-3125::DEBUG::2014-03-19 15:12:35,360::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-3125::INFO::2014-03-19 15:12:35,361::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3125::INFO::2014-03-19 15:12:35,373::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 2, 'spmStatus': 'SPM', 'spmLver': 5L}}
>Thread-3118::DEBUG::2014-03-19 15:12:35,417::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-3118::INFO::2014-03-19 15:12:35,418::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3118::INFO::2014-03-19 15:12:35,420::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9:Active', 'master_uuid': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9', 'version': '3', 'spm_id': 2, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'4cd91baa-e6dd-4d84-a89d-89fc458f15a9': {'status': 'Active', 'diskfree': '282360545280', 'isoprefix': '', 'alerts': [], 'disktotal': '422758580224', 'version': 3}}}
>GuestMonitor-a::DEBUG::2014-03-19 15:12:35,534::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk hdc stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:35,534::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vda stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:35,534::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vdb stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:35,534::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk hdc latency not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:35,534::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vda latency not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:35,534::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vdb latency not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:35,535::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk hdc stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:35,535::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vda stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:35,535::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vdb stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:35,535::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk hdc latency not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:35,536::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vda latency not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:35,536::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vdb latency not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:40,542::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk hdc stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:40,542::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vda stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:40,543::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vdb stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:40,543::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk hdc latency not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:40,543::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vda latency not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:40,544::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vdb latency not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:40,544::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk hdc stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:40,545::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vda stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:40,545::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vdb stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:40,545::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk hdc latency not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:40,545::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vda latency not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:40,545::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vdb latency not available
>Thread-71::DEBUG::2014-03-19 15:12:43,258::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.34.63.202:_mnt_export_nfs_lv3_lsvaty_nfs01/4cd91baa-e6dd-4d84-a89d-89fc458f15a9/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-71::DEBUG::2014-03-19 15:12:43,264::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n476 bytes (476 B) copied, 0.000241575 s, 2.0 MB/s\n'; <rc> = 0
>Thread-3125::DEBUG::2014-03-19 15:12:45,438::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-3125::INFO::2014-03-19 15:12:45,439::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3125::INFO::2014-03-19 15:12:45,452::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 2, 'spmStatus': 'SPM', 'spmLver': 5L}}
>Thread-3118::DEBUG::2014-03-19 15:12:45,457::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-3118::INFO::2014-03-19 15:12:45,457::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3118::INFO::2014-03-19 15:12:45,459::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9:Active', 'master_uuid': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9', 'version': '3', 'spm_id': 2, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'4cd91baa-e6dd-4d84-a89d-89fc458f15a9': {'status': 'Active', 'diskfree': '282360545280', 'isoprefix': '', 'alerts': [], 'disktotal': '422758580224', 'version': 3}}}
>GuestMonitor-a::DEBUG::2014-03-19 15:12:45,548::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk hdc stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:45,549::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vda stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:45,550::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vdb stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:45,550::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk hdc latency not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:45,550::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vda latency not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:45,550::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vdb latency not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:45,551::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk hdc stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:45,551::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vda stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:45,551::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vdb stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:45,551::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk hdc latency not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:45,551::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vda latency not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:45,552::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vdb latency not available
>Thread-3125::INFO::2014-03-19 15:12:47,468::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-3125::INFO::2014-03-19 15:12:47,468::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'4cd91baa-e6dd-4d84-a89d-89fc458f15a9': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000241575', 'lastCheck': '4.2', 'valid': True}}
>Thread-3125::DEBUG::2014-03-19 15:12:47,483::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk hdc stats not available
>Thread-3125::DEBUG::2014-03-19 15:12:47,483::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vda stats not available
>Thread-3125::DEBUG::2014-03-19 15:12:47,483::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vdb stats not available
>Thread-3125::DEBUG::2014-03-19 15:12:47,483::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk hdc latency not available
>Thread-3125::DEBUG::2014-03-19 15:12:47,483::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vda latency not available
>Thread-3125::DEBUG::2014-03-19 15:12:47,483::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vdb latency not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:50,557::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk hdc stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:50,558::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vda stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:50,559::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vdb stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:50,559::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk hdc latency not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:50,559::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vda latency not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:50,559::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vdb latency not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:50,560::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk hdc stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:50,560::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vda stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:50,560::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vdb stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:50,560::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk hdc latency not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:50,560::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vda latency not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:50,560::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vdb latency not available
>Thread-71::DEBUG::2014-03-19 15:12:53,271::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.34.63.202:_mnt_export_nfs_lv3_lsvaty_nfs01/4cd91baa-e6dd-4d84-a89d-89fc458f15a9/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-71::DEBUG::2014-03-19 15:12:53,277::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n476 bytes (476 B) copied, 0.000298192 s, 1.6 MB/s\n'; <rc> = 0
>Thread-3125::DEBUG::2014-03-19 15:12:55,478::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-3125::INFO::2014-03-19 15:12:55,478::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3125::INFO::2014-03-19 15:12:55,490::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 2, 'spmStatus': 'SPM', 'spmLver': 5L}}
>Thread-3118::DEBUG::2014-03-19 15:12:55,495::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-3118::INFO::2014-03-19 15:12:55,495::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3118::INFO::2014-03-19 15:12:55,497::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9:Active', 'master_uuid': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9', 'version': '3', 'spm_id': 2, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'4cd91baa-e6dd-4d84-a89d-89fc458f15a9': {'status': 'Active', 'diskfree': '282360545280', 'isoprefix': '', 'alerts': [], 'disktotal': '422758580224', 'version': 3}}}
>GuestMonitor-a::DEBUG::2014-03-19 15:12:55,566::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk hdc stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:55,566::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vda stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:55,567::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vdb stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:55,567::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk hdc latency not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:55,567::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vda latency not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:55,567::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vdb latency not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:55,568::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk hdc stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:55,568::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vda stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:55,568::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vdb stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:55,568::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk hdc latency not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:55,568::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vda latency not available
>GuestMonitor-a::DEBUG::2014-03-19 15:12:55,569::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vdb latency not available
>GuestMonitor-a::DEBUG::2014-03-19 15:13:00,574::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk hdc stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:13:00,575::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vda stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:13:00,575::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vdb stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:13:00,575::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk hdc latency not available
>GuestMonitor-a::DEBUG::2014-03-19 15:13:00,575::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vda latency not available
>GuestMonitor-a::DEBUG::2014-03-19 15:13:00,575::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vdb latency not available
>GuestMonitor-a::DEBUG::2014-03-19 15:13:00,576::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk hdc stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:13:00,576::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vda stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:13:00,577::vm::645::vm.Vm::(_getDiskStats) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vdb stats not available
>GuestMonitor-a::DEBUG::2014-03-19 15:13:00,577::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk hdc latency not available
>GuestMonitor-a::DEBUG::2014-03-19 15:13:00,577::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vda latency not available
>GuestMonitor-a::DEBUG::2014-03-19 15:13:00,577::vm::684::vm.Vm::(_getDiskLatency) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::Disk vdb latency not available
>Thread-3124::INFO::2014-03-19 15:13:01,795::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='4cd91baa-e6dd-4d84-a89d-89fc458f15a9', spUUID='00000002-0002-0002-0002-000000000394', imgUUID='746db1d5-a195-4dc1-833b-77c2a46f1a22', volUUID='2fbe976c-ab19-4bfb-9fce-94af66388c2e', options=None)
>Thread-3124::INFO::2014-03-19 15:13:01,797::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '88940544', 'apparentsize': '88997888'}
>Thread-3124::INFO::2014-03-19 15:13:01,798::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='4cd91baa-e6dd-4d84-a89d-89fc458f15a9', spUUID='00000002-0002-0002-0002-000000000394', imgUUID='efd305ae-6a25-4f32-88fe-b8930849c936', volUUID='5037acb2-df07-45c2-909f-044acb0611ec', options=None)
>Thread-3124::INFO::2014-03-19 15:13:01,799::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '6442455040', 'apparentsize': '6442450944'}
>Thread-3125::INFO::2014-03-19 15:13:02,573::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-3125::INFO::2014-03-19 15:13:02,573::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'4cd91baa-e6dd-4d84-a89d-89fc458f15a9': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000298192', 'lastCheck': '9.3', 'valid': True}}
>Thread-71::DEBUG::2014-03-19 15:13:03,285::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.34.63.202:_mnt_export_nfs_lv3_lsvaty_nfs01/4cd91baa-e6dd-4d84-a89d-89fc458f15a9/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-71::DEBUG::2014-03-19 15:13:03,290::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n476 bytes (476 B) copied, 0.00021615 s, 2.2 MB/s\n'; <rc> = 0
>Thread-3125::DEBUG::2014-03-19 15:13:05,516::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-3125::INFO::2014-03-19 15:13:05,517::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3125::INFO::2014-03-19 15:13:05,529::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 2, 'spmStatus': 'SPM', 'spmLver': 5L}}
>Thread-3118::DEBUG::2014-03-19 15:13:05,533::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-3118::INFO::2014-03-19 15:13:05,534::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3118::INFO::2014-03-19 15:13:05,536::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9:Active', 'master_uuid': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9', 'version': '3', 'spm_id': 2, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'4cd91baa-e6dd-4d84-a89d-89fc458f15a9': {'status': 'Active', 'diskfree': '282360545280', 'isoprefix': '', 'alerts': [], 'disktotal': '422758580224', 'version': 3}}}
>Thread-3125::DEBUG::2014-03-19 15:13:10,464::BindingXMLRPC::1067::vds::(wrapper) client [10.34.63.60]::call vmSetTicket with ('e6b03061-7a3b-46f4-9fff-a786b9d501d9', 'zQSUkaJ2LNDD', '120', 'disconnect', {'userName': 'admin', 'userId': 'fdfc627c-d875-11e0-90f0-83df133b58cc'}) {} flowID [6783256]
>Thread-3125::DEBUG::2014-03-19 15:13:10,510::BindingXMLRPC::1074::vds::(wrapper) return vmSetTicket with {'status': {'message': 'Done', 'code': 0}}
>Thread-71::DEBUG::2014-03-19 15:13:13,297::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.34.63.202:_mnt_export_nfs_lv3_lsvaty_nfs01/4cd91baa-e6dd-4d84-a89d-89fc458f15a9/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-71::DEBUG::2014-03-19 15:13:13,302::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n476 bytes (476 B) copied, 0.000226897 s, 2.1 MB/s\n'; <rc> = 0
>libvirtEventLoop::DEBUG::2014-03-19 15:13:13,653::clientIF::555::vm.Vm::(dispatchLibvirtEvents) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::graphics event phase 0 localAddr {'node': '10.34.62.203', 'service': '', 'family': 0} remoteAddr {'node': '10.34.131.169', 'service': '', 'family': 0}authScheme  subject []
>libvirtEventLoop::DEBUG::2014-03-19 15:13:13,666::clientIF::555::vm.Vm::(dispatchLibvirtEvents) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::graphics event phase 1 localAddr {'node': '10.34.62.203', 'service': '', 'family': 0} remoteAddr {'node': '10.34.131.169', 'service': '', 'family': 0}authScheme spice subject []
>libvirtEventLoop::DEBUG::2014-03-19 15:13:13,670::clientIF::555::vm.Vm::(dispatchLibvirtEvents) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::graphics event phase 0 localAddr {'node': '10.34.62.203', 'service': '', 'family': 0} remoteAddr {'node': '10.34.131.169', 'service': '', 'family': 0}authScheme  subject []
>libvirtEventLoop::DEBUG::2014-03-19 15:13:13,686::clientIF::555::vm.Vm::(dispatchLibvirtEvents) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::graphics event phase 1 localAddr {'node': '10.34.62.203', 'service': '', 'family': 0} remoteAddr {'node': '10.34.131.169', 'service': '', 'family': 0}authScheme spice subject []
>libvirtEventLoop::DEBUG::2014-03-19 15:13:13,714::clientIF::555::vm.Vm::(dispatchLibvirtEvents) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::graphics event phase 0 localAddr {'node': '10.34.62.203', 'service': '', 'family': 0} remoteAddr {'node': '10.34.131.169', 'service': '', 'family': 0}authScheme  subject []
>libvirtEventLoop::DEBUG::2014-03-19 15:13:13,715::clientIF::555::vm.Vm::(dispatchLibvirtEvents) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::graphics event phase 0 localAddr {'node': '10.34.62.203', 'service': '', 'family': 0} remoteAddr {'node': '10.34.131.169', 'service': '', 'family': 0}authScheme  subject []
>libvirtEventLoop::DEBUG::2014-03-19 15:13:13,791::clientIF::555::vm.Vm::(dispatchLibvirtEvents) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::graphics event phase 1 localAddr {'node': '10.34.62.203', 'service': '', 'family': 0} remoteAddr {'node': '10.34.131.169', 'service': '', 'family': 0}authScheme spice subject []
>libvirtEventLoop::DEBUG::2014-03-19 15:13:13,793::clientIF::555::vm.Vm::(dispatchLibvirtEvents) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::graphics event phase 1 localAddr {'node': '10.34.62.203', 'service': '', 'family': 0} remoteAddr {'node': '10.34.131.169', 'service': '', 'family': 0}authScheme spice subject []
>Thread-3125::DEBUG::2014-03-19 15:13:15,557::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-3125::INFO::2014-03-19 15:13:15,557::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3125::INFO::2014-03-19 15:13:15,569::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 2, 'spmStatus': 'SPM', 'spmLver': 5L}}
>Thread-3118::DEBUG::2014-03-19 15:13:15,574::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-3118::INFO::2014-03-19 15:13:15,574::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3118::INFO::2014-03-19 15:13:15,576::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9:Active', 'master_uuid': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9', 'version': '3', 'spm_id': 2, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'4cd91baa-e6dd-4d84-a89d-89fc458f15a9': {'status': 'Active', 'diskfree': '282360545280', 'isoprefix': '', 'alerts': [], 'disktotal': '422758580224', 'version': 3}}}
>Thread-3125::INFO::2014-03-19 15:13:17,676::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-3125::INFO::2014-03-19 15:13:17,676::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'4cd91baa-e6dd-4d84-a89d-89fc458f15a9': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000226897', 'lastCheck': '4.4', 'valid': True}}
>Thread-71::DEBUG::2014-03-19 15:13:23,305::domainMonitor::192::Storage.DomainMonitorThread::(_monitorDomain) Refreshing domain 4cd91baa-e6dd-4d84-a89d-89fc458f15a9
>Thread-71::DEBUG::2014-03-19 15:13:23,309::fileSD::140::Storage.StorageDomain::(__init__) Reading domain in path /rhev/data-center/mnt/10.34.63.202:_mnt_export_nfs_lv3_lsvaty_nfs01/4cd91baa-e6dd-4d84-a89d-89fc458f15a9
>Thread-71::DEBUG::2014-03-19 15:13:23,310::persistentDict::192::Storage.PersistentDict::(__init__) Created a persistent dict with FileMetadataRW backend
>Thread-71::DEBUG::2014-03-19 15:13:23,314::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=nfs01', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=1', 'POOL_DESCRIPTION=Default', 'POOL_DOMAINS=4cd91baa-e6dd-4d84-a89d-89fc458f15a9:Active', 'POOL_SPM_ID=2', 'POOL_SPM_LVER=0', 'POOL_UUID=00000002-0002-0002-0002-000000000394', 'REMOTE_PATH=10.34.63.202:/mnt/export/nfs/lv3/lsvaty/nfs01', 'ROLE=Master', 'SDUUID=4cd91baa-e6dd-4d84-a89d-89fc458f15a9', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=086ee2e50523c4d577916ca1c6beebd47edd1c16']
>Thread-71::DEBUG::2014-03-19 15:13:23,315::fileSD::575::Storage.StorageDomain::(imageGarbageCollector) Removing remnants of deleted images []
>Thread-71::INFO::2014-03-19 15:13:23,316::sd::374::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace 4cd91baa-e6dd-4d84-a89d-89fc458f15a9_imageNS already registered
>Thread-71::INFO::2014-03-19 15:13:23,316::sd::382::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace 4cd91baa-e6dd-4d84-a89d-89fc458f15a9_volumeNS already registered
>Thread-71::DEBUG::2014-03-19 15:13:23,321::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.34.63.202:_mnt_export_nfs_lv3_lsvaty_nfs01/4cd91baa-e6dd-4d84-a89d-89fc458f15a9/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-71::DEBUG::2014-03-19 15:13:23,326::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n476 bytes (476 B) copied, 0.000225268 s, 2.1 MB/s\n'; <rc> = 0
>VM Channels Listener::DEBUG::2014-03-19 15:13:23,811::guestIF::209::vm.Vm::(_handleMessage) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::username: u'root'
>Thread-3125::DEBUG::2014-03-19 15:13:25,597::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-3125::INFO::2014-03-19 15:13:25,597::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3125::INFO::2014-03-19 15:13:25,609::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 2, 'spmStatus': 'SPM', 'spmLver': 5L}}
>Thread-3118::DEBUG::2014-03-19 15:13:25,614::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-3118::INFO::2014-03-19 15:13:25,615::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3118::INFO::2014-03-19 15:13:25,617::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9:Active', 'master_uuid': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9', 'version': '3', 'spm_id': 2, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'4cd91baa-e6dd-4d84-a89d-89fc458f15a9': {'status': 'Active', 'diskfree': '282360545280', 'isoprefix': '', 'alerts': [], 'disktotal': '422758580224', 'version': 3}}}
>libvirtEventLoop::DEBUG::2014-03-19 15:13:30,268::clientIF::555::vm.Vm::(dispatchLibvirtEvents) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::graphics event phase 2 localAddr {'node': '10.34.62.203', 'service': '', 'family': 0} remoteAddr {'node': '10.34.131.169', 'service': '', 'family': 0}authScheme  subject []
>libvirtEventLoop::DEBUG::2014-03-19 15:13:30,268::clientIF::555::vm.Vm::(dispatchLibvirtEvents) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::graphics event phase 2 localAddr {'node': '10.34.62.203', 'service': '', 'family': 0} remoteAddr {'node': '10.34.131.169', 'service': '', 'family': 0}authScheme spice subject []
>libvirtEventLoop::DEBUG::2014-03-19 15:13:30,269::clientIF::555::vm.Vm::(dispatchLibvirtEvents) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::graphics event phase 2 localAddr {'node': '10.34.62.203', 'service': '', 'family': 0} remoteAddr {'node': '10.34.131.169', 'service': '', 'family': 0}authScheme  subject []
>libvirtEventLoop::DEBUG::2014-03-19 15:13:30,269::clientIF::555::vm.Vm::(dispatchLibvirtEvents) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::graphics event phase 2 localAddr {'node': '10.34.62.203', 'service': '', 'family': 0} remoteAddr {'node': '10.34.131.169', 'service': '', 'family': 0}authScheme  subject []
>libvirtEventLoop::DEBUG::2014-03-19 15:13:30,270::clientIF::555::vm.Vm::(dispatchLibvirtEvents) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::graphics event phase 2 localAddr {'node': '10.34.62.203', 'service': '', 'family': 0} remoteAddr {'node': '10.34.131.169', 'service': '', 'family': 0}authScheme  subject []
>Thread-3128::DEBUG::2014-03-19 15:13:32,269::guestIF::278::vm.Vm::(desktopLock) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::desktopLock called
>Thread-3129::DEBUG::2014-03-19 15:13:32,269::guestIF::278::vm.Vm::(desktopLock) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::desktopLock called
>Thread-3130::DEBUG::2014-03-19 15:13:32,269::guestIF::278::vm.Vm::(desktopLock) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::desktopLock called
>Thread-3131::DEBUG::2014-03-19 15:13:32,270::guestIF::278::vm.Vm::(desktopLock) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::desktopLock called
>Thread-3132::DEBUG::2014-03-19 15:13:32,271::guestIF::278::vm.Vm::(desktopLock) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::desktopLock called
>Thread-3125::INFO::2014-03-19 15:13:32,793::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-3125::INFO::2014-03-19 15:13:32,793::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'4cd91baa-e6dd-4d84-a89d-89fc458f15a9': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000225268', 'lastCheck': '9.5', 'valid': True}}
>Thread-71::DEBUG::2014-03-19 15:13:33,334::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.34.63.202:_mnt_export_nfs_lv3_lsvaty_nfs01/4cd91baa-e6dd-4d84-a89d-89fc458f15a9/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-71::DEBUG::2014-03-19 15:13:33,339::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n476 bytes (476 B) copied, 0.00028455 s, 1.7 MB/s\n'; <rc> = 0
>Thread-3125::DEBUG::2014-03-19 15:13:35,635::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-3125::INFO::2014-03-19 15:13:35,636::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3125::INFO::2014-03-19 15:13:35,647::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 2, 'spmStatus': 'SPM', 'spmLver': 5L}}
>Thread-3118::DEBUG::2014-03-19 15:13:35,651::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-3118::INFO::2014-03-19 15:13:35,652::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3118::INFO::2014-03-19 15:13:35,654::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9:Active', 'master_uuid': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9', 'version': '3', 'spm_id': 2, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'4cd91baa-e6dd-4d84-a89d-89fc458f15a9': {'status': 'Active', 'diskfree': '282360545280', 'isoprefix': '', 'alerts': [], 'disktotal': '422758580224', 'version': 3}}}
>Thread-71::DEBUG::2014-03-19 15:13:43,348::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.34.63.202:_mnt_export_nfs_lv3_lsvaty_nfs01/4cd91baa-e6dd-4d84-a89d-89fc458f15a9/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-71::DEBUG::2014-03-19 15:13:43,354::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n476 bytes (476 B) copied, 0.000241714 s, 2.0 MB/s\n'; <rc> = 0
>Thread-3125::DEBUG::2014-03-19 15:13:45,673::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-3125::INFO::2014-03-19 15:13:45,673::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3125::INFO::2014-03-19 15:13:45,685::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 2, 'spmStatus': 'SPM', 'spmLver': 5L}}
>Thread-3118::DEBUG::2014-03-19 15:13:45,690::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-3118::INFO::2014-03-19 15:13:45,690::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3118::INFO::2014-03-19 15:13:45,692::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9:Active', 'master_uuid': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9', 'version': '3', 'spm_id': 2, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'4cd91baa-e6dd-4d84-a89d-89fc458f15a9': {'status': 'Active', 'diskfree': '282360545280', 'isoprefix': '', 'alerts': [], 'disktotal': '422758580224', 'version': 3}}}
>Thread-3125::INFO::2014-03-19 15:13:47,929::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-3125::INFO::2014-03-19 15:13:47,930::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'4cd91baa-e6dd-4d84-a89d-89fc458f15a9': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000241714', 'lastCheck': '4.6', 'valid': True}}
>Thread-71::DEBUG::2014-03-19 15:13:53,365::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.34.63.202:_mnt_export_nfs_lv3_lsvaty_nfs01/4cd91baa-e6dd-4d84-a89d-89fc458f15a9/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-71::DEBUG::2014-03-19 15:13:53,371::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n476 bytes (476 B) copied, 0.000257529 s, 1.8 MB/s\n'; <rc> = 0
>Thread-3125::DEBUG::2014-03-19 15:13:55,711::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-3125::INFO::2014-03-19 15:13:55,711::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3125::INFO::2014-03-19 15:13:55,723::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 2, 'spmStatus': 'SPM', 'spmLver': 5L}}
>Thread-3118::DEBUG::2014-03-19 15:13:55,728::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-3118::INFO::2014-03-19 15:13:55,729::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3118::INFO::2014-03-19 15:13:55,731::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9:Active', 'master_uuid': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9', 'version': '3', 'spm_id': 2, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'4cd91baa-e6dd-4d84-a89d-89fc458f15a9': {'status': 'Active', 'diskfree': '282360545280', 'isoprefix': '', 'alerts': [], 'disktotal': '422758580224', 'version': 3}}}
>Thread-3124::INFO::2014-03-19 15:14:01,853::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='4cd91baa-e6dd-4d84-a89d-89fc458f15a9', spUUID='00000002-0002-0002-0002-000000000394', imgUUID='746db1d5-a195-4dc1-833b-77c2a46f1a22', volUUID='2fbe976c-ab19-4bfb-9fce-94af66388c2e', options=None)
>Thread-3124::INFO::2014-03-19 15:14:01,855::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '89071616', 'apparentsize': '89128960'}
>Thread-3124::INFO::2014-03-19 15:14:01,855::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='4cd91baa-e6dd-4d84-a89d-89fc458f15a9', spUUID='00000002-0002-0002-0002-000000000394', imgUUID='efd305ae-6a25-4f32-88fe-b8930849c936', volUUID='5037acb2-df07-45c2-909f-044acb0611ec', options=None)
>Thread-3124::INFO::2014-03-19 15:14:01,857::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '6442455040', 'apparentsize': '6442450944'}
>Thread-3125::INFO::2014-03-19 15:14:03,050::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-3125::INFO::2014-03-19 15:14:03,051::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'4cd91baa-e6dd-4d84-a89d-89fc458f15a9': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000257529', 'lastCheck': '9.7', 'valid': True}}
>Thread-71::DEBUG::2014-03-19 15:14:03,380::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.34.63.202:_mnt_export_nfs_lv3_lsvaty_nfs01/4cd91baa-e6dd-4d84-a89d-89fc458f15a9/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-71::DEBUG::2014-03-19 15:14:03,385::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n476 bytes (476 B) copied, 0.000223045 s, 2.1 MB/s\n'; <rc> = 0
>Thread-3125::DEBUG::2014-03-19 15:14:05,749::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-3125::INFO::2014-03-19 15:14:05,749::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3125::INFO::2014-03-19 15:14:05,761::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 2, 'spmStatus': 'SPM', 'spmLver': 5L}}
>Thread-3118::DEBUG::2014-03-19 15:14:05,765::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-3118::INFO::2014-03-19 15:14:05,766::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3118::INFO::2014-03-19 15:14:05,768::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9:Active', 'master_uuid': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9', 'version': '3', 'spm_id': 2, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'4cd91baa-e6dd-4d84-a89d-89fc458f15a9': {'status': 'Active', 'diskfree': '282360545280', 'isoprefix': '', 'alerts': [], 'disktotal': '422758580224', 'version': 3}}}
>Thread-3125::DEBUG::2014-03-19 15:14:10,433::BindingXMLRPC::1067::vds::(wrapper) client [10.34.63.60]::call vmSetTicket with ('e6b03061-7a3b-46f4-9fff-a786b9d501d9', 'Y9dvLM6UFdpM', '120', 'disconnect', {'userName': 'admin', 'userId': 'fdfc627c-d875-11e0-90f0-83df133b58cc'}) {} flowID [2dcc0d69]
>Thread-3125::DEBUG::2014-03-19 15:14:10,486::BindingXMLRPC::1074::vds::(wrapper) return vmSetTicket with {'status': {'message': 'Done', 'code': 0}}
>Thread-71::DEBUG::2014-03-19 15:14:13,392::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.34.63.202:_mnt_export_nfs_lv3_lsvaty_nfs01/4cd91baa-e6dd-4d84-a89d-89fc458f15a9/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-71::DEBUG::2014-03-19 15:14:13,397::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n476 bytes (476 B) copied, 0.000277951 s, 1.7 MB/s\n'; <rc> = 0
>libvirtEventLoop::DEBUG::2014-03-19 15:14:13,633::clientIF::555::vm.Vm::(dispatchLibvirtEvents) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::graphics event phase 0 localAddr {'node': '10.34.62.203', 'service': '', 'family': 0} remoteAddr {'node': '10.34.131.169', 'service': '', 'family': 0}authScheme  subject []
>libvirtEventLoop::DEBUG::2014-03-19 15:14:13,645::clientIF::555::vm.Vm::(dispatchLibvirtEvents) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::graphics event phase 1 localAddr {'node': '10.34.62.203', 'service': '', 'family': 0} remoteAddr {'node': '10.34.131.169', 'service': '', 'family': 0}authScheme spice subject []
>libvirtEventLoop::DEBUG::2014-03-19 15:14:13,651::clientIF::555::vm.Vm::(dispatchLibvirtEvents) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::graphics event phase 0 localAddr {'node': '10.34.62.203', 'service': '', 'family': 0} remoteAddr {'node': '10.34.131.169', 'service': '', 'family': 0}authScheme  subject []
>libvirtEventLoop::DEBUG::2014-03-19 15:14:13,695::clientIF::555::vm.Vm::(dispatchLibvirtEvents) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::graphics event phase 1 localAddr {'node': '10.34.62.203', 'service': '', 'family': 0} remoteAddr {'node': '10.34.131.169', 'service': '', 'family': 0}authScheme spice subject []
>libvirtEventLoop::DEBUG::2014-03-19 15:14:13,757::clientIF::555::vm.Vm::(dispatchLibvirtEvents) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::graphics event phase 0 localAddr {'node': '10.34.62.203', 'service': '', 'family': 0} remoteAddr {'node': '10.34.131.169', 'service': '', 'family': 0}authScheme  subject []
>libvirtEventLoop::DEBUG::2014-03-19 15:14:13,757::clientIF::555::vm.Vm::(dispatchLibvirtEvents) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::graphics event phase 0 localAddr {'node': '10.34.62.203', 'service': '', 'family': 0} remoteAddr {'node': '10.34.131.169', 'service': '', 'family': 0}authScheme  subject []
>libvirtEventLoop::DEBUG::2014-03-19 15:14:13,804::clientIF::555::vm.Vm::(dispatchLibvirtEvents) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::graphics event phase 1 localAddr {'node': '10.34.62.203', 'service': '', 'family': 0} remoteAddr {'node': '10.34.131.169', 'service': '', 'family': 0}authScheme spice subject []
>libvirtEventLoop::DEBUG::2014-03-19 15:14:13,805::clientIF::555::vm.Vm::(dispatchLibvirtEvents) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::graphics event phase 1 localAddr {'node': '10.34.62.203', 'service': '', 'family': 0} remoteAddr {'node': '10.34.131.169', 'service': '', 'family': 0}authScheme spice subject []
>Thread-3125::DEBUG::2014-03-19 15:14:15,786::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-3125::INFO::2014-03-19 15:14:15,786::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3125::INFO::2014-03-19 15:14:15,798::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 2, 'spmStatus': 'SPM', 'spmLver': 5L}}
>Thread-3118::DEBUG::2014-03-19 15:14:15,803::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-3118::INFO::2014-03-19 15:14:15,803::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3118::INFO::2014-03-19 15:14:15,807::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9:Active', 'master_uuid': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9', 'version': '3', 'spm_id': 2, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'4cd91baa-e6dd-4d84-a89d-89fc458f15a9': {'status': 'Active', 'diskfree': '282360545280', 'isoprefix': '', 'alerts': [], 'disktotal': '422758580224', 'version': 3}}}
>Thread-3125::INFO::2014-03-19 15:14:18,163::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-3125::INFO::2014-03-19 15:14:18,164::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'4cd91baa-e6dd-4d84-a89d-89fc458f15a9': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000277951', 'lastCheck': '4.8', 'valid': True}}
>Thread-71::DEBUG::2014-03-19 15:14:23,406::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.34.63.202:_mnt_export_nfs_lv3_lsvaty_nfs01/4cd91baa-e6dd-4d84-a89d-89fc458f15a9/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-71::DEBUG::2014-03-19 15:14:23,411::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n476 bytes (476 B) copied, 0.000305478 s, 1.6 MB/s\n'; <rc> = 0
>Thread-3125::DEBUG::2014-03-19 15:14:25,825::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-3125::INFO::2014-03-19 15:14:25,826::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3125::INFO::2014-03-19 15:14:25,837::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 2, 'spmStatus': 'SPM', 'spmLver': 5L}}
>Thread-3118::DEBUG::2014-03-19 15:14:25,842::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-3118::INFO::2014-03-19 15:14:25,842::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3118::INFO::2014-03-19 15:14:25,845::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9:Active', 'master_uuid': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9', 'version': '3', 'spm_id': 2, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'4cd91baa-e6dd-4d84-a89d-89fc458f15a9': {'status': 'Active', 'diskfree': '282360545280', 'isoprefix': '', 'alerts': [], 'disktotal': '422758580224', 'version': 3}}}
>Thread-3125::INFO::2014-03-19 15:14:33,293::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-3125::INFO::2014-03-19 15:14:33,293::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'4cd91baa-e6dd-4d84-a89d-89fc458f15a9': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000305478', 'lastCheck': '9.9', 'valid': True}}
>Thread-71::DEBUG::2014-03-19 15:14:33,418::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.34.63.202:_mnt_export_nfs_lv3_lsvaty_nfs01/4cd91baa-e6dd-4d84-a89d-89fc458f15a9/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-71::DEBUG::2014-03-19 15:14:33,424::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n476 bytes (476 B) copied, 0.000260229 s, 1.8 MB/s\n'; <rc> = 0
>Thread-3125::DEBUG::2014-03-19 15:14:35,863::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60] flowID [3a8010b3]
>Thread-3125::INFO::2014-03-19 15:14:35,863::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3125::INFO::2014-03-19 15:14:35,874::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 2, 'spmStatus': 'SPM', 'spmLver': 5L}}
>Thread-3118::DEBUG::2014-03-19 15:14:35,878::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60] flowID [3a8010b3]
>Thread-3118::INFO::2014-03-19 15:14:35,879::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3118::INFO::2014-03-19 15:14:35,881::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9:Active', 'master_uuid': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9', 'version': '3', 'spm_id': 2, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'4cd91baa-e6dd-4d84-a89d-89fc458f15a9': {'status': 'Active', 'diskfree': '282360545280', 'isoprefix': '', 'alerts': [], 'disktotal': '422758580224', 'version': 3}}}
>Thread-71::DEBUG::2014-03-19 15:14:43,433::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.34.63.202:_mnt_export_nfs_lv3_lsvaty_nfs01/4cd91baa-e6dd-4d84-a89d-89fc458f15a9/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-71::DEBUG::2014-03-19 15:14:43,439::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n476 bytes (476 B) copied, 0.000234136 s, 2.0 MB/s\n'; <rc> = 0
>Thread-3125::DEBUG::2014-03-19 15:14:45,899::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-3125::INFO::2014-03-19 15:14:45,899::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3125::INFO::2014-03-19 15:14:45,911::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 2, 'spmStatus': 'SPM', 'spmLver': 5L}}
>Thread-3118::DEBUG::2014-03-19 15:14:45,916::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-3118::INFO::2014-03-19 15:14:45,916::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3118::INFO::2014-03-19 15:14:45,918::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9:Active', 'master_uuid': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9', 'version': '3', 'spm_id': 2, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'4cd91baa-e6dd-4d84-a89d-89fc458f15a9': {'status': 'Active', 'diskfree': '282360545280', 'isoprefix': '', 'alerts': [], 'disktotal': '422758580224', 'version': 3}}}
>Thread-3125::INFO::2014-03-19 15:14:48,416::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-3125::INFO::2014-03-19 15:14:48,416::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'4cd91baa-e6dd-4d84-a89d-89fc458f15a9': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000234136', 'lastCheck': '5.0', 'valid': True}}
>VM Channels Listener::DEBUG::2014-03-19 15:14:53,105::guestIF::219::vm.Vm::(_handleMessage) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::RHEV agent was uninstalled.
>VM Channels Listener::ERROR::2014-03-19 15:14:53,106::guestIF::334::vm.Vm::(_processMessage) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::No JSON object could be decoded: ''
>Thread-71::DEBUG::2014-03-19 15:14:53,447::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.34.63.202:_mnt_export_nfs_lv3_lsvaty_nfs01/4cd91baa-e6dd-4d84-a89d-89fc458f15a9/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-71::DEBUG::2014-03-19 15:14:53,452::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n476 bytes (476 B) copied, 0.000248307 s, 1.9 MB/s\n'; <rc> = 0
>Thread-3125::DEBUG::2014-03-19 15:14:55,937::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-3125::INFO::2014-03-19 15:14:55,937::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3125::INFO::2014-03-19 15:14:55,984::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 2, 'spmStatus': 'SPM', 'spmLver': 5L}}
>Thread-3118::DEBUG::2014-03-19 15:14:55,988::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-3118::INFO::2014-03-19 15:14:55,989::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3118::INFO::2014-03-19 15:14:55,991::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9:Active', 'master_uuid': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9', 'version': '3', 'spm_id': 2, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'4cd91baa-e6dd-4d84-a89d-89fc458f15a9': {'status': 'Active', 'diskfree': '282359496704', 'isoprefix': '', 'alerts': [], 'disktotal': '422758580224', 'version': 3}}}
>Thread-3118::DEBUG::2014-03-19 15:14:59,783::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-3118::INFO::2014-03-19 15:14:59,783::logUtils::44::dispatcher::(wrapper) Run and protect: updateVM(spUUID='00000002-0002-0002-0002-000000000394', vmList=[{'imglist': 'efd305ae-6a25-4f32-88fe-b8930849c936,746db1d5-a195-4dc1-833b-77c2a46f1a22', 'ovf': '<?xml version=\'1.0\' encoding=\'UTF-8\'?><ovf:Envelope xmlns:ovf="http://schemas.dmtf.org/ovf/envelope/1/" xmlns:rasd="http://schemas.dmtf.org/wbem/wscim/1/cim-schema/2/CIM_ResourceAllocationSettingData" xmlns:vssd="http://schemas.dmtf.org/wbem/wscim/1/cim-schema/2/CIM_VirtualSystemSettingData" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" ovf:version="3.4.0.0"><References><File ovf:href="746db1d5-a195-4dc1-833b-77c2a46f1a22/2fbe976c-ab19-4bfb-9fce-94af66388c2e" ovf:id="2fbe976c-ab19-4bfb-9fce-94af66388c2e" ovf:size="6442450944" ovf:description="Active VM"/><File ovf:href="746db1d5-a195-4dc1-833b-77c2a46f1a22/d4c57797-a344-4079-92cf-2e07e0aced30" ovf:id="d4c57797-a344-4079-92cf-2e07e0aced30" ovf:size="6442450944" ovf:description="snappy"/><File ovf:href="efd305ae-6a25-4f32-88fe-b8930849c936/5037acb2-df07-45c2-909f-044acb0611ec" ovf:id="5037acb2-df07-45c2-909f-044acb0611ec" ovf:size="6442450944" ovf:description="Active VM"/><Nic ovf:id="921515b8-8d80-4fb0-989b-ace2415fb852"/></References><Section xsi:type="ovf:NetworkSection_Type"><Info>List of networks</Info><Network ovf:name="Network 1"/></Section><Section xsi:type="ovf:DiskSection_Type"><Info>List of Virtual Disks</Info><Disk ovf:diskId="2fbe976c-ab19-4bfb-9fce-94af66388c2e" ovf:size="6" ovf:actual_size="0" ovf:vm_snapshot_id="2e980293-19da-4f66-a91e-babb6f981bdd" ovf:parentRef="746db1d5-a195-4dc1-833b-77c2a46f1a22/2fbe976c-ab19-4bfb-9fce-94af66388c2e" ovf:fileRef="746db1d5-a195-4dc1-833b-77c2a46f1a22/2fbe976c-ab19-4bfb-9fce-94af66388c2e" ovf:format="http://www.gnome.org/~markmc/qcow-image-format.html" ovf:volume-format="COW" ovf:volume-type="Sparse" ovf:disk-interface="VirtIO" ovf:boot="true" ovf:disk-alias="a_Disk1" ovf:wipe-after-delete="false"/><Disk ovf:diskId="d4c57797-a344-4079-92cf-2e07e0aced30" ovf:size="6" ovf:actual_size="1" ovf:vm_snapshot_id="ac5caf56-90e7-4ed1-a00c-69c6952c0f19" ovf:parentRef="" ovf:fileRef="746db1d5-a195-4dc1-833b-77c2a46f1a22/d4c57797-a344-4079-92cf-2e07e0aced30" ovf:format="http://www.vmware.com/specifications/vmdk.html#sparse" ovf:volume-format="RAW" ovf:volume-type="Sparse" ovf:disk-interface="VirtIO" ovf:boot="true" ovf:disk-alias="a_Disk1" ovf:wipe-after-delete="false"/><Disk ovf:diskId="5037acb2-df07-45c2-909f-044acb0611ec" ovf:size="6" ovf:actual_size="6" ovf:vm_snapshot_id="2e980293-19da-4f66-a91e-babb6f981bdd" ovf:parentRef="" ovf:fileRef="efd305ae-6a25-4f32-88fe-b8930849c936/5037acb2-df07-45c2-909f-044acb0611ec" ovf:format="http://www.vmware.com/specifications/vmdk.html#sparse" ovf:volume-format="RAW" ovf:volume-type="Preallocated" ovf:disk-interface="VirtIO" ovf:boot="false" ovf:disk-alias="a_Disk2" ovf:wipe-after-delete="false"/></Section><Content ovf:id="out" xsi:type="ovf:VirtualSystem_Type"><Description></Description><CreationDate>2014/03/13 21:45:30</CreationDate><ExportDate>2014/03/19 14:14:59</ExportDate><DeleteProtected>false</DeleteProtected><SsoMethod>guest_agent</SsoMethod><IsSmartcardEnabled>false</IsSmartcardEnabled><TimeZone>SA Pacific Standard Time</TimeZone><default_boot_sequence>0</default_boot_sequence><Generation>12</Generation><VmType>1</VmType><MinAllocatedMem>1024</MinAllocatedMem><IsStateless>false</IsStateless><IsRunAndPause>false</IsRunAndPause><CreatedByUserId>fdfc627c-d875-11e0-90f0-83df133b58cc</CreatedByUserId><Name>a</Name><TemplateId>00000000-0000-0000-0000-000000000000</TemplateId><TemplateName>Blank</TemplateName><IsInitilized>true</IsInitilized><Origin>3</Origin><app_list>kernel-2.6.32-431.el6</app_list><DefaultDisplayType>1</DefaultDisplayType><TrustedService>false</TrustedService><OriginalTemplateId>00000000-0000-0000-0000-000000000000</OriginalTemplateId><OriginalTemplateName>Blank</OriginalTemplateName><AutoStartup>true</AutoStartup><UseLatestVersion>false</UseLatestVersion><Section ovf:id="e6b03061-7a3b-46f4-9fff-a786b9d501d9" ovf:required="false" xsi:type="ovf:OperatingSystemSection_Type"><Info>Guest Operating System</Info><Description>windows_7x64</Description></Section><Section xsi:type="ovf:VirtualHardwareSection_Type"><Info>1 CPU, 1024 Memeory</Info><System><vssd:VirtualSystemType>ENGINE 3.4.0.0</vssd:VirtualSystemType></System><Item><rasd:Caption>1 virtual cpu</rasd:Caption><rasd:Description>Number of virtual CPU</rasd:Description><rasd:InstanceId>1</rasd:InstanceId><rasd:ResourceType>3</rasd:ResourceType><rasd:num_of_sockets>1</rasd:num_of_sockets><rasd:cpu_per_socket>1</rasd:cpu_per_socket></Item><Item><rasd:Caption>1024 MB of memory</rasd:Caption><rasd:Description>Memory Size</rasd:Description><rasd:InstanceId>2</rasd:InstanceId><rasd:ResourceType>4</rasd:ResourceType><rasd:AllocationUnits>MegaBytes</rasd:AllocationUnits><rasd:VirtualQuantity>1024</rasd:VirtualQuantity></Item><Item><rasd:Caption>a_Disk1</rasd:Caption><rasd:InstanceId>2fbe976c-ab19-4bfb-9fce-94af66388c2e</rasd:InstanceId><rasd:ResourceType>17</rasd:ResourceType><rasd:HostResource>746db1d5-a195-4dc1-833b-77c2a46f1a22/2fbe976c-ab19-4bfb-9fce-94af66388c2e</rasd:HostResource><rasd:Parent>d4c57797-a344-4079-92cf-2e07e0aced30</rasd:Parent><rasd:Template>00000000-0000-0000-0000-000000000000</rasd:Template><rasd:ApplicationList></rasd:ApplicationList><rasd:StorageId>4cd91baa-e6dd-4d84-a89d-89fc458f15a9</rasd:StorageId><rasd:StoragePoolId>00000002-0002-0002-0002-000000000394</rasd:StoragePoolId><rasd:CreationDate>2014/03/16 10:02:23</rasd:CreationDate><rasd:LastModified>2014/03/16 10:02:23</rasd:LastModified><rasd:last_modified_date>2014/03/19 14:14:59</rasd:last_modified_date></Item><Item><rasd:Caption>a_Disk1</rasd:Caption><rasd:InstanceId>d4c57797-a344-4079-92cf-2e07e0aced30</rasd:InstanceId><rasd:ResourceType>17</rasd:ResourceType><rasd:HostResource>746db1d5-a195-4dc1-833b-77c2a46f1a22/d4c57797-a344-4079-92cf-2e07e0aced30</rasd:HostResource><rasd:Parent>00000000-0000-0000-0000-000000000000</rasd:Parent><rasd:Template>00000000-0000-0000-0000-000000000000</rasd:Template><rasd:ApplicationList>kernel-2.6.32-431.el6</rasd:ApplicationList><rasd:StorageId>4cd91baa-e6dd-4d84-a89d-89fc458f15a9</rasd:StorageId><rasd:StoragePoolId>00000002-0002-0002-0002-000000000394</rasd:StoragePoolId><rasd:CreationDate>2014/03/13 21:45:38</rasd:CreationDate><rasd:LastModified>2014/03/16 10:02:21</rasd:LastModified><rasd:last_modified_date>2014/03/19 14:14:59</rasd:last_modified_date></Item><Item><rasd:Caption>a_Disk2</rasd:Caption><rasd:InstanceId>5037acb2-df07-45c2-909f-044acb0611ec</rasd:InstanceId><rasd:ResourceType>17</rasd:ResourceType><rasd:HostResource>efd305ae-6a25-4f32-88fe-b8930849c936/5037acb2-df07-45c2-909f-044acb0611ec</rasd:HostResource><rasd:Parent>00000000-0000-0000-0000-000000000000</rasd:Parent><rasd:Template>00000000-0000-0000-0000-000000000000</rasd:Template><rasd:ApplicationList></rasd:ApplicationList><rasd:StorageId>4cd91baa-e6dd-4d84-a89d-89fc458f15a9</rasd:StorageId><rasd:StoragePoolId>00000002-0002-0002-0002-000000000394</rasd:StoragePoolId><rasd:CreationDate>2014/03/16 10:04:11</rasd:CreationDate><rasd:LastModified>2014/03/16 10:04:11</rasd:LastModified><rasd:last_modified_date>2014/03/19 14:14:59</rasd:last_modified_date></Item><Item><rasd:Caption>Ethernet adapter on rhevm</rasd:Caption><rasd:InstanceId>921515b8-8d80-4fb0-989b-ace2415fb852</rasd:InstanceId><rasd:ResourceType>10</rasd:ResourceType><rasd:OtherResourceType>ovirtmgmt</rasd:OtherResourceType><rasd:ResourceSubType>3</rasd:ResourceSubType><rasd:Connection>rhevm</rasd:Connection><rasd:Linked>true</rasd:Linked><rasd:Name>nic1</rasd:Name><rasd:MACAddress>00:1a:4a:30:54:9c</rasd:MACAddress><rasd:speed>1000</rasd:speed></Item><Item><rasd:Caption>USB Controller</rasd:Caption><rasd:InstanceId>3</rasd:InstanceId><rasd:ResourceType>23</rasd:ResourceType><rasd:UsbPolicy>DISABLED</rasd:UsbPolicy></Item></Section></Content></ovf:Envelope>', 'vm': 'e6b03061-7a3b-46f4-9fff-a786b9d501d9'}], sdUUID=None, options=None)
>Thread-3118::INFO::2014-03-19 15:14:59,785::sp::1228::Storage.StoragePool::(updateVM) spUUID=00000002-0002-0002-0002-000000000394 sdUUID=4cd91baa-e6dd-4d84-a89d-89fc458f15a9
>Thread-3118::INFO::2014-03-19 15:14:59,785::sp::1239::Storage.StoragePool::(updateVM) vmUUID=e6b03061-7a3b-46f4-9fff-a786b9d501d9 imgList=['efd305ae-6a25-4f32-88fe-b8930849c936', '746db1d5-a195-4dc1-833b-77c2a46f1a22']
>Thread-3118::INFO::2014-03-19 15:14:59,865::logUtils::47::dispatcher::(wrapper) Run and protect: updateVM, Return response: None
>Thread-3124::INFO::2014-03-19 15:15:01,905::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='4cd91baa-e6dd-4d84-a89d-89fc458f15a9', spUUID='00000002-0002-0002-0002-000000000394', imgUUID='746db1d5-a195-4dc1-833b-77c2a46f1a22', volUUID='2fbe976c-ab19-4bfb-9fce-94af66388c2e', options=None)
>Thread-3124::INFO::2014-03-19 15:15:01,907::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '92938240', 'apparentsize': '92995584'}
>Thread-3124::INFO::2014-03-19 15:15:01,907::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='4cd91baa-e6dd-4d84-a89d-89fc458f15a9', spUUID='00000002-0002-0002-0002-000000000394', imgUUID='efd305ae-6a25-4f32-88fe-b8930849c936', volUUID='5037acb2-df07-45c2-909f-044acb0611ec', options=None)
>Thread-3124::INFO::2014-03-19 15:15:01,909::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '6442455040', 'apparentsize': '6442450944'}
>Thread-71::DEBUG::2014-03-19 15:15:03,460::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.34.63.202:_mnt_export_nfs_lv3_lsvaty_nfs01/4cd91baa-e6dd-4d84-a89d-89fc458f15a9/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-71::DEBUG::2014-03-19 15:15:03,466::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n476 bytes (476 B) copied, 0.0003144 s, 1.5 MB/s\n'; <rc> = 0
>Thread-3125::INFO::2014-03-19 15:15:03,542::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-3125::INFO::2014-03-19 15:15:03,542::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'4cd91baa-e6dd-4d84-a89d-89fc458f15a9': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.0003144', 'lastCheck': '0.1', 'valid': True}}
>Thread-3125::DEBUG::2014-03-19 15:15:06,009::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-3125::INFO::2014-03-19 15:15:06,010::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3125::INFO::2014-03-19 15:15:06,020::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 2, 'spmStatus': 'SPM', 'spmLver': 5L}}
>Thread-3118::DEBUG::2014-03-19 15:15:06,026::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-3118::INFO::2014-03-19 15:15:06,026::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3118::INFO::2014-03-19 15:15:06,028::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9:Active', 'master_uuid': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9', 'version': '3', 'spm_id': 2, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'4cd91baa-e6dd-4d84-a89d-89fc458f15a9': {'status': 'Active', 'diskfree': '282356350976', 'isoprefix': '', 'alerts': [], 'disktotal': '422758580224', 'version': 3}}}
>Thread-71::DEBUG::2014-03-19 15:15:13,497::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.34.63.202:_mnt_export_nfs_lv3_lsvaty_nfs01/4cd91baa-e6dd-4d84-a89d-89fc458f15a9/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-71::DEBUG::2014-03-19 15:15:13,524::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n476 bytes (476 B) copied, 0.00399899 s, 119 kB/s\n'; <rc> = 0
>Thread-3125::DEBUG::2014-03-19 15:15:16,049::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-3125::INFO::2014-03-19 15:15:16,050::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3125::INFO::2014-03-19 15:15:16,062::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 2, 'spmStatus': 'SPM', 'spmLver': 5L}}
>Thread-3118::DEBUG::2014-03-19 15:15:16,066::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-3118::INFO::2014-03-19 15:15:16,067::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3118::INFO::2014-03-19 15:15:16,069::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9:Active', 'master_uuid': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9', 'version': '3', 'spm_id': 2, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'4cd91baa-e6dd-4d84-a89d-89fc458f15a9': {'status': 'Active', 'diskfree': '282353205248', 'isoprefix': '', 'alerts': [], 'disktotal': '422758580224', 'version': 3}}}
>Thread-3125::INFO::2014-03-19 15:15:18,652::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-3125::INFO::2014-03-19 15:15:18,652::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'4cd91baa-e6dd-4d84-a89d-89fc458f15a9': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.00399899', 'lastCheck': '5.1', 'valid': True}}
>VM Channels Listener::DEBUG::2014-03-19 15:15:23,145::vmChannels::91::vds::(_handle_timeouts) Timeout on fileno 40.
>Thread-71::DEBUG::2014-03-19 15:15:23,533::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.34.63.202:_mnt_export_nfs_lv3_lsvaty_nfs01/4cd91baa-e6dd-4d84-a89d-89fc458f15a9/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-71::DEBUG::2014-03-19 15:15:23,538::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n476 bytes (476 B) copied, 0.00025428 s, 1.9 MB/s\n'; <rc> = 0
>Thread-3125::DEBUG::2014-03-19 15:15:26,091::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-3125::INFO::2014-03-19 15:15:26,091::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3125::INFO::2014-03-19 15:15:26,103::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 2, 'spmStatus': 'SPM', 'spmLver': 5L}}
>Thread-3118::DEBUG::2014-03-19 15:15:26,107::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-3118::INFO::2014-03-19 15:15:26,108::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3118::INFO::2014-03-19 15:15:26,110::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9:Active', 'master_uuid': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9', 'version': '3', 'spm_id': 2, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'4cd91baa-e6dd-4d84-a89d-89fc458f15a9': {'status': 'Active', 'diskfree': '282352156672', 'isoprefix': '', 'alerts': [], 'disktotal': '422758580224', 'version': 3}}}
>Thread-71::DEBUG::2014-03-19 15:15:33,545::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.34.63.202:_mnt_export_nfs_lv3_lsvaty_nfs01/4cd91baa-e6dd-4d84-a89d-89fc458f15a9/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-71::DEBUG::2014-03-19 15:15:33,551::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n476 bytes (476 B) copied, 0.000284738 s, 1.7 MB/s\n'; <rc> = 0
>Thread-3125::INFO::2014-03-19 15:15:33,781::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-3125::INFO::2014-03-19 15:15:33,781::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'4cd91baa-e6dd-4d84-a89d-89fc458f15a9': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000284738', 'lastCheck': '0.2', 'valid': True}}
>Thread-3125::DEBUG::2014-03-19 15:15:36,128::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-3125::INFO::2014-03-19 15:15:36,128::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3125::INFO::2014-03-19 15:15:36,140::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 2, 'spmStatus': 'SPM', 'spmLver': 5L}}
>Thread-3118::DEBUG::2014-03-19 15:15:36,145::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-3118::INFO::2014-03-19 15:15:36,145::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3118::INFO::2014-03-19 15:15:36,148::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9:Active', 'master_uuid': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9', 'version': '3', 'spm_id': 2, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'4cd91baa-e6dd-4d84-a89d-89fc458f15a9': {'status': 'Active', 'diskfree': '282352156672', 'isoprefix': '', 'alerts': [], 'disktotal': '422758580224', 'version': 3}}}
>Thread-71::DEBUG::2014-03-19 15:15:43,558::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.34.63.202:_mnt_export_nfs_lv3_lsvaty_nfs01/4cd91baa-e6dd-4d84-a89d-89fc458f15a9/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-71::DEBUG::2014-03-19 15:15:43,564::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n476 bytes (476 B) copied, 0.000253583 s, 1.9 MB/s\n'; <rc> = 0
>Thread-3125::DEBUG::2014-03-19 15:15:46,167::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-3125::INFO::2014-03-19 15:15:46,168::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3125::INFO::2014-03-19 15:15:46,181::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 2, 'spmStatus': 'SPM', 'spmLver': 5L}}
>Thread-3118::DEBUG::2014-03-19 15:15:46,186::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-3118::INFO::2014-03-19 15:15:46,186::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3118::INFO::2014-03-19 15:15:46,188::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9:Active', 'master_uuid': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9', 'version': '3', 'spm_id': 2, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'4cd91baa-e6dd-4d84-a89d-89fc458f15a9': {'status': 'Active', 'diskfree': '282352156672', 'isoprefix': '', 'alerts': [], 'disktotal': '422758580224', 'version': 3}}}
>VM Channels Listener::DEBUG::2014-03-19 15:15:47,074::guestIF::209::vm.Vm::(_handleMessage) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::username: u'root'
>Thread-3125::INFO::2014-03-19 15:15:48,902::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-3125::INFO::2014-03-19 15:15:48,903::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'4cd91baa-e6dd-4d84-a89d-89fc458f15a9': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000253583', 'lastCheck': '5.3', 'valid': True}}
>Thread-71::DEBUG::2014-03-19 15:15:53,571::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.34.63.202:_mnt_export_nfs_lv3_lsvaty_nfs01/4cd91baa-e6dd-4d84-a89d-89fc458f15a9/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-71::DEBUG::2014-03-19 15:15:53,577::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n476 bytes (476 B) copied, 0.000250586 s, 1.9 MB/s\n'; <rc> = 0
>Thread-3125::DEBUG::2014-03-19 15:15:56,208::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-3125::INFO::2014-03-19 15:15:56,208::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3125::INFO::2014-03-19 15:15:56,220::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 2, 'spmStatus': 'SPM', 'spmLver': 5L}}
>Thread-3118::DEBUG::2014-03-19 15:15:56,226::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-3118::INFO::2014-03-19 15:15:56,226::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3118::INFO::2014-03-19 15:15:56,228::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9:Active', 'master_uuid': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9', 'version': '3', 'spm_id': 2, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'4cd91baa-e6dd-4d84-a89d-89fc458f15a9': {'status': 'Active', 'diskfree': '282352156672', 'isoprefix': '', 'alerts': [], 'disktotal': '422758580224', 'version': 3}}}
>Thread-3124::INFO::2014-03-19 15:16:01,965::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='4cd91baa-e6dd-4d84-a89d-89fc458f15a9', spUUID='00000002-0002-0002-0002-000000000394', imgUUID='746db1d5-a195-4dc1-833b-77c2a46f1a22', volUUID='2fbe976c-ab19-4bfb-9fce-94af66388c2e', options=None)
>Thread-3124::INFO::2014-03-19 15:16:01,966::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '97132544', 'apparentsize': '97189888'}
>Thread-3124::INFO::2014-03-19 15:16:01,967::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='4cd91baa-e6dd-4d84-a89d-89fc458f15a9', spUUID='00000002-0002-0002-0002-000000000394', imgUUID='efd305ae-6a25-4f32-88fe-b8930849c936', volUUID='5037acb2-df07-45c2-909f-044acb0611ec', options=None)
>Thread-3124::INFO::2014-03-19 15:16:01,968::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '6442455040', 'apparentsize': '6442450944'}
>libvirtEventLoop::DEBUG::2014-03-19 15:16:02,215::clientIF::555::vm.Vm::(dispatchLibvirtEvents) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::graphics event phase 2 localAddr {'node': '10.34.62.203', 'service': '', 'family': 0} remoteAddr {'node': '10.34.131.169', 'service': '', 'family': 0}authScheme  subject []
>libvirtEventLoop::DEBUG::2014-03-19 15:16:02,216::clientIF::555::vm.Vm::(dispatchLibvirtEvents) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::graphics event phase 2 localAddr {'node': '10.34.62.203', 'service': '', 'family': 0} remoteAddr {'node': '10.34.131.169', 'service': '', 'family': 0}authScheme spice subject []
>libvirtEventLoop::DEBUG::2014-03-19 15:16:02,216::clientIF::555::vm.Vm::(dispatchLibvirtEvents) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::graphics event phase 2 localAddr {'node': '10.34.62.203', 'service': '', 'family': 0} remoteAddr {'node': '10.34.131.169', 'service': '', 'family': 0}authScheme  subject []
>libvirtEventLoop::DEBUG::2014-03-19 15:16:02,217::clientIF::555::vm.Vm::(dispatchLibvirtEvents) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::graphics event phase 2 localAddr {'node': '10.34.62.203', 'service': '', 'family': 0} remoteAddr {'node': '10.34.131.169', 'service': '', 'family': 0}authScheme  subject []
>libvirtEventLoop::DEBUG::2014-03-19 15:16:02,227::clientIF::555::vm.Vm::(dispatchLibvirtEvents) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::graphics event phase 2 localAddr {'node': '10.34.62.203', 'service': '', 'family': 0} remoteAddr {'node': '10.34.131.169', 'service': '', 'family': 0}authScheme  subject []
>Thread-71::DEBUG::2014-03-19 15:16:03,584::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.34.63.202:_mnt_export_nfs_lv3_lsvaty_nfs01/4cd91baa-e6dd-4d84-a89d-89fc458f15a9/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-71::DEBUG::2014-03-19 15:16:03,590::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n476 bytes (476 B) copied, 0.000364681 s, 1.3 MB/s\n'; <rc> = 0
>Thread-3125::INFO::2014-03-19 15:16:04,046::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-3125::INFO::2014-03-19 15:16:04,046::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'4cd91baa-e6dd-4d84-a89d-89fc458f15a9': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000364681', 'lastCheck': '0.5', 'valid': True}}
>Thread-3133::DEBUG::2014-03-19 15:16:04,216::guestIF::278::vm.Vm::(desktopLock) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::desktopLock called
>Thread-3134::DEBUG::2014-03-19 15:16:04,216::guestIF::278::vm.Vm::(desktopLock) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::desktopLock called
>Thread-3135::DEBUG::2014-03-19 15:16:04,217::guestIF::278::vm.Vm::(desktopLock) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::desktopLock called
>Thread-3136::DEBUG::2014-03-19 15:16:04,217::guestIF::278::vm.Vm::(desktopLock) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::desktopLock called
>Thread-3137::DEBUG::2014-03-19 15:16:04,228::guestIF::278::vm.Vm::(desktopLock) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::desktopLock called
>Thread-3125::DEBUG::2014-03-19 15:16:05,070::BindingXMLRPC::1067::vds::(wrapper) client [10.34.63.60]::call vmSetTicket with ('e6b03061-7a3b-46f4-9fff-a786b9d501d9', 'd2R5ZZShBrxb', '120', 'disconnect', {'userName': 'admin', 'userId': 'fdfc627c-d875-11e0-90f0-83df133b58cc'}) {} flowID [4fdc4e54]
>Thread-3125::DEBUG::2014-03-19 15:16:05,138::BindingXMLRPC::1074::vds::(wrapper) return vmSetTicket with {'status': {'message': 'Done', 'code': 0}}
>Thread-3125::DEBUG::2014-03-19 15:16:06,248::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-3125::INFO::2014-03-19 15:16:06,248::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3125::INFO::2014-03-19 15:16:06,261::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 2, 'spmStatus': 'SPM', 'spmLver': 5L}}
>Thread-3118::DEBUG::2014-03-19 15:16:06,265::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-3118::INFO::2014-03-19 15:16:06,265::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3118::INFO::2014-03-19 15:16:06,268::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9:Active', 'master_uuid': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9', 'version': '3', 'spm_id': 2, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'4cd91baa-e6dd-4d84-a89d-89fc458f15a9': {'status': 'Active', 'diskfree': '282352156672', 'isoprefix': '', 'alerts': [], 'disktotal': '422758580224', 'version': 3}}}
>libvirtEventLoop::DEBUG::2014-03-19 15:16:08,272::clientIF::555::vm.Vm::(dispatchLibvirtEvents) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::graphics event phase 0 localAddr {'node': '10.34.62.203', 'service': '', 'family': 0} remoteAddr {'node': '10.34.131.169', 'service': '', 'family': 0}authScheme  subject []
>libvirtEventLoop::DEBUG::2014-03-19 15:16:08,281::clientIF::555::vm.Vm::(dispatchLibvirtEvents) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::graphics event phase 1 localAddr {'node': '10.34.62.203', 'service': '', 'family': 0} remoteAddr {'node': '10.34.131.169', 'service': '', 'family': 0}authScheme spice subject []
>libvirtEventLoop::DEBUG::2014-03-19 15:16:08,286::clientIF::555::vm.Vm::(dispatchLibvirtEvents) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::graphics event phase 0 localAddr {'node': '10.34.62.203', 'service': '', 'family': 0} remoteAddr {'node': '10.34.131.169', 'service': '', 'family': 0}authScheme  subject []
>libvirtEventLoop::DEBUG::2014-03-19 15:16:08,297::clientIF::555::vm.Vm::(dispatchLibvirtEvents) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::graphics event phase 1 localAddr {'node': '10.34.62.203', 'service': '', 'family': 0} remoteAddr {'node': '10.34.131.169', 'service': '', 'family': 0}authScheme spice subject []
>libvirtEventLoop::DEBUG::2014-03-19 15:16:08,334::clientIF::555::vm.Vm::(dispatchLibvirtEvents) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::graphics event phase 0 localAddr {'node': '10.34.62.203', 'service': '', 'family': 0} remoteAddr {'node': '10.34.131.169', 'service': '', 'family': 0}authScheme  subject []
>libvirtEventLoop::DEBUG::2014-03-19 15:16:08,334::clientIF::555::vm.Vm::(dispatchLibvirtEvents) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::graphics event phase 0 localAddr {'node': '10.34.62.203', 'service': '', 'family': 0} remoteAddr {'node': '10.34.131.169', 'service': '', 'family': 0}authScheme  subject []
>libvirtEventLoop::DEBUG::2014-03-19 15:16:08,363::clientIF::555::vm.Vm::(dispatchLibvirtEvents) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::graphics event phase 1 localAddr {'node': '10.34.62.203', 'service': '', 'family': 0} remoteAddr {'node': '10.34.131.169', 'service': '', 'family': 0}authScheme spice subject []
>libvirtEventLoop::DEBUG::2014-03-19 15:16:08,364::clientIF::555::vm.Vm::(dispatchLibvirtEvents) vmId=`e6b03061-7a3b-46f4-9fff-a786b9d501d9`::graphics event phase 1 localAddr {'node': '10.34.62.203', 'service': '', 'family': 0} remoteAddr {'node': '10.34.131.169', 'service': '', 'family': 0}authScheme spice subject []
>Thread-71::DEBUG::2014-03-19 15:16:13,597::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.34.63.202:_mnt_export_nfs_lv3_lsvaty_nfs01/4cd91baa-e6dd-4d84-a89d-89fc458f15a9/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-71::DEBUG::2014-03-19 15:16:13,602::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n476 bytes (476 B) copied, 0.000255311 s, 1.9 MB/s\n'; <rc> = 0
>Thread-3125::DEBUG::2014-03-19 15:16:16,286::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-3125::INFO::2014-03-19 15:16:16,286::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3125::INFO::2014-03-19 15:16:16,298::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 2, 'spmStatus': 'SPM', 'spmLver': 5L}}
>Thread-3118::DEBUG::2014-03-19 15:16:16,303::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-3118::INFO::2014-03-19 15:16:16,303::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3118::INFO::2014-03-19 15:16:16,305::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9:Active', 'master_uuid': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9', 'version': '3', 'spm_id': 2, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'4cd91baa-e6dd-4d84-a89d-89fc458f15a9': {'status': 'Active', 'diskfree': '282352156672', 'isoprefix': '', 'alerts': [], 'disktotal': '422758580224', 'version': 3}}}
>Thread-3125::INFO::2014-03-19 15:16:19,187::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-3125::INFO::2014-03-19 15:16:19,187::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'4cd91baa-e6dd-4d84-a89d-89fc458f15a9': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000255311', 'lastCheck': '5.6', 'valid': True}}
>Thread-71::DEBUG::2014-03-19 15:16:23,610::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.34.63.202:_mnt_export_nfs_lv3_lsvaty_nfs01/4cd91baa-e6dd-4d84-a89d-89fc458f15a9/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-71::DEBUG::2014-03-19 15:16:23,616::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n476 bytes (476 B) copied, 0.000263399 s, 1.8 MB/s\n'; <rc> = 0
>Thread-3125::DEBUG::2014-03-19 15:16:26,324::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-3125::INFO::2014-03-19 15:16:26,325::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3125::INFO::2014-03-19 15:16:26,337::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 2, 'spmStatus': 'SPM', 'spmLver': 5L}}
>Thread-3118::DEBUG::2014-03-19 15:16:26,341::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-3118::INFO::2014-03-19 15:16:26,342::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3118::INFO::2014-03-19 15:16:26,344::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9:Active', 'master_uuid': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9', 'version': '3', 'spm_id': 2, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'4cd91baa-e6dd-4d84-a89d-89fc458f15a9': {'status': 'Active', 'diskfree': '282352156672', 'isoprefix': '', 'alerts': [], 'disktotal': '422758580224', 'version': 3}}}
>Thread-71::DEBUG::2014-03-19 15:16:33,622::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.34.63.202:_mnt_export_nfs_lv3_lsvaty_nfs01/4cd91baa-e6dd-4d84-a89d-89fc458f15a9/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-71::DEBUG::2014-03-19 15:16:33,628::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n476 bytes (476 B) copied, 0.000225882 s, 2.1 MB/s\n'; <rc> = 0
>Thread-3125::INFO::2014-03-19 15:16:34,321::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-3125::INFO::2014-03-19 15:16:34,321::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'4cd91baa-e6dd-4d84-a89d-89fc458f15a9': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000225882', 'lastCheck': '0.7', 'valid': True}}
>Thread-3125::DEBUG::2014-03-19 15:16:36,362::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-3125::INFO::2014-03-19 15:16:36,362::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3125::INFO::2014-03-19 15:16:36,374::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 2, 'spmStatus': 'SPM', 'spmLver': 5L}}
>Thread-3118::DEBUG::2014-03-19 15:16:36,379::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-3118::INFO::2014-03-19 15:16:36,379::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3118::INFO::2014-03-19 15:16:36,382::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9:Active', 'master_uuid': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9', 'version': '3', 'spm_id': 2, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'4cd91baa-e6dd-4d84-a89d-89fc458f15a9': {'status': 'Active', 'diskfree': '282352156672', 'isoprefix': '', 'alerts': [], 'disktotal': '422758580224', 'version': 3}}}
>Thread-71::DEBUG::2014-03-19 15:16:43,636::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.34.63.202:_mnt_export_nfs_lv3_lsvaty_nfs01/4cd91baa-e6dd-4d84-a89d-89fc458f15a9/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-71::DEBUG::2014-03-19 15:16:43,641::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n476 bytes (476 B) copied, 0.000223943 s, 2.1 MB/s\n'; <rc> = 0
>Thread-3125::DEBUG::2014-03-19 15:16:46,400::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-3125::INFO::2014-03-19 15:16:46,400::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3125::INFO::2014-03-19 15:16:46,412::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 2, 'spmStatus': 'SPM', 'spmLver': 5L}}
>Thread-3118::DEBUG::2014-03-19 15:16:46,417::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-3118::INFO::2014-03-19 15:16:46,417::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3118::INFO::2014-03-19 15:16:46,420::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9:Active', 'master_uuid': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9', 'version': '3', 'spm_id': 2, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'4cd91baa-e6dd-4d84-a89d-89fc458f15a9': {'status': 'Active', 'diskfree': '282352156672', 'isoprefix': '', 'alerts': [], 'disktotal': '422758580224', 'version': 3}}}
>Thread-3125::INFO::2014-03-19 15:16:49,478::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-3125::INFO::2014-03-19 15:16:49,479::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'4cd91baa-e6dd-4d84-a89d-89fc458f15a9': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000223943', 'lastCheck': '5.8', 'valid': True}}
>Thread-71::DEBUG::2014-03-19 15:16:53,649::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.34.63.202:_mnt_export_nfs_lv3_lsvaty_nfs01/4cd91baa-e6dd-4d84-a89d-89fc458f15a9/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-71::DEBUG::2014-03-19 15:16:53,654::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n476 bytes (476 B) copied, 0.0002773 s, 1.7 MB/s\n'; <rc> = 0
>Thread-3125::DEBUG::2014-03-19 15:16:56,443::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-3125::INFO::2014-03-19 15:16:56,443::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3125::INFO::2014-03-19 15:16:56,455::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 2, 'spmStatus': 'SPM', 'spmLver': 5L}}
>Thread-3118::DEBUG::2014-03-19 15:16:56,460::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-3118::INFO::2014-03-19 15:16:56,460::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3118::INFO::2014-03-19 15:16:56,462::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9:Active', 'master_uuid': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9', 'version': '3', 'spm_id': 2, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'4cd91baa-e6dd-4d84-a89d-89fc458f15a9': {'status': 'Active', 'diskfree': '282352156672', 'isoprefix': '', 'alerts': [], 'disktotal': '422758580224', 'version': 3}}}
>Thread-3124::INFO::2014-03-19 15:17:02,012::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='4cd91baa-e6dd-4d84-a89d-89fc458f15a9', spUUID='00000002-0002-0002-0002-000000000394', imgUUID='746db1d5-a195-4dc1-833b-77c2a46f1a22', volUUID='2fbe976c-ab19-4bfb-9fce-94af66388c2e', options=None)
>Thread-3124::INFO::2014-03-19 15:17:02,014::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '97132544', 'apparentsize': '97189888'}
>Thread-3124::INFO::2014-03-19 15:17:02,014::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='4cd91baa-e6dd-4d84-a89d-89fc458f15a9', spUUID='00000002-0002-0002-0002-000000000394', imgUUID='efd305ae-6a25-4f32-88fe-b8930849c936', volUUID='5037acb2-df07-45c2-909f-044acb0611ec', options=None)
>Thread-3124::INFO::2014-03-19 15:17:02,015::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '6442455040', 'apparentsize': '6442450944'}
>Thread-71::DEBUG::2014-03-19 15:17:03,662::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.34.63.202:_mnt_export_nfs_lv3_lsvaty_nfs01/4cd91baa-e6dd-4d84-a89d-89fc458f15a9/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-71::DEBUG::2014-03-19 15:17:03,667::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n476 bytes (476 B) copied, 0.000264974 s, 1.8 MB/s\n'; <rc> = 0
>Thread-3125::INFO::2014-03-19 15:17:04,640::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-3125::INFO::2014-03-19 15:17:04,640::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'4cd91baa-e6dd-4d84-a89d-89fc458f15a9': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000264974', 'lastCheck': '1.0', 'valid': True}}
>Thread-3125::DEBUG::2014-03-19 15:17:06,480::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-3125::INFO::2014-03-19 15:17:06,480::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3125::INFO::2014-03-19 15:17:06,493::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 2, 'spmStatus': 'SPM', 'spmLver': 5L}}
>Thread-3118::DEBUG::2014-03-19 15:17:06,497::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-3118::INFO::2014-03-19 15:17:06,497::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3118::INFO::2014-03-19 15:17:06,500::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9:Active', 'master_uuid': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9', 'version': '3', 'spm_id': 2, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'4cd91baa-e6dd-4d84-a89d-89fc458f15a9': {'status': 'Active', 'diskfree': '282352156672', 'isoprefix': '', 'alerts': [], 'disktotal': '422758580224', 'version': 3}}}
>Thread-71::DEBUG::2014-03-19 15:17:13,675::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.34.63.202:_mnt_export_nfs_lv3_lsvaty_nfs01/4cd91baa-e6dd-4d84-a89d-89fc458f15a9/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-71::DEBUG::2014-03-19 15:17:13,680::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n476 bytes (476 B) copied, 0.000260445 s, 1.8 MB/s\n'; <rc> = 0
>Thread-3125::DEBUG::2014-03-19 15:17:16,518::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-3125::INFO::2014-03-19 15:17:16,519::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3125::INFO::2014-03-19 15:17:16,531::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 2, 'spmStatus': 'SPM', 'spmLver': 5L}}
>Thread-3118::DEBUG::2014-03-19 15:17:16,536::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-3118::INFO::2014-03-19 15:17:16,536::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3118::INFO::2014-03-19 15:17:16,538::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9:Active', 'master_uuid': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9', 'version': '3', 'spm_id': 2, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'4cd91baa-e6dd-4d84-a89d-89fc458f15a9': {'status': 'Active', 'diskfree': '282352156672', 'isoprefix': '', 'alerts': [], 'disktotal': '422758580224', 'version': 3}}}
>Thread-3125::INFO::2014-03-19 15:17:19,761::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-3125::INFO::2014-03-19 15:17:19,761::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'4cd91baa-e6dd-4d84-a89d-89fc458f15a9': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000260445', 'lastCheck': '6.1', 'valid': True}}
>Thread-71::DEBUG::2014-03-19 15:17:23,688::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.34.63.202:_mnt_export_nfs_lv3_lsvaty_nfs01/4cd91baa-e6dd-4d84-a89d-89fc458f15a9/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-71::DEBUG::2014-03-19 15:17:23,694::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n476 bytes (476 B) copied, 0.000271741 s, 1.8 MB/s\n'; <rc> = 0
>Thread-3125::DEBUG::2014-03-19 15:17:26,555::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-3125::INFO::2014-03-19 15:17:26,556::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3125::INFO::2014-03-19 15:17:26,568::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 2, 'spmStatus': 'SPM', 'spmLver': 5L}}
>Thread-3118::DEBUG::2014-03-19 15:17:26,573::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-3118::INFO::2014-03-19 15:17:26,573::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3118::INFO::2014-03-19 15:17:26,575::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9:Active', 'master_uuid': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9', 'version': '3', 'spm_id': 2, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'4cd91baa-e6dd-4d84-a89d-89fc458f15a9': {'status': 'Active', 'diskfree': '282352156672', 'isoprefix': '', 'alerts': [], 'disktotal': '422758580224', 'version': 3}}}
>Thread-71::DEBUG::2014-03-19 15:17:33,701::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.34.63.202:_mnt_export_nfs_lv3_lsvaty_nfs01/4cd91baa-e6dd-4d84-a89d-89fc458f15a9/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-71::DEBUG::2014-03-19 15:17:33,706::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n476 bytes (476 B) copied, 0.000290223 s, 1.6 MB/s\n'; <rc> = 0
>Thread-3125::INFO::2014-03-19 15:17:34,876::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-3125::INFO::2014-03-19 15:17:34,877::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'4cd91baa-e6dd-4d84-a89d-89fc458f15a9': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000290223', 'lastCheck': '1.2', 'valid': True}}
>Thread-3125::DEBUG::2014-03-19 15:17:36,594::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-3125::INFO::2014-03-19 15:17:36,594::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3125::INFO::2014-03-19 15:17:36,606::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 2, 'spmStatus': 'SPM', 'spmLver': 5L}}
>Thread-3118::DEBUG::2014-03-19 15:17:36,610::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-3118::INFO::2014-03-19 15:17:36,611::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3118::INFO::2014-03-19 15:17:36,613::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9:Active', 'master_uuid': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9', 'version': '3', 'spm_id': 2, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'4cd91baa-e6dd-4d84-a89d-89fc458f15a9': {'status': 'Active', 'diskfree': '282352156672', 'isoprefix': '', 'alerts': [], 'disktotal': '422758580224', 'version': 3}}}
>Thread-71::DEBUG::2014-03-19 15:17:43,714::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.34.63.202:_mnt_export_nfs_lv3_lsvaty_nfs01/4cd91baa-e6dd-4d84-a89d-89fc458f15a9/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-71::DEBUG::2014-03-19 15:17:43,720::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n476 bytes (476 B) copied, 0.000319699 s, 1.5 MB/s\n'; <rc> = 0
>Thread-3125::DEBUG::2014-03-19 15:17:46,631::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-3125::INFO::2014-03-19 15:17:46,632::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3125::INFO::2014-03-19 15:17:46,644::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 2, 'spmStatus': 'SPM', 'spmLver': 5L}}
>Thread-3118::DEBUG::2014-03-19 15:17:46,648::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-3118::INFO::2014-03-19 15:17:46,648::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3118::INFO::2014-03-19 15:17:46,650::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9:Active', 'master_uuid': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9', 'version': '3', 'spm_id': 2, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'4cd91baa-e6dd-4d84-a89d-89fc458f15a9': {'status': 'Active', 'diskfree': '282352156672', 'isoprefix': '', 'alerts': [], 'disktotal': '422758580224', 'version': 3}}}
>Thread-3125::INFO::2014-03-19 15:17:49,992::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-3125::INFO::2014-03-19 15:17:49,992::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'4cd91baa-e6dd-4d84-a89d-89fc458f15a9': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000319699', 'lastCheck': '6.3', 'valid': True}}
>Thread-71::DEBUG::2014-03-19 15:17:53,727::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.34.63.202:_mnt_export_nfs_lv3_lsvaty_nfs01/4cd91baa-e6dd-4d84-a89d-89fc458f15a9/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-71::DEBUG::2014-03-19 15:17:53,733::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n476 bytes (476 B) copied, 0.000317416 s, 1.5 MB/s\n'; <rc> = 0
>Thread-3125::DEBUG::2014-03-19 15:17:56,669::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-3125::INFO::2014-03-19 15:17:56,669::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3125::INFO::2014-03-19 15:17:56,681::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 2, 'spmStatus': 'SPM', 'spmLver': 5L}}
>Thread-3118::DEBUG::2014-03-19 15:17:56,687::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-3118::INFO::2014-03-19 15:17:56,687::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3118::INFO::2014-03-19 15:17:56,690::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9:Active', 'master_uuid': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9', 'version': '3', 'spm_id': 2, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'4cd91baa-e6dd-4d84-a89d-89fc458f15a9': {'status': 'Active', 'diskfree': '282352156672', 'isoprefix': '', 'alerts': [], 'disktotal': '422758580224', 'version': 3}}}
>Thread-3124::INFO::2014-03-19 15:18:02,057::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='4cd91baa-e6dd-4d84-a89d-89fc458f15a9', spUUID='00000002-0002-0002-0002-000000000394', imgUUID='746db1d5-a195-4dc1-833b-77c2a46f1a22', volUUID='2fbe976c-ab19-4bfb-9fce-94af66388c2e', options=None)
>Thread-3124::INFO::2014-03-19 15:18:02,059::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '97132544', 'apparentsize': '97189888'}
>Thread-3124::INFO::2014-03-19 15:18:02,059::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='4cd91baa-e6dd-4d84-a89d-89fc458f15a9', spUUID='00000002-0002-0002-0002-000000000394', imgUUID='efd305ae-6a25-4f32-88fe-b8930849c936', volUUID='5037acb2-df07-45c2-909f-044acb0611ec', options=None)
>Thread-3124::INFO::2014-03-19 15:18:02,060::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '6442455040', 'apparentsize': '6442450944'}
>Thread-71::DEBUG::2014-03-19 15:18:03,740::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/10.34.63.202:_mnt_export_nfs_lv3_lsvaty_nfs01/4cd91baa-e6dd-4d84-a89d-89fc458f15a9/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-71::DEBUG::2014-03-19 15:18:03,745::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n476 bytes (476 B) copied, 0.000217708 s, 2.2 MB/s\n'; <rc> = 0
>Thread-3125::INFO::2014-03-19 15:18:05,105::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-3125::INFO::2014-03-19 15:18:05,106::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'4cd91baa-e6dd-4d84-a89d-89fc458f15a9': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000217708', 'lastCheck': '1.4', 'valid': True}}
>Thread-3125::DEBUG::2014-03-19 15:18:06,709::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-3125::INFO::2014-03-19 15:18:06,710::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3125::INFO::2014-03-19 15:18:06,722::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 2, 'spmStatus': 'SPM', 'spmLver': 5L}}
>Thread-3118::DEBUG::2014-03-19 15:18:06,727::BindingXMLRPC::251::vds::(wrapper) client [10.34.63.60]
>Thread-3118::INFO::2014-03-19 15:18:06,727::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='00000002-0002-0002-0002-000000000394', options=None)
>Thread-3118::INFO::2014-03-19 15:18:06,729::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'Default', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9:Active', 'master_uuid': '4cd91baa-e6dd-4d84-a89d-89fc458f15a9', 'version': '3', 'spm_id': 2, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'4cd91baa-e6dd-4d84-a89d-89fc458f15a9': {'status': 'Active', 'diskfree': '2823

Actions: View

Attachments on bug 1076457: 876363 | 876365