Attachment 604607 Details for Bug 848401 – VDSM log

VDSM log

vdsm.log (text/x-log), 88.78 KB, created by Pavel Novotny on 2012-08-15 13:38:00 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: Pavel Novotny

Created: 2012-08-15 13:38:00 UTC

Size: 88.78 KB

patch

obsolete

>Thread-1940::DEBUG::2012-08-15 11:59:54,937::BindingXMLRPC::164::vds::(wrapper) [10.34.63.8]
>Thread-1940::DEBUG::2012-08-15 11:59:54,938::task::588::TaskManager.Task::(_updateState) Task=`16f41fa3-4197-40a4-b997-f087bf651e1f`::moving from state init -> state preparing
>Thread-1940::INFO::2012-08-15 11:59:54,938::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='ae32878d-2639-47d7-b751-0ced2b0cd4d2', options=None)
>Thread-1940::INFO::2012-08-15 11:59:54,939::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 0}}
>Thread-1940::DEBUG::2012-08-15 11:59:54,939::task::1172::TaskManager.Task::(prepare) Task=`16f41fa3-4197-40a4-b997-f087bf651e1f`::finished: {'spm_st': {'spmId': 1, 'spmStatus': 'SPM', 'spmLver': 0}}
>Thread-1940::DEBUG::2012-08-15 11:59:54,939::task::588::TaskManager.Task::(_updateState) Task=`16f41fa3-4197-40a4-b997-f087bf651e1f`::moving from state preparing -> state finished
>Thread-1940::DEBUG::2012-08-15 11:59:54,939::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-1940::DEBUG::2012-08-15 11:59:54,940::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-1940::DEBUG::2012-08-15 11:59:54,940::task::978::TaskManager.Task::(_decref) Task=`16f41fa3-4197-40a4-b997-f087bf651e1f`::ref 0 aborting False
>Thread-1941::DEBUG::2012-08-15 11:59:54,944::BindingXMLRPC::164::vds::(wrapper) [10.34.63.8]
>Thread-1941::DEBUG::2012-08-15 11:59:54,944::task::588::TaskManager.Task::(_updateState) Task=`6d5f00e8-cf30-414c-82f6-656e1c42f430`::moving from state init -> state preparing
>Thread-1941::INFO::2012-08-15 11:59:54,945::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='ae32878d-2639-47d7-b751-0ced2b0cd4d2', options=None)
>Thread-1941::DEBUG::2012-08-15 11:59:54,945::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.ae32878d-2639-47d7-b751-0ced2b0cd4d2`ReqID=`0676fd7a-a89a-453d-8b08-26271d8cb38f`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-1941::DEBUG::2012-08-15 11:59:54,945::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.ae32878d-2639-47d7-b751-0ced2b0cd4d2' for lock type 'shared'
>Thread-1941::DEBUG::2012-08-15 11:59:54,946::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.ae32878d-2639-47d7-b751-0ced2b0cd4d2' is free. Now locking as 'shared' (1 active user)
>Thread-1941::DEBUG::2012-08-15 11:59:54,946::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.ae32878d-2639-47d7-b751-0ced2b0cd4d2`ReqID=`0676fd7a-a89a-453d-8b08-26271d8cb38f`::Granted request
>Thread-1941::DEBUG::2012-08-15 11:59:54,946::task::817::TaskManager.Task::(resourceAcquired) Task=`6d5f00e8-cf30-414c-82f6-656e1c42f430`::_resourcesAcquired: Storage.ae32878d-2639-47d7-b751-0ced2b0cd4d2 (shared)
>Thread-1941::DEBUG::2012-08-15 11:59:54,947::task::978::TaskManager.Task::(_decref) Task=`6d5f00e8-cf30-414c-82f6-656e1c42f430`::ref 1 aborting False
>Thread-1941::INFO::2012-08-15 11:59:54,950::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': 'ab9c2853-40c8-486d-a907-c35fe1b57594', 'name': 'DC1', 'version': '3', 'domains': 'ab9c2853-40c8-486d-a907-c35fe1b57594:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'NFS', 'master_ver': 1, 'lver': 0}, 'dominfo': {'ab9c2853-40c8-486d-a907-c35fe1b57594': {'status': 'Active', 'diskfree': '59966488576', 'alerts': [], 'disktotal': '655274541056'}}}
>Thread-1941::DEBUG::2012-08-15 11:59:54,950::task::1172::TaskManager.Task::(prepare) Task=`6d5f00e8-cf30-414c-82f6-656e1c42f430`::finished: {'info': {'spm_id': 1, 'master_uuid': 'ab9c2853-40c8-486d-a907-c35fe1b57594', 'name': 'DC1', 'version': '3', 'domains': 'ab9c2853-40c8-486d-a907-c35fe1b57594:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'NFS', 'master_ver': 1, 'lver': 0}, 'dominfo': {'ab9c2853-40c8-486d-a907-c35fe1b57594': {'status': 'Active', 'diskfree': '59966488576', 'alerts': [], 'disktotal': '655274541056'}}}
>Thread-1941::DEBUG::2012-08-15 11:59:54,950::task::588::TaskManager.Task::(_updateState) Task=`6d5f00e8-cf30-414c-82f6-656e1c42f430`::moving from state preparing -> state finished
>Thread-1941::DEBUG::2012-08-15 11:59:54,951::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.ae32878d-2639-47d7-b751-0ced2b0cd4d2': < ResourceRef 'Storage.ae32878d-2639-47d7-b751-0ced2b0cd4d2', isValid: 'True' obj: 'None'>}
>Thread-1941::DEBUG::2012-08-15 11:59:54,951::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-1941::DEBUG::2012-08-15 11:59:54,951::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.ae32878d-2639-47d7-b751-0ced2b0cd4d2'
>Thread-1941::DEBUG::2012-08-15 11:59:54,952::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.ae32878d-2639-47d7-b751-0ced2b0cd4d2' (0 active users)
>Thread-1941::DEBUG::2012-08-15 11:59:54,952::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.ae32878d-2639-47d7-b751-0ced2b0cd4d2' is free, finding out if anyone is waiting for it.
>Thread-1941::DEBUG::2012-08-15 11:59:54,952::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.ae32878d-2639-47d7-b751-0ced2b0cd4d2', Clearing records.
>Thread-1941::DEBUG::2012-08-15 11:59:54,952::task::978::TaskManager.Task::(_decref) Task=`6d5f00e8-cf30-414c-82f6-656e1c42f430`::ref 0 aborting False
>Thread-1943::DEBUG::2012-08-15 11:59:57,234::task::588::TaskManager.Task::(_updateState) Task=`2ce7998b-ee70-4a56-a2dd-ed440bd8725d`::moving from state init -> state preparing
>Thread-1943::INFO::2012-08-15 11:59:57,234::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-1943::INFO::2012-08-15 11:59:57,234::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'ab9c2853-40c8-486d-a907-c35fe1b57594': {'delay': '0.002112865448', 'lastCheck': 1345024788.2817931, 'code': 0, 'valid': True}}
>Thread-1943::DEBUG::2012-08-15 11:59:57,235::task::1172::TaskManager.Task::(prepare) Task=`2ce7998b-ee70-4a56-a2dd-ed440bd8725d`::finished: {'ab9c2853-40c8-486d-a907-c35fe1b57594': {'delay': '0.002112865448', 'lastCheck': 1345024788.2817931, 'code': 0, 'valid': True}}
>Thread-1943::DEBUG::2012-08-15 11:59:57,235::task::588::TaskManager.Task::(_updateState) Task=`2ce7998b-ee70-4a56-a2dd-ed440bd8725d`::moving from state preparing -> state finished
>Thread-1943::DEBUG::2012-08-15 11:59:57,235::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-1943::DEBUG::2012-08-15 11:59:57,236::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-1943::DEBUG::2012-08-15 11:59:57,236::task::978::TaskManager.Task::(_decref) Task=`2ce7998b-ee70-4a56-a2dd-ed440bd8725d`::ref 0 aborting False
>Thread-1946::DEBUG::2012-08-15 12:00:00,989::BindingXMLRPC::164::vds::(wrapper) [10.34.63.8]
>Thread-1946::DEBUG::2012-08-15 12:00:00,990::task::588::TaskManager.Task::(_updateState) Task=`7a43e1bc-b248-4689-add1-b1a8741e5dc0`::moving from state init -> state preparing
>Thread-1946::INFO::2012-08-15 12:00:00,990::logUtils::37::dispatcher::(wrapper) Run and protect: deactivateStorageDomain(sdUUID='ab9c2853-40c8-486d-a907-c35fe1b57594', spUUID='ae32878d-2639-47d7-b751-0ced2b0cd4d2', msdUUID='00000000-0000-0000-0000-000000000000', masterVersion=1, options=None)
>Thread-1946::DEBUG::2012-08-15 12:00:00,990::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.ae32878d-2639-47d7-b751-0ced2b0cd4d2`ReqID=`b11cc795-7edc-4df1-b251-0f1fc9a7137b`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-1946::DEBUG::2012-08-15 12:00:00,991::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.ae32878d-2639-47d7-b751-0ced2b0cd4d2' for lock type 'exclusive'
>Thread-1946::DEBUG::2012-08-15 12:00:00,991::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.ae32878d-2639-47d7-b751-0ced2b0cd4d2' is free. Now locking as 'exclusive' (1 active user)
>Thread-1946::DEBUG::2012-08-15 12:00:00,991::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.ae32878d-2639-47d7-b751-0ced2b0cd4d2`ReqID=`b11cc795-7edc-4df1-b251-0f1fc9a7137b`::Granted request
>Thread-1946::DEBUG::2012-08-15 12:00:00,992::task::817::TaskManager.Task::(resourceAcquired) Task=`7a43e1bc-b248-4689-add1-b1a8741e5dc0`::_resourcesAcquired: Storage.ae32878d-2639-47d7-b751-0ced2b0cd4d2 (exclusive)
>Thread-1946::DEBUG::2012-08-15 12:00:00,992::task::978::TaskManager.Task::(_decref) Task=`7a43e1bc-b248-4689-add1-b1a8741e5dc0`::ref 1 aborting False
>Thread-1946::DEBUG::2012-08-15 12:00:00,992::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.ab9c2853-40c8-486d-a907-c35fe1b57594`ReqID=`32b04107-1144-4380-bbb3-ba7ebc02da97`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-1946::DEBUG::2012-08-15 12:00:00,993::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.ab9c2853-40c8-486d-a907-c35fe1b57594' for lock type 'exclusive'
>Thread-1946::DEBUG::2012-08-15 12:00:00,993::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.ab9c2853-40c8-486d-a907-c35fe1b57594' is free. Now locking as 'exclusive' (1 active user)
>Thread-1946::DEBUG::2012-08-15 12:00:00,993::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.ab9c2853-40c8-486d-a907-c35fe1b57594`ReqID=`32b04107-1144-4380-bbb3-ba7ebc02da97`::Granted request
>Thread-1946::DEBUG::2012-08-15 12:00:00,994::task::817::TaskManager.Task::(resourceAcquired) Task=`7a43e1bc-b248-4689-add1-b1a8741e5dc0`::_resourcesAcquired: Storage.ab9c2853-40c8-486d-a907-c35fe1b57594 (exclusive)
>Thread-1946::DEBUG::2012-08-15 12:00:00,994::task::978::TaskManager.Task::(_decref) Task=`7a43e1bc-b248-4689-add1-b1a8741e5dc0`::ref 1 aborting False
>Thread-1946::INFO::2012-08-15 12:00:00,994::sp::1074::Storage.StoragePool::(deactivateSD) sdUUID=ab9c2853-40c8-486d-a907-c35fe1b57594 spUUID=ae32878d-2639-47d7-b751-0ced2b0cd4d2 newMsdUUID=00000000-0000-0000-0000-000000000000
>Thread-1946::INFO::2012-08-15 12:00:00,995::fileSD::225::Storage.StorageDomain::(validate) sdUUID=ab9c2853-40c8-486d-a907-c35fe1b57594
>Thread-1946::DEBUG::2012-08-15 12:00:00,998::persistentDict::226::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=NFS02', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=1', 'POOL_DESCRIPTION=DC1', 'POOL_DOMAINS=ab9c2853-40c8-486d-a907-c35fe1b57594:Active', 'POOL_SPM_ID=1', 'POOL_SPM_LVER=0', 'POOL_UUID=ae32878d-2639-47d7-b751-0ced2b0cd4d2', 'REMOTE_PATH=str-02.rhev.lab.eng.brq.redhat.com:/mnt/export/nfs/50/nfs02', 'ROLE=Master', 'SDUUID=ab9c2853-40c8-486d-a907-c35fe1b57594', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=43aede007630a78979a65149bf914547b03d9134']
>Thread-1946::INFO::2012-08-15 12:00:00,998::sp::1101::Storage.StoragePool::(deactivateSD) Silently ignoring the deactivation request for the master domain ab9c2853-40c8-486d-a907-c35fe1b57594
>Thread-1946::INFO::2012-08-15 12:00:00,999::logUtils::39::dispatcher::(wrapper) Run and protect: deactivateStorageDomain, Return response: None
>Thread-1946::DEBUG::2012-08-15 12:00:00,999::task::1172::TaskManager.Task::(prepare) Task=`7a43e1bc-b248-4689-add1-b1a8741e5dc0`::finished: None
>Thread-1946::DEBUG::2012-08-15 12:00:00,999::task::588::TaskManager.Task::(_updateState) Task=`7a43e1bc-b248-4689-add1-b1a8741e5dc0`::moving from state preparing -> state finished
>Thread-1946::DEBUG::2012-08-15 12:00:00,999::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.ae32878d-2639-47d7-b751-0ced2b0cd4d2': < ResourceRef 'Storage.ae32878d-2639-47d7-b751-0ced2b0cd4d2', isValid: 'True' obj: 'None'>, 'Storage.ab9c2853-40c8-486d-a907-c35fe1b57594': < ResourceRef 'Storage.ab9c2853-40c8-486d-a907-c35fe1b57594', isValid: 'True' obj: 'None'>}
>Thread-1946::DEBUG::2012-08-15 12:00:01,000::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-1946::DEBUG::2012-08-15 12:00:01,000::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.ae32878d-2639-47d7-b751-0ced2b0cd4d2'
>Thread-1946::DEBUG::2012-08-15 12:00:01,000::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.ae32878d-2639-47d7-b751-0ced2b0cd4d2' (0 active users)
>Thread-1946::DEBUG::2012-08-15 12:00:01,001::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.ae32878d-2639-47d7-b751-0ced2b0cd4d2' is free, finding out if anyone is waiting for it.
>Thread-1946::DEBUG::2012-08-15 12:00:01,001::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.ae32878d-2639-47d7-b751-0ced2b0cd4d2', Clearing records.
>Thread-1946::DEBUG::2012-08-15 12:00:01,001::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.ab9c2853-40c8-486d-a907-c35fe1b57594'
>Thread-1946::DEBUG::2012-08-15 12:00:01,002::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.ab9c2853-40c8-486d-a907-c35fe1b57594' (0 active users)
>Thread-1946::DEBUG::2012-08-15 12:00:01,002::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.ab9c2853-40c8-486d-a907-c35fe1b57594' is free, finding out if anyone is waiting for it.
>Thread-1946::DEBUG::2012-08-15 12:00:01,002::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.ab9c2853-40c8-486d-a907-c35fe1b57594', Clearing records.
>Thread-1946::DEBUG::2012-08-15 12:00:01,002::task::978::TaskManager.Task::(_decref) Task=`7a43e1bc-b248-4689-add1-b1a8741e5dc0`::ref 0 aborting False
>Thread-1947::DEBUG::2012-08-15 12:00:01,034::BindingXMLRPC::164::vds::(wrapper) [10.34.63.8]
>Thread-1947::DEBUG::2012-08-15 12:00:01,035::task::588::TaskManager.Task::(_updateState) Task=`690b69b1-a00d-4d9d-ab24-c9fd497ea72f`::moving from state init -> state preparing
>Thread-1947::INFO::2012-08-15 12:00:01,035::logUtils::37::dispatcher::(wrapper) Run and protect: getAllTasksStatuses(spUUID=None, options=None)
>Thread-1947::DEBUG::2012-08-15 12:00:01,035::taskManager::103::TaskManager::(getAllTasksStatuses) Entry.
>Thread-1947::DEBUG::2012-08-15 12:00:01,036::taskManager::112::TaskManager::(getAllTasksStatuses) Return: {}
>Thread-1947::INFO::2012-08-15 12:00:01,036::logUtils::39::dispatcher::(wrapper) Run and protect: getAllTasksStatuses, Return response: {'allTasksStatus': {}}
>Thread-1947::DEBUG::2012-08-15 12:00:01,036::task::1172::TaskManager.Task::(prepare) Task=`690b69b1-a00d-4d9d-ab24-c9fd497ea72f`::finished: {'allTasksStatus': {}}
>Thread-1947::DEBUG::2012-08-15 12:00:01,036::task::588::TaskManager.Task::(_updateState) Task=`690b69b1-a00d-4d9d-ab24-c9fd497ea72f`::moving from state preparing -> state finished
>Thread-1947::DEBUG::2012-08-15 12:00:01,037::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-1947::DEBUG::2012-08-15 12:00:01,037::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-1947::DEBUG::2012-08-15 12:00:01,037::task::978::TaskManager.Task::(_decref) Task=`690b69b1-a00d-4d9d-ab24-c9fd497ea72f`::ref 0 aborting False
>Thread-1948::DEBUG::2012-08-15 12:00:01,041::BindingXMLRPC::164::vds::(wrapper) [10.34.63.8]
>Thread-1948::DEBUG::2012-08-15 12:00:01,042::task::588::TaskManager.Task::(_updateState) Task=`b69842b6-396a-46de-a532-93363c7e9c23`::moving from state init -> state preparing
>Thread-1948::INFO::2012-08-15 12:00:01,042::logUtils::37::dispatcher::(wrapper) Run and protect: spmStop(spUUID='ae32878d-2639-47d7-b751-0ced2b0cd4d2', options=None)
>Thread-1948::DEBUG::2012-08-15 12:00:01,042::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.ae32878d-2639-47d7-b751-0ced2b0cd4d2`ReqID=`3a565dd2-4ef4-4ca5-be1c-a27320a46ed5`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-1948::DEBUG::2012-08-15 12:00:01,043::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.ae32878d-2639-47d7-b751-0ced2b0cd4d2' for lock type 'exclusive'
>Thread-1948::DEBUG::2012-08-15 12:00:01,043::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.ae32878d-2639-47d7-b751-0ced2b0cd4d2' is free. Now locking as 'exclusive' (1 active user)
>Thread-1948::DEBUG::2012-08-15 12:00:01,043::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.ae32878d-2639-47d7-b751-0ced2b0cd4d2`ReqID=`3a565dd2-4ef4-4ca5-be1c-a27320a46ed5`::Granted request
>Thread-1948::DEBUG::2012-08-15 12:00:01,044::task::817::TaskManager.Task::(resourceAcquired) Task=`b69842b6-396a-46de-a532-93363c7e9c23`::_resourcesAcquired: Storage.ae32878d-2639-47d7-b751-0ced2b0cd4d2 (exclusive)
>Thread-1948::DEBUG::2012-08-15 12:00:01,044::task::978::TaskManager.Task::(_decref) Task=`b69842b6-396a-46de-a532-93363c7e9c23`::ref 1 aborting False
>Thread-1948::DEBUG::2012-08-15 12:00:01,044::sp::320::Storage.StoragePool::(_shutDownUpgrade) Shutting down upgrade process
>Thread-1948::DEBUG::2012-08-15 12:00:01,045::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.upgrade_ae32878d-2639-47d7-b751-0ced2b0cd4d2`ReqID=`c7390afc-d2ed-4e54-a8c6-0471ad979b02`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-1948::DEBUG::2012-08-15 12:00:01,045::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.upgrade_ae32878d-2639-47d7-b751-0ced2b0cd4d2' for lock type 'exclusive'
>Thread-1948::DEBUG::2012-08-15 12:00:01,045::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.upgrade_ae32878d-2639-47d7-b751-0ced2b0cd4d2' is free. Now locking as 'exclusive' (1 active user)
>Thread-1948::DEBUG::2012-08-15 12:00:01,046::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.upgrade_ae32878d-2639-47d7-b751-0ced2b0cd4d2`ReqID=`c7390afc-d2ed-4e54-a8c6-0471ad979b02`::Granted request
>Thread-1948::DEBUG::2012-08-15 12:00:01,046::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.upgrade_ae32878d-2639-47d7-b751-0ced2b0cd4d2'
>Thread-1948::DEBUG::2012-08-15 12:00:01,046::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.upgrade_ae32878d-2639-47d7-b751-0ced2b0cd4d2' (0 active users)
>Thread-1948::DEBUG::2012-08-15 12:00:01,047::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.upgrade_ae32878d-2639-47d7-b751-0ced2b0cd4d2' is free, finding out if anyone is waiting for it.
>Thread-1948::DEBUG::2012-08-15 12:00:01,047::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.upgrade_ae32878d-2639-47d7-b751-0ced2b0cd4d2', Clearing records.
>Thread-1948::DEBUG::2012-08-15 12:00:01,050::sp::360::Storage.StoragePool::(cleanupMasterMount) master `/rhev/data-center/mnt/blockSD/346b78b2-add3-48a0-9012-0b3d6960054d/master` is not mounted, skipping
>Thread-1948::DEBUG::2012-08-15 12:00:01,052::sp::360::Storage.StoragePool::(cleanupMasterMount) master `/rhev/data-center/mnt/blockSD/11958807-b912-4363-8f3e-6d087608764f/master` is not mounted, skipping
>Thread-1948::DEBUG::2012-08-15 12:00:01,052::persistentDict::162::Storage.PersistentDict::(transaction) Starting transaction
>Thread-1948::DEBUG::2012-08-15 12:00:01,053::persistentDict::168::Storage.PersistentDict::(transaction) Flushing changes
>Thread-1948::DEBUG::2012-08-15 12:00:01,053::persistentDict::287::Storage.PersistentDict::(flush) about to write lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=NFS02', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=1', 'POOL_DESCRIPTION=DC1', 'POOL_DOMAINS=ab9c2853-40c8-486d-a907-c35fe1b57594:Active', 'POOL_SPM_ID=-1', 'POOL_SPM_LVER=0', 'POOL_UUID=ae32878d-2639-47d7-b751-0ced2b0cd4d2', 'REMOTE_PATH=str-02.rhev.lab.eng.brq.redhat.com:/mnt/export/nfs/50/nfs02', 'ROLE=Master', 'SDUUID=ab9c2853-40c8-486d-a907-c35fe1b57594', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=20188ab1f9373d662f406127c2d0b073255f654d']
>Thread-1948::DEBUG::2012-08-15 12:00:01,060::persistentDict::170::Storage.PersistentDict::(transaction) Finished transaction
>Thread-1948::INFO::2012-08-15 12:00:01,060::safelease::239::SANLock::(release) Releasing cluster lock for domain ab9c2853-40c8-486d-a907-c35fe1b57594
>Thread-1948::DEBUG::2012-08-15 12:00:01,064::safelease::250::SANLock::(release) Cluster lock for domain ab9c2853-40c8-486d-a907-c35fe1b57594 successfully released
>Thread-1948::INFO::2012-08-15 12:00:01,064::logUtils::39::dispatcher::(wrapper) Run and protect: spmStop, Return response: None
>Thread-1948::DEBUG::2012-08-15 12:00:01,064::task::1172::TaskManager.Task::(prepare) Task=`b69842b6-396a-46de-a532-93363c7e9c23`::finished: None
>Thread-1948::DEBUG::2012-08-15 12:00:01,065::task::588::TaskManager.Task::(_updateState) Task=`b69842b6-396a-46de-a532-93363c7e9c23`::moving from state preparing -> state finished
>Thread-1948::DEBUG::2012-08-15 12:00:01,065::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.ae32878d-2639-47d7-b751-0ced2b0cd4d2': < ResourceRef 'Storage.ae32878d-2639-47d7-b751-0ced2b0cd4d2', isValid: 'True' obj: 'None'>}
>Thread-1948::DEBUG::2012-08-15 12:00:01,065::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-1948::DEBUG::2012-08-15 12:00:01,065::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.ae32878d-2639-47d7-b751-0ced2b0cd4d2'
>Thread-1948::DEBUG::2012-08-15 12:00:01,066::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.ae32878d-2639-47d7-b751-0ced2b0cd4d2' (0 active users)
>Thread-1948::DEBUG::2012-08-15 12:00:01,066::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.ae32878d-2639-47d7-b751-0ced2b0cd4d2' is free, finding out if anyone is waiting for it.
>Thread-1948::DEBUG::2012-08-15 12:00:01,066::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.ae32878d-2639-47d7-b751-0ced2b0cd4d2', Clearing records.
>Thread-1948::DEBUG::2012-08-15 12:00:01,067::task::978::TaskManager.Task::(_decref) Task=`b69842b6-396a-46de-a532-93363c7e9c23`::ref 0 aborting False
>Thread-1949::DEBUG::2012-08-15 12:00:01,081::BindingXMLRPC::164::vds::(wrapper) [10.34.63.8]
>Thread-1949::DEBUG::2012-08-15 12:00:01,082::task::588::TaskManager.Task::(_updateState) Task=`a6723325-d332-4ab6-804e-3eff8ab19e5a`::moving from state init -> state preparing
>Thread-1949::INFO::2012-08-15 12:00:01,082::logUtils::37::dispatcher::(wrapper) Run and protect: disconnectStoragePool(spUUID='ae32878d-2639-47d7-b751-0ced2b0cd4d2', hostID=1, scsiKey='ae32878d-2639-47d7-b751-0ced2b0cd4d2', remove=False, options=None)
>Thread-1949::DEBUG::2012-08-15 12:00:01,083::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.ae32878d-2639-47d7-b751-0ced2b0cd4d2`ReqID=`19a1f95f-2e05-4e7f-8dd4-082edb4cd781`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-1949::DEBUG::2012-08-15 12:00:01,083::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.ae32878d-2639-47d7-b751-0ced2b0cd4d2' for lock type 'exclusive'
>Thread-1949::DEBUG::2012-08-15 12:00:01,083::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.ae32878d-2639-47d7-b751-0ced2b0cd4d2' is free. Now locking as 'exclusive' (1 active user)
>Thread-1949::DEBUG::2012-08-15 12:00:01,084::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.ae32878d-2639-47d7-b751-0ced2b0cd4d2`ReqID=`19a1f95f-2e05-4e7f-8dd4-082edb4cd781`::Granted request
>Thread-1949::DEBUG::2012-08-15 12:00:01,084::task::817::TaskManager.Task::(resourceAcquired) Task=`a6723325-d332-4ab6-804e-3eff8ab19e5a`::_resourcesAcquired: Storage.ae32878d-2639-47d7-b751-0ced2b0cd4d2 (exclusive)
>Thread-1949::DEBUG::2012-08-15 12:00:01,084::task::978::TaskManager.Task::(_decref) Task=`a6723325-d332-4ab6-804e-3eff8ab19e5a`::ref 1 aborting False
>Thread-1949::INFO::2012-08-15 12:00:01,085::sp::664::Storage.StoragePool::(disconnect) Disconnect from the storage pool ae32878d-2639-47d7-b751-0ced2b0cd4d2
>Thread-145::DEBUG::2012-08-15 12:00:01,086::domainMonitor::182::Storage.DomainMonitor::(_monitorDomain) Monitorg for domain ab9c2853-40c8-486d-a907-c35fe1b57594 is stopping
>Thread-145::INFO::2012-08-15 12:00:01,087::safelease::183::SANLock::(releaseHostId) Releasing host id for domain ab9c2853-40c8-486d-a907-c35fe1b57594 (id: 1)
>Thread-145::DEBUG::2012-08-15 12:00:03,087::safelease::193::SANLock::(releaseHostId) Host id for domain ab9c2853-40c8-486d-a907-c35fe1b57594 released successfully (id: 1)
>Thread-1949::INFO::2012-08-15 12:00:03,088::logUtils::39::dispatcher::(wrapper) Run and protect: disconnectStoragePool, Return response: True
>Thread-1949::DEBUG::2012-08-15 12:00:03,089::task::1172::TaskManager.Task::(prepare) Task=`a6723325-d332-4ab6-804e-3eff8ab19e5a`::finished: True
>Thread-1949::DEBUG::2012-08-15 12:00:03,089::task::588::TaskManager.Task::(_updateState) Task=`a6723325-d332-4ab6-804e-3eff8ab19e5a`::moving from state preparing -> state finished
>Thread-1949::DEBUG::2012-08-15 12:00:03,089::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.ae32878d-2639-47d7-b751-0ced2b0cd4d2': < ResourceRef 'Storage.ae32878d-2639-47d7-b751-0ced2b0cd4d2', isValid: 'True' obj: 'None'>}
>Thread-1949::DEBUG::2012-08-15 12:00:03,089::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-1949::DEBUG::2012-08-15 12:00:03,090::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.ae32878d-2639-47d7-b751-0ced2b0cd4d2'
>Thread-1949::DEBUG::2012-08-15 12:00:03,090::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.ae32878d-2639-47d7-b751-0ced2b0cd4d2' (0 active users)
>Thread-1949::DEBUG::2012-08-15 12:00:03,090::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.ae32878d-2639-47d7-b751-0ced2b0cd4d2' is free, finding out if anyone is waiting for it.
>Thread-1949::DEBUG::2012-08-15 12:00:03,091::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.ae32878d-2639-47d7-b751-0ced2b0cd4d2', Clearing records.
>Thread-1949::DEBUG::2012-08-15 12:00:03,091::task::978::TaskManager.Task::(_decref) Task=`a6723325-d332-4ab6-804e-3eff8ab19e5a`::ref 0 aborting False
>Thread-1951::DEBUG::2012-08-15 12:00:03,105::BindingXMLRPC::164::vds::(wrapper) [10.34.63.8]
>Thread-1951::DEBUG::2012-08-15 12:00:03,106::task::588::TaskManager.Task::(_updateState) Task=`b8192f15-814c-4e29-a1ee-a77f8ed8d745`::moving from state init -> state preparing
>Thread-1951::INFO::2012-08-15 12:00:03,106::logUtils::37::dispatcher::(wrapper) Run and protect: disconnectStorageServer(domType=1, spUUID='00000000-0000-0000-0000-000000000000', conList=[{'connection': 'str-02.rhev.lab.eng.brq.redhat.com:/mnt/export/nfs/50/nfs02', 'iqn': '', 'portal': '', 'user': '', 'password': '******', 'id': '8f3b2e2d-57c6-48ba-8055-80209863db77', 'port': ''}], options=None)
>Thread-1951::DEBUG::2012-08-15 12:00:03,107::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /bin/umount -f -l /rhev/data-center/mnt/str-02.rhev.lab.eng.brq.redhat.com:_mnt_export_nfs_50_nfs02' (cwd None)
>Thread-1951::DEBUG::2012-08-15 12:00:03,153::misc::1080::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
>Thread-1951::DEBUG::2012-08-15 12:00:03,154::misc::1082::SamplingMethod::(__call__) Got in to sampling method
>Thread-1951::DEBUG::2012-08-15 12:00:03,155::misc::1080::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
>Thread-1951::DEBUG::2012-08-15 12:00:03,155::misc::1082::SamplingMethod::(__call__) Got in to sampling method
>Thread-1951::DEBUG::2012-08-15 12:00:03,155::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
>Thread-1951::DEBUG::2012-08-15 12:00:03,169::__init__::1164::Storage.Misc.excCmd::(_log) FAILED: <err> = 'iscsiadm: No session found.\n'; <rc> = 21
>Thread-1951::DEBUG::2012-08-15 12:00:03,169::misc::1090::SamplingMethod::(__call__) Returning last result
>Thread-1951::DEBUG::2012-08-15 12:00:05,181::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/multipath' (cwd None)
>Thread-1951::DEBUG::2012-08-15 12:00:05,338::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
>Thread-1951::DEBUG::2012-08-15 12:00:05,345::lvm::460::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-1951::DEBUG::2012-08-15 12:00:05,351::lvm::462::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-1951::DEBUG::2012-08-15 12:00:05,352::lvm::472::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-1951::DEBUG::2012-08-15 12:00:05,352::lvm::474::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-1951::DEBUG::2012-08-15 12:00:05,353::lvm::493::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-1951::DEBUG::2012-08-15 12:00:05,353::lvm::495::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-1951::DEBUG::2012-08-15 12:00:05,353::misc::1090::SamplingMethod::(__call__) Returning last result
>Thread-1951::INFO::2012-08-15 12:00:05,353::logUtils::39::dispatcher::(wrapper) Run and protect: disconnectStorageServer, Return response: {'statuslist': [{'status': 0, 'id': '8f3b2e2d-57c6-48ba-8055-80209863db77'}]}
>Thread-1951::DEBUG::2012-08-15 12:00:05,354::task::1172::TaskManager.Task::(prepare) Task=`b8192f15-814c-4e29-a1ee-a77f8ed8d745`::finished: {'statuslist': [{'status': 0, 'id': '8f3b2e2d-57c6-48ba-8055-80209863db77'}]}
>Thread-1951::DEBUG::2012-08-15 12:00:05,354::task::588::TaskManager.Task::(_updateState) Task=`b8192f15-814c-4e29-a1ee-a77f8ed8d745`::moving from state preparing -> state finished
>Thread-1951::DEBUG::2012-08-15 12:00:05,354::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-1951::DEBUG::2012-08-15 12:00:05,355::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-1951::DEBUG::2012-08-15 12:00:05,355::task::978::TaskManager.Task::(_decref) Task=`b8192f15-814c-4e29-a1ee-a77f8ed8d745`::ref 0 aborting False
>Thread-1954::DEBUG::2012-08-15 12:00:07,308::task::588::TaskManager.Task::(_updateState) Task=`930ca1a9-1f1b-4d18-91fe-9d1ebe21cd31`::moving from state init -> state preparing
>Thread-1954::INFO::2012-08-15 12:00:07,309::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-1954::INFO::2012-08-15 12:00:07,309::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
>Thread-1954::DEBUG::2012-08-15 12:00:07,309::task::1172::TaskManager.Task::(prepare) Task=`930ca1a9-1f1b-4d18-91fe-9d1ebe21cd31`::finished: {}
>Thread-1954::DEBUG::2012-08-15 12:00:07,309::task::588::TaskManager.Task::(_updateState) Task=`930ca1a9-1f1b-4d18-91fe-9d1ebe21cd31`::moving from state preparing -> state finished
>Thread-1954::DEBUG::2012-08-15 12:00:07,310::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-1954::DEBUG::2012-08-15 12:00:07,310::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-1954::DEBUG::2012-08-15 12:00:07,310::task::978::TaskManager.Task::(_decref) Task=`930ca1a9-1f1b-4d18-91fe-9d1ebe21cd31`::ref 0 aborting False
>Thread-1960::DEBUG::2012-08-15 12:00:17,365::task::588::TaskManager.Task::(_updateState) Task=`2ff59e24-bf79-4910-a43d-f9f89fc51d1e`::moving from state init -> state preparing
>Thread-1960::INFO::2012-08-15 12:00:17,365::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-1960::INFO::2012-08-15 12:00:17,366::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
>Thread-1960::DEBUG::2012-08-15 12:00:17,366::task::1172::TaskManager.Task::(prepare) Task=`2ff59e24-bf79-4910-a43d-f9f89fc51d1e`::finished: {}
>Thread-1960::DEBUG::2012-08-15 12:00:17,366::task::588::TaskManager.Task::(_updateState) Task=`2ff59e24-bf79-4910-a43d-f9f89fc51d1e`::moving from state preparing -> state finished
>Thread-1960::DEBUG::2012-08-15 12:00:17,366::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-1960::DEBUG::2012-08-15 12:00:17,367::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-1960::DEBUG::2012-08-15 12:00:17,367::task::978::TaskManager.Task::(_decref) Task=`2ff59e24-bf79-4910-a43d-f9f89fc51d1e`::ref 0 aborting False
>Thread-1966::DEBUG::2012-08-15 12:00:27,423::task::588::TaskManager.Task::(_updateState) Task=`edf0e2db-3b0b-4063-9625-2f87b3819711`::moving from state init -> state preparing
>Thread-1966::INFO::2012-08-15 12:00:27,423::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-1966::INFO::2012-08-15 12:00:27,424::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
>Thread-1966::DEBUG::2012-08-15 12:00:27,424::task::1172::TaskManager.Task::(prepare) Task=`edf0e2db-3b0b-4063-9625-2f87b3819711`::finished: {}
>Thread-1966::DEBUG::2012-08-15 12:00:27,424::task::588::TaskManager.Task::(_updateState) Task=`edf0e2db-3b0b-4063-9625-2f87b3819711`::moving from state preparing -> state finished
>Thread-1966::DEBUG::2012-08-15 12:00:27,424::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-1966::DEBUG::2012-08-15 12:00:27,425::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-1966::DEBUG::2012-08-15 12:00:27,425::task::978::TaskManager.Task::(_decref) Task=`edf0e2db-3b0b-4063-9625-2f87b3819711`::ref 0 aborting False
>Thread-1968::DEBUG::2012-08-15 12:00:27,863::BindingXMLRPC::164::vds::(wrapper) [10.34.63.8]
>Thread-1968::DEBUG::2012-08-15 12:00:27,863::task::588::TaskManager.Task::(_updateState) Task=`0b85b5e8-411b-41d6-b35b-ede0e834b905`::moving from state init -> state preparing
>Thread-1968::INFO::2012-08-15 12:00:27,864::logUtils::37::dispatcher::(wrapper) Run and protect: validateStorageServerConnection(domType=1, spUUID='00000000-0000-0000-0000-000000000000', conList=[{'connection': 'str-02.rhev.lab.eng.brq.redhat.com:/mnt/export/nfs/50/nfs02', 'iqn': '', 'portal': '', 'user': '', 'password': '******', 'id': '8f3b2e2d-57c6-48ba-8055-80209863db77', 'port': ''}], options=None)
>Thread-1968::INFO::2012-08-15 12:00:27,864::logUtils::39::dispatcher::(wrapper) Run and protect: validateStorageServerConnection, Return response: {'statuslist': [{'status': 0, 'id': '8f3b2e2d-57c6-48ba-8055-80209863db77'}]}
>Thread-1968::DEBUG::2012-08-15 12:00:27,864::task::1172::TaskManager.Task::(prepare) Task=`0b85b5e8-411b-41d6-b35b-ede0e834b905`::finished: {'statuslist': [{'status': 0, 'id': '8f3b2e2d-57c6-48ba-8055-80209863db77'}]}
>Thread-1968::DEBUG::2012-08-15 12:00:27,865::task::588::TaskManager.Task::(_updateState) Task=`0b85b5e8-411b-41d6-b35b-ede0e834b905`::moving from state preparing -> state finished
>Thread-1968::DEBUG::2012-08-15 12:00:27,865::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-1968::DEBUG::2012-08-15 12:00:27,865::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-1968::DEBUG::2012-08-15 12:00:27,865::task::978::TaskManager.Task::(_decref) Task=`0b85b5e8-411b-41d6-b35b-ede0e834b905`::ref 0 aborting False
>Thread-1969::DEBUG::2012-08-15 12:00:27,874::BindingXMLRPC::164::vds::(wrapper) [10.34.63.8]
>Thread-1969::DEBUG::2012-08-15 12:00:27,875::task::588::TaskManager.Task::(_updateState) Task=`89792e93-b585-40c4-abd4-b8e07b9b124b`::moving from state init -> state preparing
>Thread-1969::INFO::2012-08-15 12:00:27,875::logUtils::37::dispatcher::(wrapper) Run and protect: connectStorageServer(domType=1, spUUID='00000000-0000-0000-0000-000000000000', conList=[{'connection': 'str-02.rhev.lab.eng.brq.redhat.com:/mnt/export/nfs/50/nfs02', 'iqn': '', 'portal': '', 'user': '', 'password': '******', 'id': '8f3b2e2d-57c6-48ba-8055-80209863db77', 'port': ''}], options=None)
>Thread-1969::DEBUG::2012-08-15 12:00:27,879::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /bin/mount -t nfs -o soft,nosharecache,timeo=600,retrans=6 str-02.rhev.lab.eng.brq.redhat.com:/mnt/export/nfs/50/nfs02 /rhev/data-center/mnt/str-02.rhev.lab.eng.brq.redhat.com:_mnt_export_nfs_50_nfs02' (cwd None)
>Thread-1969::DEBUG::2012-08-15 12:00:32,945::lvm::460::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-1969::DEBUG::2012-08-15 12:00:32,946::lvm::462::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-1969::DEBUG::2012-08-15 12:00:32,946::lvm::472::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-1969::DEBUG::2012-08-15 12:00:32,947::lvm::474::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-1969::DEBUG::2012-08-15 12:00:32,947::lvm::493::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-1969::DEBUG::2012-08-15 12:00:32,947::lvm::495::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-1969::INFO::2012-08-15 12:00:32,948::logUtils::39::dispatcher::(wrapper) Run and protect: connectStorageServer, Return response: {'statuslist': [{'status': 0, 'id': '8f3b2e2d-57c6-48ba-8055-80209863db77'}]}
>Thread-1969::DEBUG::2012-08-15 12:00:32,948::task::1172::TaskManager.Task::(prepare) Task=`89792e93-b585-40c4-abd4-b8e07b9b124b`::finished: {'statuslist': [{'status': 0, 'id': '8f3b2e2d-57c6-48ba-8055-80209863db77'}]}
>Thread-1969::DEBUG::2012-08-15 12:00:32,948::task::588::TaskManager.Task::(_updateState) Task=`89792e93-b585-40c4-abd4-b8e07b9b124b`::moving from state preparing -> state finished
>Thread-1969::DEBUG::2012-08-15 12:00:32,948::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-1969::DEBUG::2012-08-15 12:00:32,949::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-1969::DEBUG::2012-08-15 12:00:32,949::task::978::TaskManager.Task::(_decref) Task=`89792e93-b585-40c4-abd4-b8e07b9b124b`::ref 0 aborting False
>Thread-1972::DEBUG::2012-08-15 12:00:32,959::BindingXMLRPC::164::vds::(wrapper) [10.34.63.8]
>Thread-1972::DEBUG::2012-08-15 12:00:32,959::task::588::TaskManager.Task::(_updateState) Task=`e1cdab94-023e-4dc0-8b71-e2ec485a18d5`::moving from state init -> state preparing
>Thread-1972::INFO::2012-08-15 12:00:32,959::logUtils::37::dispatcher::(wrapper) Run and protect: connectStoragePool(spUUID='ae32878d-2639-47d7-b751-0ced2b0cd4d2', hostID=1, scsiKey='ae32878d-2639-47d7-b751-0ced2b0cd4d2', msdUUID='ab9c2853-40c8-486d-a907-c35fe1b57594', masterVersion=1, options=None)
>Thread-1972::DEBUG::2012-08-15 12:00:32,960::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.ae32878d-2639-47d7-b751-0ced2b0cd4d2`ReqID=`9ac80586-2eb2-4574-b892-83e1c8bb1a00`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-1972::DEBUG::2012-08-15 12:00:32,960::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.ae32878d-2639-47d7-b751-0ced2b0cd4d2' for lock type 'exclusive'
>Thread-1972::DEBUG::2012-08-15 12:00:32,961::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.ae32878d-2639-47d7-b751-0ced2b0cd4d2' is free. Now locking as 'exclusive' (1 active user)
>Thread-1972::DEBUG::2012-08-15 12:00:32,961::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.ae32878d-2639-47d7-b751-0ced2b0cd4d2`ReqID=`9ac80586-2eb2-4574-b892-83e1c8bb1a00`::Granted request
>Thread-1972::INFO::2012-08-15 12:00:32,961::sp::628::Storage.StoragePool::(connect) Connect host #1 to the storage pool ae32878d-2639-47d7-b751-0ced2b0cd4d2 with master domain: ab9c2853-40c8-486d-a907-c35fe1b57594 (ver = 1)
>Thread-1972::DEBUG::2012-08-15 12:00:32,963::lvm::460::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-1972::DEBUG::2012-08-15 12:00:32,963::lvm::462::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-1972::DEBUG::2012-08-15 12:00:32,964::lvm::472::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-1972::DEBUG::2012-08-15 12:00:32,964::lvm::474::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-1972::DEBUG::2012-08-15 12:00:32,964::lvm::493::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-1972::DEBUG::2012-08-15 12:00:32,965::lvm::495::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-1972::DEBUG::2012-08-15 12:00:32,965::misc::1080::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
>Thread-1972::DEBUG::2012-08-15 12:00:32,965::misc::1082::SamplingMethod::(__call__) Got in to sampling method
>Thread-1972::DEBUG::2012-08-15 12:00:32,965::misc::1080::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
>Thread-1972::DEBUG::2012-08-15 12:00:32,966::misc::1082::SamplingMethod::(__call__) Got in to sampling method
>Thread-1972::DEBUG::2012-08-15 12:00:32,966::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
>Thread-1972::DEBUG::2012-08-15 12:00:32,979::__init__::1164::Storage.Misc.excCmd::(_log) FAILED: <err> = 'iscsiadm: No session found.\n'; <rc> = 21
>Thread-1972::DEBUG::2012-08-15 12:00:32,980::misc::1090::SamplingMethod::(__call__) Returning last result
>Thread-1972::DEBUG::2012-08-15 12:00:34,991::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/multipath' (cwd None)
>Thread-1972::DEBUG::2012-08-15 12:00:35,041::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
>Thread-1972::DEBUG::2012-08-15 12:00:35,042::lvm::460::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-1972::DEBUG::2012-08-15 12:00:35,042::lvm::462::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-1972::DEBUG::2012-08-15 12:00:35,043::lvm::472::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-1972::DEBUG::2012-08-15 12:00:35,043::lvm::474::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-1972::DEBUG::2012-08-15 12:00:35,043::lvm::493::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-1972::DEBUG::2012-08-15 12:00:35,044::lvm::495::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-1972::DEBUG::2012-08-15 12:00:35,044::misc::1090::SamplingMethod::(__call__) Returning last result
>Thread-1972::DEBUG::2012-08-15 12:00:35,044::lvm::352::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
>Thread-1972::DEBUG::2012-08-15 12:00:35,045::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/lvm vgs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 filter = [ \\"r%.*%\\" ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1 }  backup {  retain_min = 50  retain_days = 0 } " --noheadings --units b --nosuffix --separator | -o uuid,name,attr,size,free,extent_size,extent_count,free_count,tags,vg_mda_size,vg_mda_free ab9c2853-40c8-486d-a907-c35fe1b57594' (cwd None)
>Thread-1972::DEBUG::2012-08-15 12:00:35,189::__init__::1164::Storage.Misc.excCmd::(_log) FAILED: <err> = '  Volume group "ab9c2853-40c8-486d-a907-c35fe1b57594" not found\n'; <rc> = 5
>Thread-1972::WARNING::2012-08-15 12:00:35,190::lvm::356::Storage.LVM::(_reloadvgs) lvm vgs failed: 5 [] ['  Volume group "ab9c2853-40c8-486d-a907-c35fe1b57594" not found']
>Thread-1972::DEBUG::2012-08-15 12:00:35,191::lvm::379::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
>Thread-1972::DEBUG::2012-08-15 12:00:35,198::fileSD::105::Storage.StorageDomain::(__init__) Reading domain in path /rhev/data-center/mnt/str-02.rhev.lab.eng.brq.redhat.com:_mnt_export_nfs_50_nfs02/ab9c2853-40c8-486d-a907-c35fe1b57594
>Thread-1972::DEBUG::2012-08-15 12:00:35,199::persistentDict::185::Storage.PersistentDict::(__init__) Created a persistant dict with FileMetadataRW backend
>Thread-1972::DEBUG::2012-08-15 12:00:35,202::persistentDict::226::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=NFS02', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=1', 'POOL_DESCRIPTION=DC1', 'POOL_DOMAINS=ab9c2853-40c8-486d-a907-c35fe1b57594:Active', 'POOL_SPM_ID=-1', 'POOL_SPM_LVER=0', 'POOL_UUID=ae32878d-2639-47d7-b751-0ced2b0cd4d2', 'REMOTE_PATH=str-02.rhev.lab.eng.brq.redhat.com:/mnt/export/nfs/50/nfs02', 'ROLE=Master', 'SDUUID=ab9c2853-40c8-486d-a907-c35fe1b57594', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=20188ab1f9373d662f406127c2d0b073255f654d']
>Thread-1972::DEBUG::2012-08-15 12:00:35,204::fileSD::389::Storage.StorageDomain::(imageGarbageCollector) Removing remnants of deleted images []
>Thread-1972::WARNING::2012-08-15 12:00:35,205::sd::317::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace ab9c2853-40c8-486d-a907-c35fe1b57594_imageNS already registered
>Thread-1972::WARNING::2012-08-15 12:00:35,205::sd::323::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace ab9c2853-40c8-486d-a907-c35fe1b57594_volumeNS already registered
>Thread-1972::DEBUG::2012-08-15 12:00:35,205::sp::1518::Storage.StoragePool::(getMasterDomain) Master domain ab9c2853-40c8-486d-a907-c35fe1b57594 verified, version 1
>Thread-1972::DEBUG::2012-08-15 12:00:35,206::misc::1080::SamplingMethod::(__call__) Trying to enter sampling method (storage.sp.updateMonitoringThreads)
>Thread-1972::DEBUG::2012-08-15 12:00:35,206::misc::1082::SamplingMethod::(__call__) Got in to sampling method
>Thread-1972::DEBUG::2012-08-15 12:00:35,208::persistentDict::226::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=NFS02', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=1', 'POOL_DESCRIPTION=DC1', 'POOL_DOMAINS=ab9c2853-40c8-486d-a907-c35fe1b57594:Active', 'POOL_SPM_ID=-1', 'POOL_SPM_LVER=0', 'POOL_UUID=ae32878d-2639-47d7-b751-0ced2b0cd4d2', 'REMOTE_PATH=str-02.rhev.lab.eng.brq.redhat.com:/mnt/export/nfs/50/nfs02', 'ROLE=Master', 'SDUUID=ab9c2853-40c8-486d-a907-c35fe1b57594', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=20188ab1f9373d662f406127c2d0b073255f654d']
>Thread-1972::DEBUG::2012-08-15 12:00:35,209::sp::1553::Storage.StoragePool::(updateMonitoringThreads) Storage Pool `ae32878d-2639-47d7-b751-0ced2b0cd4d2` started monitoring domain `ab9c2853-40c8-486d-a907-c35fe1b57594`
>Thread-1972::DEBUG::2012-08-15 12:00:35,210::misc::1090::SamplingMethod::(__call__) Returning last result
>Thread-1972::DEBUG::2012-08-15 12:00:35,212::lvm::352::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
>Thread-1972::DEBUG::2012-08-15 12:00:35,214::__init__::1164::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/lvm vgs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 filter = [ \\"r%.*%\\" ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1 }  backup {  retain_min = 50  retain_days = 0 } " --noheadings --units b --nosuffix --separator | -o uuid,name,attr,size,free,extent_size,extent_count,free_count,tags,vg_mda_size,vg_mda_free' (cwd None)
>Thread-1978::INFO::2012-08-15 12:00:35,228::safelease::160::SANLock::(acquireHostId) Acquiring host id for domain ab9c2853-40c8-486d-a907-c35fe1b57594 (id: 1)
>Thread-1978::DEBUG::2012-08-15 12:00:35,229::safelease::178::SANLock::(acquireHostId) Host id for domain ab9c2853-40c8-486d-a907-c35fe1b57594 successfully acquired (id: 1)
>Thread-1972::DEBUG::2012-08-15 12:00:35,339::__init__::1164::Storage.Misc.excCmd::(_log) SUCCESS: <err> = '  No volume groups found\n'; <rc> = 0
>Thread-1972::DEBUG::2012-08-15 12:00:35,339::lvm::379::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
>Thread-1972::INFO::2012-08-15 12:00:35,344::sp::1114::Storage.StoragePool::(_linkStorageDomain) Linking /rhev/data-center/mnt/str-02.rhev.lab.eng.brq.redhat.com:_mnt_export_nfs_50_nfs02/ab9c2853-40c8-486d-a907-c35fe1b57594 to /rhev/data-center/ae32878d-2639-47d7-b751-0ced2b0cd4d2/ab9c2853-40c8-486d-a907-c35fe1b57594
>Thread-1972::INFO::2012-08-15 12:00:35,345::sp::1114::Storage.StoragePool::(_linkStorageDomain) Linking /rhev/data-center/mnt/str-02.rhev.lab.eng.brq.redhat.com:_mnt_export_nfs_50_nfs02/ab9c2853-40c8-486d-a907-c35fe1b57594 to /rhev/data-center/ae32878d-2639-47d7-b751-0ced2b0cd4d2/mastersd
>Thread-1972::DEBUG::2012-08-15 12:00:35,346::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.ae32878d-2639-47d7-b751-0ced2b0cd4d2'
>Thread-1972::DEBUG::2012-08-15 12:00:35,346::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.ae32878d-2639-47d7-b751-0ced2b0cd4d2' (0 active users)
>Thread-1972::DEBUG::2012-08-15 12:00:35,346::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.ae32878d-2639-47d7-b751-0ced2b0cd4d2' is free, finding out if anyone is waiting for it.
>Thread-1972::DEBUG::2012-08-15 12:00:35,347::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.ae32878d-2639-47d7-b751-0ced2b0cd4d2', Clearing records.
>Thread-1972::INFO::2012-08-15 12:00:35,347::logUtils::39::dispatcher::(wrapper) Run and protect: connectStoragePool, Return response: True
>Thread-1972::DEBUG::2012-08-15 12:00:35,347::task::1172::TaskManager.Task::(prepare) Task=`e1cdab94-023e-4dc0-8b71-e2ec485a18d5`::finished: True
>Thread-1972::DEBUG::2012-08-15 12:00:35,348::task::588::TaskManager.Task::(_updateState) Task=`e1cdab94-023e-4dc0-8b71-e2ec485a18d5`::moving from state preparing -> state finished
>Thread-1972::DEBUG::2012-08-15 12:00:35,348::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-1972::DEBUG::2012-08-15 12:00:35,348::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-1972::DEBUG::2012-08-15 12:00:35,348::task::978::TaskManager.Task::(_decref) Task=`e1cdab94-023e-4dc0-8b71-e2ec485a18d5`::ref 0 aborting False
>Thread-1983::DEBUG::2012-08-15 12:00:35,423::BindingXMLRPC::164::vds::(wrapper) [10.34.63.8]
>Thread-1983::DEBUG::2012-08-15 12:00:35,424::task::588::TaskManager.Task::(_updateState) Task=`d05cef41-c4c2-4081-a137-f773a31d6362`::moving from state init -> state preparing
>Thread-1983::INFO::2012-08-15 12:00:35,424::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='ae32878d-2639-47d7-b751-0ced2b0cd4d2', options=None)
>Thread-1983::INFO::2012-08-15 12:00:35,424::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': -1, 'spmStatus': 'Free', 'spmLver': 0}}
>Thread-1983::DEBUG::2012-08-15 12:00:35,425::task::1172::TaskManager.Task::(prepare) Task=`d05cef41-c4c2-4081-a137-f773a31d6362`::finished: {'spm_st': {'spmId': -1, 'spmStatus': 'Free', 'spmLver': 0}}
>Thread-1983::DEBUG::2012-08-15 12:00:35,425::task::588::TaskManager.Task::(_updateState) Task=`d05cef41-c4c2-4081-a137-f773a31d6362`::moving from state preparing -> state finished
>Thread-1983::DEBUG::2012-08-15 12:00:35,425::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-1983::DEBUG::2012-08-15 12:00:35,425::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-1983::DEBUG::2012-08-15 12:00:35,426::task::978::TaskManager.Task::(_decref) Task=`d05cef41-c4c2-4081-a137-f773a31d6362`::ref 0 aborting False
>Thread-1985::DEBUG::2012-08-15 12:00:35,608::BindingXMLRPC::164::vds::(wrapper) [10.34.63.8]
>Thread-1985::DEBUG::2012-08-15 12:00:35,608::task::588::TaskManager.Task::(_updateState) Task=`a0902b35-2e17-4cd6-8edc-602ad07b3752`::moving from state init -> state preparing
>Thread-1985::INFO::2012-08-15 12:00:35,609::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='ae32878d-2639-47d7-b751-0ced2b0cd4d2', options=None)
>Thread-1985::INFO::2012-08-15 12:00:35,609::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': -1, 'spmStatus': 'Free', 'spmLver': 0}}
>Thread-1985::DEBUG::2012-08-15 12:00:35,609::task::1172::TaskManager.Task::(prepare) Task=`a0902b35-2e17-4cd6-8edc-602ad07b3752`::finished: {'spm_st': {'spmId': -1, 'spmStatus': 'Free', 'spmLver': 0}}
>Thread-1985::DEBUG::2012-08-15 12:00:35,609::task::588::TaskManager.Task::(_updateState) Task=`a0902b35-2e17-4cd6-8edc-602ad07b3752`::moving from state preparing -> state finished
>Thread-1985::DEBUG::2012-08-15 12:00:35,610::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-1985::DEBUG::2012-08-15 12:00:35,610::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-1985::DEBUG::2012-08-15 12:00:35,610::task::978::TaskManager.Task::(_decref) Task=`a0902b35-2e17-4cd6-8edc-602ad07b3752`::ref 0 aborting False
>Thread-1986::DEBUG::2012-08-15 12:00:37,489::task::588::TaskManager.Task::(_updateState) Task=`a76bffbe-38df-4ac6-a25a-3666f84d7ba8`::moving from state init -> state preparing
>Thread-1986::INFO::2012-08-15 12:00:37,489::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-1986::INFO::2012-08-15 12:00:37,490::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'ab9c2853-40c8-486d-a907-c35fe1b57594': {'delay': '0.00229692459106', 'lastCheck': 1345024835.2280581, 'code': 0, 'valid': True}}
>Thread-1986::DEBUG::2012-08-15 12:00:37,490::task::1172::TaskManager.Task::(prepare) Task=`a76bffbe-38df-4ac6-a25a-3666f84d7ba8`::finished: {'ab9c2853-40c8-486d-a907-c35fe1b57594': {'delay': '0.00229692459106', 'lastCheck': 1345024835.2280581, 'code': 0, 'valid': True}}
>Thread-1986::DEBUG::2012-08-15 12:00:37,490::task::588::TaskManager.Task::(_updateState) Task=`a76bffbe-38df-4ac6-a25a-3666f84d7ba8`::moving from state preparing -> state finished
>Thread-1986::DEBUG::2012-08-15 12:00:37,490::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-1986::DEBUG::2012-08-15 12:00:37,491::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-1986::DEBUG::2012-08-15 12:00:37,491::task::978::TaskManager.Task::(_decref) Task=`a76bffbe-38df-4ac6-a25a-3666f84d7ba8`::ref 0 aborting False
>Thread-1991::DEBUG::2012-08-15 12:00:44,987::BindingXMLRPC::164::vds::(wrapper) [10.34.63.8]
>Thread-1991::DEBUG::2012-08-15 12:00:44,987::task::588::TaskManager.Task::(_updateState) Task=`341ed0be-cec2-4390-96a9-dbb12bef10cc`::moving from state init -> state preparing
>Thread-1991::INFO::2012-08-15 12:00:44,988::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='ae32878d-2639-47d7-b751-0ced2b0cd4d2', options=None)
>Thread-1991::INFO::2012-08-15 12:00:44,988::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': -1, 'spmStatus': 'Free', 'spmLver': 0}}
>Thread-1991::DEBUG::2012-08-15 12:00:44,988::task::1172::TaskManager.Task::(prepare) Task=`341ed0be-cec2-4390-96a9-dbb12bef10cc`::finished: {'spm_st': {'spmId': -1, 'spmStatus': 'Free', 'spmLver': 0}}
>Thread-1991::DEBUG::2012-08-15 12:00:44,989::task::588::TaskManager.Task::(_updateState) Task=`341ed0be-cec2-4390-96a9-dbb12bef10cc`::moving from state preparing -> state finished
>Thread-1991::DEBUG::2012-08-15 12:00:44,989::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-1991::DEBUG::2012-08-15 12:00:44,989::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-1991::DEBUG::2012-08-15 12:00:44,989::task::978::TaskManager.Task::(_decref) Task=`341ed0be-cec2-4390-96a9-dbb12bef10cc`::ref 0 aborting False
>Thread-1993::DEBUG::2012-08-15 12:00:47,569::task::588::TaskManager.Task::(_updateState) Task=`aee5ef86-aed5-4cd3-a57e-d617c97b9f9d`::moving from state init -> state preparing
>Thread-1993::INFO::2012-08-15 12:00:47,569::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-1993::INFO::2012-08-15 12:00:47,570::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'ab9c2853-40c8-486d-a907-c35fe1b57594': {'delay': '0.00183796882629', 'lastCheck': 1345024845.2366309, 'code': 0, 'valid': True}}
>Thread-1993::DEBUG::2012-08-15 12:00:47,570::task::1172::TaskManager.Task::(prepare) Task=`aee5ef86-aed5-4cd3-a57e-d617c97b9f9d`::finished: {'ab9c2853-40c8-486d-a907-c35fe1b57594': {'delay': '0.00183796882629', 'lastCheck': 1345024845.2366309, 'code': 0, 'valid': True}}
>Thread-1993::DEBUG::2012-08-15 12:00:47,570::task::588::TaskManager.Task::(_updateState) Task=`aee5ef86-aed5-4cd3-a57e-d617c97b9f9d`::moving from state preparing -> state finished
>Thread-1993::DEBUG::2012-08-15 12:00:47,571::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-1993::DEBUG::2012-08-15 12:00:47,571::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-1993::DEBUG::2012-08-15 12:00:47,571::task::978::TaskManager.Task::(_decref) Task=`aee5ef86-aed5-4cd3-a57e-d617c97b9f9d`::ref 0 aborting False
>Thread-1998::DEBUG::2012-08-15 12:00:55,031::BindingXMLRPC::164::vds::(wrapper) [10.34.63.8]
>Thread-1998::DEBUG::2012-08-15 12:00:55,032::task::588::TaskManager.Task::(_updateState) Task=`f546906d-1e01-4980-a9ce-f9e0a86c6bd3`::moving from state init -> state preparing
>Thread-1998::INFO::2012-08-15 12:00:55,032::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='ae32878d-2639-47d7-b751-0ced2b0cd4d2', options=None)
>Thread-1998::INFO::2012-08-15 12:00:55,032::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': -1, 'spmStatus': 'Free', 'spmLver': 0}}
>Thread-1998::DEBUG::2012-08-15 12:00:55,033::task::1172::TaskManager.Task::(prepare) Task=`f546906d-1e01-4980-a9ce-f9e0a86c6bd3`::finished: {'spm_st': {'spmId': -1, 'spmStatus': 'Free', 'spmLver': 0}}
>Thread-1998::DEBUG::2012-08-15 12:00:55,033::task::588::TaskManager.Task::(_updateState) Task=`f546906d-1e01-4980-a9ce-f9e0a86c6bd3`::moving from state preparing -> state finished
>Thread-1998::DEBUG::2012-08-15 12:00:55,033::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-1998::DEBUG::2012-08-15 12:00:55,033::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-1998::DEBUG::2012-08-15 12:00:55,034::task::978::TaskManager.Task::(_decref) Task=`f546906d-1e01-4980-a9ce-f9e0a86c6bd3`::ref 0 aborting False
>Thread-2000::DEBUG::2012-08-15 12:00:57,629::task::588::TaskManager.Task::(_updateState) Task=`f280f556-71d4-46f5-a54f-996103d93600`::moving from state init -> state preparing
>Thread-2000::INFO::2012-08-15 12:00:57,629::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-2000::INFO::2012-08-15 12:00:57,630::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'ab9c2853-40c8-486d-a907-c35fe1b57594': {'delay': '0.0018630027771', 'lastCheck': 1345024855.243665, 'code': 0, 'valid': True}}
>Thread-2000::DEBUG::2012-08-15 12:00:57,630::task::1172::TaskManager.Task::(prepare) Task=`f280f556-71d4-46f5-a54f-996103d93600`::finished: {'ab9c2853-40c8-486d-a907-c35fe1b57594': {'delay': '0.0018630027771', 'lastCheck': 1345024855.243665, 'code': 0, 'valid': True}}
>Thread-2000::DEBUG::2012-08-15 12:00:57,630::task::588::TaskManager.Task::(_updateState) Task=`f280f556-71d4-46f5-a54f-996103d93600`::moving from state preparing -> state finished
>Thread-2000::DEBUG::2012-08-15 12:00:57,630::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-2000::DEBUG::2012-08-15 12:00:57,631::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-2000::DEBUG::2012-08-15 12:00:57,631::task::978::TaskManager.Task::(_decref) Task=`f280f556-71d4-46f5-a54f-996103d93600`::ref 0 aborting False
>Thread-2005::DEBUG::2012-08-15 12:01:05,083::BindingXMLRPC::164::vds::(wrapper) [10.34.63.8]
>Thread-2005::DEBUG::2012-08-15 12:01:05,084::task::588::TaskManager.Task::(_updateState) Task=`8e8bbaa8-cbb6-472b-8c12-b7afb461168c`::moving from state init -> state preparing
>Thread-2005::INFO::2012-08-15 12:01:05,084::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='ae32878d-2639-47d7-b751-0ced2b0cd4d2', options=None)
>Thread-2005::INFO::2012-08-15 12:01:05,085::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': -1, 'spmStatus': 'Free', 'spmLver': 0}}
>Thread-2005::DEBUG::2012-08-15 12:01:05,085::task::1172::TaskManager.Task::(prepare) Task=`8e8bbaa8-cbb6-472b-8c12-b7afb461168c`::finished: {'spm_st': {'spmId': -1, 'spmStatus': 'Free', 'spmLver': 0}}
>Thread-2005::DEBUG::2012-08-15 12:01:05,085::task::588::TaskManager.Task::(_updateState) Task=`8e8bbaa8-cbb6-472b-8c12-b7afb461168c`::moving from state preparing -> state finished
>Thread-2005::DEBUG::2012-08-15 12:01:05,085::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-2005::DEBUG::2012-08-15 12:01:05,086::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-2005::DEBUG::2012-08-15 12:01:05,086::task::978::TaskManager.Task::(_decref) Task=`8e8bbaa8-cbb6-472b-8c12-b7afb461168c`::ref 0 aborting False
>Thread-2007::DEBUG::2012-08-15 12:01:07,690::task::588::TaskManager.Task::(_updateState) Task=`6d083097-39e8-4c98-ad78-39ce96a52bd8`::moving from state init -> state preparing
>Thread-2007::INFO::2012-08-15 12:01:07,691::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-2007::INFO::2012-08-15 12:01:07,691::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'ab9c2853-40c8-486d-a907-c35fe1b57594': {'delay': '0.00234484672546', 'lastCheck': 1345024865.2535059, 'code': 0, 'valid': True}}
>Thread-2007::DEBUG::2012-08-15 12:01:07,691::task::1172::TaskManager.Task::(prepare) Task=`6d083097-39e8-4c98-ad78-39ce96a52bd8`::finished: {'ab9c2853-40c8-486d-a907-c35fe1b57594': {'delay': '0.00234484672546', 'lastCheck': 1345024865.2535059, 'code': 0, 'valid': True}}
>Thread-2007::DEBUG::2012-08-15 12:01:07,691::task::588::TaskManager.Task::(_updateState) Task=`6d083097-39e8-4c98-ad78-39ce96a52bd8`::moving from state preparing -> state finished
>Thread-2007::DEBUG::2012-08-15 12:01:07,692::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-2007::DEBUG::2012-08-15 12:01:07,692::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-2007::DEBUG::2012-08-15 12:01:07,692::task::978::TaskManager.Task::(_decref) Task=`6d083097-39e8-4c98-ad78-39ce96a52bd8`::ref 0 aborting False
>Thread-2012::DEBUG::2012-08-15 12:01:15,131::BindingXMLRPC::164::vds::(wrapper) [10.34.63.8]
>Thread-2012::DEBUG::2012-08-15 12:01:15,132::task::588::TaskManager.Task::(_updateState) Task=`4e36d63d-734d-474a-a39f-97acc9d96a63`::moving from state init -> state preparing
>Thread-2012::INFO::2012-08-15 12:01:15,132::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='ae32878d-2639-47d7-b751-0ced2b0cd4d2', options=None)
>Thread-2012::INFO::2012-08-15 12:01:15,132::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': -1, 'spmStatus': 'Free', 'spmLver': 0}}
>Thread-2012::DEBUG::2012-08-15 12:01:15,133::task::1172::TaskManager.Task::(prepare) Task=`4e36d63d-734d-474a-a39f-97acc9d96a63`::finished: {'spm_st': {'spmId': -1, 'spmStatus': 'Free', 'spmLver': 0}}
>Thread-2012::DEBUG::2012-08-15 12:01:15,133::task::588::TaskManager.Task::(_updateState) Task=`4e36d63d-734d-474a-a39f-97acc9d96a63`::moving from state preparing -> state finished
>Thread-2012::DEBUG::2012-08-15 12:01:15,133::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-2012::DEBUG::2012-08-15 12:01:15,133::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-2012::DEBUG::2012-08-15 12:01:15,134::task::978::TaskManager.Task::(_decref) Task=`4e36d63d-734d-474a-a39f-97acc9d96a63`::ref 0 aborting False
>Thread-2014::DEBUG::2012-08-15 12:01:17,749::task::588::TaskManager.Task::(_updateState) Task=`311a8146-4689-4207-8a7e-b0b4d646a0e4`::moving from state init -> state preparing
>Thread-2014::INFO::2012-08-15 12:01:17,750::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-2014::INFO::2012-08-15 12:01:17,750::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'ab9c2853-40c8-486d-a907-c35fe1b57594': {'delay': '0.00204801559448', 'lastCheck': 1345024875.2607529, 'code': 0, 'valid': True}}
>Thread-2014::DEBUG::2012-08-15 12:01:17,751::task::1172::TaskManager.Task::(prepare) Task=`311a8146-4689-4207-8a7e-b0b4d646a0e4`::finished: {'ab9c2853-40c8-486d-a907-c35fe1b57594': {'delay': '0.00204801559448', 'lastCheck': 1345024875.2607529, 'code': 0, 'valid': True}}
>Thread-2014::DEBUG::2012-08-15 12:01:17,751::task::588::TaskManager.Task::(_updateState) Task=`311a8146-4689-4207-8a7e-b0b4d646a0e4`::moving from state preparing -> state finished
>Thread-2014::DEBUG::2012-08-15 12:01:17,751::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-2014::DEBUG::2012-08-15 12:01:17,751::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-2014::DEBUG::2012-08-15 12:01:17,752::task::978::TaskManager.Task::(_decref) Task=`311a8146-4689-4207-8a7e-b0b4d646a0e4`::ref 0 aborting False
>Thread-2019::DEBUG::2012-08-15 12:01:25,168::BindingXMLRPC::164::vds::(wrapper) [10.34.63.8]
>Thread-2019::DEBUG::2012-08-15 12:01:25,169::task::588::TaskManager.Task::(_updateState) Task=`2b27b388-d4c1-41cc-9a91-6714b9279cd5`::moving from state init -> state preparing
>Thread-2019::INFO::2012-08-15 12:01:25,169::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='ae32878d-2639-47d7-b751-0ced2b0cd4d2', options=None)
>Thread-2019::INFO::2012-08-15 12:01:25,170::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': -1, 'spmStatus': 'Free', 'spmLver': 0}}
>Thread-2019::DEBUG::2012-08-15 12:01:25,170::task::1172::TaskManager.Task::(prepare) Task=`2b27b388-d4c1-41cc-9a91-6714b9279cd5`::finished: {'spm_st': {'spmId': -1, 'spmStatus': 'Free', 'spmLver': 0}}
>Thread-2019::DEBUG::2012-08-15 12:01:25,170::task::588::TaskManager.Task::(_updateState) Task=`2b27b388-d4c1-41cc-9a91-6714b9279cd5`::moving from state preparing -> state finished
>Thread-2019::DEBUG::2012-08-15 12:01:25,170::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-2019::DEBUG::2012-08-15 12:01:25,171::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-2019::DEBUG::2012-08-15 12:01:25,171::task::978::TaskManager.Task::(_decref) Task=`2b27b388-d4c1-41cc-9a91-6714b9279cd5`::ref 0 aborting False
>Thread-2021::DEBUG::2012-08-15 12:01:27,810::task::588::TaskManager.Task::(_updateState) Task=`7fd8a52f-7f89-48d1-bea4-064437771da5`::moving from state init -> state preparing
>Thread-2021::INFO::2012-08-15 12:01:27,810::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-2021::INFO::2012-08-15 12:01:27,810::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'ab9c2853-40c8-486d-a907-c35fe1b57594': {'delay': '0.00184488296509', 'lastCheck': 1345024885.2677829, 'code': 0, 'valid': True}}
>Thread-2021::DEBUG::2012-08-15 12:01:27,811::task::1172::TaskManager.Task::(prepare) Task=`7fd8a52f-7f89-48d1-bea4-064437771da5`::finished: {'ab9c2853-40c8-486d-a907-c35fe1b57594': {'delay': '0.00184488296509', 'lastCheck': 1345024885.2677829, 'code': 0, 'valid': True}}
>Thread-2021::DEBUG::2012-08-15 12:01:27,811::task::588::TaskManager.Task::(_updateState) Task=`7fd8a52f-7f89-48d1-bea4-064437771da5`::moving from state preparing -> state finished
>Thread-2021::DEBUG::2012-08-15 12:01:27,811::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-2021::DEBUG::2012-08-15 12:01:27,811::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-2021::DEBUG::2012-08-15 12:01:27,812::task::978::TaskManager.Task::(_decref) Task=`7fd8a52f-7f89-48d1-bea4-064437771da5`::ref 0 aborting False
>Thread-2026::DEBUG::2012-08-15 12:01:35,205::BindingXMLRPC::164::vds::(wrapper) [10.34.63.8]
>Thread-2026::DEBUG::2012-08-15 12:01:35,206::task::588::TaskManager.Task::(_updateState) Task=`1ea8f4ba-5983-47a8-b70f-a853997cefcd`::moving from state init -> state preparing
>Thread-2026::INFO::2012-08-15 12:01:35,206::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='ae32878d-2639-47d7-b751-0ced2b0cd4d2', options=None)
>Thread-2026::INFO::2012-08-15 12:01:35,206::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': -1, 'spmStatus': 'Free', 'spmLver': 0}}
>Thread-2026::DEBUG::2012-08-15 12:01:35,207::task::1172::TaskManager.Task::(prepare) Task=`1ea8f4ba-5983-47a8-b70f-a853997cefcd`::finished: {'spm_st': {'spmId': -1, 'spmStatus': 'Free', 'spmLver': 0}}
>Thread-2026::DEBUG::2012-08-15 12:01:35,207::task::588::TaskManager.Task::(_updateState) Task=`1ea8f4ba-5983-47a8-b70f-a853997cefcd`::moving from state preparing -> state finished
>Thread-2026::DEBUG::2012-08-15 12:01:35,207::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-2026::DEBUG::2012-08-15 12:01:35,207::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-2026::DEBUG::2012-08-15 12:01:35,208::task::978::TaskManager.Task::(_decref) Task=`1ea8f4ba-5983-47a8-b70f-a853997cefcd`::ref 0 aborting False
>Thread-2028::DEBUG::2012-08-15 12:01:37,869::task::588::TaskManager.Task::(_updateState) Task=`1466950f-cc1e-48ca-b98f-2879348c1fb3`::moving from state init -> state preparing
>Thread-2028::INFO::2012-08-15 12:01:37,869::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-2028::INFO::2012-08-15 12:01:37,870::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'ab9c2853-40c8-486d-a907-c35fe1b57594': {'delay': '0.00199794769287', 'lastCheck': 1345024895.2750111, 'code': 0, 'valid': True}}
>Thread-2028::DEBUG::2012-08-15 12:01:37,870::task::1172::TaskManager.Task::(prepare) Task=`1466950f-cc1e-48ca-b98f-2879348c1fb3`::finished: {'ab9c2853-40c8-486d-a907-c35fe1b57594': {'delay': '0.00199794769287', 'lastCheck': 1345024895.2750111, 'code': 0, 'valid': True}}
>Thread-2028::DEBUG::2012-08-15 12:01:37,870::task::588::TaskManager.Task::(_updateState) Task=`1466950f-cc1e-48ca-b98f-2879348c1fb3`::moving from state preparing -> state finished
>Thread-2028::DEBUG::2012-08-15 12:01:37,870::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-2028::DEBUG::2012-08-15 12:01:37,871::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-2028::DEBUG::2012-08-15 12:01:37,871::task::978::TaskManager.Task::(_decref) Task=`1466950f-cc1e-48ca-b98f-2879348c1fb3`::ref 0 aborting False
>Thread-2033::DEBUG::2012-08-15 12:01:45,240::BindingXMLRPC::164::vds::(wrapper) [10.34.63.8]
>Thread-2033::DEBUG::2012-08-15 12:01:45,241::task::588::TaskManager.Task::(_updateState) Task=`ef6d8b5e-7be1-457b-a6be-9cceed6c4cb0`::moving from state init -> state preparing
>Thread-2033::INFO::2012-08-15 12:01:45,241::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='ae32878d-2639-47d7-b751-0ced2b0cd4d2', options=None)
>Thread-2033::INFO::2012-08-15 12:01:45,242::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': -1, 'spmStatus': 'Free', 'spmLver': 0}}
>Thread-2033::DEBUG::2012-08-15 12:01:45,242::task::1172::TaskManager.Task::(prepare) Task=`ef6d8b5e-7be1-457b-a6be-9cceed6c4cb0`::finished: {'spm_st': {'spmId': -1, 'spmStatus': 'Free', 'spmLver': 0}}
>Thread-2033::DEBUG::2012-08-15 12:01:45,242::task::588::TaskManager.Task::(_updateState) Task=`ef6d8b5e-7be1-457b-a6be-9cceed6c4cb0`::moving from state preparing -> state finished
>Thread-2033::DEBUG::2012-08-15 12:01:45,243::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-2033::DEBUG::2012-08-15 12:01:45,243::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-2033::DEBUG::2012-08-15 12:01:45,243::task::978::TaskManager.Task::(_decref) Task=`ef6d8b5e-7be1-457b-a6be-9cceed6c4cb0`::ref 0 aborting False
>Thread-2035::DEBUG::2012-08-15 12:01:47,926::task::588::TaskManager.Task::(_updateState) Task=`f0953cdc-79cc-4231-bab8-d72a09049ee4`::moving from state init -> state preparing
>Thread-2035::INFO::2012-08-15 12:01:47,926::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-2035::INFO::2012-08-15 12:01:47,927::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'ab9c2853-40c8-486d-a907-c35fe1b57594': {'delay': '0.00187993049622', 'lastCheck': 1345024905.282073, 'code': 0, 'valid': True}}
>Thread-2035::DEBUG::2012-08-15 12:01:47,927::task::1172::TaskManager.Task::(prepare) Task=`f0953cdc-79cc-4231-bab8-d72a09049ee4`::finished: {'ab9c2853-40c8-486d-a907-c35fe1b57594': {'delay': '0.00187993049622', 'lastCheck': 1345024905.282073, 'code': 0, 'valid': True}}
>Thread-2035::DEBUG::2012-08-15 12:01:47,927::task::588::TaskManager.Task::(_updateState) Task=`f0953cdc-79cc-4231-bab8-d72a09049ee4`::moving from state preparing -> state finished
>Thread-2035::DEBUG::2012-08-15 12:01:47,927::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-2035::DEBUG::2012-08-15 12:01:47,928::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-2035::DEBUG::2012-08-15 12:01:47,928::task::978::TaskManager.Task::(_decref) Task=`f0953cdc-79cc-4231-bab8-d72a09049ee4`::ref 0 aborting False
>Thread-2040::DEBUG::2012-08-15 12:01:55,279::BindingXMLRPC::164::vds::(wrapper) [10.34.63.8]
>Thread-2040::DEBUG::2012-08-15 12:01:55,279::task::588::TaskManager.Task::(_updateState) Task=`ded2f5fb-b438-4e9d-bded-3c14b2621a2d`::moving from state init -> state preparing
>Thread-2040::INFO::2012-08-15 12:01:55,280::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='ae32878d-2639-47d7-b751-0ced2b0cd4d2', options=None)
>Thread-2040::INFO::2012-08-15 12:01:55,280::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': -1, 'spmStatus': 'Free', 'spmLver': 0}}
>Thread-2040::DEBUG::2012-08-15 12:01:55,280::task::1172::TaskManager.Task::(prepare) Task=`ded2f5fb-b438-4e9d-bded-3c14b2621a2d`::finished: {'spm_st': {'spmId': -1, 'spmStatus': 'Free', 'spmLver': 0}}
>Thread-2040::DEBUG::2012-08-15 12:01:55,281::task::588::TaskManager.Task::(_updateState) Task=`ded2f5fb-b438-4e9d-bded-3c14b2621a2d`::moving from state preparing -> state finished
>Thread-2040::DEBUG::2012-08-15 12:01:55,281::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-2040::DEBUG::2012-08-15 12:01:55,281::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-2040::DEBUG::2012-08-15 12:01:55,282::task::978::TaskManager.Task::(_decref) Task=`ded2f5fb-b438-4e9d-bded-3c14b2621a2d`::ref 0 aborting False
>Thread-2042::DEBUG::2012-08-15 12:01:57,985::task::588::TaskManager.Task::(_updateState) Task=`1d6bad4a-9ebf-4bd4-af4a-6e37e76e4763`::moving from state init -> state preparing
>Thread-2042::INFO::2012-08-15 12:01:57,985::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-2042::INFO::2012-08-15 12:01:57,985::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'ab9c2853-40c8-486d-a907-c35fe1b57594': {'delay': '0.00180792808533', 'lastCheck': 1345024915.289875, 'code': 0, 'valid': True}}
>Thread-2042::DEBUG::2012-08-15 12:01:57,986::task::1172::TaskManager.Task::(prepare) Task=`1d6bad4a-9ebf-4bd4-af4a-6e37e76e4763`::finished: {'ab9c2853-40c8-486d-a907-c35fe1b57594': {'delay': '0.00180792808533', 'lastCheck': 1345024915.289875, 'code': 0, 'valid': True}}
>Thread-2042::DEBUG::2012-08-15 12:01:57,986::task::588::TaskManager.Task::(_updateState) Task=`1d6bad4a-9ebf-4bd4-af4a-6e37e76e4763`::moving from state preparing -> state finished
>Thread-2042::DEBUG::2012-08-15 12:01:57,986::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-2042::DEBUG::2012-08-15 12:01:57,987::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-2042::DEBUG::2012-08-15 12:01:57,987::task::978::TaskManager.Task::(_decref) Task=`1d6bad4a-9ebf-4bd4-af4a-6e37e76e4763`::ref 0 aborting False
>Thread-2047::DEBUG::2012-08-15 12:02:05,322::BindingXMLRPC::164::vds::(wrapper) [10.34.63.8]
>Thread-2047::DEBUG::2012-08-15 12:02:05,341::task::588::TaskManager.Task::(_updateState) Task=`fefa44e2-7bfd-4148-a827-5c995b96fb5e`::moving from state init -> state preparing
>Thread-2047::INFO::2012-08-15 12:02:05,342::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='ae32878d-2639-47d7-b751-0ced2b0cd4d2', options=None)
>Thread-2047::INFO::2012-08-15 12:02:05,342::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': -1, 'spmStatus': 'Free', 'spmLver': 0}}
>Thread-2047::DEBUG::2012-08-15 12:02:05,342::task::1172::TaskManager.Task::(prepare) Task=`fefa44e2-7bfd-4148-a827-5c995b96fb5e`::finished: {'spm_st': {'spmId': -1, 'spmStatus': 'Free', 'spmLver': 0}}
>Thread-2047::DEBUG::2012-08-15 12:02:05,343::task::588::TaskManager.Task::(_updateState) Task=`fefa44e2-7bfd-4148-a827-5c995b96fb5e`::moving from state preparing -> state finished
>Thread-2047::DEBUG::2012-08-15 12:02:05,343::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-2047::DEBUG::2012-08-15 12:02:05,343::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-2047::DEBUG::2012-08-15 12:02:05,343::task::978::TaskManager.Task::(_decref) Task=`fefa44e2-7bfd-4148-a827-5c995b96fb5e`::ref 0 aborting False
>Thread-2049::DEBUG::2012-08-15 12:02:08,074::task::588::TaskManager.Task::(_updateState) Task=`432a6fd0-2ab6-436f-adad-a1d4a4b544b3`::moving from state init -> state preparing
>Thread-2049::INFO::2012-08-15 12:02:08,093::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-2049::INFO::2012-08-15 12:02:08,093::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'ab9c2853-40c8-486d-a907-c35fe1b57594': {'delay': '0.00254917144775', 'lastCheck': 1345024925.3144901, 'code': 0, 'valid': True}}
>Thread-2049::DEBUG::2012-08-15 12:02:08,094::task::1172::TaskManager.Task::(prepare) Task=`432a6fd0-2ab6-436f-adad-a1d4a4b544b3`::finished: {'ab9c2853-40c8-486d-a907-c35fe1b57594': {'delay': '0.00254917144775', 'lastCheck': 1345024925.3144901, 'code': 0, 'valid': True}}
>Thread-2049::DEBUG::2012-08-15 12:02:08,094::task::588::TaskManager.Task::(_updateState) Task=`432a6fd0-2ab6-436f-adad-a1d4a4b544b3`::moving from state preparing -> state finished
>Thread-2049::DEBUG::2012-08-15 12:02:08,094::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-2049::DEBUG::2012-08-15 12:02:08,095::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-2049::DEBUG::2012-08-15 12:02:08,095::task::978::TaskManager.Task::(_decref) Task=`432a6fd0-2ab6-436f-adad-a1d4a4b544b3`::ref 0 aborting False
>Thread-2054::DEBUG::2012-08-15 12:02:15,378::BindingXMLRPC::164::vds::(wrapper) [10.34.63.8]
>Thread-2054::DEBUG::2012-08-15 12:02:15,392::task::588::TaskManager.Task::(_updateState) Task=`ad59e0a0-ed50-4fc2-8247-fa83a3fc8be4`::moving from state init -> state preparing
>Thread-2054::INFO::2012-08-15 12:02:15,392::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='ae32878d-2639-47d7-b751-0ced2b0cd4d2', options=None)
>Thread-2054::INFO::2012-08-15 12:02:15,392::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': -1, 'spmStatus': 'Free', 'spmLver': 0}}
>Thread-2054::DEBUG::2012-08-15 12:02:15,393::task::1172::TaskManager.Task::(prepare) Task=`ad59e0a0-ed50-4fc2-8247-fa83a3fc8be4`::finished: {'spm_st': {'spmId': -1, 'spmStatus': 'Free', 'spmLver': 0}}
>Thread-2054::DEBUG::2012-08-15 12:02:15,393::task::588::TaskManager.Task::(_updateState) Task=`ad59e0a0-ed50-4fc2-8247-fa83a3fc8be4`::moving from state preparing -> state finished
>Thread-2054::DEBUG::2012-08-15 12:02:15,393::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-2054::DEBUG::2012-08-15 12:02:15,393::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-2054::DEBUG::2012-08-15 12:02:15,394::task::978::TaskManager.Task::(_decref) Task=`ad59e0a0-ed50-4fc2-8247-fa83a3fc8be4`::ref 0 aborting False
>Thread-2056::DEBUG::2012-08-15 12:02:18,171::task::588::TaskManager.Task::(_updateState) Task=`985f4156-ae14-41a5-b8cb-158d1241acb4`::moving from state init -> state preparing
>Thread-2056::INFO::2012-08-15 12:02:18,172::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-2056::INFO::2012-08-15 12:02:18,172::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'ab9c2853-40c8-486d-a907-c35fe1b57594': {'delay': '0.00332403182983', 'lastCheck': 1345024935.3272769, 'code': 0, 'valid': True}}
>Thread-2056::DEBUG::2012-08-15 12:02:18,172::task::1172::TaskManager.Task::(prepare) Task=`985f4156-ae14-41a5-b8cb-158d1241acb4`::finished: {'ab9c2853-40c8-486d-a907-c35fe1b57594': {'delay': '0.00332403182983', 'lastCheck': 1345024935.3272769, 'code': 0, 'valid': True}}
>Thread-2056::DEBUG::2012-08-15 12:02:18,172::task::588::TaskManager.Task::(_updateState) Task=`985f4156-ae14-41a5-b8cb-158d1241acb4`::moving from state preparing -> state finished
>Thread-2056::DEBUG::2012-08-15 12:02:18,173::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-2056::DEBUG::2012-08-15 12:02:18,173::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-2056::DEBUG::2012-08-15 12:02:18,173::task::978::TaskManager.Task::(_decref) Task=`985f4156-ae14-41a5-b8cb-158d1241acb4`::ref 0 aborting False
>Thread-2061::DEBUG::2012-08-15 12:02:25,427::BindingXMLRPC::164::vds::(wrapper) [10.34.63.8]
>Thread-2061::DEBUG::2012-08-15 12:02:25,427::task::588::TaskManager.Task::(_updateState) Task=`9eca8fda-0edb-4177-b8b2-5316a9d0e2d5`::moving from state init -> state preparing
>Thread-2061::INFO::2012-08-15 12:02:25,428::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='ae32878d-2639-47d7-b751-0ced2b0cd4d2', options=None)
>Thread-2061::INFO::2012-08-15 12:02:25,428::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': -1, 'spmStatus': 'Free', 'spmLver': 0}}
>Thread-2061::DEBUG::2012-08-15 12:02:25,428::task::1172::TaskManager.Task::(prepare) Task=`9eca8fda-0edb-4177-b8b2-5316a9d0e2d5`::finished: {'spm_st': {'spmId': -1, 'spmStatus': 'Free', 'spmLver': 0}}
>Thread-2061::DEBUG::2012-08-15 12:02:25,429::task::588::TaskManager.Task::(_updateState) Task=`9eca8fda-0edb-4177-b8b2-5316a9d0e2d5`::moving from state preparing -> state finished
>Thread-2061::DEBUG::2012-08-15 12:02:25,429::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-2061::DEBUG::2012-08-15 12:02:25,429::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-2061::DEBUG::2012-08-15 12:02:25,429::task::978::TaskManager.Task::(_decref) Task=`9eca8fda-0edb-4177-b8b2-5316a9d0e2d5`::ref 0 aborting False
>Thread-2063::DEBUG::2012-08-15 12:02:28,249::task::588::TaskManager.Task::(_updateState) Task=`51ed5055-3f86-4730-8901-fdee1efc9d38`::moving from state init -> state preparing
>Thread-2063::INFO::2012-08-15 12:02:28,250::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-2063::INFO::2012-08-15 12:02:28,250::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'ab9c2853-40c8-486d-a907-c35fe1b57594': {'delay': '0.00188493728638', 'lastCheck': 1345024945.334341, 'code': 0, 'valid': True}}
>Thread-2063::DEBUG::2012-08-15 12:02:28,251::task::1172::TaskManager.Task::(prepare) Task=`51ed5055-3f86-4730-8901-fdee1efc9d38`::finished: {'ab9c2853-40c8-486d-a907-c35fe1b57594': {'delay': '0.00188493728638', 'lastCheck': 1345024945.334341, 'code': 0, 'valid': True}}
>Thread-2063::DEBUG::2012-08-15 12:02:28,251::task::588::TaskManager.Task::(_updateState) Task=`51ed5055-3f86-4730-8901-fdee1efc9d38`::moving from state preparing -> state finished
>Thread-2063::DEBUG::2012-08-15 12:02:28,252::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-2063::DEBUG::2012-08-15 12:02:28,252::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-2063::DEBUG::2012-08-15 12:02:28,252::task::978::TaskManager.Task::(_decref) Task=`51ed5055-3f86-4730-8901-fdee1efc9d38`::ref 0 aborting False
>Thread-2068::DEBUG::2012-08-15 12:02:35,464::BindingXMLRPC::164::vds::(wrapper) [10.34.63.8]
>Thread-2068::DEBUG::2012-08-15 12:02:35,465::task::588::TaskManager.Task::(_updateState) Task=`2c1b6619-73ac-48f0-a688-963cc9c699da`::moving from state init -> state preparing
>Thread-2068::INFO::2012-08-15 12:02:35,465::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='ae32878d-2639-47d7-b751-0ced2b0cd4d2', options=None)
>Thread-2068::INFO::2012-08-15 12:02:35,465::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': -1, 'spmStatus': 'Free', 'spmLver': 0}}
>Thread-2068::DEBUG::2012-08-15 12:02:35,466::task::1172::TaskManager.Task::(prepare) Task=`2c1b6619-73ac-48f0-a688-963cc9c699da`::finished: {'spm_st': {'spmId': -1, 'spmStatus': 'Free', 'spmLver': 0}}
>Thread-2068::DEBUG::2012-08-15 12:02:35,466::task::588::TaskManager.Task::(_updateState) Task=`2c1b6619-73ac-48f0-a688-963cc9c699da`::moving from state preparing -> state finished
>Thread-2068::DEBUG::2012-08-15 12:02:35,466::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-2068::DEBUG::2012-08-15 12:02:35,466::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-2068::DEBUG::2012-08-15 12:02:35,467::task::978::TaskManager.Task::(_decref) Task=`2c1b6619-73ac-48f0-a688-963cc9c699da`::ref 0 aborting False
>Thread-2070::DEBUG::2012-08-15 12:02:38,310::task::588::TaskManager.Task::(_updateState) Task=`248dd3f0-cc2c-472b-9ed4-9b8756cb59b6`::moving from state init -> state preparing
>Thread-2070::INFO::2012-08-15 12:02:38,311::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-2070::INFO::2012-08-15 12:02:38,311::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'ab9c2853-40c8-486d-a907-c35fe1b57594': {'delay': '0.0021390914917', 'lastCheck': 1345024955.342201, 'code': 0, 'valid': True}}
>Thread-2070::DEBUG::2012-08-15 12:02:38,311::task::1172::TaskManager.Task::(prepare) Task=`248dd3f0-cc2c-472b-9ed4-9b8756cb59b6`::finished: {'ab9c2853-40c8-486d-a907-c35fe1b57594': {'delay': '0.0021390914917', 'lastCheck': 1345024955.342201, 'code': 0, 'valid': True}}
>Thread-2070::DEBUG::2012-08-15 12:02:38,312::task::588::TaskManager.Task::(_updateState) Task=`248dd3f0-cc2c-472b-9ed4-9b8756cb59b6`::moving from state preparing -> state finished
>Thread-2070::DEBUG::2012-08-15 12:02:38,312::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-2070::DEBUG::2012-08-15 12:02:38,312::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-2070::DEBUG::2012-08-15 12:02:38,312::task::978::TaskManager.Task::(_decref) Task=`248dd3f0-cc2c-472b-9ed4-9b8756cb59b6`::ref 0 aborting False

Actions: View

Attachments on bug 848401: 604607