Login
[x]
Log in using an account from:
Fedora Account System
Red Hat Associate
Red Hat Customer
Or login using a Red Hat Bugzilla account
Forgot Password
Login:
Hide Forgot
Create an Account
Red Hat Bugzilla – Attachment 900483 Details for
Bug 1102881
virDomainBlockCommit fails with live snapshots on oVirt block storage
[?]
New
Simple Search
Advanced Search
My Links
Browse
Requests
Reports
Current State
Search
Tabular reports
Graphical reports
Duplicates
Other Reports
User Changes
Plotly Reports
Bug Status
Bug Severity
Non-Defaults
|
Product Dashboard
Help
Page Help!
Bug Writing Guidelines
What's new
Browser Support Policy
5.0.4.rh83 Release notes
FAQ
Guides index
User guide
Web Services
Contact
Legal
This site requires JavaScript to be enabled to function correctly, please enable it.
vdsm log 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:
vdsm log when the problem happens
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
You cannot view the attachment while viewing its details because your browser does not support IFRAMEs.
View the attachment on a separate page
.
View Attachment As Raw
Actions:
View
Attachments on
bug 1102881
:
900481
|
900482
|
900483
|
900484
|
900523
|
901471
|
901490
|
922603
|
922604
|
922606
|
922607
|
923330