Login
[x]
Log in using an account from:
Fedora Account System
Red Hat Associate
Red Hat Customer
Or login using a Red Hat Bugzilla account
Forgot Password
Login:
Hide Forgot
Create an Account
Red Hat Bugzilla – Attachment 604607 Details for
Bug 848401
[backend] Editing data center with the only master storage causes that it cannot be removed afterwards
[?]
New
Simple Search
Advanced Search
My Links
Browse
Requests
Reports
Current State
Search
Tabular reports
Graphical reports
Duplicates
Other Reports
User Changes
Plotly Reports
Bug Status
Bug Severity
Non-Defaults
|
Product Dashboard
Help
Page Help!
Bug Writing Guidelines
What's new
Browser Support Policy
5.0.4.rh83 Release notes
FAQ
Guides index
User guide
Web Services
Contact
Legal
This site requires JavaScript to be enabled to function correctly, please enable it.
VDSM log
vdsm.log (text/x-log), 88.78 KB, created by
Pavel Novotny
on 2012-08-15 13:38:00 UTC
(
hide
)
Description:
VDSM log
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
You cannot view the attachment while viewing its details because your browser does not support IFRAMEs.
View the attachment on a separate page
.
View Attachment As Raw
Actions:
View
Attachments on
bug 848401
: 604607