Attachment 572709 Details for Bug 806774 – vdsm.log

vdsm.log

vdsm.logab (text/plain), 150.03 KB, created by Royce Lv on 2012-03-26 09:00:39 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: Royce Lv

Created: 2012-03-26 09:00:39 UTC

Size: 150.03 KB

patch

obsolete

>CP Server Thread-22::DEBUG::2012-03-26 15:42:31,651::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4504' is free, finding out if anyone is waiting for it.
>CP Server Thread-22::DEBUG::2012-03-26 15:42:31,651::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4504', Clearing records.
>CP Server Thread-22::DEBUG::2012-03-26 15:42:31,651::task::980::TaskManager.Task::(_decref) Task=`48de2b26-f8c0-4297-81ee-fbe1259029c9`::ref 0 aborting False
>CP Server Thread-22::INFO::2012-03-26 15:42:31,652::_cplogging::262::cherrypy.access.23486224::(access) 127.0.0.1 - - [26/Mar/2012:15:42:31] "POST /vdsm-api/storagepools/create HTTP/1.1" 204 - "" "Python-urllib/2.7"
>CP Server Thread-23::ERROR::2012-03-26 15:42:31,656::_cplogging::183::cherrypy.error.23486224::(error) [26/Mar/2012:15:42:31] HTTP Traceback (most recent call last):
>  File "/usr/lib/python2.7/site-packages/cherrypy/_cprequest.py", line 656, in respond
>    response.body = self.handler()
>  File "/usr/lib/python2.7/site-packages/cherrypy/lib/encoding.py", line 188, in __call__
>    self.body = self.oldhandler(*args, **kwargs)
>  File "/usr/lib/python2.7/site-packages/cherrypy/_cpdispatch.py", line 34, in __call__
>    return self.callable(*self.args, **self.kwargs)
>  File "/usr/share/vdsm/rest/Controller.py", line 889, in connect
>    master_uuid = params['master_uuid']
>KeyError: 'master_uuid'
>
>CP Server Thread-23::INFO::2012-03-26 15:42:31,657::_cplogging::183::cherrypy.error.23486224::(error) [26/Mar/2012:15:42:31] HTTP 
>Request Headers:
>  Content-Length: 66
>  HOST: localhost:8080
>  CONNECTION: close
>  Remote-Addr: 127.0.0.1
>  ACCEPT: application/json
>  USER-AGENT: Python-urllib/2.7
>  Content-Type: application/json
>  ACCEPT-ENCODING: identity
>CP Server Thread-23::INFO::2012-03-26 15:42:31,657::_cplogging::262::cherrypy.access.23486224::(access) 127.0.0.1 - - [26/Mar/2012:15:42:31] "POST /vdsm-api/storagepools/connect HTTP/1.1" 500 1371 "" "Python-urllib/2.7"
>CP Server Thread-24::DEBUG::2012-03-26 15:45:30,459::task::588::TaskManager.Task::(_updateState) Task=`c69707c4-8539-4a78-a9d5-4cc8063a3017`::moving from state init -> state preparing
>CP Server Thread-24::INFO::2012-03-26 15:45:30,459::logUtils::37::dispatcher::(wrapper) Run and protect: connectStorageServer(domType=4, spUUID=None, conList=[{'connection': u'/var/lib/vdsm/bugstoragsomedomain4', 'id': 1}], options=None)
>CP Server Thread-24::INFO::2012-03-26 15:45:30,460::storage_connection::147::Storage.ServerConnection::(connect) Request to connect LOCALFS storage server
>CP Server Thread-24::DEBUG::2012-03-26 15:45:30,460::lvm::460::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
>CP Server Thread-24::DEBUG::2012-03-26 15:45:30,461::lvm::462::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
>CP Server Thread-24::DEBUG::2012-03-26 15:45:30,461::lvm::472::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
>CP Server Thread-24::DEBUG::2012-03-26 15:45:30,461::lvm::474::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
>CP Server Thread-24::DEBUG::2012-03-26 15:45:30,461::lvm::493::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
>CP Server Thread-24::DEBUG::2012-03-26 15:45:30,462::lvm::495::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
>CP Server Thread-24::INFO::2012-03-26 15:45:30,462::logUtils::39::dispatcher::(wrapper) Run and protect: connectStorageServer, Return response: {'statuslist': [{'status': 0, 'id': 1}]}
>CP Server Thread-24::DEBUG::2012-03-26 15:45:30,462::task::1174::TaskManager.Task::(prepare) Task=`c69707c4-8539-4a78-a9d5-4cc8063a3017`::finished: {'statuslist': [{'status': 0, 'id': 1}]}
>CP Server Thread-24::DEBUG::2012-03-26 15:45:30,462::task::588::TaskManager.Task::(_updateState) Task=`c69707c4-8539-4a78-a9d5-4cc8063a3017`::moving from state preparing -> state finished
>CP Server Thread-24::DEBUG::2012-03-26 15:45:30,462::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>CP Server Thread-24::DEBUG::2012-03-26 15:45:30,463::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>CP Server Thread-24::DEBUG::2012-03-26 15:45:30,463::task::980::TaskManager.Task::(_decref) Task=`c69707c4-8539-4a78-a9d5-4cc8063a3017`::ref 0 aborting False
>CP Server Thread-24::INFO::2012-03-26 15:45:30,463::_cplogging::262::cherrypy.access.23486224::(access) 127.0.0.1 - - [26/Mar/2012:15:45:30] "POST /vdsm-api/storageconnections/manage HTTP/1.1" 303 146 "" "Python-urllib/2.7"
>CP Server Thread-25::INFO::2012-03-26 15:45:30,467::_cplogging::262::cherrypy.access.23486224::(access) 127.0.0.1 - - [26/Mar/2012:15:45:30] "GET /vdsm-api/storageconnections/ HTTP/1.1" 200 36 "" "Python-urllib/2.7"
>CP Server Thread-16::DEBUG::2012-03-26 15:45:30,469::task::588::TaskManager.Task::(_updateState) Task=`f9a71b5a-f879-4e27-b67a-5d037e3b1407`::moving from state init -> state preparing
>CP Server Thread-16::INFO::2012-03-26 15:45:30,470::logUtils::37::dispatcher::(wrapper) Run and protect: createStorageDomain(storageType=4, sdUUID='1be32ac7-1e12-4823-8e8c-8c887333fe37', domainName='Test Domain', typeSpecificArg='/var/lib/vdsm/bugstoragsomedomain4', domClass=1, domVersion=0, options=None)
>CP Server Thread-16::DEBUG::2012-03-26 15:45:30,470::misc::1017::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
>CP Server Thread-16::DEBUG::2012-03-26 15:45:30,470::misc::1019::SamplingMethod::(__call__) Got in to sampling method
>CP Server Thread-16::DEBUG::2012-03-26 15:45:30,471::misc::1017::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
>CP Server Thread-16::DEBUG::2012-03-26 15:45:30,471::misc::1019::SamplingMethod::(__call__) Got in to sampling method
>CP Server Thread-16::DEBUG::2012-03-26 15:45:30,471::iscsi::389::Storage.Misc.excCmd::(rescan) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
>CP Server Thread-16::DEBUG::2012-03-26 15:45:30,489::iscsi::389::Storage.Misc.excCmd::(rescan) FAILED: <err> = 'iscsiadm: No session found.\n'; <rc> = 21
>CP Server Thread-16::DEBUG::2012-03-26 15:45:30,490::misc::1027::SamplingMethod::(__call__) Returning last result
>CP Server Thread-16::DEBUG::2012-03-26 15:45:31,860::multipath::71::Storage.Misc.excCmd::(rescan) '/usr/bin/sudo -n /sbin/multipath' (cwd None)
>CP Server Thread-16::DEBUG::2012-03-26 15:45:31,896::multipath::71::Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0
>CP Server Thread-16::DEBUG::2012-03-26 15:45:31,897::lvm::460::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
>CP Server Thread-16::DEBUG::2012-03-26 15:45:31,897::lvm::462::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
>CP Server Thread-16::DEBUG::2012-03-26 15:45:31,897::lvm::472::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
>CP Server Thread-16::DEBUG::2012-03-26 15:45:31,897::lvm::474::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
>CP Server Thread-16::DEBUG::2012-03-26 15:45:31,898::lvm::493::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
>CP Server Thread-16::DEBUG::2012-03-26 15:45:31,898::lvm::495::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
>CP Server Thread-16::DEBUG::2012-03-26 15:45:31,898::misc::1027::SamplingMethod::(__call__) Returning last result
>CP Server Thread-16::DEBUG::2012-03-26 15:45:31,898::lvm::352::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
>CP Server Thread-16::DEBUG::2012-03-26 15:45:31,899::lvm::287::Storage.Misc.excCmd::(cmd) '/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 = [ \\"a%35000c500382d9c53%\\", \\"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 1be32ac7-1e12-4823-8e8c-8c887333fe37' (cwd None)
>CP Server Thread-16::DEBUG::2012-03-26 15:45:32,231::lvm::287::Storage.Misc.excCmd::(cmd) FAILED: <err> = '  Volume group "1be32ac7-1e12-4823-8e8c-8c887333fe37" not found\n'; <rc> = 5
>CP Server Thread-16::WARNING::2012-03-26 15:45:32,232::lvm::356::Storage.LVM::(_reloadvgs) lvm vgs failed: 5 [] ['  Volume group "1be32ac7-1e12-4823-8e8c-8c887333fe37" not found']
>CP Server Thread-16::DEBUG::2012-03-26 15:45:32,233::lvm::379::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
>CP Server Thread-16::INFO::2012-03-26 15:45:32,237::localFsSD::58::Storage.StorageDomain::(create) sdUUID=1be32ac7-1e12-4823-8e8c-8c887333fe37 domainName=Test Domain remotePath=/var/lib/vdsm/bugstoragsomedomain4 domClass=1
>CP Server Thread-16::DEBUG::2012-03-26 15:45:32,242::persistentDict::175::Storage.PersistentDict::(__init__) Created a persistant dict with FileMetadataRW backend
>CP Server Thread-16::DEBUG::2012-03-26 15:45:32,243::persistentDict::216::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=[]
>CP Server Thread-16::WARNING::2012-03-26 15:45:32,243::persistentDict::238::Storage.PersistentDict::(refresh) data has no embedded checksum - trust it as it is
>CP Server Thread-16::DEBUG::2012-03-26 15:45:32,244::persistentDict::152::Storage.PersistentDict::(transaction) Starting transaction
>CP Server Thread-16::DEBUG::2012-03-26 15:45:32,244::persistentDict::158::Storage.PersistentDict::(transaction) Flushing changes
>CP Server Thread-16::DEBUG::2012-03-26 15:45:32,244::persistentDict::277::Storage.PersistentDict::(flush) about to write lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=Test Domain', 'IOOPTIMEOUTSEC=1', 'LEASERETRIES=3', 'LEASETIMESEC=5', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'POOL_UUID=', 'REMOTE_PATH=/var/lib/vdsm/bugstoragsomedomain4', 'ROLE=Regular', 'SDUUID=1be32ac7-1e12-4823-8e8c-8c887333fe37', 'TYPE=LOCALFS', 'VERSION=0', '_SHA_CKSUM=8b68aa921f50fa00ca9478b1ead85ff049fbac52']
>CP Server Thread-16::DEBUG::2012-03-26 15:45:32,245::persistentDict::160::Storage.PersistentDict::(transaction) Finished transaction
>CP Server Thread-16::DEBUG::2012-03-26 15:45:32,245::fileSD::91::Storage.StorageDomain::(__init__) Reading domain in path /rhev/data-center/mnt/_var_lib_vdsm_bugstoragsomedomain4/1be32ac7-1e12-4823-8e8c-8c887333fe37
>CP Server Thread-16::DEBUG::2012-03-26 15:45:32,246::persistentDict::175::Storage.PersistentDict::(__init__) Created a persistant dict with FileMetadataRW backend
>CP Server Thread-16::DEBUG::2012-03-26 15:45:32,248::persistentDict::216::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=Test Domain', 'IOOPTIMEOUTSEC=1', 'LEASERETRIES=3', 'LEASETIMESEC=5', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'POOL_UUID=', 'REMOTE_PATH=/var/lib/vdsm/bugstoragsomedomain4', 'ROLE=Regular', 'SDUUID=1be32ac7-1e12-4823-8e8c-8c887333fe37', 'TYPE=LOCALFS', 'VERSION=0', '_SHA_CKSUM=8b68aa921f50fa00ca9478b1ead85ff049fbac52']
>CP Server Thread-16::DEBUG::2012-03-26 15:45:32,248::fileSD::314::Storage.StorageDomain::(imageGarbageCollector) Removing remnants of deleted images []
>CP Server Thread-16::DEBUG::2012-03-26 15:45:32,249::resourceManager::379::ResourceManager::(registerNamespace) Registering namespace '1be32ac7-1e12-4823-8e8c-8c887333fe37_imageNS'
>CP Server Thread-16::DEBUG::2012-03-26 15:45:32,249::resourceManager::379::ResourceManager::(registerNamespace) Registering namespace '1be32ac7-1e12-4823-8e8c-8c887333fe37_volumeNS'
>CP Server Thread-16::DEBUG::2012-03-26 15:45:32,249::safelease::57::Storage.Misc.excCmd::(initLock) '/usr/libexec/vdsm/safelease release -f /rhev/data-center/mnt/_var_lib_vdsm_bugstoragsomedomain4/1be32ac7-1e12-4823-8e8c-8c887333fe37/dom_md/leases 0' (cwd /usr/libexec/vdsm)
>CP Server Thread-16::DEBUG::2012-03-26 15:45:32,258::safelease::57::Storage.Misc.excCmd::(initLock) SUCCESS: <err> = ''; <rc> = 0
>CP Server Thread-16::DEBUG::2012-03-26 15:45:32,258::sd::342::Storage.StorageDomain::(initSPMlease) lease initialized successfully
>CP Server Thread-16::INFO::2012-03-26 15:45:32,259::logUtils::39::dispatcher::(wrapper) Run and protect: createStorageDomain, Return response: None
>CP Server Thread-16::DEBUG::2012-03-26 15:45:32,259::task::1174::TaskManager.Task::(prepare) Task=`f9a71b5a-f879-4e27-b67a-5d037e3b1407`::finished: None
>CP Server Thread-16::DEBUG::2012-03-26 15:45:32,260::task::588::TaskManager.Task::(_updateState) Task=`f9a71b5a-f879-4e27-b67a-5d037e3b1407`::moving from state preparing -> state finished
>CP Server Thread-16::DEBUG::2012-03-26 15:45:32,260::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>CP Server Thread-16::DEBUG::2012-03-26 15:45:32,260::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>CP Server Thread-16::DEBUG::2012-03-26 15:45:32,261::task::980::TaskManager.Task::(_decref) Task=`f9a71b5a-f879-4e27-b67a-5d037e3b1407`::ref 0 aborting False
>CP Server Thread-16::INFO::2012-03-26 15:45:32,261::_cplogging::262::cherrypy.access.23486224::(access) 127.0.0.1 - - [26/Mar/2012:15:45:32] "POST /vdsm-api/storagedomains/create HTTP/1.1" 303 210 "" "Python-urllib/2.7"
>CP Server Thread-17::DEBUG::2012-03-26 15:45:32,265::task::588::TaskManager.Task::(_updateState) Task=`5e83e007-778a-47fd-8603-455a85df3d9b`::moving from state init -> state preparing
>CP Server Thread-17::INFO::2012-03-26 15:45:32,265::logUtils::37::dispatcher::(wrapper) Run and protect: getStorageDomainInfo(sdUUID='1be32ac7-1e12-4823-8e8c-8c887333fe37', options=None)
>CP Server Thread-17::DEBUG::2012-03-26 15:45:32,266::lvm::352::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
>CP Server Thread-17::DEBUG::2012-03-26 15:45:32,266::lvm::287::Storage.Misc.excCmd::(cmd) '/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 = [ \\"a%35000c500382d9c53%\\", \\"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 1be32ac7-1e12-4823-8e8c-8c887333fe37' (cwd None)
>CP Server Thread-17::DEBUG::2012-03-26 15:45:32,337::lvm::287::Storage.Misc.excCmd::(cmd) FAILED: <err> = '  Volume group "1be32ac7-1e12-4823-8e8c-8c887333fe37" not found\n'; <rc> = 5
>CP Server Thread-17::WARNING::2012-03-26 15:45:32,339::lvm::356::Storage.LVM::(_reloadvgs) lvm vgs failed: 5 [] ['  Volume group "1be32ac7-1e12-4823-8e8c-8c887333fe37" not found']
>CP Server Thread-17::DEBUG::2012-03-26 15:45:32,339::lvm::379::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
>CP Server Thread-17::DEBUG::2012-03-26 15:45:32,341::fileSD::91::Storage.StorageDomain::(__init__) Reading domain in path /rhev/data-center/mnt/_var_lib_vdsm_bugstoragsomedomain4/1be32ac7-1e12-4823-8e8c-8c887333fe37
>CP Server Thread-17::DEBUG::2012-03-26 15:45:32,342::persistentDict::175::Storage.PersistentDict::(__init__) Created a persistant dict with FileMetadataRW backend
>CP Server Thread-17::DEBUG::2012-03-26 15:45:32,344::persistentDict::216::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=Test Domain', 'IOOPTIMEOUTSEC=1', 'LEASERETRIES=3', 'LEASETIMESEC=5', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'POOL_UUID=', 'REMOTE_PATH=/var/lib/vdsm/bugstoragsomedomain4', 'ROLE=Regular', 'SDUUID=1be32ac7-1e12-4823-8e8c-8c887333fe37', 'TYPE=LOCALFS', 'VERSION=0', '_SHA_CKSUM=8b68aa921f50fa00ca9478b1ead85ff049fbac52']
>CP Server Thread-17::DEBUG::2012-03-26 15:45:32,345::fileSD::314::Storage.StorageDomain::(imageGarbageCollector) Removing remnants of deleted images []
>CP Server Thread-17::WARNING::2012-03-26 15:45:32,345::sd::293::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace 1be32ac7-1e12-4823-8e8c-8c887333fe37_imageNS already registered
>CP Server Thread-17::WARNING::2012-03-26 15:45:32,345::sd::299::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace 1be32ac7-1e12-4823-8e8c-8c887333fe37_volumeNS already registered
>CP Server Thread-17::INFO::2012-03-26 15:45:32,346::fileSD::193::Storage.StorageDomain::(validate) sdUUID=1be32ac7-1e12-4823-8e8c-8c887333fe37
>CP Server Thread-17::DEBUG::2012-03-26 15:45:32,347::persistentDict::216::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=Test Domain', 'IOOPTIMEOUTSEC=1', 'LEASERETRIES=3', 'LEASETIMESEC=5', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'POOL_UUID=', 'REMOTE_PATH=/var/lib/vdsm/bugstoragsomedomain4', 'ROLE=Regular', 'SDUUID=1be32ac7-1e12-4823-8e8c-8c887333fe37', 'TYPE=LOCALFS', 'VERSION=0', '_SHA_CKSUM=8b68aa921f50fa00ca9478b1ead85ff049fbac52']
>CP Server Thread-17::DEBUG::2012-03-26 15:45:32,347::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37`ReqID=`94e25cb0-c5c9-49f2-acaa-9e811234108d`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2036' at 'getStorageDomainInfo'
>CP Server Thread-17::DEBUG::2012-03-26 15:45:32,347::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37' for lock type 'shared'
>CP Server Thread-17::DEBUG::2012-03-26 15:45:32,348::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37' is free. Now locking as 'shared' (1 active user)
>CP Server Thread-17::DEBUG::2012-03-26 15:45:32,348::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37`ReqID=`94e25cb0-c5c9-49f2-acaa-9e811234108d`::Granted request
>CP Server Thread-17::DEBUG::2012-03-26 15:45:32,348::task::819::TaskManager.Task::(resourceAcquired) Task=`5e83e007-778a-47fd-8603-455a85df3d9b`::_resourcesAcquired: Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37 (shared)
>CP Server Thread-17::DEBUG::2012-03-26 15:45:32,348::task::980::TaskManager.Task::(_decref) Task=`5e83e007-778a-47fd-8603-455a85df3d9b`::ref 1 aborting False
>CP Server Thread-17::INFO::2012-03-26 15:45:32,349::logUtils::39::dispatcher::(wrapper) Run and protect: getStorageDomainInfo, Return response: {'info': {'uuid': '1be32ac7-1e12-4823-8e8c-8c887333fe37', 'master_ver': 0, 'lver': -1, 'version': '0', 'role': 'Regular', 'remotePath': '/var/lib/vdsm/bugstoragsomedomain4', 'spm_id': -1, 'type': 'LOCALFS', 'class': 'Data', 'pool': [], 'name': 'Test Domain'}}
>CP Server Thread-17::DEBUG::2012-03-26 15:45:32,349::task::1174::TaskManager.Task::(prepare) Task=`5e83e007-778a-47fd-8603-455a85df3d9b`::finished: {'info': {'uuid': '1be32ac7-1e12-4823-8e8c-8c887333fe37', 'master_ver': 0, 'lver': -1, 'version': '0', 'role': 'Regular', 'remotePath': '/var/lib/vdsm/bugstoragsomedomain4', 'spm_id': -1, 'type': 'LOCALFS', 'class': 'Data', 'pool': [], 'name': 'Test Domain'}}
>CP Server Thread-17::DEBUG::2012-03-26 15:45:32,349::task::588::TaskManager.Task::(_updateState) Task=`5e83e007-778a-47fd-8603-455a85df3d9b`::moving from state preparing -> state finished
>CP Server Thread-17::DEBUG::2012-03-26 15:45:32,349::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37': < ResourceRef 'Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37', isValid: 'True' obj: 'None'>}
>CP Server Thread-17::DEBUG::2012-03-26 15:45:32,350::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>CP Server Thread-17::DEBUG::2012-03-26 15:45:32,350::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37'
>CP Server Thread-17::DEBUG::2012-03-26 15:45:32,350::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37' (0 active users)
>CP Server Thread-17::DEBUG::2012-03-26 15:45:32,351::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37' is free, finding out if anyone is waiting for it.
>CP Server Thread-17::DEBUG::2012-03-26 15:45:32,351::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37', Clearing records.
>CP Server Thread-17::DEBUG::2012-03-26 15:45:32,351::task::980::TaskManager.Task::(_decref) Task=`5e83e007-778a-47fd-8603-455a85df3d9b`::ref 0 aborting False
>CP Server Thread-17::INFO::2012-03-26 15:45:32,353::_cplogging::262::cherrypy.access.23486224::(access) 127.0.0.1 - - [26/Mar/2012:15:45:32] "GET /vdsm-api/storagedomains/1be32ac7-1e12-4823-8e8c-8c887333fe37 HTTP/1.1" 301 221 "" "Python-urllib/2.7"
>CP Server Thread-18::DEBUG::2012-03-26 15:45:32,355::task::588::TaskManager.Task::(_updateState) Task=`3f57b863-f73f-419a-9416-c030fa9145f4`::moving from state init -> state preparing
>CP Server Thread-18::INFO::2012-03-26 15:45:32,356::logUtils::37::dispatcher::(wrapper) Run and protect: getStorageDomainInfo(sdUUID='1be32ac7-1e12-4823-8e8c-8c887333fe37', options=None)
>CP Server Thread-18::INFO::2012-03-26 15:45:32,356::fileSD::193::Storage.StorageDomain::(validate) sdUUID=1be32ac7-1e12-4823-8e8c-8c887333fe37
>CP Server Thread-18::DEBUG::2012-03-26 15:45:32,357::persistentDict::216::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=Test Domain', 'IOOPTIMEOUTSEC=1', 'LEASERETRIES=3', 'LEASETIMESEC=5', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'POOL_UUID=', 'REMOTE_PATH=/var/lib/vdsm/bugstoragsomedomain4', 'ROLE=Regular', 'SDUUID=1be32ac7-1e12-4823-8e8c-8c887333fe37', 'TYPE=LOCALFS', 'VERSION=0', '_SHA_CKSUM=8b68aa921f50fa00ca9478b1ead85ff049fbac52']
>CP Server Thread-18::DEBUG::2012-03-26 15:45:32,359::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37`ReqID=`d0ec9482-05f2-4562-a3c9-380b77b3fb10`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2036' at 'getStorageDomainInfo'
>CP Server Thread-18::DEBUG::2012-03-26 15:45:32,359::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37' for lock type 'shared'
>CP Server Thread-18::DEBUG::2012-03-26 15:45:32,360::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37' is free. Now locking as 'shared' (1 active user)
>CP Server Thread-18::DEBUG::2012-03-26 15:45:32,360::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37`ReqID=`d0ec9482-05f2-4562-a3c9-380b77b3fb10`::Granted request
>CP Server Thread-18::DEBUG::2012-03-26 15:45:32,361::task::819::TaskManager.Task::(resourceAcquired) Task=`3f57b863-f73f-419a-9416-c030fa9145f4`::_resourcesAcquired: Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37 (shared)
>CP Server Thread-18::DEBUG::2012-03-26 15:45:32,362::task::980::TaskManager.Task::(_decref) Task=`3f57b863-f73f-419a-9416-c030fa9145f4`::ref 1 aborting False
>CP Server Thread-18::INFO::2012-03-26 15:45:32,363::logUtils::39::dispatcher::(wrapper) Run and protect: getStorageDomainInfo, Return response: {'info': {'uuid': '1be32ac7-1e12-4823-8e8c-8c887333fe37', 'master_ver': 0, 'lver': -1, 'version': '0', 'role': 'Regular', 'remotePath': '/var/lib/vdsm/bugstoragsomedomain4', 'spm_id': -1, 'type': 'LOCALFS', 'class': 'Data', 'pool': [], 'name': 'Test Domain'}}
>CP Server Thread-18::DEBUG::2012-03-26 15:45:32,363::task::1174::TaskManager.Task::(prepare) Task=`3f57b863-f73f-419a-9416-c030fa9145f4`::finished: {'info': {'uuid': '1be32ac7-1e12-4823-8e8c-8c887333fe37', 'master_ver': 0, 'lver': -1, 'version': '0', 'role': 'Regular', 'remotePath': '/var/lib/vdsm/bugstoragsomedomain4', 'spm_id': -1, 'type': 'LOCALFS', 'class': 'Data', 'pool': [], 'name': 'Test Domain'}}
>CP Server Thread-18::DEBUG::2012-03-26 15:45:32,364::task::588::TaskManager.Task::(_updateState) Task=`3f57b863-f73f-419a-9416-c030fa9145f4`::moving from state preparing -> state finished
>CP Server Thread-18::DEBUG::2012-03-26 15:45:32,365::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37': < ResourceRef 'Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37', isValid: 'True' obj: 'None'>}
>CP Server Thread-18::DEBUG::2012-03-26 15:45:32,365::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>CP Server Thread-18::DEBUG::2012-03-26 15:45:32,366::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37'
>CP Server Thread-18::DEBUG::2012-03-26 15:45:32,367::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37' (0 active users)
>CP Server Thread-18::DEBUG::2012-03-26 15:45:32,367::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37' is free, finding out if anyone is waiting for it.
>CP Server Thread-18::DEBUG::2012-03-26 15:45:32,368::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37', Clearing records.
>CP Server Thread-18::DEBUG::2012-03-26 15:45:32,368::task::980::TaskManager.Task::(_decref) Task=`3f57b863-f73f-419a-9416-c030fa9145f4`::ref 0 aborting False
>CP Server Thread-18::INFO::2012-03-26 15:45:32,370::_cplogging::262::cherrypy.access.23486224::(access) 127.0.0.1 - - [26/Mar/2012:15:45:32] "GET /vdsm-api/storagedomains/1be32ac7-1e12-4823-8e8c-8c887333fe37/ HTTP/1.1" 200 387 "" "Python-urllib/2.7"
>CP Server Thread-19::DEBUG::2012-03-26 15:45:32,384::task::588::TaskManager.Task::(_updateState) Task=`4e6960b9-ab16-43f0-a7d1-e12034ad1b48`::moving from state init -> state preparing
>CP Server Thread-19::INFO::2012-03-26 15:45:32,385::logUtils::37::dispatcher::(wrapper) Run and protect: getStorageDomainInfo(sdUUID='1be32ac7-1e12-4823-8e8c-8c887333fe37', options=None)
>CP Server Thread-19::INFO::2012-03-26 15:45:32,385::fileSD::193::Storage.StorageDomain::(validate) sdUUID=1be32ac7-1e12-4823-8e8c-8c887333fe37
>CP Server Thread-19::DEBUG::2012-03-26 15:45:32,386::persistentDict::216::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=Test Domain', 'IOOPTIMEOUTSEC=1', 'LEASERETRIES=3', 'LEASETIMESEC=5', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'POOL_UUID=', 'REMOTE_PATH=/var/lib/vdsm/bugstoragsomedomain4', 'ROLE=Regular', 'SDUUID=1be32ac7-1e12-4823-8e8c-8c887333fe37', 'TYPE=LOCALFS', 'VERSION=0', '_SHA_CKSUM=8b68aa921f50fa00ca9478b1ead85ff049fbac52']
>CP Server Thread-19::DEBUG::2012-03-26 15:45:32,387::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37`ReqID=`45c32251-0e2f-430a-a2a0-958d3848c6c5`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2036' at 'getStorageDomainInfo'
>CP Server Thread-19::DEBUG::2012-03-26 15:45:32,388::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37' for lock type 'shared'
>CP Server Thread-19::DEBUG::2012-03-26 15:45:32,388::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37' is free. Now locking as 'shared' (1 active user)
>CP Server Thread-19::DEBUG::2012-03-26 15:45:32,389::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37`ReqID=`45c32251-0e2f-430a-a2a0-958d3848c6c5`::Granted request
>CP Server Thread-19::DEBUG::2012-03-26 15:45:32,389::task::819::TaskManager.Task::(resourceAcquired) Task=`4e6960b9-ab16-43f0-a7d1-e12034ad1b48`::_resourcesAcquired: Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37 (shared)
>CP Server Thread-19::DEBUG::2012-03-26 15:45:32,389::task::980::TaskManager.Task::(_decref) Task=`4e6960b9-ab16-43f0-a7d1-e12034ad1b48`::ref 1 aborting False
>CP Server Thread-19::INFO::2012-03-26 15:45:32,390::logUtils::39::dispatcher::(wrapper) Run and protect: getStorageDomainInfo, Return response: {'info': {'uuid': '1be32ac7-1e12-4823-8e8c-8c887333fe37', 'master_ver': 0, 'lver': -1, 'version': '0', 'role': 'Regular', 'remotePath': '/var/lib/vdsm/bugstoragsomedomain4', 'spm_id': -1, 'type': 'LOCALFS', 'class': 'Data', 'pool': [], 'name': 'Test Domain'}}
>CP Server Thread-19::DEBUG::2012-03-26 15:45:32,390::task::1174::TaskManager.Task::(prepare) Task=`4e6960b9-ab16-43f0-a7d1-e12034ad1b48`::finished: {'info': {'uuid': '1be32ac7-1e12-4823-8e8c-8c887333fe37', 'master_ver': 0, 'lver': -1, 'version': '0', 'role': 'Regular', 'remotePath': '/var/lib/vdsm/bugstoragsomedomain4', 'spm_id': -1, 'type': 'LOCALFS', 'class': 'Data', 'pool': [], 'name': 'Test Domain'}}
>CP Server Thread-19::DEBUG::2012-03-26 15:45:32,390::task::588::TaskManager.Task::(_updateState) Task=`4e6960b9-ab16-43f0-a7d1-e12034ad1b48`::moving from state preparing -> state finished
>CP Server Thread-19::DEBUG::2012-03-26 15:45:32,391::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37': < ResourceRef 'Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37', isValid: 'True' obj: 'None'>}
>CP Server Thread-19::DEBUG::2012-03-26 15:45:32,391::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>CP Server Thread-19::DEBUG::2012-03-26 15:45:32,391::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37'
>CP Server Thread-19::DEBUG::2012-03-26 15:45:32,391::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37' (0 active users)
>CP Server Thread-19::DEBUG::2012-03-26 15:45:32,392::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37' is free, finding out if anyone is waiting for it.
>CP Server Thread-19::DEBUG::2012-03-26 15:45:32,392::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37', Clearing records.
>CP Server Thread-19::DEBUG::2012-03-26 15:45:32,392::task::980::TaskManager.Task::(_decref) Task=`4e6960b9-ab16-43f0-a7d1-e12034ad1b48`::ref 0 aborting False
>CP Server Thread-19::INFO::2012-03-26 15:45:32,393::_cplogging::262::cherrypy.access.23486224::(access) 127.0.0.1 - - [26/Mar/2012:15:45:32] "GET /vdsm-api/storagedomains/1be32ac7-1e12-4823-8e8c-8c887333fe37/ HTTP/1.1" 200 387 "" "Python-urllib/2.7"
>CP Server Thread-20::DEBUG::2012-03-26 15:45:32,396::task::588::TaskManager.Task::(_updateState) Task=`762eb982-a1d5-4af1-b942-4fac5d4f93d5`::moving from state init -> state preparing
>CP Server Thread-20::INFO::2012-03-26 15:45:32,396::logUtils::37::dispatcher::(wrapper) Run and protect: createStoragePool(poolType=None, spUUID='bebd6a96-d3da-419c-8905-b5eec55c4505', poolName='Local storage pooln', masterDom='1be32ac7-1e12-4823-8e8c-8c887333fe37', domList=[u'1be32ac7-1e12-4823-8e8c-8c887333fe37'], masterVersion='0', lockPolicy=None, lockRenewalIntervalSec=None, leaseTimeSec=None, ioOpTimeoutSec=None, leaseRetries=None, options=None)
>CP Server Thread-20::INFO::2012-03-26 15:45:32,397::fileSD::193::Storage.StorageDomain::(validate) sdUUID=1be32ac7-1e12-4823-8e8c-8c887333fe37
>CP Server Thread-20::DEBUG::2012-03-26 15:45:32,398::persistentDict::216::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=Test Domain', 'IOOPTIMEOUTSEC=1', 'LEASERETRIES=3', 'LEASETIMESEC=5', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'POOL_UUID=', 'REMOTE_PATH=/var/lib/vdsm/bugstoragsomedomain4', 'ROLE=Regular', 'SDUUID=1be32ac7-1e12-4823-8e8c-8c887333fe37', 'TYPE=LOCALFS', 'VERSION=0', '_SHA_CKSUM=8b68aa921f50fa00ca9478b1ead85ff049fbac52']
>CP Server Thread-20::DEBUG::2012-03-26 15:45:32,398::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.bebd6a96-d3da-419c-8905-b5eec55c4505`ReqID=`0b30ae8a-2cb8-438f-9558-0dad6d251aaa`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '692' at 'createStoragePool'
>CP Server Thread-20::DEBUG::2012-03-26 15:45:32,399::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505' for lock type 'exclusive'
>CP Server Thread-20::DEBUG::2012-03-26 15:45:32,399::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505' is free. Now locking as 'exclusive' (1 active user)
>CP Server Thread-20::DEBUG::2012-03-26 15:45:32,399::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.bebd6a96-d3da-419c-8905-b5eec55c4505`ReqID=`0b30ae8a-2cb8-438f-9558-0dad6d251aaa`::Granted request
>CP Server Thread-20::DEBUG::2012-03-26 15:45:32,399::task::819::TaskManager.Task::(resourceAcquired) Task=`762eb982-a1d5-4af1-b942-4fac5d4f93d5`::_resourcesAcquired: Storage.bebd6a96-d3da-419c-8905-b5eec55c4505 (exclusive)
>CP Server Thread-20::DEBUG::2012-03-26 15:45:32,400::task::980::TaskManager.Task::(_decref) Task=`762eb982-a1d5-4af1-b942-4fac5d4f93d5`::ref 1 aborting False
>CP Server Thread-20::DEBUG::2012-03-26 15:45:32,400::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37`ReqID=`93d22731-7913-463a-adf2-becfc74c205d`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '694' at 'createStoragePool'
>CP Server Thread-20::DEBUG::2012-03-26 15:45:32,400::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37' for lock type 'exclusive'
>CP Server Thread-20::DEBUG::2012-03-26 15:45:32,401::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37' is free. Now locking as 'exclusive' (1 active user)
>CP Server Thread-20::DEBUG::2012-03-26 15:45:32,401::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37`ReqID=`93d22731-7913-463a-adf2-becfc74c205d`::Granted request
>CP Server Thread-20::DEBUG::2012-03-26 15:45:32,402::task::819::TaskManager.Task::(resourceAcquired) Task=`762eb982-a1d5-4af1-b942-4fac5d4f93d5`::_resourcesAcquired: Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37 (exclusive)
>CP Server Thread-20::DEBUG::2012-03-26 15:45:32,402::task::980::TaskManager.Task::(_decref) Task=`762eb982-a1d5-4af1-b942-4fac5d4f93d5`::ref 1 aborting False
>CP Server Thread-20::INFO::2012-03-26 15:45:32,402::sp::541::Storage.StoragePool::(create) spUUID=bebd6a96-d3da-419c-8905-b5eec55c4505 poolName=Local storage pooln master_sd=1be32ac7-1e12-4823-8e8c-8c887333fe37 domList=[u'1be32ac7-1e12-4823-8e8c-8c887333fe37'] masterVersion=0 {'LEASETIMESEC': 30, 'LOCKPOLICY': 'ON', 'IOOPTIMEOUTSEC': 1, 'LEASERETRIES': 3, 'LOCKRENEWALINTERVALSEC': 5}
>CP Server Thread-20::INFO::2012-03-26 15:45:32,402::fileSD::193::Storage.StorageDomain::(validate) sdUUID=1be32ac7-1e12-4823-8e8c-8c887333fe37
>CP Server Thread-20::DEBUG::2012-03-26 15:45:32,403::persistentDict::216::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=Test Domain', 'IOOPTIMEOUTSEC=1', 'LEASERETRIES=3', 'LEASETIMESEC=5', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'POOL_UUID=', 'REMOTE_PATH=/var/lib/vdsm/bugstoragsomedomain4', 'ROLE=Regular', 'SDUUID=1be32ac7-1e12-4823-8e8c-8c887333fe37', 'TYPE=LOCALFS', 'VERSION=0', '_SHA_CKSUM=8b68aa921f50fa00ca9478b1ead85ff049fbac52']
>CP Server Thread-20::DEBUG::2012-03-26 15:45:32,405::persistentDict::216::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=Test Domain', 'IOOPTIMEOUTSEC=1', 'LEASERETRIES=3', 'LEASETIMESEC=5', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'POOL_UUID=', 'REMOTE_PATH=/var/lib/vdsm/bugstoragsomedomain4', 'ROLE=Regular', 'SDUUID=1be32ac7-1e12-4823-8e8c-8c887333fe37', 'TYPE=LOCALFS', 'VERSION=0', '_SHA_CKSUM=8b68aa921f50fa00ca9478b1ead85ff049fbac52']
>CP Server Thread-20::DEBUG::2012-03-26 15:45:32,406::persistentDict::152::Storage.PersistentDict::(transaction) Starting transaction
>CP Server Thread-20::DEBUG::2012-03-26 15:45:32,406::persistentDict::158::Storage.PersistentDict::(transaction) Flushing changes
>CP Server Thread-20::DEBUG::2012-03-26 15:45:32,407::persistentDict::277::Storage.PersistentDict::(flush) about to write lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=Test Domain', 'IOOPTIMEOUTSEC=1', 'LEASERETRIES=3', 'LEASETIMESEC=30', 'LOCKPOLICY=ON', 'LOCKRENEWALINTERVALSEC=5', 'POOL_UUID=', 'REMOTE_PATH=/var/lib/vdsm/bugstoragsomedomain4', 'ROLE=Regular', 'SDUUID=1be32ac7-1e12-4823-8e8c-8c887333fe37', 'TYPE=LOCALFS', 'VERSION=0', '_SHA_CKSUM=698b19d1b04b9b004dbd62e51fcf8c7a944e3cae']
>CP Server Thread-20::DEBUG::2012-03-26 15:45:32,408::persistentDict::160::Storage.PersistentDict::(transaction) Finished transaction
>CP Server Thread-20::DEBUG::2012-03-26 15:45:32,409::safelease::85::ClusterLock::(acquire) Acquiring cluster lock for domain 1be32ac7-1e12-4823-8e8c-8c887333fe37
>CP Server Thread-20::DEBUG::2012-03-26 15:45:32,410::safelease::94::Storage.Misc.excCmd::(acquire) '/usr/bin/sudo -n /usr/bin/setsid /usr/bin/ionice -c1 -n0 /bin/su vdsm -s /bin/sh -c "/usr/libexec/vdsm/spmprotect.sh start 1be32ac7-1e12-4823-8e8c-8c887333fe37 1000 5 /rhev/data-center/mnt/_var_lib_vdsm_bugstoragsomedomain4/1be32ac7-1e12-4823-8e8c-8c887333fe37/dom_md/leases 30000 1000 3"' (cwd /usr/libexec/vdsm)
>CP Server Thread-20::DEBUG::2012-03-26 15:45:34,476::safelease::94::Storage.Misc.excCmd::(acquire) SUCCESS: <err> = ''; <rc> = 0
>CP Server Thread-20::DEBUG::2012-03-26 15:45:34,476::safelease::98::ClusterLock::(acquire) Clustered lock acquired successfully
>CP Server Thread-20::INFO::2012-03-26 15:45:34,477::sp::720::Storage.StoragePool::(createMaster) setting master domain for spUUID bebd6a96-d3da-419c-8905-b5eec55c4505 on sdUUID=1be32ac7-1e12-4823-8e8c-8c887333fe37
>CP Server Thread-20::DEBUG::2012-03-26 15:45:34,477::persistentDict::152::Storage.PersistentDict::(transaction) Starting transaction
>CP Server Thread-20::DEBUG::2012-03-26 15:45:34,477::persistentDict::145::Storage.PersistentDict::(transaction) Reusing active transaction
>CP Server Thread-20::DEBUG::2012-03-26 15:45:34,479::persistentDict::216::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=Test Domain', 'IOOPTIMEOUTSEC=1', 'LEASERETRIES=3', 'LEASETIMESEC=30', 'LOCKPOLICY=ON', 'LOCKRENEWALINTERVALSEC=5', 'POOL_UUID=', 'REMOTE_PATH=/var/lib/vdsm/bugstoragsomedomain4', 'ROLE=Regular', 'SDUUID=1be32ac7-1e12-4823-8e8c-8c887333fe37', 'TYPE=LOCALFS', 'VERSION=0', '_SHA_CKSUM=698b19d1b04b9b004dbd62e51fcf8c7a944e3cae']
>CP Server Thread-20::DEBUG::2012-03-26 15:45:34,480::persistentDict::145::Storage.PersistentDict::(transaction) Reusing active transaction
>CP Server Thread-20::DEBUG::2012-03-26 15:45:34,480::persistentDict::145::Storage.PersistentDict::(transaction) Reusing active transaction
>CP Server Thread-20::DEBUG::2012-03-26 15:45:34,480::persistentDict::145::Storage.PersistentDict::(transaction) Reusing active transaction
>CP Server Thread-20::DEBUG::2012-03-26 15:45:34,480::persistentDict::158::Storage.PersistentDict::(transaction) Flushing changes
>CP Server Thread-20::DEBUG::2012-03-26 15:45:34,481::persistentDict::277::Storage.PersistentDict::(flush) about to write lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=Test Domain', 'IOOPTIMEOUTSEC=1', 'LEASERETRIES=3', 'LEASETIMESEC=30', 'LOCKPOLICY=ON', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=0', 'POOL_DESCRIPTION=Local storage pooln', 'POOL_DOMAINS=1be32ac7-1e12-4823-8e8c-8c887333fe37:Active', 'POOL_SPM_ID=-1', 'POOL_SPM_LVER=-1', 'POOL_UUID=bebd6a96-d3da-419c-8905-b5eec55c4505', 'REMOTE_PATH=/var/lib/vdsm/bugstoragsomedomain4', 'ROLE=Master', 'SDUUID=1be32ac7-1e12-4823-8e8c-8c887333fe37', 'TYPE=LOCALFS', 'VERSION=0', '_SHA_CKSUM=7a33be6c0caad1af294e95d0b51d5d813708ef56']
>CP Server Thread-20::DEBUG::2012-03-26 15:45:34,482::persistentDict::160::Storage.PersistentDict::(transaction) Finished transaction
>CP Server Thread-20::DEBUG::2012-03-26 15:45:34,482::sp::1484::Storage.StoragePool::(getMasterDomain) Master domain 1be32ac7-1e12-4823-8e8c-8c887333fe37 verified, version 0
>CP Server Thread-20::DEBUG::2012-03-26 15:45:34,482::misc::1017::SamplingMethod::(__call__) Trying to enter sampling method (storage.sp.updateMonitoringThreads)
>CP Server Thread-20::DEBUG::2012-03-26 15:45:34,483::misc::1019::SamplingMethod::(__call__) Got in to sampling method
>CP Server Thread-20::DEBUG::2012-03-26 15:45:34,485::persistentDict::216::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=Test Domain', 'IOOPTIMEOUTSEC=1', 'LEASERETRIES=3', 'LEASETIMESEC=30', 'LOCKPOLICY=ON', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=0', 'POOL_DESCRIPTION=Local storage pooln', 'POOL_DOMAINS=1be32ac7-1e12-4823-8e8c-8c887333fe37:Active', 'POOL_SPM_ID=-1', 'POOL_SPM_LVER=-1', 'POOL_UUID=bebd6a96-d3da-419c-8905-b5eec55c4505', 'REMOTE_PATH=/var/lib/vdsm/bugstoragsomedomain4', 'ROLE=Master', 'SDUUID=1be32ac7-1e12-4823-8e8c-8c887333fe37', 'TYPE=LOCALFS', 'VERSION=0', '_SHA_CKSUM=7a33be6c0caad1af294e95d0b51d5d813708ef56']
>CP Server Thread-20::DEBUG::2012-03-26 15:45:34,486::sp::1514::Storage.StoragePool::(updateMonitoringThreads) sp `bebd6a96-d3da-419c-8905-b5eec55c4505` started monitoring domain `1be32ac7-1e12-4823-8e8c-8c887333fe37`
>CP Server Thread-20::DEBUG::2012-03-26 15:45:34,486::misc::1027::SamplingMethod::(__call__) Returning last result
>CP Server Thread-20::DEBUG::2012-03-26 15:45:34,487::lvm::352::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
>CP Server Thread-20::DEBUG::2012-03-26 15:45:34,488::lvm::287::Storage.Misc.excCmd::(cmd) '/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 = [ \\"a%35000c500382d9c53%\\", \\"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)
>CP Server Thread-20::DEBUG::2012-03-26 15:45:34,535::lvm::287::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = '  No volume groups found\n'; <rc> = 0
>CP Server Thread-20::DEBUG::2012-03-26 15:45:34,536::lvm::379::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
>CP Server Thread-20::INFO::2012-03-26 15:45:34,540::sp::1084::Storage.StoragePool::(_linkStorageDomain) Linking /rhev/data-center/mnt/_var_lib_vdsm_bugstoragsomedomain4/1be32ac7-1e12-4823-8e8c-8c887333fe37 to /rhev/data-center/bebd6a96-d3da-419c-8905-b5eec55c4505/1be32ac7-1e12-4823-8e8c-8c887333fe37
>CP Server Thread-20::INFO::2012-03-26 15:45:34,540::sp::1084::Storage.StoragePool::(_linkStorageDomain) Linking /rhev/data-center/mnt/_var_lib_vdsm_bugstoragsomedomain3/1be32ac7-1e12-4823-8e8c-8c887333fe36 to /rhev/data-center/bebd6a96-d3da-419c-8905-b5eec55c4505/1be32ac7-1e12-4823-8e8c-8c887333fe36
>CP Server Thread-20::INFO::2012-03-26 15:45:34,541::sp::1084::Storage.StoragePool::(_linkStorageDomain) Linking /rhev/data-center/mnt/_var_lib_vdsm_bugstoragsomedomain4/1be32ac7-1e12-4823-8e8c-8c887333fe37 to /rhev/data-center/bebd6a96-d3da-419c-8905-b5eec55c4505/1be32ac7-1e12-4823-8e8c-8c887333fe37
>CP Server Thread-20::INFO::2012-03-26 15:45:34,541::sp::1084::Storage.StoragePool::(_linkStorageDomain) Linking /rhev/data-center/mnt/_var_lib_vdsm_bugstoragsomedomain4/1be32ac7-1e12-4823-8e8c-8c887333fe37 to /rhev/data-center/bebd6a96-d3da-419c-8905-b5eec55c4505/mastersd
>CP Server Thread-20::INFO::2012-03-26 15:45:34,542::safelease::116::ClusterLock::(release) Releasing cluster lock for domain 1be32ac7-1e12-4823-8e8c-8c887333fe37
>CP Server Thread-20::DEBUG::2012-03-26 15:45:34,542::safelease::117::Storage.Misc.excCmd::(release) '/usr/libexec/vdsm/spmstop.sh 1be32ac7-1e12-4823-8e8c-8c887333fe37' (cwd /usr/libexec/vdsm)
>CP Server Thread-20::DEBUG::2012-03-26 15:45:35,579::safelease::117::Storage.Misc.excCmd::(release) SUCCESS: <err> = ''; <rc> = 0
>CP Server Thread-20::DEBUG::2012-03-26 15:45:35,579::safelease::120::ClusterLock::(release) Cluster lock released successfully
>CP Server Thread-20::INFO::2012-03-26 15:45:35,580::logUtils::39::dispatcher::(wrapper) Run and protect: createStoragePool, Return response: True
>CP Server Thread-20::DEBUG::2012-03-26 15:45:35,580::task::1174::TaskManager.Task::(prepare) Task=`762eb982-a1d5-4af1-b942-4fac5d4f93d5`::finished: True
>CP Server Thread-20::DEBUG::2012-03-26 15:45:35,581::task::588::TaskManager.Task::(_updateState) Task=`762eb982-a1d5-4af1-b942-4fac5d4f93d5`::moving from state preparing -> state finished
>CP Server Thread-20::DEBUG::2012-03-26 15:45:35,581::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505': < ResourceRef 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505', isValid: 'True' obj: 'None'>, u'Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37': < ResourceRef 'Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37', isValid: 'True' obj: 'None'>}
>CP Server Thread-20::DEBUG::2012-03-26 15:45:35,581::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>CP Server Thread-20::DEBUG::2012-03-26 15:45:35,582::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505'
>CP Server Thread-20::DEBUG::2012-03-26 15:45:35,582::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505' (0 active users)
>CP Server Thread-20::DEBUG::2012-03-26 15:45:35,583::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505' is free, finding out if anyone is waiting for it.
>CP Server Thread-20::DEBUG::2012-03-26 15:45:35,583::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505', Clearing records.
>CP Server Thread-20::DEBUG::2012-03-26 15:45:35,584::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37'
>CP Server Thread-20::DEBUG::2012-03-26 15:45:35,584::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37' (0 active users)
>CP Server Thread-20::DEBUG::2012-03-26 15:45:35,584::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37' is free, finding out if anyone is waiting for it.
>CP Server Thread-20::DEBUG::2012-03-26 15:45:35,585::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37', Clearing records.
>CP Server Thread-20::DEBUG::2012-03-26 15:45:35,585::task::980::TaskManager.Task::(_decref) Task=`762eb982-a1d5-4af1-b942-4fac5d4f93d5`::ref 0 aborting False
>CP Server Thread-20::INFO::2012-03-26 15:45:35,586::_cplogging::262::cherrypy.access.23486224::(access) 127.0.0.1 - - [26/Mar/2012:15:45:35] "POST /vdsm-api/storagepools/create HTTP/1.1" 204 - "" "Python-urllib/2.7"
>CP Server Thread-21::DEBUG::2012-03-26 15:45:35,590::task::588::TaskManager.Task::(_updateState) Task=`8c6979d2-6e62-4411-8154-0382ce9942ce`::moving from state init -> state preparing
>CP Server Thread-21::INFO::2012-03-26 15:45:35,591::logUtils::37::dispatcher::(wrapper) Run and protect: connectStoragePool(spUUID='bebd6a96-d3da-419c-8905-b5eec55c4505', hostID=1, scsiKey='scsikey', msdUUID='1be32ac7-1e12-4823-8e8c-8c887333fe37', masterVersion='0', options=None)
>CP Server Thread-21::DEBUG::2012-03-26 15:45:35,592::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.bebd6a96-d3da-419c-8905-b5eec55c4505`ReqID=`86b1cbb7-710f-4eab-9598-d16980bf89ff`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '749' at '_connectStoragePool'
>CP Server Thread-21::DEBUG::2012-03-26 15:45:35,592::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505' for lock type 'exclusive'
>CP Server Thread-21::DEBUG::2012-03-26 15:45:35,592::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505' is free. Now locking as 'exclusive' (1 active user)
>CP Server Thread-21::DEBUG::2012-03-26 15:45:35,592::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.bebd6a96-d3da-419c-8905-b5eec55c4505`ReqID=`86b1cbb7-710f-4eab-9598-d16980bf89ff`::Granted request
>CP Server Thread-21::INFO::2012-03-26 15:45:35,593::sp::624::Storage.StoragePool::(connect) Connect host #1 to the storage pool bebd6a96-d3da-419c-8905-b5eec55c4505 with master domain: 1be32ac7-1e12-4823-8e8c-8c887333fe37 (ver = 0)
>CP Server Thread-21::DEBUG::2012-03-26 15:45:35,593::lvm::460::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
>CP Server Thread-21::DEBUG::2012-03-26 15:45:35,593::lvm::462::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
>CP Server Thread-21::DEBUG::2012-03-26 15:45:35,593::lvm::472::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
>CP Server Thread-21::DEBUG::2012-03-26 15:45:35,594::lvm::474::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
>CP Server Thread-21::DEBUG::2012-03-26 15:45:35,594::lvm::493::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
>CP Server Thread-21::DEBUG::2012-03-26 15:45:35,594::lvm::495::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
>CP Server Thread-21::DEBUG::2012-03-26 15:45:35,594::sp::1484::Storage.StoragePool::(getMasterDomain) Master domain 1be32ac7-1e12-4823-8e8c-8c887333fe37 verified, version 0
>CP Server Thread-21::DEBUG::2012-03-26 15:45:35,594::misc::1017::SamplingMethod::(__call__) Trying to enter sampling method (storage.sp.updateMonitoringThreads)
>CP Server Thread-21::DEBUG::2012-03-26 15:45:35,595::misc::1019::SamplingMethod::(__call__) Got in to sampling method
>CP Server Thread-21::DEBUG::2012-03-26 15:45:35,596::persistentDict::216::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=Test Domain', 'IOOPTIMEOUTSEC=1', 'LEASERETRIES=3', 'LEASETIMESEC=30', 'LOCKPOLICY=ON', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=0', 'POOL_DESCRIPTION=Local storage pooln', 'POOL_DOMAINS=1be32ac7-1e12-4823-8e8c-8c887333fe37:Active', 'POOL_SPM_ID=-1', 'POOL_SPM_LVER=-1', 'POOL_UUID=bebd6a96-d3da-419c-8905-b5eec55c4505', 'REMOTE_PATH=/var/lib/vdsm/bugstoragsomedomain4', 'ROLE=Master', 'SDUUID=1be32ac7-1e12-4823-8e8c-8c887333fe37', 'TYPE=LOCALFS', 'VERSION=0', '_SHA_CKSUM=7a33be6c0caad1af294e95d0b51d5d813708ef56']
>CP Server Thread-21::DEBUG::2012-03-26 15:45:35,597::sp::1514::Storage.StoragePool::(updateMonitoringThreads) sp `bebd6a96-d3da-419c-8905-b5eec55c4505` started monitoring domain `1be32ac7-1e12-4823-8e8c-8c887333fe37`
>CP Server Thread-21::DEBUG::2012-03-26 15:45:35,597::misc::1027::SamplingMethod::(__call__) Returning last result
>CP Server Thread-21::DEBUG::2012-03-26 15:45:35,597::lvm::352::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
>CP Server Thread-21::DEBUG::2012-03-26 15:45:35,599::lvm::287::Storage.Misc.excCmd::(cmd) '/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 = [ \\"a%35000c500382d9c53%\\", \\"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)
>CP Server Thread-21::DEBUG::2012-03-26 15:45:35,657::lvm::287::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = '  No volume groups found\n'; <rc> = 0
>CP Server Thread-21::DEBUG::2012-03-26 15:45:35,658::lvm::379::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
>CP Server Thread-21::INFO::2012-03-26 15:45:35,661::sp::1084::Storage.StoragePool::(_linkStorageDomain) Linking /rhev/data-center/mnt/_var_lib_vdsm_bugstoragsomedomain4/1be32ac7-1e12-4823-8e8c-8c887333fe37 to /rhev/data-center/bebd6a96-d3da-419c-8905-b5eec55c4505/1be32ac7-1e12-4823-8e8c-8c887333fe37
>CP Server Thread-21::INFO::2012-03-26 15:45:35,662::sp::1084::Storage.StoragePool::(_linkStorageDomain) Linking /rhev/data-center/mnt/_var_lib_vdsm_bugstoragsomedomain3/1be32ac7-1e12-4823-8e8c-8c887333fe36 to /rhev/data-center/bebd6a96-d3da-419c-8905-b5eec55c4505/1be32ac7-1e12-4823-8e8c-8c887333fe36
>CP Server Thread-21::INFO::2012-03-26 15:45:35,662::sp::1084::Storage.StoragePool::(_linkStorageDomain) Linking /rhev/data-center/mnt/_var_lib_vdsm_bugstoragsomedomain4/1be32ac7-1e12-4823-8e8c-8c887333fe37 to /rhev/data-center/bebd6a96-d3da-419c-8905-b5eec55c4505/1be32ac7-1e12-4823-8e8c-8c887333fe37
>CP Server Thread-21::INFO::2012-03-26 15:45:35,662::sp::1084::Storage.StoragePool::(_linkStorageDomain) Linking /rhev/data-center/mnt/_var_lib_vdsm_bugstoragsomedomain4/1be32ac7-1e12-4823-8e8c-8c887333fe37 to /rhev/data-center/bebd6a96-d3da-419c-8905-b5eec55c4505/mastersd
>CP Server Thread-21::DEBUG::2012-03-26 15:45:35,663::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505'
>CP Server Thread-21::DEBUG::2012-03-26 15:45:35,663::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505' (0 active users)
>CP Server Thread-21::DEBUG::2012-03-26 15:45:35,663::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505' is free, finding out if anyone is waiting for it.
>CP Server Thread-21::DEBUG::2012-03-26 15:45:35,664::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505', Clearing records.
>CP Server Thread-21::INFO::2012-03-26 15:45:35,664::logUtils::39::dispatcher::(wrapper) Run and protect: connectStoragePool, Return response: True
>CP Server Thread-21::DEBUG::2012-03-26 15:45:35,664::task::1174::TaskManager.Task::(prepare) Task=`8c6979d2-6e62-4411-8154-0382ce9942ce`::finished: True
>CP Server Thread-21::DEBUG::2012-03-26 15:45:35,664::task::588::TaskManager.Task::(_updateState) Task=`8c6979d2-6e62-4411-8154-0382ce9942ce`::moving from state preparing -> state finished
>CP Server Thread-21::DEBUG::2012-03-26 15:45:35,664::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>CP Server Thread-21::DEBUG::2012-03-26 15:45:35,665::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>CP Server Thread-21::DEBUG::2012-03-26 15:45:35,665::task::980::TaskManager.Task::(_decref) Task=`8c6979d2-6e62-4411-8154-0382ce9942ce`::ref 0 aborting False
>CP Server Thread-21::INFO::2012-03-26 15:45:35,665::_cplogging::262::cherrypy.access.23486224::(access) 127.0.0.1 - - [26/Mar/2012:15:45:35] "POST /vdsm-api/storagepools/connect HTTP/1.1" 303 206 "" "Python-urllib/2.7"
>CP Server Thread-22::DEBUG::2012-03-26 15:45:35,668::task::588::TaskManager.Task::(_updateState) Task=`45ea5518-d4a8-4f54-91a9-b224a58ab78a`::moving from state init -> state preparing
>CP Server Thread-22::INFO::2012-03-26 15:45:35,668::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='bebd6a96-d3da-419c-8905-b5eec55c4505', options=None)
>CP Server Thread-22::DEBUG::2012-03-26 15:45:35,669::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.bebd6a96-d3da-419c-8905-b5eec55c4505`ReqID=`e25c4dfd-4822-4de4-8933-696cd13100e9`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '1882' at 'getStoragePoolInfo'
>CP Server Thread-22::DEBUG::2012-03-26 15:45:35,669::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505' for lock type 'shared'
>CP Server Thread-22::DEBUG::2012-03-26 15:45:35,670::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505' is free. Now locking as 'shared' (1 active user)
>CP Server Thread-22::DEBUG::2012-03-26 15:45:35,670::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.bebd6a96-d3da-419c-8905-b5eec55c4505`ReqID=`e25c4dfd-4822-4de4-8933-696cd13100e9`::Granted request
>CP Server Thread-22::DEBUG::2012-03-26 15:45:35,671::task::819::TaskManager.Task::(resourceAcquired) Task=`45ea5518-d4a8-4f54-91a9-b224a58ab78a`::_resourcesAcquired: Storage.bebd6a96-d3da-419c-8905-b5eec55c4505 (shared)
>CP Server Thread-22::DEBUG::2012-03-26 15:45:35,671::task::980::TaskManager.Task::(_decref) Task=`45ea5518-d4a8-4f54-91a9-b224a58ab78a`::ref 1 aborting False
>CP Server Thread-22::INFO::2012-03-26 15:45:35,672::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': -1, 'master_uuid': '1be32ac7-1e12-4823-8e8c-8c887333fe37', 'name': 'Local storage pooln', 'version': '0', 'domains': '1be32ac7-1e12-4823-8e8c-8c887333fe37:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'LOCALFS', 'master_ver': 0, 'lver': -1}, 'dominfo': {'1be32ac7-1e12-4823-8e8c-8c887333fe37': {'status': 'Active', 'diskfree': '8778391552', 'alerts': [], 'disktotal': '15670194176'}}}
>CP Server Thread-22::DEBUG::2012-03-26 15:45:35,672::task::1174::TaskManager.Task::(prepare) Task=`45ea5518-d4a8-4f54-91a9-b224a58ab78a`::finished: {'info': {'spm_id': -1, 'master_uuid': '1be32ac7-1e12-4823-8e8c-8c887333fe37', 'name': 'Local storage pooln', 'version': '0', 'domains': '1be32ac7-1e12-4823-8e8c-8c887333fe37:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'LOCALFS', 'master_ver': 0, 'lver': -1}, 'dominfo': {'1be32ac7-1e12-4823-8e8c-8c887333fe37': {'status': 'Active', 'diskfree': '8778391552', 'alerts': [], 'disktotal': '15670194176'}}}
>CP Server Thread-22::DEBUG::2012-03-26 15:45:35,673::task::588::TaskManager.Task::(_updateState) Task=`45ea5518-d4a8-4f54-91a9-b224a58ab78a`::moving from state preparing -> state finished
>CP Server Thread-22::DEBUG::2012-03-26 15:45:35,673::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505': < ResourceRef 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505', isValid: 'True' obj: 'None'>}
>CP Server Thread-22::DEBUG::2012-03-26 15:45:35,673::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>CP Server Thread-22::DEBUG::2012-03-26 15:45:35,674::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505'
>CP Server Thread-22::DEBUG::2012-03-26 15:45:35,674::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505' (0 active users)
>CP Server Thread-22::DEBUG::2012-03-26 15:45:35,674::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505' is free, finding out if anyone is waiting for it.
>CP Server Thread-22::DEBUG::2012-03-26 15:45:35,675::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505', Clearing records.
>CP Server Thread-22::DEBUG::2012-03-26 15:45:35,675::task::980::TaskManager.Task::(_decref) Task=`45ea5518-d4a8-4f54-91a9-b224a58ab78a`::ref 0 aborting False
>CP Server Thread-22::INFO::2012-03-26 15:45:35,676::_cplogging::262::cherrypy.access.23486224::(access) 127.0.0.1 - - [26/Mar/2012:15:45:35] "GET /vdsm-api/storagepools/bebd6a96-d3da-419c-8905-b5eec55c4505 HTTP/1.1" 301 217 "" "Python-urllib/2.7"
>CP Server Thread-23::DEBUG::2012-03-26 15:45:35,678::task::588::TaskManager.Task::(_updateState) Task=`294564cc-0395-4576-9b2f-ae7d5fc7894f`::moving from state init -> state preparing
>CP Server Thread-23::INFO::2012-03-26 15:45:35,679::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='bebd6a96-d3da-419c-8905-b5eec55c4505', options=None)
>CP Server Thread-23::DEBUG::2012-03-26 15:45:35,679::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.bebd6a96-d3da-419c-8905-b5eec55c4505`ReqID=`233ef71b-5d14-4b39-989f-fdc7675cbb74`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '1882' at 'getStoragePoolInfo'
>CP Server Thread-23::DEBUG::2012-03-26 15:45:35,680::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505' for lock type 'shared'
>CP Server Thread-23::DEBUG::2012-03-26 15:45:35,680::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505' is free. Now locking as 'shared' (1 active user)
>CP Server Thread-23::DEBUG::2012-03-26 15:45:35,680::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.bebd6a96-d3da-419c-8905-b5eec55c4505`ReqID=`233ef71b-5d14-4b39-989f-fdc7675cbb74`::Granted request
>CP Server Thread-23::DEBUG::2012-03-26 15:45:35,680::task::819::TaskManager.Task::(resourceAcquired) Task=`294564cc-0395-4576-9b2f-ae7d5fc7894f`::_resourcesAcquired: Storage.bebd6a96-d3da-419c-8905-b5eec55c4505 (shared)
>CP Server Thread-23::DEBUG::2012-03-26 15:45:35,681::task::980::TaskManager.Task::(_decref) Task=`294564cc-0395-4576-9b2f-ae7d5fc7894f`::ref 1 aborting False
>CP Server Thread-23::INFO::2012-03-26 15:45:35,681::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': -1, 'master_uuid': '1be32ac7-1e12-4823-8e8c-8c887333fe37', 'name': 'Local storage pooln', 'version': '0', 'domains': '1be32ac7-1e12-4823-8e8c-8c887333fe37:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'LOCALFS', 'master_ver': 0, 'lver': -1}, 'dominfo': {'1be32ac7-1e12-4823-8e8c-8c887333fe37': {'status': 'Active', 'diskfree': '8778391552', 'alerts': [], 'disktotal': '15670194176'}}}
>CP Server Thread-23::DEBUG::2012-03-26 15:45:35,681::task::1174::TaskManager.Task::(prepare) Task=`294564cc-0395-4576-9b2f-ae7d5fc7894f`::finished: {'info': {'spm_id': -1, 'master_uuid': '1be32ac7-1e12-4823-8e8c-8c887333fe37', 'name': 'Local storage pooln', 'version': '0', 'domains': '1be32ac7-1e12-4823-8e8c-8c887333fe37:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'LOCALFS', 'master_ver': 0, 'lver': -1}, 'dominfo': {'1be32ac7-1e12-4823-8e8c-8c887333fe37': {'status': 'Active', 'diskfree': '8778391552', 'alerts': [], 'disktotal': '15670194176'}}}
>CP Server Thread-23::DEBUG::2012-03-26 15:45:35,681::task::588::TaskManager.Task::(_updateState) Task=`294564cc-0395-4576-9b2f-ae7d5fc7894f`::moving from state preparing -> state finished
>CP Server Thread-23::DEBUG::2012-03-26 15:45:35,682::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505': < ResourceRef 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505', isValid: 'True' obj: 'None'>}
>CP Server Thread-23::DEBUG::2012-03-26 15:45:35,682::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>CP Server Thread-23::DEBUG::2012-03-26 15:45:35,682::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505'
>CP Server Thread-23::DEBUG::2012-03-26 15:45:35,682::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505' (0 active users)
>CP Server Thread-23::DEBUG::2012-03-26 15:45:35,682::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505' is free, finding out if anyone is waiting for it.
>CP Server Thread-23::DEBUG::2012-03-26 15:45:35,683::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505', Clearing records.
>CP Server Thread-23::DEBUG::2012-03-26 15:45:35,683::task::980::TaskManager.Task::(_decref) Task=`294564cc-0395-4576-9b2f-ae7d5fc7894f`::ref 0 aborting False
>CP Server Thread-23::ERROR::2012-03-26 15:45:35,683::Controller::780::vds::(index) AGLITKE: data = {'info': {'name': 'Local storage pooln', 'isoprefix': '', 'pool_status': 'connected', 'lver': -1, 'domains': '1be32ac7-1e12-4823-8e8c-8c887333fe37:Active', 'master_uuid': '1be32ac7-1e12-4823-8e8c-8c887333fe37', 'version': '0', 'spm_id': -1, 'type': 'LOCALFS', 'master_ver': 0}, 'spUUID': 'bebd6a96-d3da-419c-8905-b5eec55c4505', 'dominfo': {'1be32ac7-1e12-4823-8e8c-8c887333fe37': {'status': 'Active', 'diskfree': '8778391552', 'alerts': [], 'disktotal': '15670194176'}}}
>CP Server Thread-23::INFO::2012-03-26 15:45:35,707::_cplogging::262::cherrypy.access.23486224::(access) 127.0.0.1 - - [26/Mar/2012:15:45:35] "GET /vdsm-api/storagepools/bebd6a96-d3da-419c-8905-b5eec55c4505/ HTTP/1.1" 200 650 "" "Python-urllib/2.7"
>CP Server Thread-24::DEBUG::2012-03-26 15:45:35,710::task::588::TaskManager.Task::(_updateState) Task=`cd302a00-5d53-43a2-aecf-8acc8a10f439`::moving from state init -> state preparing
>CP Server Thread-24::INFO::2012-03-26 15:45:35,710::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='bebd6a96-d3da-419c-8905-b5eec55c4505', options=None)
>CP Server Thread-24::DEBUG::2012-03-26 15:45:35,710::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.bebd6a96-d3da-419c-8905-b5eec55c4505`ReqID=`b5342eb5-d854-468f-a289-f2cf8aeb82a9`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '1882' at 'getStoragePoolInfo'
>CP Server Thread-24::DEBUG::2012-03-26 15:45:35,710::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505' for lock type 'shared'
>CP Server Thread-24::DEBUG::2012-03-26 15:45:35,711::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505' is free. Now locking as 'shared' (1 active user)
>CP Server Thread-24::DEBUG::2012-03-26 15:45:35,711::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.bebd6a96-d3da-419c-8905-b5eec55c4505`ReqID=`b5342eb5-d854-468f-a289-f2cf8aeb82a9`::Granted request
>CP Server Thread-24::DEBUG::2012-03-26 15:45:35,711::task::819::TaskManager.Task::(resourceAcquired) Task=`cd302a00-5d53-43a2-aecf-8acc8a10f439`::_resourcesAcquired: Storage.bebd6a96-d3da-419c-8905-b5eec55c4505 (shared)
>CP Server Thread-24::DEBUG::2012-03-26 15:45:35,711::task::980::TaskManager.Task::(_decref) Task=`cd302a00-5d53-43a2-aecf-8acc8a10f439`::ref 1 aborting False
>CP Server Thread-24::INFO::2012-03-26 15:45:35,712::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': -1, 'master_uuid': '1be32ac7-1e12-4823-8e8c-8c887333fe37', 'name': 'Local storage pooln', 'version': '0', 'domains': '1be32ac7-1e12-4823-8e8c-8c887333fe37:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'LOCALFS', 'master_ver': 0, 'lver': -1}, 'dominfo': {'1be32ac7-1e12-4823-8e8c-8c887333fe37': {'status': 'Active', 'diskfree': '8778391552', 'alerts': [], 'disktotal': '15670194176'}}}
>CP Server Thread-24::DEBUG::2012-03-26 15:45:35,712::task::1174::TaskManager.Task::(prepare) Task=`cd302a00-5d53-43a2-aecf-8acc8a10f439`::finished: {'info': {'spm_id': -1, 'master_uuid': '1be32ac7-1e12-4823-8e8c-8c887333fe37', 'name': 'Local storage pooln', 'version': '0', 'domains': '1be32ac7-1e12-4823-8e8c-8c887333fe37:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'LOCALFS', 'master_ver': 0, 'lver': -1}, 'dominfo': {'1be32ac7-1e12-4823-8e8c-8c887333fe37': {'status': 'Active', 'diskfree': '8778391552', 'alerts': [], 'disktotal': '15670194176'}}}
>CP Server Thread-24::DEBUG::2012-03-26 15:45:35,712::task::588::TaskManager.Task::(_updateState) Task=`cd302a00-5d53-43a2-aecf-8acc8a10f439`::moving from state preparing -> state finished
>CP Server Thread-24::DEBUG::2012-03-26 15:45:35,713::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505': < ResourceRef 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505', isValid: 'True' obj: 'None'>}
>CP Server Thread-24::DEBUG::2012-03-26 15:45:35,713::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>CP Server Thread-24::DEBUG::2012-03-26 15:45:35,713::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505'
>CP Server Thread-24::DEBUG::2012-03-26 15:45:35,713::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505' (0 active users)
>CP Server Thread-24::DEBUG::2012-03-26 15:45:35,713::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505' is free, finding out if anyone is waiting for it.
>CP Server Thread-24::DEBUG::2012-03-26 15:45:35,713::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505', Clearing records.
>CP Server Thread-24::DEBUG::2012-03-26 15:45:35,714::task::980::TaskManager.Task::(_decref) Task=`cd302a00-5d53-43a2-aecf-8acc8a10f439`::ref 0 aborting False
>CP Server Thread-24::ERROR::2012-03-26 15:45:35,714::Controller::780::vds::(index) AGLITKE: data = {'info': {'name': 'Local storage pooln', 'isoprefix': '', 'pool_status': 'connected', 'lver': -1, 'domains': '1be32ac7-1e12-4823-8e8c-8c887333fe37:Active', 'master_uuid': '1be32ac7-1e12-4823-8e8c-8c887333fe37', 'version': '0', 'spm_id': -1, 'type': 'LOCALFS', 'master_ver': 0}, 'spUUID': 'bebd6a96-d3da-419c-8905-b5eec55c4505', 'dominfo': {'1be32ac7-1e12-4823-8e8c-8c887333fe37': {'status': 'Active', 'diskfree': '8778391552', 'alerts': [], 'disktotal': '15670194176'}}}
>CP Server Thread-24::INFO::2012-03-26 15:45:35,715::_cplogging::262::cherrypy.access.23486224::(access) 127.0.0.1 - - [26/Mar/2012:15:45:35] "GET /vdsm-api/storagepools/bebd6a96-d3da-419c-8905-b5eec55c4505/ HTTP/1.1" 200 650 "" "Python-urllib/2.7"
>CP Server Thread-25::DEBUG::2012-03-26 15:45:35,717::task::588::TaskManager.Task::(_updateState) Task=`72dac6eb-56a5-4b82-9b22-158446816de0`::moving from state init -> state preparing
>CP Server Thread-25::INFO::2012-03-26 15:45:35,718::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='bebd6a96-d3da-419c-8905-b5eec55c4505', options=None)
>CP Server Thread-25::DEBUG::2012-03-26 15:45:35,718::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.bebd6a96-d3da-419c-8905-b5eec55c4505`ReqID=`8b679867-ddb6-4038-ab72-5a12fcdb2285`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '1882' at 'getStoragePoolInfo'
>CP Server Thread-25::DEBUG::2012-03-26 15:45:35,718::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505' for lock type 'shared'
>CP Server Thread-25::DEBUG::2012-03-26 15:45:35,719::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505' is free. Now locking as 'shared' (1 active user)
>CP Server Thread-25::DEBUG::2012-03-26 15:45:35,719::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.bebd6a96-d3da-419c-8905-b5eec55c4505`ReqID=`8b679867-ddb6-4038-ab72-5a12fcdb2285`::Granted request
>CP Server Thread-25::DEBUG::2012-03-26 15:45:35,720::task::819::TaskManager.Task::(resourceAcquired) Task=`72dac6eb-56a5-4b82-9b22-158446816de0`::_resourcesAcquired: Storage.bebd6a96-d3da-419c-8905-b5eec55c4505 (shared)
>CP Server Thread-25::DEBUG::2012-03-26 15:45:35,720::task::980::TaskManager.Task::(_decref) Task=`72dac6eb-56a5-4b82-9b22-158446816de0`::ref 1 aborting False
>CP Server Thread-25::INFO::2012-03-26 15:45:35,721::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': -1, 'master_uuid': '1be32ac7-1e12-4823-8e8c-8c887333fe37', 'name': 'Local storage pooln', 'version': '0', 'domains': '1be32ac7-1e12-4823-8e8c-8c887333fe37:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'LOCALFS', 'master_ver': 0, 'lver': -1}, 'dominfo': {'1be32ac7-1e12-4823-8e8c-8c887333fe37': {'status': 'Active', 'diskfree': '8778391552', 'alerts': [], 'disktotal': '15670194176'}}}
>CP Server Thread-25::DEBUG::2012-03-26 15:45:35,721::task::1174::TaskManager.Task::(prepare) Task=`72dac6eb-56a5-4b82-9b22-158446816de0`::finished: {'info': {'spm_id': -1, 'master_uuid': '1be32ac7-1e12-4823-8e8c-8c887333fe37', 'name': 'Local storage pooln', 'version': '0', 'domains': '1be32ac7-1e12-4823-8e8c-8c887333fe37:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'LOCALFS', 'master_ver': 0, 'lver': -1}, 'dominfo': {'1be32ac7-1e12-4823-8e8c-8c887333fe37': {'status': 'Active', 'diskfree': '8778391552', 'alerts': [], 'disktotal': '15670194176'}}}
>CP Server Thread-25::DEBUG::2012-03-26 15:45:35,721::task::588::TaskManager.Task::(_updateState) Task=`72dac6eb-56a5-4b82-9b22-158446816de0`::moving from state preparing -> state finished
>CP Server Thread-25::DEBUG::2012-03-26 15:45:35,721::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505': < ResourceRef 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505', isValid: 'True' obj: 'None'>}
>CP Server Thread-25::DEBUG::2012-03-26 15:45:35,722::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>CP Server Thread-25::DEBUG::2012-03-26 15:45:35,722::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505'
>CP Server Thread-25::DEBUG::2012-03-26 15:45:35,722::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505' (0 active users)
>CP Server Thread-25::DEBUG::2012-03-26 15:45:35,722::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505' is free, finding out if anyone is waiting for it.
>CP Server Thread-25::DEBUG::2012-03-26 15:45:35,723::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505', Clearing records.
>CP Server Thread-25::DEBUG::2012-03-26 15:45:35,723::task::980::TaskManager.Task::(_decref) Task=`72dac6eb-56a5-4b82-9b22-158446816de0`::ref 0 aborting False
>CP Server Thread-25::DEBUG::2012-03-26 15:45:35,724::task::588::TaskManager.Task::(_updateState) Task=`18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d`::moving from state init -> state preparing
>CP Server Thread-25::INFO::2012-03-26 15:45:35,724::logUtils::37::dispatcher::(wrapper) Run and protect: spmStart(spUUID='bebd6a96-d3da-419c-8905-b5eec55c4505', prevID=-1, prevLVER=-1, recoveryMode=None, scsiFencing=0, maxHostID=250, domVersion=None, options=None)
>CP Server Thread-25::DEBUG::2012-03-26 15:45:35,725::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.bebd6a96-d3da-419c-8905-b5eec55c4505`ReqID=`8013770a-4cf6-45ab-8115-459ab508ecde`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '408' at 'spmStart'
>CP Server Thread-25::DEBUG::2012-03-26 15:45:35,725::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505' for lock type 'exclusive'
>CP Server Thread-25::DEBUG::2012-03-26 15:45:35,726::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505' is free. Now locking as 'exclusive' (1 active user)
>CP Server Thread-25::DEBUG::2012-03-26 15:45:35,726::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.bebd6a96-d3da-419c-8905-b5eec55c4505`ReqID=`8013770a-4cf6-45ab-8115-459ab508ecde`::Granted request
>CP Server Thread-25::DEBUG::2012-03-26 15:45:35,726::task::819::TaskManager.Task::(resourceAcquired) Task=`18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d`::_resourcesAcquired: Storage.bebd6a96-d3da-419c-8905-b5eec55c4505 (exclusive)
>CP Server Thread-25::DEBUG::2012-03-26 15:45:35,726::task::980::TaskManager.Task::(_decref) Task=`18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d`::ref 1 aborting False
>CP Server Thread-25::INFO::2012-03-26 15:45:35,727::logUtils::39::dispatcher::(wrapper) Run and protect: spmStart, Return response: None
>CP Server Thread-25::DEBUG::2012-03-26 15:45:35,727::task::1169::TaskManager.Task::(prepare) Task=`18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d`::Prepare: 1 jobs exist, move to acquiring
>CP Server Thread-25::DEBUG::2012-03-26 15:45:35,727::task::588::TaskManager.Task::(_updateState) Task=`18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d`::moving from state preparing -> state acquiring
>CP Server Thread-25::DEBUG::2012-03-26 15:45:35,727::task::588::TaskManager.Task::(_updateState) Task=`18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d`::moving from state acquiring -> state queued
>CP Server Thread-25::DEBUG::2012-03-26 15:45:35,727::taskManager::48::TaskManager::(_queueTask) queueing task: 18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d
>CP Server Thread-25::DEBUG::2012-03-26 15:45:35,727::taskManager::54::TaskManager::(_queueTask) task queued: 18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d
>Thread-8::DEBUG::2012-03-26 15:45:35,728::threadPool::67::Misc.ThreadPool::(setRunningTask) Number of running tasks: 1
>CP Server Thread-25::DEBUG::2012-03-26 15:45:35,728::task::1171::TaskManager.Task::(prepare) Task=`18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d`::returning
>18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d::DEBUG::2012-03-26 15:45:35,728::threadPool::212::Misc.ThreadPool.WorkerThread::(run) Task: 18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d running: <bound method Task.commit of <storage.task.Task instance at 0x7fe4f0081f38>> with: None
>CP Server Thread-25::DEBUG::2012-03-26 15:45:35,729::task::980::TaskManager.Task::(_decref) Task=`18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d`::ref 0 aborting False
>18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d::DEBUG::2012-03-26 15:45:35,729::task::1183::TaskManager.Task::(commit) Task=`18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d`::Commiting task: 18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d
>CP Server Thread-25::DEBUG::2012-03-26 15:45:35,730::task::588::TaskManager.Task::(_updateState) Task=`dda46ae6-8d65-4501-8964-9df29913de8f`::moving from state init -> state preparing
>18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d::DEBUG::2012-03-26 15:45:35,730::task::588::TaskManager.Task::(_updateState) Task=`18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d`::moving from state queued -> state running
>CP Server Thread-25::INFO::2012-03-26 15:45:35,731::logUtils::37::dispatcher::(wrapper) Run and protect: getTaskInfo(taskID='18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d', spUUID=None, options=None)
>18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d::DEBUG::2012-03-26 15:45:35,731::task::894::TaskManager.Task::(_runJobs) Task=`18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d`::Task.run: running job 0: spmStart: <bound method StoragePool.startSpm of <storage.sp.StoragePool object at 0x7fe4c4085b50>> (args: (-1, -1, 0, 250, None) kwargs: {})
>CP Server Thread-25::DEBUG::2012-03-26 15:45:35,731::taskManager::172::TaskManager::(getTaskInfo) Entry. taskID: 18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d
>18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d::DEBUG::2012-03-26 15:45:35,732::task::317::TaskManager.Task::(run) Task=`18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d`::Job.run: running spmStart: <bound method StoragePool.startSpm of <storage.sp.StoragePool object at 0x7fe4c4085b50>> (args: (-1, -1, 0, 250, None) kwargs: {}) callback None
>CP Server Thread-25::DEBUG::2012-03-26 15:45:35,732::taskManager::175::TaskManager::(getTaskInfo) Return. Response: {'verb': 'spmStart', 'id': '18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d'}
>18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d::DEBUG::2012-03-26 15:45:35,732::misc::1017::SamplingMethod::(__call__) Trying to enter sampling method (storage.sp.updateMonitoringThreads)
>CP Server Thread-25::INFO::2012-03-26 15:45:35,733::logUtils::39::dispatcher::(wrapper) Run and protect: getTaskInfo, Return response: {'TaskInfo': {'verb': 'spmStart', 'id': '18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d'}}
>18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d::DEBUG::2012-03-26 15:45:35,733::misc::1019::SamplingMethod::(__call__) Got in to sampling method
>CP Server Thread-25::DEBUG::2012-03-26 15:45:35,733::task::1174::TaskManager.Task::(prepare) Task=`dda46ae6-8d65-4501-8964-9df29913de8f`::finished: {'TaskInfo': {'verb': 'spmStart', 'id': '18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d'}}
>CP Server Thread-25::DEBUG::2012-03-26 15:45:35,734::task::588::TaskManager.Task::(_updateState) Task=`dda46ae6-8d65-4501-8964-9df29913de8f`::moving from state preparing -> state finished
>CP Server Thread-25::DEBUG::2012-03-26 15:45:35,735::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>CP Server Thread-25::DEBUG::2012-03-26 15:45:35,735::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>CP Server Thread-25::DEBUG::2012-03-26 15:45:35,735::task::980::TaskManager.Task::(_decref) Task=`dda46ae6-8d65-4501-8964-9df29913de8f`::ref 0 aborting False
>18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d::DEBUG::2012-03-26 15:45:35,736::persistentDict::216::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=Test Domain', 'IOOPTIMEOUTSEC=1', 'LEASERETRIES=3', 'LEASETIMESEC=30', 'LOCKPOLICY=ON', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=0', 'POOL_DESCRIPTION=Local storage pooln', 'POOL_DOMAINS=1be32ac7-1e12-4823-8e8c-8c887333fe37:Active', 'POOL_SPM_ID=-1', 'POOL_SPM_LVER=-1', 'POOL_UUID=bebd6a96-d3da-419c-8905-b5eec55c4505', 'REMOTE_PATH=/var/lib/vdsm/bugstoragsomedomain4', 'ROLE=Master', 'SDUUID=1be32ac7-1e12-4823-8e8c-8c887333fe37', 'TYPE=LOCALFS', 'VERSION=0', '_SHA_CKSUM=7a33be6c0caad1af294e95d0b51d5d813708ef56']
>CP Server Thread-25::DEBUG::2012-03-26 15:45:35,736::task::588::TaskManager.Task::(_updateState) Task=`0b4d8e4a-7c8c-49cb-8573-b450bb19e931`::moving from state init -> state preparing
>18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d::DEBUG::2012-03-26 15:45:35,737::misc::1027::SamplingMethod::(__call__) Returning last result
>CP Server Thread-25::INFO::2012-03-26 15:45:35,737::logUtils::37::dispatcher::(wrapper) Run and protect: getTaskStatus(taskID='18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d', spUUID=None, options=None)
>CP Server Thread-25::DEBUG::2012-03-26 15:45:35,738::taskManager::93::TaskManager::(getTaskStatus) Entry. taskID: 18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d
>CP Server Thread-25::DEBUG::2012-03-26 15:45:35,739::taskManager::96::TaskManager::(getTaskStatus) Return. Response: {'code': 0, 'message': 'Task is initializing', 'taskState': 'running', 'taskResult': '', 'taskID': '18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d'}
>18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d::DEBUG::2012-03-26 15:45:35,739::persistentDict::216::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=Test Domain', 'IOOPTIMEOUTSEC=1', 'LEASERETRIES=3', 'LEASETIMESEC=30', 'LOCKPOLICY=ON', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=0', 'POOL_DESCRIPTION=Local storage pooln', 'POOL_DOMAINS=1be32ac7-1e12-4823-8e8c-8c887333fe37:Active', 'POOL_SPM_ID=-1', 'POOL_SPM_LVER=-1', 'POOL_UUID=bebd6a96-d3da-419c-8905-b5eec55c4505', 'REMOTE_PATH=/var/lib/vdsm/bugstoragsomedomain4', 'ROLE=Master', 'SDUUID=1be32ac7-1e12-4823-8e8c-8c887333fe37', 'TYPE=LOCALFS', 'VERSION=0', '_SHA_CKSUM=7a33be6c0caad1af294e95d0b51d5d813708ef56']
>18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d::DEBUG::2012-03-26 15:45:35,740::safelease::85::ClusterLock::(acquire) Acquiring cluster lock for domain 1be32ac7-1e12-4823-8e8c-8c887333fe37
>CP Server Thread-25::INFO::2012-03-26 15:45:35,740::logUtils::39::dispatcher::(wrapper) Run and protect: getTaskStatus, Return response: {'taskStatus': {'code': 0, 'message': 'Task is initializing', 'taskState': 'running', 'taskResult': '', 'taskID': '18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d'}}
>18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d::DEBUG::2012-03-26 15:45:35,741::safelease::94::Storage.Misc.excCmd::(acquire) '/usr/bin/sudo -n /usr/bin/setsid /usr/bin/ionice -c1 -n0 /bin/su vdsm -s /bin/sh -c "/usr/libexec/vdsm/spmprotect.sh start 1be32ac7-1e12-4823-8e8c-8c887333fe37 1 5 /rhev/data-center/mnt/_var_lib_vdsm_bugstoragsomedomain4/1be32ac7-1e12-4823-8e8c-8c887333fe37/dom_md/leases 30000 1000 3"' (cwd /usr/libexec/vdsm)
>CP Server Thread-25::DEBUG::2012-03-26 15:45:35,741::task::1174::TaskManager.Task::(prepare) Task=`0b4d8e4a-7c8c-49cb-8573-b450bb19e931`::finished: {'taskStatus': {'code': 0, 'message': 'Task is initializing', 'taskState': 'running', 'taskResult': '', 'taskID': '18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d'}}
>CP Server Thread-25::DEBUG::2012-03-26 15:45:35,742::task::588::TaskManager.Task::(_updateState) Task=`0b4d8e4a-7c8c-49cb-8573-b450bb19e931`::moving from state preparing -> state finished
>CP Server Thread-25::DEBUG::2012-03-26 15:45:35,748::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>CP Server Thread-25::DEBUG::2012-03-26 15:45:35,749::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>CP Server Thread-25::DEBUG::2012-03-26 15:45:35,750::task::980::TaskManager.Task::(_decref) Task=`0b4d8e4a-7c8c-49cb-8573-b450bb19e931`::ref 0 aborting False
>CP Server Thread-25::INFO::2012-03-26 15:45:35,760::_cplogging::262::cherrypy.access.23486224::(access) 127.0.0.1 - - [26/Mar/2012:15:45:35] "POST /vdsm-api/storagepools/bebd6a96-d3da-419c-8905-b5eec55c4505/spmstart HTTP/1.1" 202 268 "" "Python-urllib/2.7"
>CP Server Thread-16::DEBUG::2012-03-26 15:45:35,763::task::588::TaskManager.Task::(_updateState) Task=`1f050a5b-8b84-4227-9a6f-fb7c23c33ca3`::moving from state init -> state preparing
>CP Server Thread-16::INFO::2012-03-26 15:45:35,763::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='bebd6a96-d3da-419c-8905-b5eec55c4505', options=None)
>CP Server Thread-16::DEBUG::2012-03-26 15:45:35,764::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.bebd6a96-d3da-419c-8905-b5eec55c4505`ReqID=`daccb416-c3fa-4226-8154-3cdf5122baef`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '1882' at 'getStoragePoolInfo'
>CP Server Thread-16::DEBUG::2012-03-26 15:45:35,764::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505' for lock type 'shared'
>CP Server Thread-16::DEBUG::2012-03-26 15:45:35,768::resourceManager::510::ResourceManager::(registerResource) Resource 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505' is currently locked, Entering queue (1 in queue)
>18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d::DEBUG::2012-03-26 15:45:37,823::safelease::94::Storage.Misc.excCmd::(acquire) SUCCESS: <err> = ''; <rc> = 0
>18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d::DEBUG::2012-03-26 15:45:37,824::safelease::98::ClusterLock::(acquire) Clustered lock acquired successfully
>18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d::DEBUG::2012-03-26 15:45:37,824::sp::259::Storage.StoragePool::(startSpm) spm lock acquired successfully
>18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d::DEBUG::2012-03-26 15:45:37,826::persistentDict::216::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=Test Domain', 'IOOPTIMEOUTSEC=1', 'LEASERETRIES=3', 'LEASETIMESEC=30', 'LOCKPOLICY=ON', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=0', 'POOL_DESCRIPTION=Local storage pooln', 'POOL_DOMAINS=1be32ac7-1e12-4823-8e8c-8c887333fe37:Active', 'POOL_SPM_ID=-1', 'POOL_SPM_LVER=-1', 'POOL_UUID=bebd6a96-d3da-419c-8905-b5eec55c4505', 'REMOTE_PATH=/var/lib/vdsm/bugstoragsomedomain4', 'ROLE=Master', 'SDUUID=1be32ac7-1e12-4823-8e8c-8c887333fe37', 'TYPE=LOCALFS', 'VERSION=0', '_SHA_CKSUM=7a33be6c0caad1af294e95d0b51d5d813708ef56']
>18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d::DEBUG::2012-03-26 15:45:37,826::persistentDict::152::Storage.PersistentDict::(transaction) Starting transaction
>18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d::DEBUG::2012-03-26 15:45:37,827::persistentDict::158::Storage.PersistentDict::(transaction) Flushing changes
>18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d::DEBUG::2012-03-26 15:45:37,828::persistentDict::277::Storage.PersistentDict::(flush) about to write lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=Test Domain', 'IOOPTIMEOUTSEC=1', 'LEASERETRIES=3', 'LEASETIMESEC=30', 'LOCKPOLICY=ON', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=0', 'POOL_DESCRIPTION=Local storage pooln', 'POOL_DOMAINS=1be32ac7-1e12-4823-8e8c-8c887333fe37:Active', 'POOL_SPM_ID=1', 'POOL_SPM_LVER=0', 'POOL_UUID=bebd6a96-d3da-419c-8905-b5eec55c4505', 'REMOTE_PATH=/var/lib/vdsm/bugstoragsomedomain4', 'ROLE=Master', 'SDUUID=1be32ac7-1e12-4823-8e8c-8c887333fe37', 'TYPE=LOCALFS', 'VERSION=0', '_SHA_CKSUM=b40a20cc2d9342513f99a0a9f49dd8e852e32c01']
>18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d::DEBUG::2012-03-26 15:45:37,829::persistentDict::160::Storage.PersistentDict::(transaction) Finished transaction
>18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d::DEBUG::2012-03-26 15:45:37,830::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.upgrade_bebd6a96-d3da-419c-8905-b5eec55c4505`ReqID=`16ff0cc5-aaf3-4196-85bb-9c28564edf25`::Request was made in '/usr/share/vdsm/storage/sp.py' line '401' at '_upgradePool'
>18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d::DEBUG::2012-03-26 15:45:37,830::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.upgrade_bebd6a96-d3da-419c-8905-b5eec55c4505' for lock type 'exclusive'
>18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d::DEBUG::2012-03-26 15:45:37,830::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.upgrade_bebd6a96-d3da-419c-8905-b5eec55c4505' is free. Now locking as 'exclusive' (1 active user)
>18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d::DEBUG::2012-03-26 15:45:37,830::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.upgrade_bebd6a96-d3da-419c-8905-b5eec55c4505`ReqID=`16ff0cc5-aaf3-4196-85bb-9c28564edf25`::Granted request
>18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d::INFO::2012-03-26 15:45:37,831::sp::406::Storage.StoragePool::(_upgradePool) Trying to upgrade master domain `1be32ac7-1e12-4823-8e8c-8c887333fe37`
>18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d::DEBUG::2012-03-26 15:45:37,831::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37`ReqID=`02baa48b-cf5d-4e29-a623-2d561109975a`::Request was made in '/usr/share/vdsm/storage/sp.py' line '407' at '_upgradePool'
>18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d::DEBUG::2012-03-26 15:45:37,832::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37' for lock type 'exclusive'
>18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d::DEBUG::2012-03-26 15:45:37,832::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37' is free. Now locking as 'exclusive' (1 active user)
>18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d::DEBUG::2012-03-26 15:45:37,832::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37`ReqID=`02baa48b-cf5d-4e29-a623-2d561109975a`::Granted request
>18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d::DEBUG::2012-03-26 15:45:37,832::sd::373::Storage.StorageDomain::(upgrade) Trying to upgrade domain `1be32ac7-1e12-4823-8e8c-8c887333fe37` from version 0 to version 0
>18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d::DEBUG::2012-03-26 15:45:37,833::sd::379::Storage.StorageDomain::(upgrade) No need to upgrade domain `1be32ac7-1e12-4823-8e8c-8c887333fe37`, leaving unchanged
>18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d::DEBUG::2012-03-26 15:45:37,833::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37'
>18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d::DEBUG::2012-03-26 15:45:37,833::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37' (0 active users)
>18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d::DEBUG::2012-03-26 15:45:37,833::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37' is free, finding out if anyone is waiting for it.
>18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d::DEBUG::2012-03-26 15:45:37,834::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37', Clearing records.
>18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d::DEBUG::2012-03-26 15:45:37,834::sp::410::Storage.StoragePool::(_upgradePool) Marking all domains for upgrade
>18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d::DEBUG::2012-03-26 15:45:37,834::sp::417::Storage.StoragePool::(_upgradePool) Registering with state change event
>18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d::DEBUG::2012-03-26 15:45:37,834::sp::419::Storage.StoragePool::(_upgradePool) Running initial domain upgrade threads
>18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d::DEBUG::2012-03-26 15:45:37,834::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.upgrade_bebd6a96-d3da-419c-8905-b5eec55c4505'
>18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d::DEBUG::2012-03-26 15:45:37,835::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.upgrade_bebd6a96-d3da-419c-8905-b5eec55c4505' (0 active users)
>18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d::DEBUG::2012-03-26 15:45:37,835::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.upgrade_bebd6a96-d3da-419c-8905-b5eec55c4505' is free, finding out if anyone is waiting for it.
>18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d::DEBUG::2012-03-26 15:45:37,835::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.upgrade_bebd6a96-d3da-419c-8905-b5eec55c4505', Clearing records.
>18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d::WARNING::2012-03-26 15:45:37,836::sd::546::Storage.StorageDomain::(createMasterTree) vms dir not found, creating (/rhev/data-center/mnt/_var_lib_vdsm_bugstoragsomedomain4/1be32ac7-1e12-4823-8e8c-8c887333fe37/master/vms)
>18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d::WARNING::2012-03-26 15:45:37,836::sd::551::Storage.StorageDomain::(createMasterTree) tasks dir not found, creating (/rhev/data-center/mnt/_var_lib_vdsm_bugstoragsomedomain4/1be32ac7-1e12-4823-8e8c-8c887333fe37/master/tasks)
>18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d::DEBUG::2012-03-26 15:45:37,836::sp::308::Storage.StoragePool::(startSpm) ended.
>18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d::DEBUG::2012-03-26 15:45:37,837::task::588::TaskManager.Task::(_updateState) Task=`18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d`::moving from state running -> state finished
>18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d::DEBUG::2012-03-26 15:45:37,837::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505': < ResourceRef 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505', isValid: 'True' obj: 'None'>}
>18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d::DEBUG::2012-03-26 15:45:37,837::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d::DEBUG::2012-03-26 15:45:37,837::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505'
>18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d::DEBUG::2012-03-26 15:45:37,838::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505' (0 active users)
>18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d::DEBUG::2012-03-26 15:45:37,838::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505' is free, finding out if anyone is waiting for it.
>18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d::DEBUG::2012-03-26 15:45:37,838::resourceManager::568::ResourceManager::(releaseResource) Resource 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505' has 1 requests in queue. Handling top request.
>18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d::DEBUG::2012-03-26 15:45:37,838::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.bebd6a96-d3da-419c-8905-b5eec55c4505`ReqID=`daccb416-c3fa-4226-8154-3cdf5122baef`::Granted request
>18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d::DEBUG::2012-03-26 15:45:37,838::resourceManager::589::ResourceManager::(releaseResource) Request 'Request for Storage.bebd6a96-d3da-419c-8905-b5eec55c4505 - shared: granted' was granted
>18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d::DEBUG::2012-03-26 15:45:37,839::resourceManager::597::ResourceManager::(releaseResource) This is a shared lock. Granting all shared requests
>18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d::DEBUG::2012-03-26 15:45:37,839::task::902::TaskManager.Task::(_runJobs) Task=`18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d`::Task.run: exit - success: result 
>CP Server Thread-16::DEBUG::2012-03-26 15:45:37,839::task::819::TaskManager.Task::(resourceAcquired) Task=`1f050a5b-8b84-4227-9a6f-fb7c23c33ca3`::_resourcesAcquired: Storage.bebd6a96-d3da-419c-8905-b5eec55c4505 (shared)
>18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d::DEBUG::2012-03-26 15:45:37,839::task::980::TaskManager.Task::(_decref) Task=`18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d`::ref 0 aborting False
>CP Server Thread-16::DEBUG::2012-03-26 15:45:37,840::task::980::TaskManager.Task::(_decref) Task=`1f050a5b-8b84-4227-9a6f-fb7c23c33ca3`::ref 1 aborting False
>18f1b6b9-fcd7-4e1c-8bb2-0c86f0dac74d::DEBUG::2012-03-26 15:45:37,840::threadPool::67::Misc.ThreadPool::(setRunningTask) Number of running tasks: 0
>CP Server Thread-16::INFO::2012-03-26 15:45:37,841::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': '1be32ac7-1e12-4823-8e8c-8c887333fe37', 'name': 'Local storage pooln', 'version': '0', 'domains': '1be32ac7-1e12-4823-8e8c-8c887333fe37:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'LOCALFS', 'master_ver': 0, 'lver': 0}, 'dominfo': {'1be32ac7-1e12-4823-8e8c-8c887333fe37': {'status': 'Active', 'diskfree': '8778391552', 'alerts': [], 'disktotal': '15670194176'}}}
>CP Server Thread-16::DEBUG::2012-03-26 15:45:37,842::task::1174::TaskManager.Task::(prepare) Task=`1f050a5b-8b84-4227-9a6f-fb7c23c33ca3`::finished: {'info': {'spm_id': 1, 'master_uuid': '1be32ac7-1e12-4823-8e8c-8c887333fe37', 'name': 'Local storage pooln', 'version': '0', 'domains': '1be32ac7-1e12-4823-8e8c-8c887333fe37:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'LOCALFS', 'master_ver': 0, 'lver': 0}, 'dominfo': {'1be32ac7-1e12-4823-8e8c-8c887333fe37': {'status': 'Active', 'diskfree': '8778391552', 'alerts': [], 'disktotal': '15670194176'}}}
>CP Server Thread-16::DEBUG::2012-03-26 15:45:37,842::task::588::TaskManager.Task::(_updateState) Task=`1f050a5b-8b84-4227-9a6f-fb7c23c33ca3`::moving from state preparing -> state finished
>CP Server Thread-16::DEBUG::2012-03-26 15:45:37,843::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505': < ResourceRef 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505', isValid: 'True' obj: 'None'>}
>CP Server Thread-16::DEBUG::2012-03-26 15:45:37,843::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>CP Server Thread-16::DEBUG::2012-03-26 15:45:37,843::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505'
>CP Server Thread-16::DEBUG::2012-03-26 15:45:37,844::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505' (0 active users)
>CP Server Thread-16::DEBUG::2012-03-26 15:45:37,844::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505' is free, finding out if anyone is waiting for it.
>CP Server Thread-16::DEBUG::2012-03-26 15:45:37,844::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505', Clearing records.
>CP Server Thread-16::DEBUG::2012-03-26 15:45:37,845::task::980::TaskManager.Task::(_decref) Task=`1f050a5b-8b84-4227-9a6f-fb7c23c33ca3`::ref 0 aborting False
>CP Server Thread-16::ERROR::2012-03-26 15:45:37,845::Controller::780::vds::(index) AGLITKE: data = {'info': {'name': 'Local storage pooln', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '1be32ac7-1e12-4823-8e8c-8c887333fe37:Active', 'master_uuid': '1be32ac7-1e12-4823-8e8c-8c887333fe37', 'version': '0', 'spm_id': 1, 'type': 'LOCALFS', 'master_ver': 0}, 'spUUID': 'bebd6a96-d3da-419c-8905-b5eec55c4505', 'dominfo': {'1be32ac7-1e12-4823-8e8c-8c887333fe37': {'status': 'Active', 'diskfree': '8778391552', 'alerts': [], 'disktotal': '15670194176'}}}
>CP Server Thread-16::INFO::2012-03-26 15:45:37,846::_cplogging::262::cherrypy.access.23486224::(access) 127.0.0.1 - - [26/Mar/2012:15:45:37] "GET /vdsm-api/storagepools/bebd6a96-d3da-419c-8905-b5eec55c4505/ HTTP/1.1" 200 648 "" "Python-urllib/2.7"
>CP Server Thread-17::DEBUG::2012-03-26 15:45:37,849::task::588::TaskManager.Task::(_updateState) Task=`0d1fdc51-57a2-42d9-99b0-680150418678`::moving from state init -> state preparing
>CP Server Thread-17::INFO::2012-03-26 15:45:37,850::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='bebd6a96-d3da-419c-8905-b5eec55c4505', options=None)
>CP Server Thread-17::DEBUG::2012-03-26 15:45:37,850::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.bebd6a96-d3da-419c-8905-b5eec55c4505`ReqID=`9e191195-95d8-440a-97ed-f84976fdee75`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '1882' at 'getStoragePoolInfo'
>CP Server Thread-17::DEBUG::2012-03-26 15:45:37,850::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505' for lock type 'shared'
>CP Server Thread-17::DEBUG::2012-03-26 15:45:37,850::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505' is free. Now locking as 'shared' (1 active user)
>CP Server Thread-17::DEBUG::2012-03-26 15:45:37,851::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.bebd6a96-d3da-419c-8905-b5eec55c4505`ReqID=`9e191195-95d8-440a-97ed-f84976fdee75`::Granted request
>CP Server Thread-17::DEBUG::2012-03-26 15:45:37,851::task::819::TaskManager.Task::(resourceAcquired) Task=`0d1fdc51-57a2-42d9-99b0-680150418678`::_resourcesAcquired: Storage.bebd6a96-d3da-419c-8905-b5eec55c4505 (shared)
>CP Server Thread-17::DEBUG::2012-03-26 15:45:37,851::task::980::TaskManager.Task::(_decref) Task=`0d1fdc51-57a2-42d9-99b0-680150418678`::ref 1 aborting False
>CP Server Thread-17::INFO::2012-03-26 15:45:37,852::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': '1be32ac7-1e12-4823-8e8c-8c887333fe37', 'name': 'Local storage pooln', 'version': '0', 'domains': '1be32ac7-1e12-4823-8e8c-8c887333fe37:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'LOCALFS', 'master_ver': 0, 'lver': 0}, 'dominfo': {'1be32ac7-1e12-4823-8e8c-8c887333fe37': {'status': 'Active', 'diskfree': '8778391552', 'alerts': [], 'disktotal': '15670194176'}}}
>CP Server Thread-17::DEBUG::2012-03-26 15:45:37,852::task::1174::TaskManager.Task::(prepare) Task=`0d1fdc51-57a2-42d9-99b0-680150418678`::finished: {'info': {'spm_id': 1, 'master_uuid': '1be32ac7-1e12-4823-8e8c-8c887333fe37', 'name': 'Local storage pooln', 'version': '0', 'domains': '1be32ac7-1e12-4823-8e8c-8c887333fe37:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'LOCALFS', 'master_ver': 0, 'lver': 0}, 'dominfo': {'1be32ac7-1e12-4823-8e8c-8c887333fe37': {'status': 'Active', 'diskfree': '8778391552', 'alerts': [], 'disktotal': '15670194176'}}}
>CP Server Thread-17::DEBUG::2012-03-26 15:45:37,852::task::588::TaskManager.Task::(_updateState) Task=`0d1fdc51-57a2-42d9-99b0-680150418678`::moving from state preparing -> state finished
>CP Server Thread-17::DEBUG::2012-03-26 15:45:37,852::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505': < ResourceRef 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505', isValid: 'True' obj: 'None'>}
>CP Server Thread-17::DEBUG::2012-03-26 15:45:37,853::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>CP Server Thread-17::DEBUG::2012-03-26 15:45:37,853::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505'
>CP Server Thread-17::DEBUG::2012-03-26 15:45:37,853::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505' (0 active users)
>CP Server Thread-17::DEBUG::2012-03-26 15:45:37,853::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505' is free, finding out if anyone is waiting for it.
>CP Server Thread-17::DEBUG::2012-03-26 15:45:37,853::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505', Clearing records.
>CP Server Thread-17::DEBUG::2012-03-26 15:45:37,854::task::980::TaskManager.Task::(_decref) Task=`0d1fdc51-57a2-42d9-99b0-680150418678`::ref 0 aborting False
>CP Server Thread-17::ERROR::2012-03-26 15:45:37,854::Controller::780::vds::(index) AGLITKE: data = {'info': {'name': 'Local storage pooln', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': '1be32ac7-1e12-4823-8e8c-8c887333fe37:Active', 'master_uuid': '1be32ac7-1e12-4823-8e8c-8c887333fe37', 'version': '0', 'spm_id': 1, 'type': 'LOCALFS', 'master_ver': 0}, 'spUUID': 'bebd6a96-d3da-419c-8905-b5eec55c4505', 'dominfo': {'1be32ac7-1e12-4823-8e8c-8c887333fe37': {'status': 'Active', 'diskfree': '8778391552', 'alerts': [], 'disktotal': '15670194176'}}}
>CP Server Thread-17::INFO::2012-03-26 15:45:37,855::_cplogging::262::cherrypy.access.23486224::(access) 127.0.0.1 - - [26/Mar/2012:15:45:37] "GET /vdsm-api/storagepools/bebd6a96-d3da-419c-8905-b5eec55c4505/ HTTP/1.1" 200 648 "" "Python-urllib/2.7"
>CP Server Thread-18::DEBUG::2012-03-26 15:45:37,857::task::588::TaskManager.Task::(_updateState) Task=`25b929ca-4190-45f5-abfc-3a111176552e`::moving from state init -> state preparing
>CP Server Thread-18::INFO::2012-03-26 15:45:37,858::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='bebd6a96-d3da-419c-8905-b5eec55c4505', options=None)
>CP Server Thread-18::DEBUG::2012-03-26 15:45:37,858::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.bebd6a96-d3da-419c-8905-b5eec55c4505`ReqID=`d57bdb8c-33d9-4d44-92a1-63a052f69945`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '1882' at 'getStoragePoolInfo'
>CP Server Thread-18::DEBUG::2012-03-26 15:45:37,859::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505' for lock type 'shared'
>CP Server Thread-18::DEBUG::2012-03-26 15:45:37,860::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505' is free. Now locking as 'shared' (1 active user)
>CP Server Thread-18::DEBUG::2012-03-26 15:45:37,860::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.bebd6a96-d3da-419c-8905-b5eec55c4505`ReqID=`d57bdb8c-33d9-4d44-92a1-63a052f69945`::Granted request
>CP Server Thread-18::DEBUG::2012-03-26 15:45:37,860::task::819::TaskManager.Task::(resourceAcquired) Task=`25b929ca-4190-45f5-abfc-3a111176552e`::_resourcesAcquired: Storage.bebd6a96-d3da-419c-8905-b5eec55c4505 (shared)
>CP Server Thread-18::DEBUG::2012-03-26 15:45:37,860::task::980::TaskManager.Task::(_decref) Task=`25b929ca-4190-45f5-abfc-3a111176552e`::ref 1 aborting False
>CP Server Thread-18::INFO::2012-03-26 15:45:37,861::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 1, 'master_uuid': '1be32ac7-1e12-4823-8e8c-8c887333fe37', 'name': 'Local storage pooln', 'version': '0', 'domains': '1be32ac7-1e12-4823-8e8c-8c887333fe37:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'LOCALFS', 'master_ver': 0, 'lver': 0}, 'dominfo': {'1be32ac7-1e12-4823-8e8c-8c887333fe37': {'status': 'Active', 'diskfree': '8778391552', 'alerts': [], 'disktotal': '15670194176'}}}
>CP Server Thread-18::DEBUG::2012-03-26 15:45:37,861::task::1174::TaskManager.Task::(prepare) Task=`25b929ca-4190-45f5-abfc-3a111176552e`::finished: {'info': {'spm_id': 1, 'master_uuid': '1be32ac7-1e12-4823-8e8c-8c887333fe37', 'name': 'Local storage pooln', 'version': '0', 'domains': '1be32ac7-1e12-4823-8e8c-8c887333fe37:Active', 'pool_status': 'connected', 'isoprefix': '', 'type': 'LOCALFS', 'master_ver': 0, 'lver': 0}, 'dominfo': {'1be32ac7-1e12-4823-8e8c-8c887333fe37': {'status': 'Active', 'diskfree': '8778391552', 'alerts': [], 'disktotal': '15670194176'}}}
>CP Server Thread-18::DEBUG::2012-03-26 15:45:37,862::task::588::TaskManager.Task::(_updateState) Task=`25b929ca-4190-45f5-abfc-3a111176552e`::moving from state preparing -> state finished
>CP Server Thread-18::DEBUG::2012-03-26 15:45:37,862::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505': < ResourceRef 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505', isValid: 'True' obj: 'None'>}
>CP Server Thread-18::DEBUG::2012-03-26 15:45:37,862::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>CP Server Thread-18::DEBUG::2012-03-26 15:45:37,863::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505'
>CP Server Thread-18::DEBUG::2012-03-26 15:45:37,863::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505' (0 active users)
>CP Server Thread-18::DEBUG::2012-03-26 15:45:37,863::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505' is free, finding out if anyone is waiting for it.
>CP Server Thread-18::DEBUG::2012-03-26 15:45:37,863::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505', Clearing records.
>CP Server Thread-18::DEBUG::2012-03-26 15:45:37,864::task::980::TaskManager.Task::(_decref) Task=`25b929ca-4190-45f5-abfc-3a111176552e`::ref 0 aborting False
>CP Server Thread-18::DEBUG::2012-03-26 15:45:37,864::task::588::TaskManager.Task::(_updateState) Task=`4ee4ce88-b7f3-496a-b3d0-0c1e6f4cf1e0`::moving from state init -> state preparing
>CP Server Thread-18::INFO::2012-03-26 15:45:37,864::logUtils::37::dispatcher::(wrapper) Run and protect: destroyStoragePool(spUUID='bebd6a96-d3da-419c-8905-b5eec55c4505', hostID=1, scsiKey='scsikey', options=None)
>CP Server Thread-18::INFO::2012-03-26 15:45:37,865::hsm::828::Storage.HSM::(destroyStoragePool) spUUID=bebd6a96-d3da-419c-8905-b5eec55c4505
>CP Server Thread-18::DEBUG::2012-03-26 15:45:37,865::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.bebd6a96-d3da-419c-8905-b5eec55c4505`ReqID=`03e260e9-b881-4031-ac29-ff15c0f2cbf6`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '834' at 'destroyStoragePool'
>CP Server Thread-18::DEBUG::2012-03-26 15:45:37,865::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505' for lock type 'exclusive'
>CP Server Thread-18::DEBUG::2012-03-26 15:45:37,865::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505' is free. Now locking as 'exclusive' (1 active user)
>CP Server Thread-18::DEBUG::2012-03-26 15:45:37,866::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.bebd6a96-d3da-419c-8905-b5eec55c4505`ReqID=`03e260e9-b881-4031-ac29-ff15c0f2cbf6`::Granted request
>CP Server Thread-18::DEBUG::2012-03-26 15:45:37,866::task::819::TaskManager.Task::(resourceAcquired) Task=`4ee4ce88-b7f3-496a-b3d0-0c1e6f4cf1e0`::_resourcesAcquired: Storage.bebd6a96-d3da-419c-8905-b5eec55c4505 (exclusive)
>CP Server Thread-18::DEBUG::2012-03-26 15:45:37,866::task::980::TaskManager.Task::(_decref) Task=`4ee4ce88-b7f3-496a-b3d0-0c1e6f4cf1e0`::ref 1 aborting False
>CP Server Thread-18::DEBUG::2012-03-26 15:45:37,866::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37`ReqID=`3aa2cc87-8f89-480d-921f-9a24fc99da53`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '838' at 'destroyStoragePool'
>CP Server Thread-18::DEBUG::2012-03-26 15:45:37,867::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37' for lock type 'exclusive'
>CP Server Thread-18::DEBUG::2012-03-26 15:45:37,867::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37' is free. Now locking as 'exclusive' (1 active user)
>CP Server Thread-18::DEBUG::2012-03-26 15:45:37,867::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37`ReqID=`3aa2cc87-8f89-480d-921f-9a24fc99da53`::Granted request
>CP Server Thread-18::DEBUG::2012-03-26 15:45:37,867::task::819::TaskManager.Task::(resourceAcquired) Task=`4ee4ce88-b7f3-496a-b3d0-0c1e6f4cf1e0`::_resourcesAcquired: Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37 (exclusive)
>CP Server Thread-18::DEBUG::2012-03-26 15:45:37,868::task::980::TaskManager.Task::(_decref) Task=`4ee4ce88-b7f3-496a-b3d0-0c1e6f4cf1e0`::ref 1 aborting False
>CP Server Thread-18::DEBUG::2012-03-26 15:45:37,868::sp::318::Storage.StoragePool::(_shutDownUpgrade) Shutting down upgrade process
>CP Server Thread-18::DEBUG::2012-03-26 15:45:37,868::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.upgrade_bebd6a96-d3da-419c-8905-b5eec55c4505`ReqID=`17377153-df3e-4fd0-955c-2df374b9e18b`::Request was made in '/usr/share/vdsm/storage/sp.py' line '319' at '_shutDownUpgrade'
>CP Server Thread-18::DEBUG::2012-03-26 15:45:37,868::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.upgrade_bebd6a96-d3da-419c-8905-b5eec55c4505' for lock type 'exclusive'
>CP Server Thread-18::DEBUG::2012-03-26 15:45:37,868::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.upgrade_bebd6a96-d3da-419c-8905-b5eec55c4505' is free. Now locking as 'exclusive' (1 active user)
>CP Server Thread-18::DEBUG::2012-03-26 15:45:37,869::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.upgrade_bebd6a96-d3da-419c-8905-b5eec55c4505`ReqID=`17377153-df3e-4fd0-955c-2df374b9e18b`::Granted request
>CP Server Thread-18::DEBUG::2012-03-26 15:45:37,869::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.upgrade_bebd6a96-d3da-419c-8905-b5eec55c4505'
>CP Server Thread-18::DEBUG::2012-03-26 15:45:37,869::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.upgrade_bebd6a96-d3da-419c-8905-b5eec55c4505' (0 active users)
>CP Server Thread-18::DEBUG::2012-03-26 15:45:37,869::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.upgrade_bebd6a96-d3da-419c-8905-b5eec55c4505' is free, finding out if anyone is waiting for it.
>CP Server Thread-18::DEBUG::2012-03-26 15:45:37,869::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.upgrade_bebd6a96-d3da-419c-8905-b5eec55c4505', Clearing records.
>CP Server Thread-18::INFO::2012-03-26 15:45:37,870::safelease::116::ClusterLock::(release) Releasing cluster lock for domain 1be32ac7-1e12-4823-8e8c-8c887333fe37
>CP Server Thread-18::DEBUG::2012-03-26 15:45:37,870::safelease::117::Storage.Misc.excCmd::(release) '/usr/libexec/vdsm/spmstop.sh 1be32ac7-1e12-4823-8e8c-8c887333fe37' (cwd /usr/libexec/vdsm)
>CP Server Thread-18::DEBUG::2012-03-26 15:45:38,904::safelease::117::Storage.Misc.excCmd::(release) SUCCESS: <err> = ''; <rc> = 0
>CP Server Thread-18::DEBUG::2012-03-26 15:45:38,905::safelease::120::ClusterLock::(release) Cluster lock released successfully
>CP Server Thread-18::INFO::2012-03-26 15:45:38,905::sp::976::Storage.StoragePool::(detachSD) sdUUID=1be32ac7-1e12-4823-8e8c-8c887333fe37 spUUID=bebd6a96-d3da-419c-8905-b5eec55c4505 msdUUID=00000000-0000-0000-0000-000000000000
>CP Server Thread-18::INFO::2012-03-26 15:45:38,906::sp::909::Storage.StoragePool::(masterMigrate) sdUUID=1be32ac7-1e12-4823-8e8c-8c887333fe37 spUUID=bebd6a96-d3da-419c-8905-b5eec55c4505 msdUUID=00000000-0000-0000-0000-000000000000
>CP Server Thread-18::ERROR::2012-03-26 15:45:38,906::sp::1008::Storage.StoragePool::(detachSD) Unexpected error
>Traceback (most recent call last):
>  File "/usr/share/vdsm/storage/sp.py", line 987, in detachSD
>    self.masterMigrate(sdUUID, msdUUID, masterVersion, __securityOverride=True)
>  File "/usr/share/vdsm/storage/securable.py", line 80, in wrapper
>    return f(*args, **kwargs)
>  File "/usr/share/vdsm/storage/sp.py", line 921, in masterMigrate
>    self.stopSpm(self.spUUID)
>  File "/usr/share/vdsm/storage/securable.py", line 78, in wrapper
>    raise SecureError()
>SecureError
>CP Server Thread-18::INFO::2012-03-26 15:45:38,907::sp::667::Storage.StoragePool::(disconnect) Disconnect from the storage pool bebd6a96-d3da-419c-8905-b5eec55c4505
>CP Server Thread-18::INFO::2012-03-26 15:45:38,908::logUtils::39::dispatcher::(wrapper) Run and protect: destroyStoragePool, Return response: True
>CP Server Thread-18::DEBUG::2012-03-26 15:45:38,909::task::1174::TaskManager.Task::(prepare) Task=`4ee4ce88-b7f3-496a-b3d0-0c1e6f4cf1e0`::finished: True
>CP Server Thread-18::DEBUG::2012-03-26 15:45:38,909::task::588::TaskManager.Task::(_updateState) Task=`4ee4ce88-b7f3-496a-b3d0-0c1e6f4cf1e0`::moving from state preparing -> state finished
>CP Server Thread-18::DEBUG::2012-03-26 15:45:38,910::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505': < ResourceRef 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505', isValid: 'True' obj: 'None'>, 'Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37': < ResourceRef 'Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37', isValid: 'True' obj: 'None'>}
>CP Server Thread-18::DEBUG::2012-03-26 15:45:38,910::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>CP Server Thread-18::DEBUG::2012-03-26 15:45:38,910::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505'
>CP Server Thread-18::DEBUG::2012-03-26 15:45:38,911::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505' (0 active users)
>CP Server Thread-18::DEBUG::2012-03-26 15:45:38,911::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505' is free, finding out if anyone is waiting for it.
>CP Server Thread-18::DEBUG::2012-03-26 15:45:38,911::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505', Clearing records.
>CP Server Thread-18::DEBUG::2012-03-26 15:45:38,912::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37'
>CP Server Thread-18::DEBUG::2012-03-26 15:45:38,912::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37' (0 active users)
>CP Server Thread-18::DEBUG::2012-03-26 15:45:38,913::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37' is free, finding out if anyone is waiting for it.
>CP Server Thread-18::DEBUG::2012-03-26 15:45:38,913::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37', Clearing records.
>CP Server Thread-18::DEBUG::2012-03-26 15:45:38,913::task::980::TaskManager.Task::(_decref) Task=`4ee4ce88-b7f3-496a-b3d0-0c1e6f4cf1e0`::ref 0 aborting False
>CP Server Thread-18::INFO::2012-03-26 15:45:38,914::_cplogging::262::cherrypy.access.23486224::(access) 127.0.0.1 - - [26/Mar/2012:15:45:38] "POST /vdsm-api/storagepools/bebd6a96-d3da-419c-8905-b5eec55c4505/destroy HTTP/1.1" 204 - "" "Python-urllib/2.7"
>CP Server Thread-19::DEBUG::2012-03-26 15:45:38,917::task::588::TaskManager.Task::(_updateState) Task=`9a3c0b15-b0f0-4d5f-9fe4-1df5e43492d1`::moving from state init -> state preparing
>CP Server Thread-19::INFO::2012-03-26 15:45:38,917::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='bebd6a96-d3da-419c-8905-b5eec55c4505', options=None)
>CP Server Thread-19::DEBUG::2012-03-26 15:45:38,917::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.bebd6a96-d3da-419c-8905-b5eec55c4505`ReqID=`a38eac65-2651-4de7-bfa6-35d28fc165d6`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '1882' at 'getStoragePoolInfo'
>CP Server Thread-19::DEBUG::2012-03-26 15:45:38,917::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505' for lock type 'shared'
>CP Server Thread-19::DEBUG::2012-03-26 15:45:38,918::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505' is free. Now locking as 'shared' (1 active user)
>CP Server Thread-19::DEBUG::2012-03-26 15:45:38,918::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.bebd6a96-d3da-419c-8905-b5eec55c4505`ReqID=`a38eac65-2651-4de7-bfa6-35d28fc165d6`::Granted request
>CP Server Thread-19::DEBUG::2012-03-26 15:45:38,918::task::819::TaskManager.Task::(resourceAcquired) Task=`9a3c0b15-b0f0-4d5f-9fe4-1df5e43492d1`::_resourcesAcquired: Storage.bebd6a96-d3da-419c-8905-b5eec55c4505 (shared)
>CP Server Thread-19::DEBUG::2012-03-26 15:45:38,918::task::980::TaskManager.Task::(_decref) Task=`9a3c0b15-b0f0-4d5f-9fe4-1df5e43492d1`::ref 1 aborting False
>CP Server Thread-19::ERROR::2012-03-26 15:45:38,919::task::855::TaskManager.Task::(_setError) Task=`9a3c0b15-b0f0-4d5f-9fe4-1df5e43492d1`::Unexpected error
>Traceback (most recent call last):
>  File "/usr/share/vdsm/storage/task.py", line 863, in _run
>    return fn(*args, **kargs)
>  File "/usr/share/vdsm/logUtils.py", line 38, in wrapper
>    res = f(*args, **kwargs)
>  File "/usr/share/vdsm/storage/hsm.py", line 1883, in getStoragePoolInfo
>    return self.getPool(spUUID).getInfo()
>  File "/usr/share/vdsm/storage/hsm.py", line 188, in getPool
>    raise se.StoragePoolUnknown(spUUID)
>StoragePoolUnknown: Unknown pool id, pool not connected: ('bebd6a96-d3da-419c-8905-b5eec55c4505',)
>CP Server Thread-19::DEBUG::2012-03-26 15:45:38,919::task::874::TaskManager.Task::(_run) Task=`9a3c0b15-b0f0-4d5f-9fe4-1df5e43492d1`::Task._run: 9a3c0b15-b0f0-4d5f-9fe4-1df5e43492d1 ('bebd6a96-d3da-419c-8905-b5eec55c4505',) {} failed - stopping task
>CP Server Thread-19::DEBUG::2012-03-26 15:45:38,919::task::1201::TaskManager.Task::(stop) Task=`9a3c0b15-b0f0-4d5f-9fe4-1df5e43492d1`::stopping in state preparing (force False)
>CP Server Thread-19::DEBUG::2012-03-26 15:45:38,919::task::980::TaskManager.Task::(_decref) Task=`9a3c0b15-b0f0-4d5f-9fe4-1df5e43492d1`::ref 1 aborting True
>CP Server Thread-19::INFO::2012-03-26 15:45:38,919::task::1159::TaskManager.Task::(prepare) Task=`9a3c0b15-b0f0-4d5f-9fe4-1df5e43492d1`::aborting: Task is aborted: 'Unknown pool id, pool not connected' - code 309
>CP Server Thread-19::DEBUG::2012-03-26 15:45:38,920::task::1164::TaskManager.Task::(prepare) Task=`9a3c0b15-b0f0-4d5f-9fe4-1df5e43492d1`::Prepare: aborted: Unknown pool id, pool not connected
>CP Server Thread-19::DEBUG::2012-03-26 15:45:38,920::task::980::TaskManager.Task::(_decref) Task=`9a3c0b15-b0f0-4d5f-9fe4-1df5e43492d1`::ref 0 aborting True
>CP Server Thread-19::DEBUG::2012-03-26 15:45:38,920::task::915::TaskManager.Task::(_doAbort) Task=`9a3c0b15-b0f0-4d5f-9fe4-1df5e43492d1`::Task._doAbort: force False
>CP Server Thread-19::DEBUG::2012-03-26 15:45:38,921::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>CP Server Thread-19::DEBUG::2012-03-26 15:45:38,921::task::588::TaskManager.Task::(_updateState) Task=`9a3c0b15-b0f0-4d5f-9fe4-1df5e43492d1`::moving from state preparing -> state aborting
>CP Server Thread-19::DEBUG::2012-03-26 15:45:38,921::task::537::TaskManager.Task::(__state_aborting) Task=`9a3c0b15-b0f0-4d5f-9fe4-1df5e43492d1`::_aborting: recover policy none
>CP Server Thread-19::DEBUG::2012-03-26 15:45:38,921::task::588::TaskManager.Task::(_updateState) Task=`9a3c0b15-b0f0-4d5f-9fe4-1df5e43492d1`::moving from state aborting -> state failed
>CP Server Thread-19::DEBUG::2012-03-26 15:45:38,922::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505': < ResourceRef 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505', isValid: 'True' obj: 'None'>}
>CP Server Thread-19::DEBUG::2012-03-26 15:45:38,922::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>CP Server Thread-19::DEBUG::2012-03-26 15:45:38,922::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505'
>CP Server Thread-19::DEBUG::2012-03-26 15:45:38,923::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505' (0 active users)
>CP Server Thread-19::DEBUG::2012-03-26 15:45:38,923::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505' is free, finding out if anyone is waiting for it.
>CP Server Thread-19::DEBUG::2012-03-26 15:45:38,923::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.bebd6a96-d3da-419c-8905-b5eec55c4505', Clearing records.
>CP Server Thread-19::ERROR::2012-03-26 15:45:38,924::dispatcher::90::Storage.Dispatcher.Protect::(run) {'status': {'message': "Unknown pool id, pool not connected: ('bebd6a96-d3da-419c-8905-b5eec55c4505',)", 'code': 309}}
>CP Server Thread-19::INFO::2012-03-26 15:45:38,925::_cplogging::262::cherrypy.access.23486224::(access) 127.0.0.1 - - [26/Mar/2012:15:45:38] "GET /vdsm-api/storagepools/bebd6a96-d3da-419c-8905-b5eec55c4505/ HTTP/1.1" 404 1151 "" "Python-urllib/2.7"
>CP Server Thread-20::DEBUG::2012-03-26 15:45:38,929::task::588::TaskManager.Task::(_updateState) Task=`39061a22-992a-481d-8eff-5827c37768e2`::moving from state init -> state preparing
>CP Server Thread-20::INFO::2012-03-26 15:45:38,929::logUtils::37::dispatcher::(wrapper) Run and protect: getStorageDomainInfo(sdUUID='1be32ac7-1e12-4823-8e8c-8c887333fe37', options=None)
>CP Server Thread-20::INFO::2012-03-26 15:45:38,929::fileSD::193::Storage.StorageDomain::(validate) sdUUID=1be32ac7-1e12-4823-8e8c-8c887333fe37
>CP Server Thread-20::DEBUG::2012-03-26 15:45:38,931::persistentDict::216::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=Test Domain', 'IOOPTIMEOUTSEC=1', 'LEASERETRIES=3', 'LEASETIMESEC=30', 'LOCKPOLICY=ON', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=0', 'POOL_DESCRIPTION=Local storage pooln', 'POOL_DOMAINS=1be32ac7-1e12-4823-8e8c-8c887333fe37:Active', 'POOL_SPM_ID=1', 'POOL_SPM_LVER=0', 'POOL_UUID=bebd6a96-d3da-419c-8905-b5eec55c4505', 'REMOTE_PATH=/var/lib/vdsm/bugstoragsomedomain4', 'ROLE=Master', 'SDUUID=1be32ac7-1e12-4823-8e8c-8c887333fe37', 'TYPE=LOCALFS', 'VERSION=0', '_SHA_CKSUM=b40a20cc2d9342513f99a0a9f49dd8e852e32c01']
>CP Server Thread-20::DEBUG::2012-03-26 15:45:38,931::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37`ReqID=`0b0fb5d8-6c32-48d3-bd65-132ac1f23aab`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2036' at 'getStorageDomainInfo'
>CP Server Thread-20::DEBUG::2012-03-26 15:45:38,932::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37' for lock type 'shared'
>CP Server Thread-20::DEBUG::2012-03-26 15:45:38,932::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37' is free. Now locking as 'shared' (1 active user)
>CP Server Thread-20::DEBUG::2012-03-26 15:45:38,932::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37`ReqID=`0b0fb5d8-6c32-48d3-bd65-132ac1f23aab`::Granted request
>CP Server Thread-20::DEBUG::2012-03-26 15:45:38,932::task::819::TaskManager.Task::(resourceAcquired) Task=`39061a22-992a-481d-8eff-5827c37768e2`::_resourcesAcquired: Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37 (shared)
>CP Server Thread-20::DEBUG::2012-03-26 15:45:38,933::task::980::TaskManager.Task::(_decref) Task=`39061a22-992a-481d-8eff-5827c37768e2`::ref 1 aborting False
>CP Server Thread-20::INFO::2012-03-26 15:45:38,933::logUtils::39::dispatcher::(wrapper) Run and protect: getStorageDomainInfo, Return response: {'info': {'uuid': '1be32ac7-1e12-4823-8e8c-8c887333fe37', 'master_ver': 0, 'lver': -1, 'version': '0', 'role': 'Master', 'remotePath': '/var/lib/vdsm/bugstoragsomedomain4', 'spm_id': -1, 'type': 'LOCALFS', 'class': 'Data', 'pool': ['bebd6a96-d3da-419c-8905-b5eec55c4505'], 'name': 'Test Domain'}}
>CP Server Thread-20::DEBUG::2012-03-26 15:45:38,933::task::1174::TaskManager.Task::(prepare) Task=`39061a22-992a-481d-8eff-5827c37768e2`::finished: {'info': {'uuid': '1be32ac7-1e12-4823-8e8c-8c887333fe37', 'master_ver': 0, 'lver': -1, 'version': '0', 'role': 'Master', 'remotePath': '/var/lib/vdsm/bugstoragsomedomain4', 'spm_id': -1, 'type': 'LOCALFS', 'class': 'Data', 'pool': ['bebd6a96-d3da-419c-8905-b5eec55c4505'], 'name': 'Test Domain'}}
>CP Server Thread-20::DEBUG::2012-03-26 15:45:38,933::task::588::TaskManager.Task::(_updateState) Task=`39061a22-992a-481d-8eff-5827c37768e2`::moving from state preparing -> state finished
>CP Server Thread-20::DEBUG::2012-03-26 15:45:38,934::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37': < ResourceRef 'Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37', isValid: 'True' obj: 'None'>}
>CP Server Thread-20::DEBUG::2012-03-26 15:45:38,934::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>CP Server Thread-20::DEBUG::2012-03-26 15:45:38,934::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37'
>CP Server Thread-20::DEBUG::2012-03-26 15:45:38,934::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37' (0 active users)
>CP Server Thread-20::DEBUG::2012-03-26 15:45:38,934::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37' is free, finding out if anyone is waiting for it.
>CP Server Thread-20::DEBUG::2012-03-26 15:45:38,935::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37', Clearing records.
>CP Server Thread-20::DEBUG::2012-03-26 15:45:38,935::task::980::TaskManager.Task::(_decref) Task=`39061a22-992a-481d-8eff-5827c37768e2`::ref 0 aborting False
>CP Server Thread-20::DEBUG::2012-03-26 15:45:38,935::task::588::TaskManager.Task::(_updateState) Task=`71846f39-4df8-4ee1-9c5e-52e311e81498`::moving from state init -> state preparing
>CP Server Thread-20::INFO::2012-03-26 15:45:38,936::logUtils::37::dispatcher::(wrapper) Run and protect: formatStorageDomain(sdUUID='1be32ac7-1e12-4823-8e8c-8c887333fe37', autoDetach='True', options=None)
>CP Server Thread-20::DEBUG::2012-03-26 15:45:38,936::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37`ReqID=`6bb0e15f-3242-4b73-865e-12ee0948606a`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '1978' at 'formatStorageDomain'
>CP Server Thread-20::DEBUG::2012-03-26 15:45:38,936::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37' for lock type 'exclusive'
>CP Server Thread-20::DEBUG::2012-03-26 15:45:38,936::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37' is free. Now locking as 'exclusive' (1 active user)
>CP Server Thread-20::DEBUG::2012-03-26 15:45:38,936::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37`ReqID=`6bb0e15f-3242-4b73-865e-12ee0948606a`::Granted request
>CP Server Thread-20::DEBUG::2012-03-26 15:45:38,937::task::819::TaskManager.Task::(resourceAcquired) Task=`71846f39-4df8-4ee1-9c5e-52e311e81498`::_resourcesAcquired: Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37 (exclusive)
>CP Server Thread-20::DEBUG::2012-03-26 15:45:38,937::task::980::TaskManager.Task::(_decref) Task=`71846f39-4df8-4ee1-9c5e-52e311e81498`::ref 1 aborting False
>CP Server Thread-20::WARNING::2012-03-26 15:45:38,937::hsm::1956::Storage.HSM::(_recycle) Storage domain 1be32ac7-1e12-4823-8e8c-8c887333fe37 doesn't exist in cache. Trying recycle leftovers ...
>CP Server Thread-20::INFO::2012-03-26 15:45:38,937::fileSD::225::Storage.StorageDomain::(format) Formating domain 1be32ac7-1e12-4823-8e8c-8c887333fe37
>CP Server Thread-20::INFO::2012-03-26 15:45:38,940::logUtils::39::dispatcher::(wrapper) Run and protect: formatStorageDomain, Return response: None
>CP Server Thread-20::DEBUG::2012-03-26 15:45:38,940::task::1174::TaskManager.Task::(prepare) Task=`71846f39-4df8-4ee1-9c5e-52e311e81498`::finished: None
>CP Server Thread-20::DEBUG::2012-03-26 15:45:38,940::task::588::TaskManager.Task::(_updateState) Task=`71846f39-4df8-4ee1-9c5e-52e311e81498`::moving from state preparing -> state finished
>CP Server Thread-20::DEBUG::2012-03-26 15:45:38,941::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37': < ResourceRef 'Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37', isValid: 'True' obj: 'None'>}
>CP Server Thread-20::DEBUG::2012-03-26 15:45:38,941::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>CP Server Thread-20::DEBUG::2012-03-26 15:45:38,942::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37'
>CP Server Thread-20::DEBUG::2012-03-26 15:45:38,942::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37' (0 active users)
>CP Server Thread-20::DEBUG::2012-03-26 15:45:38,942::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37' is free, finding out if anyone is waiting for it.
>CP Server Thread-20::DEBUG::2012-03-26 15:45:38,943::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.1be32ac7-1e12-4823-8e8c-8c887333fe37', Clearing records.
>CP Server Thread-20::DEBUG::2012-03-26 15:45:38,944::task::980::TaskManager.Task::(_decref) Task=`71846f39-4df8-4ee1-9c5e-52e311e81498`::ref 0 aborting False
>CP Server Thread-20::INFO::2012-03-26 15:45:38,944::_cplogging::262::cherrypy.access.23486224::(access) 127.0.0.1 - - [26/Mar/2012:15:45:38] "POST /vdsm-api/storagedomains/1be32ac7-1e12-4823-8e8c-8c887333fe37/format HTTP/1.1" 200 - "" "Python-urllib/2.7"
>CP Server Thread-21::DEBUG::2012-03-26 15:45:38,948::task::588::TaskManager.Task::(_updateState) Task=`c3fd6757-03d8-45a6-8aae-af9538ef938d`::moving from state init -> state preparing
>CP Server Thread-21::INFO::2012-03-26 15:45:38,948::logUtils::37::dispatcher::(wrapper) Run and protect: connectStorageServer(domType=4, spUUID=None, conList=[{'connection': u'/var/lib/vdsm/bugstoragsomedomain4', 'id': 1}], options=None)
>CP Server Thread-21::INFO::2012-03-26 15:45:38,949::storage_connection::147::Storage.ServerConnection::(connect) Request to connect LOCALFS storage server
>CP Server Thread-21::DEBUG::2012-03-26 15:45:38,949::lvm::460::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
>CP Server Thread-21::DEBUG::2012-03-26 15:45:38,950::lvm::462::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
>CP Server Thread-21::DEBUG::2012-03-26 15:45:38,950::lvm::472::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
>CP Server Thread-21::DEBUG::2012-03-26 15:45:38,950::lvm::474::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
>CP Server Thread-21::DEBUG::2012-03-26 15:45:38,951::lvm::493::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
>CP Server Thread-21::DEBUG::2012-03-26 15:45:38,951::lvm::495::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
>CP Server Thread-21::INFO::2012-03-26 15:45:38,952::logUtils::39::dispatcher::(wrapper) Run and protect: connectStorageServer, Return response: {'statuslist': [{'status': 0, 'id': 1}]}
>CP Server Thread-21::DEBUG::2012-03-26 15:45:38,952::task::1174::TaskManager.Task::(prepare) Task=`c3fd6757-03d8-45a6-8aae-af9538ef938d`::finished: {'statuslist': [{'status': 0, 'id': 1}]}
>CP Server Thread-21::DEBUG::2012-03-26 15:45:38,952::task::588::TaskManager.Task::(_updateState) Task=`c3fd6757-03d8-45a6-8aae-af9538ef938d`::moving from state preparing -> state finished
>CP Server Thread-21::DEBUG::2012-03-26 15:45:38,953::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>CP Server Thread-21::DEBUG::2012-03-26 15:45:38,953::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>CP Server Thread-21::DEBUG::2012-03-26 15:45:38,953::task::980::TaskManager.Task::(_decref) Task=`c3fd6757-03d8-45a6-8aae-af9538ef938d`::ref 0 aborting False
>CP Server Thread-21::INFO::2012-03-26 15:45:38,954::_cplogging::262::cherrypy.access.23486224::(access) 127.0.0.1 - - [26/Mar/2012:15:45:38] "POST /vdsm-api/storageconnections/manage HTTP/1.1" 303 146 "" "Python-urllib/2.7"
>CP Server Thread-22::INFO::2012-03-26 15:45:38,958::_cplogging::262::cherrypy.access.23486224::(access) 127.0.0.1 - - [26/Mar/2012:15:45:38] "GET /vdsm-api/storageconnections/ HTTP/1.1" 200 36 "" "Python-urllib/2.7"
>CP Server Thread-23::DEBUG::2012-03-26 15:45:38,961::task::588::TaskManager.Task::(_updateState) Task=`b56f239f-72c6-4d83-b80f-7b00c8946221`::moving from state init -> state preparing
>CP Server Thread-23::INFO::2012-03-26 15:45:38,961::logUtils::37::dispatcher::(wrapper) Run and protect: createStorageDomain(storageType=4, sdUUID='1be32ac7-1e12-4823-8e8c-8c887333fe37', domainName='Test Domain', typeSpecificArg='/var/lib/vdsm/bugstoragsomedomain4', domClass=1, domVersion=0, options=None)
>CP Server Thread-23::ERROR::2012-03-26 15:45:38,961::task::855::TaskManager.Task::(_setError) Task=`b56f239f-72c6-4d83-b80f-7b00c8946221`::Unexpected error
>Traceback (most recent call last):
>  File "/usr/share/vdsm/storage/task.py", line 863, in _run
>    return fn(*args, **kargs)
>  File "/usr/share/vdsm/logUtils.py", line 38, in wrapper
>    res = f(*args, **kwargs)
>  File "/usr/share/vdsm/storage/hsm.py", line 1912, in createStorageDomain
>    self.validateNonDomain(sdUUID)
>  File "/usr/share/vdsm/storage/hsm.py", line 167, in validateNonDomain
>    raise se.StorageDomainAlreadyExists(sdUUID)
>StorageDomainAlreadyExists: Storage domain already exists: ('1be32ac7-1e12-4823-8e8c-8c887333fe37',)
>CP Server Thread-23::DEBUG::2012-03-26 15:45:38,962::task::874::TaskManager.Task::(_run) Task=`b56f239f-72c6-4d83-b80f-7b00c8946221`::Task._run: b56f239f-72c6-4d83-b80f-7b00c8946221 (4, '1be32ac7-1e12-4823-8e8c-8c887333fe37', 'Test Domain', '/var/lib/vdsm/bugstoragsomedomain4', 1, 0) {} failed - stopping task
>CP Server Thread-23::DEBUG::2012-03-26 15:45:38,962::task::1201::TaskManager.Task::(stop) Task=`b56f239f-72c6-4d83-b80f-7b00c8946221`::stopping in state preparing (force False)
>CP Server Thread-23::DEBUG::2012-03-26 15:45:38,962::task::980::TaskManager.Task::(_decref) Task=`b56f239f-72c6-4d83-b80f-7b00c8946221`::ref 1 aborting True
>CP Server Thread-23::INFO::2012-03-26 15:45:38,963::task::1159::TaskManager.Task::(prepare) Task=`b56f239f-72c6-4d83-b80f-7b00c8946221`::aborting: Task is aborted: 'Storage domain already exists' - code 365
>CP Server Thread-23::DEBUG::2012-03-26 15:45:38,963::task::1164::TaskManager.Task::(prepare) Task=`b56f239f-72c6-4d83-b80f-7b00c8946221`::Prepare: aborted: Storage domain already exists
>CP Server Thread-23::DEBUG::2012-03-26 15:45:38,963::task::980::TaskManager.Task::(_decref) Task=`b56f239f-72c6-4d83-b80f-7b00c8946221`::ref 0 aborting True
>CP Server Thread-23::DEBUG::2012-03-26 15:45:38,963::task::915::TaskManager.Task::(_doAbort) Task=`b56f239f-72c6-4d83-b80f-7b00c8946221`::Task._doAbort: force False
>CP Server Thread-23::DEBUG::2012-03-26 15:45:38,964::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>CP Server Thread-23::DEBUG::2012-03-26 15:45:38,964::task::588::TaskManager.Task::(_updateState) Task=`b56f239f-72c6-4d83-b80f-7b00c8946221`::moving from state preparing -> state aborting
>CP Server Thread-23::DEBUG::2012-03-26 15:45:38,964::task::537::TaskManager.Task::(__state_aborting) Task=`b56f239f-72c6-4d83-b80f-7b00c8946221`::_aborting: recover policy none
>CP Server Thread-23::DEBUG::2012-03-26 15:45:38,964::task::588::TaskManager.Task::(_updateState) Task=`b56f239f-72c6-4d83-b80f-7b00c8946221`::moving from state aborting -> state failed
>CP Server Thread-23::DEBUG::2012-03-26 15:45:38,965::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>CP Server Thread-23::DEBUG::2012-03-26 15:45:38,965::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>CP Server Thread-23::ERROR::2012-03-26 15:45:38,965::dispatcher::90::Storage.Dispatcher.Protect::(run) {'status': {'message': "Storage domain already exists: ('1be32ac7-1e12-4823-8e8c-8c887333fe37',)", 'code': 365}}
>CP Server Thread-23::INFO::2012-03-26 15:45:38,966::_cplogging::262::cherrypy.access.23486224::(access) 127.0.0.1 - - [26/Mar/2012:15:45:38] "POST /vdsm-api/storagedomains/create HTTP/1.1" 400 1316 "" "Python-urllib/2.7"
>CP Server Thread-24::DEBUG::2012-03-26 15:45:38,969::task::588::TaskManager.Task::(_updateState) Task=`e158182a-7c7f-420d-8a07-415f4eddb6ff`::moving from state init -> state preparing
>CP Server Thread-24::INFO::2012-03-26 15:45:38,969::logUtils::37::dispatcher::(wrapper) Run and protect: disconnectStorageServer(domType=4, spUUID=None, conList=[{'connection': u'/var/lib/vdsm/bugstoragsomedomain4', 'id': 1}], options=None)
>CP Server Thread-24::INFO::2012-03-26 15:45:38,969::storage_connection::168::Storage.ServerConnection::(disconnect) Request to disconnect LOCALFS storage server
>CP Server Thread-24::DEBUG::2012-03-26 15:45:38,970::misc::1017::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
>CP Server Thread-24::DEBUG::2012-03-26 15:45:38,970::misc::1019::SamplingMethod::(__call__) Got in to sampling method
>CP Server Thread-24::DEBUG::2012-03-26 15:45:38,970::misc::1017::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
>CP Server Thread-24::DEBUG::2012-03-26 15:45:38,970::misc::1019::SamplingMethod::(__call__) Got in to sampling method
>CP Server Thread-24::DEBUG::2012-03-26 15:45:38,971::iscsi::389::Storage.Misc.excCmd::(rescan) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
>CP Server Thread-24::DEBUG::2012-03-26 15:45:38,986::iscsi::389::Storage.Misc.excCmd::(rescan) FAILED: <err> = 'iscsiadm: No session found.\n'; <rc> = 21
>CP Server Thread-24::DEBUG::2012-03-26 15:45:38,987::misc::1027::SamplingMethod::(__call__) Returning last result
>CP Server Thread-24::DEBUG::2012-03-26 15:45:40,229::multipath::71::Storage.Misc.excCmd::(rescan) '/usr/bin/sudo -n /sbin/multipath' (cwd None)
>CP Server Thread-24::DEBUG::2012-03-26 15:45:40,259::multipath::71::Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0
>CP Server Thread-24::DEBUG::2012-03-26 15:45:40,260::lvm::460::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
>CP Server Thread-24::DEBUG::2012-03-26 15:45:40,260::lvm::462::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
>CP Server Thread-24::DEBUG::2012-03-26 15:45:40,260::lvm::472::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
>CP Server Thread-24::DEBUG::2012-03-26 15:45:40,261::lvm::474::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
>CP Server Thread-24::DEBUG::2012-03-26 15:45:40,261::lvm::493::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
>CP Server Thread-24::DEBUG::2012-03-26 15:45:40,261::lvm::495::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
>CP Server Thread-24::DEBUG::2012-03-26 15:45:40,261::misc::1027::SamplingMethod::(__call__) Returning last result
>CP Server Thread-24::INFO::2012-03-26 15:45:40,261::logUtils::39::dispatcher::(wrapper) Run and protect: disconnectStorageServer, Return response: {'statuslist': [{'status': 0, 'id': 1}]}
>CP Server Thread-24::DEBUG::2012-03-26 15:45:40,262::task::1174::TaskManager.Task::(prepare) Task=`e158182a-7c7f-420d-8a07-415f4eddb6ff`::finished: {'statuslist': [{'status': 0, 'id': 1}]}
>CP Server Thread-24::DEBUG::2012-03-26 15:45:40,262::task::588::TaskManager.Task::(_updateState) Task=`e158182a-7c7f-420d-8a07-415f4eddb6ff`::moving from state preparing -> state finished
>CP Server Thread-24::DEBUG::2012-03-26 15:45:40,262::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>CP Server Thread-24::DEBUG::2012-03-26 15:45:40,262::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>CP Server Thread-24::DEBUG::2012-03-26 15:45:40,263::task::980::TaskManager.Task::(_decref) Task=`e158182a-7c7f-420d-8a07-415f4eddb6ff`::ref 0 aborting False
>CP Server Thread-24::INFO::2012-03-26 15:45:40,263::_cplogging::262::cherrypy.access.23486224::(access) 127.0.0.1 - - [26/Mar/2012:15:45:40] "POST /vdsm-api/storageconnections/fooid/unmanage HTTP/1.1" 204 - "" "Python-urllib/2.7"
>CP Server Thread-25::DEBUG::2012-03-26 15:55:03,883::task::588::TaskManager.Task::(_updateState) Task=`a88e1ddd-bd1d-4fc5-b650-9a43c6f49054`::moving from state init -> state preparing
>CP Server Thread-25::INFO::2012-03-26 15:55:03,884::logUtils::37::dispatcher::(wrapper) Run and protect: getStorageDomainsList(spUUID=None, domainClass=None, storageType=None, remotePath=None, options=None)
>CP Server Thread-25::DEBUG::2012-03-26 15:55:03,884::misc::1017::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
>CP Server Thread-25::DEBUG::2012-03-26 15:55:03,884::misc::1019::SamplingMethod::(__call__) Got in to sampling method
>CP Server Thread-25::DEBUG::2012-03-26 15:55:03,884::misc::1017::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
>CP Server Thread-25::DEBUG::2012-03-26 15:55:03,885::misc::1019::SamplingMethod::(__call__) Got in to sampling method
>CP Server Thread-25::DEBUG::2012-03-26 15:55:03,885::iscsi::389::Storage.Misc.excCmd::(rescan) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
>CP Server Thread-25::DEBUG::2012-03-26 15:55:03,900::iscsi::389::Storage.Misc.excCmd::(rescan) FAILED: <err> = 'iscsiadm: No session found.\n'; <rc> = 21
>CP Server Thread-25::DEBUG::2012-03-26 15:55:03,900::misc::1027::SamplingMethod::(__call__) Returning last result
>CP Server Thread-25::DEBUG::2012-03-26 15:55:05,265::multipath::71::Storage.Misc.excCmd::(rescan) '/usr/bin/sudo -n /sbin/multipath' (cwd None)
>CP Server Thread-25::DEBUG::2012-03-26 15:55:05,302::multipath::71::Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0
>CP Server Thread-25::DEBUG::2012-03-26 15:55:05,303::lvm::460::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
>CP Server Thread-25::DEBUG::2012-03-26 15:55:05,303::lvm::462::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
>CP Server Thread-25::DEBUG::2012-03-26 15:55:05,304::lvm::472::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
>CP Server Thread-25::DEBUG::2012-03-26 15:55:05,304::lvm::474::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
>CP Server Thread-25::DEBUG::2012-03-26 15:55:05,305::lvm::493::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
>CP Server Thread-25::DEBUG::2012-03-26 15:55:05,305::lvm::495::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
>CP Server Thread-25::DEBUG::2012-03-26 15:55:05,305::misc::1027::SamplingMethod::(__call__) Returning last result
>CP Server Thread-25::DEBUG::2012-03-26 15:55:05,306::lvm::352::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
>CP Server Thread-25::DEBUG::2012-03-26 15:55:05,307::lvm::287::Storage.Misc.excCmd::(cmd) '/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 = [ \\"a%35000c500382d9c53%\\", \\"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)
>CP Server Thread-25::DEBUG::2012-03-26 15:55:05,622::lvm::287::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = '  No volume groups found\n'; <rc> = 0
>CP Server Thread-25::DEBUG::2012-03-26 15:55:05,623::lvm::379::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
>CP Server Thread-25::INFO::2012-03-26 15:55:05,625::logUtils::39::dispatcher::(wrapper) Run and protect: getStorageDomainsList, Return response: {'domlist': ['1be32ac7-1e12-4823-8e8c-8c887333fe36']}
>CP Server Thread-25::DEBUG::2012-03-26 15:55:05,626::task::1174::TaskManager.Task::(prepare) Task=`a88e1ddd-bd1d-4fc5-b650-9a43c6f49054`::finished: {'domlist': ['1be32ac7-1e12-4823-8e8c-8c887333fe36']}
>CP Server Thread-25::DEBUG::2012-03-26 15:55:05,626::task::588::TaskManager.Task::(_updateState) Task=`a88e1ddd-bd1d-4fc5-b650-9a43c6f49054`::moving from state preparing -> state finished
>CP Server Thread-25::DEBUG::2012-03-26 15:55:05,627::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>CP Server Thread-25::DEBUG::2012-03-26 15:55:05,627::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>CP Server Thread-25::DEBUG::2012-03-26 15:55:05,627::task::980::TaskManager.Task::(_decref) Task=`a88e1ddd-bd1d-4fc5-b650-9a43c6f49054`::ref 0 aborting False
>CP Server Thread-25::INFO::2012-03-26 15:55:05,628::_cplogging::262::cherrypy.access.23486224::(access) 127.0.0.1 - - [26/Mar/2012:15:55:05] "GET /vdsm-api/storagedomains/ HTTP/1.1" 200 161 "" "curl/7.21.7 (x86_64-redhat-linux-gnu) libcurl/7.21.7 NSS/3.13.1.0 zlib/1.2.5 libidn/1.22 libssh2/1.2.7"

Actions: View

Attachments on bug 806774: 572709