Attachment 900483 Details for Bug 1102881 – vdsm log when the problem happens

vdsm log when the problem happens

vdsm.log (text/plain), 136.70 KB, created by Adam Litke on 2014-05-29 18:32:45 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: Adam Litke

Created: 2014-05-29 18:32:45 UTC

Size: 136.70 KB

patch

obsolete

>Thread-828::DEBUG::2014-05-29 12:26:29,570::BindingXMLRPC::1052::vds::(wrapper) client [192.168.2.1]::call vmCreate with ({'acpiEnable': 'true', 'emulatedMachine': 'pc', 'vmId': 'af8df38e-2e99-4a89-9483-a540027ea6b1', 'memGuaranteedSize': 1024, 'spiceSslCipherSuite': 'DEFAULT', 'timeOffset': '0', 'cpuType': 'SandyBridge', 'custom': {}, 'smp': '1', 'vmType': 'kvm', 'memSize': 1024, 'smpCoresPerSocket': '1', 'vmName': 'brewer-5', 'nice': '0', 'bootMenuEnable': 'false', 'smartcardEnable': 'false', 'keyboardLayout': 'en-us', 'kvmEnable': 'true', 'transparentHugePages': 'true', 'devices': [{'device': 'qxl', 'specParams': {'vram': '32768', 'heads': '1'}, 'type': 'video', 'deviceId': '924c7182-95b4-47cd-aab0-22f8c4e9cde8'}, {'index': '2', 'iface': 'ide', 'bootOrder': '2', 'specParams': {}, 'readonly': 'true', 'deviceId': '22ce29f0-b97f-43f9-949e-3e406a0a61b9', 'path': '/rhev/data-center/mnt/192.168.2.1:_home_storage_iso/e453999e-ec9f-420b-941c-a9f9cc4432bb/images/11111111-1111-1111-1111-111111111111/CorePlus-current.iso', 'device': 'cdrom', 'shared': 'false', 'type': 'disk'}, {'index': 0, 'iface': 'virtio', 'format': 'cow', 'bootOrder': '1', 'poolID': 'be744655-2a19-4919-92f3-e7c20ac03193', 'volumeID': '7e0ec106-f2dc-4567-b050-e3289bf2d47f', 'imageID': 'dad706d6-e1e9-4f31-87d4-610b3511a932', 'specParams': {}, 'readonly': 'false', 'domainID': 'a246386b-f31d-451d-b8a6-2f4c0dfa27b4', 'optional': 'false', 'deviceId': 'dad706d6-e1e9-4f31-87d4-610b3511a932', 'address': {'slot': '0x06', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'disk', 'shared': 'false', 'propagateErrors': 'off', 'type': 'disk'}, {'nicModel': 'pv', 'macAddr': '00:1a:4a:3f:44:a3', 'linkActive': 'true', 'network': 'ovirtmgmt', 'bootOrder': '3', 'filter': 'vdsm-no-mac-spoofing', 'specParams': {}, 'deviceId': 'c5fc77bc-0890-49a1-a5f2-1bbe20fd649b', 'address': {'slot': '0x03', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'bridge', 'type': 'interface'}, {'device': 'memballoon', 'specParams': {'model': 'virtio'}, 'type': 'balloon', 'deviceId': '5c14bea3-5fa4-4f3d-adbf-e05293fbadfa'}, {'index': '0', 'specParams': {}, 'deviceId': 'a20c804c-8f15-4bb5-bfa7-6681cdaa20a1', '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 [2def372c]
>Thread-828::INFO::2014-05-29 12:26:29,570::clientIF::372::vds::(createVm) vmContainerLock acquired by vm af8df38e-2e99-4a89-9483-a540027ea6b1
>Thread-828::INFO::2014-05-29 12:26:29,573::vm::5284::root::(_getNetworkIp) network None: using 0
>Thread-828::DEBUG::2014-05-29 12:26:29,573::libvirtconnection::146::root::(get) trying to connect libvirt
>Thread-864::DEBUG::2014-05-29 12:26:29,584::vm::2015::vm.Vm::(_startUnderlyingVm) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::Start
>Thread-828::DEBUG::2014-05-29 12:26:29,584::clientIF::385::vds::(createVm) Total desktops after creation of af8df38e-2e99-4a89-9483-a540027ea6b1 is 1
>Thread-864::DEBUG::2014-05-29 12:26:29,585::vm::2019::vm.Vm::(_startUnderlyingVm) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::_ongoingCreations acquired
>Thread-864::INFO::2014-05-29 12:26:29,585::vm::2957::vm.Vm::(_run) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::VM wrapper has started
>Thread-864::DEBUG::2014-05-29 12:26:29,586::task::595::TaskManager.Task::(_updateState) Task=`88661a9a-a781-400c-8d4c-419a362625a6`::moving from state init -> state preparing
>Thread-864::INFO::2014-05-29 12:26:29,587::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='a246386b-f31d-451d-b8a6-2f4c0dfa27b4', spUUID='be744655-2a19-4919-92f3-e7c20ac03193', imgUUID='dad706d6-e1e9-4f31-87d4-610b3511a932', volUUID='7e0ec106-f2dc-4567-b050-e3289bf2d47f', options=None)
>Thread-864::DEBUG::2014-05-29 12:26:29,588::lvm::419::OperationMutex::(_reloadlvs) Operation 'lvm reload operation' got the operation mutex
>Thread-828::DEBUG::2014-05-29 12:26:29,590::BindingXMLRPC::1059::vds::(wrapper) return vmCreate with {'status': {'message': 'Done', 'code': 0}, 'vmList': {'acpiEnable': 'true', 'emulatedMachine': 'pc', 'vmId': 'af8df38e-2e99-4a89-9483-a540027ea6b1', 'memGuaranteedSize': 1024, 'spiceSslCipherSuite': 'DEFAULT', 'displaySecurePort': '-1', 'timeOffset': '0', 'cpuType': 'SandyBridge', 'smp': '1', 'custom': {}, 'vmType': 'kvm', 'memSize': 1024, 'smpCoresPerSocket': '1', 'vmName': 'brewer-5', 'nice': '0', 'status': 'WaitForLaunch', 'bootMenuEnable': 'false', 'pid': '0', 'displayIp': '0', 'displayPort': '-1', 'smartcardEnable': 'false', 'spiceSecureChannels': 'smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard', 'nicModel': 'rtl8139,pv', 'keyboardLayout': 'en-us', 'kvmEnable': 'true', 'transparentHugePages': 'true', 'devices': [{'device': 'qxl', 'specParams': {'vram': '32768', 'heads': '1'}, 'type': 'video', 'deviceId': '924c7182-95b4-47cd-aab0-22f8c4e9cde8'}, {'index': '2', 'iface': 'ide', 'bootOrder': '2', 'specParams': {}, 'readonly': 'true', 'deviceId': '22ce29f0-b97f-43f9-949e-3e406a0a61b9', 'shared': 'false', 'device': 'cdrom', 'path': '/rhev/data-center/mnt/192.168.2.1:_home_storage_iso/e453999e-ec9f-420b-941c-a9f9cc4432bb/images/11111111-1111-1111-1111-111111111111/CorePlus-current.iso', 'type': 'disk'}, {'index': 0, 'iface': 'virtio', 'reqsize': '0', 'format': 'cow', 'bootOrder': '1', 'address': {'slot': '0x06', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'volumeID': '7e0ec106-f2dc-4567-b050-e3289bf2d47f', 'imageID': 'dad706d6-e1e9-4f31-87d4-610b3511a932', 'specParams': {}, 'readonly': 'false', 'domainID': 'a246386b-f31d-451d-b8a6-2f4c0dfa27b4', 'deviceId': 'dad706d6-e1e9-4f31-87d4-610b3511a932', 'type': 'disk', 'poolID': 'be744655-2a19-4919-92f3-e7c20ac03193', 'device': 'disk', 'shared': 'false', 'propagateErrors': 'off', 'optional': 'false'}, {'nicModel': 'pv', 'macAddr': '00:1a:4a:3f:44:a3', 'linkActive': 'true', 'network': 'ovirtmgmt', 'bootOrder': '3', 'filter': 'vdsm-no-mac-spoofing', 'specParams': {}, 'deviceId': 'c5fc77bc-0890-49a1-a5f2-1bbe20fd649b', 'address': {'slot': '0x03', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'bridge', 'type': 'interface'}, {'device': 'memballoon', 'specParams': {'model': 'virtio'}, 'type': 'balloon', 'deviceId': '5c14bea3-5fa4-4f3d-adbf-e05293fbadfa'}, {'index': '0', 'specParams': {}, 'deviceId': 'a20c804c-8f15-4bb5-bfa7-6681cdaa20a1', 'address': {'slot': '0x04', 'bus': '0x00', 'domain': '0x0000', 'type': 'pci', 'function': '0x0'}, 'device': 'scsi', 'model': 'virtio-scsi', 'type': 'controller'}], 'maxVCpus': '160', 'clientIp': '', 'display': 'qxl'}}
>Thread-864::DEBUG::2014-05-29 12:26:29,591::lvm::288::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /usr/sbin/lvm lvs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ \'a|/dev/mapper/3600140596b9bb9189094a98a6891f0a4|\', \'r|.*|\' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1  use_lvmetad=0 }  backup {  retain_min = 50  retain_days = 0 } " --noheadings --units b --nosuffix --separator | --ignoreskippedcluster -o uuid,name,vg_name,attr,size,seg_start_pe,devices,tags a246386b-f31d-451d-b8a6-2f4c0dfa27b4' (cwd None)
>Thread-864::DEBUG::2014-05-29 12:26:29,633::lvm::288::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-864::DEBUG::2014-05-29 12:26:29,634::lvm::454::Storage.LVM::(_reloadlvs) lvs reloaded
>Thread-864::DEBUG::2014-05-29 12:26:29,634::lvm::454::OperationMutex::(_reloadlvs) Operation 'lvm reload operation' released the operation mutex
>Thread-864::INFO::2014-05-29 12:26:29,634::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '134217728', 'apparentsize': '134217728'}
>Thread-864::DEBUG::2014-05-29 12:26:29,635::task::1188::TaskManager.Task::(prepare) Task=`88661a9a-a781-400c-8d4c-419a362625a6`::finished: {'truesize': '134217728', 'apparentsize': '134217728'}
>Thread-864::DEBUG::2014-05-29 12:26:29,635::task::595::TaskManager.Task::(_updateState) Task=`88661a9a-a781-400c-8d4c-419a362625a6`::moving from state preparing -> state finished
>Thread-864::DEBUG::2014-05-29 12:26:29,635::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-864::DEBUG::2014-05-29 12:26:29,635::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-864::DEBUG::2014-05-29 12:26:29,635::task::993::TaskManager.Task::(_decref) Task=`88661a9a-a781-400c-8d4c-419a362625a6`::ref 0 aborting False
>Thread-864::INFO::2014-05-29 12:26:29,635::clientIF::313::vds::(prepareVolumePath) prepared volume path: /rhev/data-center/mnt/192.168.2.1:_home_storage_iso/e453999e-ec9f-420b-941c-a9f9cc4432bb/images/11111111-1111-1111-1111-111111111111/CorePlus-current.iso
>Thread-864::DEBUG::2014-05-29 12:26:29,635::task::595::TaskManager.Task::(_updateState) Task=`63426c80-7982-485a-b1c4-7b12108cc8e4`::moving from state init -> state preparing
>Thread-864::INFO::2014-05-29 12:26:29,636::logUtils::44::dispatcher::(wrapper) Run and protect: prepareImage(sdUUID='a246386b-f31d-451d-b8a6-2f4c0dfa27b4', spUUID='be744655-2a19-4919-92f3-e7c20ac03193', imgUUID='dad706d6-e1e9-4f31-87d4-610b3511a932', leafUUID='7e0ec106-f2dc-4567-b050-e3289bf2d47f')
>Thread-864::DEBUG::2014-05-29 12:26:29,636::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.a246386b-f31d-451d-b8a6-2f4c0dfa27b4`ReqID=`1e5b6979-a251-4b8f-96a1-b3f1365777e4`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '3243' at 'prepareImage'
>Thread-864::DEBUG::2014-05-29 12:26:29,636::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.a246386b-f31d-451d-b8a6-2f4c0dfa27b4' for lock type 'shared'
>Thread-864::DEBUG::2014-05-29 12:26:29,636::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.a246386b-f31d-451d-b8a6-2f4c0dfa27b4' is free. Now locking as 'shared' (1 active user)
>Thread-864::DEBUG::2014-05-29 12:26:29,636::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.a246386b-f31d-451d-b8a6-2f4c0dfa27b4`ReqID=`1e5b6979-a251-4b8f-96a1-b3f1365777e4`::Granted request
>Thread-864::DEBUG::2014-05-29 12:26:29,636::task::827::TaskManager.Task::(resourceAcquired) Task=`63426c80-7982-485a-b1c4-7b12108cc8e4`::_resourcesAcquired: Storage.a246386b-f31d-451d-b8a6-2f4c0dfa27b4 (shared)
>Thread-864::DEBUG::2014-05-29 12:26:29,636::task::993::TaskManager.Task::(_decref) Task=`63426c80-7982-485a-b1c4-7b12108cc8e4`::ref 1 aborting False
>Thread-864::DEBUG::2014-05-29 12:26:29,637::lvm::419::OperationMutex::(_reloadlvs) Operation 'lvm reload operation' got the operation mutex
>Thread-864::DEBUG::2014-05-29 12:26:29,637::lvm::288::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /usr/sbin/lvm lvs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ \'a|/dev/mapper/3600140596b9bb9189094a98a6891f0a4|\', \'r|.*|\' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1  use_lvmetad=0 }  backup {  retain_min = 50  retain_days = 0 } " --noheadings --units b --nosuffix --separator | --ignoreskippedcluster -o uuid,name,vg_name,attr,size,seg_start_pe,devices,tags a246386b-f31d-451d-b8a6-2f4c0dfa27b4' (cwd None)
>Thread-864::DEBUG::2014-05-29 12:26:29,678::lvm::288::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-864::DEBUG::2014-05-29 12:26:29,679::lvm::454::Storage.LVM::(_reloadlvs) lvs reloaded
>Thread-864::DEBUG::2014-05-29 12:26:29,679::lvm::454::OperationMutex::(_reloadlvs) Operation 'lvm reload operation' released the operation mutex
>Thread-864::DEBUG::2014-05-29 12:26:29,680::lvm::288::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /usr/sbin/lvm lvchange --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ \'a|/dev/mapper/3600140596b9bb9189094a98a6891f0a4|\', \'r|.*|\' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1  use_lvmetad=0 }  backup {  retain_min = 50  retain_days = 0 } " --autobackup n --available y a246386b-f31d-451d-b8a6-2f4c0dfa27b4/7e0ec106-f2dc-4567-b050-e3289bf2d47f a246386b-f31d-451d-b8a6-2f4c0dfa27b4/378fdb5e-1853-4946-9a79-fd7bd00bb466' (cwd None)
>Thread-864::DEBUG::2014-05-29 12:26:29,847::lvm::288::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-864::DEBUG::2014-05-29 12:26:29,847::lvm::505::OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-864::DEBUG::2014-05-29 12:26:29,847::lvm::517::OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-864::DEBUG::2014-05-29 12:26:29,848::fileUtils::142::Storage.fileUtils::(createdir) Creating directory: /var/run/vdsm/storage/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/dad706d6-e1e9-4f31-87d4-610b3511a932
>Thread-864::DEBUG::2014-05-29 12:26:29,848::blockSD::1078::Storage.StorageDomain::(createImageLinks) Creating symlink from /dev/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/7e0ec106-f2dc-4567-b050-e3289bf2d47f to /var/run/vdsm/storage/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/dad706d6-e1e9-4f31-87d4-610b3511a932/7e0ec106-f2dc-4567-b050-e3289bf2d47f
>Thread-864::DEBUG::2014-05-29 12:26:29,848::blockSD::1078::Storage.StorageDomain::(createImageLinks) Creating symlink from /dev/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/378fdb5e-1853-4946-9a79-fd7bd00bb466 to /var/run/vdsm/storage/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/dad706d6-e1e9-4f31-87d4-610b3511a932/378fdb5e-1853-4946-9a79-fd7bd00bb466
>Thread-864::DEBUG::2014-05-29 12:26:29,848::blockSD::1048::Storage.StorageDomain::(linkBCImage) Creating symlink from /var/run/vdsm/storage/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/dad706d6-e1e9-4f31-87d4-610b3511a932 to /rhev/data-center/mnt/blockSD/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/images/dad706d6-e1e9-4f31-87d4-610b3511a932
>Thread-864::DEBUG::2014-05-29 12:26:29,848::lvm::419::OperationMutex::(_reloadlvs) Operation 'lvm reload operation' got the operation mutex
>Thread-864::DEBUG::2014-05-29 12:26:29,849::lvm::288::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /usr/sbin/lvm lvs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ \'a|/dev/mapper/3600140596b9bb9189094a98a6891f0a4|\', \'r|.*|\' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1  use_lvmetad=0 }  backup {  retain_min = 50  retain_days = 0 } " --noheadings --units b --nosuffix --separator | --ignoreskippedcluster -o uuid,name,vg_name,attr,size,seg_start_pe,devices,tags a246386b-f31d-451d-b8a6-2f4c0dfa27b4' (cwd None)
>Thread-864::DEBUG::2014-05-29 12:26:29,890::lvm::288::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-864::DEBUG::2014-05-29 12:26:29,891::lvm::454::Storage.LVM::(_reloadlvs) lvs reloaded
>Thread-864::DEBUG::2014-05-29 12:26:29,891::lvm::454::OperationMutex::(_reloadlvs) Operation 'lvm reload operation' released the operation mutex
>Thread-864::INFO::2014-05-29 12:26:29,891::logUtils::47::dispatcher::(wrapper) Run and protect: prepareImage, Return response: {'info': {'domainID': 'a246386b-f31d-451d-b8a6-2f4c0dfa27b4', 'volType': 'path', 'leaseOffset': 115343360, 'path': '/rhev/data-center/mnt/blockSD/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/images/dad706d6-e1e9-4f31-87d4-610b3511a932/7e0ec106-f2dc-4567-b050-e3289bf2d47f', 'volumeID': '7e0ec106-f2dc-4567-b050-e3289bf2d47f', 'leasePath': '/dev/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/leases', 'imageID': 'dad706d6-e1e9-4f31-87d4-610b3511a932'}, 'path': '/rhev/data-center/mnt/blockSD/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/images/dad706d6-e1e9-4f31-87d4-610b3511a932/7e0ec106-f2dc-4567-b050-e3289bf2d47f', 'imgVolumesInfo': [{'domainID': 'a246386b-f31d-451d-b8a6-2f4c0dfa27b4', 'volType': 'path', 'leaseOffset': 115343360, 'path': '/rhev/data-center/mnt/blockSD/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/images/dad706d6-e1e9-4f31-87d4-610b3511a932/7e0ec106-f2dc-4567-b050-e3289bf2d47f', 'volumeID': '7e0ec106-f2dc-4567-b050-e3289bf2d47f', 'leasePath': '/dev/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/leases', 'imageID': 'dad706d6-e1e9-4f31-87d4-610b3511a932'}, {'domainID': 'a246386b-f31d-451d-b8a6-2f4c0dfa27b4', 'volType': 'path', 'leaseOffset': 110100480, 'path': '/rhev/data-center/mnt/blockSD/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/images/dad706d6-e1e9-4f31-87d4-610b3511a932/378fdb5e-1853-4946-9a79-fd7bd00bb466', 'volumeID': '378fdb5e-1853-4946-9a79-fd7bd00bb466', 'leasePath': '/dev/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/leases', 'imageID': 'dad706d6-e1e9-4f31-87d4-610b3511a932'}]}
>Thread-864::DEBUG::2014-05-29 12:26:29,891::task::1188::TaskManager.Task::(prepare) Task=`63426c80-7982-485a-b1c4-7b12108cc8e4`::finished: {'info': {'domainID': 'a246386b-f31d-451d-b8a6-2f4c0dfa27b4', 'volType': 'path', 'leaseOffset': 115343360, 'path': '/rhev/data-center/mnt/blockSD/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/images/dad706d6-e1e9-4f31-87d4-610b3511a932/7e0ec106-f2dc-4567-b050-e3289bf2d47f', 'volumeID': '7e0ec106-f2dc-4567-b050-e3289bf2d47f', 'leasePath': '/dev/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/leases', 'imageID': 'dad706d6-e1e9-4f31-87d4-610b3511a932'}, 'path': '/rhev/data-center/mnt/blockSD/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/images/dad706d6-e1e9-4f31-87d4-610b3511a932/7e0ec106-f2dc-4567-b050-e3289bf2d47f', 'imgVolumesInfo': [{'domainID': 'a246386b-f31d-451d-b8a6-2f4c0dfa27b4', 'volType': 'path', 'leaseOffset': 115343360, 'path': '/rhev/data-center/mnt/blockSD/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/images/dad706d6-e1e9-4f31-87d4-610b3511a932/7e0ec106-f2dc-4567-b050-e3289bf2d47f', 'volumeID': '7e0ec106-f2dc-4567-b050-e3289bf2d47f', 'leasePath': '/dev/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/leases', 'imageID': 'dad706d6-e1e9-4f31-87d4-610b3511a932'}, {'domainID': 'a246386b-f31d-451d-b8a6-2f4c0dfa27b4', 'volType': 'path', 'leaseOffset': 110100480, 'path': '/rhev/data-center/mnt/blockSD/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/images/dad706d6-e1e9-4f31-87d4-610b3511a932/378fdb5e-1853-4946-9a79-fd7bd00bb466', 'volumeID': '378fdb5e-1853-4946-9a79-fd7bd00bb466', 'leasePath': '/dev/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/leases', 'imageID': 'dad706d6-e1e9-4f31-87d4-610b3511a932'}]}
>Thread-864::DEBUG::2014-05-29 12:26:29,892::task::595::TaskManager.Task::(_updateState) Task=`63426c80-7982-485a-b1c4-7b12108cc8e4`::moving from state preparing -> state finished
>Thread-864::DEBUG::2014-05-29 12:26:29,892::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.a246386b-f31d-451d-b8a6-2f4c0dfa27b4': < ResourceRef 'Storage.a246386b-f31d-451d-b8a6-2f4c0dfa27b4', isValid: 'True' obj: 'None'>}
>Thread-864::DEBUG::2014-05-29 12:26:29,892::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-864::DEBUG::2014-05-29 12:26:29,892::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.a246386b-f31d-451d-b8a6-2f4c0dfa27b4'
>Thread-864::DEBUG::2014-05-29 12:26:29,892::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.a246386b-f31d-451d-b8a6-2f4c0dfa27b4' (0 active users)
>Thread-864::DEBUG::2014-05-29 12:26:29,892::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.a246386b-f31d-451d-b8a6-2f4c0dfa27b4' is free, finding out if anyone is waiting for it.
>Thread-864::DEBUG::2014-05-29 12:26:29,892::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.a246386b-f31d-451d-b8a6-2f4c0dfa27b4', Clearing records.
>Thread-864::DEBUG::2014-05-29 12:26:29,892::task::993::TaskManager.Task::(_decref) Task=`63426c80-7982-485a-b1c4-7b12108cc8e4`::ref 0 aborting False
>Thread-864::INFO::2014-05-29 12:26:29,893::clientIF::313::vds::(prepareVolumePath) prepared volume path: /rhev/data-center/mnt/blockSD/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/images/dad706d6-e1e9-4f31-87d4-610b3511a932/7e0ec106-f2dc-4567-b050-e3289bf2d47f
>Thread-864::INFO::2014-05-29 12:26:29,896::vm::5284::root::(_getNetworkIp) network None: using 0
>Thread-864::DEBUG::2014-05-29 12:26:29,896::vm::845::vm.Vm::(__init__) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::Ignoring param (target, 1048576) in BalloonDevice
>Thread-864::DEBUG::2014-05-29 12:26:29,904::vm::2989::vm.Vm::(_run) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::<?xml version="1.0" encoding="utf-8"?>
><domain type="kvm">
>	<name>brewer-5</name>
>	<uuid>af8df38e-2e99-4a89-9483-a540027ea6b1</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/af8df38e-2e99-4a89-9483-a540027ea6b1.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/af8df38e-2e99-4a89-9483-a540027ea6b1.org.qemu.guest_agent.0"/>
>		</channel>
>		<input bus="ps2" type="mouse"/>
>		<memballoon model="virtio"/>
>		<controller index="0" model="virtio-scsi" type="scsi">
>			<address bus="0x00" domain="0x0000" function="0x0" slot="0x04" type="pci"/>
>		</controller>
>		<video>
>			<model heads="1" type="qxl" vram="32768"/>
>		</video>
>		<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>
>		<interface type="bridge">
>			<address bus="0x00" domain="0x0000" function="0x0" slot="0x03" type="pci"/>
>			<mac address="00:1a:4a:3f:44:a3"/>
>			<model type="virtio"/>
>			<source bridge="ovirtmgmt"/>
>			<filterref filter="vdsm-no-mac-spoofing"/>
>			<link state="up"/>
>			<boot order="3"/>
>		</interface>
>		<disk device="cdrom" snapshot="no" type="file">
>			<source file="/rhev/data-center/mnt/192.168.2.1:_home_storage_iso/e453999e-ec9f-420b-941c-a9f9cc4432bb/images/11111111-1111-1111-1111-111111111111/CorePlus-current.iso" startupPolicy="optional"/>
>			<target bus="ide" dev="hdc"/>
>			<readonly/>
>			<serial/>
>			<boot order="2"/>
>		</disk>
>		<disk device="disk" snapshot="no" type="block">
>			<address bus="0x00" domain="0x0000" function="0x0" slot="0x06" type="pci"/>
>			<source dev="/rhev/data-center/mnt/blockSD/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/images/dad706d6-e1e9-4f31-87d4-610b3511a932/7e0ec106-f2dc-4567-b050-e3289bf2d47f"/>
>			<target bus="virtio" dev="vda"/>
>			<serial>dad706d6-e1e9-4f31-87d4-610b3511a932</serial>
>			<boot order="1"/>
>			<driver cache="none" error_policy="stop" io="native" name="qemu" type="qcow2"/>
>		</disk>
>		<channel type="spicevmc">
>			<target name="com.redhat.spice.0" type="virtio"/>
>		</channel>
>	</devices>
>	<os>
>		<type arch="x86_64" machine="pc">hvm</type>
>		<smbios mode="sysinfo"/>
>	</os>
>	<sysinfo type="smbios">
>		<system>
>			<entry name="manufacturer">oVirt</entry>
>			<entry name="product">oVirt Node</entry>
>			<entry name="version">20-3</entry>
>			<entry name="serial">4C4C4544-0043-5310-8037-C4C04F425A31</entry>
>			<entry name="uuid">af8df38e-2e99-4a89-9483-a540027ea6b1</entry>
>		</system>
>	</sysinfo>
>	<clock adjustment="0" offset="variable">
>		<timer name="rtc" tickpolicy="catchup"/>
>		<timer name="pit" tickpolicy="delay"/>
>		<timer name="hpet" present="no"/>
>	</clock>
>	<features>
>		<acpi/>
>	</features>
>	<cpu match="exact">
>		<model>SandyBridge</model>
>		<topology cores="1" sockets="160" threads="1"/>
>	</cpu>
></domain>
>
>Thread-450::DEBUG::2014-05-29 12:26:30,402::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd if=/rhev/data-center/mnt/192.168.2.1:_home_storage_iso/e453999e-ec9f-420b-941c-a9f9cc4432bb/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1' (cwd None)
>Thread-450::DEBUG::2014-05-29 12:26:30,409::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n531 bytes (531 B) copied, 0.000961331 s, 552 kB/s\n'; <rc> = 0
>libvirtEventLoop::DEBUG::2014-05-29 12:26:30,504::vm::4942::vm.Vm::(_onLibvirtLifecycleEvent) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::event Started detail 0 opaque None
>Thread-864::DEBUG::2014-05-29 12:26:30,518::vm::4785::vm.Vm::(_getUnderlyingDriveInfo) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::Looking for drive with attributes {'name': u'hdc', 'bootOrder': u'2', 'boot': [<DOM Element: boot at 0x7f5fcc35a2d8>], 'readonly': True, 'address': {u'bus': u'1', u'controller': u'0', u'type': u'drive', u'target': u'0', u'unit': u'0'}, 'path': u'/rhev/data-center/mnt/192.168.2.1:_home_storage_iso/e453999e-ec9f-420b-941c-a9f9cc4432bb/images/11111111-1111-1111-1111-111111111111/CorePlus-current.iso', 'type': u'cdrom'}
>Thread-864::DEBUG::2014-05-29 12:26:30,518::vm::4806::vm.Vm::(_getUnderlyingDriveInfo) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::Matched {'name': (u'hdc', u'hdc'), 'bootOrder': (u'2', u'2'), 'boot': ([<DOM Element: boot at 0x7f5fcc35a2d8>], 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': (u'/rhev/data-center/mnt/192.168.2.1:_home_storage_iso/e453999e-ec9f-420b-941c-a9f9cc4432bb/images/11111111-1111-1111-1111-111111111111/CorePlus-current.iso', '/rhev/data-center/mnt/192.168.2.1:_home_storage_iso/e453999e-ec9f-420b-941c-a9f9cc4432bb/images/11111111-1111-1111-1111-111111111111/CorePlus-current.iso'), 'type': (u'cdrom', u'cdrom')}
>Thread-864::DEBUG::2014-05-29 12:26:30,519::vm::4825::vm.Vm::(_getUnderlyingDriveInfo) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::Matched {'name': (u'hdc', None), 'bootOrder': (u'2', None), 'boot': ([<DOM Element: boot at 0x7f5fcc35a2d8>], None), 'readonly': (True, None), 'address': ({u'bus': u'1', u'controller': u'0', u'type': u'drive', u'target': u'0', u'unit': u'0'}, None), 'path': (u'/rhev/data-center/mnt/192.168.2.1:_home_storage_iso/e453999e-ec9f-420b-941c-a9f9cc4432bb/images/11111111-1111-1111-1111-111111111111/CorePlus-current.iso', None), 'type': (u'cdrom', None)}
>Thread-864::DEBUG::2014-05-29 12:26:30,519::vm::4785::vm.Vm::(_getUnderlyingDriveInfo) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::Looking for drive with attributes {'name': u'vda', 'bootOrder': u'1', 'boot': [<DOM Element: boot at 0x7f5fb40e33b0>], '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/blockSD/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/images/dad706d6-e1e9-4f31-87d4-610b3511a932/7e0ec106-f2dc-4567-b050-e3289bf2d47f', 'type': u'disk'}
>Thread-864::DEBUG::2014-05-29 12:26:30,519::vm::4806::vm.Vm::(_getUnderlyingDriveInfo) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::Matched {'name': (u'vda', u'vda'), 'bootOrder': (u'1', u'1'), 'boot': ([<DOM Element: boot at 0x7f5fb40e33b0>], 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/blockSD/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/images/dad706d6-e1e9-4f31-87d4-610b3511a932/7e0ec106-f2dc-4567-b050-e3289bf2d47f', '/rhev/data-center/mnt/blockSD/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/images/dad706d6-e1e9-4f31-87d4-610b3511a932/7e0ec106-f2dc-4567-b050-e3289bf2d47f'), 'type': (u'disk', u'disk')}
>Thread-864::DEBUG::2014-05-29 12:26:30,519::vm::4825::vm.Vm::(_getUnderlyingDriveInfo) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::Matched {'name': (u'vda', None), 'bootOrder': (u'1', None), 'boot': ([<DOM Element: boot at 0x7f5fb40e33b0>], None), 'readonly': (False, None), 'address': ({u'slot': u'0x06', u'bus': u'0x00', u'domain': u'0x0000', u'type': u'pci', u'function': u'0x0'}, None), 'path': (u'/rhev/data-center/mnt/blockSD/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/images/dad706d6-e1e9-4f31-87d4-610b3511a932/7e0ec106-f2dc-4567-b050-e3289bf2d47f', None), 'type': (u'disk', None)}
>Thread-864::DEBUG::2014-05-29 12:26:30,555::task::595::TaskManager.Task::(_updateState) Task=`70dfaaa5-5205-4b14-acc2-8589407e85d4`::moving from state init -> state preparing
>Thread-864::INFO::2014-05-29 12:26:30,556::logUtils::44::dispatcher::(wrapper) Run and protect: imageSyncVolumeChain(sdUUID='a246386b-f31d-451d-b8a6-2f4c0dfa27b4', imgUUID='dad706d6-e1e9-4f31-87d4-610b3511a932', volUUID='7e0ec106-f2dc-4567-b050-e3289bf2d47f', newChain=['378fdb5e-1853-4946-9a79-fd7bd00bb466', '7e0ec106-f2dc-4567-b050-e3289bf2d47f'])
>Thread-864::DEBUG::2014-05-29 12:26:30,556::resourceManager::198::ResourceManager.Request::(__init__) ResName=`a246386b-f31d-451d-b8a6-2f4c0dfa27b4_imageNS.dad706d6-e1e9-4f31-87d4-610b3511a932`ReqID=`78832464-d123-4640-8773-871823a99962`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '1773' at 'imageSyncVolumeChain'
>Thread-864::DEBUG::2014-05-29 12:26:30,556::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'a246386b-f31d-451d-b8a6-2f4c0dfa27b4_imageNS.dad706d6-e1e9-4f31-87d4-610b3511a932' for lock type 'shared'
>Thread-864::DEBUG::2014-05-29 12:26:30,556::lvm::419::OperationMutex::(_reloadlvs) Operation 'lvm reload operation' got the operation mutex
>Thread-864::DEBUG::2014-05-29 12:26:30,557::lvm::288::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /usr/sbin/lvm lvs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ \'a|/dev/mapper/3600140596b9bb9189094a98a6891f0a4|\', \'r|.*|\' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1  use_lvmetad=0 }  backup {  retain_min = 50  retain_days = 0 } " --noheadings --units b --nosuffix --separator | --ignoreskippedcluster -o uuid,name,vg_name,attr,size,seg_start_pe,devices,tags a246386b-f31d-451d-b8a6-2f4c0dfa27b4' (cwd None)
>Thread-864::DEBUG::2014-05-29 12:26:30,603::lvm::288::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-864::DEBUG::2014-05-29 12:26:30,604::lvm::454::Storage.LVM::(_reloadlvs) lvs reloaded
>Thread-864::DEBUG::2014-05-29 12:26:30,605::lvm::454::OperationMutex::(_reloadlvs) Operation 'lvm reload operation' released the operation mutex
>Thread-864::DEBUG::2014-05-29 12:26:30,605::blockVolume::596::Storage.Misc.excCmd::(getMetadata) '/usr/bin/dd iflag=direct skip=10 bs=512 if=/dev/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/metadata count=1' (cwd None)
>Thread-864::DEBUG::2014-05-29 12:26:30,611::blockVolume::596::Storage.Misc.excCmd::(getMetadata) SUCCESS: <err> = '1+0 records in\n1+0 records out\n512 bytes (512 B) copied, 0.000898377 s, 570 kB/s\n'; <rc> = 0
>Thread-864::DEBUG::2014-05-29 12:26:30,611::misc::287::Storage.Misc::(validateDDBytes) err: ['1+0 records in', '1+0 records out', '512 bytes (512 B) copied, 0.000898377 s, 570 kB/s'], size: 512
>Thread-864::DEBUG::2014-05-29 12:26:30,611::blockVolume::596::Storage.Misc.excCmd::(getMetadata) '/usr/bin/dd iflag=direct skip=10 bs=512 if=/dev/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/metadata count=1' (cwd None)
>Thread-864::DEBUG::2014-05-29 12:26:30,616::blockVolume::596::Storage.Misc.excCmd::(getMetadata) SUCCESS: <err> = '1+0 records in\n1+0 records out\n512 bytes (512 B) copied, 0.000856292 s, 598 kB/s\n'; <rc> = 0
>Thread-864::DEBUG::2014-05-29 12:26:30,616::misc::287::Storage.Misc::(validateDDBytes) err: ['1+0 records in', '1+0 records out', '512 bytes (512 B) copied, 0.000856292 s, 598 kB/s'], size: 512
>Thread-864::DEBUG::2014-05-29 12:26:30,617::blockVolume::596::Storage.Misc.excCmd::(getMetadata) '/usr/bin/dd iflag=direct skip=5 bs=512 if=/dev/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/metadata count=1' (cwd None)
>Thread-864::DEBUG::2014-05-29 12:26:30,622::blockVolume::596::Storage.Misc.excCmd::(getMetadata) SUCCESS: <err> = '1+0 records in\n1+0 records out\n512 bytes (512 B) copied, 0.000922049 s, 555 kB/s\n'; <rc> = 0
>Thread-864::DEBUG::2014-05-29 12:26:30,622::misc::287::Storage.Misc::(validateDDBytes) err: ['1+0 records in', '1+0 records out', '512 bytes (512 B) copied, 0.000922049 s, 555 kB/s'], size: 512
>Thread-864::INFO::2014-05-29 12:26:30,623::image::213::Storage.Image::(getChain) sdUUID=a246386b-f31d-451d-b8a6-2f4c0dfa27b4 imgUUID=dad706d6-e1e9-4f31-87d4-610b3511a932 chain=[<storage.blockVolume.BlockVolume object at 0x7f5fcc42dc10>] 
>Thread-864::DEBUG::2014-05-29 12:26:30,623::resourceManager::198::ResourceManager.Request::(__init__) ResName=`a246386b-f31d-451d-b8a6-2f4c0dfa27b4_volumeNS.378fdb5e-1853-4946-9a79-fd7bd00bb466`ReqID=`0bfd2cf1-2096-40a0-bb70-2f1809e1c312`::Request was made in '/usr/share/vdsm/storage/resourceFactories.py' line '159' at '__getResourceCandidatesList'
>Thread-864::DEBUG::2014-05-29 12:26:30,623::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'a246386b-f31d-451d-b8a6-2f4c0dfa27b4_volumeNS.378fdb5e-1853-4946-9a79-fd7bd00bb466' for lock type 'shared'
>Thread-864::DEBUG::2014-05-29 12:26:30,624::resourceManager::601::ResourceManager::(registerResource) Resource 'a246386b-f31d-451d-b8a6-2f4c0dfa27b4_volumeNS.378fdb5e-1853-4946-9a79-fd7bd00bb466' is free. Now locking as 'shared' (1 active user)
>Thread-864::DEBUG::2014-05-29 12:26:30,624::resourceManager::238::ResourceManager.Request::(grant) ResName=`a246386b-f31d-451d-b8a6-2f4c0dfa27b4_volumeNS.378fdb5e-1853-4946-9a79-fd7bd00bb466`ReqID=`0bfd2cf1-2096-40a0-bb70-2f1809e1c312`::Granted request
>Thread-864::DEBUG::2014-05-29 12:26:30,624::resourceManager::198::ResourceManager.Request::(__init__) ResName=`a246386b-f31d-451d-b8a6-2f4c0dfa27b4_volumeNS.7e0ec106-f2dc-4567-b050-e3289bf2d47f`ReqID=`07ad3bfa-1cc8-41ae-aa78-1c85a81e904f`::Request was made in '/usr/share/vdsm/storage/resourceFactories.py' line '172' at '__getResourceCandidatesList'
>Thread-864::DEBUG::2014-05-29 12:26:30,624::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'a246386b-f31d-451d-b8a6-2f4c0dfa27b4_volumeNS.7e0ec106-f2dc-4567-b050-e3289bf2d47f' for lock type 'shared'
>Thread-864::DEBUG::2014-05-29 12:26:30,624::resourceManager::601::ResourceManager::(registerResource) Resource 'a246386b-f31d-451d-b8a6-2f4c0dfa27b4_volumeNS.7e0ec106-f2dc-4567-b050-e3289bf2d47f' is free. Now locking as 'shared' (1 active user)
>Thread-864::DEBUG::2014-05-29 12:26:30,624::resourceManager::238::ResourceManager.Request::(grant) ResName=`a246386b-f31d-451d-b8a6-2f4c0dfa27b4_volumeNS.7e0ec106-f2dc-4567-b050-e3289bf2d47f`ReqID=`07ad3bfa-1cc8-41ae-aa78-1c85a81e904f`::Granted request
>Thread-864::DEBUG::2014-05-29 12:26:30,625::resourceManager::601::ResourceManager::(registerResource) Resource 'a246386b-f31d-451d-b8a6-2f4c0dfa27b4_imageNS.dad706d6-e1e9-4f31-87d4-610b3511a932' is free. Now locking as 'shared' (1 active user)
>Thread-864::DEBUG::2014-05-29 12:26:30,625::resourceManager::238::ResourceManager.Request::(grant) ResName=`a246386b-f31d-451d-b8a6-2f4c0dfa27b4_imageNS.dad706d6-e1e9-4f31-87d4-610b3511a932`ReqID=`78832464-d123-4640-8773-871823a99962`::Granted request
>Thread-864::DEBUG::2014-05-29 12:26:30,625::blockVolume::596::Storage.Misc.excCmd::(getMetadata) '/usr/bin/dd iflag=direct skip=10 bs=512 if=/dev/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/metadata count=1' (cwd None)
>Thread-864::DEBUG::2014-05-29 12:26:30,630::blockVolume::596::Storage.Misc.excCmd::(getMetadata) SUCCESS: <err> = '1+0 records in\n1+0 records out\n512 bytes (512 B) copied, 0.000933527 s, 548 kB/s\n'; <rc> = 0
>Thread-864::DEBUG::2014-05-29 12:26:30,631::misc::287::Storage.Misc::(validateDDBytes) err: ['1+0 records in', '1+0 records out', '512 bytes (512 B) copied, 0.000933527 s, 548 kB/s'], size: 512
>Thread-864::DEBUG::2014-05-29 12:26:30,631::blockVolume::596::Storage.Misc.excCmd::(getMetadata) '/usr/bin/dd iflag=direct skip=5 bs=512 if=/dev/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/metadata count=1' (cwd None)
>Thread-864::DEBUG::2014-05-29 12:26:30,637::blockVolume::596::Storage.Misc.excCmd::(getMetadata) SUCCESS: <err> = '1+0 records in\n1+0 records out\n512 bytes (512 B) copied, 0.000895115 s, 572 kB/s\n'; <rc> = 0
>Thread-864::DEBUG::2014-05-29 12:26:30,637::misc::287::Storage.Misc::(validateDDBytes) err: ['1+0 records in', '1+0 records out', '512 bytes (512 B) copied, 0.000895115 s, 572 kB/s'], size: 512
>Thread-864::INFO::2014-05-29 12:26:30,637::image::213::Storage.Image::(getChain) sdUUID=a246386b-f31d-451d-b8a6-2f4c0dfa27b4 imgUUID=dad706d6-e1e9-4f31-87d4-610b3511a932 chain=[<storage.blockVolume.BlockVolume object at 0x1f94910>] 
>Thread-864::DEBUG::2014-05-29 12:26:30,637::hsm::1781::Storage.HSM::(imageSyncVolumeChain) unlinking subchain: []
>Thread-864::DEBUG::2014-05-29 12:26:30,637::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'a246386b-f31d-451d-b8a6-2f4c0dfa27b4_imageNS.dad706d6-e1e9-4f31-87d4-610b3511a932'
>Thread-864::DEBUG::2014-05-29 12:26:30,638::resourceManager::635::ResourceManager::(releaseResource) Released resource 'a246386b-f31d-451d-b8a6-2f4c0dfa27b4_imageNS.dad706d6-e1e9-4f31-87d4-610b3511a932' (0 active users)
>Thread-864::DEBUG::2014-05-29 12:26:30,638::resourceManager::641::ResourceManager::(releaseResource) Resource 'a246386b-f31d-451d-b8a6-2f4c0dfa27b4_imageNS.dad706d6-e1e9-4f31-87d4-610b3511a932' is free, finding out if anyone is waiting for it.
>Thread-864::DEBUG::2014-05-29 12:26:30,638::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'a246386b-f31d-451d-b8a6-2f4c0dfa27b4_volumeNS.378fdb5e-1853-4946-9a79-fd7bd00bb466'
>Thread-864::DEBUG::2014-05-29 12:26:30,638::resourceManager::635::ResourceManager::(releaseResource) Released resource 'a246386b-f31d-451d-b8a6-2f4c0dfa27b4_volumeNS.378fdb5e-1853-4946-9a79-fd7bd00bb466' (0 active users)
>Thread-864::DEBUG::2014-05-29 12:26:30,638::resourceManager::641::ResourceManager::(releaseResource) Resource 'a246386b-f31d-451d-b8a6-2f4c0dfa27b4_volumeNS.378fdb5e-1853-4946-9a79-fd7bd00bb466' is free, finding out if anyone is waiting for it.
>Thread-864::DEBUG::2014-05-29 12:26:30,638::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'a246386b-f31d-451d-b8a6-2f4c0dfa27b4_volumeNS.378fdb5e-1853-4946-9a79-fd7bd00bb466', Clearing records.
>Thread-864::DEBUG::2014-05-29 12:26:30,638::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'a246386b-f31d-451d-b8a6-2f4c0dfa27b4_volumeNS.7e0ec106-f2dc-4567-b050-e3289bf2d47f'
>Thread-864::DEBUG::2014-05-29 12:26:30,638::resourceManager::635::ResourceManager::(releaseResource) Released resource 'a246386b-f31d-451d-b8a6-2f4c0dfa27b4_volumeNS.7e0ec106-f2dc-4567-b050-e3289bf2d47f' (0 active users)
>Thread-864::DEBUG::2014-05-29 12:26:30,639::resourceManager::641::ResourceManager::(releaseResource) Resource 'a246386b-f31d-451d-b8a6-2f4c0dfa27b4_volumeNS.7e0ec106-f2dc-4567-b050-e3289bf2d47f' is free, finding out if anyone is waiting for it.
>Thread-864::DEBUG::2014-05-29 12:26:30,639::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'a246386b-f31d-451d-b8a6-2f4c0dfa27b4_volumeNS.7e0ec106-f2dc-4567-b050-e3289bf2d47f', Clearing records.
>Thread-864::DEBUG::2014-05-29 12:26:30,639::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'a246386b-f31d-451d-b8a6-2f4c0dfa27b4_imageNS.dad706d6-e1e9-4f31-87d4-610b3511a932', Clearing records.
>Thread-864::INFO::2014-05-29 12:26:30,639::logUtils::47::dispatcher::(wrapper) Run and protect: imageSyncVolumeChain, Return response: None
>Thread-864::DEBUG::2014-05-29 12:26:30,639::task::1188::TaskManager.Task::(prepare) Task=`70dfaaa5-5205-4b14-acc2-8589407e85d4`::finished: None
>Thread-864::DEBUG::2014-05-29 12:26:30,639::task::595::TaskManager.Task::(_updateState) Task=`70dfaaa5-5205-4b14-acc2-8589407e85d4`::moving from state preparing -> state finished
>Thread-864::DEBUG::2014-05-29 12:26:30,639::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-864::DEBUG::2014-05-29 12:26:30,639::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-864::DEBUG::2014-05-29 12:26:30,639::task::993::TaskManager.Task::(_decref) Task=`70dfaaa5-5205-4b14-acc2-8589407e85d4`::ref 0 aborting False
>Thread-864::DEBUG::2014-05-29 12:26:30,640::vm::5205::vm.Vm::(_postLiveMergeSyncVolumeChain) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::Volume chain for drive 'vda' is consistent
>Thread-864::DEBUG::2014-05-29 12:26:30,640::sampling::361::vm.Vm::(start) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::Start statistics collection
>Thread-866::DEBUG::2014-05-29 12:26:30,640::sampling::390::vm.Vm::(run) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::Stats thread started
>Thread-864::DEBUG::2014-05-29 12:26:30,642::vmchannels::195::vds::(register) Add fileno 54 to listener's channels.
>Thread-864::WARNING::2014-05-29 12:26:30,649::vm::3547::vm.Vm::(_readPauseCode) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::_readPauseCode unsupported by libvirt vm
>Thread-866::DEBUG::2014-05-29 12:26:30,650::task::595::TaskManager.Task::(_updateState) Task=`f0a78472-bd8c-4078-a061-06a2694bd24c`::moving from state init -> state preparing
>Thread-866::INFO::2014-05-29 12:26:30,651::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='a246386b-f31d-451d-b8a6-2f4c0dfa27b4', spUUID='be744655-2a19-4919-92f3-e7c20ac03193', imgUUID='dad706d6-e1e9-4f31-87d4-610b3511a932', volUUID='7e0ec106-f2dc-4567-b050-e3289bf2d47f', options=None)
>Thread-866::INFO::2014-05-29 12:26:30,651::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '134217728', 'apparentsize': '134217728'}
>Thread-866::DEBUG::2014-05-29 12:26:30,651::task::1188::TaskManager.Task::(prepare) Task=`f0a78472-bd8c-4078-a061-06a2694bd24c`::finished: {'truesize': '134217728', 'apparentsize': '134217728'}
>Thread-866::DEBUG::2014-05-29 12:26:30,651::task::595::TaskManager.Task::(_updateState) Task=`f0a78472-bd8c-4078-a061-06a2694bd24c`::moving from state preparing -> state finished
>Thread-866::DEBUG::2014-05-29 12:26:30,652::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-866::DEBUG::2014-05-29 12:26:30,652::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-866::DEBUG::2014-05-29 12:26:30,652::task::993::TaskManager.Task::(_decref) Task=`f0a78472-bd8c-4078-a061-06a2694bd24c`::ref 0 aborting False
>Thread-864::DEBUG::2014-05-29 12:26:30,652::vm::2041::vm.Vm::(_startUnderlyingVm) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::_ongoingCreations released
>VM Channels Listener::DEBUG::2014-05-29 12:26:31,236::vmchannels::103::vds::(_do_add_channels) fileno 54 was added to unconnected channels.
>VM Channels Listener::DEBUG::2014-05-29 12:26:31,236::vmchannels::129::vds::(_handle_unconnected) Trying to connect fileno 54.
>VM Channels Listener::DEBUG::2014-05-29 12:26:31,236::guestagent::199::vm.Vm::(_connect) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::Attempting connection to /var/lib/libvirt/qemu/channels/af8df38e-2e99-4a89-9483-a540027ea6b1.com.redhat.rhevm.vdsm
>VM Channels Listener::DEBUG::2014-05-29 12:26:31,236::guestagent::202::vm.Vm::(_connect) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::Connected to /var/lib/libvirt/qemu/channels/af8df38e-2e99-4a89-9483-a540027ea6b1.com.redhat.rhevm.vdsm
>VM Channels Listener::DEBUG::2014-05-29 12:26:31,236::vmchannels::145::vds::(_handle_unconnected) Connecting to fileno 54 succeeded.
>Thread-451::DEBUG::2014-05-29 12:26:31,875::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd if=/dev/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/metadata iflag=direct of=/dev/null bs=4096 count=1' (cwd None)
>Thread-451::DEBUG::2014-05-29 12:26:31,881::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.00164132 s, 2.5 MB/s\n'; <rc> = 0
>Thread-828::DEBUG::2014-05-29 12:26:32,514::BindingXMLRPC::1052::vds::(wrapper) client [192.168.2.1]::call vmGetStats with ('af8df38e-2e99-4a89-9483-a540027ea6b1',) {} flowID [2b2b19f4]
>Thread-828::DEBUG::2014-05-29 12:26:32,515::vm::284::vm.Vm::(_getCpuStats) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::CPU stats not available: 'NoneType' object has no attribute '__getitem__'
>Thread-828::DEBUG::2014-05-29 12:26:32,515::vm::393::vm.Vm::(_getDiskLatency) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::Disk hdc latency not available
>Thread-828::DEBUG::2014-05-29 12:26:32,515::vm::393::vm.Vm::(_getDiskLatency) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::Disk vda latency not available
>Thread-828::DEBUG::2014-05-29 12:26:32,515::vm::405::vm.Vm::(_getVmJobs) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::VmJob stats not available
>Thread-828::DEBUG::2014-05-29 12:26:32,516::BindingXMLRPC::1059::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Powering up', 'username': 'Unknown', 'memUsage': '0', 'acpiEnable': 'true', 'guestFQDN': '', 'pid': '20589', 'displayIp': '0', 'displayPort': '-1', 'session': 'Unknown', 'displaySecurePort': u'5900', 'timeOffset': '0', 'hash': '7153593655711157332', 'balloonInfo': {'balloon_max': '1048576', 'balloon_target': '1048576', 'balloon_cur': '1048576', 'balloon_min': '1048576'}, 'pauseCode': 'NOERR', 'clientIp': '', 'kvmEnable': 'true', 'network': {}, 'vmId': 'af8df38e-2e99-4a89-9483-a540027ea6b1', 'displayType': 'qxl', 'cpuUser': '0.00', 'disks': {u'vda': {'truesize': '134217728', 'apparentsize': '134217728', 'imageID': 'dad706d6-e1e9-4f31-87d4-610b3511a932'}, u'hdc': {'truesize': '0', 'apparentsize': '0'}}, 'monitorResponse': '0', 'statsAge': '1.87', 'elapsedTime': '2', 'vmType': 'kvm', 'cpuSys': '0.00', 'guestCPUCount': -1, 'appsList': [], 'guestIPs': ''}]}
>GuestMonitor-brewer-5::DEBUG::2014-05-29 12:26:34,133::vm::284::vm.Vm::(_getCpuStats) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::CPU stats not available: 'NoneType' object has no attribute '__getitem__'
>GuestMonitor-brewer-5::DEBUG::2014-05-29 12:26:34,133::vm::393::vm.Vm::(_getDiskLatency) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::Disk hdc latency not available
>GuestMonitor-brewer-5::DEBUG::2014-05-29 12:26:34,133::vm::393::vm.Vm::(_getDiskLatency) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::Disk vda latency not available
>GuestMonitor-brewer-5::DEBUG::2014-05-29 12:26:34,133::vm::405::vm.Vm::(_getVmJobs) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::VmJob stats not available
>GuestMonitor-brewer-5::DEBUG::2014-05-29 12:26:34,134::vm::284::vm.Vm::(_getCpuStats) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::CPU stats not available: 'NoneType' object has no attribute '__getitem__'
>GuestMonitor-brewer-5::DEBUG::2014-05-29 12:26:34,134::vm::393::vm.Vm::(_getDiskLatency) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::Disk hdc latency not available
>GuestMonitor-brewer-5::DEBUG::2014-05-29 12:26:34,134::vm::393::vm.Vm::(_getDiskLatency) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::Disk vda latency not available
>GuestMonitor-brewer-5::DEBUG::2014-05-29 12:26:34,134::vm::405::vm.Vm::(_getVmJobs) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::VmJob stats not available
>Thread-828::DEBUG::2014-05-29 12:26:35,596::BindingXMLRPC::1052::vds::(wrapper) client [192.168.2.1]::call vmGetStats with ('af8df38e-2e99-4a89-9483-a540027ea6b1',) {} flowID [60d94c75]
>Thread-828::DEBUG::2014-05-29 12:26:35,596::vm::284::vm.Vm::(_getCpuStats) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::CPU stats not available: 'NoneType' object has no attribute '__getitem__'
>Thread-828::DEBUG::2014-05-29 12:26:35,596::vm::393::vm.Vm::(_getDiskLatency) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::Disk hdc latency not available
>Thread-828::DEBUG::2014-05-29 12:26:35,596::vm::393::vm.Vm::(_getDiskLatency) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::Disk vda latency not available
>Thread-828::DEBUG::2014-05-29 12:26:35,596::vm::405::vm.Vm::(_getVmJobs) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::VmJob stats not available
>Thread-828::DEBUG::2014-05-29 12:26:35,597::BindingXMLRPC::1059::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Powering up', 'username': 'Unknown', 'memUsage': '0', 'acpiEnable': 'true', 'guestFQDN': '', 'pid': '20589', 'displayIp': '0', 'displayPort': '-1', 'session': 'Unknown', 'displaySecurePort': u'5900', 'timeOffset': '0', 'hash': '7153593655711157332', 'balloonInfo': {'balloon_max': '1048576', 'balloon_target': '1048576', 'balloon_cur': '1048576', 'balloon_min': '1048576'}, 'pauseCode': 'NOERR', 'clientIp': '', 'kvmEnable': 'true', 'network': {}, 'vmId': 'af8df38e-2e99-4a89-9483-a540027ea6b1', 'displayType': 'qxl', 'cpuUser': '0.00', 'disks': {u'vda': {'truesize': '134217728', 'apparentsize': '134217728', 'imageID': 'dad706d6-e1e9-4f31-87d4-610b3511a932'}, u'hdc': {'truesize': '0', 'apparentsize': '0'}}, 'monitorResponse': '0', 'statsAge': '0.91', 'elapsedTime': '6', 'vmType': 'kvm', 'cpuSys': '0.00', 'guestCPUCount': -1, 'appsList': [], 'guestIPs': ''}]}
>Thread-870::DEBUG::2014-05-29 12:26:36,536::BindingXMLRPC::249::vds::(wrapper) client [192.168.2.1]
>Thread-870::DEBUG::2014-05-29 12:26:36,536::task::595::TaskManager.Task::(_updateState) Task=`4105f239-60d9-4cb1-8851-1fca18ce68c7`::moving from state init -> state preparing
>Thread-870::INFO::2014-05-29 12:26:36,536::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeInfo(sdUUID='a246386b-f31d-451d-b8a6-2f4c0dfa27b4', spUUID='be744655-2a19-4919-92f3-e7c20ac03193', imgUUID='dad706d6-e1e9-4f31-87d4-610b3511a932', volUUID='7e0ec106-f2dc-4567-b050-e3289bf2d47f', options=None)
>Thread-870::DEBUG::2014-05-29 12:26:36,537::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.a246386b-f31d-451d-b8a6-2f4c0dfa27b4`ReqID=`31d6de8d-4bd9-4736-a78d-cd211b1464f2`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '3084' at 'getVolumeInfo'
>Thread-870::DEBUG::2014-05-29 12:26:36,537::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.a246386b-f31d-451d-b8a6-2f4c0dfa27b4' for lock type 'shared'
>Thread-870::DEBUG::2014-05-29 12:26:36,537::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.a246386b-f31d-451d-b8a6-2f4c0dfa27b4' is free. Now locking as 'shared' (1 active user)
>Thread-870::DEBUG::2014-05-29 12:26:36,537::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.a246386b-f31d-451d-b8a6-2f4c0dfa27b4`ReqID=`31d6de8d-4bd9-4736-a78d-cd211b1464f2`::Granted request
>Thread-870::DEBUG::2014-05-29 12:26:36,537::task::827::TaskManager.Task::(resourceAcquired) Task=`4105f239-60d9-4cb1-8851-1fca18ce68c7`::_resourcesAcquired: Storage.a246386b-f31d-451d-b8a6-2f4c0dfa27b4 (shared)
>Thread-870::DEBUG::2014-05-29 12:26:36,537::task::993::TaskManager.Task::(_decref) Task=`4105f239-60d9-4cb1-8851-1fca18ce68c7`::ref 1 aborting False
>Thread-870::INFO::2014-05-29 12:26:36,538::volume::853::Storage.Volume::(getInfo) Info request: sdUUID=a246386b-f31d-451d-b8a6-2f4c0dfa27b4 imgUUID=dad706d6-e1e9-4f31-87d4-610b3511a932 volUUID = 7e0ec106-f2dc-4567-b050-e3289bf2d47f 
>Thread-870::DEBUG::2014-05-29 12:26:36,538::blockVolume::596::Storage.Misc.excCmd::(getMetadata) '/usr/bin/dd iflag=direct skip=10 bs=512 if=/dev/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/metadata count=1' (cwd None)
>Thread-870::DEBUG::2014-05-29 12:26:36,543::blockVolume::596::Storage.Misc.excCmd::(getMetadata) SUCCESS: <err> = '1+0 records in\n1+0 records out\n512 bytes (512 B) copied, 0.00101121 s, 506 kB/s\n'; <rc> = 0
>Thread-870::DEBUG::2014-05-29 12:26:36,543::misc::287::Storage.Misc::(validateDDBytes) err: ['1+0 records in', '1+0 records out', '512 bytes (512 B) copied, 0.00101121 s, 506 kB/s'], size: 512
>Thread-870::INFO::2014-05-29 12:26:36,544::volume::881::Storage.Volume::(getInfo) a246386b-f31d-451d-b8a6-2f4c0dfa27b4/dad706d6-e1e9-4f31-87d4-610b3511a932/7e0ec106-f2dc-4567-b050-e3289bf2d47f info is {'status': 'OK', 'domain': 'a246386b-f31d-451d-b8a6-2f4c0dfa27b4', 'voltype': 'LEAF', 'description': '', 'parent': '378fdb5e-1853-4946-9a79-fd7bd00bb466', 'format': 'COW', 'image': 'dad706d6-e1e9-4f31-87d4-610b3511a932', 'ctime': '1401296437', 'disktype': '2', 'legality': 'LEGAL', 'mtime': '0', 'apparentsize': '134217728', 'children': [], 'pool': '', 'capacity': '2147483648', 'uuid': '7e0ec106-f2dc-4567-b050-e3289bf2d47f', 'truesize': '134217728', 'type': 'SPARSE'}
>Thread-870::INFO::2014-05-29 12:26:36,544::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeInfo, Return response: {'info': {'status': 'OK', 'domain': 'a246386b-f31d-451d-b8a6-2f4c0dfa27b4', 'voltype': 'LEAF', 'description': '', 'parent': '378fdb5e-1853-4946-9a79-fd7bd00bb466', 'format': 'COW', 'image': 'dad706d6-e1e9-4f31-87d4-610b3511a932', 'ctime': '1401296437', 'disktype': '2', 'legality': 'LEGAL', 'mtime': '0', 'apparentsize': '134217728', 'children': [], 'pool': '', 'capacity': '2147483648', 'uuid': '7e0ec106-f2dc-4567-b050-e3289bf2d47f', 'truesize': '134217728', 'type': 'SPARSE'}}
>Thread-870::DEBUG::2014-05-29 12:26:36,544::task::1188::TaskManager.Task::(prepare) Task=`4105f239-60d9-4cb1-8851-1fca18ce68c7`::finished: {'info': {'status': 'OK', 'domain': 'a246386b-f31d-451d-b8a6-2f4c0dfa27b4', 'voltype': 'LEAF', 'description': '', 'parent': '378fdb5e-1853-4946-9a79-fd7bd00bb466', 'format': 'COW', 'image': 'dad706d6-e1e9-4f31-87d4-610b3511a932', 'ctime': '1401296437', 'disktype': '2', 'legality': 'LEGAL', 'mtime': '0', 'apparentsize': '134217728', 'children': [], 'pool': '', 'capacity': '2147483648', 'uuid': '7e0ec106-f2dc-4567-b050-e3289bf2d47f', 'truesize': '134217728', 'type': 'SPARSE'}}
>Thread-870::DEBUG::2014-05-29 12:26:36,544::task::595::TaskManager.Task::(_updateState) Task=`4105f239-60d9-4cb1-8851-1fca18ce68c7`::moving from state preparing -> state finished
>Thread-870::DEBUG::2014-05-29 12:26:36,544::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.a246386b-f31d-451d-b8a6-2f4c0dfa27b4': < ResourceRef 'Storage.a246386b-f31d-451d-b8a6-2f4c0dfa27b4', isValid: 'True' obj: 'None'>}
>Thread-870::DEBUG::2014-05-29 12:26:36,544::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-870::DEBUG::2014-05-29 12:26:36,544::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.a246386b-f31d-451d-b8a6-2f4c0dfa27b4'
>Thread-870::DEBUG::2014-05-29 12:26:36,545::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.a246386b-f31d-451d-b8a6-2f4c0dfa27b4' (0 active users)
>Thread-870::DEBUG::2014-05-29 12:26:36,545::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.a246386b-f31d-451d-b8a6-2f4c0dfa27b4' is free, finding out if anyone is waiting for it.
>Thread-870::DEBUG::2014-05-29 12:26:36,545::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.a246386b-f31d-451d-b8a6-2f4c0dfa27b4', Clearing records.
>Thread-870::DEBUG::2014-05-29 12:26:36,545::task::993::TaskManager.Task::(_decref) Task=`4105f239-60d9-4cb1-8851-1fca18ce68c7`::ref 0 aborting False
>Thread-871::DEBUG::2014-05-29 12:26:36,557::BindingXMLRPC::249::vds::(wrapper) client [192.168.2.1]
>Thread-871::DEBUG::2014-05-29 12:26:36,557::task::595::TaskManager.Task::(_updateState) Task=`57ba3931-79b1-4269-a9cd-cd17cf1a996f`::moving from state init -> state preparing
>Thread-871::INFO::2014-05-29 12:26:36,557::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeInfo(sdUUID='a246386b-f31d-451d-b8a6-2f4c0dfa27b4', spUUID='be744655-2a19-4919-92f3-e7c20ac03193', imgUUID='dad706d6-e1e9-4f31-87d4-610b3511a932', volUUID='378fdb5e-1853-4946-9a79-fd7bd00bb466', options=None)
>Thread-871::DEBUG::2014-05-29 12:26:36,557::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.a246386b-f31d-451d-b8a6-2f4c0dfa27b4`ReqID=`cb44bede-5c34-46c7-902f-495e3f76440e`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '3084' at 'getVolumeInfo'
>Thread-871::DEBUG::2014-05-29 12:26:36,557::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.a246386b-f31d-451d-b8a6-2f4c0dfa27b4' for lock type 'shared'
>Thread-871::DEBUG::2014-05-29 12:26:36,558::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.a246386b-f31d-451d-b8a6-2f4c0dfa27b4' is free. Now locking as 'shared' (1 active user)
>Thread-871::DEBUG::2014-05-29 12:26:36,558::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.a246386b-f31d-451d-b8a6-2f4c0dfa27b4`ReqID=`cb44bede-5c34-46c7-902f-495e3f76440e`::Granted request
>Thread-871::DEBUG::2014-05-29 12:26:36,558::task::827::TaskManager.Task::(resourceAcquired) Task=`57ba3931-79b1-4269-a9cd-cd17cf1a996f`::_resourcesAcquired: Storage.a246386b-f31d-451d-b8a6-2f4c0dfa27b4 (shared)
>Thread-871::DEBUG::2014-05-29 12:26:36,558::task::993::TaskManager.Task::(_decref) Task=`57ba3931-79b1-4269-a9cd-cd17cf1a996f`::ref 1 aborting False
>Thread-871::INFO::2014-05-29 12:26:36,558::volume::853::Storage.Volume::(getInfo) Info request: sdUUID=a246386b-f31d-451d-b8a6-2f4c0dfa27b4 imgUUID=dad706d6-e1e9-4f31-87d4-610b3511a932 volUUID = 378fdb5e-1853-4946-9a79-fd7bd00bb466 
>Thread-871::DEBUG::2014-05-29 12:26:36,558::blockVolume::596::Storage.Misc.excCmd::(getMetadata) '/usr/bin/dd iflag=direct skip=5 bs=512 if=/dev/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/metadata count=1' (cwd None)
>Thread-871::DEBUG::2014-05-29 12:26:36,564::blockVolume::596::Storage.Misc.excCmd::(getMetadata) SUCCESS: <err> = '1+0 records in\n1+0 records out\n512 bytes (512 B) copied, 0.00114466 s, 447 kB/s\n'; <rc> = 0
>Thread-871::DEBUG::2014-05-29 12:26:36,564::misc::287::Storage.Misc::(validateDDBytes) err: ['1+0 records in', '1+0 records out', '512 bytes (512 B) copied, 0.00114466 s, 447 kB/s'], size: 512
>Thread-871::INFO::2014-05-29 12:26:36,564::volume::881::Storage.Volume::(getInfo) a246386b-f31d-451d-b8a6-2f4c0dfa27b4/dad706d6-e1e9-4f31-87d4-610b3511a932/378fdb5e-1853-4946-9a79-fd7bd00bb466 info is {'status': 'OK', 'domain': 'a246386b-f31d-451d-b8a6-2f4c0dfa27b4', 'voltype': 'SHARED', 'description': 'Active VM', 'parent': '00000000-0000-0000-0000-000000000000', 'format': 'COW', 'image': '455fb293-c3a5-413f-8068-2de666b4fb4b', 'ctime': '1401296310', 'disktype': '2', 'legality': 'LEGAL', 'mtime': '0', 'apparentsize': '134217728', 'children': [], 'pool': '', 'capacity': '2147483648', 'uuid': '378fdb5e-1853-4946-9a79-fd7bd00bb466', 'truesize': '134217728', 'type': 'SPARSE'}
>Thread-871::INFO::2014-05-29 12:26:36,564::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeInfo, Return response: {'info': {'status': 'OK', 'domain': 'a246386b-f31d-451d-b8a6-2f4c0dfa27b4', 'voltype': 'SHARED', 'description': 'Active VM', 'parent': '00000000-0000-0000-0000-000000000000', 'format': 'COW', 'image': '455fb293-c3a5-413f-8068-2de666b4fb4b', 'ctime': '1401296310', 'disktype': '2', 'legality': 'LEGAL', 'mtime': '0', 'apparentsize': '134217728', 'children': [], 'pool': '', 'capacity': '2147483648', 'uuid': '378fdb5e-1853-4946-9a79-fd7bd00bb466', 'truesize': '134217728', 'type': 'SPARSE'}}
>Thread-871::DEBUG::2014-05-29 12:26:36,564::task::1188::TaskManager.Task::(prepare) Task=`57ba3931-79b1-4269-a9cd-cd17cf1a996f`::finished: {'info': {'status': 'OK', 'domain': 'a246386b-f31d-451d-b8a6-2f4c0dfa27b4', 'voltype': 'SHARED', 'description': 'Active VM', 'parent': '00000000-0000-0000-0000-000000000000', 'format': 'COW', 'image': '455fb293-c3a5-413f-8068-2de666b4fb4b', 'ctime': '1401296310', 'disktype': '2', 'legality': 'LEGAL', 'mtime': '0', 'apparentsize': '134217728', 'children': [], 'pool': '', 'capacity': '2147483648', 'uuid': '378fdb5e-1853-4946-9a79-fd7bd00bb466', 'truesize': '134217728', 'type': 'SPARSE'}}
>Thread-871::DEBUG::2014-05-29 12:26:36,565::task::595::TaskManager.Task::(_updateState) Task=`57ba3931-79b1-4269-a9cd-cd17cf1a996f`::moving from state preparing -> state finished
>Thread-871::DEBUG::2014-05-29 12:26:36,565::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.a246386b-f31d-451d-b8a6-2f4c0dfa27b4': < ResourceRef 'Storage.a246386b-f31d-451d-b8a6-2f4c0dfa27b4', isValid: 'True' obj: 'None'>}
>Thread-871::DEBUG::2014-05-29 12:26:36,565::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-871::DEBUG::2014-05-29 12:26:36,565::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.a246386b-f31d-451d-b8a6-2f4c0dfa27b4'
>Thread-871::DEBUG::2014-05-29 12:26:36,565::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.a246386b-f31d-451d-b8a6-2f4c0dfa27b4' (0 active users)
>Thread-871::DEBUG::2014-05-29 12:26:36,565::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.a246386b-f31d-451d-b8a6-2f4c0dfa27b4' is free, finding out if anyone is waiting for it.
>Thread-871::DEBUG::2014-05-29 12:26:36,565::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.a246386b-f31d-451d-b8a6-2f4c0dfa27b4', Clearing records.
>Thread-871::DEBUG::2014-05-29 12:26:36,566::task::993::TaskManager.Task::(_decref) Task=`57ba3931-79b1-4269-a9cd-cd17cf1a996f`::ref 0 aborting False
>Thread-828::DEBUG::2014-05-29 12:26:38,637::BindingXMLRPC::1052::vds::(wrapper) client [192.168.2.1]::call vmGetStats with ('af8df38e-2e99-4a89-9483-a540027ea6b1',) {} flowID [7e6b10d5]
>Thread-828::DEBUG::2014-05-29 12:26:38,638::vm::284::vm.Vm::(_getCpuStats) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::CPU stats not available: 'NoneType' object has no attribute '__getitem__'
>Thread-828::DEBUG::2014-05-29 12:26:38,638::vm::393::vm.Vm::(_getDiskLatency) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::Disk hdc latency not available
>Thread-828::DEBUG::2014-05-29 12:26:38,638::vm::393::vm.Vm::(_getDiskLatency) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::Disk vda latency not available
>Thread-828::DEBUG::2014-05-29 12:26:38,638::vm::405::vm.Vm::(_getVmJobs) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::VmJob stats not available
>Thread-828::DEBUG::2014-05-29 12:26:38,639::BindingXMLRPC::1059::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Powering up', 'username': 'Unknown', 'memUsage': '0', 'acpiEnable': 'true', 'guestFQDN': '', 'pid': '20589', 'displayIp': '0', 'displayPort': '-1', 'session': 'Unknown', 'displaySecurePort': u'5900', 'timeOffset': '0', 'hash': '7153593655711157332', 'balloonInfo': {'balloon_max': '1048576', 'balloon_target': '1048576', 'balloon_cur': '1048576', 'balloon_min': '1048576'}, 'pauseCode': 'NOERR', 'clientIp': '', 'kvmEnable': 'true', 'network': {}, 'vmId': 'af8df38e-2e99-4a89-9483-a540027ea6b1', 'displayType': 'qxl', 'cpuUser': '0.00', 'disks': {u'vda': {'truesize': '134217728', 'apparentsize': '134217728', 'imageID': 'dad706d6-e1e9-4f31-87d4-610b3511a932'}, u'hdc': {'truesize': '0', 'apparentsize': '0'}}, 'monitorResponse': '0', 'statsAge': '1.95', 'elapsedTime': '9', 'vmType': 'kvm', 'cpuSys': '0.00', 'guestCPUCount': -1, 'appsList': [], 'guestIPs': ''}]}
>Thread-872::DEBUG::2014-05-29 12:26:38,851::BindingXMLRPC::1052::vds::(wrapper) client [192.168.2.1]::call vmSnapshot with ('af8df38e-2e99-4a89-9483-a540027ea6b1', [{'baseVolumeID': '7e0ec106-f2dc-4567-b050-e3289bf2d47f', 'domainID': 'a246386b-f31d-451d-b8a6-2f4c0dfa27b4', 'volumeID': '59354326-443a-42dc-b21d-8649056ced83', 'imageID': 'dad706d6-e1e9-4f31-87d4-610b3511a932'}]) {}
>Thread-872::DEBUG::2014-05-29 12:26:38,852::task::595::TaskManager.Task::(_updateState) Task=`b2891905-90c1-4713-b370-018d74f36b6e`::moving from state init -> state preparing
>Thread-872::INFO::2014-05-29 12:26:38,852::logUtils::44::dispatcher::(wrapper) Run and protect: prepareImage(sdUUID='a246386b-f31d-451d-b8a6-2f4c0dfa27b4', spUUID='be744655-2a19-4919-92f3-e7c20ac03193', imgUUID='dad706d6-e1e9-4f31-87d4-610b3511a932', leafUUID='59354326-443a-42dc-b21d-8649056ced83')
>Thread-872::DEBUG::2014-05-29 12:26:38,852::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.a246386b-f31d-451d-b8a6-2f4c0dfa27b4`ReqID=`288e73a9-9741-4a5c-a98a-df565a5518fb`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '3243' at 'prepareImage'
>Thread-872::DEBUG::2014-05-29 12:26:38,852::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.a246386b-f31d-451d-b8a6-2f4c0dfa27b4' for lock type 'shared'
>Thread-872::DEBUG::2014-05-29 12:26:38,852::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.a246386b-f31d-451d-b8a6-2f4c0dfa27b4' is free. Now locking as 'shared' (1 active user)
>Thread-872::DEBUG::2014-05-29 12:26:38,852::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.a246386b-f31d-451d-b8a6-2f4c0dfa27b4`ReqID=`288e73a9-9741-4a5c-a98a-df565a5518fb`::Granted request
>Thread-872::DEBUG::2014-05-29 12:26:38,853::task::827::TaskManager.Task::(resourceAcquired) Task=`b2891905-90c1-4713-b370-018d74f36b6e`::_resourcesAcquired: Storage.a246386b-f31d-451d-b8a6-2f4c0dfa27b4 (shared)
>Thread-872::DEBUG::2014-05-29 12:26:38,853::task::993::TaskManager.Task::(_decref) Task=`b2891905-90c1-4713-b370-018d74f36b6e`::ref 1 aborting False
>Thread-872::DEBUG::2014-05-29 12:26:38,853::lvm::419::OperationMutex::(_reloadlvs) Operation 'lvm reload operation' got the operation mutex
>Thread-872::DEBUG::2014-05-29 12:26:38,853::lvm::288::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /usr/sbin/lvm lvs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ \'a|/dev/mapper/3600140596b9bb9189094a98a6891f0a4|\', \'r|.*|\' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1  use_lvmetad=0 }  backup {  retain_min = 50  retain_days = 0 } " --noheadings --units b --nosuffix --separator | --ignoreskippedcluster -o uuid,name,vg_name,attr,size,seg_start_pe,devices,tags a246386b-f31d-451d-b8a6-2f4c0dfa27b4' (cwd None)
>Thread-872::DEBUG::2014-05-29 12:26:38,896::lvm::288::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-872::DEBUG::2014-05-29 12:26:38,896::lvm::454::Storage.LVM::(_reloadlvs) lvs reloaded
>Thread-872::DEBUG::2014-05-29 12:26:38,897::lvm::454::OperationMutex::(_reloadlvs) Operation 'lvm reload operation' released the operation mutex
>Thread-872::DEBUG::2014-05-29 12:26:38,897::lvm::288::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /usr/sbin/lvm lvchange --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ \'a|/dev/mapper/3600140596b9bb9189094a98a6891f0a4|\', \'r|.*|\' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1  use_lvmetad=0 }  backup {  retain_min = 50  retain_days = 0 } " --autobackup n --available y a246386b-f31d-451d-b8a6-2f4c0dfa27b4/59354326-443a-42dc-b21d-8649056ced83' (cwd None)
>Thread-872::DEBUG::2014-05-29 12:26:39,056::lvm::288::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-872::DEBUG::2014-05-29 12:26:39,057::lvm::505::OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-872::DEBUG::2014-05-29 12:26:39,057::lvm::517::OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-872::DEBUG::2014-05-29 12:26:39,057::fileUtils::142::Storage.fileUtils::(createdir) Creating directory: /var/run/vdsm/storage/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/dad706d6-e1e9-4f31-87d4-610b3511a932
>Thread-872::WARNING::2014-05-29 12:26:39,057::fileUtils::149::Storage.fileUtils::(createdir) Dir /var/run/vdsm/storage/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/dad706d6-e1e9-4f31-87d4-610b3511a932 already exists
>Thread-872::DEBUG::2014-05-29 12:26:39,057::blockSD::1078::Storage.StorageDomain::(createImageLinks) Creating symlink from /dev/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/7e0ec106-f2dc-4567-b050-e3289bf2d47f to /var/run/vdsm/storage/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/dad706d6-e1e9-4f31-87d4-610b3511a932/7e0ec106-f2dc-4567-b050-e3289bf2d47f
>Thread-872::DEBUG::2014-05-29 12:26:39,057::blockSD::1083::Storage.StorageDomain::(createImageLinks) img run vol already exists: /var/run/vdsm/storage/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/dad706d6-e1e9-4f31-87d4-610b3511a932/7e0ec106-f2dc-4567-b050-e3289bf2d47f
>Thread-872::DEBUG::2014-05-29 12:26:39,057::blockSD::1078::Storage.StorageDomain::(createImageLinks) Creating symlink from /dev/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/59354326-443a-42dc-b21d-8649056ced83 to /var/run/vdsm/storage/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/dad706d6-e1e9-4f31-87d4-610b3511a932/59354326-443a-42dc-b21d-8649056ced83
>Thread-872::DEBUG::2014-05-29 12:26:39,057::blockSD::1078::Storage.StorageDomain::(createImageLinks) Creating symlink from /dev/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/378fdb5e-1853-4946-9a79-fd7bd00bb466 to /var/run/vdsm/storage/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/dad706d6-e1e9-4f31-87d4-610b3511a932/378fdb5e-1853-4946-9a79-fd7bd00bb466
>Thread-872::DEBUG::2014-05-29 12:26:39,057::blockSD::1083::Storage.StorageDomain::(createImageLinks) img run vol already exists: /var/run/vdsm/storage/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/dad706d6-e1e9-4f31-87d4-610b3511a932/378fdb5e-1853-4946-9a79-fd7bd00bb466
>Thread-872::DEBUG::2014-05-29 12:26:39,058::blockSD::1048::Storage.StorageDomain::(linkBCImage) Creating symlink from /var/run/vdsm/storage/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/dad706d6-e1e9-4f31-87d4-610b3511a932 to /rhev/data-center/mnt/blockSD/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/images/dad706d6-e1e9-4f31-87d4-610b3511a932
>Thread-872::DEBUG::2014-05-29 12:26:39,058::blockSD::1054::Storage.StorageDomain::(linkBCImage) path to image directory already exists: /rhev/data-center/mnt/blockSD/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/images/dad706d6-e1e9-4f31-87d4-610b3511a932
>Thread-872::DEBUG::2014-05-29 12:26:39,058::lvm::419::OperationMutex::(_reloadlvs) Operation 'lvm reload operation' got the operation mutex
>Thread-872::DEBUG::2014-05-29 12:26:39,058::lvm::288::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /usr/sbin/lvm lvs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ \'a|/dev/mapper/3600140596b9bb9189094a98a6891f0a4|\', \'r|.*|\' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1  use_lvmetad=0 }  backup {  retain_min = 50  retain_days = 0 } " --noheadings --units b --nosuffix --separator | --ignoreskippedcluster -o uuid,name,vg_name,attr,size,seg_start_pe,devices,tags a246386b-f31d-451d-b8a6-2f4c0dfa27b4' (cwd None)
>Thread-872::DEBUG::2014-05-29 12:26:39,101::lvm::288::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-872::DEBUG::2014-05-29 12:26:39,102::lvm::454::Storage.LVM::(_reloadlvs) lvs reloaded
>Thread-872::DEBUG::2014-05-29 12:26:39,102::lvm::454::OperationMutex::(_reloadlvs) Operation 'lvm reload operation' released the operation mutex
>Thread-872::INFO::2014-05-29 12:26:39,103::logUtils::47::dispatcher::(wrapper) Run and protect: prepareImage, Return response: {'info': {'domainID': 'a246386b-f31d-451d-b8a6-2f4c0dfa27b4', 'volType': 'path', 'leaseOffset': 130023424, 'path': '/rhev/data-center/mnt/blockSD/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/images/dad706d6-e1e9-4f31-87d4-610b3511a932/59354326-443a-42dc-b21d-8649056ced83', 'volumeID': '59354326-443a-42dc-b21d-8649056ced83', 'leasePath': '/dev/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/leases', 'imageID': 'dad706d6-e1e9-4f31-87d4-610b3511a932'}, 'path': '/rhev/data-center/mnt/blockSD/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/images/dad706d6-e1e9-4f31-87d4-610b3511a932/59354326-443a-42dc-b21d-8649056ced83', 'imgVolumesInfo': [{'domainID': 'a246386b-f31d-451d-b8a6-2f4c0dfa27b4', 'volType': 'path', 'leaseOffset': 115343360, 'path': '/rhev/data-center/mnt/blockSD/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/images/dad706d6-e1e9-4f31-87d4-610b3511a932/7e0ec106-f2dc-4567-b050-e3289bf2d47f', 'volumeID': '7e0ec106-f2dc-4567-b050-e3289bf2d47f', 'leasePath': '/dev/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/leases', 'imageID': 'dad706d6-e1e9-4f31-87d4-610b3511a932'}, {'domainID': 'a246386b-f31d-451d-b8a6-2f4c0dfa27b4', 'volType': 'path', 'leaseOffset': 130023424, 'path': '/rhev/data-center/mnt/blockSD/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/images/dad706d6-e1e9-4f31-87d4-610b3511a932/59354326-443a-42dc-b21d-8649056ced83', 'volumeID': '59354326-443a-42dc-b21d-8649056ced83', 'leasePath': '/dev/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/leases', 'imageID': 'dad706d6-e1e9-4f31-87d4-610b3511a932'}, {'domainID': 'a246386b-f31d-451d-b8a6-2f4c0dfa27b4', 'volType': 'path', 'leaseOffset': 110100480, 'path': '/rhev/data-center/mnt/blockSD/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/images/dad706d6-e1e9-4f31-87d4-610b3511a932/378fdb5e-1853-4946-9a79-fd7bd00bb466', 'volumeID': '378fdb5e-1853-4946-9a79-fd7bd00bb466', 'leasePath': '/dev/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/leases', 'imageID': 'dad706d6-e1e9-4f31-87d4-610b3511a932'}]}
>Thread-872::DEBUG::2014-05-29 12:26:39,103::task::1188::TaskManager.Task::(prepare) Task=`b2891905-90c1-4713-b370-018d74f36b6e`::finished: {'info': {'domainID': 'a246386b-f31d-451d-b8a6-2f4c0dfa27b4', 'volType': 'path', 'leaseOffset': 130023424, 'path': '/rhev/data-center/mnt/blockSD/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/images/dad706d6-e1e9-4f31-87d4-610b3511a932/59354326-443a-42dc-b21d-8649056ced83', 'volumeID': '59354326-443a-42dc-b21d-8649056ced83', 'leasePath': '/dev/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/leases', 'imageID': 'dad706d6-e1e9-4f31-87d4-610b3511a932'}, 'path': '/rhev/data-center/mnt/blockSD/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/images/dad706d6-e1e9-4f31-87d4-610b3511a932/59354326-443a-42dc-b21d-8649056ced83', 'imgVolumesInfo': [{'domainID': 'a246386b-f31d-451d-b8a6-2f4c0dfa27b4', 'volType': 'path', 'leaseOffset': 115343360, 'path': '/rhev/data-center/mnt/blockSD/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/images/dad706d6-e1e9-4f31-87d4-610b3511a932/7e0ec106-f2dc-4567-b050-e3289bf2d47f', 'volumeID': '7e0ec106-f2dc-4567-b050-e3289bf2d47f', 'leasePath': '/dev/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/leases', 'imageID': 'dad706d6-e1e9-4f31-87d4-610b3511a932'}, {'domainID': 'a246386b-f31d-451d-b8a6-2f4c0dfa27b4', 'volType': 'path', 'leaseOffset': 130023424, 'path': '/rhev/data-center/mnt/blockSD/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/images/dad706d6-e1e9-4f31-87d4-610b3511a932/59354326-443a-42dc-b21d-8649056ced83', 'volumeID': '59354326-443a-42dc-b21d-8649056ced83', 'leasePath': '/dev/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/leases', 'imageID': 'dad706d6-e1e9-4f31-87d4-610b3511a932'}, {'domainID': 'a246386b-f31d-451d-b8a6-2f4c0dfa27b4', 'volType': 'path', 'leaseOffset': 110100480, 'path': '/rhev/data-center/mnt/blockSD/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/images/dad706d6-e1e9-4f31-87d4-610b3511a932/378fdb5e-1853-4946-9a79-fd7bd00bb466', 'volumeID': '378fdb5e-1853-4946-9a79-fd7bd00bb466', 'leasePath': '/dev/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/leases', 'imageID': 'dad706d6-e1e9-4f31-87d4-610b3511a932'}]}
>Thread-872::DEBUG::2014-05-29 12:26:39,103::task::595::TaskManager.Task::(_updateState) Task=`b2891905-90c1-4713-b370-018d74f36b6e`::moving from state preparing -> state finished
>Thread-872::DEBUG::2014-05-29 12:26:39,103::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.a246386b-f31d-451d-b8a6-2f4c0dfa27b4': < ResourceRef 'Storage.a246386b-f31d-451d-b8a6-2f4c0dfa27b4', isValid: 'True' obj: 'None'>}
>Thread-872::DEBUG::2014-05-29 12:26:39,103::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-872::DEBUG::2014-05-29 12:26:39,104::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.a246386b-f31d-451d-b8a6-2f4c0dfa27b4'
>Thread-872::DEBUG::2014-05-29 12:26:39,104::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.a246386b-f31d-451d-b8a6-2f4c0dfa27b4' (0 active users)
>Thread-872::DEBUG::2014-05-29 12:26:39,104::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.a246386b-f31d-451d-b8a6-2f4c0dfa27b4' is free, finding out if anyone is waiting for it.
>Thread-872::DEBUG::2014-05-29 12:26:39,104::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.a246386b-f31d-451d-b8a6-2f4c0dfa27b4', Clearing records.
>Thread-872::DEBUG::2014-05-29 12:26:39,104::task::993::TaskManager.Task::(_decref) Task=`b2891905-90c1-4713-b370-018d74f36b6e`::ref 0 aborting False
>Thread-872::INFO::2014-05-29 12:26:39,104::clientIF::313::vds::(prepareVolumePath) prepared volume path: /rhev/data-center/mnt/blockSD/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/images/dad706d6-e1e9-4f31-87d4-610b3511a932/59354326-443a-42dc-b21d-8649056ced83
>Thread-872::DEBUG::2014-05-29 12:26:39,104::vm::3872::vm.Vm::(snapshot) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::<domainsnapshot>
>	<disks>
>		<disk name="vda" snapshot="external">
>			<source file="/rhev/data-center/mnt/blockSD/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/images/dad706d6-e1e9-4f31-87d4-610b3511a932/59354326-443a-42dc-b21d-8649056ced83" type="block"/>
>		</disk>
>	</disks>
></domainsnapshot>
>
>GuestMonitor-brewer-5::DEBUG::2014-05-29 12:26:39,140::vm::284::vm.Vm::(_getCpuStats) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::CPU stats not available: 'NoneType' object has no attribute '__getitem__'
>GuestMonitor-brewer-5::DEBUG::2014-05-29 12:26:39,140::vm::393::vm.Vm::(_getDiskLatency) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::Disk hdc latency not available
>GuestMonitor-brewer-5::DEBUG::2014-05-29 12:26:39,141::vm::393::vm.Vm::(_getDiskLatency) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::Disk vda latency not available
>GuestMonitor-brewer-5::DEBUG::2014-05-29 12:26:39,141::vm::405::vm.Vm::(_getVmJobs) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::VmJob stats not available
>GuestMonitor-brewer-5::DEBUG::2014-05-29 12:26:39,142::vm::284::vm.Vm::(_getCpuStats) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::CPU stats not available: 'NoneType' object has no attribute '__getitem__'
>GuestMonitor-brewer-5::DEBUG::2014-05-29 12:26:39,142::vm::393::vm.Vm::(_getDiskLatency) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::Disk hdc latency not available
>GuestMonitor-brewer-5::DEBUG::2014-05-29 12:26:39,142::vm::393::vm.Vm::(_getDiskLatency) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::Disk vda latency not available
>GuestMonitor-brewer-5::DEBUG::2014-05-29 12:26:39,142::vm::405::vm.Vm::(_getVmJobs) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::VmJob stats not available
>Thread-450::DEBUG::2014-05-29 12:26:40,415::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd if=/rhev/data-center/mnt/192.168.2.1:_home_storage_iso/e453999e-ec9f-420b-941c-a9f9cc4432bb/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1' (cwd None)
>Thread-450::DEBUG::2014-05-29 12:26:40,421::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n531 bytes (531 B) copied, 0.000995082 s, 534 kB/s\n'; <rc> = 0
>Thread-828::DEBUG::2014-05-29 12:26:41,670::task::595::TaskManager.Task::(_updateState) Task=`ff963eff-79f3-44c2-bbc9-a46941a4cb61`::moving from state init -> state preparing
>Thread-828::INFO::2014-05-29 12:26:41,670::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-828::INFO::2014-05-29 12:26:41,671::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'e453999e-ec9f-420b-941c-a9f9cc4432bb': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000995082', 'lastCheck': '1.2', 'valid': True}, u'a246386b-f31d-451d-b8a6-2f4c0dfa27b4': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.00164132', 'lastCheck': '9.8', 'valid': True}}
>Thread-828::DEBUG::2014-05-29 12:26:41,671::task::1188::TaskManager.Task::(prepare) Task=`ff963eff-79f3-44c2-bbc9-a46941a4cb61`::finished: {u'e453999e-ec9f-420b-941c-a9f9cc4432bb': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000995082', 'lastCheck': '1.2', 'valid': True}, u'a246386b-f31d-451d-b8a6-2f4c0dfa27b4': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.00164132', 'lastCheck': '9.8', 'valid': True}}
>Thread-828::DEBUG::2014-05-29 12:26:41,671::task::595::TaskManager.Task::(_updateState) Task=`ff963eff-79f3-44c2-bbc9-a46941a4cb61`::moving from state preparing -> state finished
>Thread-828::DEBUG::2014-05-29 12:26:41,671::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-828::DEBUG::2014-05-29 12:26:41,671::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-828::DEBUG::2014-05-29 12:26:41,671::task::993::TaskManager.Task::(_decref) Task=`ff963eff-79f3-44c2-bbc9-a46941a4cb61`::ref 0 aborting False
>Thread-828::DEBUG::2014-05-29 12:26:41,682::vm::284::vm.Vm::(_getCpuStats) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::CPU stats not available: 'NoneType' object has no attribute '__getitem__'
>Thread-828::DEBUG::2014-05-29 12:26:41,682::vm::393::vm.Vm::(_getDiskLatency) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::Disk hdc latency not available
>Thread-828::DEBUG::2014-05-29 12:26:41,682::vm::393::vm.Vm::(_getDiskLatency) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::Disk vda latency not available
>Thread-828::DEBUG::2014-05-29 12:26:41,682::vm::405::vm.Vm::(_getVmJobs) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::VmJob stats not available
>Thread-451::DEBUG::2014-05-29 12:26:41,886::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd if=/dev/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/metadata iflag=direct of=/dev/null bs=4096 count=1' (cwd None)
>Thread-451::DEBUG::2014-05-29 12:26:41,892::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.00152798 s, 2.7 MB/s\n'; <rc> = 0
>GuestMonitor-brewer-5::DEBUG::2014-05-29 12:26:44,148::vm::284::vm.Vm::(_getCpuStats) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::CPU stats not available: 'NoneType' object has no attribute '__getitem__'
>GuestMonitor-brewer-5::DEBUG::2014-05-29 12:26:44,148::vm::393::vm.Vm::(_getDiskLatency) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::Disk hdc latency not available
>GuestMonitor-brewer-5::DEBUG::2014-05-29 12:26:44,148::vm::393::vm.Vm::(_getDiskLatency) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::Disk vda latency not available
>GuestMonitor-brewer-5::DEBUG::2014-05-29 12:26:44,148::vm::405::vm.Vm::(_getVmJobs) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::VmJob stats not available
>GuestMonitor-brewer-5::DEBUG::2014-05-29 12:26:44,149::vm::284::vm.Vm::(_getCpuStats) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::CPU stats not available: 'NoneType' object has no attribute '__getitem__'
>GuestMonitor-brewer-5::DEBUG::2014-05-29 12:26:44,149::vm::393::vm.Vm::(_getDiskLatency) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::Disk hdc latency not available
>GuestMonitor-brewer-5::DEBUG::2014-05-29 12:26:44,149::vm::393::vm.Vm::(_getDiskLatency) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::Disk vda latency not available
>GuestMonitor-brewer-5::DEBUG::2014-05-29 12:26:44,150::vm::405::vm.Vm::(_getVmJobs) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::VmJob stats not available
>Thread-828::DEBUG::2014-05-29 12:26:44,776::BindingXMLRPC::1052::vds::(wrapper) client [192.168.2.1]::call vmGetStats with ('af8df38e-2e99-4a89-9483-a540027ea6b1',) {} flowID [c797464]
>Thread-828::DEBUG::2014-05-29 12:26:44,776::vm::284::vm.Vm::(_getCpuStats) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::CPU stats not available: 'NoneType' object has no attribute '__getitem__'
>Thread-828::DEBUG::2014-05-29 12:26:44,776::vm::393::vm.Vm::(_getDiskLatency) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::Disk hdc latency not available
>Thread-828::DEBUG::2014-05-29 12:26:44,777::vm::393::vm.Vm::(_getDiskLatency) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::Disk vda latency not available
>Thread-828::DEBUG::2014-05-29 12:26:44,777::vm::405::vm.Vm::(_getVmJobs) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::VmJob stats not available
>Thread-828::DEBUG::2014-05-29 12:26:44,777::BindingXMLRPC::1059::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Powering up', 'username': 'Unknown', 'memUsage': '0', 'acpiEnable': 'true', 'guestFQDN': '', 'pid': '20589', 'displayIp': '0', 'displayPort': '-1', 'session': 'Unknown', 'displaySecurePort': u'5900', 'timeOffset': '0', 'hash': '7153593655711157332', 'balloonInfo': {'balloon_max': '1048576', 'balloon_target': '1048576', 'balloon_cur': '1048576', 'balloon_min': '1048576'}, 'pauseCode': 'NOERR', 'clientIp': '', 'kvmEnable': 'true', 'network': {}, 'vmId': 'af8df38e-2e99-4a89-9483-a540027ea6b1', 'displayType': 'qxl', 'cpuUser': '0.00', 'disks': {u'vda': {'truesize': '134217728', 'apparentsize': '134217728', 'imageID': 'dad706d6-e1e9-4f31-87d4-610b3511a932'}, u'hdc': {'truesize': '0', 'apparentsize': '0'}}, 'monitorResponse': '0', 'statsAge': '0.09', 'elapsedTime': '15', 'vmType': 'kvm', 'cpuSys': '0.00', 'guestCPUCount': -1, 'appsList': [], 'guestIPs': ''}]}
>Thread-828::DEBUG::2014-05-29 12:26:47,817::BindingXMLRPC::1052::vds::(wrapper) client [192.168.2.1]::call vmGetStats with ('af8df38e-2e99-4a89-9483-a540027ea6b1',) {} flowID [551d2040]
>Thread-828::DEBUG::2014-05-29 12:26:47,817::vm::393::vm.Vm::(_getDiskLatency) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::Disk hdc latency not available
>Thread-828::DEBUG::2014-05-29 12:26:47,817::vm::393::vm.Vm::(_getDiskLatency) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::Disk vda latency not available
>Thread-828::DEBUG::2014-05-29 12:26:47,818::BindingXMLRPC::1059::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Powering up', 'username': 'Unknown', 'memUsage': '0', 'acpiEnable': 'true', 'guestFQDN': '', 'pid': '20589', 'displayIp': '0', 'displayPort': '-1', 'session': 'Unknown', 'displaySecurePort': u'5900', 'timeOffset': '0', 'hash': '7153593655711157332', '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:3f:44:a3', 'rxDropped': '0', 'rxErrors': '0', 'txDropped': '0', 'txRate': '0.0', 'rxRate': '0.0', 'txErrors': '0', 'state': 'unknown', 'speed': '1000', 'name': u'vnet0'}}, 'vmId': 'af8df38e-2e99-4a89-9483-a540027ea6b1', 'vmJobs': {}, 'cpuUser': '14.43', 'disks': {u'vda': {'truesize': '134217728', 'apparentsize': '134217728', 'imageID': 'dad706d6-e1e9-4f31-87d4-610b3511a932'}, u'hdc': {'truesize': '0', 'apparentsize': '0'}}, 'monitorResponse': '0', 'statsAge': '1.12', 'elapsedTime': '18', 'vmType': 'kvm', 'cpuSys': '6.78', 'guestCPUCount': -1, 'appsList': [], 'guestIPs': '', 'displayType': 'qxl'}]}
>Thread-872::DEBUG::2014-05-29 12:26:49,000::libvirtconnection::125::root::(wrapper) Unknown libvirterror: ecode: 86 edom: 10 level: 2 message: Guest agent is not responding: Guest agent not available for now
>Thread-872::DEBUG::2014-05-29 12:26:49,000::vm::3893::vm.Vm::(snapshot) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::Snapshot failed using the quiesce flag, trying again without it (Guest agent is not responding: Guest agent not available for now)
>GuestMonitor-brewer-5::DEBUG::2014-05-29 12:26:49,156::vm::393::vm.Vm::(_getDiskLatency) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::Disk hdc latency not available
>GuestMonitor-brewer-5::DEBUG::2014-05-29 12:26:49,156::vm::393::vm.Vm::(_getDiskLatency) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::Disk vda latency not available
>GuestMonitor-brewer-5::DEBUG::2014-05-29 12:26:49,157::vm::393::vm.Vm::(_getDiskLatency) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::Disk hdc latency not available
>GuestMonitor-brewer-5::DEBUG::2014-05-29 12:26:49,157::vm::393::vm.Vm::(_getDiskLatency) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::Disk vda latency not available
>Thread-872::DEBUG::2014-05-29 12:26:49,278::task::595::TaskManager.Task::(_updateState) Task=`a4f3d231-f001-48a8-844a-e86151ef6499`::moving from state init -> state preparing
>Thread-872::INFO::2014-05-29 12:26:49,278::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='a246386b-f31d-451d-b8a6-2f4c0dfa27b4', spUUID='be744655-2a19-4919-92f3-e7c20ac03193', imgUUID='dad706d6-e1e9-4f31-87d4-610b3511a932', volUUID='59354326-443a-42dc-b21d-8649056ced83', options=None)
>Thread-872::INFO::2014-05-29 12:26:49,278::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '134217728', 'apparentsize': '134217728'}
>Thread-872::DEBUG::2014-05-29 12:26:49,278::task::1188::TaskManager.Task::(prepare) Task=`a4f3d231-f001-48a8-844a-e86151ef6499`::finished: {'truesize': '134217728', 'apparentsize': '134217728'}
>Thread-872::DEBUG::2014-05-29 12:26:49,278::task::595::TaskManager.Task::(_updateState) Task=`a4f3d231-f001-48a8-844a-e86151ef6499`::moving from state preparing -> state finished
>Thread-872::DEBUG::2014-05-29 12:26:49,279::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-872::DEBUG::2014-05-29 12:26:49,279::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-872::DEBUG::2014-05-29 12:26:49,279::task::993::TaskManager.Task::(_decref) Task=`a4f3d231-f001-48a8-844a-e86151ef6499`::ref 0 aborting False
>Thread-872::DEBUG::2014-05-29 12:26:49,288::BindingXMLRPC::1059::vds::(wrapper) return vmSnapshot with {'status': {'message': 'Done', 'code': 0}, 'quiesce': False}
>Thread-450::DEBUG::2014-05-29 12:26:50,427::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd if=/rhev/data-center/mnt/192.168.2.1:_home_storage_iso/e453999e-ec9f-420b-941c-a9f9cc4432bb/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1' (cwd None)
>Thread-450::DEBUG::2014-05-29 12:26:50,434::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n531 bytes (531 B) copied, 0.000858633 s, 618 kB/s\n'; <rc> = 0
>Thread-828::DEBUG::2014-05-29 12:26:50,878::BindingXMLRPC::1052::vds::(wrapper) client [192.168.2.1]::call vmGetStats with ('af8df38e-2e99-4a89-9483-a540027ea6b1',) {} flowID [71cf499f]
>Thread-828::DEBUG::2014-05-29 12:26:50,878::vm::393::vm.Vm::(_getDiskLatency) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::Disk hdc latency not available
>Thread-828::DEBUG::2014-05-29 12:26:50,878::vm::393::vm.Vm::(_getDiskLatency) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::Disk vda latency not available
>Thread-828::DEBUG::2014-05-29 12:26:50,879::BindingXMLRPC::1059::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Powering up', 'username': 'Unknown', 'memUsage': '0', 'acpiEnable': 'true', 'guestFQDN': '', 'pid': '20589', 'displayIp': '0', 'displayPort': '-1', 'session': 'Unknown', 'displaySecurePort': u'5900', 'timeOffset': '0', 'hash': '1834567123264894057', '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:3f:44:a3', 'rxDropped': '0', 'rxErrors': '0', 'txDropped': '0', 'txRate': '0.0', 'rxRate': '0.0', 'txErrors': '0', 'state': 'unknown', 'speed': '1000', 'name': u'vnet0'}}, 'vmId': 'af8df38e-2e99-4a89-9483-a540027ea6b1', 'vmJobs': {}, 'cpuUser': '14.43', 'disks': {u'vda': {'truesize': '134217728', 'apparentsize': '134217728', 'imageID': 'dad706d6-e1e9-4f31-87d4-610b3511a932'}, u'hdc': {'truesize': '0', 'apparentsize': '0'}}, 'monitorResponse': '0', 'statsAge': '0.19', 'elapsedTime': '21', 'vmType': 'kvm', 'cpuSys': '6.78', 'guestCPUCount': -1, 'appsList': [], 'guestIPs': '', 'displayType': 'qxl'}]}
>libvirtEventLoop::INFO::2014-05-29 12:26:50,997::vm::4304::vm.Vm::(_onIOError) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::abnormal vm stop device virtio-disk0 error 
>libvirtEventLoop::DEBUG::2014-05-29 12:26:50,998::vm::4942::vm.Vm::(_onLibvirtLifecycleEvent) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::event Suspended detail 2 opaque None
>libvirtEventLoop::INFO::2014-05-29 12:26:51,154::vm::4304::vm.Vm::(_onIOError) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::abnormal vm stop device virtio-disk0 error 
>libvirtEventLoop::INFO::2014-05-29 12:26:51,160::vm::4304::vm.Vm::(_onIOError) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::abnormal vm stop device virtio-disk0 error 
>libvirtEventLoop::INFO::2014-05-29 12:26:51,164::vm::4304::vm.Vm::(_onIOError) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::abnormal vm stop device virtio-disk0 error 
>libvirtEventLoop::INFO::2014-05-29 12:26:51,169::vm::4304::vm.Vm::(_onIOError) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::abnormal vm stop device virtio-disk0 error 
>Thread-451::DEBUG::2014-05-29 12:26:51,896::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd if=/dev/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/metadata iflag=direct of=/dev/null bs=4096 count=1' (cwd None)
>Thread-451::DEBUG::2014-05-29 12:26:51,902::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.00165453 s, 2.5 MB/s\n'; <rc> = 0
>Thread-875::DEBUG::2014-05-29 12:26:52,649::BindingXMLRPC::1052::vds::(wrapper) client [192.168.2.1]::call vmSnapshot with ('af8df38e-2e99-4a89-9483-a540027ea6b1', [{'baseVolumeID': '59354326-443a-42dc-b21d-8649056ced83', 'domainID': 'a246386b-f31d-451d-b8a6-2f4c0dfa27b4', 'volumeID': 'ea12203c-36a5-43d7-b351-492ec8c7944d', 'imageID': 'dad706d6-e1e9-4f31-87d4-610b3511a932'}]) {}
>Thread-875::DEBUG::2014-05-29 12:26:52,650::task::595::TaskManager.Task::(_updateState) Task=`57ba14a7-6905-421e-b95c-b6700932b53a`::moving from state init -> state preparing
>Thread-875::INFO::2014-05-29 12:26:52,650::logUtils::44::dispatcher::(wrapper) Run and protect: prepareImage(sdUUID='a246386b-f31d-451d-b8a6-2f4c0dfa27b4', spUUID='be744655-2a19-4919-92f3-e7c20ac03193', imgUUID='dad706d6-e1e9-4f31-87d4-610b3511a932', leafUUID='ea12203c-36a5-43d7-b351-492ec8c7944d')
>Thread-875::DEBUG::2014-05-29 12:26:52,650::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.a246386b-f31d-451d-b8a6-2f4c0dfa27b4`ReqID=`febc6189-ca11-459d-9db1-abd90c5e625c`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '3243' at 'prepareImage'
>Thread-875::DEBUG::2014-05-29 12:26:52,650::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.a246386b-f31d-451d-b8a6-2f4c0dfa27b4' for lock type 'shared'
>Thread-875::DEBUG::2014-05-29 12:26:52,650::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.a246386b-f31d-451d-b8a6-2f4c0dfa27b4' is free. Now locking as 'shared' (1 active user)
>Thread-875::DEBUG::2014-05-29 12:26:52,650::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.a246386b-f31d-451d-b8a6-2f4c0dfa27b4`ReqID=`febc6189-ca11-459d-9db1-abd90c5e625c`::Granted request
>Thread-875::DEBUG::2014-05-29 12:26:52,651::task::827::TaskManager.Task::(resourceAcquired) Task=`57ba14a7-6905-421e-b95c-b6700932b53a`::_resourcesAcquired: Storage.a246386b-f31d-451d-b8a6-2f4c0dfa27b4 (shared)
>Thread-875::DEBUG::2014-05-29 12:26:52,651::task::993::TaskManager.Task::(_decref) Task=`57ba14a7-6905-421e-b95c-b6700932b53a`::ref 1 aborting False
>Thread-875::DEBUG::2014-05-29 12:26:52,651::lvm::419::OperationMutex::(_reloadlvs) Operation 'lvm reload operation' got the operation mutex
>Thread-875::DEBUG::2014-05-29 12:26:52,651::lvm::288::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /usr/sbin/lvm lvs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ \'a|/dev/mapper/3600140596b9bb9189094a98a6891f0a4|\', \'r|.*|\' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1  use_lvmetad=0 }  backup {  retain_min = 50  retain_days = 0 } " --noheadings --units b --nosuffix --separator | --ignoreskippedcluster -o uuid,name,vg_name,attr,size,seg_start_pe,devices,tags a246386b-f31d-451d-b8a6-2f4c0dfa27b4' (cwd None)
>Thread-875::DEBUG::2014-05-29 12:26:52,693::lvm::288::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-875::DEBUG::2014-05-29 12:26:52,694::lvm::454::Storage.LVM::(_reloadlvs) lvs reloaded
>Thread-875::DEBUG::2014-05-29 12:26:52,694::lvm::454::OperationMutex::(_reloadlvs) Operation 'lvm reload operation' released the operation mutex
>Thread-875::DEBUG::2014-05-29 12:26:52,695::lvm::288::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /usr/sbin/lvm lvchange --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ \'a|/dev/mapper/3600140596b9bb9189094a98a6891f0a4|\', \'r|.*|\' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1  use_lvmetad=0 }  backup {  retain_min = 50  retain_days = 0 } " --autobackup n --available y a246386b-f31d-451d-b8a6-2f4c0dfa27b4/ea12203c-36a5-43d7-b351-492ec8c7944d' (cwd None)
>Thread-875::DEBUG::2014-05-29 12:26:52,844::lvm::288::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-875::DEBUG::2014-05-29 12:26:52,844::lvm::505::OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-875::DEBUG::2014-05-29 12:26:52,845::lvm::517::OperationMutex::(_invalidatelvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-875::DEBUG::2014-05-29 12:26:52,845::fileUtils::142::Storage.fileUtils::(createdir) Creating directory: /var/run/vdsm/storage/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/dad706d6-e1e9-4f31-87d4-610b3511a932
>Thread-875::WARNING::2014-05-29 12:26:52,845::fileUtils::149::Storage.fileUtils::(createdir) Dir /var/run/vdsm/storage/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/dad706d6-e1e9-4f31-87d4-610b3511a932 already exists
>Thread-875::DEBUG::2014-05-29 12:26:52,845::blockSD::1078::Storage.StorageDomain::(createImageLinks) Creating symlink from /dev/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/7e0ec106-f2dc-4567-b050-e3289bf2d47f to /var/run/vdsm/storage/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/dad706d6-e1e9-4f31-87d4-610b3511a932/7e0ec106-f2dc-4567-b050-e3289bf2d47f
>Thread-875::DEBUG::2014-05-29 12:26:52,845::blockSD::1083::Storage.StorageDomain::(createImageLinks) img run vol already exists: /var/run/vdsm/storage/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/dad706d6-e1e9-4f31-87d4-610b3511a932/7e0ec106-f2dc-4567-b050-e3289bf2d47f
>Thread-875::DEBUG::2014-05-29 12:26:52,845::blockSD::1078::Storage.StorageDomain::(createImageLinks) Creating symlink from /dev/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/ea12203c-36a5-43d7-b351-492ec8c7944d to /var/run/vdsm/storage/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/dad706d6-e1e9-4f31-87d4-610b3511a932/ea12203c-36a5-43d7-b351-492ec8c7944d
>Thread-875::DEBUG::2014-05-29 12:26:52,845::blockSD::1078::Storage.StorageDomain::(createImageLinks) Creating symlink from /dev/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/59354326-443a-42dc-b21d-8649056ced83 to /var/run/vdsm/storage/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/dad706d6-e1e9-4f31-87d4-610b3511a932/59354326-443a-42dc-b21d-8649056ced83
>Thread-875::DEBUG::2014-05-29 12:26:52,845::blockSD::1083::Storage.StorageDomain::(createImageLinks) img run vol already exists: /var/run/vdsm/storage/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/dad706d6-e1e9-4f31-87d4-610b3511a932/59354326-443a-42dc-b21d-8649056ced83
>Thread-875::DEBUG::2014-05-29 12:26:52,845::blockSD::1078::Storage.StorageDomain::(createImageLinks) Creating symlink from /dev/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/378fdb5e-1853-4946-9a79-fd7bd00bb466 to /var/run/vdsm/storage/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/dad706d6-e1e9-4f31-87d4-610b3511a932/378fdb5e-1853-4946-9a79-fd7bd00bb466
>Thread-875::DEBUG::2014-05-29 12:26:52,845::blockSD::1083::Storage.StorageDomain::(createImageLinks) img run vol already exists: /var/run/vdsm/storage/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/dad706d6-e1e9-4f31-87d4-610b3511a932/378fdb5e-1853-4946-9a79-fd7bd00bb466
>Thread-875::DEBUG::2014-05-29 12:26:52,846::blockSD::1048::Storage.StorageDomain::(linkBCImage) Creating symlink from /var/run/vdsm/storage/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/dad706d6-e1e9-4f31-87d4-610b3511a932 to /rhev/data-center/mnt/blockSD/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/images/dad706d6-e1e9-4f31-87d4-610b3511a932
>Thread-875::DEBUG::2014-05-29 12:26:52,846::blockSD::1054::Storage.StorageDomain::(linkBCImage) path to image directory already exists: /rhev/data-center/mnt/blockSD/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/images/dad706d6-e1e9-4f31-87d4-610b3511a932
>Thread-875::DEBUG::2014-05-29 12:26:52,846::lvm::419::OperationMutex::(_reloadlvs) Operation 'lvm reload operation' got the operation mutex
>Thread-875::DEBUG::2014-05-29 12:26:52,846::lvm::288::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /usr/sbin/lvm lvs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [ \'a|/dev/mapper/3600140596b9bb9189094a98a6891f0a4|\', \'r|.*|\' ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1  use_lvmetad=0 }  backup {  retain_min = 50  retain_days = 0 } " --noheadings --units b --nosuffix --separator | --ignoreskippedcluster -o uuid,name,vg_name,attr,size,seg_start_pe,devices,tags a246386b-f31d-451d-b8a6-2f4c0dfa27b4' (cwd None)
>Thread-875::DEBUG::2014-05-29 12:26:52,889::lvm::288::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>Thread-875::DEBUG::2014-05-29 12:26:52,889::lvm::454::Storage.LVM::(_reloadlvs) lvs reloaded
>Thread-875::DEBUG::2014-05-29 12:26:52,890::lvm::454::OperationMutex::(_reloadlvs) Operation 'lvm reload operation' released the operation mutex
>Thread-875::INFO::2014-05-29 12:26:52,890::logUtils::47::dispatcher::(wrapper) Run and protect: prepareImage, Return response: {'info': {'domainID': 'a246386b-f31d-451d-b8a6-2f4c0dfa27b4', 'volType': 'path', 'leaseOffset': 131072000, 'path': '/rhev/data-center/mnt/blockSD/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/images/dad706d6-e1e9-4f31-87d4-610b3511a932/ea12203c-36a5-43d7-b351-492ec8c7944d', 'volumeID': 'ea12203c-36a5-43d7-b351-492ec8c7944d', 'leasePath': '/dev/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/leases', 'imageID': 'dad706d6-e1e9-4f31-87d4-610b3511a932'}, 'path': '/rhev/data-center/mnt/blockSD/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/images/dad706d6-e1e9-4f31-87d4-610b3511a932/ea12203c-36a5-43d7-b351-492ec8c7944d', 'imgVolumesInfo': [{'domainID': 'a246386b-f31d-451d-b8a6-2f4c0dfa27b4', 'volType': 'path', 'leaseOffset': 115343360, 'path': '/rhev/data-center/mnt/blockSD/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/images/dad706d6-e1e9-4f31-87d4-610b3511a932/7e0ec106-f2dc-4567-b050-e3289bf2d47f', 'volumeID': '7e0ec106-f2dc-4567-b050-e3289bf2d47f', 'leasePath': '/dev/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/leases', 'imageID': 'dad706d6-e1e9-4f31-87d4-610b3511a932'}, {'domainID': 'a246386b-f31d-451d-b8a6-2f4c0dfa27b4', 'volType': 'path', 'leaseOffset': 131072000, 'path': '/rhev/data-center/mnt/blockSD/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/images/dad706d6-e1e9-4f31-87d4-610b3511a932/ea12203c-36a5-43d7-b351-492ec8c7944d', 'volumeID': 'ea12203c-36a5-43d7-b351-492ec8c7944d', 'leasePath': '/dev/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/leases', 'imageID': 'dad706d6-e1e9-4f31-87d4-610b3511a932'}, {'domainID': 'a246386b-f31d-451d-b8a6-2f4c0dfa27b4', 'volType': 'path', 'leaseOffset': 130023424, 'path': '/rhev/data-center/mnt/blockSD/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/images/dad706d6-e1e9-4f31-87d4-610b3511a932/59354326-443a-42dc-b21d-8649056ced83', 'volumeID': '59354326-443a-42dc-b21d-8649056ced83', 'leasePath': '/dev/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/leases', 'imageID': 'dad706d6-e1e9-4f31-87d4-610b3511a932'}, {'domainID': 'a246386b-f31d-451d-b8a6-2f4c0dfa27b4', 'volType': 'path', 'leaseOffset': 110100480, 'path': '/rhev/data-center/mnt/blockSD/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/images/dad706d6-e1e9-4f31-87d4-610b3511a932/378fdb5e-1853-4946-9a79-fd7bd00bb466', 'volumeID': '378fdb5e-1853-4946-9a79-fd7bd00bb466', 'leasePath': '/dev/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/leases', 'imageID': 'dad706d6-e1e9-4f31-87d4-610b3511a932'}]}
>Thread-875::DEBUG::2014-05-29 12:26:52,890::task::1188::TaskManager.Task::(prepare) Task=`57ba14a7-6905-421e-b95c-b6700932b53a`::finished: {'info': {'domainID': 'a246386b-f31d-451d-b8a6-2f4c0dfa27b4', 'volType': 'path', 'leaseOffset': 131072000, 'path': '/rhev/data-center/mnt/blockSD/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/images/dad706d6-e1e9-4f31-87d4-610b3511a932/ea12203c-36a5-43d7-b351-492ec8c7944d', 'volumeID': 'ea12203c-36a5-43d7-b351-492ec8c7944d', 'leasePath': '/dev/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/leases', 'imageID': 'dad706d6-e1e9-4f31-87d4-610b3511a932'}, 'path': '/rhev/data-center/mnt/blockSD/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/images/dad706d6-e1e9-4f31-87d4-610b3511a932/ea12203c-36a5-43d7-b351-492ec8c7944d', 'imgVolumesInfo': [{'domainID': 'a246386b-f31d-451d-b8a6-2f4c0dfa27b4', 'volType': 'path', 'leaseOffset': 115343360, 'path': '/rhev/data-center/mnt/blockSD/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/images/dad706d6-e1e9-4f31-87d4-610b3511a932/7e0ec106-f2dc-4567-b050-e3289bf2d47f', 'volumeID': '7e0ec106-f2dc-4567-b050-e3289bf2d47f', 'leasePath': '/dev/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/leases', 'imageID': 'dad706d6-e1e9-4f31-87d4-610b3511a932'}, {'domainID': 'a246386b-f31d-451d-b8a6-2f4c0dfa27b4', 'volType': 'path', 'leaseOffset': 131072000, 'path': '/rhev/data-center/mnt/blockSD/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/images/dad706d6-e1e9-4f31-87d4-610b3511a932/ea12203c-36a5-43d7-b351-492ec8c7944d', 'volumeID': 'ea12203c-36a5-43d7-b351-492ec8c7944d', 'leasePath': '/dev/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/leases', 'imageID': 'dad706d6-e1e9-4f31-87d4-610b3511a932'}, {'domainID': 'a246386b-f31d-451d-b8a6-2f4c0dfa27b4', 'volType': 'path', 'leaseOffset': 130023424, 'path': '/rhev/data-center/mnt/blockSD/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/images/dad706d6-e1e9-4f31-87d4-610b3511a932/59354326-443a-42dc-b21d-8649056ced83', 'volumeID': '59354326-443a-42dc-b21d-8649056ced83', 'leasePath': '/dev/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/leases', 'imageID': 'dad706d6-e1e9-4f31-87d4-610b3511a932'}, {'domainID': 'a246386b-f31d-451d-b8a6-2f4c0dfa27b4', 'volType': 'path', 'leaseOffset': 110100480, 'path': '/rhev/data-center/mnt/blockSD/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/images/dad706d6-e1e9-4f31-87d4-610b3511a932/378fdb5e-1853-4946-9a79-fd7bd00bb466', 'volumeID': '378fdb5e-1853-4946-9a79-fd7bd00bb466', 'leasePath': '/dev/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/leases', 'imageID': 'dad706d6-e1e9-4f31-87d4-610b3511a932'}]}
>Thread-875::DEBUG::2014-05-29 12:26:52,890::task::595::TaskManager.Task::(_updateState) Task=`57ba14a7-6905-421e-b95c-b6700932b53a`::moving from state preparing -> state finished
>Thread-875::DEBUG::2014-05-29 12:26:52,890::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.a246386b-f31d-451d-b8a6-2f4c0dfa27b4': < ResourceRef 'Storage.a246386b-f31d-451d-b8a6-2f4c0dfa27b4', isValid: 'True' obj: 'None'>}
>Thread-875::DEBUG::2014-05-29 12:26:52,891::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-875::DEBUG::2014-05-29 12:26:52,891::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.a246386b-f31d-451d-b8a6-2f4c0dfa27b4'
>Thread-875::DEBUG::2014-05-29 12:26:52,891::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.a246386b-f31d-451d-b8a6-2f4c0dfa27b4' (0 active users)
>Thread-875::DEBUG::2014-05-29 12:26:52,891::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.a246386b-f31d-451d-b8a6-2f4c0dfa27b4' is free, finding out if anyone is waiting for it.
>Thread-875::DEBUG::2014-05-29 12:26:52,891::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.a246386b-f31d-451d-b8a6-2f4c0dfa27b4', Clearing records.
>Thread-875::DEBUG::2014-05-29 12:26:52,891::task::993::TaskManager.Task::(_decref) Task=`57ba14a7-6905-421e-b95c-b6700932b53a`::ref 0 aborting False
>Thread-875::INFO::2014-05-29 12:26:52,891::clientIF::313::vds::(prepareVolumePath) prepared volume path: /rhev/data-center/mnt/blockSD/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/images/dad706d6-e1e9-4f31-87d4-610b3511a932/ea12203c-36a5-43d7-b351-492ec8c7944d
>Thread-875::DEBUG::2014-05-29 12:26:52,892::vm::3872::vm.Vm::(snapshot) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::<domainsnapshot>
>	<disks>
>		<disk name="vda" snapshot="external">
>			<source file="/rhev/data-center/mnt/blockSD/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/images/dad706d6-e1e9-4f31-87d4-610b3511a932/ea12203c-36a5-43d7-b351-492ec8c7944d" type="block"/>
>		</disk>
>	</disks>
></domainsnapshot>
>
>Thread-828::DEBUG::2014-05-29 12:26:53,983::BindingXMLRPC::1052::vds::(wrapper) client [192.168.2.1]::call vmGetStats with ('af8df38e-2e99-4a89-9483-a540027ea6b1',) {} flowID [70be129f]
>Thread-828::DEBUG::2014-05-29 12:26:53,983::vm::393::vm.Vm::(_getDiskLatency) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::Disk hdc latency not available
>Thread-828::DEBUG::2014-05-29 12:26:53,984::vm::393::vm.Vm::(_getDiskLatency) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::Disk vda latency not available
>Thread-828::DEBUG::2014-05-29 12:26:53,984::BindingXMLRPC::1059::vds::(wrapper) return vmGetStats with {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Paused', 'username': 'Unknown', 'memUsage': '0', 'acpiEnable': 'true', 'guestFQDN': '', 'pid': '20589', 'displayIp': '0', 'displayPort': '-1', 'session': 'Unknown', 'displaySecurePort': u'5900', 'timeOffset': '0', 'hash': '1834567123264894057', 'balloonInfo': {'balloon_max': '1048576', 'balloon_target': '1048576', 'balloon_cur': '1048576', 'balloon_min': '1048576'}, 'pauseCode': '', 'clientIp': '', 'kvmEnable': 'true', 'network': {u'vnet0': {'macAddr': '00:1a:4a:3f:44:a3', 'rxDropped': '0', 'rxErrors': '0', 'txDropped': '0', 'txRate': '0.0', 'rxRate': '0.0', 'txErrors': '0', 'state': 'unknown', 'speed': '1000', 'name': u'vnet0'}}, 'vmId': 'af8df38e-2e99-4a89-9483-a540027ea6b1', 'vmJobs': {}, 'cpuUser': '14.43', 'disks': {u'vda': {'truesize': '134217728', 'apparentsize': '134217728', 'imageID': 'dad706d6-e1e9-4f31-87d4-610b3511a932'}, u'hdc': {'truesize': '0', 'apparentsize': '0'}}, 'monitorResponse': '0', 'statsAge': '1.28', 'elapsedTime': '24', 'vmType': 'kvm', 'cpuSys': '6.78', 'guestCPUCount': -1, 'appsList': [], 'guestIPs': '', 'displayType': 'qxl'}]}
>Thread-828::DEBUG::2014-05-29 12:26:57,038::task::595::TaskManager.Task::(_updateState) Task=`3fae7cce-b7e1-496c-a27f-2fcc50227410`::moving from state init -> state preparing
>Thread-828::INFO::2014-05-29 12:26:57,039::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-828::INFO::2014-05-29 12:26:57,039::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'e453999e-ec9f-420b-941c-a9f9cc4432bb': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000858633', 'lastCheck': '6.6', 'valid': True}, u'a246386b-f31d-451d-b8a6-2f4c0dfa27b4': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.00165453', 'lastCheck': '5.1', 'valid': True}}
>Thread-828::DEBUG::2014-05-29 12:26:57,039::task::1188::TaskManager.Task::(prepare) Task=`3fae7cce-b7e1-496c-a27f-2fcc50227410`::finished: {u'e453999e-ec9f-420b-941c-a9f9cc4432bb': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000858633', 'lastCheck': '6.6', 'valid': True}, u'a246386b-f31d-451d-b8a6-2f4c0dfa27b4': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.00165453', 'lastCheck': '5.1', 'valid': True}}
>Thread-828::DEBUG::2014-05-29 12:26:57,039::task::595::TaskManager.Task::(_updateState) Task=`3fae7cce-b7e1-496c-a27f-2fcc50227410`::moving from state preparing -> state finished
>Thread-828::DEBUG::2014-05-29 12:26:57,039::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-828::DEBUG::2014-05-29 12:26:57,039::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-828::DEBUG::2014-05-29 12:26:57,039::task::993::TaskManager.Task::(_decref) Task=`3fae7cce-b7e1-496c-a27f-2fcc50227410`::ref 0 aborting False
>Thread-828::DEBUG::2014-05-29 12:26:57,052::vm::393::vm.Vm::(_getDiskLatency) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::Disk hdc latency not available
>Thread-828::DEBUG::2014-05-29 12:26:57,052::vm::393::vm.Vm::(_getDiskLatency) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::Disk vda latency not available
>Thread-450::DEBUG::2014-05-29 12:27:00,441::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd if=/rhev/data-center/mnt/192.168.2.1:_home_storage_iso/e453999e-ec9f-420b-941c-a9f9cc4432bb/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1' (cwd None)
>Thread-450::DEBUG::2014-05-29 12:27:00,450::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n531 bytes (531 B) copied, 0.0010545 s, 504 kB/s\n'; <rc> = 0
>VM Channels Listener::DEBUG::2014-05-29 12:27:01,269::vmchannels::92::vds::(_handle_timeouts) Timeout on fileno 54.
>Thread-451::DEBUG::2014-05-29 12:27:01,906::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd if=/dev/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/metadata iflag=direct of=/dev/null bs=4096 count=1' (cwd None)
>Thread-451::DEBUG::2014-05-29 12:27:01,912::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.00146663 s, 2.8 MB/s\n'; <rc> = 0
>Thread-875::DEBUG::2014-05-29 12:27:02,000::libvirtconnection::125::root::(wrapper) Unknown libvirterror: ecode: 86 edom: 10 level: 2 message: Guest agent is not responding: Guest agent not available for now
>Thread-875::DEBUG::2014-05-29 12:27:02,000::vm::3893::vm.Vm::(snapshot) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::Snapshot failed using the quiesce flag, trying again without it (Guest agent is not responding: Guest agent not available for now)
>Thread-875::DEBUG::2014-05-29 12:27:02,057::task::595::TaskManager.Task::(_updateState) Task=`fc630148-2277-425b-9eb1-226033ff1fea`::moving from state init -> state preparing
>Thread-875::INFO::2014-05-29 12:27:02,058::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='a246386b-f31d-451d-b8a6-2f4c0dfa27b4', spUUID='be744655-2a19-4919-92f3-e7c20ac03193', imgUUID='dad706d6-e1e9-4f31-87d4-610b3511a932', volUUID='ea12203c-36a5-43d7-b351-492ec8c7944d', options=None)
>Thread-875::INFO::2014-05-29 12:27:02,058::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '134217728', 'apparentsize': '134217728'}
>Thread-875::DEBUG::2014-05-29 12:27:02,058::task::1188::TaskManager.Task::(prepare) Task=`fc630148-2277-425b-9eb1-226033ff1fea`::finished: {'truesize': '134217728', 'apparentsize': '134217728'}
>Thread-875::DEBUG::2014-05-29 12:27:02,058::task::595::TaskManager.Task::(_updateState) Task=`fc630148-2277-425b-9eb1-226033ff1fea`::moving from state preparing -> state finished
>Thread-875::DEBUG::2014-05-29 12:27:02,058::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-875::DEBUG::2014-05-29 12:27:02,058::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-875::DEBUG::2014-05-29 12:27:02,059::task::993::TaskManager.Task::(_decref) Task=`fc630148-2277-425b-9eb1-226033ff1fea`::ref 0 aborting False
>Thread-875::DEBUG::2014-05-29 12:27:02,068::BindingXMLRPC::1059::vds::(wrapper) return vmSnapshot with {'status': {'message': 'Done', 'code': 0}, 'quiesce': False}
>Thread-450::DEBUG::2014-05-29 12:27:10,456::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd if=/rhev/data-center/mnt/192.168.2.1:_home_storage_iso/e453999e-ec9f-420b-941c-a9f9cc4432bb/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1' (cwd None)
>Thread-450::DEBUG::2014-05-29 12:27:10,464::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n531 bytes (531 B) copied, 0.0020968 s, 253 kB/s\n'; <rc> = 0
>Thread-451::DEBUG::2014-05-29 12:27:11,916::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd if=/dev/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/metadata iflag=direct of=/dev/null bs=4096 count=1' (cwd None)
>Thread-451::DEBUG::2014-05-29 12:27:11,922::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.00151924 s, 2.7 MB/s\n'; <rc> = 0
>Thread-828::DEBUG::2014-05-29 12:27:12,166::task::595::TaskManager.Task::(_updateState) Task=`7a464cad-0589-4684-8745-934469f416bf`::moving from state init -> state preparing
>Thread-828::INFO::2014-05-29 12:27:12,166::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-828::INFO::2014-05-29 12:27:12,166::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'e453999e-ec9f-420b-941c-a9f9cc4432bb': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.0020968', 'lastCheck': '1.7', 'valid': True}, u'a246386b-f31d-451d-b8a6-2f4c0dfa27b4': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.00151924', 'lastCheck': '0.2', 'valid': True}}
>Thread-828::DEBUG::2014-05-29 12:27:12,167::task::1188::TaskManager.Task::(prepare) Task=`7a464cad-0589-4684-8745-934469f416bf`::finished: {u'e453999e-ec9f-420b-941c-a9f9cc4432bb': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.0020968', 'lastCheck': '1.7', 'valid': True}, u'a246386b-f31d-451d-b8a6-2f4c0dfa27b4': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.00151924', 'lastCheck': '0.2', 'valid': True}}
>Thread-828::DEBUG::2014-05-29 12:27:12,167::task::595::TaskManager.Task::(_updateState) Task=`7a464cad-0589-4684-8745-934469f416bf`::moving from state preparing -> state finished
>Thread-828::DEBUG::2014-05-29 12:27:12,167::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-828::DEBUG::2014-05-29 12:27:12,167::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-828::DEBUG::2014-05-29 12:27:12,167::task::993::TaskManager.Task::(_decref) Task=`7a464cad-0589-4684-8745-934469f416bf`::ref 0 aborting False
>Thread-828::DEBUG::2014-05-29 12:27:12,177::vm::393::vm.Vm::(_getDiskLatency) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::Disk hdc latency not available
>Thread-828::DEBUG::2014-05-29 12:27:12,177::vm::393::vm.Vm::(_getDiskLatency) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::Disk vda latency not available
>Thread-866::DEBUG::2014-05-29 12:27:15,727::task::595::TaskManager.Task::(_updateState) Task=`d04559dc-b94e-40a7-9783-90cd02426396`::moving from state init -> state preparing
>Thread-866::INFO::2014-05-29 12:27:15,727::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='a246386b-f31d-451d-b8a6-2f4c0dfa27b4', spUUID='be744655-2a19-4919-92f3-e7c20ac03193', imgUUID='dad706d6-e1e9-4f31-87d4-610b3511a932', volUUID='ea12203c-36a5-43d7-b351-492ec8c7944d', options=None)
>Thread-866::INFO::2014-05-29 12:27:15,727::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '134217728', 'apparentsize': '134217728'}
>Thread-866::DEBUG::2014-05-29 12:27:15,727::task::1188::TaskManager.Task::(prepare) Task=`d04559dc-b94e-40a7-9783-90cd02426396`::finished: {'truesize': '134217728', 'apparentsize': '134217728'}
>Thread-866::DEBUG::2014-05-29 12:27:15,727::task::595::TaskManager.Task::(_updateState) Task=`d04559dc-b94e-40a7-9783-90cd02426396`::moving from state preparing -> state finished
>Thread-866::DEBUG::2014-05-29 12:27:15,728::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-866::DEBUG::2014-05-29 12:27:15,728::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-866::DEBUG::2014-05-29 12:27:15,728::task::993::TaskManager.Task::(_decref) Task=`d04559dc-b94e-40a7-9783-90cd02426396`::ref 0 aborting False
>Thread-450::DEBUG::2014-05-29 12:27:20,475::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd if=/rhev/data-center/mnt/192.168.2.1:_home_storage_iso/e453999e-ec9f-420b-941c-a9f9cc4432bb/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1' (cwd None)
>Thread-450::DEBUG::2014-05-29 12:27:20,482::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n531 bytes (531 B) copied, 0.00108423 s, 490 kB/s\n'; <rc> = 0
>Thread-451::DEBUG::2014-05-29 12:27:21,926::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd if=/dev/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/metadata iflag=direct of=/dev/null bs=4096 count=1' (cwd None)
>Thread-451::DEBUG::2014-05-29 12:27:21,932::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.00159417 s, 2.6 MB/s\n'; <rc> = 0
>Thread-828::DEBUG::2014-05-29 12:27:27,569::task::595::TaskManager.Task::(_updateState) Task=`d4ab25c5-eb7f-4b7b-b57e-8a766a294701`::moving from state init -> state preparing
>Thread-828::INFO::2014-05-29 12:27:27,569::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-828::INFO::2014-05-29 12:27:27,569::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'e453999e-ec9f-420b-941c-a9f9cc4432bb': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.00108423', 'lastCheck': '7.1', 'valid': True}, u'a246386b-f31d-451d-b8a6-2f4c0dfa27b4': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.00159417', 'lastCheck': '5.6', 'valid': True}}
>Thread-828::DEBUG::2014-05-29 12:27:27,569::task::1188::TaskManager.Task::(prepare) Task=`d4ab25c5-eb7f-4b7b-b57e-8a766a294701`::finished: {u'e453999e-ec9f-420b-941c-a9f9cc4432bb': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.00108423', 'lastCheck': '7.1', 'valid': True}, u'a246386b-f31d-451d-b8a6-2f4c0dfa27b4': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.00159417', 'lastCheck': '5.6', 'valid': True}}
>Thread-828::DEBUG::2014-05-29 12:27:27,569::task::595::TaskManager.Task::(_updateState) Task=`d4ab25c5-eb7f-4b7b-b57e-8a766a294701`::moving from state preparing -> state finished
>Thread-828::DEBUG::2014-05-29 12:27:27,569::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-828::DEBUG::2014-05-29 12:27:27,569::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-828::DEBUG::2014-05-29 12:27:27,569::task::993::TaskManager.Task::(_decref) Task=`d4ab25c5-eb7f-4b7b-b57e-8a766a294701`::ref 0 aborting False
>Thread-828::DEBUG::2014-05-29 12:27:27,581::vm::393::vm.Vm::(_getDiskLatency) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::Disk hdc latency not available
>Thread-828::DEBUG::2014-05-29 12:27:27,581::vm::393::vm.Vm::(_getDiskLatency) vmId=`af8df38e-2e99-4a89-9483-a540027ea6b1`::Disk vda latency not available
>Thread-450::DEBUG::2014-05-29 12:27:30,488::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd if=/rhev/data-center/mnt/192.168.2.1:_home_storage_iso/e453999e-ec9f-420b-941c-a9f9cc4432bb/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1' (cwd None)
>Thread-450::DEBUG::2014-05-29 12:27:30,494::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n531 bytes (531 B) copied, 0.00106885 s, 497 kB/s\n'; <rc> = 0
>Thread-866::DEBUG::2014-05-29 12:27:30,745::task::595::TaskManager.Task::(_updateState) Task=`60385e25-0bed-40ea-8255-aafd10cc34c6`::moving from state init -> state preparing
>Thread-866::INFO::2014-05-29 12:27:30,745::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='a246386b-f31d-451d-b8a6-2f4c0dfa27b4', spUUID='be744655-2a19-4919-92f3-e7c20ac03193', imgUUID='dad706d6-e1e9-4f31-87d4-610b3511a932', volUUID='ea12203c-36a5-43d7-b351-492ec8c7944d', options=None)
>Thread-866::INFO::2014-05-29 12:27:30,745::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '134217728', 'apparentsize': '134217728'}
>Thread-866::DEBUG::2014-05-29 12:27:30,745::task::1188::TaskManager.Task::(prepare) Task=`60385e25-0bed-40ea-8255-aafd10cc34c6`::finished: {'truesize': '134217728', 'apparentsize': '134217728'}
>Thread-866::DEBUG::2014-05-29 12:27:30,745::task::595::TaskManager.Task::(_updateState) Task=`60385e25-0bed-40ea-8255-aafd10cc34c6`::moving from state preparing -> state finished
>Thread-866::DEBUG::2014-05-29 12:27:30,745::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-866::DEBUG::2014-05-29 12:27:30,745::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-866::DEBUG::2014-05-29 12:27:30,745::task::993::TaskManager.Task::(_decref) Task=`60385e25-0bed-40ea-8255-aafd10cc34c6`::ref 0 aborting False
>VM Channels Listener::DEBUG::2014-05-29 12:27:31,301::vmchannels::92::vds::(_handle_timeouts) Timeout on fileno 54.
>Thread-451::DEBUG::2014-05-29 12:27:31,936::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd if=/dev/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/metadata iflag=direct of=/dev/null bs=4096 count=1' (cwd None)
>Thread-451::DEBUG::2014-05-29 12:27:31,942::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.00148777 s, 2.8 MB/s\n'; <rc> = 0
>Thread-450::DEBUG::2014-05-29 12:27:40,501::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd if=/rhev/data-center/mnt/192.168.2.1:_home_storage_iso/e453999e-ec9f-420b-941c-a9f9cc4432bb/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1' (cwd None)
>Thread-450::DEBUG::2014-05-29 12:27:40,507::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n531 bytes (531 B) copied, 0.00104848 s, 506 kB/s\n'; <rc> = 0
>Thread-451::DEBUG::2014-05-29 12:27:41,946::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd if=/dev/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/metadata iflag=direct of=/dev/null bs=4096 count=1' (cwd None)
>Thread-451::DEBUG::2014-05-29 12:27:41,952::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.00166547 s, 2.5 MB/s\n'; <rc> = 0
>Thread-828::DEBUG::2014-05-29 12:27:42,711::task::595::TaskManager.Task::(_updateState) Task=`10ae5121-ef36-4249-b2f7-53290df2f0aa`::moving from state init -> state preparing
>Thread-828::INFO::2014-05-29 12:27:42,712::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-828::INFO::2014-05-29 12:27:42,712::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'e453999e-ec9f-420b-941c-a9f9cc4432bb': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.00104848', 'lastCheck': '2.2', 'valid': True}, u'a246386b-f31d-451d-b8a6-2f4c0dfa27b4': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.00166547', 'lastCheck': '0.8', 'valid': True}}
>Thread-828::DEBUG::2014-05-29 12:27:42,712::task::1188::TaskManager.Task::(prepare) Task=`10ae5121-ef36-4249-b2f7-53290df2f0aa`::finished: {u'e453999e-ec9f-420b-941c-a9f9cc4432bb': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.00104848', 'lastCheck': '2.2', 'valid': True}, u'a246386b-f31d-451d-b8a6-2f4c0dfa27b4': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.00166547', 'lastCheck': '0.8', 'valid': True}}
>Thread-828::DEBUG::2014-05-29 12:27:42,712::task::595::TaskManager.Task::(_updateState) Task=`10ae5121-ef36-4249-b2f7-53290df2f0aa`::moving from state preparing -> state finished
>Thread-828::DEBUG::2014-05-29 12:27:42,712::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-828::DEBUG::2014-05-29 12:27:42,712::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-828::DEBUG::2014-05-29 12:27:42,712::task::993::TaskManager.Task::(_decref) Task=`10ae5121-ef36-4249-b2f7-53290df2f0aa`::ref 0 aborting False
>Thread-866::DEBUG::2014-05-29 12:27:45,769::task::595::TaskManager.Task::(_updateState) Task=`53d87baa-6d00-4c06-b970-848d1ea15f2a`::moving from state init -> state preparing
>Thread-866::INFO::2014-05-29 12:27:45,770::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='a246386b-f31d-451d-b8a6-2f4c0dfa27b4', spUUID='be744655-2a19-4919-92f3-e7c20ac03193', imgUUID='dad706d6-e1e9-4f31-87d4-610b3511a932', volUUID='ea12203c-36a5-43d7-b351-492ec8c7944d', options=None)
>Thread-866::INFO::2014-05-29 12:27:45,770::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '134217728', 'apparentsize': '134217728'}
>Thread-866::DEBUG::2014-05-29 12:27:45,770::task::1188::TaskManager.Task::(prepare) Task=`53d87baa-6d00-4c06-b970-848d1ea15f2a`::finished: {'truesize': '134217728', 'apparentsize': '134217728'}
>Thread-866::DEBUG::2014-05-29 12:27:45,770::task::595::TaskManager.Task::(_updateState) Task=`53d87baa-6d00-4c06-b970-848d1ea15f2a`::moving from state preparing -> state finished
>Thread-866::DEBUG::2014-05-29 12:27:45,770::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-866::DEBUG::2014-05-29 12:27:45,770::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-866::DEBUG::2014-05-29 12:27:45,770::task::993::TaskManager.Task::(_decref) Task=`53d87baa-6d00-4c06-b970-848d1ea15f2a`::ref 0 aborting False
>Thread-450::DEBUG::2014-05-29 12:27:50,513::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd if=/rhev/data-center/mnt/192.168.2.1:_home_storage_iso/e453999e-ec9f-420b-941c-a9f9cc4432bb/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1' (cwd None)
>Thread-450::DEBUG::2014-05-29 12:27:50,520::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n531 bytes (531 B) copied, 0.00111669 s, 476 kB/s\n'; <rc> = 0
>Thread-451::DEBUG::2014-05-29 12:27:51,956::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd if=/dev/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/metadata iflag=direct of=/dev/null bs=4096 count=1' (cwd None)
>Thread-451::DEBUG::2014-05-29 12:27:51,962::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.00154701 s, 2.6 MB/s\n'; <rc> = 0
>Thread-828::DEBUG::2014-05-29 12:27:57,881::task::595::TaskManager.Task::(_updateState) Task=`d6c8fb95-47fe-4d8e-8316-9ddc61b41688`::moving from state init -> state preparing
>Thread-828::INFO::2014-05-29 12:27:57,881::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-828::INFO::2014-05-29 12:27:57,882::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'e453999e-ec9f-420b-941c-a9f9cc4432bb': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.00111669', 'lastCheck': '7.4', 'valid': True}, u'a246386b-f31d-451d-b8a6-2f4c0dfa27b4': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.00154701', 'lastCheck': '5.9', 'valid': True}}
>Thread-828::DEBUG::2014-05-29 12:27:57,882::task::1188::TaskManager.Task::(prepare) Task=`d6c8fb95-47fe-4d8e-8316-9ddc61b41688`::finished: {u'e453999e-ec9f-420b-941c-a9f9cc4432bb': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.00111669', 'lastCheck': '7.4', 'valid': True}, u'a246386b-f31d-451d-b8a6-2f4c0dfa27b4': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.00154701', 'lastCheck': '5.9', 'valid': True}}
>Thread-828::DEBUG::2014-05-29 12:27:57,882::task::595::TaskManager.Task::(_updateState) Task=`d6c8fb95-47fe-4d8e-8316-9ddc61b41688`::moving from state preparing -> state finished
>Thread-828::DEBUG::2014-05-29 12:27:57,882::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-828::DEBUG::2014-05-29 12:27:57,882::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-828::DEBUG::2014-05-29 12:27:57,882::task::993::TaskManager.Task::(_decref) Task=`d6c8fb95-47fe-4d8e-8316-9ddc61b41688`::ref 0 aborting False
>Thread-450::DEBUG::2014-05-29 12:28:00,528::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd if=/rhev/data-center/mnt/192.168.2.1:_home_storage_iso/e453999e-ec9f-420b-941c-a9f9cc4432bb/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1' (cwd None)
>Thread-450::DEBUG::2014-05-29 12:28:00,537::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n531 bytes (531 B) copied, 0.0011002 s, 483 kB/s\n'; <rc> = 0
>Thread-866::DEBUG::2014-05-29 12:28:00,787::task::595::TaskManager.Task::(_updateState) Task=`ea885e66-17ef-4227-be41-3d952d07fbac`::moving from state init -> state preparing
>Thread-866::INFO::2014-05-29 12:28:00,787::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='a246386b-f31d-451d-b8a6-2f4c0dfa27b4', spUUID='be744655-2a19-4919-92f3-e7c20ac03193', imgUUID='dad706d6-e1e9-4f31-87d4-610b3511a932', volUUID='ea12203c-36a5-43d7-b351-492ec8c7944d', options=None)
>Thread-866::INFO::2014-05-29 12:28:00,788::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '134217728', 'apparentsize': '134217728'}
>Thread-866::DEBUG::2014-05-29 12:28:00,788::task::1188::TaskManager.Task::(prepare) Task=`ea885e66-17ef-4227-be41-3d952d07fbac`::finished: {'truesize': '134217728', 'apparentsize': '134217728'}
>Thread-866::DEBUG::2014-05-29 12:28:00,788::task::595::TaskManager.Task::(_updateState) Task=`ea885e66-17ef-4227-be41-3d952d07fbac`::moving from state preparing -> state finished
>Thread-866::DEBUG::2014-05-29 12:28:00,788::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-866::DEBUG::2014-05-29 12:28:00,788::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-866::DEBUG::2014-05-29 12:28:00,788::task::993::TaskManager.Task::(_decref) Task=`ea885e66-17ef-4227-be41-3d952d07fbac`::ref 0 aborting False
>VM Channels Listener::DEBUG::2014-05-29 12:28:01,334::vmchannels::92::vds::(_handle_timeouts) Timeout on fileno 54.
>Thread-451::DEBUG::2014-05-29 12:28:01,966::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd if=/dev/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/metadata iflag=direct of=/dev/null bs=4096 count=1' (cwd None)
>Thread-451::DEBUG::2014-05-29 12:28:01,972::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.00156685 s, 2.6 MB/s\n'; <rc> = 0
>Thread-450::DEBUG::2014-05-29 12:28:10,543::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd if=/rhev/data-center/mnt/192.168.2.1:_home_storage_iso/e453999e-ec9f-420b-941c-a9f9cc4432bb/dom_md/metadata iflag=direct of=/dev/null bs=4096 count=1' (cwd None)
>Thread-450::DEBUG::2014-05-29 12:28:10,549::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n531 bytes (531 B) copied, 0.00104104 s, 510 kB/s\n'; <rc> = 0
>Thread-451::DEBUG::2014-05-29 12:28:11,977::blockSD::595::Storage.Misc.excCmd::(getReadDelay) '/usr/bin/dd if=/dev/a246386b-f31d-451d-b8a6-2f4c0dfa27b4/metadata iflag=direct of=/dev/null bs=4096 count=1' (cwd None)
>Thread-451::DEBUG::2014-05-29 12:28:11,983::blockSD::595::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.00165722 s, 2.5 MB/s\n'; <rc> = 0
>Thread-828::DEBUG::2014-05-29 12:28:13,018::task::595::TaskManager.Task::(_updateState) Task=`918cfb27-a0c7-4edc-aac0-8786a8c9a115`::moving from state init -> state preparing
>Thread-828::INFO::2014-05-29 12:28:13,018::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-828::INFO::2014-05-29 12:28:13,018::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'e453999e-ec9f-420b-941c-a9f9cc4432bb': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.00104104', 'lastCheck': '2.5', 'valid': True}, u'a246386b-f31d-451d-b8a6-2f4c0dfa27b4': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.00165722', 'lastCheck': '1.0', 'valid': True}}
>Thread-828::DEBUG::2014-05-29 12:28:13,018::task::1188::TaskManager.Task::(prepare) Task=`918cfb27-a0c7-4edc-aac0-8786a8c9a115`::finished: {u'e453999e-ec9f-420b-941c-a9f9cc4432bb': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.00104104', 'lastCheck': '2.5', 'valid': True}, u'a246386b-f31d-451d-b8a6-2f4c0dfa27b4': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.00165722', 'lastCheck': '1.0', 'valid': True}}
>Thread-828::DEBUG::2014-05-29 12:28:13,018::task::595::TaskManager.Task::(_updateState) Task=`918cfb27-a0c7-4edc-aac0-8786a8c9a115`::moving from state preparing -> state finished
>Thread-828::DEBUG::2014-05-29 12:28:13,018::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-828::DEBUG::2014-05-29 12:28:13,019::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-828::DEBUG::2014-05-29 12:28:13,019::task::993::TaskManager.Task::(_decref) Task=`918cfb27-a0c7-4edc-aac0-8786a8c9a115`::ref 0 aborting False
>Thread-866::DEBUG::2014-05-29 12:28:15,803::task::595::TaskManager.Task::(_updateState) Task=`ec538774-d908-4acb-aa1f-83e7a8a48be1`::moving from state init -> state preparing
>Thread-866::INFO::2014-05-29 12:28:15,803::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='a246386b-f31d-451d-b8a6-2f4c0dfa27b4', spUUID='be744655-2a19-4919-92f3-e7c20ac03193', imgUUID='dad706d6-e1e9-4f31-87d4-610b3511a932', volUUID='ea12203c-36a5-43d7-b351-492ec8c7944d', options=None)
>Thread-866::INFO::2014-05-29 12:28:15,804::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '134217728', 'apparentsize': '134217728'}
>Thread-866::DEBUG::2014-05-29 12:28:15,804::task::1188::TaskManager.Task::(prepare) Task=`ec538774-d908-4acb-aa1f-83e7a8a48be1`::finished: {'truesize': '134217728', 'apparentsize': '134217728'}
>Thread-866::DEBUG::2014-05-29 12:28:15,804::task::595::TaskManager.Task::(_updateState) Task=`ec538774-d908-4acb-aa1f-83e7a8a48be1`::moving from state preparing -> state finished
>Thread-866::DEBUG::2014-05-29 12:28:15,804::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-866::DEBUG::2014-05-29 12:28:15,804::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-866::DEBUG::2014-05-29 12:28:15,804::task::993::TaskManager.Task::(_decref) Task=`ec538774-d908-4acb-aa1f-83e7a8a48be1`::ref 0 aborting False

Actions: View

Attachments on bug 1102881: 900481 | 900482 | 900483 | 900484 | 900523 | 901471 | 901490 | 922603 | 922604 | 922606 | 922607 | 923330