Attachment 641526 Details for Bug 874120 – Full vdsm.log

Full vdsm.log

vdsm.log (text/x-log), 74.10 KB, created by Valentin Bajrami on 2012-11-09 13:11:09 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: Valentin Bajrami

Created: 2012-11-09 13:11:09 UTC

Size: 74.10 KB

patch

obsolete

>Thread-551::DEBUG::2012-11-09 06:06:32,118::BindingXMLRPC::156::vds::(wrapper) [192.168.2.113]
>Thread-551::DEBUG::2012-11-09 06:06:32,119::task::588::TaskManager.Task::(_updateState) Task=`c2dc6cf5-bb5b-47d9-8228-a7f9ed8e1735`::moving from state init -> state preparing
>Thread-551::INFO::2012-11-09 06:06:32,119::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='c02503a4-274e-11e2-b33c-002590730631', options=None)
>Thread-551::ERROR::2012-11-09 06:06:32,119::task::853::TaskManager.Task::(_setError) Task=`c2dc6cf5-bb5b-47d9-8228-a7f9ed8e1735`::Unexpected error
>Traceback (most recent call last):
>  File "/usr/share/vdsm/storage/task.py", line 861, in _run
>    return fn(*args, **kargs)
>  File "/usr/share/vdsm/logUtils.py", line 38, in wrapper
>    res = f(*args, **kwargs)
>  File "/usr/share/vdsm/storage/hsm.py", line 528, in getSpmStatus
>    pool = self.getPool(spUUID)
>  File "/usr/share/vdsm/storage/hsm.py", line 265, in getPool
>    raise se.StoragePoolUnknown(spUUID)
>StoragePoolUnknown: Unknown pool id, pool not connected: ('c02503a4-274e-11e2-b33c-002590730631',)
>Thread-551::DEBUG::2012-11-09 06:06:32,119::task::872::TaskManager.Task::(_run) Task=`c2dc6cf5-bb5b-47d9-8228-a7f9ed8e1735`::Task._run: c2dc6cf5-bb5b-47d9-8228-a7f9ed8e1735 ('c02503a4-274e-11e2-b33c-002590730631',) {} failed - stopping task
>Thread-551::DEBUG::2012-11-09 06:06:32,120::task::1199::TaskManager.Task::(stop) Task=`c2dc6cf5-bb5b-47d9-8228-a7f9ed8e1735`::stopping in state preparing (force False)
>Thread-551::DEBUG::2012-11-09 06:06:32,120::task::978::TaskManager.Task::(_decref) Task=`c2dc6cf5-bb5b-47d9-8228-a7f9ed8e1735`::ref 1 aborting True
>Thread-551::INFO::2012-11-09 06:06:32,120::task::1157::TaskManager.Task::(prepare) Task=`c2dc6cf5-bb5b-47d9-8228-a7f9ed8e1735`::aborting: Task is aborted: 'Unknown pool id, pool not connected' - code 309
>Thread-551::DEBUG::2012-11-09 06:06:32,120::task::1162::TaskManager.Task::(prepare) Task=`c2dc6cf5-bb5b-47d9-8228-a7f9ed8e1735`::Prepare: aborted: Unknown pool id, pool not connected
>Thread-551::DEBUG::2012-11-09 06:06:32,120::task::978::TaskManager.Task::(_decref) Task=`c2dc6cf5-bb5b-47d9-8228-a7f9ed8e1735`::ref 0 aborting True
>Thread-551::DEBUG::2012-11-09 06:06:32,121::task::913::TaskManager.Task::(_doAbort) Task=`c2dc6cf5-bb5b-47d9-8228-a7f9ed8e1735`::Task._doAbort: force False
>Thread-551::DEBUG::2012-11-09 06:06:32,121::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-551::DEBUG::2012-11-09 06:06:32,121::task::588::TaskManager.Task::(_updateState) Task=`c2dc6cf5-bb5b-47d9-8228-a7f9ed8e1735`::moving from state preparing -> state aborting
>Thread-551::DEBUG::2012-11-09 06:06:32,121::task::537::TaskManager.Task::(__state_aborting) Task=`c2dc6cf5-bb5b-47d9-8228-a7f9ed8e1735`::_aborting: recover policy none
>Thread-551::DEBUG::2012-11-09 06:06:32,121::task::588::TaskManager.Task::(_updateState) Task=`c2dc6cf5-bb5b-47d9-8228-a7f9ed8e1735`::moving from state aborting -> state failed
>Thread-551::DEBUG::2012-11-09 06:06:32,121::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-551::DEBUG::2012-11-09 06:06:32,121::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-551::ERROR::2012-11-09 06:06:32,122::dispatcher::66::Storage.Dispatcher.Protect::(run) {'status': {'message': "Unknown pool id, pool not connected: ('c02503a4-274e-11e2-b33c-002590730631',)", 'code': 309}}
>Thread-552::DEBUG::2012-11-09 06:06:32,162::BindingXMLRPC::156::vds::(wrapper) [192.168.2.113]
>Thread-552::DEBUG::2012-11-09 06:06:32,162::task::588::TaskManager.Task::(_updateState) Task=`0157a04c-67e2-4a37-a709-2e8bbb390f0d`::moving from state init -> state preparing
>Thread-552::INFO::2012-11-09 06:06:32,162::logUtils::37::dispatcher::(wrapper) Run and protect: connectStoragePool(spUUID='c02503a4-274e-11e2-b33c-002590730631', hostID=1, scsiKey='c02503a4-274e-11e2-b33c-002590730631', msdUUID='b1658676-2dc3-4357-b112-3852a056c663', masterVersion=1, options=None)
>Thread-552::DEBUG::2012-11-09 06:06:32,163::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.c02503a4-274e-11e2-b33c-002590730631`ReqID=`510acdb7-c7ec-4738-86b5-3d332b895362`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-552::DEBUG::2012-11-09 06:06:32,163::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.c02503a4-274e-11e2-b33c-002590730631' for lock type 'exclusive'
>Thread-552::DEBUG::2012-11-09 06:06:32,163::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.c02503a4-274e-11e2-b33c-002590730631' is free. Now locking as 'exclusive' (1 active user)
>Thread-552::DEBUG::2012-11-09 06:06:32,164::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.c02503a4-274e-11e2-b33c-002590730631`ReqID=`510acdb7-c7ec-4738-86b5-3d332b895362`::Granted request
>Thread-552::INFO::2012-11-09 06:06:32,164::sp::625::Storage.StoragePool::(connect) Connect host #1 to the storage pool c02503a4-274e-11e2-b33c-002590730631 with master domain: b1658676-2dc3-4357-b112-3852a056c663 (ver = 1)
>Thread-552::DEBUG::2012-11-09 06:06:32,164::lvm::457::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-552::DEBUG::2012-11-09 06:06:32,165::lvm::459::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-552::DEBUG::2012-11-09 06:06:32,165::lvm::469::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-552::DEBUG::2012-11-09 06:06:32,165::lvm::471::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-552::DEBUG::2012-11-09 06:06:32,165::lvm::490::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-552::DEBUG::2012-11-09 06:06:32,166::lvm::492::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-552::DEBUG::2012-11-09 06:06:32,166::misc::1053::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
>Thread-552::DEBUG::2012-11-09 06:06:32,166::misc::1055::SamplingMethod::(__call__) Got in to sampling method
>Thread-552::DEBUG::2012-11-09 06:06:32,166::misc::1053::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
>Thread-552::DEBUG::2012-11-09 06:06:32,166::misc::1055::SamplingMethod::(__call__) Got in to sampling method
>Thread-552::DEBUG::2012-11-09 06:06:32,167::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
>Thread-552::DEBUG::2012-11-09 06:06:32,182::__init__::1249::Storage.Misc.excCmd::(_log) FAILED: <err> = 'iscsiadm: No session found.\n'; <rc> = 21
>Thread-552::DEBUG::2012-11-09 06:06:32,182::misc::1063::SamplingMethod::(__call__) Returning last result
>Thread-552::DEBUG::2012-11-09 06:06:32,868::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/multipath' (cwd None)
>Thread-552::DEBUG::2012-11-09 06:06:32,929::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
>Thread-552::DEBUG::2012-11-09 06:06:32,929::lvm::457::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-552::DEBUG::2012-11-09 06:06:32,930::lvm::459::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-552::DEBUG::2012-11-09 06:06:32,930::lvm::469::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-552::DEBUG::2012-11-09 06:06:32,930::lvm::471::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-552::DEBUG::2012-11-09 06:06:32,930::lvm::490::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-552::DEBUG::2012-11-09 06:06:32,930::lvm::492::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-552::DEBUG::2012-11-09 06:06:32,931::misc::1063::SamplingMethod::(__call__) Returning last result
>Thread-552::DEBUG::2012-11-09 06:06:32,931::lvm::349::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
>Thread-552::DEBUG::2012-11-09 06:06:32,932::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/lvm vgs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 filter = [ \\"r%.*%\\" ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1 }  backup {  retain_min = 50  retain_days = 0 } " --noheadings --units b --nosuffix --separator | -o uuid,name,attr,size,free,extent_size,extent_count,free_count,tags,vg_mda_size,vg_mda_free b1658676-2dc3-4357-b112-3852a056c663' (cwd None)
>Thread-552::DEBUG::2012-11-09 06:06:32,980::__init__::1249::Storage.Misc.excCmd::(_log) FAILED: <err> = '  Volume group "b1658676-2dc3-4357-b112-3852a056c663" not found\n'; <rc> = 5
>Thread-552::WARNING::2012-11-09 06:06:32,981::lvm::353::Storage.LVM::(_reloadvgs) lvm vgs failed: 5 [] ['  Volume group "b1658676-2dc3-4357-b112-3852a056c663" not found']
>Thread-552::DEBUG::2012-11-09 06:06:32,982::lvm::376::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
>Thread-552::DEBUG::2012-11-09 06:06:32,984::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.c02503a4-274e-11e2-b33c-002590730631'
>Thread-552::DEBUG::2012-11-09 06:06:32,985::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.c02503a4-274e-11e2-b33c-002590730631' (0 active users)
>Thread-552::DEBUG::2012-11-09 06:06:32,985::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.c02503a4-274e-11e2-b33c-002590730631' is free, finding out if anyone is waiting for it.
>Thread-552::DEBUG::2012-11-09 06:06:32,985::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.c02503a4-274e-11e2-b33c-002590730631', Clearing records.
>Thread-552::ERROR::2012-11-09 06:06:32,985::task::853::TaskManager.Task::(_setError) Task=`0157a04c-67e2-4a37-a709-2e8bbb390f0d`::Unexpected error
>Traceback (most recent call last):
>  File "/usr/share/vdsm/storage/task.py", line 861, in _run
>    return fn(*args, **kargs)
>  File "/usr/share/vdsm/logUtils.py", line 38, in wrapper
>    res = f(*args, **kwargs)
>  File "/usr/share/vdsm/storage/hsm.py", line 817, in connectStoragePool
>    return self._connectStoragePool(spUUID, hostID, scsiKey, msdUUID, masterVersion, options)
>  File "/usr/share/vdsm/storage/hsm.py", line 859, in _connectStoragePool
>    res = pool.connect(hostID, scsiKey, msdUUID, masterVersion)
>  File "/usr/share/vdsm/storage/sp.py", line 641, in connect
>    self.__rebuild(msdUUID=msdUUID, masterVersion=masterVersion)
>  File "/usr/share/vdsm/storage/sp.py", line 1109, in __rebuild
>    self.masterDomain = self.getMasterDomain(msdUUID=msdUUID, masterVersion=masterVersion)
>  File "/usr/share/vdsm/storage/sp.py", line 1448, in getMasterDomain
>    raise se.StoragePoolMasterNotFound(self.spUUID, msdUUID)
>StoragePoolMasterNotFound: Cannot find master domain: 'spUUID=c02503a4-274e-11e2-b33c-002590730631, msdUUID=b1658676-2dc3-4357-b112-3852a056c663'
>Thread-552::DEBUG::2012-11-09 06:06:32,985::task::872::TaskManager.Task::(_run) Task=`0157a04c-67e2-4a37-a709-2e8bbb390f0d`::Task._run: 0157a04c-67e2-4a37-a709-2e8bbb390f0d ('c02503a4-274e-11e2-b33c-002590730631', 1, 'c02503a4-274e-11e2-b33c-002590730631', 'b1658676-2dc3-4357-b112-3852a056c663', 1) {} failed - stopping task
>Thread-552::DEBUG::2012-11-09 06:06:32,986::task::1199::TaskManager.Task::(stop) Task=`0157a04c-67e2-4a37-a709-2e8bbb390f0d`::stopping in state preparing (force False)
>Thread-552::DEBUG::2012-11-09 06:06:32,986::task::978::TaskManager.Task::(_decref) Task=`0157a04c-67e2-4a37-a709-2e8bbb390f0d`::ref 1 aborting True
>Thread-552::INFO::2012-11-09 06:06:32,986::task::1157::TaskManager.Task::(prepare) Task=`0157a04c-67e2-4a37-a709-2e8bbb390f0d`::aborting: Task is aborted: 'Cannot find master domain' - code 304
>Thread-552::DEBUG::2012-11-09 06:06:32,986::task::1162::TaskManager.Task::(prepare) Task=`0157a04c-67e2-4a37-a709-2e8bbb390f0d`::Prepare: aborted: Cannot find master domain
>Thread-552::DEBUG::2012-11-09 06:06:32,986::task::978::TaskManager.Task::(_decref) Task=`0157a04c-67e2-4a37-a709-2e8bbb390f0d`::ref 0 aborting True
>Thread-552::DEBUG::2012-11-09 06:06:32,986::task::913::TaskManager.Task::(_doAbort) Task=`0157a04c-67e2-4a37-a709-2e8bbb390f0d`::Task._doAbort: force False
>Thread-552::DEBUG::2012-11-09 06:06:32,986::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-552::DEBUG::2012-11-09 06:06:32,986::task::588::TaskManager.Task::(_updateState) Task=`0157a04c-67e2-4a37-a709-2e8bbb390f0d`::moving from state preparing -> state aborting
>Thread-552::DEBUG::2012-11-09 06:06:32,987::task::537::TaskManager.Task::(__state_aborting) Task=`0157a04c-67e2-4a37-a709-2e8bbb390f0d`::_aborting: recover policy none
>Thread-552::DEBUG::2012-11-09 06:06:32,987::task::588::TaskManager.Task::(_updateState) Task=`0157a04c-67e2-4a37-a709-2e8bbb390f0d`::moving from state aborting -> state failed
>Thread-552::DEBUG::2012-11-09 06:06:32,987::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-552::DEBUG::2012-11-09 06:06:32,987::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-552::ERROR::2012-11-09 06:06:32,987::dispatcher::66::Storage.Dispatcher.Protect::(run) {'status': {'message': "Cannot find master domain: 'spUUID=c02503a4-274e-11e2-b33c-002590730631, msdUUID=b1658676-2dc3-4357-b112-3852a056c663'", 'code': 304}}
>Thread-555::DEBUG::2012-11-09 06:06:33,987::task::588::TaskManager.Task::(_updateState) Task=`3ab39083-7264-4792-ace0-2169806975c4`::moving from state init -> state preparing
>Thread-555::INFO::2012-11-09 06:06:33,988::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-555::INFO::2012-11-09 06:06:33,988::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
>Thread-555::DEBUG::2012-11-09 06:06:33,988::task::1172::TaskManager.Task::(prepare) Task=`3ab39083-7264-4792-ace0-2169806975c4`::finished: {}
>Thread-555::DEBUG::2012-11-09 06:06:33,988::task::588::TaskManager.Task::(_updateState) Task=`3ab39083-7264-4792-ace0-2169806975c4`::moving from state preparing -> state finished
>Thread-555::DEBUG::2012-11-09 06:06:33,988::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-555::DEBUG::2012-11-09 06:06:33,989::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-555::DEBUG::2012-11-09 06:06:33,989::task::978::TaskManager.Task::(_decref) Task=`3ab39083-7264-4792-ace0-2169806975c4`::ref 0 aborting False
>Thread-561::DEBUG::2012-11-09 06:06:43,196::BindingXMLRPC::156::vds::(wrapper) [192.168.2.113]
>Thread-561::DEBUG::2012-11-09 06:06:43,196::task::588::TaskManager.Task::(_updateState) Task=`9438b74e-4503-4aea-ab24-b70987d9c74e`::moving from state init -> state preparing
>Thread-561::INFO::2012-11-09 06:06:43,196::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='c02503a4-274e-11e2-b33c-002590730631', options=None)
>Thread-561::ERROR::2012-11-09 06:06:43,196::task::853::TaskManager.Task::(_setError) Task=`9438b74e-4503-4aea-ab24-b70987d9c74e`::Unexpected error
>Traceback (most recent call last):
>  File "/usr/share/vdsm/storage/task.py", line 861, in _run
>    return fn(*args, **kargs)
>  File "/usr/share/vdsm/logUtils.py", line 38, in wrapper
>    res = f(*args, **kwargs)
>  File "/usr/share/vdsm/storage/hsm.py", line 528, in getSpmStatus
>    pool = self.getPool(spUUID)
>  File "/usr/share/vdsm/storage/hsm.py", line 265, in getPool
>    raise se.StoragePoolUnknown(spUUID)
>StoragePoolUnknown: Unknown pool id, pool not connected: ('c02503a4-274e-11e2-b33c-002590730631',)
>Thread-561::DEBUG::2012-11-09 06:06:43,197::task::872::TaskManager.Task::(_run) Task=`9438b74e-4503-4aea-ab24-b70987d9c74e`::Task._run: 9438b74e-4503-4aea-ab24-b70987d9c74e ('c02503a4-274e-11e2-b33c-002590730631',) {} failed - stopping task
>Thread-561::DEBUG::2012-11-09 06:06:43,197::task::1199::TaskManager.Task::(stop) Task=`9438b74e-4503-4aea-ab24-b70987d9c74e`::stopping in state preparing (force False)
>Thread-561::DEBUG::2012-11-09 06:06:43,197::task::978::TaskManager.Task::(_decref) Task=`9438b74e-4503-4aea-ab24-b70987d9c74e`::ref 1 aborting True
>Thread-561::INFO::2012-11-09 06:06:43,197::task::1157::TaskManager.Task::(prepare) Task=`9438b74e-4503-4aea-ab24-b70987d9c74e`::aborting: Task is aborted: 'Unknown pool id, pool not connected' - code 309
>Thread-561::DEBUG::2012-11-09 06:06:43,197::task::1162::TaskManager.Task::(prepare) Task=`9438b74e-4503-4aea-ab24-b70987d9c74e`::Prepare: aborted: Unknown pool id, pool not connected
>Thread-561::DEBUG::2012-11-09 06:06:43,197::task::978::TaskManager.Task::(_decref) Task=`9438b74e-4503-4aea-ab24-b70987d9c74e`::ref 0 aborting True
>Thread-561::DEBUG::2012-11-09 06:06:43,197::task::913::TaskManager.Task::(_doAbort) Task=`9438b74e-4503-4aea-ab24-b70987d9c74e`::Task._doAbort: force False
>Thread-561::DEBUG::2012-11-09 06:06:43,197::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-561::DEBUG::2012-11-09 06:06:43,197::task::588::TaskManager.Task::(_updateState) Task=`9438b74e-4503-4aea-ab24-b70987d9c74e`::moving from state preparing -> state aborting
>Thread-561::DEBUG::2012-11-09 06:06:43,197::task::537::TaskManager.Task::(__state_aborting) Task=`9438b74e-4503-4aea-ab24-b70987d9c74e`::_aborting: recover policy none
>Thread-561::DEBUG::2012-11-09 06:06:43,197::task::588::TaskManager.Task::(_updateState) Task=`9438b74e-4503-4aea-ab24-b70987d9c74e`::moving from state aborting -> state failed
>Thread-561::DEBUG::2012-11-09 06:06:43,197::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-561::DEBUG::2012-11-09 06:06:43,198::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-561::ERROR::2012-11-09 06:06:43,198::dispatcher::66::Storage.Dispatcher.Protect::(run) {'status': {'message': "Unknown pool id, pool not connected: ('c02503a4-274e-11e2-b33c-002590730631',)", 'code': 309}}
>Thread-562::DEBUG::2012-11-09 06:06:43,239::BindingXMLRPC::156::vds::(wrapper) [192.168.2.113]
>Thread-562::DEBUG::2012-11-09 06:06:43,239::task::588::TaskManager.Task::(_updateState) Task=`8dad86d1-15e1-4d1b-bec7-c29f8075b323`::moving from state init -> state preparing
>Thread-562::INFO::2012-11-09 06:06:43,239::logUtils::37::dispatcher::(wrapper) Run and protect: connectStoragePool(spUUID='c02503a4-274e-11e2-b33c-002590730631', hostID=1, scsiKey='c02503a4-274e-11e2-b33c-002590730631', msdUUID='b1658676-2dc3-4357-b112-3852a056c663', masterVersion=1, options=None)
>Thread-562::DEBUG::2012-11-09 06:06:43,239::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.c02503a4-274e-11e2-b33c-002590730631`ReqID=`356f7a98-2db7-43d6-bbc9-0c5a6d3c7af1`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-562::DEBUG::2012-11-09 06:06:43,239::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.c02503a4-274e-11e2-b33c-002590730631' for lock type 'exclusive'
>Thread-562::DEBUG::2012-11-09 06:06:43,240::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.c02503a4-274e-11e2-b33c-002590730631' is free. Now locking as 'exclusive' (1 active user)
>Thread-562::DEBUG::2012-11-09 06:06:43,240::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.c02503a4-274e-11e2-b33c-002590730631`ReqID=`356f7a98-2db7-43d6-bbc9-0c5a6d3c7af1`::Granted request
>Thread-562::INFO::2012-11-09 06:06:43,240::sp::625::Storage.StoragePool::(connect) Connect host #1 to the storage pool c02503a4-274e-11e2-b33c-002590730631 with master domain: b1658676-2dc3-4357-b112-3852a056c663 (ver = 1)
>Thread-562::DEBUG::2012-11-09 06:06:43,240::lvm::457::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-562::DEBUG::2012-11-09 06:06:43,240::lvm::459::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-562::DEBUG::2012-11-09 06:06:43,240::lvm::469::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-562::DEBUG::2012-11-09 06:06:43,240::lvm::471::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-562::DEBUG::2012-11-09 06:06:43,241::lvm::490::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-562::DEBUG::2012-11-09 06:06:43,241::lvm::492::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-562::DEBUG::2012-11-09 06:06:43,241::misc::1053::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
>Thread-562::DEBUG::2012-11-09 06:06:43,241::misc::1055::SamplingMethod::(__call__) Got in to sampling method
>Thread-562::DEBUG::2012-11-09 06:06:43,241::misc::1053::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
>Thread-562::DEBUG::2012-11-09 06:06:43,241::misc::1055::SamplingMethod::(__call__) Got in to sampling method
>Thread-562::DEBUG::2012-11-09 06:06:43,241::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
>Thread-562::DEBUG::2012-11-09 06:06:43,252::__init__::1249::Storage.Misc.excCmd::(_log) FAILED: <err> = 'iscsiadm: No session found.\n'; <rc> = 21
>Thread-562::DEBUG::2012-11-09 06:06:43,252::misc::1063::SamplingMethod::(__call__) Returning last result
>Thread-562::DEBUG::2012-11-09 06:06:43,933::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/multipath' (cwd None)
>Thread-562::DEBUG::2012-11-09 06:06:43,993::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
>Thread-562::DEBUG::2012-11-09 06:06:43,993::lvm::457::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-562::DEBUG::2012-11-09 06:06:43,994::lvm::459::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-562::DEBUG::2012-11-09 06:06:43,994::lvm::469::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-562::DEBUG::2012-11-09 06:06:43,994::lvm::471::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-562::DEBUG::2012-11-09 06:06:43,994::lvm::490::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-562::DEBUG::2012-11-09 06:06:43,995::lvm::492::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-562::DEBUG::2012-11-09 06:06:43,995::misc::1063::SamplingMethod::(__call__) Returning last result
>Thread-562::DEBUG::2012-11-09 06:06:43,995::lvm::349::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
>Thread-562::DEBUG::2012-11-09 06:06:43,996::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/lvm vgs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 filter = [ \\"r%.*%\\" ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1 }  backup {  retain_min = 50  retain_days = 0 } " --noheadings --units b --nosuffix --separator | -o uuid,name,attr,size,free,extent_size,extent_count,free_count,tags,vg_mda_size,vg_mda_free b1658676-2dc3-4357-b112-3852a056c663' (cwd None)
>Thread-562::DEBUG::2012-11-09 06:06:44,047::__init__::1249::Storage.Misc.excCmd::(_log) FAILED: <err> = '  Volume group "b1658676-2dc3-4357-b112-3852a056c663" not found\n'; <rc> = 5
>Thread-562::WARNING::2012-11-09 06:06:44,049::lvm::353::Storage.LVM::(_reloadvgs) lvm vgs failed: 5 [] ['  Volume group "b1658676-2dc3-4357-b112-3852a056c663" not found']
>Thread-562::DEBUG::2012-11-09 06:06:44,049::lvm::376::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
>Thread-562::DEBUG::2012-11-09 06:06:44,051::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.c02503a4-274e-11e2-b33c-002590730631'
>Thread-562::DEBUG::2012-11-09 06:06:44,051::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.c02503a4-274e-11e2-b33c-002590730631' (0 active users)
>Thread-562::DEBUG::2012-11-09 06:06:44,052::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.c02503a4-274e-11e2-b33c-002590730631' is free, finding out if anyone is waiting for it.
>Thread-562::DEBUG::2012-11-09 06:06:44,052::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.c02503a4-274e-11e2-b33c-002590730631', Clearing records.
>Thread-562::ERROR::2012-11-09 06:06:44,052::task::853::TaskManager.Task::(_setError) Task=`8dad86d1-15e1-4d1b-bec7-c29f8075b323`::Unexpected error
>Traceback (most recent call last):
>  File "/usr/share/vdsm/storage/task.py", line 861, in _run
>    return fn(*args, **kargs)
>  File "/usr/share/vdsm/logUtils.py", line 38, in wrapper
>    res = f(*args, **kwargs)
>  File "/usr/share/vdsm/storage/hsm.py", line 817, in connectStoragePool
>    return self._connectStoragePool(spUUID, hostID, scsiKey, msdUUID, masterVersion, options)
>  File "/usr/share/vdsm/storage/hsm.py", line 859, in _connectStoragePool
>    res = pool.connect(hostID, scsiKey, msdUUID, masterVersion)
>  File "/usr/share/vdsm/storage/sp.py", line 641, in connect
>    self.__rebuild(msdUUID=msdUUID, masterVersion=masterVersion)
>  File "/usr/share/vdsm/storage/sp.py", line 1109, in __rebuild
>    self.masterDomain = self.getMasterDomain(msdUUID=msdUUID, masterVersion=masterVersion)
>  File "/usr/share/vdsm/storage/sp.py", line 1448, in getMasterDomain
>    raise se.StoragePoolMasterNotFound(self.spUUID, msdUUID)
>StoragePoolMasterNotFound: Cannot find master domain: 'spUUID=c02503a4-274e-11e2-b33c-002590730631, msdUUID=b1658676-2dc3-4357-b112-3852a056c663'
>Thread-562::DEBUG::2012-11-09 06:06:44,053::task::872::TaskManager.Task::(_run) Task=`8dad86d1-15e1-4d1b-bec7-c29f8075b323`::Task._run: 8dad86d1-15e1-4d1b-bec7-c29f8075b323 ('c02503a4-274e-11e2-b33c-002590730631', 1, 'c02503a4-274e-11e2-b33c-002590730631', 'b1658676-2dc3-4357-b112-3852a056c663', 1) {} failed - stopping task
>Thread-562::DEBUG::2012-11-09 06:06:44,053::task::1199::TaskManager.Task::(stop) Task=`8dad86d1-15e1-4d1b-bec7-c29f8075b323`::stopping in state preparing (force False)
>Thread-562::DEBUG::2012-11-09 06:06:44,053::task::978::TaskManager.Task::(_decref) Task=`8dad86d1-15e1-4d1b-bec7-c29f8075b323`::ref 1 aborting True
>Thread-562::INFO::2012-11-09 06:06:44,053::task::1157::TaskManager.Task::(prepare) Task=`8dad86d1-15e1-4d1b-bec7-c29f8075b323`::aborting: Task is aborted: 'Cannot find master domain' - code 304
>Thread-562::DEBUG::2012-11-09 06:06:44,053::task::1162::TaskManager.Task::(prepare) Task=`8dad86d1-15e1-4d1b-bec7-c29f8075b323`::Prepare: aborted: Cannot find master domain
>Thread-562::DEBUG::2012-11-09 06:06:44,053::task::978::TaskManager.Task::(_decref) Task=`8dad86d1-15e1-4d1b-bec7-c29f8075b323`::ref 0 aborting True
>Thread-562::DEBUG::2012-11-09 06:06:44,054::task::913::TaskManager.Task::(_doAbort) Task=`8dad86d1-15e1-4d1b-bec7-c29f8075b323`::Task._doAbort: force False
>Thread-562::DEBUG::2012-11-09 06:06:44,054::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-562::DEBUG::2012-11-09 06:06:44,054::task::588::TaskManager.Task::(_updateState) Task=`8dad86d1-15e1-4d1b-bec7-c29f8075b323`::moving from state preparing -> state aborting
>Thread-562::DEBUG::2012-11-09 06:06:44,054::task::537::TaskManager.Task::(__state_aborting) Task=`8dad86d1-15e1-4d1b-bec7-c29f8075b323`::_aborting: recover policy none
>Thread-562::DEBUG::2012-11-09 06:06:44,054::task::588::TaskManager.Task::(_updateState) Task=`8dad86d1-15e1-4d1b-bec7-c29f8075b323`::moving from state aborting -> state failed
>Thread-562::DEBUG::2012-11-09 06:06:44,054::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-562::DEBUG::2012-11-09 06:06:44,055::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-562::ERROR::2012-11-09 06:06:44,055::dispatcher::66::Storage.Dispatcher.Protect::(run) {'status': {'message': "Cannot find master domain: 'spUUID=c02503a4-274e-11e2-b33c-002590730631, msdUUID=b1658676-2dc3-4357-b112-3852a056c663'", 'code': 304}}
>Thread-565::DEBUG::2012-11-09 06:06:44,172::task::588::TaskManager.Task::(_updateState) Task=`8a257d95-8410-435f-998d-e9adb8a54dde`::moving from state init -> state preparing
>Thread-565::INFO::2012-11-09 06:06:44,172::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-565::INFO::2012-11-09 06:06:44,172::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
>Thread-565::DEBUG::2012-11-09 06:06:44,172::task::1172::TaskManager.Task::(prepare) Task=`8a257d95-8410-435f-998d-e9adb8a54dde`::finished: {}
>Thread-565::DEBUG::2012-11-09 06:06:44,172::task::588::TaskManager.Task::(_updateState) Task=`8a257d95-8410-435f-998d-e9adb8a54dde`::moving from state preparing -> state finished
>Thread-565::DEBUG::2012-11-09 06:06:44,172::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-565::DEBUG::2012-11-09 06:06:44,173::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-565::DEBUG::2012-11-09 06:06:44,173::task::978::TaskManager.Task::(_decref) Task=`8a257d95-8410-435f-998d-e9adb8a54dde`::ref 0 aborting False
>Thread-571::DEBUG::2012-11-09 06:06:54,253::BindingXMLRPC::156::vds::(wrapper) [192.168.2.113]
>Thread-571::DEBUG::2012-11-09 06:06:54,253::task::588::TaskManager.Task::(_updateState) Task=`aa96819f-4da1-4665-95ca-bd1b3afc24b4`::moving from state init -> state preparing
>Thread-571::INFO::2012-11-09 06:06:54,254::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='c02503a4-274e-11e2-b33c-002590730631', options=None)
>Thread-571::ERROR::2012-11-09 06:06:54,254::task::853::TaskManager.Task::(_setError) Task=`aa96819f-4da1-4665-95ca-bd1b3afc24b4`::Unexpected error
>Traceback (most recent call last):
>  File "/usr/share/vdsm/storage/task.py", line 861, in _run
>    return fn(*args, **kargs)
>  File "/usr/share/vdsm/logUtils.py", line 38, in wrapper
>    res = f(*args, **kwargs)
>  File "/usr/share/vdsm/storage/hsm.py", line 528, in getSpmStatus
>    pool = self.getPool(spUUID)
>  File "/usr/share/vdsm/storage/hsm.py", line 265, in getPool
>    raise se.StoragePoolUnknown(spUUID)
>StoragePoolUnknown: Unknown pool id, pool not connected: ('c02503a4-274e-11e2-b33c-002590730631',)
>Thread-571::DEBUG::2012-11-09 06:06:54,254::task::872::TaskManager.Task::(_run) Task=`aa96819f-4da1-4665-95ca-bd1b3afc24b4`::Task._run: aa96819f-4da1-4665-95ca-bd1b3afc24b4 ('c02503a4-274e-11e2-b33c-002590730631',) {} failed - stopping task
>Thread-571::DEBUG::2012-11-09 06:06:54,254::task::1199::TaskManager.Task::(stop) Task=`aa96819f-4da1-4665-95ca-bd1b3afc24b4`::stopping in state preparing (force False)
>Thread-571::DEBUG::2012-11-09 06:06:54,254::task::978::TaskManager.Task::(_decref) Task=`aa96819f-4da1-4665-95ca-bd1b3afc24b4`::ref 1 aborting True
>Thread-571::INFO::2012-11-09 06:06:54,255::task::1157::TaskManager.Task::(prepare) Task=`aa96819f-4da1-4665-95ca-bd1b3afc24b4`::aborting: Task is aborted: 'Unknown pool id, pool not connected' - code 309
>Thread-571::DEBUG::2012-11-09 06:06:54,255::task::1162::TaskManager.Task::(prepare) Task=`aa96819f-4da1-4665-95ca-bd1b3afc24b4`::Prepare: aborted: Unknown pool id, pool not connected
>Thread-571::DEBUG::2012-11-09 06:06:54,255::task::978::TaskManager.Task::(_decref) Task=`aa96819f-4da1-4665-95ca-bd1b3afc24b4`::ref 0 aborting True
>Thread-571::DEBUG::2012-11-09 06:06:54,255::task::913::TaskManager.Task::(_doAbort) Task=`aa96819f-4da1-4665-95ca-bd1b3afc24b4`::Task._doAbort: force False
>Thread-571::DEBUG::2012-11-09 06:06:54,255::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-571::DEBUG::2012-11-09 06:06:54,255::task::588::TaskManager.Task::(_updateState) Task=`aa96819f-4da1-4665-95ca-bd1b3afc24b4`::moving from state preparing -> state aborting
>Thread-571::DEBUG::2012-11-09 06:06:54,256::task::537::TaskManager.Task::(__state_aborting) Task=`aa96819f-4da1-4665-95ca-bd1b3afc24b4`::_aborting: recover policy none
>Thread-571::DEBUG::2012-11-09 06:06:54,256::task::588::TaskManager.Task::(_updateState) Task=`aa96819f-4da1-4665-95ca-bd1b3afc24b4`::moving from state aborting -> state failed
>Thread-571::DEBUG::2012-11-09 06:06:54,256::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-571::DEBUG::2012-11-09 06:06:54,256::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-571::ERROR::2012-11-09 06:06:54,256::dispatcher::66::Storage.Dispatcher.Protect::(run) {'status': {'message': "Unknown pool id, pool not connected: ('c02503a4-274e-11e2-b33c-002590730631',)", 'code': 309}}
>Thread-572::DEBUG::2012-11-09 06:06:54,299::BindingXMLRPC::156::vds::(wrapper) [192.168.2.113]
>Thread-572::DEBUG::2012-11-09 06:06:54,299::task::588::TaskManager.Task::(_updateState) Task=`95a6bdac-98f0-4e3e-9110-e5cd3e3fd6dd`::moving from state init -> state preparing
>Thread-572::INFO::2012-11-09 06:06:54,300::logUtils::37::dispatcher::(wrapper) Run and protect: connectStoragePool(spUUID='c02503a4-274e-11e2-b33c-002590730631', hostID=1, scsiKey='c02503a4-274e-11e2-b33c-002590730631', msdUUID='b1658676-2dc3-4357-b112-3852a056c663', masterVersion=1, options=None)
>Thread-572::DEBUG::2012-11-09 06:06:54,300::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.c02503a4-274e-11e2-b33c-002590730631`ReqID=`f4a920f3-1f7e-45f6-9ade-1336497c5f36`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-572::DEBUG::2012-11-09 06:06:54,300::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.c02503a4-274e-11e2-b33c-002590730631' for lock type 'exclusive'
>Thread-572::DEBUG::2012-11-09 06:06:54,301::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.c02503a4-274e-11e2-b33c-002590730631' is free. Now locking as 'exclusive' (1 active user)
>Thread-572::DEBUG::2012-11-09 06:06:54,301::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.c02503a4-274e-11e2-b33c-002590730631`ReqID=`f4a920f3-1f7e-45f6-9ade-1336497c5f36`::Granted request
>Thread-572::INFO::2012-11-09 06:06:54,301::sp::625::Storage.StoragePool::(connect) Connect host #1 to the storage pool c02503a4-274e-11e2-b33c-002590730631 with master domain: b1658676-2dc3-4357-b112-3852a056c663 (ver = 1)
>Thread-572::DEBUG::2012-11-09 06:06:54,302::lvm::457::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-572::DEBUG::2012-11-09 06:06:54,302::lvm::459::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-572::DEBUG::2012-11-09 06:06:54,302::lvm::469::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-572::DEBUG::2012-11-09 06:06:54,302::lvm::471::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-572::DEBUG::2012-11-09 06:06:54,303::lvm::490::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-572::DEBUG::2012-11-09 06:06:54,303::lvm::492::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-572::DEBUG::2012-11-09 06:06:54,303::misc::1053::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
>Thread-572::DEBUG::2012-11-09 06:06:54,303::misc::1055::SamplingMethod::(__call__) Got in to sampling method
>Thread-572::DEBUG::2012-11-09 06:06:54,303::misc::1053::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
>Thread-572::DEBUG::2012-11-09 06:06:54,303::misc::1055::SamplingMethod::(__call__) Got in to sampling method
>Thread-572::DEBUG::2012-11-09 06:06:54,304::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
>Thread-572::DEBUG::2012-11-09 06:06:54,315::__init__::1249::Storage.Misc.excCmd::(_log) FAILED: <err> = 'iscsiadm: No session found.\n'; <rc> = 21
>Thread-572::DEBUG::2012-11-09 06:06:54,316::misc::1063::SamplingMethod::(__call__) Returning last result
>Thread-573::DEBUG::2012-11-09 06:06:54,392::task::588::TaskManager.Task::(_updateState) Task=`a6ea5515-ae33-4540-8dd6-d49e4c745674`::moving from state init -> state preparing
>Thread-573::INFO::2012-11-09 06:06:54,393::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-573::INFO::2012-11-09 06:06:54,393::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
>Thread-573::DEBUG::2012-11-09 06:06:54,393::task::1172::TaskManager.Task::(prepare) Task=`a6ea5515-ae33-4540-8dd6-d49e4c745674`::finished: {}
>Thread-573::DEBUG::2012-11-09 06:06:54,393::task::588::TaskManager.Task::(_updateState) Task=`a6ea5515-ae33-4540-8dd6-d49e4c745674`::moving from state preparing -> state finished
>Thread-573::DEBUG::2012-11-09 06:06:54,393::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-573::DEBUG::2012-11-09 06:06:54,394::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-573::DEBUG::2012-11-09 06:06:54,394::task::978::TaskManager.Task::(_decref) Task=`a6ea5515-ae33-4540-8dd6-d49e4c745674`::ref 0 aborting False
>Thread-572::DEBUG::2012-11-09 06:06:55,026::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/multipath' (cwd None)
>Thread-572::DEBUG::2012-11-09 06:06:55,093::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
>Thread-572::DEBUG::2012-11-09 06:06:55,093::lvm::457::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-572::DEBUG::2012-11-09 06:06:55,093::lvm::459::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-572::DEBUG::2012-11-09 06:06:55,094::lvm::469::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-572::DEBUG::2012-11-09 06:06:55,094::lvm::471::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-572::DEBUG::2012-11-09 06:06:55,094::lvm::490::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-572::DEBUG::2012-11-09 06:06:55,094::lvm::492::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-572::DEBUG::2012-11-09 06:06:55,095::misc::1063::SamplingMethod::(__call__) Returning last result
>Thread-572::DEBUG::2012-11-09 06:06:55,095::lvm::349::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
>Thread-572::DEBUG::2012-11-09 06:06:55,096::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/lvm vgs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 filter = [ \\"r%.*%\\" ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1 }  backup {  retain_min = 50  retain_days = 0 } " --noheadings --units b --nosuffix --separator | -o uuid,name,attr,size,free,extent_size,extent_count,free_count,tags,vg_mda_size,vg_mda_free b1658676-2dc3-4357-b112-3852a056c663' (cwd None)
>Thread-572::DEBUG::2012-11-09 06:06:55,143::__init__::1249::Storage.Misc.excCmd::(_log) FAILED: <err> = '  Volume group "b1658676-2dc3-4357-b112-3852a056c663" not found\n'; <rc> = 5
>Thread-572::WARNING::2012-11-09 06:06:55,144::lvm::353::Storage.LVM::(_reloadvgs) lvm vgs failed: 5 [] ['  Volume group "b1658676-2dc3-4357-b112-3852a056c663" not found']
>Thread-572::DEBUG::2012-11-09 06:06:55,144::lvm::376::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
>Thread-572::DEBUG::2012-11-09 06:06:55,147::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.c02503a4-274e-11e2-b33c-002590730631'
>Thread-572::DEBUG::2012-11-09 06:06:55,147::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.c02503a4-274e-11e2-b33c-002590730631' (0 active users)
>Thread-572::DEBUG::2012-11-09 06:06:55,147::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.c02503a4-274e-11e2-b33c-002590730631' is free, finding out if anyone is waiting for it.
>Thread-572::DEBUG::2012-11-09 06:06:55,147::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.c02503a4-274e-11e2-b33c-002590730631', Clearing records.
>Thread-572::ERROR::2012-11-09 06:06:55,148::task::853::TaskManager.Task::(_setError) Task=`95a6bdac-98f0-4e3e-9110-e5cd3e3fd6dd`::Unexpected error
>Traceback (most recent call last):
>  File "/usr/share/vdsm/storage/task.py", line 861, in _run
>    return fn(*args, **kargs)
>  File "/usr/share/vdsm/logUtils.py", line 38, in wrapper
>    res = f(*args, **kwargs)
>  File "/usr/share/vdsm/storage/hsm.py", line 817, in connectStoragePool
>    return self._connectStoragePool(spUUID, hostID, scsiKey, msdUUID, masterVersion, options)
>  File "/usr/share/vdsm/storage/hsm.py", line 859, in _connectStoragePool
>    res = pool.connect(hostID, scsiKey, msdUUID, masterVersion)
>  File "/usr/share/vdsm/storage/sp.py", line 641, in connect
>    self.__rebuild(msdUUID=msdUUID, masterVersion=masterVersion)
>  File "/usr/share/vdsm/storage/sp.py", line 1109, in __rebuild
>    self.masterDomain = self.getMasterDomain(msdUUID=msdUUID, masterVersion=masterVersion)
>  File "/usr/share/vdsm/storage/sp.py", line 1448, in getMasterDomain
>    raise se.StoragePoolMasterNotFound(self.spUUID, msdUUID)
>StoragePoolMasterNotFound: Cannot find master domain: 'spUUID=c02503a4-274e-11e2-b33c-002590730631, msdUUID=b1658676-2dc3-4357-b112-3852a056c663'
>Thread-572::DEBUG::2012-11-09 06:06:55,148::task::872::TaskManager.Task::(_run) Task=`95a6bdac-98f0-4e3e-9110-e5cd3e3fd6dd`::Task._run: 95a6bdac-98f0-4e3e-9110-e5cd3e3fd6dd ('c02503a4-274e-11e2-b33c-002590730631', 1, 'c02503a4-274e-11e2-b33c-002590730631', 'b1658676-2dc3-4357-b112-3852a056c663', 1) {} failed - stopping task
>Thread-572::DEBUG::2012-11-09 06:06:55,148::task::1199::TaskManager.Task::(stop) Task=`95a6bdac-98f0-4e3e-9110-e5cd3e3fd6dd`::stopping in state preparing (force False)
>Thread-572::DEBUG::2012-11-09 06:06:55,149::task::978::TaskManager.Task::(_decref) Task=`95a6bdac-98f0-4e3e-9110-e5cd3e3fd6dd`::ref 1 aborting True
>Thread-572::INFO::2012-11-09 06:06:55,149::task::1157::TaskManager.Task::(prepare) Task=`95a6bdac-98f0-4e3e-9110-e5cd3e3fd6dd`::aborting: Task is aborted: 'Cannot find master domain' - code 304
>Thread-572::DEBUG::2012-11-09 06:06:55,149::task::1162::TaskManager.Task::(prepare) Task=`95a6bdac-98f0-4e3e-9110-e5cd3e3fd6dd`::Prepare: aborted: Cannot find master domain
>Thread-572::DEBUG::2012-11-09 06:06:55,149::task::978::TaskManager.Task::(_decref) Task=`95a6bdac-98f0-4e3e-9110-e5cd3e3fd6dd`::ref 0 aborting True
>Thread-572::DEBUG::2012-11-09 06:06:55,149::task::913::TaskManager.Task::(_doAbort) Task=`95a6bdac-98f0-4e3e-9110-e5cd3e3fd6dd`::Task._doAbort: force False
>Thread-572::DEBUG::2012-11-09 06:06:55,150::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-572::DEBUG::2012-11-09 06:06:55,150::task::588::TaskManager.Task::(_updateState) Task=`95a6bdac-98f0-4e3e-9110-e5cd3e3fd6dd`::moving from state preparing -> state aborting
>Thread-572::DEBUG::2012-11-09 06:06:55,150::task::537::TaskManager.Task::(__state_aborting) Task=`95a6bdac-98f0-4e3e-9110-e5cd3e3fd6dd`::_aborting: recover policy none
>Thread-572::DEBUG::2012-11-09 06:06:55,150::task::588::TaskManager.Task::(_updateState) Task=`95a6bdac-98f0-4e3e-9110-e5cd3e3fd6dd`::moving from state aborting -> state failed
>Thread-572::DEBUG::2012-11-09 06:06:55,150::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-572::DEBUG::2012-11-09 06:06:55,150::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-572::ERROR::2012-11-09 06:06:55,151::dispatcher::66::Storage.Dispatcher.Protect::(run) {'status': {'message': "Cannot find master domain: 'spUUID=c02503a4-274e-11e2-b33c-002590730631, msdUUID=b1658676-2dc3-4357-b112-3852a056c663'", 'code': 304}}
>Thread-581::DEBUG::2012-11-09 06:07:04,873::task::588::TaskManager.Task::(_updateState) Task=`8a4f4e69-256d-4f0f-815d-17d512ad3876`::moving from state init -> state preparing
>Thread-581::INFO::2012-11-09 06:07:04,873::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-581::INFO::2012-11-09 06:07:04,873::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
>Thread-581::DEBUG::2012-11-09 06:07:04,873::task::1172::TaskManager.Task::(prepare) Task=`8a4f4e69-256d-4f0f-815d-17d512ad3876`::finished: {}
>Thread-581::DEBUG::2012-11-09 06:07:04,873::task::588::TaskManager.Task::(_updateState) Task=`8a4f4e69-256d-4f0f-815d-17d512ad3876`::moving from state preparing -> state finished
>Thread-581::DEBUG::2012-11-09 06:07:04,873::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-581::DEBUG::2012-11-09 06:07:04,874::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-581::DEBUG::2012-11-09 06:07:04,874::task::978::TaskManager.Task::(_decref) Task=`8a4f4e69-256d-4f0f-815d-17d512ad3876`::ref 0 aborting False
>Thread-583::DEBUG::2012-11-09 06:07:05,368::BindingXMLRPC::156::vds::(wrapper) [192.168.2.113]
>Thread-583::DEBUG::2012-11-09 06:07:05,368::task::588::TaskManager.Task::(_updateState) Task=`18c112d3-f450-479e-92ae-d17f583a6ec6`::moving from state init -> state preparing
>Thread-583::INFO::2012-11-09 06:07:05,368::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='c02503a4-274e-11e2-b33c-002590730631', options=None)
>Thread-583::ERROR::2012-11-09 06:07:05,369::task::853::TaskManager.Task::(_setError) Task=`18c112d3-f450-479e-92ae-d17f583a6ec6`::Unexpected error
>Traceback (most recent call last):
>  File "/usr/share/vdsm/storage/task.py", line 861, in _run
>    return fn(*args, **kargs)
>  File "/usr/share/vdsm/logUtils.py", line 38, in wrapper
>    res = f(*args, **kwargs)
>  File "/usr/share/vdsm/storage/hsm.py", line 528, in getSpmStatus
>    pool = self.getPool(spUUID)
>  File "/usr/share/vdsm/storage/hsm.py", line 265, in getPool
>    raise se.StoragePoolUnknown(spUUID)
>StoragePoolUnknown: Unknown pool id, pool not connected: ('c02503a4-274e-11e2-b33c-002590730631',)
>Thread-583::DEBUG::2012-11-09 06:07:05,369::task::872::TaskManager.Task::(_run) Task=`18c112d3-f450-479e-92ae-d17f583a6ec6`::Task._run: 18c112d3-f450-479e-92ae-d17f583a6ec6 ('c02503a4-274e-11e2-b33c-002590730631',) {} failed - stopping task
>Thread-583::DEBUG::2012-11-09 06:07:05,369::task::1199::TaskManager.Task::(stop) Task=`18c112d3-f450-479e-92ae-d17f583a6ec6`::stopping in state preparing (force False)
>Thread-583::DEBUG::2012-11-09 06:07:05,369::task::978::TaskManager.Task::(_decref) Task=`18c112d3-f450-479e-92ae-d17f583a6ec6`::ref 1 aborting True
>Thread-583::INFO::2012-11-09 06:07:05,369::task::1157::TaskManager.Task::(prepare) Task=`18c112d3-f450-479e-92ae-d17f583a6ec6`::aborting: Task is aborted: 'Unknown pool id, pool not connected' - code 309
>Thread-583::DEBUG::2012-11-09 06:07:05,369::task::1162::TaskManager.Task::(prepare) Task=`18c112d3-f450-479e-92ae-d17f583a6ec6`::Prepare: aborted: Unknown pool id, pool not connected
>Thread-583::DEBUG::2012-11-09 06:07:05,369::task::978::TaskManager.Task::(_decref) Task=`18c112d3-f450-479e-92ae-d17f583a6ec6`::ref 0 aborting True
>Thread-583::DEBUG::2012-11-09 06:07:05,369::task::913::TaskManager.Task::(_doAbort) Task=`18c112d3-f450-479e-92ae-d17f583a6ec6`::Task._doAbort: force False
>Thread-583::DEBUG::2012-11-09 06:07:05,369::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-583::DEBUG::2012-11-09 06:07:05,369::task::588::TaskManager.Task::(_updateState) Task=`18c112d3-f450-479e-92ae-d17f583a6ec6`::moving from state preparing -> state aborting
>Thread-583::DEBUG::2012-11-09 06:07:05,370::task::537::TaskManager.Task::(__state_aborting) Task=`18c112d3-f450-479e-92ae-d17f583a6ec6`::_aborting: recover policy none
>Thread-583::DEBUG::2012-11-09 06:07:05,370::task::588::TaskManager.Task::(_updateState) Task=`18c112d3-f450-479e-92ae-d17f583a6ec6`::moving from state aborting -> state failed
>Thread-583::DEBUG::2012-11-09 06:07:05,370::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-583::DEBUG::2012-11-09 06:07:05,370::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-583::ERROR::2012-11-09 06:07:05,370::dispatcher::66::Storage.Dispatcher.Protect::(run) {'status': {'message': "Unknown pool id, pool not connected: ('c02503a4-274e-11e2-b33c-002590730631',)", 'code': 309}}
>Thread-584::DEBUG::2012-11-09 06:07:05,408::BindingXMLRPC::156::vds::(wrapper) [192.168.2.113]
>Thread-584::DEBUG::2012-11-09 06:07:05,409::task::588::TaskManager.Task::(_updateState) Task=`f0fb030b-f840-4953-8ff2-369c5f6f3be7`::moving from state init -> state preparing
>Thread-584::INFO::2012-11-09 06:07:05,409::logUtils::37::dispatcher::(wrapper) Run and protect: connectStoragePool(spUUID='c02503a4-274e-11e2-b33c-002590730631', hostID=1, scsiKey='c02503a4-274e-11e2-b33c-002590730631', msdUUID='b1658676-2dc3-4357-b112-3852a056c663', masterVersion=1, options=None)
>Thread-584::DEBUG::2012-11-09 06:07:05,410::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.c02503a4-274e-11e2-b33c-002590730631`ReqID=`47eeee21-c889-47ee-b352-646d8709e5ed`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-584::DEBUG::2012-11-09 06:07:05,410::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.c02503a4-274e-11e2-b33c-002590730631' for lock type 'exclusive'
>Thread-584::DEBUG::2012-11-09 06:07:05,410::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.c02503a4-274e-11e2-b33c-002590730631' is free. Now locking as 'exclusive' (1 active user)
>Thread-584::DEBUG::2012-11-09 06:07:05,410::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.c02503a4-274e-11e2-b33c-002590730631`ReqID=`47eeee21-c889-47ee-b352-646d8709e5ed`::Granted request
>Thread-584::INFO::2012-11-09 06:07:05,411::sp::625::Storage.StoragePool::(connect) Connect host #1 to the storage pool c02503a4-274e-11e2-b33c-002590730631 with master domain: b1658676-2dc3-4357-b112-3852a056c663 (ver = 1)
>Thread-584::DEBUG::2012-11-09 06:07:05,411::lvm::457::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-584::DEBUG::2012-11-09 06:07:05,411::lvm::459::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-584::DEBUG::2012-11-09 06:07:05,412::lvm::469::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-584::DEBUG::2012-11-09 06:07:05,412::lvm::471::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-584::DEBUG::2012-11-09 06:07:05,412::lvm::490::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-584::DEBUG::2012-11-09 06:07:05,412::lvm::492::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-584::DEBUG::2012-11-09 06:07:05,412::misc::1053::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
>Thread-584::DEBUG::2012-11-09 06:07:05,413::misc::1055::SamplingMethod::(__call__) Got in to sampling method
>Thread-584::DEBUG::2012-11-09 06:07:05,413::misc::1053::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
>Thread-584::DEBUG::2012-11-09 06:07:05,413::misc::1055::SamplingMethod::(__call__) Got in to sampling method
>Thread-584::DEBUG::2012-11-09 06:07:05,413::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
>Thread-584::DEBUG::2012-11-09 06:07:05,425::__init__::1249::Storage.Misc.excCmd::(_log) FAILED: <err> = 'iscsiadm: No session found.\n'; <rc> = 21
>Thread-584::DEBUG::2012-11-09 06:07:05,426::misc::1063::SamplingMethod::(__call__) Returning last result
>Thread-584::DEBUG::2012-11-09 06:07:06,062::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/multipath' (cwd None)
>Thread-584::DEBUG::2012-11-09 06:07:06,133::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
>Thread-584::DEBUG::2012-11-09 06:07:06,134::lvm::457::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-584::DEBUG::2012-11-09 06:07:06,134::lvm::459::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-584::DEBUG::2012-11-09 06:07:06,134::lvm::469::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-584::DEBUG::2012-11-09 06:07:06,134::lvm::471::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-584::DEBUG::2012-11-09 06:07:06,135::lvm::490::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-584::DEBUG::2012-11-09 06:07:06,135::lvm::492::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-584::DEBUG::2012-11-09 06:07:06,135::misc::1063::SamplingMethod::(__call__) Returning last result
>Thread-584::DEBUG::2012-11-09 06:07:06,135::lvm::349::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
>Thread-584::DEBUG::2012-11-09 06:07:06,136::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/lvm vgs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 filter = [ \\"r%.*%\\" ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1 }  backup {  retain_min = 50  retain_days = 0 } " --noheadings --units b --nosuffix --separator | -o uuid,name,attr,size,free,extent_size,extent_count,free_count,tags,vg_mda_size,vg_mda_free b1658676-2dc3-4357-b112-3852a056c663' (cwd None)
>Thread-584::DEBUG::2012-11-09 06:07:06,182::__init__::1249::Storage.Misc.excCmd::(_log) FAILED: <err> = '  Volume group "b1658676-2dc3-4357-b112-3852a056c663" not found\n'; <rc> = 5
>Thread-584::WARNING::2012-11-09 06:07:06,183::lvm::353::Storage.LVM::(_reloadvgs) lvm vgs failed: 5 [] ['  Volume group "b1658676-2dc3-4357-b112-3852a056c663" not found']
>Thread-584::DEBUG::2012-11-09 06:07:06,184::lvm::376::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
>Thread-584::DEBUG::2012-11-09 06:07:06,187::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.c02503a4-274e-11e2-b33c-002590730631'
>Thread-584::DEBUG::2012-11-09 06:07:06,187::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.c02503a4-274e-11e2-b33c-002590730631' (0 active users)
>Thread-584::DEBUG::2012-11-09 06:07:06,187::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.c02503a4-274e-11e2-b33c-002590730631' is free, finding out if anyone is waiting for it.
>Thread-584::DEBUG::2012-11-09 06:07:06,187::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.c02503a4-274e-11e2-b33c-002590730631', Clearing records.
>Thread-584::ERROR::2012-11-09 06:07:06,187::task::853::TaskManager.Task::(_setError) Task=`f0fb030b-f840-4953-8ff2-369c5f6f3be7`::Unexpected error
>Traceback (most recent call last):
>  File "/usr/share/vdsm/storage/task.py", line 861, in _run
>    return fn(*args, **kargs)
>  File "/usr/share/vdsm/logUtils.py", line 38, in wrapper
>    res = f(*args, **kwargs)
>  File "/usr/share/vdsm/storage/hsm.py", line 817, in connectStoragePool
>    return self._connectStoragePool(spUUID, hostID, scsiKey, msdUUID, masterVersion, options)
>  File "/usr/share/vdsm/storage/hsm.py", line 859, in _connectStoragePool
>    res = pool.connect(hostID, scsiKey, msdUUID, masterVersion)
>  File "/usr/share/vdsm/storage/sp.py", line 641, in connect
>    self.__rebuild(msdUUID=msdUUID, masterVersion=masterVersion)
>  File "/usr/share/vdsm/storage/sp.py", line 1109, in __rebuild
>    self.masterDomain = self.getMasterDomain(msdUUID=msdUUID, masterVersion=masterVersion)
>  File "/usr/share/vdsm/storage/sp.py", line 1448, in getMasterDomain
>    raise se.StoragePoolMasterNotFound(self.spUUID, msdUUID)
>StoragePoolMasterNotFound: Cannot find master domain: 'spUUID=c02503a4-274e-11e2-b33c-002590730631, msdUUID=b1658676-2dc3-4357-b112-3852a056c663'
>Thread-584::DEBUG::2012-11-09 06:07:06,187::task::872::TaskManager.Task::(_run) Task=`f0fb030b-f840-4953-8ff2-369c5f6f3be7`::Task._run: f0fb030b-f840-4953-8ff2-369c5f6f3be7 ('c02503a4-274e-11e2-b33c-002590730631', 1, 'c02503a4-274e-11e2-b33c-002590730631', 'b1658676-2dc3-4357-b112-3852a056c663', 1) {} failed - stopping task
>Thread-584::DEBUG::2012-11-09 06:07:06,187::task::1199::TaskManager.Task::(stop) Task=`f0fb030b-f840-4953-8ff2-369c5f6f3be7`::stopping in state preparing (force False)
>Thread-584::DEBUG::2012-11-09 06:07:06,187::task::978::TaskManager.Task::(_decref) Task=`f0fb030b-f840-4953-8ff2-369c5f6f3be7`::ref 1 aborting True
>Thread-584::INFO::2012-11-09 06:07:06,188::task::1157::TaskManager.Task::(prepare) Task=`f0fb030b-f840-4953-8ff2-369c5f6f3be7`::aborting: Task is aborted: 'Cannot find master domain' - code 304
>Thread-584::DEBUG::2012-11-09 06:07:06,188::task::1162::TaskManager.Task::(prepare) Task=`f0fb030b-f840-4953-8ff2-369c5f6f3be7`::Prepare: aborted: Cannot find master domain
>Thread-584::DEBUG::2012-11-09 06:07:06,188::task::978::TaskManager.Task::(_decref) Task=`f0fb030b-f840-4953-8ff2-369c5f6f3be7`::ref 0 aborting True
>Thread-584::DEBUG::2012-11-09 06:07:06,188::task::913::TaskManager.Task::(_doAbort) Task=`f0fb030b-f840-4953-8ff2-369c5f6f3be7`::Task._doAbort: force False
>Thread-584::DEBUG::2012-11-09 06:07:06,188::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-584::DEBUG::2012-11-09 06:07:06,188::task::588::TaskManager.Task::(_updateState) Task=`f0fb030b-f840-4953-8ff2-369c5f6f3be7`::moving from state preparing -> state aborting
>Thread-584::DEBUG::2012-11-09 06:07:06,188::task::537::TaskManager.Task::(__state_aborting) Task=`f0fb030b-f840-4953-8ff2-369c5f6f3be7`::_aborting: recover policy none
>Thread-584::DEBUG::2012-11-09 06:07:06,188::task::588::TaskManager.Task::(_updateState) Task=`f0fb030b-f840-4953-8ff2-369c5f6f3be7`::moving from state aborting -> state failed
>Thread-584::DEBUG::2012-11-09 06:07:06,188::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-584::DEBUG::2012-11-09 06:07:06,188::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-584::ERROR::2012-11-09 06:07:06,189::dispatcher::66::Storage.Dispatcher.Protect::(run) {'status': {'message': "Cannot find master domain: 'spUUID=c02503a4-274e-11e2-b33c-002590730631, msdUUID=b1658676-2dc3-4357-b112-3852a056c663'", 'code': 304}}
>Thread-591::DEBUG::2012-11-09 06:07:15,061::task::588::TaskManager.Task::(_updateState) Task=`798c9ac6-bfa9-4d1e-818a-67e9d7295e40`::moving from state init -> state preparing
>Thread-591::INFO::2012-11-09 06:07:15,061::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=None)
>Thread-591::INFO::2012-11-09 06:07:15,061::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
>Thread-591::DEBUG::2012-11-09 06:07:15,062::task::1172::TaskManager.Task::(prepare) Task=`798c9ac6-bfa9-4d1e-818a-67e9d7295e40`::finished: {}
>Thread-591::DEBUG::2012-11-09 06:07:15,062::task::588::TaskManager.Task::(_updateState) Task=`798c9ac6-bfa9-4d1e-818a-67e9d7295e40`::moving from state preparing -> state finished
>Thread-591::DEBUG::2012-11-09 06:07:15,062::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-591::DEBUG::2012-11-09 06:07:15,062::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-591::DEBUG::2012-11-09 06:07:15,062::task::978::TaskManager.Task::(_decref) Task=`798c9ac6-bfa9-4d1e-818a-67e9d7295e40`::ref 0 aborting False
>Thread-593::DEBUG::2012-11-09 06:07:16,412::BindingXMLRPC::156::vds::(wrapper) [192.168.2.113]
>Thread-593::DEBUG::2012-11-09 06:07:16,412::task::588::TaskManager.Task::(_updateState) Task=`23005315-3aae-4ca7-bbe4-8c71b4e850c6`::moving from state init -> state preparing
>Thread-593::INFO::2012-11-09 06:07:16,413::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='c02503a4-274e-11e2-b33c-002590730631', options=None)
>Thread-593::ERROR::2012-11-09 06:07:16,413::task::853::TaskManager.Task::(_setError) Task=`23005315-3aae-4ca7-bbe4-8c71b4e850c6`::Unexpected error
>Traceback (most recent call last):
>  File "/usr/share/vdsm/storage/task.py", line 861, in _run
>    return fn(*args, **kargs)
>  File "/usr/share/vdsm/logUtils.py", line 38, in wrapper
>    res = f(*args, **kwargs)
>  File "/usr/share/vdsm/storage/hsm.py", line 528, in getSpmStatus
>    pool = self.getPool(spUUID)
>  File "/usr/share/vdsm/storage/hsm.py", line 265, in getPool
>    raise se.StoragePoolUnknown(spUUID)
>StoragePoolUnknown: Unknown pool id, pool not connected: ('c02503a4-274e-11e2-b33c-002590730631',)
>Thread-593::DEBUG::2012-11-09 06:07:16,413::task::872::TaskManager.Task::(_run) Task=`23005315-3aae-4ca7-bbe4-8c71b4e850c6`::Task._run: 23005315-3aae-4ca7-bbe4-8c71b4e850c6 ('c02503a4-274e-11e2-b33c-002590730631',) {} failed - stopping task
>Thread-593::DEBUG::2012-11-09 06:07:16,413::task::1199::TaskManager.Task::(stop) Task=`23005315-3aae-4ca7-bbe4-8c71b4e850c6`::stopping in state preparing (force False)
>Thread-593::DEBUG::2012-11-09 06:07:16,414::task::978::TaskManager.Task::(_decref) Task=`23005315-3aae-4ca7-bbe4-8c71b4e850c6`::ref 1 aborting True
>Thread-593::INFO::2012-11-09 06:07:16,414::task::1157::TaskManager.Task::(prepare) Task=`23005315-3aae-4ca7-bbe4-8c71b4e850c6`::aborting: Task is aborted: 'Unknown pool id, pool not connected' - code 309
>Thread-593::DEBUG::2012-11-09 06:07:16,414::task::1162::TaskManager.Task::(prepare) Task=`23005315-3aae-4ca7-bbe4-8c71b4e850c6`::Prepare: aborted: Unknown pool id, pool not connected
>Thread-593::DEBUG::2012-11-09 06:07:16,414::task::978::TaskManager.Task::(_decref) Task=`23005315-3aae-4ca7-bbe4-8c71b4e850c6`::ref 0 aborting True
>Thread-593::DEBUG::2012-11-09 06:07:16,414::task::913::TaskManager.Task::(_doAbort) Task=`23005315-3aae-4ca7-bbe4-8c71b4e850c6`::Task._doAbort: force False
>Thread-593::DEBUG::2012-11-09 06:07:16,414::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-593::DEBUG::2012-11-09 06:07:16,415::task::588::TaskManager.Task::(_updateState) Task=`23005315-3aae-4ca7-bbe4-8c71b4e850c6`::moving from state preparing -> state aborting
>Thread-593::DEBUG::2012-11-09 06:07:16,415::task::537::TaskManager.Task::(__state_aborting) Task=`23005315-3aae-4ca7-bbe4-8c71b4e850c6`::_aborting: recover policy none
>Thread-593::DEBUG::2012-11-09 06:07:16,415::task::588::TaskManager.Task::(_updateState) Task=`23005315-3aae-4ca7-bbe4-8c71b4e850c6`::moving from state aborting -> state failed
>Thread-593::DEBUG::2012-11-09 06:07:16,415::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-593::DEBUG::2012-11-09 06:07:16,415::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-593::ERROR::2012-11-09 06:07:16,415::dispatcher::66::Storage.Dispatcher.Protect::(run) {'status': {'message': "Unknown pool id, pool not connected: ('c02503a4-274e-11e2-b33c-002590730631',)", 'code': 309}}
>Thread-594::DEBUG::2012-11-09 06:07:16,460::BindingXMLRPC::156::vds::(wrapper) [192.168.2.113]
>Thread-594::DEBUG::2012-11-09 06:07:16,460::task::588::TaskManager.Task::(_updateState) Task=`d9aea9c2-6d55-4074-bf80-2044dc33a908`::moving from state init -> state preparing
>Thread-594::INFO::2012-11-09 06:07:16,460::logUtils::37::dispatcher::(wrapper) Run and protect: connectStoragePool(spUUID='c02503a4-274e-11e2-b33c-002590730631', hostID=1, scsiKey='c02503a4-274e-11e2-b33c-002590730631', msdUUID='b1658676-2dc3-4357-b112-3852a056c663', masterVersion=1, options=None)
>Thread-594::DEBUG::2012-11-09 06:07:16,461::resourceManager::175::ResourceManager.Request::(__init__) ResName=`Storage.c02503a4-274e-11e2-b33c-002590730631`ReqID=`c92a49a1-a9c1-4896-b504-3abd2d7213a7`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at 'registerResource'
>Thread-594::DEBUG::2012-11-09 06:07:16,461::resourceManager::486::ResourceManager::(registerResource) Trying to register resource 'Storage.c02503a4-274e-11e2-b33c-002590730631' for lock type 'exclusive'
>Thread-594::DEBUG::2012-11-09 06:07:16,461::resourceManager::528::ResourceManager::(registerResource) Resource 'Storage.c02503a4-274e-11e2-b33c-002590730631' is free. Now locking as 'exclusive' (1 active user)
>Thread-594::DEBUG::2012-11-09 06:07:16,461::resourceManager::212::ResourceManager.Request::(grant) ResName=`Storage.c02503a4-274e-11e2-b33c-002590730631`ReqID=`c92a49a1-a9c1-4896-b504-3abd2d7213a7`::Granted request
>Thread-594::INFO::2012-11-09 06:07:16,462::sp::625::Storage.StoragePool::(connect) Connect host #1 to the storage pool c02503a4-274e-11e2-b33c-002590730631 with master domain: b1658676-2dc3-4357-b112-3852a056c663 (ver = 1)
>Thread-594::DEBUG::2012-11-09 06:07:16,462::lvm::457::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-594::DEBUG::2012-11-09 06:07:16,463::lvm::459::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-594::DEBUG::2012-11-09 06:07:16,463::lvm::469::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-594::DEBUG::2012-11-09 06:07:16,463::lvm::471::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-594::DEBUG::2012-11-09 06:07:16,463::lvm::490::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-594::DEBUG::2012-11-09 06:07:16,463::lvm::492::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-594::DEBUG::2012-11-09 06:07:16,464::misc::1053::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
>Thread-594::DEBUG::2012-11-09 06:07:16,464::misc::1055::SamplingMethod::(__call__) Got in to sampling method
>Thread-594::DEBUG::2012-11-09 06:07:16,464::misc::1053::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
>Thread-594::DEBUG::2012-11-09 06:07:16,464::misc::1055::SamplingMethod::(__call__) Got in to sampling method
>Thread-594::DEBUG::2012-11-09 06:07:16,464::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
>Thread-594::DEBUG::2012-11-09 06:07:16,476::__init__::1249::Storage.Misc.excCmd::(_log) FAILED: <err> = 'iscsiadm: No session found.\n'; <rc> = 21
>Thread-594::DEBUG::2012-11-09 06:07:16,476::misc::1063::SamplingMethod::(__call__) Returning last result
>Thread-594::DEBUG::2012-11-09 06:07:17,124::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/multipath' (cwd None)
>Thread-594::DEBUG::2012-11-09 06:07:17,190::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err> = ''; <rc> = 0
>Thread-594::DEBUG::2012-11-09 06:07:17,191::lvm::457::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-594::DEBUG::2012-11-09 06:07:17,191::lvm::459::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-594::DEBUG::2012-11-09 06:07:17,191::lvm::469::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-594::DEBUG::2012-11-09 06:07:17,192::lvm::471::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-594::DEBUG::2012-11-09 06:07:17,192::lvm::490::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-594::DEBUG::2012-11-09 06:07:17,192::lvm::492::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-594::DEBUG::2012-11-09 06:07:17,192::misc::1063::SamplingMethod::(__call__) Returning last result
>Thread-594::DEBUG::2012-11-09 06:07:17,193::lvm::349::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
>Thread-594::DEBUG::2012-11-09 06:07:17,194::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -n /sbin/lvm vgs --config " devices { preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0 disable_after_error_count=3 filter = [ \\"r%.*%\\" ] }  global {  locking_type=1  prioritise_write_locks=1  wait_for_locks=1 }  backup {  retain_min = 50  retain_days = 0 } " --noheadings --units b --nosuffix --separator | -o uuid,name,attr,size,free,extent_size,extent_count,free_count,tags,vg_mda_size,vg_mda_free b1658676-2dc3-4357-b112-3852a056c663' (cwd None)
>Thread-594::DEBUG::2012-11-09 06:07:17,242::__init__::1249::Storage.Misc.excCmd::(_log) FAILED: <err> = '  Volume group "b1658676-2dc3-4357-b112-3852a056c663" not found\n'; <rc> = 5
>Thread-594::WARNING::2012-11-09 06:07:17,243::lvm::353::Storage.LVM::(_reloadvgs) lvm vgs failed: 5 [] ['  Volume group "b1658676-2dc3-4357-b112-3852a056c663" not found']
>Thread-594::DEBUG::2012-11-09 06:07:17,243::lvm::376::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
>Thread-594::DEBUG::2012-11-09 06:07:17,246::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.c02503a4-274e-11e2-b33c-002590730631'
>Thread-594::DEBUG::2012-11-09 06:07:17,246::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.c02503a4-274e-11e2-b33c-002590730631' (0 active users)
>Thread-594::DEBUG::2012-11-09 06:07:17,246::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.c02503a4-274e-11e2-b33c-002590730631' is free, finding out if anyone is waiting for it.
>Thread-594::DEBUG::2012-11-09 06:07:17,247::resourceManager::565::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.c02503a4-274e-11e2-b33c-002590730631', Clearing records.
>Thread-594::ERROR::2012-11-09 06:07:17,247::task::853::TaskManager.Task::(_setError) Task=`d9aea9c2-6d55-4074-bf80-2044dc33a908`::Unexpected error
>Traceback (most recent call last):
>  File "/usr/share/vdsm/storage/task.py", line 861, in _run
>    return fn(*args, **kargs)
>  File "/usr/share/vdsm/logUtils.py", line 38, in wrapper
>    res = f(*args, **kwargs)
>  File "/usr/share/vdsm/storage/hsm.py", line 817, in connectStoragePool
>    return self._connectStoragePool(spUUID, hostID, scsiKey, msdUUID, masterVersion, options)
>  File "/usr/share/vdsm/storage/hsm.py", line 859, in _connectStoragePool
>    res = pool.connect(hostID, scsiKey, msdUUID, masterVersion)
>  File "/usr/share/vdsm/storage/sp.py", line 641, in connect
>    self.__rebuild(msdUUID=msdUUID, masterVersion=masterVersion)
>  File "/usr/share/vdsm/storage/sp.py", line 1109, in __rebuild
>    self.masterDomain = self.getMasterDomain(msdUUID=msdUUID, masterVersion=masterVersion)
>  File "/usr/share/vdsm/storage/sp.py", line 1448, in getMasterDomain
>    raise se.StoragePoolMasterNotFound(self.spUUID, msdUUID)
>StoragePoolMasterNotFound: Cannot find master domain: 'spUUID=c02503a4-274e-11e2-b33c-002590730631, msdUUID=b1658676-2dc3-4357-b112-3852a056c663'
>Thread-594::DEBUG::2012-11-09 06:07:17,247::task::872::TaskManager.Task::(_run) Task=`d9aea9c2-6d55-4074-bf80-2044dc33a908`::Task._run: d9aea9c2-6d55-4074-bf80-2044dc33a908 ('c02503a4-274e-11e2-b33c-002590730631', 1, 'c02503a4-274e-11e2-b33c-002590730631', 'b1658676-2dc3-4357-b112-3852a056c663', 1) {} failed - stopping task
>Thread-594::DEBUG::2012-11-09 06:07:17,247::task::1199::TaskManager.Task::(stop) Task=`d9aea9c2-6d55-4074-bf80-2044dc33a908`::stopping in state preparing (force False)
>Thread-594::DEBUG::2012-11-09 06:07:17,248::task::978::TaskManager.Task::(_decref) Task=`d9aea9c2-6d55-4074-bf80-2044dc33a908`::ref 1 aborting True
>Thread-594::INFO::2012-11-09 06:07:17,248::task::1157::TaskManager.Task::(prepare) Task=`d9aea9c2-6d55-4074-bf80-2044dc33a908`::aborting: Task is aborted: 'Cannot find master domain' - code 304
>Thread-594::DEBUG::2012-11-09 06:07:17,248::task::1162::TaskManager.Task::(prepare) Task=`d9aea9c2-6d55-4074-bf80-2044dc33a908`::Prepare: aborted: Cannot find master domain
>Thread-594::DEBUG::2012-11-09 06:07:17,248::task::978::TaskManager.Task::(_decref) Task=`d9aea9c2-6d55-4074-bf80-2044dc33a908`::ref 0 aborting True
>Thread-594::DEBUG::2012-11-09 06:07:17,249::task::913::TaskManager.Task::(_doAbort) Task=`d9aea9c2-6d55-4074-bf80-2044dc33a908`::Task._doAbort: force False
>Thread-594::DEBUG::2012-11-09 06:07:17,249::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-594::DEBUG::2012-11-09 06:07:17,249::task::588::TaskManager.Task::(_updateState) Task=`d9aea9c2-6d55-4074-bf80-2044dc33a908`::moving from state preparing -> state aborting
>Thread-594::DEBUG::2012-11-09 06:07:17,249::task::537::TaskManager.Task::(__state_aborting) Task=`d9aea9c2-6d55-4074-bf80-2044dc33a908`::_aborting: recover policy none
>Thread-594::DEBUG::2012-11-09 06:07:17,249::task::588::TaskManager.Task::(_updateState) Task=`d9aea9c2-6d55-4074-bf80-2044dc33a908`::moving from state aborting -> state failed
>Thread-594::DEBUG::2012-11-09 06:07:17,249::resourceManager::809::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-594::DEBUG::2012-11-09 06:07:17,250::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-594::ERROR::2012-11-09 06:07:17,250::dispatcher::66::Storage.Dispatcher.Protect::(run) {'status': {'message': "Cannot find master domain: 'spUUID=c02503a4-274e-11e2-b33c-002590730631, msdUUID=b1658676-2dc3-4357-b112-3852a056c663'", 'code': 304}}

Actions: View

Attachments on bug 874120: 640114 | 641526 | 641527