Attachment 652563 Details for Bug 880555 – vdsm log file

vdsm log file

vdsm.txt (text/plain), 139.59 KB, created by Valentin Bajrami on 2012-11-27 10:14:36 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: Valentin Bajrami

Created: 2012-11-27 10:14:36 UTC

Size: 139.59 KB

patch

obsolete

>
>Fedora Pastebin
>New Paste Fedora: Solved | Mobile | Wiki | Planet
>My Pastes | Preferences
>TTL: 23 hours, 59 minutes | View raw
>VM Channels Listener::DEBUG::2012-11 ... e-c86e3da0f7a0`::Disk hdc stats not ... -582418865527`::ref 1 aborting False
>
>    VM Channels Listener::DEBUG::2012-11-27 10:32:24,895::vmChannels::60::vds::(_handle_timeouts) Timeout on fileno 22.
>    Thread-350::DEBUG::2012-11-27 10:32:26,633::BindingXMLRPC::156::vds::(wrapper) [192.168.2.113]
>    Thread-350::DEBUG::2012-11-27 10:32:26,634::task::588::TaskManager.Task::(_updateState) Task=`76a4ef3d-0e80-4d1b-9fb3-81406c11cea0`::moving from state init -> state preparing
>    Thread-350::INFO::2012-11-27 10:32:26,634::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='25f8442c-bb4e-4f72-a66a-35715f149300', options=None)
>    Thread-350::INFO::2012-11-27 10:32:26,634::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 11}}
>    Thread-350::DEBUG::2012-11-27 10:32:26,635::task::1172::TaskManager.Task::(prepare) Task=`76a4ef3d-0e80-4d1b-9fb3-81406c11cea0`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 11}}
>    Thread-350::DEBUG::2012-11-27 10:32:26,635::task::588::TaskManager.Task::(_updateState) Task=`76a4ef3d-0e80-4d1b-9fb3-81406c11cea0`::moving from state preparing -> state finished
>    Thread-350::DEBUG::2012-11-27 10:32:26,635::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>    Thread-350::DEBUG::2012-11-27 10:32:26,635::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>    Thread-350::DEBUG::2012-11-27 10:32:26,635::task::978::TaskManager.Task::(_decref) Task=`76a4ef3d-0e80-4d1b-9fb3-81406c11cea0`::ref 0 aborting False
>    Thread-351::DEBUG::2012-11-27 10:32:26,658::BindingXMLRPC::156::vds::(wrapper) [192.168.2.113]
>    Thread-351::DEBUG::2012-11-27 10:32:26,658::task::588::TaskManager.Task::(_updateState) Task=`3036433a-0e44-440e-8b6e-08878ceb3a0d`::moving from state init -> state preparing
>    Thread-351::INFO::2012-11-27 10:32:26,658::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='25f8442c-bb4e-4f72-a66a-35715f149300', options=None)
>    Thread-351::DEBUG::2012-11-27 10:32:26,659::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.25f8442c-bb4e-4f72-a66a-35715f149300`ReqID=`866ad49a-52b4-4acb-8c02-21ded4ae36b8`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>    Thread-351::DEBUG::2012-11-27 10:32:26,659::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300' for lock type 'shared'
>    Thread-351::DEBUG::2012-11-27 10:32:26,659::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300' is free. Now locking as 'shared' (1 active user)
>    Thread-351::DEBUG::2012-11-27 10:32:26,659::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.25f8442c-bb4e-4f72-a66a-35715f149300`ReqID=`866ad49a-52b4-4acb-8c02-21ded4ae36b8`::Granted request
>    Thread-351::DEBUG::2012-11-27 10:32:26,660::task::817::TaskManager.Task::(resourceAcquired) Task=`3036433a-0e44-440e-8b6e-08878ceb3a0d`::_resourcesAcquired: Storage.25f8442c-bb4e-4f72-a66a-35715f149300 (shared)
>    Thread-351::DEBUG::2012-11-27 10:32:26,660::task::978::TaskManager.Task::(_decref) Task=`3036433a-0e44-440e-8b6e-08878ceb3a0d`::ref 1 aborting False
>    Thread-351::INFO::2012-11-27 10:32:26,666::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': '0149d080-a94c-446d-969c-eef7da5f6706', 'name': 'MuntCenter', 'version': '0', 'domains': '3d40cf03-891e-471e-93ce-7e7970f73723:Active,0149d080-a94c-446d-969c-eef7da5f6706:Active', 'pool_status': 'connected', 'isoprefix': '/rhev/data-center/25f8442c-bb4e-4f72-a66a-35715f149300/3d40cf03-891e-471e-93ce-7e7970f73723/images/11111111-1111-1111-1111-111111111111', 'type': 'NFS', 'master_ver': 1, 'lver': 11}, 'dominfo': {'3d40cf03-891e-471e-93ce-7e7970f73723': {'status': 'Active', 'diskfree': '18295816192', 'alerts': [], 'disktotal': '21137981440'}, '0149d080-a94c-446d-969c-eef7da5f6706': {'status': 'Active', 'diskfree': '355573694464', 'alerts': [], 'disktotal': '433102258176'}}}
>    Thread-351::DEBUG::2012-11-27 10:32:26,666::task::1172::TaskManager.Task::(prepare) Task=`3036433a-0e44-440e-8b6e-08878ceb3a0d`::finished: {'info': {'spm_id': 1, 'master_uuid': '0149d080-a94c-446d-969c-eef7da5f6706', 'name': 'MuntCenter', 'version': '0', 'domains': '3d40cf03-891e-471e-93ce-7e7970f73723:Active,0149d080-a94c-446d-969c-eef7da5f6706:Active', 'pool_status': 'connected', 'isoprefix': '/rhev/data-center/25f8442c-bb4e-4f72-a66a-35715f149300/3d40cf03-891e-471e-93ce-7e7970f73723/images/11111111-1111-1111-1111-111111111111', 'type': 'NFS', 'master_ver': 1, 'lver': 11}, 'dominfo': {'3d40cf03-891e-471e-93ce-7e7970f73723': {'status': 'Active', 'diskfree': '18295816192', 'alerts': [], 'disktotal': '21137981440'}, '0149d080-a94c-446d-969c-eef7da5f6706': {'status': 'Active', 'diskfree': '355573694464', 'alerts': [], 'disktotal': '433102258176'}}}
>    Thread-351::DEBUG::2012-11-27 10:32:26,666::task::588::TaskManager.Task::(_updateState) Task=`3036433a-0e44-440e-8b6e-08878ceb3a0d`::moving from state preparing -> state finished
>    Thread-351::DEBUG::2012-11-27 10:32:26,667::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.25f8442c-bb4e-4f72-a66a-35715f149300': < ResourceRef 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300', isValid: 'True' obj: 'None'>}
>    Thread-351::DEBUG::2012-11-27 10:32:26,667::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>    Thread-351::DEBUG::2012-11-27 10:32:26,667::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300'
>    Thread-351::DEBUG::2012-11-27 10:32:26,667::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300' (0 active users)
>    Thread-351::DEBUG::2012-11-27 10:32:26,667::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300' is free, finding out if anyone is waiting for it.
>    Thread-351::DEBUG::2012-11-27 10:32:26,667::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300', Clearing records.
>    Thread-351::DEBUG::2012-11-27 10:32:26,667::task::978::TaskManager.Task::(_decref) Task=`3036433a-0e44-440e-8b6e-08878ceb3a0d`::ref 0 aborting False
>    Thread-353::DEBUG::2012-11-27 10:32:29,589::task::588::TaskManager.Task::(_updateState) Task=`7eb48aad-bc0b-4871-9aea-002ac1d62911`::moving from state init -> state preparing
>    Thread-353::INFO::2012-11-27 10:32:29,590::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>    Thread-353::INFO::2012-11-27 10:32:29,590::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'3d40cf03-891e-471e-93ce-7e7970f73723': {'delay': '0.0027379989624', 'lastCheck': 1354008745.933386, 'code': 0, 'valid': True}, '0149d080-a94c-446d-969c-eef7da5f6706': {'delay': '0.00146508216858', 'lastCheck': 1354008745.93718, 'code': 0, 'valid': True}}
>    Thread-353::DEBUG::2012-11-27 10:32:29,590::task::1172::TaskManager.Task::(prepare) Task=`7eb48aad-bc0b-4871-9aea-002ac1d62911`::finished: {'3d40cf03-891e-471e-93ce-7e7970f73723': {'delay': '0.0027379989624', 'lastCheck': 1354008745.933386, 'code': 0, 'valid': True}, '0149d080-a94c-446d-969c-eef7da5f6706': {'delay': '0.00146508216858', 'lastCheck': 1354008745.93718, 'code': 0, 'valid': True}}
>    Thread-353::DEBUG::2012-11-27 10:32:29,590::task::588::TaskManager.Task::(_updateState) Task=`7eb48aad-bc0b-4871-9aea-002ac1d62911`::moving from state preparing -> state finished
>    Thread-353::DEBUG::2012-11-27 10:32:29,591::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>    Thread-353::DEBUG::2012-11-27 10:32:29,591::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>    Thread-353::DEBUG::2012-11-27 10:32:29,591::task::978::TaskManager.Task::(_decref) Task=`7eb48aad-bc0b-4871-9aea-002ac1d62911`::ref 0 aborting False
>    Thread-354::DEBUG::2012-11-27 10:32:29,617::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`28efde72-eecc-4714-928e-c86e3da0f7a0`::Disk hdc stats not available
>    Thread-358::DEBUG::2012-11-27 10:32:36,777::BindingXMLRPC::156::vds::(wrapper) [192.168.2.113]
>    Thread-358::DEBUG::2012-11-27 10:32:36,777::task::588::TaskManager.Task::(_updateState) Task=`31377d10-62cf-47bf-8761-d59512bfc148`::moving from state init -> state preparing
>    Thread-358::INFO::2012-11-27 10:32:36,778::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='25f8442c-bb4e-4f72-a66a-35715f149300', options=None)
>    Thread-358::INFO::2012-11-27 10:32:36,778::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 11}}
>    Thread-358::DEBUG::2012-11-27 10:32:36,778::task::1172::TaskManager.Task::(prepare) Task=`31377d10-62cf-47bf-8761-d59512bfc148`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 11}}
>    Thread-358::DEBUG::2012-11-27 10:32:36,778::task::588::TaskManager.Task::(_updateState) Task=`31377d10-62cf-47bf-8761-d59512bfc148`::moving from state preparing -> state finished
>    Thread-358::DEBUG::2012-11-27 10:32:36,779::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>    Thread-358::DEBUG::2012-11-27 10:32:36,779::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>    Thread-358::DEBUG::2012-11-27 10:32:36,779::task::978::TaskManager.Task::(_decref) Task=`31377d10-62cf-47bf-8761-d59512bfc148`::ref 0 aborting False
>    Thread-359::DEBUG::2012-11-27 10:32:36,799::BindingXMLRPC::156::vds::(wrapper) [192.168.2.113]
>    Thread-359::DEBUG::2012-11-27 10:32:36,799::task::588::TaskManager.Task::(_updateState) Task=`8d861d6a-cec5-410b-aeb1-fcafb8fda980`::moving from state init -> state preparing
>    Thread-359::INFO::2012-11-27 10:32:36,799::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='25f8442c-bb4e-4f72-a66a-35715f149300', options=None)
>    Thread-359::DEBUG::2012-11-27 10:32:36,800::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.25f8442c-bb4e-4f72-a66a-35715f149300`ReqID=`b63ca1c7-a6fc-4f89-9cb2-12a54f487019`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>    Thread-359::DEBUG::2012-11-27 10:32:36,800::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300' for lock type 'shared'
>    Thread-359::DEBUG::2012-11-27 10:32:36,800::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300' is free. Now locking as 'shared' (1 active user)
>    Thread-359::DEBUG::2012-11-27 10:32:36,800::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.25f8442c-bb4e-4f72-a66a-35715f149300`ReqID=`b63ca1c7-a6fc-4f89-9cb2-12a54f487019`::Granted request
>    Thread-359::DEBUG::2012-11-27 10:32:36,801::task::817::TaskManager.Task::(resourceAcquired) Task=`8d861d6a-cec5-410b-aeb1-fcafb8fda980`::_resourcesAcquired: Storage.25f8442c-bb4e-4f72-a66a-35715f149300 (shared)
>    Thread-359::DEBUG::2012-11-27 10:32:36,801::task::978::TaskManager.Task::(_decref) Task=`8d861d6a-cec5-410b-aeb1-fcafb8fda980`::ref 1 aborting False
>    Thread-359::INFO::2012-11-27 10:32:36,807::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': '0149d080-a94c-446d-969c-eef7da5f6706', 'name': 'MuntCenter', 'version': '0', 'domains': '3d40cf03-891e-471e-93ce-7e7970f73723:Active,0149d080-a94c-446d-969c-eef7da5f6706:Active', 'pool_status': 'connected', 'isoprefix': '/rhev/data-center/25f8442c-bb4e-4f72-a66a-35715f149300/3d40cf03-891e-471e-93ce-7e7970f73723/images/11111111-1111-1111-1111-111111111111', 'type': 'NFS', 'master_ver': 1, 'lver': 11}, 'dominfo': {'3d40cf03-891e-471e-93ce-7e7970f73723': {'status': 'Active', 'diskfree': '18295816192', 'alerts': [], 'disktotal': '21137981440'}, '0149d080-a94c-446d-969c-eef7da5f6706': {'status': 'Active', 'diskfree': '355573694464', 'alerts': [], 'disktotal': '433102258176'}}}
>    Thread-359::DEBUG::2012-11-27 10:32:36,807::task::1172::TaskManager.Task::(prepare) Task=`8d861d6a-cec5-410b-aeb1-fcafb8fda980`::finished: {'info': {'spm_id': 1, 'master_uuid': '0149d080-a94c-446d-969c-eef7da5f6706', 'name': 'MuntCenter', 'version': '0', 'domains': '3d40cf03-891e-471e-93ce-7e7970f73723:Active,0149d080-a94c-446d-969c-eef7da5f6706:Active', 'pool_status': 'connected', 'isoprefix': '/rhev/data-center/25f8442c-bb4e-4f72-a66a-35715f149300/3d40cf03-891e-471e-93ce-7e7970f73723/images/11111111-1111-1111-1111-111111111111', 'type': 'NFS', 'master_ver': 1, 'lver': 11}, 'dominfo': {'3d40cf03-891e-471e-93ce-7e7970f73723': {'status': 'Active', 'diskfree': '18295816192', 'alerts': [], 'disktotal': '21137981440'}, '0149d080-a94c-446d-969c-eef7da5f6706': {'status': 'Active', 'diskfree': '355573694464', 'alerts': [], 'disktotal': '433102258176'}}}
>    Thread-359::DEBUG::2012-11-27 10:32:36,807::task::588::TaskManager.Task::(_updateState) Task=`8d861d6a-cec5-410b-aeb1-fcafb8fda980`::moving from state preparing -> state finished
>    Thread-359::DEBUG::2012-11-27 10:32:36,807::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.25f8442c-bb4e-4f72-a66a-35715f149300': < ResourceRef 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300', isValid: 'True' obj: 'None'>}
>    Thread-359::DEBUG::2012-11-27 10:32:36,807::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>    Thread-359::DEBUG::2012-11-27 10:32:36,807::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300'
>    Thread-359::DEBUG::2012-11-27 10:32:36,807::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300' (0 active users)
>    Thread-359::DEBUG::2012-11-27 10:32:36,807::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300' is free, finding out if anyone is waiting for it.
>    Thread-359::DEBUG::2012-11-27 10:32:36,807::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300', Clearing records.
>    Thread-359::DEBUG::2012-11-27 10:32:36,808::task::978::TaskManager.Task::(_decref) Task=`8d861d6a-cec5-410b-aeb1-fcafb8fda980`::ref 0 aborting False
>    Thread-361::DEBUG::2012-11-27 10:32:39,860::task::588::TaskManager.Task::(_updateState) Task=`9149472d-2bf9-4db8-b964-98c68c58d5ba`::moving from state init -> state preparing
>    Thread-361::INFO::2012-11-27 10:32:39,860::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>    Thread-361::INFO::2012-11-27 10:32:39,860::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'3d40cf03-891e-471e-93ce-7e7970f73723': {'delay': '0.00417613983154', 'lastCheck': 1354008755.945416, 'code': 0, 'valid': True}, '0149d080-a94c-446d-969c-eef7da5f6706': {'delay': '0.00194096565247', 'lastCheck': 1354008755.950105, 'code': 0, 'valid': True}}
>    Thread-361::DEBUG::2012-11-27 10:32:39,860::task::1172::TaskManager.Task::(prepare) Task=`9149472d-2bf9-4db8-b964-98c68c58d5ba`::finished: {'3d40cf03-891e-471e-93ce-7e7970f73723': {'delay': '0.00417613983154', 'lastCheck': 1354008755.945416, 'code': 0, 'valid': True}, '0149d080-a94c-446d-969c-eef7da5f6706': {'delay': '0.00194096565247', 'lastCheck': 1354008755.950105, 'code': 0, 'valid': True}}
>    Thread-361::DEBUG::2012-11-27 10:32:39,860::task::588::TaskManager.Task::(_updateState) Task=`9149472d-2bf9-4db8-b964-98c68c58d5ba`::moving from state preparing -> state finished
>    Thread-361::DEBUG::2012-11-27 10:32:39,860::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>    Thread-361::DEBUG::2012-11-27 10:32:39,860::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>    Thread-361::DEBUG::2012-11-27 10:32:39,861::task::978::TaskManager.Task::(_decref) Task=`9149472d-2bf9-4db8-b964-98c68c58d5ba`::ref 0 aborting False
>    Thread-362::DEBUG::2012-11-27 10:32:39,875::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`28efde72-eecc-4714-928e-c86e3da0f7a0`::Disk hdc stats not available
>    Thread-366::DEBUG::2012-11-27 10:32:46,944::BindingXMLRPC::156::vds::(wrapper) [192.168.2.113]
>    Thread-366::DEBUG::2012-11-27 10:32:46,945::task::588::TaskManager.Task::(_updateState) Task=`b90eab42-6d0b-4b23-a3f3-35e2e8545b89`::moving from state init -> state preparing
>    Thread-366::INFO::2012-11-27 10:32:46,945::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='25f8442c-bb4e-4f72-a66a-35715f149300', options=None)
>    Thread-366::INFO::2012-11-27 10:32:46,945::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 11}}
>    Thread-366::DEBUG::2012-11-27 10:32:46,945::task::1172::TaskManager.Task::(prepare) Task=`b90eab42-6d0b-4b23-a3f3-35e2e8545b89`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 11}}
>    Thread-366::DEBUG::2012-11-27 10:32:46,946::task::588::TaskManager.Task::(_updateState) Task=`b90eab42-6d0b-4b23-a3f3-35e2e8545b89`::moving from state preparing -> state finished
>    Thread-366::DEBUG::2012-11-27 10:32:46,946::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>    Thread-366::DEBUG::2012-11-27 10:32:46,946::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>    Thread-366::DEBUG::2012-11-27 10:32:46,946::task::978::TaskManager.Task::(_decref) Task=`b90eab42-6d0b-4b23-a3f3-35e2e8545b89`::ref 0 aborting False
>    Thread-367::DEBUG::2012-11-27 10:32:46,967::BindingXMLRPC::156::vds::(wrapper) [192.168.2.113]
>    Thread-367::DEBUG::2012-11-27 10:32:46,967::task::588::TaskManager.Task::(_updateState) Task=`340a9e6c-a498-4895-9670-ab66621c9095`::moving from state init -> state preparing
>    Thread-367::INFO::2012-11-27 10:32:46,968::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='25f8442c-bb4e-4f72-a66a-35715f149300', options=None)
>    Thread-367::DEBUG::2012-11-27 10:32:46,968::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.25f8442c-bb4e-4f72-a66a-35715f149300`ReqID=`d121416f-3f04-462a-9096-f264e270572a`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>    Thread-367::DEBUG::2012-11-27 10:32:46,968::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300' for lock type 'shared'
>    Thread-367::DEBUG::2012-11-27 10:32:46,968::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300' is free. Now locking as 'shared' (1 active user)
>    Thread-367::DEBUG::2012-11-27 10:32:46,969::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.25f8442c-bb4e-4f72-a66a-35715f149300`ReqID=`d121416f-3f04-462a-9096-f264e270572a`::Granted request
>    Thread-367::DEBUG::2012-11-27 10:32:46,969::task::817::TaskManager.Task::(resourceAcquired) Task=`340a9e6c-a498-4895-9670-ab66621c9095`::_resourcesAcquired: Storage.25f8442c-bb4e-4f72-a66a-35715f149300 (shared)
>    Thread-367::DEBUG::2012-11-27 10:32:46,969::task::978::TaskManager.Task::(_decref) Task=`340a9e6c-a498-4895-9670-ab66621c9095`::ref 1 aborting False
>    Thread-367::INFO::2012-11-27 10:32:46,976::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': '0149d080-a94c-446d-969c-eef7da5f6706', 'name': 'MuntCenter', 'version': '0', 'domains': '3d40cf03-891e-471e-93ce-7e7970f73723:Active,0149d080-a94c-446d-969c-eef7da5f6706:Active', 'pool_status': 'connected', 'isoprefix': '/rhev/data-center/25f8442c-bb4e-4f72-a66a-35715f149300/3d40cf03-891e-471e-93ce-7e7970f73723/images/11111111-1111-1111-1111-111111111111', 'type': 'NFS', 'master_ver': 1, 'lver': 11}, 'dominfo': {'3d40cf03-891e-471e-93ce-7e7970f73723': {'status': 'Active', 'diskfree': '18295816192', 'alerts': [], 'disktotal': '21137981440'}, '0149d080-a94c-446d-969c-eef7da5f6706': {'status': 'Active', 'diskfree': '355573694464', 'alerts': [], 'disktotal': '433102258176'}}}
>    Thread-367::DEBUG::2012-11-27 10:32:46,976::task::1172::TaskManager.Task::(prepare) Task=`340a9e6c-a498-4895-9670-ab66621c9095`::finished: {'info': {'spm_id': 1, 'master_uuid': '0149d080-a94c-446d-969c-eef7da5f6706', 'name': 'MuntCenter', 'version': '0', 'domains': '3d40cf03-891e-471e-93ce-7e7970f73723:Active,0149d080-a94c-446d-969c-eef7da5f6706:Active', 'pool_status': 'connected', 'isoprefix': '/rhev/data-center/25f8442c-bb4e-4f72-a66a-35715f149300/3d40cf03-891e-471e-93ce-7e7970f73723/images/11111111-1111-1111-1111-111111111111', 'type': 'NFS', 'master_ver': 1, 'lver': 11}, 'dominfo': {'3d40cf03-891e-471e-93ce-7e7970f73723': {'status': 'Active', 'diskfree': '18295816192', 'alerts': [], 'disktotal': '21137981440'}, '0149d080-a94c-446d-969c-eef7da5f6706': {'status': 'Active', 'diskfree': '355573694464', 'alerts': [], 'disktotal': '433102258176'}}}
>    Thread-367::DEBUG::2012-11-27 10:32:46,976::task::588::TaskManager.Task::(_updateState) Task=`340a9e6c-a498-4895-9670-ab66621c9095`::moving from state preparing -> state finished
>    Thread-367::DEBUG::2012-11-27 10:32:46,976::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.25f8442c-bb4e-4f72-a66a-35715f149300': < ResourceRef 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300', isValid: 'True' obj: 'None'>}
>    Thread-367::DEBUG::2012-11-27 10:32:46,976::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>    Thread-367::DEBUG::2012-11-27 10:32:46,976::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300'
>    Thread-367::DEBUG::2012-11-27 10:32:46,976::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300' (0 active users)
>    Thread-367::DEBUG::2012-11-27 10:32:46,977::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300' is free, finding out if anyone is waiting for it.
>    Thread-367::DEBUG::2012-11-27 10:32:46,977::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300', Clearing records.
>    Thread-367::DEBUG::2012-11-27 10:32:46,977::task::978::TaskManager.Task::(_decref) Task=`340a9e6c-a498-4895-9670-ab66621c9095`::ref 0 aborting False
>    Thread-369::DEBUG::2012-11-27 10:32:50,125::task::588::TaskManager.Task::(_updateState) Task=`2983ea7f-3335-4b60-9607-3adba27331fe`::moving from state init -> state preparing
>    Thread-369::INFO::2012-11-27 10:32:50,126::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>    Thread-369::INFO::2012-11-27 10:32:50,126::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'3d40cf03-891e-471e-93ce-7e7970f73723': {'delay': '0.00253582000732', 'lastCheck': 1354008765.957111, 'code': 0, 'valid': True}, '0149d080-a94c-446d-969c-eef7da5f6706': {'delay': '0.00169777870178', 'lastCheck': 1354008765.962815, 'code': 0, 'valid': True}}
>    Thread-369::DEBUG::2012-11-27 10:32:50,126::task::1172::TaskManager.Task::(prepare) Task=`2983ea7f-3335-4b60-9607-3adba27331fe`::finished: {'3d40cf03-891e-471e-93ce-7e7970f73723': {'delay': '0.00253582000732', 'lastCheck': 1354008765.957111, 'code': 0, 'valid': True}, '0149d080-a94c-446d-969c-eef7da5f6706': {'delay': '0.00169777870178', 'lastCheck': 1354008765.962815, 'code': 0, 'valid': True}}
>    Thread-369::DEBUG::2012-11-27 10:32:50,126::task::588::TaskManager.Task::(_updateState) Task=`2983ea7f-3335-4b60-9607-3adba27331fe`::moving from state preparing -> state finished
>    Thread-369::DEBUG::2012-11-27 10:32:50,126::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>    Thread-369::DEBUG::2012-11-27 10:32:50,127::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>    Thread-369::DEBUG::2012-11-27 10:32:50,127::task::978::TaskManager.Task::(_decref) Task=`2983ea7f-3335-4b60-9607-3adba27331fe`::ref 0 aborting False
>    Thread-370::DEBUG::2012-11-27 10:32:50,153::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`28efde72-eecc-4714-928e-c86e3da0f7a0`::Disk hdc stats not available
>    Thread-16::DEBUG::2012-11-27 10:32:54,133::task::588::TaskManager.Task::(_updateState) Task=`01d94b4b-4375-4ecb-898e-2cc6c9f072a9`::moving from state init -> state preparing
>    Thread-16::INFO::2012-11-27 10:32:54,133::logUtils::37::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='0149d080-a94c-446d-969c-eef7da5f6706', spUUID='25f8442c-bb4e-4f72-a66a-35715f149300', imgUUID='16dc8590-0538-4a32-8bf1-fb67ee33bc35', volUUID='73380a26-37b4-4f24-979c-4464d8b4401c', options=None)
>    Thread-16::DEBUG::2012-11-27 10:32:54,135::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.0149d080-a94c-446d-969c-eef7da5f6706`ReqID=`55ab12da-761c-4bf1-b121-8c72320101d1`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>    Thread-16::DEBUG::2012-11-27 10:32:54,135::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.0149d080-a94c-446d-969c-eef7da5f6706' for lock type 'shared'
>    Thread-16::DEBUG::2012-11-27 10:32:54,135::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.0149d080-a94c-446d-969c-eef7da5f6706' is free. Now locking as 'shared' (1 active user)
>    Thread-16::DEBUG::2012-11-27 10:32:54,136::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.0149d080-a94c-446d-969c-eef7da5f6706`ReqID=`55ab12da-761c-4bf1-b121-8c72320101d1`::Granted request
>    Thread-16::DEBUG::2012-11-27 10:32:54,136::task::817::TaskManager.Task::(resourceAcquired) Task=`01d94b4b-4375-4ecb-898e-2cc6c9f072a9`::_resourcesAcquired: Storage.0149d080-a94c-446d-969c-eef7da5f6706 (shared)
>    Thread-16::DEBUG::2012-11-27 10:32:54,136::task::978::TaskManager.Task::(_decref) Task=`01d94b4b-4375-4ecb-898e-2cc6c9f072a9`::ref 1 aborting False
>    Thread-16::DEBUG::2012-11-27 10:32:54,139::fileVolume::535::Storage.Volume::(validateVolumePath) validate path for 73380a26-37b4-4f24-979c-4464d8b4401c
>    Thread-16::DEBUG::2012-11-27 10:32:54,141::fileVolume::535::Storage.Volume::(validateVolumePath) validate path for 73380a26-37b4-4f24-979c-4464d8b4401c
>    Thread-16::INFO::2012-11-27 10:32:54,142::logUtils::39::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '1633136640', 'apparentsize': '4294967296'}
>    Thread-16::DEBUG::2012-11-27 10:32:54,143::task::1172::TaskManager.Task::(prepare) Task=`01d94b4b-4375-4ecb-898e-2cc6c9f072a9`::finished: {'truesize': '1633136640', 'apparentsize': '4294967296'}
>    Thread-16::DEBUG::2012-11-27 10:32:54,143::task::588::TaskManager.Task::(_updateState) Task=`01d94b4b-4375-4ecb-898e-2cc6c9f072a9`::moving from state preparing -> state finished
>    Thread-16::DEBUG::2012-11-27 10:32:54,143::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.0149d080-a94c-446d-969c-eef7da5f6706': < ResourceRef 'Storage.0149d080-a94c-446d-969c-eef7da5f6706', isValid: 'True' obj: 'None'>}
>    Thread-16::DEBUG::2012-11-27 10:32:54,143::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>    Thread-16::DEBUG::2012-11-27 10:32:54,143::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.0149d080-a94c-446d-969c-eef7da5f6706'
>    Thread-16::DEBUG::2012-11-27 10:32:54,144::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.0149d080-a94c-446d-969c-eef7da5f6706' (0 active users)
>    Thread-16::DEBUG::2012-11-27 10:32:54,144::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.0149d080-a94c-446d-969c-eef7da5f6706' is free, finding out if anyone is waiting for it.
>    Thread-16::DEBUG::2012-11-27 10:32:54,144::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.0149d080-a94c-446d-969c-eef7da5f6706', Clearing records.
>    Thread-16::DEBUG::2012-11-27 10:32:54,144::task::978::TaskManager.Task::(_decref) Task=`01d94b4b-4375-4ecb-898e-2cc6c9f072a9`::ref 0 aborting False
>    VM Channels Listener::DEBUG::2012-11-27 10:32:54,928::vmChannels::60::vds::(_handle_timeouts) Timeout on fileno 22.
>    Thread-374::DEBUG::2012-11-27 10:32:57,087::BindingXMLRPC::156::vds::(wrapper) [192.168.2.113]
>    Thread-374::DEBUG::2012-11-27 10:32:57,088::task::588::TaskManager.Task::(_updateState) Task=`a72aabe5-afc4-48c5-b03f-0752e1b0ae69`::moving from state init -> state preparing
>    Thread-374::INFO::2012-11-27 10:32:57,088::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='25f8442c-bb4e-4f72-a66a-35715f149300', options=None)
>    Thread-374::INFO::2012-11-27 10:32:57,088::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 11}}
>    Thread-374::DEBUG::2012-11-27 10:32:57,088::task::1172::TaskManager.Task::(prepare) Task=`a72aabe5-afc4-48c5-b03f-0752e1b0ae69`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 11}}
>    Thread-374::DEBUG::2012-11-27 10:32:57,089::task::588::TaskManager.Task::(_updateState) Task=`a72aabe5-afc4-48c5-b03f-0752e1b0ae69`::moving from state preparing -> state finished
>    Thread-374::DEBUG::2012-11-27 10:32:57,089::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>    Thread-374::DEBUG::2012-11-27 10:32:57,089::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>    Thread-374::DEBUG::2012-11-27 10:32:57,089::task::978::TaskManager.Task::(_decref) Task=`a72aabe5-afc4-48c5-b03f-0752e1b0ae69`::ref 0 aborting False
>    Thread-375::DEBUG::2012-11-27 10:32:57,108::BindingXMLRPC::156::vds::(wrapper) [192.168.2.113]
>    Thread-375::DEBUG::2012-11-27 10:32:57,108::task::588::TaskManager.Task::(_updateState) Task=`0edd993d-7d61-413e-83b8-8faf1fbcbbb7`::moving from state init -> state preparing
>    Thread-375::INFO::2012-11-27 10:32:57,109::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='25f8442c-bb4e-4f72-a66a-35715f149300', options=None)
>    Thread-375::DEBUG::2012-11-27 10:32:57,109::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.25f8442c-bb4e-4f72-a66a-35715f149300`ReqID=`eddf5fd0-0fd6-4268-bf83-68e69bcbafac`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>    Thread-375::DEBUG::2012-11-27 10:32:57,109::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300' for lock type 'shared'
>    Thread-375::DEBUG::2012-11-27 10:32:57,109::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300' is free. Now locking as 'shared' (1 active user)
>    Thread-375::DEBUG::2012-11-27 10:32:57,110::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.25f8442c-bb4e-4f72-a66a-35715f149300`ReqID=`eddf5fd0-0fd6-4268-bf83-68e69bcbafac`::Granted request
>    Thread-375::DEBUG::2012-11-27 10:32:57,111::task::817::TaskManager.Task::(resourceAcquired) Task=`0edd993d-7d61-413e-83b8-8faf1fbcbbb7`::_resourcesAcquired: Storage.25f8442c-bb4e-4f72-a66a-35715f149300 (shared)
>    Thread-375::DEBUG::2012-11-27 10:32:57,111::task::978::TaskManager.Task::(_decref) Task=`0edd993d-7d61-413e-83b8-8faf1fbcbbb7`::ref 1 aborting False
>    Thread-375::INFO::2012-11-27 10:32:57,117::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': '0149d080-a94c-446d-969c-eef7da5f6706', 'name': 'MuntCenter', 'version': '0', 'domains': '3d40cf03-891e-471e-93ce-7e7970f73723:Active,0149d080-a94c-446d-969c-eef7da5f6706:Active', 'pool_status': 'connected', 'isoprefix': '/rhev/data-center/25f8442c-bb4e-4f72-a66a-35715f149300/3d40cf03-891e-471e-93ce-7e7970f73723/images/11111111-1111-1111-1111-111111111111', 'type': 'NFS', 'master_ver': 1, 'lver': 11}, 'dominfo': {'3d40cf03-891e-471e-93ce-7e7970f73723': {'status': 'Active', 'diskfree': '18295816192', 'alerts': [], 'disktotal': '21137981440'}, '0149d080-a94c-446d-969c-eef7da5f6706': {'status': 'Active', 'diskfree': '355573694464', 'alerts': [], 'disktotal': '433102258176'}}}
>    Thread-375::DEBUG::2012-11-27 10:32:57,117::task::1172::TaskManager.Task::(prepare) Task=`0edd993d-7d61-413e-83b8-8faf1fbcbbb7`::finished: {'info': {'spm_id': 1, 'master_uuid': '0149d080-a94c-446d-969c-eef7da5f6706', 'name': 'MuntCenter', 'version': '0', 'domains': '3d40cf03-891e-471e-93ce-7e7970f73723:Active,0149d080-a94c-446d-969c-eef7da5f6706:Active', 'pool_status': 'connected', 'isoprefix': '/rhev/data-center/25f8442c-bb4e-4f72-a66a-35715f149300/3d40cf03-891e-471e-93ce-7e7970f73723/images/11111111-1111-1111-1111-111111111111', 'type': 'NFS', 'master_ver': 1, 'lver': 11}, 'dominfo': {'3d40cf03-891e-471e-93ce-7e7970f73723': {'status': 'Active', 'diskfree': '18295816192', 'alerts': [], 'disktotal': '21137981440'}, '0149d080-a94c-446d-969c-eef7da5f6706': {'status': 'Active', 'diskfree': '355573694464', 'alerts': [], 'disktotal': '433102258176'}}}
>    Thread-375::DEBUG::2012-11-27 10:32:57,117::task::588::TaskManager.Task::(_updateState) Task=`0edd993d-7d61-413e-83b8-8faf1fbcbbb7`::moving from state preparing -> state finished
>    Thread-375::DEBUG::2012-11-27 10:32:57,117::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.25f8442c-bb4e-4f72-a66a-35715f149300': < ResourceRef 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300', isValid: 'True' obj: 'None'>}
>    Thread-375::DEBUG::2012-11-27 10:32:57,117::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>    Thread-375::DEBUG::2012-11-27 10:32:57,117::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300'
>    Thread-375::DEBUG::2012-11-27 10:32:57,117::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300' (0 active users)
>    Thread-375::DEBUG::2012-11-27 10:32:57,117::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300' is free, finding out if anyone is waiting for it.
>    Thread-375::DEBUG::2012-11-27 10:32:57,117::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300', Clearing records.
>    Thread-375::DEBUG::2012-11-27 10:32:57,118::task::978::TaskManager.Task::(_decref) Task=`0edd993d-7d61-413e-83b8-8faf1fbcbbb7`::ref 0 aborting False
>    Thread-377::DEBUG::2012-11-27 10:33:00,367::task::588::TaskManager.Task::(_updateState) Task=`77864712-cc0e-43b2-9cb3-0042ea48f4e0`::moving from state init -> state preparing
>    Thread-377::INFO::2012-11-27 10:33:00,368::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>    Thread-377::INFO::2012-11-27 10:33:00,368::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'3d40cf03-891e-471e-93ce-7e7970f73723': {'delay': '0.00268697738647', 'lastCheck': 1354008775.970663, 'code': 0, 'valid': True}, '0149d080-a94c-446d-969c-eef7da5f6706': {'delay': '0.00148797035217', 'lastCheck': 1354008775.974523, 'code': 0, 'valid': True}}
>    Thread-377::DEBUG::2012-11-27 10:33:00,368::task::1172::TaskManager.Task::(prepare) Task=`77864712-cc0e-43b2-9cb3-0042ea48f4e0`::finished: {'3d40cf03-891e-471e-93ce-7e7970f73723': {'delay': '0.00268697738647', 'lastCheck': 1354008775.970663, 'code': 0, 'valid': True}, '0149d080-a94c-446d-969c-eef7da5f6706': {'delay': '0.00148797035217', 'lastCheck': 1354008775.974523, 'code': 0, 'valid': True}}
>    Thread-377::DEBUG::2012-11-27 10:33:00,368::task::588::TaskManager.Task::(_updateState) Task=`77864712-cc0e-43b2-9cb3-0042ea48f4e0`::moving from state preparing -> state finished
>    Thread-377::DEBUG::2012-11-27 10:33:00,369::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>    Thread-377::DEBUG::2012-11-27 10:33:00,369::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>    Thread-377::DEBUG::2012-11-27 10:33:00,369::task::978::TaskManager.Task::(_decref) Task=`77864712-cc0e-43b2-9cb3-0042ea48f4e0`::ref 0 aborting False
>    Thread-378::DEBUG::2012-11-27 10:33:00,395::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`28efde72-eecc-4714-928e-c86e3da0f7a0`::Disk hdc stats not available
>    Thread-382::DEBUG::2012-11-27 10:33:07,230::BindingXMLRPC::156::vds::(wrapper) [192.168.2.113]
>    Thread-382::DEBUG::2012-11-27 10:33:07,230::task::588::TaskManager.Task::(_updateState) Task=`ea36a034-09c4-4037-ad20-aad9ae9ccb23`::moving from state init -> state preparing
>    Thread-382::INFO::2012-11-27 10:33:07,230::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='25f8442c-bb4e-4f72-a66a-35715f149300', options=None)
>    Thread-382::INFO::2012-11-27 10:33:07,231::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 11}}
>    Thread-382::DEBUG::2012-11-27 10:33:07,231::task::1172::TaskManager.Task::(prepare) Task=`ea36a034-09c4-4037-ad20-aad9ae9ccb23`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 11}}
>    Thread-382::DEBUG::2012-11-27 10:33:07,231::task::588::TaskManager.Task::(_updateState) Task=`ea36a034-09c4-4037-ad20-aad9ae9ccb23`::moving from state preparing -> state finished
>    Thread-382::DEBUG::2012-11-27 10:33:07,231::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>    Thread-382::DEBUG::2012-11-27 10:33:07,231::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>    Thread-382::DEBUG::2012-11-27 10:33:07,231::task::978::TaskManager.Task::(_decref) Task=`ea36a034-09c4-4037-ad20-aad9ae9ccb23`::ref 0 aborting False
>    Thread-383::DEBUG::2012-11-27 10:33:07,254::BindingXMLRPC::156::vds::(wrapper) [192.168.2.113]
>    Thread-383::DEBUG::2012-11-27 10:33:07,254::task::588::TaskManager.Task::(_updateState) Task=`5fbf21c8-33bf-4dd7-8508-aa479ac690ef`::moving from state init -> state preparing
>    Thread-383::INFO::2012-11-27 10:33:07,254::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='25f8442c-bb4e-4f72-a66a-35715f149300', options=None)
>    Thread-383::DEBUG::2012-11-27 10:33:07,255::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.25f8442c-bb4e-4f72-a66a-35715f149300`ReqID=`5183a60d-47f7-4ff2-9a31-aeedd494c86a`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>    Thread-383::DEBUG::2012-11-27 10:33:07,255::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300' for lock type 'shared'
>    Thread-383::DEBUG::2012-11-27 10:33:07,255::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300' is free. Now locking as 'shared' (1 active user)
>    Thread-383::DEBUG::2012-11-27 10:33:07,256::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.25f8442c-bb4e-4f72-a66a-35715f149300`ReqID=`5183a60d-47f7-4ff2-9a31-aeedd494c86a`::Granted request
>    Thread-383::DEBUG::2012-11-27 10:33:07,256::task::817::TaskManager.Task::(resourceAcquired) Task=`5fbf21c8-33bf-4dd7-8508-aa479ac690ef`::_resourcesAcquired: Storage.25f8442c-bb4e-4f72-a66a-35715f149300 (shared)
>    Thread-383::DEBUG::2012-11-27 10:33:07,256::task::978::TaskManager.Task::(_decref) Task=`5fbf21c8-33bf-4dd7-8508-aa479ac690ef`::ref 1 aborting False
>    Thread-383::INFO::2012-11-27 10:33:07,259::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': '0149d080-a94c-446d-969c-eef7da5f6706', 'name': 'MuntCenter', 'version': '0', 'domains': '3d40cf03-891e-471e-93ce-7e7970f73723:Active,0149d080-a94c-446d-969c-eef7da5f6706:Active', 'pool_status': 'connected', 'isoprefix': '/rhev/data-center/25f8442c-bb4e-4f72-a66a-35715f149300/3d40cf03-891e-471e-93ce-7e7970f73723/images/11111111-1111-1111-1111-111111111111', 'type': 'NFS', 'master_ver': 1, 'lver': 11}, 'dominfo': {'3d40cf03-891e-471e-93ce-7e7970f73723': {'status': 'Active', 'diskfree': '18295816192', 'alerts': [], 'disktotal': '21137981440'}, '0149d080-a94c-446d-969c-eef7da5f6706': {'status': 'Active', 'diskfree': '355573694464', 'alerts': [], 'disktotal': '433102258176'}}}
>    Thread-383::DEBUG::2012-11-27 10:33:07,259::task::1172::TaskManager.Task::(prepare) Task=`5fbf21c8-33bf-4dd7-8508-aa479ac690ef`::finished: {'info': {'spm_id': 1, 'master_uuid': '0149d080-a94c-446d-969c-eef7da5f6706', 'name': 'MuntCenter', 'version': '0', 'domains': '3d40cf03-891e-471e-93ce-7e7970f73723:Active,0149d080-a94c-446d-969c-eef7da5f6706:Active', 'pool_status': 'connected', 'isoprefix': '/rhev/data-center/25f8442c-bb4e-4f72-a66a-35715f149300/3d40cf03-891e-471e-93ce-7e7970f73723/images/11111111-1111-1111-1111-111111111111', 'type': 'NFS', 'master_ver': 1, 'lver': 11}, 'dominfo': {'3d40cf03-891e-471e-93ce-7e7970f73723': {'status': 'Active', 'diskfree': '18295816192', 'alerts': [], 'disktotal': '21137981440'}, '0149d080-a94c-446d-969c-eef7da5f6706': {'status': 'Active', 'diskfree': '355573694464', 'alerts': [], 'disktotal': '433102258176'}}}
>    Thread-383::DEBUG::2012-11-27 10:33:07,259::task::588::TaskManager.Task::(_updateState) Task=`5fbf21c8-33bf-4dd7-8508-aa479ac690ef`::moving from state preparing -> state finished
>    Thread-383::DEBUG::2012-11-27 10:33:07,259::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.25f8442c-bb4e-4f72-a66a-35715f149300': < ResourceRef 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300', isValid: 'True' obj: 'None'>}
>    Thread-383::DEBUG::2012-11-27 10:33:07,260::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>    Thread-383::DEBUG::2012-11-27 10:33:07,260::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300'
>    Thread-383::DEBUG::2012-11-27 10:33:07,260::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300' (0 active users)
>    Thread-383::DEBUG::2012-11-27 10:33:07,260::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300' is free, finding out if anyone is waiting for it.
>    Thread-383::DEBUG::2012-11-27 10:33:07,260::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300', Clearing records.
>    Thread-383::DEBUG::2012-11-27 10:33:07,260::task::978::TaskManager.Task::(_decref) Task=`5fbf21c8-33bf-4dd7-8508-aa479ac690ef`::ref 0 aborting False
>    Thread-385::DEBUG::2012-11-27 10:33:10,659::task::588::TaskManager.Task::(_updateState) Task=`b895f2f4-d805-436a-981b-21155af296ba`::moving from state init -> state preparing
>    Thread-385::INFO::2012-11-27 10:33:10,659::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>    Thread-385::INFO::2012-11-27 10:33:10,660::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'3d40cf03-891e-471e-93ce-7e7970f73723': {'delay': '0.00194311141968', 'lastCheck': 1354008785.985037, 'code': 0, 'valid': True}, '0149d080-a94c-446d-969c-eef7da5f6706': {'delay': '0.00174689292908', 'lastCheck': 1354008785.988694, 'code': 0, 'valid': True}}
>    Thread-385::DEBUG::2012-11-27 10:33:10,660::task::1172::TaskManager.Task::(prepare) Task=`b895f2f4-d805-436a-981b-21155af296ba`::finished: {'3d40cf03-891e-471e-93ce-7e7970f73723': {'delay': '0.00194311141968', 'lastCheck': 1354008785.985037, 'code': 0, 'valid': True}, '0149d080-a94c-446d-969c-eef7da5f6706': {'delay': '0.00174689292908', 'lastCheck': 1354008785.988694, 'code': 0, 'valid': True}}
>    Thread-385::DEBUG::2012-11-27 10:33:10,660::task::588::TaskManager.Task::(_updateState) Task=`b895f2f4-d805-436a-981b-21155af296ba`::moving from state preparing -> state finished
>    Thread-385::DEBUG::2012-11-27 10:33:10,660::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>    Thread-385::DEBUG::2012-11-27 10:33:10,660::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>    Thread-385::DEBUG::2012-11-27 10:33:10,660::task::978::TaskManager.Task::(_decref) Task=`b895f2f4-d805-436a-981b-21155af296ba`::ref 0 aborting False
>    Thread-386::DEBUG::2012-11-27 10:33:10,686::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`28efde72-eecc-4714-928e-c86e3da0f7a0`::Disk hdc stats not available
>    Thread-390::DEBUG::2012-11-27 10:33:17,368::BindingXMLRPC::156::vds::(wrapper) [192.168.2.113]
>    Thread-390::DEBUG::2012-11-27 10:33:17,368::task::588::TaskManager.Task::(_updateState) Task=`9b87f467-0447-40a6-9bbb-de6b863192db`::moving from state init -> state preparing
>    Thread-390::INFO::2012-11-27 10:33:17,368::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='25f8442c-bb4e-4f72-a66a-35715f149300', options=None)
>    Thread-390::INFO::2012-11-27 10:33:17,369::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 11}}
>    Thread-390::DEBUG::2012-11-27 10:33:17,369::task::1172::TaskManager.Task::(prepare) Task=`9b87f467-0447-40a6-9bbb-de6b863192db`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 11}}
>    Thread-390::DEBUG::2012-11-27 10:33:17,369::task::588::TaskManager.Task::(_updateState) Task=`9b87f467-0447-40a6-9bbb-de6b863192db`::moving from state preparing -> state finished
>    Thread-390::DEBUG::2012-11-27 10:33:17,369::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>    Thread-390::DEBUG::2012-11-27 10:33:17,369::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>    Thread-390::DEBUG::2012-11-27 10:33:17,370::task::978::TaskManager.Task::(_decref) Task=`9b87f467-0447-40a6-9bbb-de6b863192db`::ref 0 aborting False
>    Thread-391::DEBUG::2012-11-27 10:33:17,389::BindingXMLRPC::156::vds::(wrapper) [192.168.2.113]
>    Thread-391::DEBUG::2012-11-27 10:33:17,389::task::588::TaskManager.Task::(_updateState) Task=`092b3ffd-99bf-47a3-b6d3-f50a57116183`::moving from state init -> state preparing
>    Thread-391::INFO::2012-11-27 10:33:17,390::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='25f8442c-bb4e-4f72-a66a-35715f149300', options=None)
>    Thread-391::DEBUG::2012-11-27 10:33:17,390::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.25f8442c-bb4e-4f72-a66a-35715f149300`ReqID=`5f2645ee-c9e6-4f99-8373-0910277b48e7`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>    Thread-391::DEBUG::2012-11-27 10:33:17,390::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300' for lock type 'shared'
>    Thread-391::DEBUG::2012-11-27 10:33:17,391::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300' is free. Now locking as 'shared' (1 active user)
>    Thread-391::DEBUG::2012-11-27 10:33:17,391::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.25f8442c-bb4e-4f72-a66a-35715f149300`ReqID=`5f2645ee-c9e6-4f99-8373-0910277b48e7`::Granted request
>    Thread-391::DEBUG::2012-11-27 10:33:17,391::task::817::TaskManager.Task::(resourceAcquired) Task=`092b3ffd-99bf-47a3-b6d3-f50a57116183`::_resourcesAcquired: Storage.25f8442c-bb4e-4f72-a66a-35715f149300 (shared)
>    Thread-391::DEBUG::2012-11-27 10:33:17,391::task::978::TaskManager.Task::(_decref) Task=`092b3ffd-99bf-47a3-b6d3-f50a57116183`::ref 1 aborting False
>    Thread-391::INFO::2012-11-27 10:33:17,397::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': '0149d080-a94c-446d-969c-eef7da5f6706', 'name': 'MuntCenter', 'version': '0', 'domains': '3d40cf03-891e-471e-93ce-7e7970f73723:Active,0149d080-a94c-446d-969c-eef7da5f6706:Active', 'pool_status': 'connected', 'isoprefix': '/rhev/data-center/25f8442c-bb4e-4f72-a66a-35715f149300/3d40cf03-891e-471e-93ce-7e7970f73723/images/11111111-1111-1111-1111-111111111111', 'type': 'NFS', 'master_ver': 1, 'lver': 11}, 'dominfo': {'3d40cf03-891e-471e-93ce-7e7970f73723': {'status': 'Active', 'diskfree': '18295816192', 'alerts': [], 'disktotal': '21137981440'}, '0149d080-a94c-446d-969c-eef7da5f6706': {'status': 'Active', 'diskfree': '355573694464', 'alerts': [], 'disktotal': '433102258176'}}}
>    Thread-391::DEBUG::2012-11-27 10:33:17,397::task::1172::TaskManager.Task::(prepare) Task=`092b3ffd-99bf-47a3-b6d3-f50a57116183`::finished: {'info': {'spm_id': 1, 'master_uuid': '0149d080-a94c-446d-969c-eef7da5f6706', 'name': 'MuntCenter', 'version': '0', 'domains': '3d40cf03-891e-471e-93ce-7e7970f73723:Active,0149d080-a94c-446d-969c-eef7da5f6706:Active', 'pool_status': 'connected', 'isoprefix': '/rhev/data-center/25f8442c-bb4e-4f72-a66a-35715f149300/3d40cf03-891e-471e-93ce-7e7970f73723/images/11111111-1111-1111-1111-111111111111', 'type': 'NFS', 'master_ver': 1, 'lver': 11}, 'dominfo': {'3d40cf03-891e-471e-93ce-7e7970f73723': {'status': 'Active', 'diskfree': '18295816192', 'alerts': [], 'disktotal': '21137981440'}, '0149d080-a94c-446d-969c-eef7da5f6706': {'status': 'Active', 'diskfree': '355573694464', 'alerts': [], 'disktotal': '433102258176'}}}
>    Thread-391::DEBUG::2012-11-27 10:33:17,397::task::588::TaskManager.Task::(_updateState) Task=`092b3ffd-99bf-47a3-b6d3-f50a57116183`::moving from state preparing -> state finished
>    Thread-391::DEBUG::2012-11-27 10:33:17,397::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.25f8442c-bb4e-4f72-a66a-35715f149300': < ResourceRef 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300', isValid: 'True' obj: 'None'>}
>    Thread-391::DEBUG::2012-11-27 10:33:17,397::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>    Thread-391::DEBUG::2012-11-27 10:33:17,397::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300'
>    Thread-391::DEBUG::2012-11-27 10:33:17,397::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300' (0 active users)
>    Thread-391::DEBUG::2012-11-27 10:33:17,398::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300' is free, finding out if anyone is waiting for it.
>    Thread-391::DEBUG::2012-11-27 10:33:17,398::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300', Clearing records.
>    Thread-391::DEBUG::2012-11-27 10:33:17,398::task::978::TaskManager.Task::(_decref) Task=`092b3ffd-99bf-47a3-b6d3-f50a57116183`::ref 0 aborting False
>    Thread-393::DEBUG::2012-11-27 10:33:20,960::task::588::TaskManager.Task::(_updateState) Task=`81eff578-0f0b-4f40-88e0-df9911d5c0a7`::moving from state init -> state preparing
>    Thread-393::INFO::2012-11-27 10:33:20,960::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>    Thread-393::INFO::2012-11-27 10:33:20,960::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'3d40cf03-891e-471e-93ce-7e7970f73723': {'delay': '0.00198292732239', 'lastCheck': 1354008795.999165, 'code': 0, 'valid': True}, '0149d080-a94c-446d-969c-eef7da5f6706': {'delay': '0.00162196159363', 'lastCheck': 1354008796.003627, 'code': 0, 'valid': True}}
>    Thread-393::DEBUG::2012-11-27 10:33:20,961::task::1172::TaskManager.Task::(prepare) Task=`81eff578-0f0b-4f40-88e0-df9911d5c0a7`::finished: {'3d40cf03-891e-471e-93ce-7e7970f73723': {'delay': '0.00198292732239', 'lastCheck': 1354008795.999165, 'code': 0, 'valid': True}, '0149d080-a94c-446d-969c-eef7da5f6706': {'delay': '0.00162196159363', 'lastCheck': 1354008796.003627, 'code': 0, 'valid': True}}
>    Thread-393::DEBUG::2012-11-27 10:33:20,961::task::588::TaskManager.Task::(_updateState) Task=`81eff578-0f0b-4f40-88e0-df9911d5c0a7`::moving from state preparing -> state finished
>    Thread-393::DEBUG::2012-11-27 10:33:20,961::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>    Thread-393::DEBUG::2012-11-27 10:33:20,961::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>    Thread-393::DEBUG::2012-11-27 10:33:20,961::task::978::TaskManager.Task::(_decref) Task=`81eff578-0f0b-4f40-88e0-df9911d5c0a7`::ref 0 aborting False
>    Thread-394::DEBUG::2012-11-27 10:33:20,988::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`28efde72-eecc-4714-928e-c86e3da0f7a0`::Disk hdc stats not available
>    VM Channels Listener::DEBUG::2012-11-27 10:33:24,960::vmChannels::60::vds::(_handle_timeouts) Timeout on fileno 22.
>    Thread-398::DEBUG::2012-11-27 10:33:27,505::BindingXMLRPC::156::vds::(wrapper) [192.168.2.113]
>    Thread-398::DEBUG::2012-11-27 10:33:27,506::task::588::TaskManager.Task::(_updateState) Task=`b4661243-237a-4c2b-9fa2-a3c3cfec7557`::moving from state init -> state preparing
>    Thread-398::INFO::2012-11-27 10:33:27,506::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='25f8442c-bb4e-4f72-a66a-35715f149300', options=None)
>    Thread-398::INFO::2012-11-27 10:33:27,506::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 11}}
>    Thread-398::DEBUG::2012-11-27 10:33:27,506::task::1172::TaskManager.Task::(prepare) Task=`b4661243-237a-4c2b-9fa2-a3c3cfec7557`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 11}}
>    Thread-398::DEBUG::2012-11-27 10:33:27,507::task::588::TaskManager.Task::(_updateState) Task=`b4661243-237a-4c2b-9fa2-a3c3cfec7557`::moving from state preparing -> state finished
>    Thread-398::DEBUG::2012-11-27 10:33:27,507::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>    Thread-398::DEBUG::2012-11-27 10:33:27,507::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>    Thread-398::DEBUG::2012-11-27 10:33:27,507::task::978::TaskManager.Task::(_decref) Task=`b4661243-237a-4c2b-9fa2-a3c3cfec7557`::ref 0 aborting False
>    Thread-399::DEBUG::2012-11-27 10:33:27,526::BindingXMLRPC::156::vds::(wrapper) [192.168.2.113]
>    Thread-399::DEBUG::2012-11-27 10:33:27,526::task::588::TaskManager.Task::(_updateState) Task=`efac33f4-f0cf-4290-aca6-ab66bb0430eb`::moving from state init -> state preparing
>    Thread-399::INFO::2012-11-27 10:33:27,527::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='25f8442c-bb4e-4f72-a66a-35715f149300', options=None)
>    Thread-399::DEBUG::2012-11-27 10:33:27,527::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.25f8442c-bb4e-4f72-a66a-35715f149300`ReqID=`3c2eb4b9-a56e-4f05-97bc-645462e242cb`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>    Thread-399::DEBUG::2012-11-27 10:33:27,527::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300' for lock type 'shared'
>    Thread-399::DEBUG::2012-11-27 10:33:27,528::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300' is free. Now locking as 'shared' (1 active user)
>    Thread-399::DEBUG::2012-11-27 10:33:27,528::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.25f8442c-bb4e-4f72-a66a-35715f149300`ReqID=`3c2eb4b9-a56e-4f05-97bc-645462e242cb`::Granted request
>    Thread-399::DEBUG::2012-11-27 10:33:27,528::task::817::TaskManager.Task::(resourceAcquired) Task=`efac33f4-f0cf-4290-aca6-ab66bb0430eb`::_resourcesAcquired: Storage.25f8442c-bb4e-4f72-a66a-35715f149300 (shared)
>    Thread-399::DEBUG::2012-11-27 10:33:27,528::task::978::TaskManager.Task::(_decref) Task=`efac33f4-f0cf-4290-aca6-ab66bb0430eb`::ref 1 aborting False
>    Thread-399::INFO::2012-11-27 10:33:27,535::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': '0149d080-a94c-446d-969c-eef7da5f6706', 'name': 'MuntCenter', 'version': '0', 'domains': '3d40cf03-891e-471e-93ce-7e7970f73723:Active,0149d080-a94c-446d-969c-eef7da5f6706:Active', 'pool_status': 'connected', 'isoprefix': '/rhev/data-center/25f8442c-bb4e-4f72-a66a-35715f149300/3d40cf03-891e-471e-93ce-7e7970f73723/images/11111111-1111-1111-1111-111111111111', 'type': 'NFS', 'master_ver': 1, 'lver': 11}, 'dominfo': {'3d40cf03-891e-471e-93ce-7e7970f73723': {'status': 'Active', 'diskfree': '18295816192', 'alerts': [], 'disktotal': '21137981440'}, '0149d080-a94c-446d-969c-eef7da5f6706': {'status': 'Active', 'diskfree': '355573694464', 'alerts': [], 'disktotal': '433102258176'}}}
>    Thread-399::DEBUG::2012-11-27 10:33:27,536::task::1172::TaskManager.Task::(prepare) Task=`efac33f4-f0cf-4290-aca6-ab66bb0430eb`::finished: {'info': {'spm_id': 1, 'master_uuid': '0149d080-a94c-446d-969c-eef7da5f6706', 'name': 'MuntCenter', 'version': '0', 'domains': '3d40cf03-891e-471e-93ce-7e7970f73723:Active,0149d080-a94c-446d-969c-eef7da5f6706:Active', 'pool_status': 'connected', 'isoprefix': '/rhev/data-center/25f8442c-bb4e-4f72-a66a-35715f149300/3d40cf03-891e-471e-93ce-7e7970f73723/images/11111111-1111-1111-1111-111111111111', 'type': 'NFS', 'master_ver': 1, 'lver': 11}, 'dominfo': {'3d40cf03-891e-471e-93ce-7e7970f73723': {'status': 'Active', 'diskfree': '18295816192', 'alerts': [], 'disktotal': '21137981440'}, '0149d080-a94c-446d-969c-eef7da5f6706': {'status': 'Active', 'diskfree': '355573694464', 'alerts': [], 'disktotal': '433102258176'}}}
>    Thread-399::DEBUG::2012-11-27 10:33:27,536::task::588::TaskManager.Task::(_updateState) Task=`efac33f4-f0cf-4290-aca6-ab66bb0430eb`::moving from state preparing -> state finished
>    Thread-399::DEBUG::2012-11-27 10:33:27,536::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.25f8442c-bb4e-4f72-a66a-35715f149300': < ResourceRef 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300', isValid: 'True' obj: 'None'>}
>    Thread-399::DEBUG::2012-11-27 10:33:27,536::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>    Thread-399::DEBUG::2012-11-27 10:33:27,536::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300'
>    Thread-399::DEBUG::2012-11-27 10:33:27,536::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300' (0 active users)
>    Thread-399::DEBUG::2012-11-27 10:33:27,536::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300' is free, finding out if anyone is waiting for it.
>    Thread-399::DEBUG::2012-11-27 10:33:27,536::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300', Clearing records.
>    Thread-399::DEBUG::2012-11-27 10:33:27,536::task::978::TaskManager.Task::(_decref) Task=`efac33f4-f0cf-4290-aca6-ab66bb0430eb`::ref 0 aborting False
>    Thread-401::DEBUG::2012-11-27 10:33:31,221::task::588::TaskManager.Task::(_updateState) Task=`b41f0fc8-3157-4c7a-9dd8-0169f4cb2cc0`::moving from state init -> state preparing
>    Thread-401::INFO::2012-11-27 10:33:31,222::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>    Thread-401::INFO::2012-11-27 10:33:31,222::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'3d40cf03-891e-471e-93ce-7e7970f73723': {'delay': '0.00276017189026', 'lastCheck': 1354008806.012811, 'code': 0, 'valid': True}, '0149d080-a94c-446d-969c-eef7da5f6706': {'delay': '0.00170493125916', 'lastCheck': 1354008806.016785, 'code': 0, 'valid': True}}
>    Thread-401::DEBUG::2012-11-27 10:33:31,222::task::1172::TaskManager.Task::(prepare) Task=`b41f0fc8-3157-4c7a-9dd8-0169f4cb2cc0`::finished: {'3d40cf03-891e-471e-93ce-7e7970f73723': {'delay': '0.00276017189026', 'lastCheck': 1354008806.012811, 'code': 0, 'valid': True}, '0149d080-a94c-446d-969c-eef7da5f6706': {'delay': '0.00170493125916', 'lastCheck': 1354008806.016785, 'code': 0, 'valid': True}}
>    Thread-401::DEBUG::2012-11-27 10:33:31,222::task::588::TaskManager.Task::(_updateState) Task=`b41f0fc8-3157-4c7a-9dd8-0169f4cb2cc0`::moving from state preparing -> state finished
>    Thread-401::DEBUG::2012-11-27 10:33:31,222::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>    Thread-401::DEBUG::2012-11-27 10:33:31,223::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>    Thread-401::DEBUG::2012-11-27 10:33:31,223::task::978::TaskManager.Task::(_decref) Task=`b41f0fc8-3157-4c7a-9dd8-0169f4cb2cc0`::ref 0 aborting False
>    Thread-402::DEBUG::2012-11-27 10:33:31,242::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`28efde72-eecc-4714-928e-c86e3da0f7a0`::Disk hdc stats not available
>    Thread-406::DEBUG::2012-11-27 10:33:37,639::BindingXMLRPC::156::vds::(wrapper) [192.168.2.113]
>    Thread-406::DEBUG::2012-11-27 10:33:37,639::task::588::TaskManager.Task::(_updateState) Task=`7d55d137-bf5f-48d9-946e-e31b8f279456`::moving from state init -> state preparing
>    Thread-406::INFO::2012-11-27 10:33:37,639::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='25f8442c-bb4e-4f72-a66a-35715f149300', options=None)
>    Thread-406::INFO::2012-11-27 10:33:37,640::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 11}}
>    Thread-406::DEBUG::2012-11-27 10:33:37,640::task::1172::TaskManager.Task::(prepare) Task=`7d55d137-bf5f-48d9-946e-e31b8f279456`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 11}}
>    Thread-406::DEBUG::2012-11-27 10:33:37,640::task::588::TaskManager.Task::(_updateState) Task=`7d55d137-bf5f-48d9-946e-e31b8f279456`::moving from state preparing -> state finished
>    Thread-406::DEBUG::2012-11-27 10:33:37,640::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>    Thread-406::DEBUG::2012-11-27 10:33:37,640::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>    Thread-406::DEBUG::2012-11-27 10:33:37,641::task::978::TaskManager.Task::(_decref) Task=`7d55d137-bf5f-48d9-946e-e31b8f279456`::ref 0 aborting False
>    Thread-407::DEBUG::2012-11-27 10:33:37,655::BindingXMLRPC::156::vds::(wrapper) [192.168.2.113]
>    Thread-407::DEBUG::2012-11-27 10:33:37,655::task::588::TaskManager.Task::(_updateState) Task=`09cae17e-7e93-4893-817c-648ba2c1f91c`::moving from state init -> state preparing
>    Thread-407::INFO::2012-11-27 10:33:37,656::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='25f8442c-bb4e-4f72-a66a-35715f149300', options=None)
>    Thread-407::DEBUG::2012-11-27 10:33:37,656::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.25f8442c-bb4e-4f72-a66a-35715f149300`ReqID=`150cc248-6f33-409f-ac44-52b074e12324`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>    Thread-407::DEBUG::2012-11-27 10:33:37,656::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300' for lock type 'shared'
>    Thread-407::DEBUG::2012-11-27 10:33:37,657::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300' is free. Now locking as 'shared' (1 active user)
>    Thread-407::DEBUG::2012-11-27 10:33:37,657::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.25f8442c-bb4e-4f72-a66a-35715f149300`ReqID=`150cc248-6f33-409f-ac44-52b074e12324`::Granted request
>    Thread-407::DEBUG::2012-11-27 10:33:37,657::task::817::TaskManager.Task::(resourceAcquired) Task=`09cae17e-7e93-4893-817c-648ba2c1f91c`::_resourcesAcquired: Storage.25f8442c-bb4e-4f72-a66a-35715f149300 (shared)
>    Thread-407::DEBUG::2012-11-27 10:33:37,657::task::978::TaskManager.Task::(_decref) Task=`09cae17e-7e93-4893-817c-648ba2c1f91c`::ref 1 aborting False
>    Thread-407::INFO::2012-11-27 10:33:37,664::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': '0149d080-a94c-446d-969c-eef7da5f6706', 'name': 'MuntCenter', 'version': '0', 'domains': '3d40cf03-891e-471e-93ce-7e7970f73723:Active,0149d080-a94c-446d-969c-eef7da5f6706:Active', 'pool_status': 'connected', 'isoprefix': '/rhev/data-center/25f8442c-bb4e-4f72-a66a-35715f149300/3d40cf03-891e-471e-93ce-7e7970f73723/images/11111111-1111-1111-1111-111111111111', 'type': 'NFS', 'master_ver': 1, 'lver': 11}, 'dominfo': {'3d40cf03-891e-471e-93ce-7e7970f73723': {'status': 'Active', 'diskfree': '18295816192', 'alerts': [], 'disktotal': '21137981440'}, '0149d080-a94c-446d-969c-eef7da5f6706': {'status': 'Active', 'diskfree': '355573694464', 'alerts': [], 'disktotal': '433102258176'}}}
>    Thread-407::DEBUG::2012-11-27 10:33:37,665::task::1172::TaskManager.Task::(prepare) Task=`09cae17e-7e93-4893-817c-648ba2c1f91c`::finished: {'info': {'spm_id': 1, 'master_uuid': '0149d080-a94c-446d-969c-eef7da5f6706', 'name': 'MuntCenter', 'version': '0', 'domains': '3d40cf03-891e-471e-93ce-7e7970f73723:Active,0149d080-a94c-446d-969c-eef7da5f6706:Active', 'pool_status': 'connected', 'isoprefix': '/rhev/data-center/25f8442c-bb4e-4f72-a66a-35715f149300/3d40cf03-891e-471e-93ce-7e7970f73723/images/11111111-1111-1111-1111-111111111111', 'type': 'NFS', 'master_ver': 1, 'lver': 11}, 'dominfo': {'3d40cf03-891e-471e-93ce-7e7970f73723': {'status': 'Active', 'diskfree': '18295816192', 'alerts': [], 'disktotal': '21137981440'}, '0149d080-a94c-446d-969c-eef7da5f6706': {'status': 'Active', 'diskfree': '355573694464', 'alerts': [], 'disktotal': '433102258176'}}}
>    Thread-407::DEBUG::2012-11-27 10:33:37,665::task::588::TaskManager.Task::(_updateState) Task=`09cae17e-7e93-4893-817c-648ba2c1f91c`::moving from state preparing -> state finished
>    Thread-407::DEBUG::2012-11-27 10:33:37,665::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.25f8442c-bb4e-4f72-a66a-35715f149300': < ResourceRef 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300', isValid: 'True' obj: 'None'>}
>    Thread-407::DEBUG::2012-11-27 10:33:37,665::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>    Thread-407::DEBUG::2012-11-27 10:33:37,665::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300'
>    Thread-407::DEBUG::2012-11-27 10:33:37,666::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300' (0 active users)
>    Thread-407::DEBUG::2012-11-27 10:33:37,666::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300' is free, finding out if anyone is waiting for it.
>    Thread-407::DEBUG::2012-11-27 10:33:37,666::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300', Clearing records.
>    Thread-407::DEBUG::2012-11-27 10:33:37,666::task::978::TaskManager.Task::(_decref) Task=`09cae17e-7e93-4893-817c-648ba2c1f91c`::ref 0 aborting False
>    Thread-409::DEBUG::2012-11-27 10:33:41,490::task::588::TaskManager.Task::(_updateState) Task=`990e38d8-ed12-4db9-846d-c9c6fa6a60ac`::moving from state init -> state preparing
>    Thread-409::INFO::2012-11-27 10:33:41,490::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>    Thread-409::INFO::2012-11-27 10:33:41,491::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'3d40cf03-891e-471e-93ce-7e7970f73723': {'delay': '0.00271391868591', 'lastCheck': 1354008816.02483, 'code': 0, 'valid': True}, '0149d080-a94c-446d-969c-eef7da5f6706': {'delay': '0.00209283828735', 'lastCheck': 1354008816.030195, 'code': 0, 'valid': True}}
>    Thread-409::DEBUG::2012-11-27 10:33:41,491::task::1172::TaskManager.Task::(prepare) Task=`990e38d8-ed12-4db9-846d-c9c6fa6a60ac`::finished: {'3d40cf03-891e-471e-93ce-7e7970f73723': {'delay': '0.00271391868591', 'lastCheck': 1354008816.02483, 'code': 0, 'valid': True}, '0149d080-a94c-446d-969c-eef7da5f6706': {'delay': '0.00209283828735', 'lastCheck': 1354008816.030195, 'code': 0, 'valid': True}}
>    Thread-409::DEBUG::2012-11-27 10:33:41,491::task::588::TaskManager.Task::(_updateState) Task=`990e38d8-ed12-4db9-846d-c9c6fa6a60ac`::moving from state preparing -> state finished
>    Thread-409::DEBUG::2012-11-27 10:33:41,491::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>    Thread-409::DEBUG::2012-11-27 10:33:41,491::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>    Thread-409::DEBUG::2012-11-27 10:33:41,491::task::978::TaskManager.Task::(_decref) Task=`990e38d8-ed12-4db9-846d-c9c6fa6a60ac`::ref 0 aborting False
>    Thread-410::DEBUG::2012-11-27 10:33:41,518::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`28efde72-eecc-4714-928e-c86e3da0f7a0`::Disk hdc stats not available
>    Thread-414::DEBUG::2012-11-27 10:33:47,769::BindingXMLRPC::156::vds::(wrapper) [192.168.2.113]
>    Thread-414::DEBUG::2012-11-27 10:33:47,770::task::588::TaskManager.Task::(_updateState) Task=`a0750b78-7fdf-4718-822a-7b26274dfaa3`::moving from state init -> state preparing
>    Thread-414::INFO::2012-11-27 10:33:47,770::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='25f8442c-bb4e-4f72-a66a-35715f149300', options=None)
>    Thread-414::INFO::2012-11-27 10:33:47,770::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 11}}
>    Thread-414::DEBUG::2012-11-27 10:33:47,770::task::1172::TaskManager.Task::(prepare) Task=`a0750b78-7fdf-4718-822a-7b26274dfaa3`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 11}}
>    Thread-414::DEBUG::2012-11-27 10:33:47,771::task::588::TaskManager.Task::(_updateState) Task=`a0750b78-7fdf-4718-822a-7b26274dfaa3`::moving from state preparing -> state finished
>    Thread-414::DEBUG::2012-11-27 10:33:47,771::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>    Thread-414::DEBUG::2012-11-27 10:33:47,771::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>    Thread-414::DEBUG::2012-11-27 10:33:47,771::task::978::TaskManager.Task::(_decref) Task=`a0750b78-7fdf-4718-822a-7b26274dfaa3`::ref 0 aborting False
>    Thread-415::DEBUG::2012-11-27 10:33:47,789::BindingXMLRPC::156::vds::(wrapper) [192.168.2.113]
>    Thread-415::DEBUG::2012-11-27 10:33:47,789::task::588::TaskManager.Task::(_updateState) Task=`3607573d-4f09-48a3-ac2e-a660c1e4716e`::moving from state init -> state preparing
>    Thread-415::INFO::2012-11-27 10:33:47,789::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='25f8442c-bb4e-4f72-a66a-35715f149300', options=None)
>    Thread-415::DEBUG::2012-11-27 10:33:47,790::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.25f8442c-bb4e-4f72-a66a-35715f149300`ReqID=`0727c62f-ce9e-4d87-ad92-c71993b85db8`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>    Thread-415::DEBUG::2012-11-27 10:33:47,790::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300' for lock type 'shared'
>    Thread-415::DEBUG::2012-11-27 10:33:47,790::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300' is free. Now locking as 'shared' (1 active user)
>    Thread-415::DEBUG::2012-11-27 10:33:47,790::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.25f8442c-bb4e-4f72-a66a-35715f149300`ReqID=`0727c62f-ce9e-4d87-ad92-c71993b85db8`::Granted request
>    Thread-415::DEBUG::2012-11-27 10:33:47,790::task::817::TaskManager.Task::(resourceAcquired) Task=`3607573d-4f09-48a3-ac2e-a660c1e4716e`::_resourcesAcquired: Storage.25f8442c-bb4e-4f72-a66a-35715f149300 (shared)
>    Thread-415::DEBUG::2012-11-27 10:33:47,790::task::978::TaskManager.Task::(_decref) Task=`3607573d-4f09-48a3-ac2e-a660c1e4716e`::ref 1 aborting False
>    Thread-415::INFO::2012-11-27 10:33:47,794::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': '0149d080-a94c-446d-969c-eef7da5f6706', 'name': 'MuntCenter', 'version': '0', 'domains': '3d40cf03-891e-471e-93ce-7e7970f73723:Active,0149d080-a94c-446d-969c-eef7da5f6706:Active', 'pool_status': 'connected', 'isoprefix': '/rhev/data-center/25f8442c-bb4e-4f72-a66a-35715f149300/3d40cf03-891e-471e-93ce-7e7970f73723/images/11111111-1111-1111-1111-111111111111', 'type': 'NFS', 'master_ver': 1, 'lver': 11}, 'dominfo': {'3d40cf03-891e-471e-93ce-7e7970f73723': {'status': 'Active', 'diskfree': '18295816192', 'alerts': [], 'disktotal': '21137981440'}, '0149d080-a94c-446d-969c-eef7da5f6706': {'status': 'Active', 'diskfree': '355573694464', 'alerts': [], 'disktotal': '433102258176'}}}
>    Thread-415::DEBUG::2012-11-27 10:33:47,794::task::1172::TaskManager.Task::(prepare) Task=`3607573d-4f09-48a3-ac2e-a660c1e4716e`::finished: {'info': {'spm_id': 1, 'master_uuid': '0149d080-a94c-446d-969c-eef7da5f6706', 'name': 'MuntCenter', 'version': '0', 'domains': '3d40cf03-891e-471e-93ce-7e7970f73723:Active,0149d080-a94c-446d-969c-eef7da5f6706:Active', 'pool_status': 'connected', 'isoprefix': '/rhev/data-center/25f8442c-bb4e-4f72-a66a-35715f149300/3d40cf03-891e-471e-93ce-7e7970f73723/images/11111111-1111-1111-1111-111111111111', 'type': 'NFS', 'master_ver': 1, 'lver': 11}, 'dominfo': {'3d40cf03-891e-471e-93ce-7e7970f73723': {'status': 'Active', 'diskfree': '18295816192', 'alerts': [], 'disktotal': '21137981440'}, '0149d080-a94c-446d-969c-eef7da5f6706': {'status': 'Active', 'diskfree': '355573694464', 'alerts': [], 'disktotal': '433102258176'}}}
>    Thread-415::DEBUG::2012-11-27 10:33:47,794::task::588::TaskManager.Task::(_updateState) Task=`3607573d-4f09-48a3-ac2e-a660c1e4716e`::moving from state preparing -> state finished
>    Thread-415::DEBUG::2012-11-27 10:33:47,794::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.25f8442c-bb4e-4f72-a66a-35715f149300': < ResourceRef 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300', isValid: 'True' obj: 'None'>}
>    Thread-415::DEBUG::2012-11-27 10:33:47,794::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>    Thread-415::DEBUG::2012-11-27 10:33:47,794::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300'
>    Thread-415::DEBUG::2012-11-27 10:33:47,794::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300' (0 active users)
>    Thread-415::DEBUG::2012-11-27 10:33:47,794::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300' is free, finding out if anyone is waiting for it.
>    Thread-415::DEBUG::2012-11-27 10:33:47,794::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300', Clearing records.
>    Thread-415::DEBUG::2012-11-27 10:33:47,794::task::978::TaskManager.Task::(_decref) Task=`3607573d-4f09-48a3-ac2e-a660c1e4716e`::ref 0 aborting False
>    Thread-417::DEBUG::2012-11-27 10:33:51,759::task::588::TaskManager.Task::(_updateState) Task=`5e03c933-95a1-4bb3-b9bf-dee3ed4d21c0`::moving from state init -> state preparing
>    Thread-417::INFO::2012-11-27 10:33:51,759::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>    Thread-417::INFO::2012-11-27 10:33:51,759::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'3d40cf03-891e-471e-93ce-7e7970f73723': {'delay': '0.00275588035583', 'lastCheck': 1354008826.037707, 'code': 0, 'valid': True}, '0149d080-a94c-446d-969c-eef7da5f6706': {'delay': '0.00170803070068', 'lastCheck': 1354008826.041976, 'code': 0, 'valid': True}}
>    Thread-417::DEBUG::2012-11-27 10:33:51,759::task::1172::TaskManager.Task::(prepare) Task=`5e03c933-95a1-4bb3-b9bf-dee3ed4d21c0`::finished: {'3d40cf03-891e-471e-93ce-7e7970f73723': {'delay': '0.00275588035583', 'lastCheck': 1354008826.037707, 'code': 0, 'valid': True}, '0149d080-a94c-446d-969c-eef7da5f6706': {'delay': '0.00170803070068', 'lastCheck': 1354008826.041976, 'code': 0, 'valid': True}}
>    Thread-417::DEBUG::2012-11-27 10:33:51,760::task::588::TaskManager.Task::(_updateState) Task=`5e03c933-95a1-4bb3-b9bf-dee3ed4d21c0`::moving from state preparing -> state finished
>    Thread-417::DEBUG::2012-11-27 10:33:51,760::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>    Thread-417::DEBUG::2012-11-27 10:33:51,760::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>    Thread-417::DEBUG::2012-11-27 10:33:51,760::task::978::TaskManager.Task::(_decref) Task=`5e03c933-95a1-4bb3-b9bf-dee3ed4d21c0`::ref 0 aborting False
>    Thread-418::DEBUG::2012-11-27 10:33:51,786::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`28efde72-eecc-4714-928e-c86e3da0f7a0`::Disk hdc stats not available
>    Thread-16::DEBUG::2012-11-27 10:33:54,227::task::588::TaskManager.Task::(_updateState) Task=`70544935-fe66-4b32-9d2e-217cce096af7`::moving from state init -> state preparing
>    Thread-16::INFO::2012-11-27 10:33:54,227::logUtils::37::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='0149d080-a94c-446d-969c-eef7da5f6706', spUUID='25f8442c-bb4e-4f72-a66a-35715f149300', imgUUID='16dc8590-0538-4a32-8bf1-fb67ee33bc35', volUUID='73380a26-37b4-4f24-979c-4464d8b4401c', options=None)
>    Thread-16::DEBUG::2012-11-27 10:33:54,228::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.0149d080-a94c-446d-969c-eef7da5f6706`ReqID=`16a6e997-f80f-4037-981a-392eaa0c3fb9`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>    Thread-16::DEBUG::2012-11-27 10:33:54,228::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.0149d080-a94c-446d-969c-eef7da5f6706' for lock type 'shared'
>    Thread-16::DEBUG::2012-11-27 10:33:54,228::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.0149d080-a94c-446d-969c-eef7da5f6706' is free. Now locking as 'shared' (1 active user)
>    Thread-16::DEBUG::2012-11-27 10:33:54,228::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.0149d080-a94c-446d-969c-eef7da5f6706`ReqID=`16a6e997-f80f-4037-981a-392eaa0c3fb9`::Granted request
>    Thread-16::DEBUG::2012-11-27 10:33:54,229::task::817::TaskManager.Task::(resourceAcquired) Task=`70544935-fe66-4b32-9d2e-217cce096af7`::_resourcesAcquired: Storage.0149d080-a94c-446d-969c-eef7da5f6706 (shared)
>    Thread-16::DEBUG::2012-11-27 10:33:54,229::task::978::TaskManager.Task::(_decref) Task=`70544935-fe66-4b32-9d2e-217cce096af7`::ref 1 aborting False
>    VM Channels Listener::DEBUG::2012-11-27 10:33:54,993::vmChannels::60::vds::(_handle_timeouts) Timeout on fileno 22.
>    Thread-421::DEBUG::2012-11-27 10:33:57,892::BindingXMLRPC::156::vds::(wrapper) [192.168.2.113]
>    Thread-421::DEBUG::2012-11-27 10:33:57,892::task::588::TaskManager.Task::(_updateState) Task=`57c0e990-a36e-46d0-bfca-20cd16cb4b31`::moving from state init -> state preparing
>    Thread-421::INFO::2012-11-27 10:33:57,892::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='25f8442c-bb4e-4f72-a66a-35715f149300', options=None)
>    Thread-421::INFO::2012-11-27 10:33:57,893::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 11}}
>    Thread-421::DEBUG::2012-11-27 10:33:57,893::task::1172::TaskManager.Task::(prepare) Task=`57c0e990-a36e-46d0-bfca-20cd16cb4b31`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 11}}
>    Thread-421::DEBUG::2012-11-27 10:33:57,893::task::588::TaskManager.Task::(_updateState) Task=`57c0e990-a36e-46d0-bfca-20cd16cb4b31`::moving from state preparing -> state finished
>    Thread-421::DEBUG::2012-11-27 10:33:57,893::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>    Thread-421::DEBUG::2012-11-27 10:33:57,893::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>    Thread-421::DEBUG::2012-11-27 10:33:57,893::task::978::TaskManager.Task::(_decref) Task=`57c0e990-a36e-46d0-bfca-20cd16cb4b31`::ref 0 aborting False
>    Thread-422::DEBUG::2012-11-27 10:33:57,906::BindingXMLRPC::156::vds::(wrapper) [192.168.2.113]
>    Thread-422::DEBUG::2012-11-27 10:33:57,906::task::588::TaskManager.Task::(_updateState) Task=`d05ab59b-78ea-46cb-b835-02553cdf833d`::moving from state init -> state preparing
>    Thread-422::INFO::2012-11-27 10:33:57,906::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='25f8442c-bb4e-4f72-a66a-35715f149300', options=None)
>    Thread-422::DEBUG::2012-11-27 10:33:57,906::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.25f8442c-bb4e-4f72-a66a-35715f149300`ReqID=`d0138543-dbb9-4db5-bef0-716ce80131f8`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>    Thread-422::DEBUG::2012-11-27 10:33:57,906::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300' for lock type 'shared'
>    Thread-422::DEBUG::2012-11-27 10:33:57,907::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300' is free. Now locking as 'shared' (1 active user)
>    Thread-422::DEBUG::2012-11-27 10:33:57,907::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.25f8442c-bb4e-4f72-a66a-35715f149300`ReqID=`d0138543-dbb9-4db5-bef0-716ce80131f8`::Granted request
>    Thread-422::DEBUG::2012-11-27 10:33:57,907::task::817::TaskManager.Task::(resourceAcquired) Task=`d05ab59b-78ea-46cb-b835-02553cdf833d`::_resourcesAcquired: Storage.25f8442c-bb4e-4f72-a66a-35715f149300 (shared)
>    Thread-422::DEBUG::2012-11-27 10:33:57,907::task::978::TaskManager.Task::(_decref) Task=`d05ab59b-78ea-46cb-b835-02553cdf833d`::ref 1 aborting False
>    Thread-422::INFO::2012-11-27 10:33:57,910::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': '0149d080-a94c-446d-969c-eef7da5f6706', 'name': 'MuntCenter', 'version': '0', 'domains': '3d40cf03-891e-471e-93ce-7e7970f73723:Active,0149d080-a94c-446d-969c-eef7da5f6706:Active', 'pool_status': 'connected', 'isoprefix': '/rhev/data-center/25f8442c-bb4e-4f72-a66a-35715f149300/3d40cf03-891e-471e-93ce-7e7970f73723/images/11111111-1111-1111-1111-111111111111', 'type': 'NFS', 'master_ver': 1, 'lver': 11}, 'dominfo': {'3d40cf03-891e-471e-93ce-7e7970f73723': {'status': 'Active', 'diskfree': '18295816192', 'alerts': [], 'disktotal': '21137981440'}, '0149d080-a94c-446d-969c-eef7da5f6706': {'status': 'Active', 'diskfree': '355573694464', 'alerts': [], 'disktotal': '433102258176'}}}
>    Thread-422::DEBUG::2012-11-27 10:33:57,910::task::1172::TaskManager.Task::(prepare) Task=`d05ab59b-78ea-46cb-b835-02553cdf833d`::finished: {'info': {'spm_id': 1, 'master_uuid': '0149d080-a94c-446d-969c-eef7da5f6706', 'name': 'MuntCenter', 'version': '0', 'domains': '3d40cf03-891e-471e-93ce-7e7970f73723:Active,0149d080-a94c-446d-969c-eef7da5f6706:Active', 'pool_status': 'connected', 'isoprefix': '/rhev/data-center/25f8442c-bb4e-4f72-a66a-35715f149300/3d40cf03-891e-471e-93ce-7e7970f73723/images/11111111-1111-1111-1111-111111111111', 'type': 'NFS', 'master_ver': 1, 'lver': 11}, 'dominfo': {'3d40cf03-891e-471e-93ce-7e7970f73723': {'status': 'Active', 'diskfree': '18295816192', 'alerts': [], 'disktotal': '21137981440'}, '0149d080-a94c-446d-969c-eef7da5f6706': {'status': 'Active', 'diskfree': '355573694464', 'alerts': [], 'disktotal': '433102258176'}}}
>    Thread-422::DEBUG::2012-11-27 10:33:57,911::task::588::TaskManager.Task::(_updateState) Task=`d05ab59b-78ea-46cb-b835-02553cdf833d`::moving from state preparing -> state finished
>    Thread-422::DEBUG::2012-11-27 10:33:57,911::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.25f8442c-bb4e-4f72-a66a-35715f149300': < ResourceRef 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300', isValid: 'True' obj: 'None'>}
>    Thread-422::DEBUG::2012-11-27 10:33:57,911::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>    Thread-422::DEBUG::2012-11-27 10:33:57,911::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300'
>    Thread-422::DEBUG::2012-11-27 10:33:57,911::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300' (0 active users)
>    Thread-422::DEBUG::2012-11-27 10:33:57,911::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300' is free, finding out if anyone is waiting for it.
>    Thread-422::DEBUG::2012-11-27 10:33:57,911::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300', Clearing records.
>    Thread-422::DEBUG::2012-11-27 10:33:57,911::task::978::TaskManager.Task::(_decref) Task=`d05ab59b-78ea-46cb-b835-02553cdf833d`::ref 0 aborting False
>    Thread-425::DEBUG::2012-11-27 10:34:02,033::task::588::TaskManager.Task::(_updateState) Task=`9cd060e9-ba9c-49e9-8a44-3afd97deca1d`::moving from state init -> state preparing
>    Thread-425::INFO::2012-11-27 10:34:02,033::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>    Thread-425::INFO::2012-11-27 10:34:02,034::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'3d40cf03-891e-471e-93ce-7e7970f73723': {'delay': '0.00275588035583', 'lastCheck': 1354008826.037707, 'code': 0, 'valid': True}, '0149d080-a94c-446d-969c-eef7da5f6706': {'delay': '0.00170803070068', 'lastCheck': 1354008826.041976, 'code': 0, 'valid': True}}
>    Thread-425::DEBUG::2012-11-27 10:34:02,034::task::1172::TaskManager.Task::(prepare) Task=`9cd060e9-ba9c-49e9-8a44-3afd97deca1d`::finished: {'3d40cf03-891e-471e-93ce-7e7970f73723': {'delay': '0.00275588035583', 'lastCheck': 1354008826.037707, 'code': 0, 'valid': True}, '0149d080-a94c-446d-969c-eef7da5f6706': {'delay': '0.00170803070068', 'lastCheck': 1354008826.041976, 'code': 0, 'valid': True}}
>    Thread-425::DEBUG::2012-11-27 10:34:02,034::task::588::TaskManager.Task::(_updateState) Task=`9cd060e9-ba9c-49e9-8a44-3afd97deca1d`::moving from state preparing -> state finished
>    Thread-425::DEBUG::2012-11-27 10:34:02,034::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>    Thread-425::DEBUG::2012-11-27 10:34:02,034::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>    Thread-425::DEBUG::2012-11-27 10:34:02,035::task::978::TaskManager.Task::(_decref) Task=`9cd060e9-ba9c-49e9-8a44-3afd97deca1d`::ref 0 aborting False
>    Thread-426::DEBUG::2012-11-27 10:34:02,059::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`28efde72-eecc-4714-928e-c86e3da0f7a0`::Disk hdc stats not available
>    Thread-429::DEBUG::2012-11-27 10:34:08,016::BindingXMLRPC::156::vds::(wrapper) [192.168.2.113]
>    Thread-429::DEBUG::2012-11-27 10:34:08,017::task::588::TaskManager.Task::(_updateState) Task=`09952cdc-6d73-4864-b95b-7842dfb7736f`::moving from state init -> state preparing
>    Thread-429::INFO::2012-11-27 10:34:08,017::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='25f8442c-bb4e-4f72-a66a-35715f149300', options=None)
>    Thread-429::INFO::2012-11-27 10:34:08,017::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 11}}
>    Thread-429::DEBUG::2012-11-27 10:34:08,017::task::1172::TaskManager.Task::(prepare) Task=`09952cdc-6d73-4864-b95b-7842dfb7736f`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 11}}
>    Thread-429::DEBUG::2012-11-27 10:34:08,018::task::588::TaskManager.Task::(_updateState) Task=`09952cdc-6d73-4864-b95b-7842dfb7736f`::moving from state preparing -> state finished
>    Thread-429::DEBUG::2012-11-27 10:34:08,018::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>    Thread-429::DEBUG::2012-11-27 10:34:08,018::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>    Thread-429::DEBUG::2012-11-27 10:34:08,018::task::978::TaskManager.Task::(_decref) Task=`09952cdc-6d73-4864-b95b-7842dfb7736f`::ref 0 aborting False
>    Thread-430::DEBUG::2012-11-27 10:34:08,033::BindingXMLRPC::156::vds::(wrapper) [192.168.2.113]
>    Thread-430::DEBUG::2012-11-27 10:34:08,033::task::588::TaskManager.Task::(_updateState) Task=`15f77ba2-3c4f-4302-a841-11da761e4248`::moving from state init -> state preparing
>    Thread-430::INFO::2012-11-27 10:34:08,033::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='25f8442c-bb4e-4f72-a66a-35715f149300', options=None)
>    Thread-430::DEBUG::2012-11-27 10:34:08,034::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.25f8442c-bb4e-4f72-a66a-35715f149300`ReqID=`a4b970fd-f75f-4e0a-8c46-8b9df253b323`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>    Thread-430::DEBUG::2012-11-27 10:34:08,034::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300' for lock type 'shared'
>    Thread-430::DEBUG::2012-11-27 10:34:08,034::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300' is free. Now locking as 'shared' (1 active user)
>    Thread-430::DEBUG::2012-11-27 10:34:08,034::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.25f8442c-bb4e-4f72-a66a-35715f149300`ReqID=`a4b970fd-f75f-4e0a-8c46-8b9df253b323`::Granted request
>    Thread-430::DEBUG::2012-11-27 10:34:08,035::task::817::TaskManager.Task::(resourceAcquired) Task=`15f77ba2-3c4f-4302-a841-11da761e4248`::_resourcesAcquired: Storage.25f8442c-bb4e-4f72-a66a-35715f149300 (shared)
>    Thread-430::DEBUG::2012-11-27 10:34:08,035::task::978::TaskManager.Task::(_decref) Task=`15f77ba2-3c4f-4302-a841-11da761e4248`::ref 1 aborting False
>    Thread-430::INFO::2012-11-27 10:34:08,042::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': '0149d080-a94c-446d-969c-eef7da5f6706', 'name': 'MuntCenter', 'version': '0', 'domains': '3d40cf03-891e-471e-93ce-7e7970f73723:Active,0149d080-a94c-446d-969c-eef7da5f6706:Active', 'pool_status': 'connected', 'isoprefix': '/rhev/data-center/25f8442c-bb4e-4f72-a66a-35715f149300/3d40cf03-891e-471e-93ce-7e7970f73723/images/11111111-1111-1111-1111-111111111111', 'type': 'NFS', 'master_ver': 1, 'lver': 11}, 'dominfo': {'3d40cf03-891e-471e-93ce-7e7970f73723': {'status': 'Active', 'diskfree': '18295816192', 'alerts': [], 'disktotal': '21137981440'}, '0149d080-a94c-446d-969c-eef7da5f6706': {'status': 'Active', 'diskfree': '355573694464', 'alerts': [], 'disktotal': '433102258176'}}}
>    Thread-430::DEBUG::2012-11-27 10:34:08,042::task::1172::TaskManager.Task::(prepare) Task=`15f77ba2-3c4f-4302-a841-11da761e4248`::finished: {'info': {'spm_id': 1, 'master_uuid': '0149d080-a94c-446d-969c-eef7da5f6706', 'name': 'MuntCenter', 'version': '0', 'domains': '3d40cf03-891e-471e-93ce-7e7970f73723:Active,0149d080-a94c-446d-969c-eef7da5f6706:Active', 'pool_status': 'connected', 'isoprefix': '/rhev/data-center/25f8442c-bb4e-4f72-a66a-35715f149300/3d40cf03-891e-471e-93ce-7e7970f73723/images/11111111-1111-1111-1111-111111111111', 'type': 'NFS', 'master_ver': 1, 'lver': 11}, 'dominfo': {'3d40cf03-891e-471e-93ce-7e7970f73723': {'status': 'Active', 'diskfree': '18295816192', 'alerts': [], 'disktotal': '21137981440'}, '0149d080-a94c-446d-969c-eef7da5f6706': {'status': 'Active', 'diskfree': '355573694464', 'alerts': [], 'disktotal': '433102258176'}}}
>    Thread-430::DEBUG::2012-11-27 10:34:08,042::task::588::TaskManager.Task::(_updateState) Task=`15f77ba2-3c4f-4302-a841-11da761e4248`::moving from state preparing -> state finished
>    Thread-430::DEBUG::2012-11-27 10:34:08,042::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.25f8442c-bb4e-4f72-a66a-35715f149300': < ResourceRef 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300', isValid: 'True' obj: 'None'>}
>    Thread-430::DEBUG::2012-11-27 10:34:08,043::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>    Thread-430::DEBUG::2012-11-27 10:34:08,043::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300'
>    Thread-430::DEBUG::2012-11-27 10:34:08,043::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300' (0 active users)
>    Thread-430::DEBUG::2012-11-27 10:34:08,043::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300' is free, finding out if anyone is waiting for it.
>    Thread-430::DEBUG::2012-11-27 10:34:08,043::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300', Clearing records.
>    Thread-430::DEBUG::2012-11-27 10:34:08,044::task::978::TaskManager.Task::(_decref) Task=`15f77ba2-3c4f-4302-a841-11da761e4248`::ref 0 aborting False
>    Thread-433::DEBUG::2012-11-27 10:34:12,339::task::588::TaskManager.Task::(_updateState) Task=`c77a01ff-6db5-46b9-8a60-9c1c7cab5718`::moving from state init -> state preparing
>    Thread-433::INFO::2012-11-27 10:34:12,340::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>    Thread-433::INFO::2012-11-27 10:34:12,340::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'3d40cf03-891e-471e-93ce-7e7970f73723': {'delay': '0.00275588035583', 'lastCheck': 1354008826.037707, 'code': 0, 'valid': True}, '0149d080-a94c-446d-969c-eef7da5f6706': {'delay': '0.00170803070068', 'lastCheck': 1354008826.041976, 'code': 0, 'valid': True}}
>    Thread-433::DEBUG::2012-11-27 10:34:12,340::task::1172::TaskManager.Task::(prepare) Task=`c77a01ff-6db5-46b9-8a60-9c1c7cab5718`::finished: {'3d40cf03-891e-471e-93ce-7e7970f73723': {'delay': '0.00275588035583', 'lastCheck': 1354008826.037707, 'code': 0, 'valid': True}, '0149d080-a94c-446d-969c-eef7da5f6706': {'delay': '0.00170803070068', 'lastCheck': 1354008826.041976, 'code': 0, 'valid': True}}
>    Thread-433::DEBUG::2012-11-27 10:34:12,340::task::588::TaskManager.Task::(_updateState) Task=`c77a01ff-6db5-46b9-8a60-9c1c7cab5718`::moving from state preparing -> state finished
>    Thread-433::DEBUG::2012-11-27 10:34:12,340::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>    Thread-433::DEBUG::2012-11-27 10:34:12,340::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>    Thread-433::DEBUG::2012-11-27 10:34:12,340::task::978::TaskManager.Task::(_decref) Task=`c77a01ff-6db5-46b9-8a60-9c1c7cab5718`::ref 0 aborting False
>    Thread-434::DEBUG::2012-11-27 10:34:12,365::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`28efde72-eecc-4714-928e-c86e3da0f7a0`::Disk hdc stats not available
>    Thread-437::DEBUG::2012-11-27 10:34:18,128::BindingXMLRPC::156::vds::(wrapper) [192.168.2.113]
>    Thread-437::DEBUG::2012-11-27 10:34:18,128::task::588::TaskManager.Task::(_updateState) Task=`e3042414-4fec-4b7a-960d-84eb93db7a02`::moving from state init -> state preparing
>    Thread-437::INFO::2012-11-27 10:34:18,128::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='25f8442c-bb4e-4f72-a66a-35715f149300', options=None)
>    Thread-437::INFO::2012-11-27 10:34:18,129::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 11}}
>    Thread-437::DEBUG::2012-11-27 10:34:18,129::task::1172::TaskManager.Task::(prepare) Task=`e3042414-4fec-4b7a-960d-84eb93db7a02`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 11}}
>    Thread-437::DEBUG::2012-11-27 10:34:18,129::task::588::TaskManager.Task::(_updateState) Task=`e3042414-4fec-4b7a-960d-84eb93db7a02`::moving from state preparing -> state finished
>    Thread-437::DEBUG::2012-11-27 10:34:18,129::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>    Thread-437::DEBUG::2012-11-27 10:34:18,129::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>    Thread-437::DEBUG::2012-11-27 10:34:18,130::task::978::TaskManager.Task::(_decref) Task=`e3042414-4fec-4b7a-960d-84eb93db7a02`::ref 0 aborting False
>    Thread-438::DEBUG::2012-11-27 10:34:18,144::BindingXMLRPC::156::vds::(wrapper) [192.168.2.113]
>    Thread-438::DEBUG::2012-11-27 10:34:18,144::task::588::TaskManager.Task::(_updateState) Task=`e3d0c9c4-6479-4958-8b79-ca0c54d42f3a`::moving from state init -> state preparing
>    Thread-438::INFO::2012-11-27 10:34:18,144::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='25f8442c-bb4e-4f72-a66a-35715f149300', options=None)
>    Thread-438::DEBUG::2012-11-27 10:34:18,144::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.25f8442c-bb4e-4f72-a66a-35715f149300`ReqID=`1bf71196-3716-4e14-8f45-d98f1ec91c3d`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>    Thread-438::DEBUG::2012-11-27 10:34:18,144::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300' for lock type 'shared'
>    Thread-438::DEBUG::2012-11-27 10:34:18,144::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300' is free. Now locking as 'shared' (1 active user)
>    Thread-438::DEBUG::2012-11-27 10:34:18,144::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.25f8442c-bb4e-4f72-a66a-35715f149300`ReqID=`1bf71196-3716-4e14-8f45-d98f1ec91c3d`::Granted request
>    Thread-438::DEBUG::2012-11-27 10:34:18,145::task::817::TaskManager.Task::(resourceAcquired) Task=`e3d0c9c4-6479-4958-8b79-ca0c54d42f3a`::_resourcesAcquired: Storage.25f8442c-bb4e-4f72-a66a-35715f149300 (shared)
>    Thread-438::DEBUG::2012-11-27 10:34:18,145::task::978::TaskManager.Task::(_decref) Task=`e3d0c9c4-6479-4958-8b79-ca0c54d42f3a`::ref 1 aborting False
>    Thread-438::INFO::2012-11-27 10:34:18,148::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': '0149d080-a94c-446d-969c-eef7da5f6706', 'name': 'MuntCenter', 'version': '0', 'domains': '3d40cf03-891e-471e-93ce-7e7970f73723:Active,0149d080-a94c-446d-969c-eef7da5f6706:Active', 'pool_status': 'connected', 'isoprefix': '/rhev/data-center/25f8442c-bb4e-4f72-a66a-35715f149300/3d40cf03-891e-471e-93ce-7e7970f73723/images/11111111-1111-1111-1111-111111111111', 'type': 'NFS', 'master_ver': 1, 'lver': 11}, 'dominfo': {'3d40cf03-891e-471e-93ce-7e7970f73723': {'status': 'Active', 'diskfree': '18295816192', 'alerts': [], 'disktotal': '21137981440'}, '0149d080-a94c-446d-969c-eef7da5f6706': {'status': 'Active', 'diskfree': '355573694464', 'alerts': [], 'disktotal': '433102258176'}}}
>    Thread-438::DEBUG::2012-11-27 10:34:18,148::task::1172::TaskManager.Task::(prepare) Task=`e3d0c9c4-6479-4958-8b79-ca0c54d42f3a`::finished: {'info': {'spm_id': 1, 'master_uuid': '0149d080-a94c-446d-969c-eef7da5f6706', 'name': 'MuntCenter', 'version': '0', 'domains': '3d40cf03-891e-471e-93ce-7e7970f73723:Active,0149d080-a94c-446d-969c-eef7da5f6706:Active', 'pool_status': 'connected', 'isoprefix': '/rhev/data-center/25f8442c-bb4e-4f72-a66a-35715f149300/3d40cf03-891e-471e-93ce-7e7970f73723/images/11111111-1111-1111-1111-111111111111', 'type': 'NFS', 'master_ver': 1, 'lver': 11}, 'dominfo': {'3d40cf03-891e-471e-93ce-7e7970f73723': {'status': 'Active', 'diskfree': '18295816192', 'alerts': [], 'disktotal': '21137981440'}, '0149d080-a94c-446d-969c-eef7da5f6706': {'status': 'Active', 'diskfree': '355573694464', 'alerts': [], 'disktotal': '433102258176'}}}
>    Thread-438::DEBUG::2012-11-27 10:34:18,148::task::588::TaskManager.Task::(_updateState) Task=`e3d0c9c4-6479-4958-8b79-ca0c54d42f3a`::moving from state preparing -> state finished
>    Thread-438::DEBUG::2012-11-27 10:34:18,148::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.25f8442c-bb4e-4f72-a66a-35715f149300': < ResourceRef 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300', isValid: 'True' obj: 'None'>}
>    Thread-438::DEBUG::2012-11-27 10:34:18,149::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>    Thread-438::DEBUG::2012-11-27 10:34:18,149::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300'
>    Thread-438::DEBUG::2012-11-27 10:34:18,149::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300' (0 active users)
>    Thread-438::DEBUG::2012-11-27 10:34:18,149::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300' is free, finding out if anyone is waiting for it.
>    Thread-438::DEBUG::2012-11-27 10:34:18,149::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300', Clearing records.
>    Thread-438::DEBUG::2012-11-27 10:34:18,149::task::978::TaskManager.Task::(_decref) Task=`e3d0c9c4-6479-4958-8b79-ca0c54d42f3a`::ref 0 aborting False
>    Thread-441::DEBUG::2012-11-27 10:34:22,610::task::588::TaskManager.Task::(_updateState) Task=`d1775210-e4f0-4f33-ae47-edd3f4bdf1ef`::moving from state init -> state preparing
>    Thread-441::INFO::2012-11-27 10:34:22,610::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>    Thread-441::INFO::2012-11-27 10:34:22,610::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'3d40cf03-891e-471e-93ce-7e7970f73723': {'delay': '0.00275588035583', 'lastCheck': 1354008826.037707, 'code': 0, 'valid': True}, '0149d080-a94c-446d-969c-eef7da5f6706': {'delay': '0.00170803070068', 'lastCheck': 1354008826.041976, 'code': 0, 'valid': True}}
>    Thread-441::DEBUG::2012-11-27 10:34:22,611::task::1172::TaskManager.Task::(prepare) Task=`d1775210-e4f0-4f33-ae47-edd3f4bdf1ef`::finished: {'3d40cf03-891e-471e-93ce-7e7970f73723': {'delay': '0.00275588035583', 'lastCheck': 1354008826.037707, 'code': 0, 'valid': True}, '0149d080-a94c-446d-969c-eef7da5f6706': {'delay': '0.00170803070068', 'lastCheck': 1354008826.041976, 'code': 0, 'valid': True}}
>    Thread-441::DEBUG::2012-11-27 10:34:22,611::task::588::TaskManager.Task::(_updateState) Task=`d1775210-e4f0-4f33-ae47-edd3f4bdf1ef`::moving from state preparing -> state finished
>    Thread-441::DEBUG::2012-11-27 10:34:22,611::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>    Thread-441::DEBUG::2012-11-27 10:34:22,611::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>    Thread-441::DEBUG::2012-11-27 10:34:22,611::task::978::TaskManager.Task::(_decref) Task=`d1775210-e4f0-4f33-ae47-edd3f4bdf1ef`::ref 0 aborting False
>    Thread-442::DEBUG::2012-11-27 10:34:22,637::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`28efde72-eecc-4714-928e-c86e3da0f7a0`::Disk hdc stats not available
>    VM Channels Listener::DEBUG::2012-11-27 10:34:25,025::vmChannels::60::vds::(_handle_timeouts) Timeout on fileno 22.
>    Thread-445::DEBUG::2012-11-27 10:34:28,258::BindingXMLRPC::156::vds::(wrapper) [192.168.2.113]
>    Thread-445::DEBUG::2012-11-27 10:34:28,258::task::588::TaskManager.Task::(_updateState) Task=`24337dbb-88a4-436b-855b-46b015456e63`::moving from state init -> state preparing
>    Thread-445::INFO::2012-11-27 10:34:28,258::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='25f8442c-bb4e-4f72-a66a-35715f149300', options=None)
>    Thread-445::INFO::2012-11-27 10:34:28,259::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 11}}
>    Thread-445::DEBUG::2012-11-27 10:34:28,259::task::1172::TaskManager.Task::(prepare) Task=`24337dbb-88a4-436b-855b-46b015456e63`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 11}}
>    Thread-445::DEBUG::2012-11-27 10:34:28,259::task::588::TaskManager.Task::(_updateState) Task=`24337dbb-88a4-436b-855b-46b015456e63`::moving from state preparing -> state finished
>    Thread-445::DEBUG::2012-11-27 10:34:28,259::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>    Thread-445::DEBUG::2012-11-27 10:34:28,259::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>    Thread-445::DEBUG::2012-11-27 10:34:28,259::task::978::TaskManager.Task::(_decref) Task=`24337dbb-88a4-436b-855b-46b015456e63`::ref 0 aborting False
>    Thread-446::DEBUG::2012-11-27 10:34:28,279::BindingXMLRPC::156::vds::(wrapper) [192.168.2.113]
>    Thread-446::DEBUG::2012-11-27 10:34:28,279::task::588::TaskManager.Task::(_updateState) Task=`2597a0e4-1df1-4b16-8e3c-6065bf608343`::moving from state init -> state preparing
>    Thread-446::INFO::2012-11-27 10:34:28,279::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='25f8442c-bb4e-4f72-a66a-35715f149300', options=None)
>    Thread-446::DEBUG::2012-11-27 10:34:28,280::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.25f8442c-bb4e-4f72-a66a-35715f149300`ReqID=`0ad3c98f-c7f2-4030-8b5a-42a1c4ff75a0`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>    Thread-446::DEBUG::2012-11-27 10:34:28,280::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300' for lock type 'shared'
>    Thread-446::DEBUG::2012-11-27 10:34:28,280::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300' is free. Now locking as 'shared' (1 active user)
>    Thread-446::DEBUG::2012-11-27 10:34:28,280::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.25f8442c-bb4e-4f72-a66a-35715f149300`ReqID=`0ad3c98f-c7f2-4030-8b5a-42a1c4ff75a0`::Granted request
>    Thread-446::DEBUG::2012-11-27 10:34:28,281::task::817::TaskManager.Task::(resourceAcquired) Task=`2597a0e4-1df1-4b16-8e3c-6065bf608343`::_resourcesAcquired: Storage.25f8442c-bb4e-4f72-a66a-35715f149300 (shared)
>    Thread-446::DEBUG::2012-11-27 10:34:28,281::task::978::TaskManager.Task::(_decref) Task=`2597a0e4-1df1-4b16-8e3c-6065bf608343`::ref 1 aborting False
>    Thread-446::INFO::2012-11-27 10:34:28,287::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': '0149d080-a94c-446d-969c-eef7da5f6706', 'name': 'MuntCenter', 'version': '0', 'domains': '3d40cf03-891e-471e-93ce-7e7970f73723:Active,0149d080-a94c-446d-969c-eef7da5f6706:Active', 'pool_status': 'connected', 'isoprefix': '/rhev/data-center/25f8442c-bb4e-4f72-a66a-35715f149300/3d40cf03-891e-471e-93ce-7e7970f73723/images/11111111-1111-1111-1111-111111111111', 'type': 'NFS', 'master_ver': 1, 'lver': 11}, 'dominfo': {'3d40cf03-891e-471e-93ce-7e7970f73723': {'status': 'Active', 'diskfree': '18295816192', 'alerts': [], 'disktotal': '21137981440'}, '0149d080-a94c-446d-969c-eef7da5f6706': {'status': 'Active', 'diskfree': '355573694464', 'alerts': [], 'disktotal': '433102258176'}}}
>    Thread-446::DEBUG::2012-11-27 10:34:28,287::task::1172::TaskManager.Task::(prepare) Task=`2597a0e4-1df1-4b16-8e3c-6065bf608343`::finished: {'info': {'spm_id': 1, 'master_uuid': '0149d080-a94c-446d-969c-eef7da5f6706', 'name': 'MuntCenter', 'version': '0', 'domains': '3d40cf03-891e-471e-93ce-7e7970f73723:Active,0149d080-a94c-446d-969c-eef7da5f6706:Active', 'pool_status': 'connected', 'isoprefix': '/rhev/data-center/25f8442c-bb4e-4f72-a66a-35715f149300/3d40cf03-891e-471e-93ce-7e7970f73723/images/11111111-1111-1111-1111-111111111111', 'type': 'NFS', 'master_ver': 1, 'lver': 11}, 'dominfo': {'3d40cf03-891e-471e-93ce-7e7970f73723': {'status': 'Active', 'diskfree': '18295816192', 'alerts': [], 'disktotal': '21137981440'}, '0149d080-a94c-446d-969c-eef7da5f6706': {'status': 'Active', 'diskfree': '355573694464', 'alerts': [], 'disktotal': '433102258176'}}}
>    Thread-446::DEBUG::2012-11-27 10:34:28,287::task::588::TaskManager.Task::(_updateState) Task=`2597a0e4-1df1-4b16-8e3c-6065bf608343`::moving from state preparing -> state finished
>    Thread-446::DEBUG::2012-11-27 10:34:28,287::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.25f8442c-bb4e-4f72-a66a-35715f149300': < ResourceRef 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300', isValid: 'True' obj: 'None'>}
>    Thread-446::DEBUG::2012-11-27 10:34:28,287::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>    Thread-446::DEBUG::2012-11-27 10:34:28,287::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300'
>    Thread-446::DEBUG::2012-11-27 10:34:28,287::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300' (0 active users)
>    Thread-446::DEBUG::2012-11-27 10:34:28,287::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300' is free, finding out if anyone is waiting for it.
>    Thread-446::DEBUG::2012-11-27 10:34:28,287::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300', Clearing records.
>    Thread-446::DEBUG::2012-11-27 10:34:28,288::task::978::TaskManager.Task::(_decref) Task=`2597a0e4-1df1-4b16-8e3c-6065bf608343`::ref 0 aborting False
>    Thread-449::DEBUG::2012-11-27 10:34:32,883::task::588::TaskManager.Task::(_updateState) Task=`d952e1fb-6017-43f1-ac18-a2575d9e0209`::moving from state init -> state preparing
>    Thread-449::INFO::2012-11-27 10:34:32,883::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>    Thread-449::INFO::2012-11-27 10:34:32,884::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'3d40cf03-891e-471e-93ce-7e7970f73723': {'delay': '0.00275588035583', 'lastCheck': 1354008826.037707, 'code': 0, 'valid': True}, '0149d080-a94c-446d-969c-eef7da5f6706': {'delay': '0.00170803070068', 'lastCheck': 1354008826.041976, 'code': 0, 'valid': True}}
>    Thread-449::DEBUG::2012-11-27 10:34:32,884::task::1172::TaskManager.Task::(prepare) Task=`d952e1fb-6017-43f1-ac18-a2575d9e0209`::finished: {'3d40cf03-891e-471e-93ce-7e7970f73723': {'delay': '0.00275588035583', 'lastCheck': 1354008826.037707, 'code': 0, 'valid': True}, '0149d080-a94c-446d-969c-eef7da5f6706': {'delay': '0.00170803070068', 'lastCheck': 1354008826.041976, 'code': 0, 'valid': True}}
>    Thread-449::DEBUG::2012-11-27 10:34:32,884::task::588::TaskManager.Task::(_updateState) Task=`d952e1fb-6017-43f1-ac18-a2575d9e0209`::moving from state preparing -> state finished
>    Thread-449::DEBUG::2012-11-27 10:34:32,884::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>    Thread-449::DEBUG::2012-11-27 10:34:32,884::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>    Thread-449::DEBUG::2012-11-27 10:34:32,885::task::978::TaskManager.Task::(_decref) Task=`d952e1fb-6017-43f1-ac18-a2575d9e0209`::ref 0 aborting False
>    Thread-450::DEBUG::2012-11-27 10:34:32,907::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`28efde72-eecc-4714-928e-c86e3da0f7a0`::Disk hdc stats not available
>    Thread-453::DEBUG::2012-11-27 10:34:38,393::BindingXMLRPC::156::vds::(wrapper) [192.168.2.113]
>    Thread-453::DEBUG::2012-11-27 10:34:38,394::task::588::TaskManager.Task::(_updateState) Task=`f86b76b9-cad9-4823-a948-49c8e7969068`::moving from state init -> state preparing
>    Thread-453::INFO::2012-11-27 10:34:38,394::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='25f8442c-bb4e-4f72-a66a-35715f149300', options=None)
>    Thread-453::INFO::2012-11-27 10:34:38,394::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 11}}
>    Thread-453::DEBUG::2012-11-27 10:34:38,395::task::1172::TaskManager.Task::(prepare) Task=`f86b76b9-cad9-4823-a948-49c8e7969068`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 11}}
>    Thread-453::DEBUG::2012-11-27 10:34:38,395::task::588::TaskManager.Task::(_updateState) Task=`f86b76b9-cad9-4823-a948-49c8e7969068`::moving from state preparing -> state finished
>    Thread-453::DEBUG::2012-11-27 10:34:38,395::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>    Thread-453::DEBUG::2012-11-27 10:34:38,395::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>    Thread-453::DEBUG::2012-11-27 10:34:38,395::task::978::TaskManager.Task::(_decref) Task=`f86b76b9-cad9-4823-a948-49c8e7969068`::ref 0 aborting False
>    Thread-454::DEBUG::2012-11-27 10:34:38,416::BindingXMLRPC::156::vds::(wrapper) [192.168.2.113]
>    Thread-454::DEBUG::2012-11-27 10:34:38,417::task::588::TaskManager.Task::(_updateState) Task=`de46c471-4504-4f24-b12e-daf156cf0371`::moving from state init -> state preparing
>    Thread-454::INFO::2012-11-27 10:34:38,417::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='25f8442c-bb4e-4f72-a66a-35715f149300', options=None)
>    Thread-454::DEBUG::2012-11-27 10:34:38,417::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.25f8442c-bb4e-4f72-a66a-35715f149300`ReqID=`64d78841-2090-4068-b874-464953ba7376`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>    Thread-454::DEBUG::2012-11-27 10:34:38,418::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300' for lock type 'shared'
>    Thread-454::DEBUG::2012-11-27 10:34:38,418::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300' is free. Now locking as 'shared' (1 active user)
>    Thread-454::DEBUG::2012-11-27 10:34:38,418::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.25f8442c-bb4e-4f72-a66a-35715f149300`ReqID=`64d78841-2090-4068-b874-464953ba7376`::Granted request
>    Thread-454::DEBUG::2012-11-27 10:34:38,418::task::817::TaskManager.Task::(resourceAcquired) Task=`de46c471-4504-4f24-b12e-daf156cf0371`::_resourcesAcquired: Storage.25f8442c-bb4e-4f72-a66a-35715f149300 (shared)
>    Thread-454::DEBUG::2012-11-27 10:34:38,419::task::978::TaskManager.Task::(_decref) Task=`de46c471-4504-4f24-b12e-daf156cf0371`::ref 1 aborting False
>    Thread-454::INFO::2012-11-27 10:34:38,425::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': '0149d080-a94c-446d-969c-eef7da5f6706', 'name': 'MuntCenter', 'version': '0', 'domains': '3d40cf03-891e-471e-93ce-7e7970f73723:Active,0149d080-a94c-446d-969c-eef7da5f6706:Active', 'pool_status': 'connected', 'isoprefix': '/rhev/data-center/25f8442c-bb4e-4f72-a66a-35715f149300/3d40cf03-891e-471e-93ce-7e7970f73723/images/11111111-1111-1111-1111-111111111111', 'type': 'NFS', 'master_ver': 1, 'lver': 11}, 'dominfo': {'3d40cf03-891e-471e-93ce-7e7970f73723': {'status': 'Active', 'diskfree': '18295816192', 'alerts': [], 'disktotal': '21137981440'}, '0149d080-a94c-446d-969c-eef7da5f6706': {'status': 'Active', 'diskfree': '355573694464', 'alerts': [], 'disktotal': '433102258176'}}}
>    Thread-454::DEBUG::2012-11-27 10:34:38,426::task::1172::TaskManager.Task::(prepare) Task=`de46c471-4504-4f24-b12e-daf156cf0371`::finished: {'info': {'spm_id': 1, 'master_uuid': '0149d080-a94c-446d-969c-eef7da5f6706', 'name': 'MuntCenter', 'version': '0', 'domains': '3d40cf03-891e-471e-93ce-7e7970f73723:Active,0149d080-a94c-446d-969c-eef7da5f6706:Active', 'pool_status': 'connected', 'isoprefix': '/rhev/data-center/25f8442c-bb4e-4f72-a66a-35715f149300/3d40cf03-891e-471e-93ce-7e7970f73723/images/11111111-1111-1111-1111-111111111111', 'type': 'NFS', 'master_ver': 1, 'lver': 11}, 'dominfo': {'3d40cf03-891e-471e-93ce-7e7970f73723': {'status': 'Active', 'diskfree': '18295816192', 'alerts': [], 'disktotal': '21137981440'}, '0149d080-a94c-446d-969c-eef7da5f6706': {'status': 'Active', 'diskfree': '355573694464', 'alerts': [], 'disktotal': '433102258176'}}}
>    Thread-454::DEBUG::2012-11-27 10:34:38,426::task::588::TaskManager.Task::(_updateState) Task=`de46c471-4504-4f24-b12e-daf156cf0371`::moving from state preparing -> state finished
>    Thread-454::DEBUG::2012-11-27 10:34:38,426::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.25f8442c-bb4e-4f72-a66a-35715f149300': < ResourceRef 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300', isValid: 'True' obj: 'None'>}
>    Thread-454::DEBUG::2012-11-27 10:34:38,426::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>    Thread-454::DEBUG::2012-11-27 10:34:38,426::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300'
>    Thread-454::DEBUG::2012-11-27 10:34:38,426::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300' (0 active users)
>    Thread-454::DEBUG::2012-11-27 10:34:38,426::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300' is free, finding out if anyone is waiting for it.
>    Thread-454::DEBUG::2012-11-27 10:34:38,426::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300', Clearing records.
>    Thread-454::DEBUG::2012-11-27 10:34:38,426::task::978::TaskManager.Task::(_decref) Task=`de46c471-4504-4f24-b12e-daf156cf0371`::ref 0 aborting False
>    Thread-457::DEBUG::2012-11-27 10:34:43,148::task::588::TaskManager.Task::(_updateState) Task=`27df5eac-7cdc-4c16-b5ec-800b33db5de3`::moving from state init -> state preparing
>    Thread-457::INFO::2012-11-27 10:34:43,149::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>    Thread-457::INFO::2012-11-27 10:34:43,149::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'3d40cf03-891e-471e-93ce-7e7970f73723': {'delay': '0.00275588035583', 'lastCheck': 1354008826.037707, 'code': 0, 'valid': True}, '0149d080-a94c-446d-969c-eef7da5f6706': {'delay': '0.00170803070068', 'lastCheck': 1354008826.041976, 'code': 0, 'valid': True}}
>    Thread-457::DEBUG::2012-11-27 10:34:43,149::task::1172::TaskManager.Task::(prepare) Task=`27df5eac-7cdc-4c16-b5ec-800b33db5de3`::finished: {'3d40cf03-891e-471e-93ce-7e7970f73723': {'delay': '0.00275588035583', 'lastCheck': 1354008826.037707, 'code': 0, 'valid': True}, '0149d080-a94c-446d-969c-eef7da5f6706': {'delay': '0.00170803070068', 'lastCheck': 1354008826.041976, 'code': 0, 'valid': True}}
>    Thread-457::DEBUG::2012-11-27 10:34:43,149::task::588::TaskManager.Task::(_updateState) Task=`27df5eac-7cdc-4c16-b5ec-800b33db5de3`::moving from state preparing -> state finished
>    Thread-457::DEBUG::2012-11-27 10:34:43,150::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>    Thread-457::DEBUG::2012-11-27 10:34:43,150::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>    Thread-457::DEBUG::2012-11-27 10:34:43,150::task::978::TaskManager.Task::(_decref) Task=`27df5eac-7cdc-4c16-b5ec-800b33db5de3`::ref 0 aborting False
>    Thread-458::DEBUG::2012-11-27 10:34:43,176::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=`28efde72-eecc-4714-928e-c86e3da0f7a0`::Disk hdc stats not available
>    MainThread::DEBUG::2012-11-27 10:34:45,459::task::588::TaskManager.Task::(_updateState) Task=`65048aca-02fb-4906-97d1-db2d7f0ca30b`::moving from state init -> state preparing
>    MainThread::INFO::2012-11-27 10:34:45,459::logUtils::37::dispatcher::(wrapper) Run and protect: getConnectedStoragePoolsList(options=None)
>    MainThread::INFO::2012-11-27 10:34:45,459::logUtils::39::dispatcher::(wrapper) Run and protect: getConnectedStoragePoolsList, Return response: {'poollist': ['25f8442c-bb4e-4f72-a66a-35715f149300']}
>    MainThread::DEBUG::2012-11-27 10:34:45,460::task::1172::TaskManager.Task::(prepare) Task=`65048aca-02fb-4906-97d1-db2d7f0ca30b`::finished: {'poollist': ['25f8442c-bb4e-4f72-a66a-35715f149300']}
>    MainThread::DEBUG::2012-11-27 10:34:45,460::task::588::TaskManager.Task::(_updateState) Task=`65048aca-02fb-4906-97d1-db2d7f0ca30b`::moving from state preparing -> state finished
>    MainThread::DEBUG::2012-11-27 10:34:45,460::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>    MainThread::DEBUG::2012-11-27 10:34:45,460::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>    MainThread::DEBUG::2012-11-27 10:34:45,460::task::978::TaskManager.Task::(_decref) Task=`65048aca-02fb-4906-97d1-db2d7f0ca30b`::ref 0 aborting False
>    MainThread::DEBUG::2012-11-27 10:34:45,461::task::588::TaskManager.Task::(_updateState) Task=`6677ca09-30e0-44ba-bacd-403185b55e58`::moving from state init -> state preparing
>    MainThread::INFO::2012-11-27 10:34:45,461::logUtils::37::dispatcher::(wrapper) Run and protect: spmStop(spUUID='25f8442c-bb4e-4f72-a66a-35715f149300', options=None)
>    MainThread::DEBUG::2012-11-27 10:34:45,461::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.25f8442c-bb4e-4f72-a66a-35715f149300`ReqID=`160c3a30-fe3b-4ed9-a5bc-813080a56a95`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>    MainThread::DEBUG::2012-11-27 10:34:45,461::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300' for lock type 'exclusive'
>    MainThread::DEBUG::2012-11-27 10:34:45,462::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.25f8442c-bb4e-4f72-a66a-35715f149300' is free. Now locking as 'exclusive' (1 active user)
>    MainThread::DEBUG::2012-11-27 10:34:45,462::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.25f8442c-bb4e-4f72-a66a-35715f149300`ReqID=`160c3a30-fe3b-4ed9-a5bc-813080a56a95`::Granted request
>    MainThread::DEBUG::2012-11-27 10:34:45,462::task::817::TaskManager.Task::(resourceAcquired) Task=`6677ca09-30e0-44ba-bacd-403185b55e58`::_resourcesAcquired: Storage.25f8442c-bb4e-4f72-a66a-35715f149300 (exclusive)
>    MainThread::DEBUG::2012-11-27 10:34:45,463::task::978::TaskManager.Task::(_decref) Task=`6677ca09-30e0-44ba-bacd-403185b55e58`::ref 1 aborting False
>    MainThread::DEBUG::2012-11-27 10:34:45,463::sp::319::Storage.StoragePool::(_shutDownUpgrade) Shutting down upgrade process
>    MainThread::DEBUG::2012-11-27 10:34:45,463::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.upgrade_25f8442c-bb4e-4f72-a66a-35715f149300`ReqID=`5c3f5d62-218c-4260-be6c-693ae534b0c4`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>    MainThread::DEBUG::2012-11-27 10:34:45,463::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.upgrade_25f8442c-bb4e-4f72-a66a-35715f149300' for lock type 'exclusive'
>    MainThread::DEBUG::2012-11-27 10:34:45,463::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.upgrade_25f8442c-bb4e-4f72-a66a-35715f149300' is free. Now locking as 'exclusive' (1 active user)
>    MainThread::DEBUG::2012-11-27 10:34:45,464::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.upgrade_25f8442c-bb4e-4f72-a66a-35715f149300`ReqID=`5c3f5d62-218c-4260-be6c-693ae534b0c4`::Granted request
>    MainThread::DEBUG::2012-11-27 10:34:45,464::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.upgrade_25f8442c-bb4e-4f72-a66a-35715f149300'
>    MainThread::DEBUG::2012-11-27 10:34:45,464::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.upgrade_25f8442c-bb4e-4f72-a66a-35715f149300' (0 active users)
>    MainThread::DEBUG::2012-11-27 10:34:45,464::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.upgrade_25f8442c-bb4e-4f72-a66a-35715f149300' is free, finding out if anyone is waiting for it.
>    MainThread::DEBUG::2012-11-27 10:34:45,465::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.upgrade_25f8442c-bb4e-4f72-a66a-35715f149300', Clearing records.
>    MainThread::DEBUG::2012-11-27 10:34:45,465::persistentDict::162::Storage.PersistentDict::(transaction) Starting transaction
>    MainThread::DEBUG::2012-11-27 10:34:45,465::persistentDict::168::Storage.PersistentDict::(transaction) Flushing changes
>    MainThread::DEBUG::2012-11-27 10:34:45,466::persistentDict::287::Storage.PersistentDict::(flush) about to write lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=data', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=1', 'POOL_DESCRIPTION=MuntCenter', 'POOL_DOMAINS=3d40cf03-891e-471e-93ce-7e7970f73723:Active,0149d080-a94c-446d-969c-eef7da5f6706:Active', 'POOL_SPM_ID=-1', 'POOL_SPM_LVER=11', 'POOL_UUID=25f8442c-bb4e-4f72-a66a-35715f149300', 'REMOTE_PATH=192.168.2.93:/srv/data', 'ROLE=Master', 'SDUUID=0149d080-a94c-446d-969c-eef7da5f6706', 'TYPE=NFS', 'VERSION=0', '_SHA_CKSUM=1728c015ffb836a1197e90d3ed653a87d4825bc7']
>    Thread-461::DEBUG::2012-11-27 10:34:48,509::BindingXMLRPC::156::vds::(wrapper) [192.168.2.113]
>    Thread-461::DEBUG::2012-11-27 10:34:48,509::task::588::TaskManager.Task::(_updateState) Task=`5878fd9a-b970-4da7-b241-b7bf5e27037f`::moving from state init -> state preparing
>    Thread-461::INFO::2012-11-27 10:34:48,510::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='25f8442c-bb4e-4f72-a66a-35715f149300', options=None)
>    MainThread::INFO::2012-11-27 10:34:53,358::vmChannels::135::vds::(stop) VM channels listener was stopped.
>    MainThread::DEBUG::2012-11-27 10:34:53,359::task::588::TaskManager.Task::(_updateState) Task=`3d1f2183-c310-47cf-8572-40c019c3f8d0`::moving from state init -> state preparing
>    MainThread::INFO::2012-11-27 10:34:53,359::logUtils::37::dispatcher::(wrapper) Run and protect: prepareForShutdown(options=None)
>    Thread-11::DEBUG::2012-11-27 10:34:53,360::storageServer::617::ConnectionMonitor::(_monitorConnections) Monitoring stopped
>    MainThread::WARNING::2012-11-27 10:34:53,387::hsm::2972::Storage.HSM::(__releaseLocks) Found lease locks, releasing
>    Thread-16::ERROR::2012-11-27 10:34:56,233::task::853::TaskManager.Task::(_setError) Task=`70544935-fe66-4b32-9d2e-217cce096af7`::Unexpected error
>    Traceback (most recent call last):
>    File "/usr/share/vdsm/storage/task.py", line 861, in _run
>    return fn(*args, **kargs)
>    File "/usr/share/vdsm/logUtils.py", line 38, in wrapper
>    res = f(*args, **kwargs)
>    File "/usr/share/vdsm/storage/hsm.py", line 2551, in getVolumeSize
>    apparentsize = str(volume.Volume.getVSize(sdUUID, imgUUID, volUUID, bs=1))
>    File "/usr/share/vdsm/storage/volume.py", line 283, in getVSize
>    return mysd.getVolumeClass().getVSize(mysd, imgUUID, volUUID, bs)
>    File "/usr/share/vdsm/storage/fileVolume.py", line 457, in getVSize
>    return sdobj.produceVolume(imgUUID, volUUID).getVolumeSize(bs)
>    File "/usr/share/vdsm/storage/fileSD.py", line 207, in produceVolume
>    return fileVolume.FileVolume(repoPath, self.sdUUID, imgUUID, volUUID)
>    File "/usr/share/vdsm/storage/fileVolume.py", line 68, in __init__
>    volume.Volume.__init__(self, repoPath, sdUUID, imgUUID, volUUID)
>    File "/usr/share/vdsm/storage/volume.py", line 120, in __init__
>    self.validate()
>    File "/usr/share/vdsm/storage/volume.py", line 126, in validate
>    self.validateImagePath()
>    File "/usr/share/vdsm/storage/fileVolume.py", line 502, in validateImagePath
>    if not self.oop.os.path.isdir(imageDir):
>    File "/usr/share/vdsm/storage/processPool.py", line 63, in wrapper
>    return self.runExternally(func, *args, **kwds)
>    File "/usr/share/vdsm/storage/processPool.py", line 74, in runExternally
>    return self._procPool.runExternally(*args, **kwargs)
>    File "/usr/share/vdsm/storage/processPool.py", line 161, in runExternally
>    raise Timeout("Operation Stuck")
>    Timeout: Operation Stuck
>    Thread-16::DEBUG::2012-11-27 10:34:56,236::task::872::TaskManager.Task::(_run) Task=`70544935-fe66-4b32-9d2e-217cce096af7`::Task._run: 70544935-fe66-4b32-9d2e-217cce096af7 ('0149d080-a94c-446d-969c-eef7da5f6706', '25f8442c-bb4e-4f72-a66a-35715f149300', '16dc8590-0538-4a32-8bf1-fb67ee33bc35', '73380a26-37b4-4f24-979c-4464d8b4401c') {} failed - stopping task
>    Thread-16::DEBUG::2012-11-27 10:34:56,236::task::1199::TaskManager.Task::(stop) Task=`70544935-fe66-4b32-9d2e-217cce096af7`::stopping in state preparing (force False)
>    Thread-16::DEBUG::2012-11-27 10:34:56,236::task::978::TaskManager.Task::(_decref) Task=`70544935-fe66-4b32-9d2e-217cce096af7`::ref 1 aborting True
>    Thread-16::INFO::2012-11-27 10:34:56,237::task::1157::TaskManager.Task::(prepare) Task=`70544935-fe66-4b32-9d2e-217cce096af7`::aborting: Task is aborted: u'Operation Stuck' - code 100
>    Thread-16::DEBUG::2012-11-27 10:34:56,237::task::1162::TaskManager.Task::(prepare) Task=`70544935-fe66-4b32-9d2e-217cce096af7`::Prepare: aborted: Operation Stuck
>    Thread-16::DEBUG::2012-11-27 10:34:56,237::task::978::TaskManager.Task::(_decref) Task=`70544935-fe66-4b32-9d2e-217cce096af7`::ref 0 aborting True
>    Thread-16::DEBUG::2012-11-27 10:34:56,237::task::913::TaskManager.Task::(_doAbort) Task=`70544935-fe66-4b32-9d2e-217cce096af7`::Task._doAbort: force False
>    Thread-16::DEBUG::2012-11-27 10:34:56,237::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>    Thread-16::DEBUG::2012-11-27 10:34:56,237::task::588::TaskManager.Task::(_updateState) Task=`70544935-fe66-4b32-9d2e-217cce096af7`::moving from state preparing -> state aborting
>    Thread-16::DEBUG::2012-11-27 10:34:56,237::task::537::TaskManager.Task::(__state_aborting) Task=`70544935-fe66-4b32-9d2e-217cce096af7`::_aborting: recover policy none
>    Thread-16::DEBUG::2012-11-27 10:34:56,237::task::588::TaskManager.Task::(_updateState) Task=`70544935-fe66-4b32-9d2e-217cce096af7`::moving from state aborting -> state failed
>    Thread-16::DEBUG::2012-11-27 10:34:56,237::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.0149d080-a94c-446d-969c-eef7da5f6706': < ResourceRef 'Storage.0149d080-a94c-446d-969c-eef7da5f6706', isValid: 'True' obj: 'None'>}
>    Thread-16::DEBUG::2012-11-27 10:34:56,238::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>    Thread-16::DEBUG::2012-11-27 10:34:56,238::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.0149d080-a94c-446d-969c-eef7da5f6706'
>    Thread-16::DEBUG::2012-11-27 10:34:56,238::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.0149d080-a94c-446d-969c-eef7da5f6706' (0 active users)
>    Thread-16::DEBUG::2012-11-27 10:34:56,238::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.0149d080-a94c-446d-969c-eef7da5f6706' is free, finding out if anyone is waiting for it.
>    Thread-16::DEBUG::2012-11-27 10:34:56,238::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.0149d080-a94c-446d-969c-eef7da5f6706', Clearing records.
>    Thread-16::ERROR::2012-11-27 10:34:56,238::dispatcher::69::Storage.Dispatcher.Protect::(run) Operation Stuck
>    Traceback (most recent call last):
>    File "/usr/share/vdsm/storage/dispatcher.py", line 61, in run
>    result = ctask.prepare(self.func, *args, **kwargs)
>    File "/usr/share/vdsm/storage/task.py", line 1164, in prepare
>    raise self.error
>    Timeout: Operation Stuck
>    Thread-22::ERROR::2012-11-27 10:34:58,046::domainMonitor::120::Storage.DomainMonitor::(_monitorDomain) Error while collecting domain `3d40cf03-891e-471e-93ce-7e7970f73723` monitoring information
>    Traceback (most recent call last):
>    File "/usr/share/vdsm/storage/domainMonitor.py", line 103, in _monitorDomain
>    domain.selftest()
>    File "/usr/share/vdsm/storage/nfsSD.py", line 103, in selftest
>    fileSD.FileStorageDomain.selftest(self)
>    File "/usr/share/vdsm/storage/fileSD.py", line 399, in selftest
>    self.oop.os.statvfs(self.domaindir)
>    File "/usr/share/vdsm/storage/processPool.py", line 63, in wrapper
>    return self.runExternally(func, *args, **kwds)
>    File "/usr/share/vdsm/storage/processPool.py", line 74, in runExternally
>    return self._procPool.runExternally(*args, **kwargs)
>    File "/usr/share/vdsm/storage/processPool.py", line 161, in runExternally
>    raise Timeout("Operation Stuck")
>    Timeout: Operation Stuck
>    Thread-22::DEBUG::2012-11-27 10:34:58,047::domainMonitor::130::Storage.DomainMonitor::(_monitorDomain) Domain `3d40cf03-891e-471e-93ce-7e7970f73723` changed its status to Invalid
>    Thread-23::ERROR::2012-11-27 10:34:58,080::domainMonitor::120::Storage.DomainMonitor::(_monitorDomain) Error while collecting domain `0149d080-a94c-446d-969c-eef7da5f6706` monitoring information
>    Traceback (most recent call last):
>    File "/usr/share/vdsm/storage/domainMonitor.py", line 103, in _monitorDomain
>    domain.selftest()
>    File "/usr/share/vdsm/storage/nfsSD.py", line 103, in selftest
>    fileSD.FileStorageDomain.selftest(self)
>    File "/usr/share/vdsm/storage/fileSD.py", line 399, in selftest
>    self.oop.os.statvfs(self.domaindir)
>    File "/usr/share/vdsm/storage/processPool.py", line 63, in wrapper
>    return self.runExternally(func, *args, **kwds)
>    File "/usr/share/vdsm/storage/processPool.py", line 74, in runExternally
>    return self._procPool.runExternally(*args, **kwargs)
>    File "/usr/share/vdsm/storage/processPool.py", line 161, in runExternally
>    raise Timeout("Operation Stuck")
>    Timeout: Operation Stuck
>    Thread-23::DEBUG::2012-11-27 10:34:58,081::domainMonitor::130::Storage.DomainMonitor::(_monitorDomain) Domain `0149d080-a94c-446d-969c-eef7da5f6706` changed its status to Invalid
>    MainThread::WARNING::2012-11-27 10:35:03,645::hsm::2982::Storage.HSM::(__releaseLocks) Could not release locks, killing lock processes
>    MainThread::DEBUG::2012-11-27 10:35:03,666::taskManager::80::TaskManager::(prepareForShutdown) Request to stop all tasks
>    MainThread::INFO::2012-11-27 10:35:03,667::logUtils::39::dispatcher::(wrapper) Run and protect: prepareForShutdown, Return response: None
>    MainThread::DEBUG::2012-11-27 10:35:03,667::task::1172::TaskManager.Task::(prepare) Task=`3d1f2183-c310-47cf-8572-40c019c3f8d0`::finished: None
>    MainThread::DEBUG::2012-11-27 10:35:03,667::task::588::TaskManager.Task::(_updateState) Task=`3d1f2183-c310-47cf-8572-40c019c3f8d0`::moving from state preparing -> state finished
>    MainThread::DEBUG::2012-11-27 10:35:03,668::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>    MainThread::DEBUG::2012-11-27 10:35:03,668::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>    MainThread::DEBUG::2012-11-27 10:35:03,668::task::978::TaskManager.Task::(_decref) Task=`3d1f2183-c310-47cf-8572-40c019c3f8d0`::ref 0 aborting False
>    MainThread::WARNING::2012-11-27 10:35:47,471::persistentDict::172::Storage.PersistentDict::(transaction) Error in transaction, rolling back changes
>    Traceback (most recent call last):
>    File "/usr/share/vdsm/storage/persistentDict.py", line 169, in transaction
>    self.flush(self._metadata)
>    File "/usr/share/vdsm/storage/persistentDict.py", line 288, in flush
>    self._metaRW.writelines(lines)
>    File "/usr/share/vdsm/storage/fileSD.py", line 93, in writelines
>    self._oop.writeLines(tmpFilePath, metadata)
>    File "/usr/share/vdsm/storage/processPool.py", line 63, in wrapper
>    return self.runExternally(func, *args, **kwds)
>    File "/usr/share/vdsm/storage/processPool.py", line 74, in runExternally
>    return self._procPool.runExternally(*args, **kwargs)
>    File "/usr/share/vdsm/storage/processPool.py", line 161, in runExternally
>    raise Timeout("Operation Stuck")
>    Timeout: Operation Stuck
>    MainThread::DEBUG::2012-11-27 10:35:47,472::persistentDict::287::Storage.PersistentDict::(flush) about to write lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=data', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=1', 'POOL_DESCRIPTION=MuntCenter', 'POOL_DOMAINS=3d40cf03-891e-471e-93ce-7e7970f73723:Active,0149d080-a94c-446d-969c-eef7da5f6706:Active', 'POOL_SPM_ID=1', 'POOL_SPM_LVER=11', 'POOL_UUID=25f8442c-bb4e-4f72-a66a-35715f149300', 'REMOTE_PATH=192.168.2.93:/srv/data', 'ROLE=Master', 'SDUUID=0149d080-a94c-446d-969c-eef7da5f6706', 'TYPE=NFS', 'VERSION=0', '_SHA_CKSUM=232610c57a5afc19d01bd8602761bf7e958dc50c']
>    Thread-16::DEBUG::2012-11-27 10:35:56,318::task::588::TaskManager.Task::(_updateState) Task=`fdb6d402-3546-4a38-8f95-582418865527`::moving from state init -> state preparing
>    Thread-16::INFO::2012-11-27 10:35:56,319::logUtils::37::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='0149d080-a94c-446d-969c-eef7da5f6706', spUUID='25f8442c-bb4e-4f72-a66a-35715f149300', imgUUID='16dc8590-0538-4a32-8bf1-fb67ee33bc35', volUUID='73380a26-37b4-4f24-979c-4464d8b4401c', options=None)
>    Thread-16::DEBUG::2012-11-27 10:35:56,321::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.0149d080-a94c-446d-969c-eef7da5f6706`ReqID=`1bb8175a-537f-48a5-95ef-3c8acd0cd302`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>    Thread-16::DEBUG::2012-11-27 10:35:56,322::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.0149d080-a94c-446d-969c-eef7da5f6706' for lock type 'shared'
>    Thread-16::DEBUG::2012-11-27 10:35:56,322::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.0149d080-a94c-446d-969c-eef7da5f6706' is free. Now locking as 'shared' (1 active user)
>    Thread-16::DEBUG::2012-11-27 10:35:56,322::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.0149d080-a94c-446d-969c-eef7da5f6706`ReqID=`1bb8175a-537f-48a5-95ef-3c8acd0cd302`::Granted request
>    Thread-16::DEBUG::2012-11-27 10:35:56,323::task::817::TaskManager.Task::(resourceAcquired) Task=`fdb6d402-3546-4a38-8f95-582418865527`::_resourcesAcquired: Storage.0149d080-a94c-446d-969c-eef7da5f6706 (shared)
>    Thread-16::DEBUG::2012-11-27 10:35:56,323::task::978::TaskManager.Task::(_decref) Task=`fdb6d402-3546-4a38-8f95-582418865527`::ref 1 aborting False
>
>Revise paste â
>We are not responsible for any content on this site.
>About this site. Coded and hosted by Fedora Unity.
>

Actions: View

Attachments on bug 880555: 652563 | 652564 | 653581