Attachment 607114 Details for Bug 851936 – vdsm.log

vdsm.log

vdsm.log (text/x-log), 72.55 KB, created by Gowrishankar Rajaiyan on 2012-08-27 04:53:13 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: Gowrishankar Rajaiyan

Created: 2012-08-27 04:53:13 UTC

Size: 72.55 KB

patch

obsolete

>Thread-194242::DEBUG::2011-10-11 14:01:01,763::BindingXMLRPC::164::vds::(wrapper) [10.70.34.52]
>Thread-194242::DEBUG::2011-10-11 14:01:01,763::task::588::TaskManager.Task::(_updateState) Task=`d4c639de-0ece-4cb9-8636-a4adfd38c045`::moving from state init -> state preparing
>Thread-194242::INFO::2011-10-11 14:01:01,764::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='22fb1d8d-7329-4573-9827-ca5d49cab451', options=None)
>Thread-194242::INFO::2011-10-11 14:01:01,764::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 1}}
>Thread-194242::DEBUG::2011-10-11 14:01:01,765::task::1172::TaskManager.Task::(prepare) Task=`d4c639de-0ece-4cb9-8636-a4adfd38c045`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 1}}
>Thread-194242::DEBUG::2011-10-11 14:01:01,765::task::588::TaskManager.Task::(_updateState) Task=`d4c639de-0ece-4cb9-8636-a4adfd38c045`::moving from state preparing -> state finished
>Thread-194242::DEBUG::2011-10-11 14:01:01,766::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-194242::DEBUG::2011-10-11 14:01:01,766::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-194242::DEBUG::2011-10-11 14:01:01,767::task::978::TaskManager.Task::(_decref) Task=`d4c639de-0ece-4cb9-8636-a4adfd38c045`::ref 0 aborting False
>Thread-194243::DEBUG::2011-10-11 14:01:01,792::BindingXMLRPC::164::vds::(wrapper) [10.70.34.52]
>Thread-194243::DEBUG::2011-10-11 14:01:01,793::task::588::TaskManager.Task::(_updateState) Task=`b19df36e-fa2b-4eac-b7a5-ec3f273bc1d8`::moving from state init -> state preparing
>Thread-194243::INFO::2011-10-11 14:01:01,794::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='22fb1d8d-7329-4573-9827-ca5d49cab451', options=None)
>Thread-194243::DEBUG::2011-10-11 14:01:01,794::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.22fb1d8d-7329-4573-9827-ca5d49cab451`ReqID=`a2299dff-11b8-45c3-a243-3b596c7d4dc0`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-194243::DEBUG::2011-10-11 14:01:01,795::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.22fb1d8d-7329-4573-9827-ca5d49cab451' for lock type 'shared'
>Thread-194243::DEBUG::2011-10-11 14:01:01,795::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.22fb1d8d-7329-4573-9827-ca5d49cab451' is free. Now locking as 'shared' (1 active user)
>Thread-194243::DEBUG::2011-10-11 14:01:01,796::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.22fb1d8d-7329-4573-9827-ca5d49cab451`ReqID=`a2299dff-11b8-45c3-a243-3b596c7d4dc0`::Granted request
>Thread-194243::DEBUG::2011-10-11 14:01:01,796::task::817::TaskManager.Task::(resourceAcquired) Task=`b19df36e-fa2b-4eac-b7a5-ec3f273bc1d8`::_resourcesAcquired: Storage.22fb1d8d-7329-4573-9827-ca5d49cab451 (shared)
>Thread-194243::DEBUG::2011-10-11 14:01:01,797::task::978::TaskManager.Task::(_decref) Task=`b19df36e-fa2b-4eac-b7a5-ec3f273bc1d8`::ref 1 aborting False
>Thread-194243::INFO::2011-10-11 14:01:01,806::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': 'b8fde061-56bd-4e42-8d50-7dbb9bd9c5e1', 'name': 'RHS_RHEV_001', 'version': '3', 'domains': '523559dc-b966-4544-8618-620ca06c4d4d:Active,41263435-b36f-49dc-960a-8758a3744546:Active,ed1c88c8-54b5-4616-aa00-26096173feaf:Active,b8fde061-56bd-4e42-8d50-7dbb9bd9c5e1:Active,79b1039e-34a7-4cb4-aedf-271a304468f5:Active,5743191c-5960-48cb-b87b-3f40645149ba:Active', 'pool_status': 'connected', 'isoprefix': '/rhev/data-center/22fb1d8d-7329-4573-9827-ca5d49cab451/ed1c88c8-54b5-4616-aa00-26096173feaf/images/11111111-1111-1111-1111-111111111111', 'type': 'POSIXFS', 'master_ver': 2, 'lver': 1}, 'dominfo': {'523559dc-b966-4544-8618-620ca06c4d4d': {'status': 'Active', 'diskfree': '315304968192', 'alerts': [], 'disktotal': '321963163648'}, '41263435-b36f-49dc-960a-8758a3744546': {'status': 'Active', 'diskfree': '632269963264', 'alerts': [], 'disktotal': '643926327296'}, 'ed1c88c8-54b5-4616-aa00-26096173feaf': {'status': 'Active', 'diskfree': '377466388480', 'alerts': [], 'disktotal': '403472121856'}, 'b8fde061-56bd-4e42-8d50-7dbb9bd9c5e1': {'status': 'Active', 'diskfree': '315304968192', 'alerts': [], 'disktotal': '321963163648'}, '79b1039e-34a7-4cb4-aedf-271a304468f5': {'status': 'Active', 'diskfree': '624710385664', 'alerts': [], 'disktotal': '643926327296'}, '5743191c-5960-48cb-b87b-3f40645149ba': {'status': 'Active', 'diskfree': '624710385664', 'alerts': [], 'disktotal': '643926327296'}}}
>Thread-194243::DEBUG::2011-10-11 14:01:01,807::task::1172::TaskManager.Task::(prepare) Task=`b19df36e-fa2b-4eac-b7a5-ec3f273bc1d8`::finished: {'info': {'spm_id': 1, 'master_uuid': 'b8fde061-56bd-4e42-8d50-7dbb9bd9c5e1', 'name': 'RHS_RHEV_001', 'version': '3', 'domains': '523559dc-b966-4544-8618-620ca06c4d4d:Active,41263435-b36f-49dc-960a-8758a3744546:Active,ed1c88c8-54b5-4616-aa00-26096173feaf:Active,b8fde061-56bd-4e42-8d50-7dbb9bd9c5e1:Active,79b1039e-34a7-4cb4-aedf-271a304468f5:Active,5743191c-5960-48cb-b87b-3f40645149ba:Active', 'pool_status': 'connected', 'isoprefix': '/rhev/data-center/22fb1d8d-7329-4573-9827-ca5d49cab451/ed1c88c8-54b5-4616-aa00-26096173feaf/images/11111111-1111-1111-1111-111111111111', 'type': 'POSIXFS', 'master_ver': 2, 'lver': 1}, 'dominfo': {'523559dc-b966-4544-8618-620ca06c4d4d': {'status': 'Active', 'diskfree': '315304968192', 'alerts': [], 'disktotal': '321963163648'}, '41263435-b36f-49dc-960a-8758a3744546': {'status': 'Active', 'diskfree': '632269963264', 'alerts': [], 'disktotal': '643926327296'}, 'ed1c88c8-54b5-4616-aa00-26096173feaf': {'status': 'Active', 'diskfree': '377466388480', 'alerts': [], 'disktotal': '403472121856'}, 'b8fde061-56bd-4e42-8d50-7dbb9bd9c5e1': {'status': 'Active', 'diskfree': '315304968192', 'alerts': [], 'disktotal': '321963163648'}, '79b1039e-34a7-4cb4-aedf-271a304468f5': {'status': 'Active', 'diskfree': '624710385664', 'alerts': [], 'disktotal': '643926327296'}, '5743191c-5960-48cb-b87b-3f40645149ba': {'status': 'Active', 'diskfree': '624710385664', 'alerts': [], 'disktotal': '643926327296'}}}
>Thread-194243::DEBUG::2011-10-11 14:01:01,808::task::588::TaskManager.Task::(_updateState) Task=`b19df36e-fa2b-4eac-b7a5-ec3f273bc1d8`::moving from state preparing -> state finished
>Thread-194243::DEBUG::2011-10-11 14:01:01,808::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.22fb1d8d-7329-4573-9827-ca5d49cab451': < ResourceRef 'Storage.22fb1d8d-7329-4573-9827-ca5d49cab451', isValid: 'True' obj: 'None'>}
>Thread-194243::DEBUG::2011-10-11 14:01:01,808::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-194243::DEBUG::2011-10-11 14:01:01,809::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.22fb1d8d-7329-4573-9827-ca5d49cab451'
>Thread-194243::DEBUG::2011-10-11 14:01:01,809::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.22fb1d8d-7329-4573-9827-ca5d49cab451' (0 active users)
>Thread-194243::DEBUG::2011-10-11 14:01:01,810::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.22fb1d8d-7329-4573-9827-ca5d49cab451' is free, finding out if anyone is waiting for it.
>Thread-194243::DEBUG::2011-10-11 14:01:01,810::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.22fb1d8d-7329-4573-9827-ca5d49cab451', Clearing records.
>Thread-194243::DEBUG::2011-10-11 14:01:01,811::task::978::TaskManager.Task::(_decref) Task=`b19df36e-fa2b-4eac-b7a5-ec3f273bc1d8`::ref 0 aborting False
>Thread-22::ERROR::2011-10-11 14:01:04,159::utils::399::vm.Vm::(collect) vmId=`4f1d9317-46ab-4eb3-8f90-e0b258513d19`::Stats function failed: <AdvancedStatsFunction _sampleNet at 0x29b0a78>
>Traceback (most recent call last):
>  File "/usr/lib64/python2.6/site-packages/vdsm/utils.py", line 395, in collect
>    statsFunction()
>  File "/usr/lib64/python2.6/site-packages/vdsm/utils.py", line 272, in __call__
>    retValue = self._function(*args, **kwargs)
>  File "/usr/share/vdsm/libvirtvm.py", line 179, in _sampleNet
>    netSamples[nic.name] = self._vm._dom.interfaceStats(nic.name)
>  File "/usr/share/vdsm/libvirtvm.py", line 491, in f
>    ret = attr(*args, **kwargs)
>  File "/usr/lib64/python2.6/site-packages/vdsm/libvirtconnection.py", line 82, in wrapper
>    ret = f(*args, **kwargs)
>  File "/usr/lib64/python2.6/site-packages/libvirt.py", line 1762, in interfaceStats
>    if ret is None: raise libvirtError ('virDomainInterfaceStats() failed', dom=self)
>libvirtError: internal error client socket is closed
>Thread-21::ERROR::2011-10-11 14:01:04,171::utils::399::vm.Vm::(collect) vmId=`816ac538-6aa6-44af-8ad0-7c35d149d6c0`::Stats function failed: <AdvancedStatsFunction _sampleNet at 0x29b0a78>
>Traceback (most recent call last):
>  File "/usr/lib64/python2.6/site-packages/vdsm/utils.py", line 395, in collect
>    statsFunction()
>  File "/usr/lib64/python2.6/site-packages/vdsm/utils.py", line 272, in __call__
>    retValue = self._function(*args, **kwargs)
>  File "/usr/share/vdsm/libvirtvm.py", line 179, in _sampleNet
>    netSamples[nic.name] = self._vm._dom.interfaceStats(nic.name)
>  File "/usr/share/vdsm/libvirtvm.py", line 491, in f
>    ret = attr(*args, **kwargs)
>  File "/usr/lib64/python2.6/site-packages/vdsm/libvirtconnection.py", line 82, in wrapper
>    ret = f(*args, **kwargs)
>  File "/usr/lib64/python2.6/site-packages/libvirt.py", line 1762, in interfaceStats
>    if ret is None: raise libvirtError ('virDomainInterfaceStats() failed', dom=self)
>libvirtError: internal error client socket is closed
>Thread-16::DEBUG::2011-10-11 14:01:04,533::task::588::TaskManager.Task::(_updateState) Task=`a220aad7-9787-4278-9924-b865c3fcb553`::moving from state init -> state preparing
>Thread-16::INFO::2011-10-11 14:01:04,533::logUtils::37::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='79b1039e-34a7-4cb4-aedf-271a304468f5', spUUID='22fb1d8d-7329-4573-9827-ca5d49cab451', imgUUID='95935815-35ee-47f1-8d9b-6cff983ba8d6', volUUID='be03aa75-c5a0-438d-911b-64c84704fa38', options=None)
>Thread-16::DEBUG::2011-10-11 14:01:04,534::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.79b1039e-34a7-4cb4-aedf-271a304468f5`ReqID=`df0f593c-e571-45e0-a15a-93b145a62723`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-16::DEBUG::2011-10-11 14:01:04,534::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.79b1039e-34a7-4cb4-aedf-271a304468f5' for lock type 'shared'
>Thread-16::DEBUG::2011-10-11 14:01:04,535::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.79b1039e-34a7-4cb4-aedf-271a304468f5' is free. Now locking as 'shared' (1 active user)
>Thread-16::DEBUG::2011-10-11 14:01:04,535::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.79b1039e-34a7-4cb4-aedf-271a304468f5`ReqID=`df0f593c-e571-45e0-a15a-93b145a62723`::Granted request
>Thread-16::DEBUG::2011-10-11 14:01:04,536::task::817::TaskManager.Task::(resourceAcquired) Task=`a220aad7-9787-4278-9924-b865c3fcb553`::_resourcesAcquired: Storage.79b1039e-34a7-4cb4-aedf-271a304468f5 (shared)
>Thread-16::DEBUG::2011-10-11 14:01:04,536::task::978::TaskManager.Task::(_decref) Task=`a220aad7-9787-4278-9924-b865c3fcb553`::ref 1 aborting False
>Thread-16::DEBUG::2011-10-11 14:01:04,542::fileVolume::552::Storage.Volume::(validateVolumePath) validate path for be03aa75-c5a0-438d-911b-64c84704fa38
>Thread-16::DEBUG::2011-10-11 14:01:04,547::fileVolume::552::Storage.Volume::(validateVolumePath) validate path for be03aa75-c5a0-438d-911b-64c84704fa38
>Thread-16::INFO::2011-10-11 14:01:04,550::logUtils::39::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '1782120448', 'apparentsize': '16106127360'}
>Thread-16::DEBUG::2011-10-11 14:01:04,550::task::1172::TaskManager.Task::(prepare) Task=`a220aad7-9787-4278-9924-b865c3fcb553`::finished: {'truesize': '1782120448', 'apparentsize': '16106127360'}
>Thread-16::DEBUG::2011-10-11 14:01:04,550::task::588::TaskManager.Task::(_updateState) Task=`a220aad7-9787-4278-9924-b865c3fcb553`::moving from state preparing -> state finished
>Thread-16::DEBUG::2011-10-11 14:01:04,551::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.79b1039e-34a7-4cb4-aedf-271a304468f5': < ResourceRef 'Storage.79b1039e-34a7-4cb4-aedf-271a304468f5', isValid: 'True' obj: 'None'>}
>Thread-16::DEBUG::2011-10-11 14:01:04,551::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-16::DEBUG::2011-10-11 14:01:04,552::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.79b1039e-34a7-4cb4-aedf-271a304468f5'
>Thread-16::DEBUG::2011-10-11 14:01:04,552::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.79b1039e-34a7-4cb4-aedf-271a304468f5' (0 active users)
>Thread-16::DEBUG::2011-10-11 14:01:04,553::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.79b1039e-34a7-4cb4-aedf-271a304468f5' is free, finding out if anyone is waiting for it.
>Thread-16::DEBUG::2011-10-11 14:01:04,553::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.79b1039e-34a7-4cb4-aedf-271a304468f5', Clearing records.
>Thread-16::DEBUG::2011-10-11 14:01:04,554::task::978::TaskManager.Task::(_decref) Task=`a220aad7-9787-4278-9924-b865c3fcb553`::ref 0 aborting False
>Thread-16::ERROR::2011-10-11 14:01:04,554::utils::399::vm.Vm::(collect) vmId=`d0f58ab3-7202-45a0-a9b9-6088e00a65f1`::Stats function failed: <AdvancedStatsFunction _sampleCpu at 0x29b0998>
>Traceback (most recent call last):
>  File "/usr/lib64/python2.6/site-packages/vdsm/utils.py", line 395, in collect
>    statsFunction()
>  File "/usr/lib64/python2.6/site-packages/vdsm/utils.py", line 272, in __call__
>    retValue = self._function(*args, **kwargs)
>  File "/usr/share/vdsm/libvirtvm.py", line 109, in _sampleCpu
>    state, maxMem, memory, nrVirtCpu, cpuTime = self._vm._dom.info()
>  File "/usr/share/vdsm/libvirtvm.py", line 491, in f
>    ret = attr(*args, **kwargs)
>  File "/usr/lib64/python2.6/site-packages/vdsm/libvirtconnection.py", line 82, in wrapper
>    ret = f(*args, **kwargs)
>  File "/usr/lib64/python2.6/site-packages/libvirt.py", line 1750, in info
>    if ret is None: raise libvirtError ('virDomainGetInfo() failed', dom=self)
>libvirtError: internal error client socket is closed
>Thread-16::ERROR::2011-10-11 14:01:04,555::utils::399::vm.Vm::(collect) vmId=`d0f58ab3-7202-45a0-a9b9-6088e00a65f1`::Stats function failed: <AdvancedStatsFunction _sampleDisk at 0x29b0a08>
>Traceback (most recent call last):
>  File "/usr/lib64/python2.6/site-packages/vdsm/utils.py", line 395, in collect
>    statsFunction()
>  File "/usr/lib64/python2.6/site-packages/vdsm/utils.py", line 272, in __call__
>    retValue = self._function(*args, **kwargs)
>  File "/usr/share/vdsm/libvirtvm.py", line 119, in _sampleDisk
>    diskSamples[vmDrive.name] = self._vm._dom.blockStats(vmDrive.name)
>  File "/usr/share/vdsm/libvirtvm.py", line 491, in f
>    ret = attr(*args, **kwargs)
>  File "/usr/lib64/python2.6/site-packages/vdsm/libvirtconnection.py", line 82, in wrapper
>    ret = f(*args, **kwargs)
>  File "/usr/lib64/python2.6/site-packages/libvirt.py", line 1715, in blockStats
>    if ret is None: raise libvirtError ('virDomainBlockStats() failed', dom=self)
>libvirtError: internal error client socket is closed
>Thread-16::ERROR::2011-10-11 14:01:04,556::utils::399::vm.Vm::(collect) vmId=`d0f58ab3-7202-45a0-a9b9-6088e00a65f1`::Stats function failed: <AdvancedStatsFunction _sampleDiskLatency at 0x29b4270>
>Traceback (most recent call last):
>  File "/usr/lib64/python2.6/site-packages/vdsm/utils.py", line 395, in collect
>    statsFunction()
>  File "/usr/lib64/python2.6/site-packages/vdsm/utils.py", line 272, in __call__
>    retValue = self._function(*args, **kwargs)
>  File "/usr/share/vdsm/libvirtvm.py", line 160, in _sampleDiskLatency
>    libvirt_qemu.VIR_DOMAIN_QEMU_MONITOR_COMMAND_DEFAULT)
>  File "/usr/lib64/python2.6/site-packages/libvirt_qemu.py", line 37, in qemuMonitorCommand
>    if ret is None: raise libvirt.libvirtError('virDomainQemuMonitorCommand() failed')
>libvirtError: internal error client socket is closed
>Thread-16::ERROR::2011-10-11 14:01:04,557::utils::399::vm.Vm::(collect) vmId=`d0f58ab3-7202-45a0-a9b9-6088e00a65f1`::Stats function failed: <AdvancedStatsFunction _sampleNet at 0x29b0a78>
>Traceback (most recent call last):
>  File "/usr/lib64/python2.6/site-packages/vdsm/utils.py", line 395, in collect
>    statsFunction()
>  File "/usr/lib64/python2.6/site-packages/vdsm/utils.py", line 272, in __call__
>    retValue = self._function(*args, **kwargs)
>  File "/usr/share/vdsm/libvirtvm.py", line 179, in _sampleNet
>    netSamples[nic.name] = self._vm._dom.interfaceStats(nic.name)
>  File "/usr/share/vdsm/libvirtvm.py", line 491, in f
>    ret = attr(*args, **kwargs)
>  File "/usr/lib64/python2.6/site-packages/vdsm/libvirtconnection.py", line 82, in wrapper
>    ret = f(*args, **kwargs)
>  File "/usr/lib64/python2.6/site-packages/libvirt.py", line 1762, in interfaceStats
>    if ret is None: raise libvirtError ('virDomainInterfaceStats() failed', dom=self)
>libvirtError: internal error client socket is closed
>Thread-28::ERROR::2011-10-11 14:01:04,675::utils::399::vm.Vm::(collect) vmId=`6de348d7-bf46-4881-ab23-e5d41d13f42e`::Stats function failed: <AdvancedStatsFunction _sampleNet at 0x29b0a78>
>Traceback (most recent call last):
>  File "/usr/lib64/python2.6/site-packages/vdsm/utils.py", line 395, in collect
>    statsFunction()
>  File "/usr/lib64/python2.6/site-packages/vdsm/utils.py", line 272, in __call__
>    retValue = self._function(*args, **kwargs)
>  File "/usr/share/vdsm/libvirtvm.py", line 179, in _sampleNet
>    netSamples[nic.name] = self._vm._dom.interfaceStats(nic.name)
>  File "/usr/share/vdsm/libvirtvm.py", line 491, in f
>    ret = attr(*args, **kwargs)
>  File "/usr/lib64/python2.6/site-packages/vdsm/libvirtconnection.py", line 82, in wrapper
>    ret = f(*args, **kwargs)
>  File "/usr/lib64/python2.6/site-packages/libvirt.py", line 1762, in interfaceStats
>    if ret is None: raise libvirtError ('virDomainInterfaceStats() failed', dom=self)
>libvirtError: internal error client socket is closed
>Thread-194245::DEBUG::2011-10-11 14:01:05,087::task::588::TaskManager.Task::(_updateState) Task=`020c8c74-1050-4d36-a715-a6c96fdd6175`::moving from state init -> state preparing
>Thread-194245::INFO::2011-10-11 14:01:05,087::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-194245::INFO::2011-10-11 14:01:05,087::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'523559dc-b966-4544-8618-620ca06c4d4d': {'delay': '0.00510621070862', 'lastCheck': 1318321856.9881761, 'code': 0, 'valid': True}, '41263435-b36f-49dc-960a-8758a3744546': {'delay': '0.00515508651733', 'lastCheck': 1318321861.0826221, 'code': 0, 'valid': True}, 'ed1c88c8-54b5-4616-aa00-26096173feaf': {'delay': '0.00170707702637', 'lastCheck': 1318321858.609288, 'code': 0, 'valid': True}, 'b8fde061-56bd-4e42-8d50-7dbb9bd9c5e1': {'delay': '0.003986120224', 'lastCheck': 1318321864.1200011, 'code': 0, 'valid': True}, '79b1039e-34a7-4cb4-aedf-271a304468f5': {'delay': '0.00527310371399', 'lastCheck': 1318321861.27299, 'code': 0, 'valid': True}, '5743191c-5960-48cb-b87b-3f40645149ba': {'delay': '0.0053231716156', 'lastCheck': 1318321858.2998531, 'code': 0, 'valid': True}}
>Thread-194245::DEBUG::2011-10-11 14:01:05,088::task::1172::TaskManager.Task::(prepare) Task=`020c8c74-1050-4d36-a715-a6c96fdd6175`::finished: {'523559dc-b966-4544-8618-620ca06c4d4d': {'delay': '0.00510621070862', 'lastCheck': 1318321856.9881761, 'code': 0, 'valid': True}, '41263435-b36f-49dc-960a-8758a3744546': {'delay': '0.00515508651733', 'lastCheck': 1318321861.0826221, 'code': 0, 'valid': True}, 'ed1c88c8-54b5-4616-aa00-26096173feaf': {'delay': '0.00170707702637', 'lastCheck': 1318321858.609288, 'code': 0, 'valid': True}, 'b8fde061-56bd-4e42-8d50-7dbb9bd9c5e1': {'delay': '0.003986120224', 'lastCheck': 1318321864.1200011, 'code': 0, 'valid': True}, '79b1039e-34a7-4cb4-aedf-271a304468f5': {'delay': '0.00527310371399', 'lastCheck': 1318321861.27299, 'code': 0, 'valid': True}, '5743191c-5960-48cb-b87b-3f40645149ba': {'delay': '0.0053231716156', 'lastCheck': 1318321858.2998531, 'code': 0, 'valid': True}}
>Thread-194245::DEBUG::2011-10-11 14:01:05,088::task::588::TaskManager.Task::(_updateState) Task=`020c8c74-1050-4d36-a715-a6c96fdd6175`::moving from state preparing -> state finished
>Thread-194245::DEBUG::2011-10-11 14:01:05,088::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-194245::DEBUG::2011-10-11 14:01:05,088::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-194245::DEBUG::2011-10-11 14:01:05,089::task::978::TaskManager.Task::(_decref) Task=`020c8c74-1050-4d36-a715-a6c96fdd6175`::ref 0 aborting False
>Thread-194246::DEBUG::2011-10-11 14:01:05,119::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`6de348d7-bf46-4881-ab23-e5d41d13f42e`::Disk hdc stats not available
>Thread-194246::DEBUG::2011-10-11 14:01:05,120::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`d0f58ab3-7202-45a0-a9b9-6088e00a65f1`::Disk hdc stats not available
>Thread-194246::DEBUG::2011-10-11 14:01:05,120::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`4f1d9317-46ab-4eb3-8f90-e0b258513d19`::Disk hdc stats not available
>Thread-194246::DEBUG::2011-10-11 14:01:05,121::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`816ac538-6aa6-44af-8ad0-7c35d149d6c0`::Disk hdc stats not available
>Thread-194246::DEBUG::2011-10-11 14:01:05,122::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`d9e0053c-0e7b-442f-abb5-733f31da97b4`::Disk hdc stats not available
>Thread-25::ERROR::2011-10-11 14:01:05,438::utils::399::vm.Vm::(collect) vmId=`d9e0053c-0e7b-442f-abb5-733f31da97b4`::Stats function failed: <AdvancedStatsFunction _sampleNet at 0x29b0a78>
>Traceback (most recent call last):
>  File "/usr/lib64/python2.6/site-packages/vdsm/utils.py", line 395, in collect
>    statsFunction()
>  File "/usr/lib64/python2.6/site-packages/vdsm/utils.py", line 272, in __call__
>    retValue = self._function(*args, **kwargs)
>  File "/usr/share/vdsm/libvirtvm.py", line 179, in _sampleNet
>    netSamples[nic.name] = self._vm._dom.interfaceStats(nic.name)
>  File "/usr/share/vdsm/libvirtvm.py", line 491, in f
>    ret = attr(*args, **kwargs)
>  File "/usr/lib64/python2.6/site-packages/vdsm/libvirtconnection.py", line 82, in wrapper
>    ret = f(*args, **kwargs)
>  File "/usr/lib64/python2.6/site-packages/libvirt.py", line 1762, in interfaceStats
>    if ret is None: raise libvirtError ('virDomainInterfaceStats() failed', dom=self)
>libvirtError: internal error client socket is closed
>VM Channels Listener::DEBUG::2011-10-11 14:01:05,735::vmChannels::60::vds::(_handle_timeouts) Timeout on fileno 24.
>VM Channels Listener::DEBUG::2011-10-11 14:01:05,735::vmChannels::60::vds::(_handle_timeouts) Timeout on fileno 26.
>VM Channels Listener::DEBUG::2011-10-11 14:01:05,735::vmChannels::60::vds::(_handle_timeouts) Timeout on fileno 28.
>VM Channels Listener::DEBUG::2011-10-11 14:01:05,735::vmChannels::60::vds::(_handle_timeouts) Timeout on fileno 23.
>Thread-22::ERROR::2011-10-11 14:01:09,163::utils::399::vm.Vm::(collect) vmId=`4f1d9317-46ab-4eb3-8f90-e0b258513d19`::Stats function failed: <AdvancedStatsFunction _sampleNet at 0x29b0a78>
>Traceback (most recent call last):
>  File "/usr/lib64/python2.6/site-packages/vdsm/utils.py", line 395, in collect
>    statsFunction()
>  File "/usr/lib64/python2.6/site-packages/vdsm/utils.py", line 272, in __call__
>    retValue = self._function(*args, **kwargs)
>  File "/usr/share/vdsm/libvirtvm.py", line 179, in _sampleNet
>    netSamples[nic.name] = self._vm._dom.interfaceStats(nic.name)
>  File "/usr/share/vdsm/libvirtvm.py", line 491, in f
>    ret = attr(*args, **kwargs)
>  File "/usr/lib64/python2.6/site-packages/vdsm/libvirtconnection.py", line 82, in wrapper
>    ret = f(*args, **kwargs)
>  File "/usr/lib64/python2.6/site-packages/libvirt.py", line 1762, in interfaceStats
>    if ret is None: raise libvirtError ('virDomainInterfaceStats() failed', dom=self)
>libvirtError: internal error client socket is closed
>Thread-21::ERROR::2011-10-11 14:01:09,172::utils::399::vm.Vm::(collect) vmId=`816ac538-6aa6-44af-8ad0-7c35d149d6c0`::Stats function failed: <AdvancedStatsFunction _sampleNet at 0x29b0a78>
>Traceback (most recent call last):
>  File "/usr/lib64/python2.6/site-packages/vdsm/utils.py", line 395, in collect
>    statsFunction()
>  File "/usr/lib64/python2.6/site-packages/vdsm/utils.py", line 272, in __call__
>    retValue = self._function(*args, **kwargs)
>  File "/usr/share/vdsm/libvirtvm.py", line 179, in _sampleNet
>    netSamples[nic.name] = self._vm._dom.interfaceStats(nic.name)
>  File "/usr/share/vdsm/libvirtvm.py", line 491, in f
>    ret = attr(*args, **kwargs)
>  File "/usr/lib64/python2.6/site-packages/vdsm/libvirtconnection.py", line 82, in wrapper
>    ret = f(*args, **kwargs)
>  File "/usr/lib64/python2.6/site-packages/libvirt.py", line 1762, in interfaceStats
>    if ret is None: raise libvirtError ('virDomainInterfaceStats() failed', dom=self)
>libvirtError: internal error client socket is closed
>Thread-16::ERROR::2011-10-11 14:01:09,558::utils::399::vm.Vm::(collect) vmId=`d0f58ab3-7202-45a0-a9b9-6088e00a65f1`::Stats function failed: <AdvancedStatsFunction _sampleNet at 0x29b0a78>
>Traceback (most recent call last):
>  File "/usr/lib64/python2.6/site-packages/vdsm/utils.py", line 395, in collect
>    statsFunction()
>  File "/usr/lib64/python2.6/site-packages/vdsm/utils.py", line 272, in __call__
>    retValue = self._function(*args, **kwargs)
>  File "/usr/share/vdsm/libvirtvm.py", line 179, in _sampleNet
>    netSamples[nic.name] = self._vm._dom.interfaceStats(nic.name)
>  File "/usr/share/vdsm/libvirtvm.py", line 491, in f
>    ret = attr(*args, **kwargs)
>  File "/usr/lib64/python2.6/site-packages/vdsm/libvirtconnection.py", line 82, in wrapper
>    ret = f(*args, **kwargs)
>  File "/usr/lib64/python2.6/site-packages/libvirt.py", line 1762, in interfaceStats
>    if ret is None: raise libvirtError ('virDomainInterfaceStats() failed', dom=self)
>libvirtError: internal error client socket is closed
>Thread-28::DEBUG::2011-10-11 14:01:09,676::task::588::TaskManager.Task::(_updateState) Task=`aa4fb450-2421-4cae-8c9e-176bf4790d4f`::moving from state init -> state preparing
>Thread-28::INFO::2011-10-11 14:01:09,677::logUtils::37::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='41263435-b36f-49dc-960a-8758a3744546', spUUID='22fb1d8d-7329-4573-9827-ca5d49cab451', imgUUID='87c4b188-66d9-4b23-b8c8-74f313eaaa12', volUUID='4b2563f1-dc21-4327-838e-a95fb8f19e2f', options=None)
>Thread-28::DEBUG::2011-10-11 14:01:09,678::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.41263435-b36f-49dc-960a-8758a3744546`ReqID=`85c2c046-a72f-4b77-bc5f-e4038381afc6`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-28::DEBUG::2011-10-11 14:01:09,678::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.41263435-b36f-49dc-960a-8758a3744546' for lock type 'shared'
>Thread-28::DEBUG::2011-10-11 14:01:09,678::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.41263435-b36f-49dc-960a-8758a3744546' is free. Now locking as 'shared' (1 active user)
>Thread-28::DEBUG::2011-10-11 14:01:09,679::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.41263435-b36f-49dc-960a-8758a3744546`ReqID=`85c2c046-a72f-4b77-bc5f-e4038381afc6`::Granted request
>Thread-28::DEBUG::2011-10-11 14:01:09,680::task::817::TaskManager.Task::(resourceAcquired) Task=`aa4fb450-2421-4cae-8c9e-176bf4790d4f`::_resourcesAcquired: Storage.41263435-b36f-49dc-960a-8758a3744546 (shared)
>Thread-28::DEBUG::2011-10-11 14:01:09,680::task::978::TaskManager.Task::(_decref) Task=`aa4fb450-2421-4cae-8c9e-176bf4790d4f`::ref 1 aborting False
>Thread-28::DEBUG::2011-10-11 14:01:09,685::fileVolume::552::Storage.Volume::(validateVolumePath) validate path for 4b2563f1-dc21-4327-838e-a95fb8f19e2f
>Thread-28::DEBUG::2011-10-11 14:01:09,690::fileVolume::552::Storage.Volume::(validateVolumePath) validate path for 4b2563f1-dc21-4327-838e-a95fb8f19e2f
>Thread-28::INFO::2011-10-11 14:01:09,692::logUtils::39::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '1658667008', 'apparentsize': '16106127360'}
>Thread-28::DEBUG::2011-10-11 14:01:09,693::task::1172::TaskManager.Task::(prepare) Task=`aa4fb450-2421-4cae-8c9e-176bf4790d4f`::finished: {'truesize': '1658667008', 'apparentsize': '16106127360'}
>Thread-28::DEBUG::2011-10-11 14:01:09,693::task::588::TaskManager.Task::(_updateState) Task=`aa4fb450-2421-4cae-8c9e-176bf4790d4f`::moving from state preparing -> state finished
>Thread-28::DEBUG::2011-10-11 14:01:09,694::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.41263435-b36f-49dc-960a-8758a3744546': < ResourceRef 'Storage.41263435-b36f-49dc-960a-8758a3744546', isValid: 'True' obj: 'None'>}
>Thread-28::DEBUG::2011-10-11 14:01:09,694::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-28::DEBUG::2011-10-11 14:01:09,695::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.41263435-b36f-49dc-960a-8758a3744546'
>Thread-28::DEBUG::2011-10-11 14:01:09,695::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.41263435-b36f-49dc-960a-8758a3744546' (0 active users)
>Thread-28::DEBUG::2011-10-11 14:01:09,695::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.41263435-b36f-49dc-960a-8758a3744546' is free, finding out if anyone is waiting for it.
>Thread-28::DEBUG::2011-10-11 14:01:09,696::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.41263435-b36f-49dc-960a-8758a3744546', Clearing records.
>Thread-28::DEBUG::2011-10-11 14:01:09,696::task::978::TaskManager.Task::(_decref) Task=`aa4fb450-2421-4cae-8c9e-176bf4790d4f`::ref 0 aborting False
>Thread-28::ERROR::2011-10-11 14:01:09,697::utils::399::vm.Vm::(collect) vmId=`6de348d7-bf46-4881-ab23-e5d41d13f42e`::Stats function failed: <AdvancedStatsFunction _sampleCpu at 0x29b0998>
>Traceback (most recent call last):
>  File "/usr/lib64/python2.6/site-packages/vdsm/utils.py", line 395, in collect
>    statsFunction()
>  File "/usr/lib64/python2.6/site-packages/vdsm/utils.py", line 272, in __call__
>    retValue = self._function(*args, **kwargs)
>  File "/usr/share/vdsm/libvirtvm.py", line 109, in _sampleCpu
>    state, maxMem, memory, nrVirtCpu, cpuTime = self._vm._dom.info()
>  File "/usr/share/vdsm/libvirtvm.py", line 491, in f
>    ret = attr(*args, **kwargs)
>  File "/usr/lib64/python2.6/site-packages/vdsm/libvirtconnection.py", line 82, in wrapper
>    ret = f(*args, **kwargs)
>  File "/usr/lib64/python2.6/site-packages/libvirt.py", line 1750, in info
>    if ret is None: raise libvirtError ('virDomainGetInfo() failed', dom=self)
>libvirtError: internal error client socket is closed
>Thread-28::ERROR::2011-10-11 14:01:09,698::utils::399::vm.Vm::(collect) vmId=`6de348d7-bf46-4881-ab23-e5d41d13f42e`::Stats function failed: <AdvancedStatsFunction _sampleDisk at 0x29b0a08>
>Traceback (most recent call last):
>  File "/usr/lib64/python2.6/site-packages/vdsm/utils.py", line 395, in collect
>    statsFunction()
>  File "/usr/lib64/python2.6/site-packages/vdsm/utils.py", line 272, in __call__
>    retValue = self._function(*args, **kwargs)
>  File "/usr/share/vdsm/libvirtvm.py", line 119, in _sampleDisk
>    diskSamples[vmDrive.name] = self._vm._dom.blockStats(vmDrive.name)
>  File "/usr/share/vdsm/libvirtvm.py", line 491, in f
>    ret = attr(*args, **kwargs)
>  File "/usr/lib64/python2.6/site-packages/vdsm/libvirtconnection.py", line 82, in wrapper
>    ret = f(*args, **kwargs)
>  File "/usr/lib64/python2.6/site-packages/libvirt.py", line 1715, in blockStats
>    if ret is None: raise libvirtError ('virDomainBlockStats() failed', dom=self)
>libvirtError: internal error client socket is closed
>Thread-28::ERROR::2011-10-11 14:01:09,699::utils::399::vm.Vm::(collect) vmId=`6de348d7-bf46-4881-ab23-e5d41d13f42e`::Stats function failed: <AdvancedStatsFunction _sampleDiskLatency at 0x29b4270>
>Traceback (most recent call last):
>  File "/usr/lib64/python2.6/site-packages/vdsm/utils.py", line 395, in collect
>    statsFunction()
>  File "/usr/lib64/python2.6/site-packages/vdsm/utils.py", line 272, in __call__
>    retValue = self._function(*args, **kwargs)
>  File "/usr/share/vdsm/libvirtvm.py", line 160, in _sampleDiskLatency
>    libvirt_qemu.VIR_DOMAIN_QEMU_MONITOR_COMMAND_DEFAULT)
>  File "/usr/lib64/python2.6/site-packages/libvirt_qemu.py", line 37, in qemuMonitorCommand
>    if ret is None: raise libvirt.libvirtError('virDomainQemuMonitorCommand() failed')
>libvirtError: internal error client socket is closed
>Thread-28::ERROR::2011-10-11 14:01:09,699::utils::399::vm.Vm::(collect) vmId=`6de348d7-bf46-4881-ab23-e5d41d13f42e`::Stats function failed: <AdvancedStatsFunction _sampleNet at 0x29b0a78>
>Traceback (most recent call last):
>  File "/usr/lib64/python2.6/site-packages/vdsm/utils.py", line 395, in collect
>    statsFunction()
>  File "/usr/lib64/python2.6/site-packages/vdsm/utils.py", line 272, in __call__
>    retValue = self._function(*args, **kwargs)
>  File "/usr/share/vdsm/libvirtvm.py", line 179, in _sampleNet
>    netSamples[nic.name] = self._vm._dom.interfaceStats(nic.name)
>  File "/usr/share/vdsm/libvirtvm.py", line 491, in f
>    ret = attr(*args, **kwargs)
>  File "/usr/lib64/python2.6/site-packages/vdsm/libvirtconnection.py", line 82, in wrapper
>    ret = f(*args, **kwargs)
>  File "/usr/lib64/python2.6/site-packages/libvirt.py", line 1762, in interfaceStats
>    if ret is None: raise libvirtError ('virDomainInterfaceStats() failed', dom=self)
>libvirtError: internal error client socket is closed
>Thread-25::DEBUG::2011-10-11 14:01:10,439::task::588::TaskManager.Task::(_updateState) Task=`9a32b557-67e1-42ad-8a21-1275884dd72b`::moving from state init -> state preparing
>Thread-25::INFO::2011-10-11 14:01:10,440::logUtils::37::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='5743191c-5960-48cb-b87b-3f40645149ba', spUUID='22fb1d8d-7329-4573-9827-ca5d49cab451', imgUUID='c5f5115d-28f3-4bd3-b950-a05b48236411', volUUID='4d095c72-9f2e-40b5-98ba-0ee5b7b799be', options=None)
>Thread-25::DEBUG::2011-10-11 14:01:10,440::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.5743191c-5960-48cb-b87b-3f40645149ba`ReqID=`82ffd011-4103-46bd-a4c6-7ebf4e2296b0`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-25::DEBUG::2011-10-11 14:01:10,441::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.5743191c-5960-48cb-b87b-3f40645149ba' for lock type 'shared'
>Thread-25::DEBUG::2011-10-11 14:01:10,441::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.5743191c-5960-48cb-b87b-3f40645149ba' is free. Now locking as 'shared' (1 active user)
>Thread-25::DEBUG::2011-10-11 14:01:10,442::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.5743191c-5960-48cb-b87b-3f40645149ba`ReqID=`82ffd011-4103-46bd-a4c6-7ebf4e2296b0`::Granted request
>Thread-25::DEBUG::2011-10-11 14:01:10,443::task::817::TaskManager.Task::(resourceAcquired) Task=`9a32b557-67e1-42ad-8a21-1275884dd72b`::_resourcesAcquired: Storage.5743191c-5960-48cb-b87b-3f40645149ba (shared)
>Thread-25::DEBUG::2011-10-11 14:01:10,443::task::978::TaskManager.Task::(_decref) Task=`9a32b557-67e1-42ad-8a21-1275884dd72b`::ref 1 aborting False
>Thread-25::DEBUG::2011-10-11 14:01:10,449::fileVolume::552::Storage.Volume::(validateVolumePath) validate path for 4d095c72-9f2e-40b5-98ba-0ee5b7b799be
>Thread-25::DEBUG::2011-10-11 14:01:10,454::fileVolume::552::Storage.Volume::(validateVolumePath) validate path for 4d095c72-9f2e-40b5-98ba-0ee5b7b799be
>Thread-25::INFO::2011-10-11 14:01:10,456::logUtils::39::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '1579876352', 'apparentsize': '16106127360'}
>Thread-25::DEBUG::2011-10-11 14:01:10,457::task::1172::TaskManager.Task::(prepare) Task=`9a32b557-67e1-42ad-8a21-1275884dd72b`::finished: {'truesize': '1579876352', 'apparentsize': '16106127360'}
>Thread-25::DEBUG::2011-10-11 14:01:10,457::task::588::TaskManager.Task::(_updateState) Task=`9a32b557-67e1-42ad-8a21-1275884dd72b`::moving from state preparing -> state finished
>Thread-25::DEBUG::2011-10-11 14:01:10,458::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.5743191c-5960-48cb-b87b-3f40645149ba': < ResourceRef 'Storage.5743191c-5960-48cb-b87b-3f40645149ba', isValid: 'True' obj: 'None'>}
>Thread-25::DEBUG::2011-10-11 14:01:10,458::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-25::DEBUG::2011-10-11 14:01:10,459::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.5743191c-5960-48cb-b87b-3f40645149ba'
>Thread-25::DEBUG::2011-10-11 14:01:10,459::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.5743191c-5960-48cb-b87b-3f40645149ba' (0 active users)
>Thread-25::DEBUG::2011-10-11 14:01:10,460::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.5743191c-5960-48cb-b87b-3f40645149ba' is free, finding out if anyone is waiting for it.
>Thread-25::DEBUG::2011-10-11 14:01:10,460::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.5743191c-5960-48cb-b87b-3f40645149ba', Clearing records.
>Thread-25::DEBUG::2011-10-11 14:01:10,461::task::978::TaskManager.Task::(_decref) Task=`9a32b557-67e1-42ad-8a21-1275884dd72b`::ref 0 aborting False
>Thread-25::ERROR::2011-10-11 14:01:10,461::utils::399::vm.Vm::(collect) vmId=`d9e0053c-0e7b-442f-abb5-733f31da97b4`::Stats function failed: <AdvancedStatsFunction _sampleCpu at 0x29b0998>
>Traceback (most recent call last):
>  File "/usr/lib64/python2.6/site-packages/vdsm/utils.py", line 395, in collect
>    statsFunction()
>  File "/usr/lib64/python2.6/site-packages/vdsm/utils.py", line 272, in __call__
>    retValue = self._function(*args, **kwargs)
>  File "/usr/share/vdsm/libvirtvm.py", line 109, in _sampleCpu
>    state, maxMem, memory, nrVirtCpu, cpuTime = self._vm._dom.info()
>  File "/usr/share/vdsm/libvirtvm.py", line 491, in f
>    ret = attr(*args, **kwargs)
>  File "/usr/lib64/python2.6/site-packages/vdsm/libvirtconnection.py", line 82, in wrapper
>    ret = f(*args, **kwargs)
>  File "/usr/lib64/python2.6/site-packages/libvirt.py", line 1750, in info
>    if ret is None: raise libvirtError ('virDomainGetInfo() failed', dom=self)
>libvirtError: internal error client socket is closed
>Thread-25::ERROR::2011-10-11 14:01:10,462::utils::399::vm.Vm::(collect) vmId=`d9e0053c-0e7b-442f-abb5-733f31da97b4`::Stats function failed: <AdvancedStatsFunction _sampleDisk at 0x29b0a08>
>Traceback (most recent call last):
>  File "/usr/lib64/python2.6/site-packages/vdsm/utils.py", line 395, in collect
>    statsFunction()
>  File "/usr/lib64/python2.6/site-packages/vdsm/utils.py", line 272, in __call__
>    retValue = self._function(*args, **kwargs)
>  File "/usr/share/vdsm/libvirtvm.py", line 119, in _sampleDisk
>    diskSamples[vmDrive.name] = self._vm._dom.blockStats(vmDrive.name)
>  File "/usr/share/vdsm/libvirtvm.py", line 491, in f
>    ret = attr(*args, **kwargs)
>  File "/usr/lib64/python2.6/site-packages/vdsm/libvirtconnection.py", line 82, in wrapper
>    ret = f(*args, **kwargs)
>  File "/usr/lib64/python2.6/site-packages/libvirt.py", line 1715, in blockStats
>    if ret is None: raise libvirtError ('virDomainBlockStats() failed', dom=self)
>libvirtError: internal error client socket is closed
>Thread-25::ERROR::2011-10-11 14:01:10,463::utils::399::vm.Vm::(collect) vmId=`d9e0053c-0e7b-442f-abb5-733f31da97b4`::Stats function failed: <AdvancedStatsFunction _sampleDiskLatency at 0x29b4270>
>Traceback (most recent call last):
>  File "/usr/lib64/python2.6/site-packages/vdsm/utils.py", line 395, in collect
>    statsFunction()
>  File "/usr/lib64/python2.6/site-packages/vdsm/utils.py", line 272, in __call__
>    retValue = self._function(*args, **kwargs)
>  File "/usr/share/vdsm/libvirtvm.py", line 160, in _sampleDiskLatency
>    libvirt_qemu.VIR_DOMAIN_QEMU_MONITOR_COMMAND_DEFAULT)
>  File "/usr/lib64/python2.6/site-packages/libvirt_qemu.py", line 37, in qemuMonitorCommand
>    if ret is None: raise libvirt.libvirtError('virDomainQemuMonitorCommand() failed')
>libvirtError: internal error client socket is closed
>Thread-25::ERROR::2011-10-11 14:01:10,464::utils::399::vm.Vm::(collect) vmId=`d9e0053c-0e7b-442f-abb5-733f31da97b4`::Stats function failed: <AdvancedStatsFunction _sampleNet at 0x29b0a78>
>Traceback (most recent call last):
>  File "/usr/lib64/python2.6/site-packages/vdsm/utils.py", line 395, in collect
>    statsFunction()
>  File "/usr/lib64/python2.6/site-packages/vdsm/utils.py", line 272, in __call__
>    retValue = self._function(*args, **kwargs)
>  File "/usr/share/vdsm/libvirtvm.py", line 179, in _sampleNet
>    netSamples[nic.name] = self._vm._dom.interfaceStats(nic.name)
>  File "/usr/share/vdsm/libvirtvm.py", line 491, in f
>    ret = attr(*args, **kwargs)
>  File "/usr/lib64/python2.6/site-packages/vdsm/libvirtconnection.py", line 82, in wrapper
>    ret = f(*args, **kwargs)
>  File "/usr/lib64/python2.6/site-packages/libvirt.py", line 1762, in interfaceStats
>    if ret is None: raise libvirtError ('virDomainInterfaceStats() failed', dom=self)
>libvirtError: internal error client socket is closed
>Thread-194250::DEBUG::2011-10-11 14:01:11,876::BindingXMLRPC::164::vds::(wrapper) [10.70.34.52]
>Thread-194250::DEBUG::2011-10-11 14:01:11,877::task::588::TaskManager.Task::(_updateState) Task=`883caeb8-5598-4fe7-8d64-6db594dc6bfb`::moving from state init -> state preparing
>Thread-194250::INFO::2011-10-11 14:01:11,878::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='22fb1d8d-7329-4573-9827-ca5d49cab451', options=None)
>Thread-194250::INFO::2011-10-11 14:01:11,878::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 1}}
>Thread-194250::DEBUG::2011-10-11 14:01:11,879::task::1172::TaskManager.Task::(prepare) Task=`883caeb8-5598-4fe7-8d64-6db594dc6bfb`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 1}}
>Thread-194250::DEBUG::2011-10-11 14:01:11,879::task::588::TaskManager.Task::(_updateState) Task=`883caeb8-5598-4fe7-8d64-6db594dc6bfb`::moving from state preparing -> state finished
>Thread-194250::DEBUG::2011-10-11 14:01:11,880::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-194250::DEBUG::2011-10-11 14:01:11,880::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-194250::DEBUG::2011-10-11 14:01:11,880::task::978::TaskManager.Task::(_decref) Task=`883caeb8-5598-4fe7-8d64-6db594dc6bfb`::ref 0 aborting False
>Thread-194251::DEBUG::2011-10-11 14:01:11,906::BindingXMLRPC::164::vds::(wrapper) [10.70.34.52]
>Thread-194251::DEBUG::2011-10-11 14:01:11,907::task::588::TaskManager.Task::(_updateState) Task=`433aefdd-0efb-4cde-b05d-e3a1810a54ce`::moving from state init -> state preparing
>Thread-194251::INFO::2011-10-11 14:01:11,908::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='22fb1d8d-7329-4573-9827-ca5d49cab451', options=None)
>Thread-194251::DEBUG::2011-10-11 14:01:11,908::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.22fb1d8d-7329-4573-9827-ca5d49cab451`ReqID=`0debd82f-92b0-4f96-96d6-5cd1b3a917a3`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-194251::DEBUG::2011-10-11 14:01:11,909::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.22fb1d8d-7329-4573-9827-ca5d49cab451' for lock type 'shared'
>Thread-194251::DEBUG::2011-10-11 14:01:11,909::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.22fb1d8d-7329-4573-9827-ca5d49cab451' is free. Now locking as 'shared' (1 active user)
>Thread-194251::DEBUG::2011-10-11 14:01:11,910::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.22fb1d8d-7329-4573-9827-ca5d49cab451`ReqID=`0debd82f-92b0-4f96-96d6-5cd1b3a917a3`::Granted request
>Thread-194251::DEBUG::2011-10-11 14:01:11,910::task::817::TaskManager.Task::(resourceAcquired) Task=`433aefdd-0efb-4cde-b05d-e3a1810a54ce`::_resourcesAcquired: Storage.22fb1d8d-7329-4573-9827-ca5d49cab451 (shared)
>Thread-194251::DEBUG::2011-10-11 14:01:11,911::task::978::TaskManager.Task::(_decref) Task=`433aefdd-0efb-4cde-b05d-e3a1810a54ce`::ref 1 aborting False
>Thread-194251::INFO::2011-10-11 14:01:11,921::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': 'b8fde061-56bd-4e42-8d50-7dbb9bd9c5e1', 'name': 'RHS_RHEV_001', 'version': '3', 'domains': '523559dc-b966-4544-8618-620ca06c4d4d:Active,41263435-b36f-49dc-960a-8758a3744546:Active,ed1c88c8-54b5-4616-aa00-26096173feaf:Active,b8fde061-56bd-4e42-8d50-7dbb9bd9c5e1:Active,79b1039e-34a7-4cb4-aedf-271a304468f5:Active,5743191c-5960-48cb-b87b-3f40645149ba:Active', 'pool_status': 'connected', 'isoprefix': '/rhev/data-center/22fb1d8d-7329-4573-9827-ca5d49cab451/ed1c88c8-54b5-4616-aa00-26096173feaf/images/11111111-1111-1111-1111-111111111111', 'type': 'POSIXFS', 'master_ver': 2, 'lver': 1}, 'dominfo': {'523559dc-b966-4544-8618-620ca06c4d4d': {'status': 'Active', 'diskfree': '315304968192', 'alerts': [], 'disktotal': '321963163648'}, '41263435-b36f-49dc-960a-8758a3744546': {'status': 'Active', 'diskfree': '632269963264', 'alerts': [], 'disktotal': '643926327296'}, 'ed1c88c8-54b5-4616-aa00-26096173feaf': {'status': 'Active', 'diskfree': '377466388480', 'alerts': [], 'disktotal': '403472121856'}, 'b8fde061-56bd-4e42-8d50-7dbb9bd9c5e1': {'status': 'Active', 'diskfree': '315304968192', 'alerts': [], 'disktotal': '321963163648'}, '79b1039e-34a7-4cb4-aedf-271a304468f5': {'status': 'Active', 'diskfree': '624710385664', 'alerts': [], 'disktotal': '643926327296'}, '5743191c-5960-48cb-b87b-3f40645149ba': {'status': 'Active', 'diskfree': '624710385664', 'alerts': [], 'disktotal': '643926327296'}}}
>Thread-194251::DEBUG::2011-10-11 14:01:11,921::task::1172::TaskManager.Task::(prepare) Task=`433aefdd-0efb-4cde-b05d-e3a1810a54ce`::finished: {'info': {'spm_id': 1, 'master_uuid': 'b8fde061-56bd-4e42-8d50-7dbb9bd9c5e1', 'name': 'RHS_RHEV_001', 'version': '3', 'domains': '523559dc-b966-4544-8618-620ca06c4d4d:Active,41263435-b36f-49dc-960a-8758a3744546:Active,ed1c88c8-54b5-4616-aa00-26096173feaf:Active,b8fde061-56bd-4e42-8d50-7dbb9bd9c5e1:Active,79b1039e-34a7-4cb4-aedf-271a304468f5:Active,5743191c-5960-48cb-b87b-3f40645149ba:Active', 'pool_status': 'connected', 'isoprefix': '/rhev/data-center/22fb1d8d-7329-4573-9827-ca5d49cab451/ed1c88c8-54b5-4616-aa00-26096173feaf/images/11111111-1111-1111-1111-111111111111', 'type': 'POSIXFS', 'master_ver': 2, 'lver': 1}, 'dominfo': {'523559dc-b966-4544-8618-620ca06c4d4d': {'status': 'Active', 'diskfree': '315304968192', 'alerts': [], 'disktotal': '321963163648'}, '41263435-b36f-49dc-960a-8758a3744546': {'status': 'Active', 'diskfree': '632269963264', 'alerts': [], 'disktotal': '643926327296'}, 'ed1c88c8-54b5-4616-aa00-26096173feaf': {'status': 'Active', 'diskfree': '377466388480', 'alerts': [], 'disktotal': '403472121856'}, 'b8fde061-56bd-4e42-8d50-7dbb9bd9c5e1': {'status': 'Active', 'diskfree': '315304968192', 'alerts': [], 'disktotal': '321963163648'}, '79b1039e-34a7-4cb4-aedf-271a304468f5': {'status': 'Active', 'diskfree': '624710385664', 'alerts': [], 'disktotal': '643926327296'}, '5743191c-5960-48cb-b87b-3f40645149ba': {'status': 'Active', 'diskfree': '624710385664', 'alerts': [], 'disktotal': '643926327296'}}}
>Thread-194251::DEBUG::2011-10-11 14:01:11,922::task::588::TaskManager.Task::(_updateState) Task=`433aefdd-0efb-4cde-b05d-e3a1810a54ce`::moving from state preparing -> state finished
>Thread-194251::DEBUG::2011-10-11 14:01:11,922::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.22fb1d8d-7329-4573-9827-ca5d49cab451': < ResourceRef 'Storage.22fb1d8d-7329-4573-9827-ca5d49cab451', isValid: 'True' obj: 'None'>}
>Thread-194251::DEBUG::2011-10-11 14:01:11,923::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-194251::DEBUG::2011-10-11 14:01:11,923::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.22fb1d8d-7329-4573-9827-ca5d49cab451'
>Thread-194251::DEBUG::2011-10-11 14:01:11,924::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.22fb1d8d-7329-4573-9827-ca5d49cab451' (0 active users)
>Thread-194251::DEBUG::2011-10-11 14:01:11,924::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.22fb1d8d-7329-4573-9827-ca5d49cab451' is free, finding out if anyone is waiting for it.
>Thread-194251::DEBUG::2011-10-11 14:01:11,925::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.22fb1d8d-7329-4573-9827-ca5d49cab451', Clearing records.
>Thread-194251::DEBUG::2011-10-11 14:01:11,925::task::978::TaskManager.Task::(_decref) Task=`433aefdd-0efb-4cde-b05d-e3a1810a54ce`::ref 0 aborting False
>Thread-22::DEBUG::2011-10-11 14:01:14,164::task::588::TaskManager.Task::(_updateState) Task=`10df65c0-97a5-4dd5-86e9-5471fccb978a`::moving from state init -> state preparing
>Thread-22::INFO::2011-10-11 14:01:14,165::logUtils::37::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='b8fde061-56bd-4e42-8d50-7dbb9bd9c5e1', spUUID='22fb1d8d-7329-4573-9827-ca5d49cab451', imgUUID='4f2621f7-e438-4ea6-aab8-7fe700398f03', volUUID='7ed29876-7609-47ca-ade9-386bb5ae1b87', options=None)
>Thread-22::DEBUG::2011-10-11 14:01:14,166::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.b8fde061-56bd-4e42-8d50-7dbb9bd9c5e1`ReqID=`a2874e19-d3d4-467a-8f48-62371a4cec36`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-22::DEBUG::2011-10-11 14:01:14,166::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.b8fde061-56bd-4e42-8d50-7dbb9bd9c5e1' for lock type 'shared'
>Thread-22::DEBUG::2011-10-11 14:01:14,167::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.b8fde061-56bd-4e42-8d50-7dbb9bd9c5e1' is free. Now locking as 'shared' (1 active user)
>Thread-22::DEBUG::2011-10-11 14:01:14,167::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.b8fde061-56bd-4e42-8d50-7dbb9bd9c5e1`ReqID=`a2874e19-d3d4-467a-8f48-62371a4cec36`::Granted request
>Thread-22::DEBUG::2011-10-11 14:01:14,168::task::817::TaskManager.Task::(resourceAcquired) Task=`10df65c0-97a5-4dd5-86e9-5471fccb978a`::_resourcesAcquired: Storage.b8fde061-56bd-4e42-8d50-7dbb9bd9c5e1 (shared)
>Thread-22::DEBUG::2011-10-11 14:01:14,168::task::978::TaskManager.Task::(_decref) Task=`10df65c0-97a5-4dd5-86e9-5471fccb978a`::ref 1 aborting False
>Thread-22::DEBUG::2011-10-11 14:01:14,172::fileVolume::552::Storage.Volume::(validateVolumePath) validate path for 7ed29876-7609-47ca-ade9-386bb5ae1b87
>Thread-21::DEBUG::2011-10-11 14:01:14,174::task::588::TaskManager.Task::(_updateState) Task=`97a54f62-7a86-4038-a1e7-cbe05c7c7914`::moving from state init -> state preparing
>Thread-21::INFO::2011-10-11 14:01:14,175::logUtils::37::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='523559dc-b966-4544-8618-620ca06c4d4d', spUUID='22fb1d8d-7329-4573-9827-ca5d49cab451', imgUUID='c8b0c87e-f59f-40ce-9c48-e25f9bbbd832', volUUID='4845138d-6c52-4309-9583-eb38a81abba2', options=None)
>Thread-21::DEBUG::2011-10-11 14:01:14,176::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.523559dc-b966-4544-8618-620ca06c4d4d`ReqID=`184f1560-6299-465c-80f3-3decb4c9c07b`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-21::DEBUG::2011-10-11 14:01:14,177::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.523559dc-b966-4544-8618-620ca06c4d4d' for lock type 'shared'
>Thread-22::DEBUG::2011-10-11 14:01:14,178::fileVolume::552::Storage.Volume::(validateVolumePath) validate path for 7ed29876-7609-47ca-ade9-386bb5ae1b87
>Thread-21::DEBUG::2011-10-11 14:01:14,178::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.523559dc-b966-4544-8618-620ca06c4d4d' is free. Now locking as 'shared' (1 active user)
>Thread-21::DEBUG::2011-10-11 14:01:14,179::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.523559dc-b966-4544-8618-620ca06c4d4d`ReqID=`184f1560-6299-465c-80f3-3decb4c9c07b`::Granted request
>Thread-21::DEBUG::2011-10-11 14:01:14,180::task::817::TaskManager.Task::(resourceAcquired) Task=`97a54f62-7a86-4038-a1e7-cbe05c7c7914`::_resourcesAcquired: Storage.523559dc-b966-4544-8618-620ca06c4d4d (shared)
>Thread-21::DEBUG::2011-10-11 14:01:14,181::task::978::TaskManager.Task::(_decref) Task=`97a54f62-7a86-4038-a1e7-cbe05c7c7914`::ref 1 aborting False
>Thread-22::INFO::2011-10-11 14:01:14,181::logUtils::39::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '1589100544', 'apparentsize': '16106127360'}
>Thread-22::DEBUG::2011-10-11 14:01:14,182::task::1172::TaskManager.Task::(prepare) Task=`10df65c0-97a5-4dd5-86e9-5471fccb978a`::finished: {'truesize': '1589100544', 'apparentsize': '16106127360'}
>Thread-22::DEBUG::2011-10-11 14:01:14,183::task::588::TaskManager.Task::(_updateState) Task=`10df65c0-97a5-4dd5-86e9-5471fccb978a`::moving from state preparing -> state finished
>Thread-22::DEBUG::2011-10-11 14:01:14,183::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.b8fde061-56bd-4e42-8d50-7dbb9bd9c5e1': < ResourceRef 'Storage.b8fde061-56bd-4e42-8d50-7dbb9bd9c5e1', isValid: 'True' obj: 'None'>}
>Thread-22::DEBUG::2011-10-11 14:01:14,184::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-22::DEBUG::2011-10-11 14:01:14,184::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.b8fde061-56bd-4e42-8d50-7dbb9bd9c5e1'
>Thread-22::DEBUG::2011-10-11 14:01:14,185::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.b8fde061-56bd-4e42-8d50-7dbb9bd9c5e1' (0 active users)
>Thread-22::DEBUG::2011-10-11 14:01:14,185::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.b8fde061-56bd-4e42-8d50-7dbb9bd9c5e1' is free, finding out if anyone is waiting for it.
>Thread-22::DEBUG::2011-10-11 14:01:14,185::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.b8fde061-56bd-4e42-8d50-7dbb9bd9c5e1', Clearing records.
>Thread-22::DEBUG::2011-10-11 14:01:14,186::task::978::TaskManager.Task::(_decref) Task=`10df65c0-97a5-4dd5-86e9-5471fccb978a`::ref 0 aborting False
>Thread-22::ERROR::2011-10-11 14:01:14,187::utils::399::vm.Vm::(collect) vmId=`4f1d9317-46ab-4eb3-8f90-e0b258513d19`::Stats function failed: <AdvancedStatsFunction _sampleCpu at 0x29b0998>
>Traceback (most recent call last):
>  File "/usr/lib64/python2.6/site-packages/vdsm/utils.py", line 395, in collect
>    statsFunction()
>  File "/usr/lib64/python2.6/site-packages/vdsm/utils.py", line 272, in __call__
>    retValue = self._function(*args, **kwargs)
>  File "/usr/share/vdsm/libvirtvm.py", line 109, in _sampleCpu
>    state, maxMem, memory, nrVirtCpu, cpuTime = self._vm._dom.info()
>  File "/usr/share/vdsm/libvirtvm.py", line 491, in f
>    ret = attr(*args, **kwargs)
>  File "/usr/lib64/python2.6/site-packages/vdsm/libvirtconnection.py", line 82, in wrapper
>    ret = f(*args, **kwargs)
>  File "/usr/lib64/python2.6/site-packages/libvirt.py", line 1750, in info
>    if ret is None: raise libvirtError ('virDomainGetInfo() failed', dom=self)
>libvirtError: internal error client socket is closed
>Thread-21::DEBUG::2011-10-11 14:01:14,187::fileVolume::552::Storage.Volume::(validateVolumePath) validate path for 4845138d-6c52-4309-9583-eb38a81abba2
>Thread-22::ERROR::2011-10-11 14:01:14,188::utils::399::vm.Vm::(collect) vmId=`4f1d9317-46ab-4eb3-8f90-e0b258513d19`::Stats function failed: <AdvancedStatsFunction _sampleDisk at 0x29b0a08>
>Traceback (most recent call last):
>  File "/usr/lib64/python2.6/site-packages/vdsm/utils.py", line 395, in collect
>    statsFunction()
>  File "/usr/lib64/python2.6/site-packages/vdsm/utils.py", line 272, in __call__
>    retValue = self._function(*args, **kwargs)
>  File "/usr/share/vdsm/libvirtvm.py", line 119, in _sampleDisk
>    diskSamples[vmDrive.name] = self._vm._dom.blockStats(vmDrive.name)
>  File "/usr/share/vdsm/libvirtvm.py", line 491, in f
>    ret = attr(*args, **kwargs)
>  File "/usr/lib64/python2.6/site-packages/vdsm/libvirtconnection.py", line 82, in wrapper
>    ret = f(*args, **kwargs)
>  File "/usr/lib64/python2.6/site-packages/libvirt.py", line 1715, in blockStats
>    if ret is None: raise libvirtError ('virDomainBlockStats() failed', dom=self)
>libvirtError: internal error client socket is closed
>Thread-22::ERROR::2011-10-11 14:01:14,190::utils::399::vm.Vm::(collect) vmId=`4f1d9317-46ab-4eb3-8f90-e0b258513d19`::Stats function failed: <AdvancedStatsFunction _sampleDiskLatency at 0x29b4270>
>Traceback (most recent call last):
>  File "/usr/lib64/python2.6/site-packages/vdsm/utils.py", line 395, in collect
>    statsFunction()
>  File "/usr/lib64/python2.6/site-packages/vdsm/utils.py", line 272, in __call__
>    retValue = self._function(*args, **kwargs)
>  File "/usr/share/vdsm/libvirtvm.py", line 160, in _sampleDiskLatency
>    libvirt_qemu.VIR_DOMAIN_QEMU_MONITOR_COMMAND_DEFAULT)
>  File "/usr/lib64/python2.6/site-packages/libvirt_qemu.py", line 37, in qemuMonitorCommand
>    if ret is None: raise libvirt.libvirtError('virDomainQemuMonitorCommand() failed')
>libvirtError: internal error client socket is closed
>Thread-22::ERROR::2011-10-11 14:01:14,191::utils::399::vm.Vm::(collect) vmId=`4f1d9317-46ab-4eb3-8f90-e0b258513d19`::Stats function failed: <AdvancedStatsFunction _sampleNet at 0x29b0a78>
>Traceback (most recent call last):
>  File "/usr/lib64/python2.6/site-packages/vdsm/utils.py", line 395, in collect
>    statsFunction()
>  File "/usr/lib64/python2.6/site-packages/vdsm/utils.py", line 272, in __call__
>    retValue = self._function(*args, **kwargs)
>  File "/usr/share/vdsm/libvirtvm.py", line 179, in _sampleNet
>    netSamples[nic.name] = self._vm._dom.interfaceStats(nic.name)
>  File "/usr/share/vdsm/libvirtvm.py", line 491, in f
>    ret = attr(*args, **kwargs)
>  File "/usr/lib64/python2.6/site-packages/vdsm/libvirtconnection.py", line 82, in wrapper
>    ret = f(*args, **kwargs)
>  File "/usr/lib64/python2.6/site-packages/libvirt.py", line 1762, in interfaceStats
>    if ret is None: raise libvirtError ('virDomainInterfaceStats() failed', dom=self)
>libvirtError: internal error client socket is closed
>Thread-21::DEBUG::2011-10-11 14:01:14,194::fileVolume::552::Storage.Volume::(validateVolumePath) validate path for 4845138d-6c52-4309-9583-eb38a81abba2
>Thread-21::INFO::2011-10-11 14:01:14,196::logUtils::39::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '1710460928', 'apparentsize': '16106127360'}
>Thread-21::DEBUG::2011-10-11 14:01:14,196::task::1172::TaskManager.Task::(prepare) Task=`97a54f62-7a86-4038-a1e7-cbe05c7c7914`::finished: {'truesize': '1710460928', 'apparentsize': '16106127360'}
>Thread-21::DEBUG::2011-10-11 14:01:14,197::task::588::TaskManager.Task::(_updateState) Task=`97a54f62-7a86-4038-a1e7-cbe05c7c7914`::moving from state preparing -> state finished
>Thread-21::DEBUG::2011-10-11 14:01:14,197::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.523559dc-b966-4544-8618-620ca06c4d4d': < ResourceRef 'Storage.523559dc-b966-4544-8618-620ca06c4d4d', isValid: 'True' obj: 'None'>}
>Thread-21::DEBUG::2011-10-11 14:01:14,198::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-21::DEBUG::2011-10-11 14:01:14,198::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.523559dc-b966-4544-8618-620ca06c4d4d'
>Thread-21::DEBUG::2011-10-11 14:01:14,199::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.523559dc-b966-4544-8618-620ca06c4d4d' (0 active users)
>Thread-21::DEBUG::2011-10-11 14:01:14,199::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.523559dc-b966-4544-8618-620ca06c4d4d' is free, finding out if anyone is waiting for it.
>Thread-21::DEBUG::2011-10-11 14:01:14,200::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.523559dc-b966-4544-8618-620ca06c4d4d', Clearing records.
>Thread-21::DEBUG::2011-10-11 14:01:14,200::task::978::TaskManager.Task::(_decref) Task=`97a54f62-7a86-4038-a1e7-cbe05c7c7914`::ref 0 aborting False
>Thread-21::ERROR::2011-10-11 14:01:14,201::utils::399::vm.Vm::(collect) vmId=`816ac538-6aa6-44af-8ad0-7c35d149d6c0`::Stats function failed: <AdvancedStatsFunction _sampleCpu at 0x29b0998>
>Traceback (most recent call last):
>  File "/usr/lib64/python2.6/site-packages/vdsm/utils.py", line 395, in collect
>    statsFunction()
>  File "/usr/lib64/python2.6/site-packages/vdsm/utils.py", line 272, in __call__
>    retValue = self._function(*args, **kwargs)
>  File "/usr/share/vdsm/libvirtvm.py", line 109, in _sampleCpu
>    state, maxMem, memory, nrVirtCpu, cpuTime = self._vm._dom.info()
>  File "/usr/share/vdsm/libvirtvm.py", line 491, in f
>    ret = attr(*args, **kwargs)
>  File "/usr/lib64/python2.6/site-packages/vdsm/libvirtconnection.py", line 82, in wrapper
>    ret = f(*args, **kwargs)
>  File "/usr/lib64/python2.6/site-packages/libvirt.py", line 1750, in info
>    if ret is None: raise libvirtError ('virDomainGetInfo() failed', dom=self)
>libvirtError: internal error client socket is closed
>Thread-21::ERROR::2011-10-11 14:01:14,202::utils::399::vm.Vm::(collect) vmId=`816ac538-6aa6-44af-8ad0-7c35d149d6c0`::Stats function failed: <AdvancedStatsFunction _sampleDisk at 0x29b0a08>
>Traceback (most recent call last):
>  File "/usr/lib64/python2.6/site-packages/vdsm/utils.py", line 395, in collect
>    statsFunction()
>  File "/usr/lib64/python2.6/site-packages/vdsm/utils.py", line 272, in __call__
>    retValue = self._function(*args, **kwargs)
>  File "/usr/share/vdsm/libvirtvm.py", line 119, in _sampleDisk
>    diskSamples[vmDrive.name] = self._vm._dom.blockStats(vmDrive.name)
>  File "/usr/share/vdsm/libvirtvm.py", line 491, in f
>    ret = attr(*args, **kwargs)
>  File "/usr/lib64/python2.6/site-packages/vdsm/libvirtconnection.py", line 82, in wrapper
>    ret = f(*args, **kwargs)
>  File "/usr/lib64/python2.6/site-packages/libvirt.py", line 1715, in blockStats
>    if ret is None: raise libvirtError ('virDomainBlockStats() failed', dom=self)
>libvirtError: internal error client socket is closed
>Thread-21::ERROR::2011-10-11 14:01:14,203::utils::399::vm.Vm::(collect) vmId=`816ac538-6aa6-44af-8ad0-7c35d149d6c0`::Stats function failed: <AdvancedStatsFunction _sampleDiskLatency at 0x29b4270>
>Traceback (most recent call last):
>  File "/usr/lib64/python2.6/site-packages/vdsm/utils.py", line 395, in collect
>    statsFunction()
>  File "/usr/lib64/python2.6/site-packages/vdsm/utils.py", line 272, in __call__
>    retValue = self._function(*args, **kwargs)
>  File "/usr/share/vdsm/libvirtvm.py", line 160, in _sampleDiskLatency
>    libvirt_qemu.VIR_DOMAIN_QEMU_MONITOR_COMMAND_DEFAULT)
>  File "/usr/lib64/python2.6/site-packages/libvirt_qemu.py", line 37, in qemuMonitorCommand
>    if ret is None: raise libvirt.libvirtError('virDomainQemuMonitorCommand() failed')
>libvirtError: internal error client socket is closed
>Thread-21::ERROR::2011-10-11 14:01:14,203::utils::399::vm.Vm::(collect) vmId=`816ac538-6aa6-44af-8ad0-7c35d149d6c0`::Stats function failed: <AdvancedStatsFunction _sampleNet at 0x29b0a78>
>Traceback (most recent call last):
>  File "/usr/lib64/python2.6/site-packages/vdsm/utils.py", line 395, in collect
>    statsFunction()
>  File "/usr/lib64/python2.6/site-packages/vdsm/utils.py", line 272, in __call__
>    retValue = self._function(*args, **kwargs)
>  File "/usr/share/vdsm/libvirtvm.py", line 179, in _sampleNet
>    netSamples[nic.name] = self._vm._dom.interfaceStats(nic.name)
>  File "/usr/share/vdsm/libvirtvm.py", line 491, in f
>    ret = attr(*args, **kwargs)
>  File "/usr/lib64/python2.6/site-packages/vdsm/libvirtconnection.py", line 82, in wrapper
>    ret = f(*args, **kwargs)
>  File "/usr/lib64/python2.6/site-packages/libvirt.py", line 1762, in interfaceStats
>    if ret is None: raise libvirtError ('virDomainInterfaceStats() failed', dom=self)
>libvirtError: internal error client socket is closed
>Thread-16::ERROR::2011-10-11 14:01:14,560::utils::399::vm.Vm::(collect) vmId=`d0f58ab3-7202-45a0-a9b9-6088e00a65f1`::Stats function failed: <AdvancedStatsFunction _sampleNet at 0x29b0a78>
>Traceback (most recent call last):
>  File "/usr/lib64/python2.6/site-packages/vdsm/utils.py", line 395, in collect
>    statsFunction()
>  File "/usr/lib64/python2.6/site-packages/vdsm/utils.py", line 272, in __call__
>    retValue = self._function(*args, **kwargs)
>  File "/usr/share/vdsm/libvirtvm.py", line 179, in _sampleNet
>    netSamples[nic.name] = self._vm._dom.interfaceStats(nic.name)
>  File "/usr/share/vdsm/libvirtvm.py", line 491, in f
>    ret = attr(*args, **kwargs)
>  File "/usr/lib64/python2.6/site-packages/vdsm/libvirtconnection.py", line 82, in wrapper
>    ret = f(*args, **kwargs)
>  File "/usr/lib64/python2.6/site-packages/libvirt.py", line 1762, in interfaceStats
>    if ret is None: raise libvirtError ('virDomainInterfaceStats() failed', dom=self)
>libvirtError: internal error client socket is closed
>Thread-28::ERROR::2011-10-11 14:01:14,701::utils::399::vm.Vm::(collect) vmId=`6de348d7-bf46-4881-ab23-e5d41d13f42e`::Stats function failed: <AdvancedStatsFunction _sampleNet at 0x29b0a78>
>Traceback (most recent call last):
>  File "/usr/lib64/python2.6/site-packages/vdsm/utils.py", line 395, in collect
>    statsFunction()
>  File "/usr/lib64/python2.6/site-packages/vdsm/utils.py", line 272, in __call__
>    retValue = self._function(*args, **kwargs)
>  File "/usr/share/vdsm/libvirtvm.py", line 179, in _sampleNet
>    netSamples[nic.name] = self._vm._dom.interfaceStats(nic.name)
>  File "/usr/share/vdsm/libvirtvm.py", line 491, in f
>    ret = attr(*args, **kwargs)
>  File "/usr/lib64/python2.6/site-packages/vdsm/libvirtconnection.py", line 82, in wrapper
>    ret = f(*args, **kwargs)
>  File "/usr/lib64/python2.6/site-packages/libvirt.py", line 1762, in interfaceStats
>    if ret is None: raise libvirtError ('virDomainInterfaceStats() failed', dom=self)
>libvirtError: internal error client socket is closed
>Thread-194253::DEBUG::2011-10-11 14:01:15,347::task::588::TaskManager.Task::(_updateState) Task=`4dc31781-bb5b-4a71-8d72-5e12ea60ef2e`::moving from state init -> state preparing
>Thread-194253::INFO::2011-10-11 14:01:15,348::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-194253::INFO::2011-10-11 14:01:15,349::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'523559dc-b966-4544-8618-620ca06c4d4d': {'delay': '0.00448393821716', 'lastCheck': 1318321867.0074279, 'code': 0, 'valid': True}, '41263435-b36f-49dc-960a-8758a3744546': {'delay': '0.00539994239807', 'lastCheck': 1318321871.101887, 'code': 0, 'valid': True}, 'ed1c88c8-54b5-4616-aa00-26096173feaf': {'delay': '0.0023250579834', 'lastCheck': 1318321868.622283, 'code': 0, 'valid': True}, 'b8fde061-56bd-4e42-8d50-7dbb9bd9c5e1': {'delay': '0.00500512123108', 'lastCheck': 1318321874.143295, 'code': 0, 'valid': True}, '79b1039e-34a7-4cb4-aedf-271a304468f5': {'delay': '0.004802942276', 'lastCheck': 1318321871.2913499, 'code': 0, 'valid': True}, '5743191c-5960-48cb-b87b-3f40645149ba': {'delay': '0.00530314445496', 'lastCheck': 1318321868.3254089, 'code': 0, 'valid': True}}
>Thread-194253::DEBUG::2011-10-11 14:01:15,349::task::1172::TaskManager.Task::(prepare) Task=`4dc31781-bb5b-4a71-8d72-5e12ea60ef2e`::finished: {'523559dc-b966-4544-8618-620ca06c4d4d': {'delay': '0.00448393821716', 'lastCheck': 1318321867.0074279, 'code': 0, 'valid': True}, '41263435-b36f-49dc-960a-8758a3744546': {'delay': '0.00539994239807', 'lastCheck': 1318321871.101887, 'code': 0, 'valid': True}, 'ed1c88c8-54b5-4616-aa00-26096173feaf': {'delay': '0.0023250579834', 'lastCheck': 1318321868.622283, 'code': 0, 'valid': True}, 'b8fde061-56bd-4e42-8d50-7dbb9bd9c5e1': {'delay': '0.00500512123108', 'lastCheck': 1318321874.143295, 'code': 0, 'valid': True}, '79b1039e-34a7-4cb4-aedf-271a304468f5': {'delay': '0.004802942276', 'lastCheck': 1318321871.2913499, 'code': 0, 'valid': True}, '5743191c-5960-48cb-b87b-3f40645149ba': {'delay': '0.00530314445496', 'lastCheck': 1318321868.3254089, 'code': 0, 'valid': True}}
>Thread-194253::DEBUG::2011-10-11 14:01:15,350::task::588::TaskManager.Task::(_updateState) Task=`4dc31781-bb5b-4a71-8d72-5e12ea60ef2e`::moving from state preparing -> state finished
>Thread-194253::DEBUG::2011-10-11 14:01:15,350::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-194253::DEBUG::2011-10-11 14:01:15,351::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-194253::DEBUG::2011-10-11 14:01:15,351::task::978::TaskManager.Task::(_decref) Task=`4dc31781-bb5b-4a71-8d72-5e12ea60ef2e`::ref 0 aborting False
>Thread-194254::DEBUG::2011-10-11 14:01:15,384::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`6de348d7-bf46-4881-ab23-e5d41d13f42e`::Disk hdc stats not available
>Thread-194254::DEBUG::2011-10-11 14:01:15,385::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`d0f58ab3-7202-45a0-a9b9-6088e00a65f1`::Disk hdc stats not available
>Thread-194254::DEBUG::2011-10-11 14:01:15,386::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`4f1d9317-46ab-4eb3-8f90-e0b258513d19`::Disk hdc stats not available
>Thread-194254::DEBUG::2011-10-11 14:01:15,386::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`816ac538-6aa6-44af-8ad0-7c35d149d6c0`::Disk hdc stats not available
>Thread-194254::DEBUG::2011-10-11 14:01:15,387::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`d9e0053c-0e7b-442f-abb5-733f31da97b4`::Disk hdc stats not available
>Thread-25::ERROR::2011-10-11 14:01:15,465::utils::399::vm.Vm::(collect) vmId=`d9e0053c-0e7b-442f-abb5-733f31da97b4`::Stats function failed: <AdvancedStatsFunction _sampleNet at 0x29b0a78>
>Traceback (most recent call last):
>  File "/usr/lib64/python2.6/site-packages/vdsm/utils.py", line 395, in collect
>    statsFunction()
>  File "/usr/lib64/python2.6/site-packages/vdsm/utils.py", line 272, in __call__
>    retValue = self._function(*args, **kwargs)
>  File "/usr/share/vdsm/libvirtvm.py", line 179, in _sampleNet
>    netSamples[nic.name] = self._vm._dom.interfaceStats(nic.name)
>  File "/usr/share/vdsm/libvirtvm.py", line 491, in f
>    ret = attr(*args, **kwargs)
>  File "/usr/lib64/python2.6/site-packages/vdsm/libvirtconnection.py", line 82, in wrapper
>    ret = f(*args, **kwargs)
>  File "/usr/lib64/python2.6/site-packages/libvirt.py", line 1762, in interfaceStats
>    if ret is None: raise libvirtError ('virDomainInterfaceStats() failed', dom=self)
>libvirtError: internal error client socket is closed
>Thread-22::ERROR::2011-10-11 14:01:19,192::utils::399::vm.Vm::(collect) vmId=`4f1d9317-46ab-4eb3-8f90-e0b258513d19`::Stats function failed: <AdvancedStatsFunction _sampleNet at 0x29b0a78>
>Traceback (most recent call last):
>  File "/usr/lib64/python2.6/site-packages/vdsm/utils.py", line 395, in collect
>    statsFunction()
>  File "/usr/lib64/python2.6/site-packages/vdsm/utils.py", line 272, in __call__
>    retValue = self._function(*args, **kwargs)
>  File "/usr/share/vdsm/libvirtvm.py", line 179, in _sampleNet
>    netSamples[nic.name] = self._vm._dom.interfaceStats(nic.name)
>  File "/usr/share/vdsm/libvirtvm.py", line 491, in f
>    ret = attr(*args, **kwargs)
>  File "/usr/lib64/python2.6/site-packages/vdsm/libvirtconnection.py", line 82, in wrapper
>    ret = f(*args, **kwargs)
>  File "/usr/lib64/python2.6/site-packages/libvirt.py", line 1762, in interfaceStats
>    if ret is None: raise libvirtError ('virDomainInterfaceStats() failed', dom=self)
>libvirtError: internal error client socket is closed
>Thread-21::ERROR::2011-10-11 14:01:19,205::utils::399::vm.Vm::(collect) vmId=`816ac538-6aa6-44af-8ad0-7c35d149d6c0`::Stats function failed: <AdvancedStatsFunction _sampleNet at 0x29b0a78>
>Traceback (most recent call last):
>  File "/usr/lib64/python2.6/site-packages/vdsm/utils.py", line 395, in collect
>    statsFunction()
>  File "/usr/lib64/python2.6/site-packages/vdsm/utils.py", line 272, in __call__
>    retValue = self._function(*args, **kwargs)
>  File "/usr/share/vdsm/libvirtvm.py", line 179, in _sampleNet
>    netSamples[nic.name] = self._vm._dom.interfaceStats(nic.name)
>  File "/usr/share/vdsm/libvirtvm.py", line 491, in f
>    ret = attr(*args, **kwargs)
>  File "/usr/lib64/python2.6/site-packages/vdsm/libvirtconnection.py", line 82, in wrapper
>    ret = f(*args, **kwargs)
>  File "/usr/lib64/python2.6/site-packages/libvirt.py", line 1762, in interfaceStats
>    if ret is None: raise libvirtError ('virDomainInterfaceStats() failed', dom=self)
>libvirtError: internal error client socket is closed

Actions: View

Attachments on bug 851936: 607114