[ovirt-users] Storage Domain Not Found After upgrade from 3.3.2 to 3.4

Friday, 25 April 2014

Hi,

I have an All-in-one installation engine node and an Ovirt node. They 
each use local storage and are thus configured in separate Data 
Centres.  I upgraded both from 3.3.2 to 3.4 and this completed without 
error.  I completed the engine-setup upgrade and this complete ok.  I 
rebooted both the servers and the Ovirt engine node worked fine and I 
could start it's VMs.  The Ovirt Node's datacenter is not activating, 
which seems to be due to none of the storage domains coming online.  
I've checked and the storage is mounted and available fine on the Ovirt 
node.

Looking at the vdsm.log I can see errors stating that it can't find the 
storage domain.  I have restored the entire node back to the pre-upgrade 
state and it works fine.  It breaks again when I upgrade it.  The 
approach I used was to put the Ovirt node in maintenance mode and run 
yum update.  Anybody have similar issues or understand the log errors below?

Traceback (most recent call last):
   File "/usr/share/vdsm/storage/dispatcher.py", line 60, in run
     result = ctask.prepare(self.func, *args, **kwargs)
   File "/usr/share/vdsm/storage/task.py", line 103, in wrapper
     return m(self, *a, **kw)
   File "/usr/share/vdsm/storage/task.py", line 1176, in prepare
     raise self.error
SecureError: Secured object is not in safe state
Thread-180::DEBUG::2014-04-25 
19:58:17,581::BindingXMLRPC::251::vds::(wrapper) client [10.50.0.18] 
flowID [21f7a1a7]
Thread-180::DEBUG::2014-04-25 
19:58:17,581::task::595::TaskManager.Task::(_updateState) 
Task=`545a6b49-bcd5-4e42-b64c-ee99329d3b7a`::moving from state init -> 
state preparing
Thread-180::INFO::2014-04-25 
19:58:17,582::logUtils::44::dispatcher::(wrapper) Run and protect: 
getSpmStatus(spUUID='c713062f-300f-4256-9ac8-2d3fcfcdb002', options=None)
Thread-180::INFO::2014-04-25 
19:58:17,582::logUtils::47::dispatcher::(wrapper) Run and protect: 
getSpmStatus, Return response: {'spm_st': {'spmId': -1,
'spmStatus': 
'Free', 'spmLver': -1}}
Thread-180::DEBUG::2014-04-25 
19:58:17,582::task::1185::TaskManager.Task::(prepare) 
Task=`545a6b49-bcd5-4e42-b64c-ee99329d3b7a`::finished: {'spm_st': 
{'spmId': -1, 'spmStatus': 'Free', 'spmLver': -1}}
Thread-180::DEBUG::2014-04-25 
19:58:17,582::task::595::TaskManager.Task::(_updateState) 
Task=`545a6b49-bcd5-4e42-b64c-ee99329d3b7a`::moving from state preparing 
-> state finished
Thread-180::DEBUG::2014-04-25 
19:58:17,582::resourceManager::940::ResourceManager.Owner::(releaseAll) 
Owner.releaseAll requests {} resources {}
Thread-180::DEBUG::2014-04-25 
19:58:17,582::resourceManager::977::ResourceManager.Owner::(cancelAll) 
Owner.cancelAll requests {}
Thread-180::DEBUG::2014-04-25 
19:58:17,582::task::990::TaskManager.Task::(_decref) 
Task=`545a6b49-bcd5-4e42-b64c-ee99329d3b7a`::ref 0 aborting False
Thread-180::DEBUG::2014-04-25 
19:58:17,732::BindingXMLRPC::251::vds::(wrapper) client [10.50.0.18] 
flowID [21f7a1a7]
Thread-180::DEBUG::2014-04-25 
19:58:17,733::task::595::TaskManager.Task::(_updateState) 
Task=`b9623891-cda5-4ac3-b4ab-efde3cc5ac97`::moving from state init -> 
state preparing
Thread-180::INFO::2014-04-25 
19:58:17,733::logUtils::44::dispatcher::(wrapper) Run and protect: 
spmStart(spUUID='c713062f-300f-4256-9ac8-2d3fcfcdb002', prevID=-1, 
prevLVER='-1', maxHostID=250, domVersion='3', options=None)
Thread-180::DEBUG::2014-04-25 
19:58:17,733::resourceManager::198::ResourceManager.Request::(__init__) 
ResName=`Storage.c713062f-300f-4256-9ac8-2d3fcfcdb002`ReqID=`ce97fd39-373c-4464-9921-2180f0f2e2c5`::Request

was made in '/usr/share/vdsm/storage/hsm.py' line '577' at
'spmStart'
Thread-180::DEBUG::2014-04-25 
19:58:17,733::resourceManager::542::ResourceManager::(registerResource) 
Trying to register resource 
'Storage.c713062f-300f-4256-9ac8-2d3fcfcdb002' for lock type 'exclusive'
Thread-180::DEBUG::2014-04-25 
19:58:17,733::resourceManager::601::ResourceManager::(registerResource) 
Resource 'Storage.c713062f-300f-4256-9ac8-2d3fcfcdb002' is free. Now 
locking as 'exclusive' (1 active user)
Thread-180::DEBUG::2014-04-25 
19:58:17,733::resourceManager::238::ResourceManager.Request::(grant) 
ResName=`Storage.c713062f-300f-4256-9ac8-2d3fcfcdb002`ReqID=`ce97fd39-373c-4464-9921-2180f0f2e2c5`::Granted

request
Thread-180::DEBUG::2014-04-25 
19:58:17,734::task::827::TaskManager.Task::(resourceAcquired) 
Task=`b9623891-cda5-4ac3-b4ab-efde3cc5ac97`::_resourcesAcquired: 
Storage.c713062f-300f-4256-9ac8-2d3fcfcdb002 (exclusive)
Thread-180::DEBUG::2014-04-25 
19:58:17,734::task::990::TaskManager.Task::(_decref) 
Task=`b9623891-cda5-4ac3-b4ab-efde3cc5ac97`::ref 1 aborting False
Thread-180::INFO::2014-04-25 
19:58:17,734::logUtils::47::dispatcher::(wrapper) Run and protect: 
spmStart, Return response: None
Thread-180::DEBUG::2014-04-25 
19:58:17,734::task::1180::TaskManager.Task::(prepare) 
Task=`b9623891-cda5-4ac3-b4ab-efde3cc5ac97`::Prepare: 1 jobs exist, move 
to acquiring
Thread-180::DEBUG::2014-04-25 
19:58:17,734::task::595::TaskManager.Task::(_updateState) 
Task=`b9623891-cda5-4ac3-b4ab-efde3cc5ac97`::moving from state preparing 
-> state acquiring
Thread-180::DEBUG::2014-04-25 
19:58:17,734::task::595::TaskManager.Task::(_updateState) 
Task=`b9623891-cda5-4ac3-b4ab-efde3cc5ac97`::moving from state acquiring 
-> state queued
Thread-180::DEBUG::2014-04-25 
19:58:17,734::taskManager::50::TaskManager::(_queueTask) queuing task: 
b9623891-cda5-4ac3-b4ab-efde3cc5ac97
Thread-180::DEBUG::2014-04-25 
19:58:17,734::taskManager::56::TaskManager::(_queueTask) task queued: 
b9623891-cda5-4ac3-b4ab-efde3cc5ac97
Thread-180::DEBUG::2014-04-25 
19:58:17,734::task::1182::TaskManager.Task::(prepare) 
Task=`b9623891-cda5-4ac3-b4ab-efde3cc5ac97`::returning
Thread-180::DEBUG::2014-04-25 
19:58:17,735::task::990::TaskManager.Task::(_decref) 
Task=`b9623891-cda5-4ac3-b4ab-efde3cc5ac97`::ref 0 aborting False
Thread-2::DEBUG::2014-04-25 
19:58:17,735::threadPool::57::Misc.ThreadPool::(setRunningTask) Number 
of running tasks: 1
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,735::threadPool::200::Misc.ThreadPool.WorkerThread::(_processNextTask) 
Task: b9623891-cda5-4ac3-b4ab-efde3cc5ac97 running: <bound method 
Task.commit of <storage.task.Task instance at 0x7f95a41007e8>> with: None
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,735::task::1194::TaskManager.Task::(commit) 
Task=`b9623891-cda5-4ac3-b4ab-efde3cc5ac97`::committing task: 
b9623891-cda5-4ac3-b4ab-efde3cc5ac97
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,735::task::595::TaskManager.Task::(_updateState) 
Task=`b9623891-cda5-4ac3-b4ab-efde3cc5ac97`::moving from state queued -> 
state running
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,736::task::905::TaskManager.Task::(_runJobs) 
Task=`b9623891-cda5-4ac3-b4ab-efde3cc5ac97`::Task.run: running job 0: 
spmStart: <bound method StoragePool.startSpm of <storage.sp.StoragePool 
object at 0x7f95a4195cd0>> (args: (-1, '-1', 250, 3) kwargs: {})
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,736::task::331::TaskManager.Task::(run) 
Task=`b9623891-cda5-4ac3-b4ab-efde3cc5ac97`::Job.run: running spmStart: 
<bound method StoragePool.startSpm of <storage.sp.StoragePool object at 
0x7f95a4195cd0>> (args: (-1, '-1', 250, 3) kwargs: {}) callback None
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,736::misc::762::SamplingMethod::(__call__) Trying to enter 
sampling method (storage.sp.updateMonitoringThreads)
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,736::misc::764::SamplingMethod::(__call__) Got in to sampling 
method
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,746::persistentDict::234::Storage.PersistentDict::(refresh) 
read lines (FileMetadataRW)=['CLASS=Data', 
'DESCRIPTION=s2data1_s2mgt_boot1', 'IOOPTIMEOUTSEC=10', 
'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 
'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=1', 
'POOL_DESCRIPTION=BDS_DataCentre2', 
'POOL_DOMAINS=7b083758-45f9-4896-913d-11fe02043e6e:Active,e637bb04-a8b7-4c77-809c-d58051494c52:Active,0a897f2e-1b01-4577-9f91-cd136ef4a978:Active,c2c4ade6-049e-4159-a294-a0c151f4983d:Active,9a4a80a1-5377-4a94-ade3-e58183e916ae:Active',

'POOL_SPM_ID=-1', 'POOL_SPM_LVER=0', 
'POOL_UUID=c713062f-300f-4256-9ac8-2d3fcfcdb002', 
'REMOTE_PATH=/vdsm_store/s2data1_s2mgt_boot1', 'ROLE=Master', 
'SDUUID=0a897f2e-1b01-4577-9f91-cd136ef4a978', 'TYPE=LOCALFS', 
'VERSION=3', '_SHA_CKSUM=afe618d7596d75d0fb96453bcdd34a1255534454']
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,746::misc::772::SamplingMethod::(__call__) Returning last result
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,746::clusterlock::337::LocalLock::(acquireHostId) Host id for 
domain 0a897f2e-1b01-4577-9f91-cd136ef4a978 successfully acquired (id: 1)
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::INFO::2014-04-25 
19:58:17,746::clusterlock::365::LocalLock::(acquire) Acquiring local 
lock for domain 0a897f2e-1b01-4577-9f91-cd136ef4a978 (id: 1)
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,746::clusterlock::400::LocalLock::(acquire) Local lock for 
domain 0a897f2e-1b01-4577-9f91-cd136ef4a978 successfully acquired (id: 1)
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,746::sp::266::Storage.StoragePool::(startSpm) spm lock acquired 
successfully
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,756::persistentDict::234::Storage.PersistentDict::(refresh) 
read lines (FileMetadataRW)=['CLASS=Data', 
'DESCRIPTION=s2data1_s2mgt_boot1', 'IOOPTIMEOUTSEC=10', 
'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 
'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=1', 
'POOL_DESCRIPTION=BDS_DataCentre2', 
'POOL_DOMAINS=7b083758-45f9-4896-913d-11fe02043e6e:Active,e637bb04-a8b7-4c77-809c-d58051494c52:Active,0a897f2e-1b01-4577-9f91-cd136ef4a978:Active,c2c4ade6-049e-4159-a294-a0c151f4983d:Active,9a4a80a1-5377-4a94-ade3-e58183e916ae:Active',

'POOL_SPM_ID=-1', 'POOL_SPM_LVER=0', 
'POOL_UUID=c713062f-300f-4256-9ac8-2d3fcfcdb002', 
'REMOTE_PATH=/vdsm_store/s2data1_s2mgt_boot1', 'ROLE=Master', 
'SDUUID=0a897f2e-1b01-4577-9f91-cd136ef4a978', 'TYPE=LOCALFS', 
'VERSION=3', '_SHA_CKSUM=afe618d7596d75d0fb96453bcdd34a1255534454']
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,756::persistentDict::167::Storage.PersistentDict::(transaction) 
Starting transaction
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,756::persistentDict::173::Storage.PersistentDict::(transaction) 
Flushing changes
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,756::persistentDict::299::Storage.PersistentDict::(flush) about 
to write lines (FileMetadataRW)=['CLASS=Data', 
'DESCRIPTION=s2data1_s2mgt_boot1', 'IOOPTIMEOUTSEC=10', 
'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 
'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=1', 
'POOL_DESCRIPTION=BDS_DataCentre2', 
'POOL_DOMAINS=7b083758-45f9-4896-913d-11fe02043e6e:Active,e637bb04-a8b7-4c77-809c-d58051494c52:Active,0a897f2e-1b01-4577-9f91-cd136ef4a978:Active,c2c4ade6-049e-4159-a294-a0c151f4983d:Active,9a4a80a1-5377-4a94-ade3-e58183e916ae:Active',

'POOL_SPM_ID=1', 'POOL_SPM_LVER=0', 
'POOL_UUID=c713062f-300f-4256-9ac8-2d3fcfcdb002', 
'REMOTE_PATH=/vdsm_store/s2data1_s2mgt_boot1', 'ROLE=Master', 
'SDUUID=0a897f2e-1b01-4577-9f91-cd136ef4a978', 'TYPE=LOCALFS', 
'VERSION=3', '_SHA_CKSUM=68a337432f9f1794a057deb08eb27f6bb3513470']
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,757::persistentDict::175::Storage.PersistentDict::(transaction) 
Finished transaction
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,757::resourceManager::198::ResourceManager.Request::(__init__) 
ResName=`Storage.upgrade_c713062f-300f-4256-9ac8-2d3fcfcdb002`ReqID=`479828cf-c60b-465a-96f8-edc76af93804`::Request

was made in '/usr/share/vdsm/storage/sp.py' line '425' at
'_upgradePool'
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,757::resourceManager::542::ResourceManager::(registerResource) 
Trying to register resource 
'Storage.upgrade_c713062f-300f-4256-9ac8-2d3fcfcdb002' for lock type 
'exclusive'
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,757::resourceManager::601::ResourceManager::(registerResource) 
Resource 'Storage.upgrade_c713062f-300f-4256-9ac8-2d3fcfcdb002' is free. 
Now locking as 'exclusive' (1 active user)
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,758::resourceManager::238::ResourceManager.Request::(grant) 
ResName=`Storage.upgrade_c713062f-300f-4256-9ac8-2d3fcfcdb002`ReqID=`479828cf-c60b-465a-96f8-edc76af93804`::Granted

request
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::INFO::2014-04-25 
19:58:17,758::sp::431::Storage.StoragePool::(_upgradePool) Trying to 
upgrade master domain `0a897f2e-1b01-4577-9f91-cd136ef4a978`
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,759::resourceManager::198::ResourceManager.Request::(__init__) 
ResName=`Storage.0a897f2e-1b01-4577-9f91-cd136ef4a978`ReqID=`cb5a1648-5020-4509-9d9e-60db98cf7c75`::Request

was made in '/usr/share/vdsm/storage/sp.py' line '433' at
'_upgradePool'
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,759::resourceManager::542::ResourceManager::(registerResource) 
Trying to register resource 
'Storage.0a897f2e-1b01-4577-9f91-cd136ef4a978' for lock type 'exclusive'
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,759::resourceManager::601::ResourceManager::(registerResource) 
Resource 'Storage.0a897f2e-1b01-4577-9f91-cd136ef4a978' is free. Now 
locking as 'exclusive' (1 active user)
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,759::resourceManager::238::ResourceManager.Request::(grant) 
ResName=`Storage.0a897f2e-1b01-4577-9f91-cd136ef4a978`ReqID=`cb5a1648-5020-4509-9d9e-60db98cf7c75`::Granted

request
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,761::fileSD::140::Storage.StorageDomain::(__init__) Reading 
domain in path 
/rhev/data-center/mnt/_vdsm__store_s2data1__s2mgt__boot1/0a897f2e-1b01-4577-9f91-cd136ef4a978
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,761::persistentDict::192::Storage.PersistentDict::(__init__) 
Created a persistent dict with FileMetadataRW backend
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,770::persistentDict::234::Storage.PersistentDict::(refresh) 
read lines (FileMetadataRW)=['CLASS=Data', 
'DESCRIPTION=s2data1_s2mgt_boot1', 'IOOPTIMEOUTSEC=10', 
'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 
'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=1', 
'POOL_DESCRIPTION=BDS_DataCentre2', 
'POOL_DOMAINS=7b083758-45f9-4896-913d-11fe02043e6e:Active,e637bb04-a8b7-4c77-809c-d58051494c52:Active,0a897f2e-1b01-4577-9f91-cd136ef4a978:Active,c2c4ade6-049e-4159-a294-a0c151f4983d:Active,9a4a80a1-5377-4a94-ade3-e58183e916ae:Active',

'POOL_SPM_ID=1', 'POOL_SPM_LVER=0', 
'POOL_UUID=c713062f-300f-4256-9ac8-2d3fcfcdb002', 
'REMOTE_PATH=/vdsm_store/s2data1_s2mgt_boot1', 'ROLE=Master', 
'SDUUID=0a897f2e-1b01-4577-9f91-cd136ef4a978', 'TYPE=LOCALFS', 
'VERSION=3', '_SHA_CKSUM=68a337432f9f1794a057deb08eb27f6bb3513470']
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,771::fileSD::575::Storage.StorageDomain::(imageGarbageCollector) Removing 
remnants of deleted images []
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::INFO::2014-04-25 
19:58:17,771::sd::374::Storage.StorageDomain::(_registerResourceNamespaces) 
Resource namespace 0a897f2e-1b01-4577-9f91-cd136ef4a978_imageNS already 
registered
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::INFO::2014-04-25 
19:58:17,771::sd::382::Storage.StorageDomain::(_registerResourceNamespaces) 
Resource namespace 0a897f2e-1b01-4577-9f91-cd136ef4a978_volumeNS already 
registered
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,772::resourceManager::616::ResourceManager::(releaseResource) 
Trying to release resource 'Storage.0a897f2e-1b01-4577-9f91-cd136ef4a978'
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,772::resourceManager::635::ResourceManager::(releaseResource) 
Released resource 'Storage.0a897f2e-1b01-4577-9f91-cd136ef4a978' (0 
active users)
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,772::resourceManager::641::ResourceManager::(releaseResource) 
Resource 'Storage.0a897f2e-1b01-4577-9f91-cd136ef4a978' is free, finding 
out if anyone is waiting for it.
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,772::resourceManager::649::ResourceManager::(releaseResource) 
No one is waiting for resource 
'Storage.0a897f2e-1b01-4577-9f91-cd136ef4a978', Clearing records.
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,772::sp::436::Storage.StoragePool::(_upgradePool) Marking all 
domains for upgrade
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,781::persistentDict::234::Storage.PersistentDict::(refresh) 
read lines (FileMetadataRW)=['CLASS=Data', 
'DESCRIPTION=s2data1_s2mgt_boot1', 'IOOPTIMEOUTSEC=10', 
'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 
'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=1', 
'POOL_DESCRIPTION=BDS_DataCentre2', 
'POOL_DOMAINS=7b083758-45f9-4896-913d-11fe02043e6e:Active,e637bb04-a8b7-4c77-809c-d58051494c52:Active,0a897f2e-1b01-4577-9f91-cd136ef4a978:Active,c2c4ade6-049e-4159-a294-a0c151f4983d:Active,9a4a80a1-5377-4a94-ade3-e58183e916ae:Active',

'POOL_SPM_ID=1', 'POOL_SPM_LVER=0', 
'POOL_UUID=c713062f-300f-4256-9ac8-2d3fcfcdb002', 
'REMOTE_PATH=/vdsm_store/s2data1_s2mgt_boot1', 'ROLE=Master', 
'SDUUID=0a897f2e-1b01-4577-9f91-cd136ef4a978', 'TYPE=LOCALFS', 
'VERSION=3', '_SHA_CKSUM=68a337432f9f1794a057deb08eb27f6bb3513470']
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,782::sp::443::Storage.StoragePool::(_upgradePool) Registering 
with state change event
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,782::sp::446::Storage.StoragePool::(_upgradePool) Running 
initial domain upgrade threads
Thread-857::DEBUG::2014-04-25 
19:58:17,782::sp::152::Storage.StoragePool::(_upgradePoolDomain) 
Preparing to upgrade domain 7b083758-45f9-4896-913d-11fe02043e6e
Thread-858::DEBUG::2014-04-25 
19:58:17,782::sp::152::Storage.StoragePool::(_upgradePoolDomain) 
Preparing to upgrade domain e637bb04-a8b7-4c77-809c-d58051494c52
Thread-857::DEBUG::2014-04-25 
19:58:17,782::resourceManager::198::ResourceManager.Request::(__init__) 
ResName=`Storage.upgrade_7b083758-45f9-4896-913d-11fe02043e6e`ReqID=`c50b5f1d-d9fd-4317-bc98-4d40fad3e553`::Request

was made in '/usr/share/vdsm/storage/sp.py' line '163' at 
'_upgradePoolDomain'
Thread-858::DEBUG::2014-04-25 
19:58:17,783::resourceManager::198::ResourceManager.Request::(__init__) 
ResName=`Storage.upgrade_e637bb04-a8b7-4c77-809c-d58051494c52`ReqID=`89314c30-0d9e-4b1d-b5f9-1ab61127274d`::Request

was made in '/usr/share/vdsm/storage/sp.py' line '163' at 
'_upgradePoolDomain'
Thread-859::DEBUG::2014-04-25 
19:58:17,783::sp::152::Storage.StoragePool::(_upgradePoolDomain) 
Preparing to upgrade domain c2c4ade6-049e-4159-a294-a0c151f4983d
Thread-857::DEBUG::2014-04-25 
19:58:17,783::resourceManager::542::ResourceManager::(registerResource) 
Trying to register resource 
'Storage.upgrade_7b083758-45f9-4896-913d-11fe02043e6e' for lock type 
'exclusive'
Thread-860::ERROR::2014-04-25 
19:58:17,783::sdc::137::Storage.StorageDomainCache::(_findDomain) 
looking for unfetched domain 9a4a80a1-5377-4a94-ade3-e58183e916ae
Thread-859::DEBUG::2014-04-25 
19:58:17,784::resourceManager::198::ResourceManager.Request::(__init__) 
ResName=`Storage.upgrade_c2c4ade6-049e-4159-a294-a0c151f4983d`ReqID=`40a09482-c4be-472b-ae79-0b62c4640b5b`::Request

was made in '/usr/share/vdsm/storage/sp.py' line '163' at 
'_upgradePoolDomain'
Thread-858::DEBUG::2014-04-25 
19:58:17,784::resourceManager::542::ResourceManager::(registerResource) 
Trying to register resource 
'Storage.upgrade_e637bb04-a8b7-4c77-809c-d58051494c52' for lock type 
'exclusive'
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,784::resourceManager::616::ResourceManager::(releaseResource) 
Trying to release resource 
'Storage.upgrade_c713062f-300f-4256-9ac8-2d3fcfcdb002'
Thread-857::DEBUG::2014-04-25 
19:58:17,784::resourceManager::601::ResourceManager::(registerResource) 
Resource 'Storage.upgrade_7b083758-45f9-4896-913d-11fe02043e6e' is free. 
Now locking as 'exclusive' (1 active user)
Thread-860::ERROR::2014-04-25 
19:58:17,784::sdc::154::Storage.StorageDomainCache::(_findUnfetchedDomain) 
looking for domain 9a4a80a1-5377-4a94-ade3-e58183e916ae
Thread-859::DEBUG::2014-04-25 
19:58:17,784::resourceManager::542::ResourceManager::(registerResource) 
Trying to register resource 
'Storage.upgrade_c2c4ade6-049e-4159-a294-a0c151f4983d' for lock type 
'exclusive'
Thread-857::DEBUG::2014-04-25 
19:58:17,785::resourceManager::238::ResourceManager.Request::(grant) 
ResName=`Storage.upgrade_7b083758-45f9-4896-913d-11fe02043e6e`ReqID=`c50b5f1d-d9fd-4317-bc98-4d40fad3e553`::Granted

request
Thread-860::DEBUG::2014-04-25 
19:58:17,785::lvm::372::OperationMutex::(_reloadvgs) Operation 'lvm 
reload operation' got the operation mutex
Thread-858::DEBUG::2014-04-25 
19:58:17,785::resourceManager::601::ResourceManager::(registerResource) 
Resource 'Storage.upgrade_e637bb04-a8b7-4c77-809c-d58051494c52' is free. 
Now locking as 'exclusive' (1 active user)
Thread-857::DEBUG::2014-04-25 
19:58:17,786::resourceManager::198::ResourceManager.Request::(__init__) 
ResName=`Storage.7b083758-45f9-4896-913d-11fe02043e6e`ReqID=`a81f0cf3-f66a-4620-a380-9776968f5686`::Request

was made in '/usr/share/vdsm/storage/sp.py' line '165' at 
'_upgradePoolDomain'
Thread-860::DEBUG::2014-04-25 
19:58:17,786::lvm::295::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 obtain_device_list_from_udev=0 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,lv_count,pv_count,pv_name

9a4a80a1-5377-4a94-ade3-e58183e916ae' (cwd None)
Thread-858::DEBUG::2014-04-25 
19:58:17,786::resourceManager::238::ResourceManager.Request::(grant) 
ResName=`Storage.upgrade_e637bb04-a8b7-4c77-809c-d58051494c52`ReqID=`89314c30-0d9e-4b1d-b5f9-1ab61127274d`::Granted

request
Thread-857::DEBUG::2014-04-25 
19:58:17,786::resourceManager::542::ResourceManager::(registerResource) 
Trying to register resource 
'Storage.7b083758-45f9-4896-913d-11fe02043e6e' for lock type 'exclusive'
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,791::resourceManager::635::ResourceManager::(releaseResource) 
Released resource 'Storage.upgrade_c713062f-300f-4256-9ac8-2d3fcfcdb002' 
(0 active users)
Thread-858::DEBUG::2014-04-25 
19:58:17,791::resourceManager::198::ResourceManager.Request::(__init__) 
ResName=`Storage.e637bb04-a8b7-4c77-809c-d58051494c52`ReqID=`c5d0a1e7-9ebd-4175-86dd-30ef0e8f0a5c`::Request

was made in '/usr/share/vdsm/storage/sp.py' line '165' at 
'_upgradePoolDomain'
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,791::resourceManager::641::ResourceManager::(releaseResource) 
Resource 'Storage.upgrade_c713062f-300f-4256-9ac8-2d3fcfcdb002' is free, 
finding out if anyone is waiting for it.
Thread-858::DEBUG::2014-04-25 
19:58:17,791::resourceManager::542::ResourceManager::(registerResource) 
Trying to register resource 
'Storage.e637bb04-a8b7-4c77-809c-d58051494c52' for lock type 'exclusive'
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,792::resourceManager::649::ResourceManager::(releaseResource) 
No one is waiting for resource 
'Storage.upgrade_c713062f-300f-4256-9ac8-2d3fcfcdb002', Clearing records.
Thread-859::DEBUG::2014-04-25 
19:58:17,792::resourceManager::601::ResourceManager::(registerResource) 
Resource 'Storage.upgrade_c2c4ade6-049e-4159-a294-a0c151f4983d' is free. 
Now locking as 'exclusive' (1 active user)
Thread-859::DEBUG::2014-04-25 
19:58:17,792::resourceManager::238::ResourceManager.Request::(grant) 
ResName=`Storage.upgrade_c2c4ade6-049e-4159-a294-a0c151f4983d`ReqID=`40a09482-c4be-472b-ae79-0b62c4640b5b`::Granted

request
Thread-857::DEBUG::2014-04-25 
19:58:17,793::resourceManager::601::ResourceManager::(registerResource) 
Resource 'Storage.7b083758-45f9-4896-913d-11fe02043e6e' is free. Now 
locking as 'exclusive' (1 active user)
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,793::sd::623::Storage.StorageDomain::(createMasterTree) 
creating vms dir: 
/rhev/data-center/mnt/_vdsm__store_s2data1__s2mgt__boot1/0a897f2e-1b01-4577-9f91-cd136ef4a978/master/vms
Thread-859::DEBUG::2014-04-25 
19:58:17,793::resourceManager::198::ResourceManager.Request::(__init__) 
ResName=`Storage.c2c4ade6-049e-4159-a294-a0c151f4983d`ReqID=`47c69548-2b50-4d71-98f1-4bd3a70edaff`::Request

was made in '/usr/share/vdsm/storage/sp.py' line '165' at 
'_upgradePoolDomain'
Thread-859::DEBUG::2014-04-25 
19:58:17,793::resourceManager::542::ResourceManager::(registerResource) 
Trying to register resource 
'Storage.c2c4ade6-049e-4159-a294-a0c151f4983d' for lock type 'exclusive'
Thread-857::DEBUG::2014-04-25 
19:58:17,793::resourceManager::238::ResourceManager.Request::(grant) 
ResName=`Storage.7b083758-45f9-4896-913d-11fe02043e6e`ReqID=`a81f0cf3-f66a-4620-a380-9776968f5686`::Granted

request
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,794::sd::626::Storage.StorageDomain::(createMasterTree) 
creating task dir: 
/rhev/data-center/mnt/_vdsm__store_s2data1__s2mgt__boot1/0a897f2e-1b01-4577-9f91-cd136ef4a978/master/tasks
Thread-858::DEBUG::2014-04-25 
19:58:17,794::resourceManager::601::ResourceManager::(registerResource) 
Resource 'Storage.e637bb04-a8b7-4c77-809c-d58051494c52' is free. Now 
locking as 'exclusive' (1 active user)
Thread-857::DEBUG::2014-04-25 
19:58:17,794::sp::175::Storage.StoragePool::(_upgradePoolDomain) Domain 
`7b083758-45f9-4896-913d-11fe02043e6e` is not a data domain it is an 2 
domain, not upgrading
Thread-858::DEBUG::2014-04-25 
19:58:17,795::resourceManager::238::ResourceManager.Request::(grant) 
ResName=`Storage.e637bb04-a8b7-4c77-809c-d58051494c52`ReqID=`c5d0a1e7-9ebd-4175-86dd-30ef0e8f0a5c`::Granted

request
Thread-860::DEBUG::2014-04-25 
19:58:17,800::lvm::295::Storage.Misc.excCmd::(cmd) FAILED: <err> = '  
Volume group "9a4a80a1-5377-4a94-ade3-e58183e916ae" not found\n  
Skipping volume group 9a4a80a1-5377-4a94-ade3-e58183e916ae\n'; <rc> = 5
Thread-857::DEBUG::2014-04-25 
19:58:17,804::resourceManager::616::ResourceManager::(releaseResource) 
Trying to release resource 'Storage.7b083758-45f9-4896-913d-11fe02043e6e'
Thread-859::DEBUG::2014-04-25 
19:58:17,804::resourceManager::601::ResourceManager::(registerResource) 
Resource 'Storage.c2c4ade6-049e-4159-a294-a0c151f4983d' is free. Now 
locking as 'exclusive' (1 active user)
Thread-859::DEBUG::2014-04-25 
19:58:17,807::resourceManager::238::ResourceManager.Request::(grant) 
ResName=`Storage.c2c4ade6-049e-4159-a294-a0c151f4983d`ReqID=`47c69548-2b50-4d71-98f1-4bd3a70edaff`::Granted

request
Thread-860::WARNING::2014-04-25 
19:58:17,808::lvm::377::Storage.LVM::(_reloadvgs) lvm vgs failed: 5 [] 
['  Volume group "9a4a80a1-5377-4a94-ade3-e58183e916ae" not found',
'  
Skipping volume group 9a4a80a1-5377-4a94-ade3-e58183e916ae']
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,809::persistentDict::234::Storage.PersistentDict::(refresh) 
read lines (FileMetadataRW)=['CLASS=Data', 
'DESCRIPTION=s2data1_s2mgt_boot1', 'IOOPTIMEOUTSEC=10', 
'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 
'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=1', 
'POOL_DESCRIPTION=BDS_DataCentre2', 
'POOL_DOMAINS=7b083758-45f9-4896-913d-11fe02043e6e:Active,e637bb04-a8b7-4c77-809c-d58051494c52:Active,0a897f2e-1b01-4577-9f91-cd136ef4a978:Active,c2c4ade6-049e-4159-a294-a0c151f4983d:Active,9a4a80a1-5377-4a94-ade3-e58183e916ae:Active',

'POOL_SPM_ID=1', 'POOL_SPM_LVER=0', 
'POOL_UUID=c713062f-300f-4256-9ac8-2d3fcfcdb002', 
'REMOTE_PATH=/vdsm_store/s2data1_s2mgt_boot1', 'ROLE=Master', 
'SDUUID=0a897f2e-1b01-4577-9f91-cd136ef4a978', 'TYPE=LOCALFS', 
'VERSION=3', '_SHA_CKSUM=68a337432f9f1794a057deb08eb27f6bb3513470']
Thread-857::DEBUG::2014-04-25 
19:58:17,810::resourceManager::635::ResourceManager::(releaseResource) 
Released resource 'Storage.7b083758-45f9-4896-913d-11fe02043e6e' (0 
active users)
Thread-857::DEBUG::2014-04-25 
19:58:17,811::resourceManager::641::ResourceManager::(releaseResource) 
Resource 'Storage.7b083758-45f9-4896-913d-11fe02043e6e' is free, finding 
out if anyone is waiting for it.
Thread-857::DEBUG::2014-04-25 
19:58:17,813::resourceManager::649::ResourceManager::(releaseResource) 
No one is waiting for resource 
'Storage.7b083758-45f9-4896-913d-11fe02043e6e', Clearing records.
Thread-857::DEBUG::2014-04-25 
19:58:17,813::resourceManager::616::ResourceManager::(releaseResource) 
Trying to release resource 
'Storage.upgrade_7b083758-45f9-4896-913d-11fe02043e6e'
Thread-857::DEBUG::2014-04-25 
19:58:17,814::resourceManager::635::ResourceManager::(releaseResource) 
Released resource 'Storage.upgrade_7b083758-45f9-4896-913d-11fe02043e6e' 
(0 active users)
Thread-857::DEBUG::2014-04-25 
19:58:17,814::resourceManager::641::ResourceManager::(releaseResource) 
Resource 'Storage.upgrade_7b083758-45f9-4896-913d-11fe02043e6e' is free, 
finding out if anyone is waiting for it.
Thread-857::DEBUG::2014-04-25 
19:58:17,814::resourceManager::649::ResourceManager::(releaseResource) 
No one is waiting for resource 
'Storage.upgrade_7b083758-45f9-4896-913d-11fe02043e6e', Clearing records.
Thread-860::DEBUG::2014-04-25 
19:58:17,820::lvm::414::OperationMutex::(_reloadvgs) Operation 'lvm 
reload operation' released the operation mutex
Thread-858::DEBUG::2014-04-25 
19:58:17,826::persistentDict::234::Storage.PersistentDict::(refresh) 
read lines (FileMetadataRW)=['CLASS=Data', 
'DESCRIPTION=s2data1_s2usr_boot1', 'IOOPTIMEOUTSEC=10', 
'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 
'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=0', 
'POOL_UUID=c713062f-300f-4256-9ac8-2d3fcfcdb002', 
'REMOTE_PATH=/vdsm_store/s2data1_s2usr_boot1', 'ROLE=Regular', 
'SDUUID=e637bb04-a8b7-4c77-809c-d58051494c52', 'TYPE=LOCALFS', 
'VERSION=3', '_SHA_CKSUM=1f8ddad2bfec7f562b2e20b339649fe8c088a3d9']
Thread-859::DEBUG::2014-04-25 
19:58:17,827::persistentDict::234::Storage.PersistentDict::(refresh) 
read lines (FileMetadataRW)=['CLASS=Data', 
'DESCRIPTION=s2data1_s2mgt_app1', 'IOOPTIMEOUTSEC=10',
'LEASERETRIES=3', 
'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 
'MASTER_VERSION=0', 'POOL_UUID=c713062f-300f-4256-9ac8-2d3fcfcdb002', 
'REMOTE_PATH=/vdsm_store/s2data1_s2mgt_app1', 'ROLE=Regular', 
'SDUUID=c2c4ade6-049e-4159-a294-a0c151f4983d', 'TYPE=LOCALFS', 
'VERSION=3', '_SHA_CKSUM=5eda40da414dcb977d9d94d0ed6ad1162a55d69f']
Thread-858::DEBUG::2014-04-25 
19:58:17,831::resourceManager::616::ResourceManager::(releaseResource) 
Trying to release resource 'Storage.e637bb04-a8b7-4c77-809c-d58051494c52'
Thread-859::DEBUG::2014-04-25 
19:58:17,832::resourceManager::616::ResourceManager::(releaseResource) 
Trying to release resource 'Storage.c2c4ade6-049e-4159-a294-a0c151f4983d'
Thread-858::DEBUG::2014-04-25 
19:58:17,834::resourceManager::635::ResourceManager::(releaseResource) 
Released resource 'Storage.e637bb04-a8b7-4c77-809c-d58051494c52' (0 
active users)
Thread-858::DEBUG::2014-04-25 
19:58:17,836::resourceManager::641::ResourceManager::(releaseResource) 
Resource 'Storage.e637bb04-a8b7-4c77-809c-d58051494c52' is free, finding 
out if anyone is waiting for it.
Thread-858::DEBUG::2014-04-25 
19:58:17,838::resourceManager::649::ResourceManager::(releaseResource) 
No one is waiting for resource 
'Storage.e637bb04-a8b7-4c77-809c-d58051494c52', Clearing records.
Thread-860::ERROR::2014-04-25 
19:58:17,838::sdc::143::Storage.StorageDomainCache::(_findDomain) domain 
9a4a80a1-5377-4a94-ade3-e58183e916ae not found
Traceback (most recent call last):
   File "/usr/share/vdsm/storage/sdc.py", line 141, in _findDomain
     dom = findMethod(sdUUID)
   File "/usr/share/vdsm/storage/sdc.py", line 171, in _findUnfetchedDomain
     raise se.StorageDomainDoesNotExist(sdUUID)
StorageDomainDoesNotExist: Storage domain does not exist: 
('9a4a80a1-5377-4a94-ade3-e58183e916ae',)
Thread-859::DEBUG::2014-04-25 
19:58:17,839::resourceManager::635::ResourceManager::(releaseResource) 
Released resource 'Storage.c2c4ade6-049e-4159-a294-a0c151f4983d' (0 
active users)
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::ERROR::2014-04-25 
19:58:17,840::sdc::137::Storage.StorageDomainCache::(_findDomain) 
looking for unfetched domain 9a4a80a1-5377-4a94-ade3-e58183e916ae
Thread-859::DEBUG::2014-04-25 
19:58:17,840::resourceManager::641::ResourceManager::(releaseResource) 
Resource 'Storage.c2c4ade6-049e-4159-a294-a0c151f4983d' is free, finding 
out if anyone is waiting for it.
Thread-858::DEBUG::2014-04-25 
19:58:17,841::resourceManager::616::ResourceManager::(releaseResource) 
Trying to release resource 
'Storage.upgrade_e637bb04-a8b7-4c77-809c-d58051494c52'
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::ERROR::2014-04-25 
19:58:17,841::sdc::154::Storage.StorageDomainCache::(_findUnfetchedDomain) 
looking for domain 9a4a80a1-5377-4a94-ade3-e58183e916ae
Thread-859::DEBUG::2014-04-25 
19:58:17,842::resourceManager::649::ResourceManager::(releaseResource) 
No one is waiting for resource 
'Storage.c2c4ade6-049e-4159-a294-a0c151f4983d', Clearing records.
Thread-858::DEBUG::2014-04-25 
19:58:17,843::resourceManager::635::ResourceManager::(releaseResource) 
Released resource 'Storage.upgrade_e637bb04-a8b7-4c77-809c-d58051494c52' 
(0 active users)
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,843::lvm::372::OperationMutex::(_reloadvgs) Operation 'lvm 
reload operation' got the operation mutex
Thread-858::DEBUG::2014-04-25 
19:58:17,844::resourceManager::641::ResourceManager::(releaseResource) 
Resource 'Storage.upgrade_e637bb04-a8b7-4c77-809c-d58051494c52' is free, 
finding out if anyone is waiting for it.
Thread-859::DEBUG::2014-04-25 
19:58:17,844::resourceManager::616::ResourceManager::(releaseResource) 
Trying to release resource 
'Storage.upgrade_c2c4ade6-049e-4159-a294-a0c151f4983d'
Thread-858::DEBUG::2014-04-25 
19:58:17,845::resourceManager::649::ResourceManager::(releaseResource) 
No one is waiting for resource 
'Storage.upgrade_e637bb04-a8b7-4c77-809c-d58051494c52', Clearing records.
Thread-859::DEBUG::2014-04-25 
19:58:17,846::resourceManager::635::ResourceManager::(releaseResource) 
Released resource 'Storage.upgrade_c2c4ade6-049e-4159-a294-a0c151f4983d' 
(0 active users)
Thread-859::DEBUG::2014-04-25 
19:58:17,847::resourceManager::641::ResourceManager::(releaseResource) 
Resource 'Storage.upgrade_c2c4ade6-049e-4159-a294-a0c151f4983d' is free, 
finding out if anyone is waiting for it.
Thread-859::DEBUG::2014-04-25 
19:58:17,848::resourceManager::649::ResourceManager::(releaseResource) 
No one is waiting for resource 
'Storage.upgrade_c2c4ade6-049e-4159-a294-a0c151f4983d', Clearing records.
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,848::lvm::295::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 obtain_device_list_from_udev=0 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,lv_count,pv_count,pv_name

9a4a80a1-5377-4a94-ade3-e58183e916ae' (cwd None)
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,862::lvm::295::Storage.Misc.excCmd::(cmd) FAILED: <err> = '  
Volume group "9a4a80a1-5377-4a94-ade3-e58183e916ae" not found\n  
Skipping volume group 9a4a80a1-5377-4a94-ade3-e58183e916ae\n'; <rc> = 5
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::WARNING::2014-04-25 
19:58:17,863::lvm::377::Storage.LVM::(_reloadvgs) lvm vgs failed: 5 [] 
['  Volume group "9a4a80a1-5377-4a94-ade3-e58183e916ae" not found',
'  
Skipping volume group 9a4a80a1-5377-4a94-ade3-e58183e916ae']
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,863::lvm::414::OperationMutex::(_reloadvgs) Operation 'lvm 
reload operation' released the operation mutex
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::ERROR::2014-04-25 
19:58:17,873::sdc::143::Storage.StorageDomainCache::(_findDomain) domain 
9a4a80a1-5377-4a94-ade3-e58183e916ae not found
Traceback (most recent call last):
   File "/usr/share/vdsm/storage/sdc.py", line 141, in _findDomain
     dom = findMethod(sdUUID)
   File "/usr/share/vdsm/storage/sdc.py", line 171, in _findUnfetchedDomain
     raise se.StorageDomainDoesNotExist(sdUUID)
StorageDomainDoesNotExist: Storage domain does not exist: 
('9a4a80a1-5377-4a94-ade3-e58183e916ae',)
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::ERROR::2014-04-25 
19:58:17,874::sp::288::Storage.StoragePool::(startSpm) Backup domain 
validation failed
Traceback (most recent call last):
   File "/usr/share/vdsm/storage/sp.py", line 285, in startSpm
     self.checkBackupDomain(__securityOverride=True)
   File "/usr/share/vdsm/storage/securable.py", line 75, in wrapper
     return method(self, *args, **kwargs)
   File "/usr/share/vdsm/storage/sp.py", line 1409, in checkBackupDomain
     dom = sdCache.produce(sdUUID)
   File "/usr/share/vdsm/storage/sdc.py", line 98, in produce
     domain.getRealDomain()
   File "/usr/share/vdsm/storage/sdc.py", line 52, in getRealDomain
     return self._cache._realProduce(self._sdUUID)
   File "/usr/share/vdsm/storage/sdc.py", line 122, in _realProduce
     domain = self._findDomain(sdUUID)
   File "/usr/share/vdsm/storage/sdc.py", line 141, in _findDomain
     dom = findMethod(sdUUID)
   File "/usr/share/vdsm/storage/sdc.py", line 171, in _findUnfetchedDomain
     raise se.StorageDomainDoesNotExist(sdUUID)
StorageDomainDoesNotExist: Storage domain does not exist: 
('9a4a80a1-5377-4a94-ade3-e58183e916ae',)
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::ERROR::2014-04-25 
19:58:17,874::sdc::137::Storage.StorageDomainCache::(_findDomain) 
looking for unfetched domain 9a4a80a1-5377-4a94-ade3-e58183e916ae
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::ERROR::2014-04-25 
19:58:17,874::sdc::154::Storage.StorageDomainCache::(_findUnfetchedDomain) 
looking for domain 9a4a80a1-5377-4a94-ade3-e58183e916ae
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,874::lvm::372::OperationMutex::(_reloadvgs) Operation 'lvm 
reload operation' got the operation mutex
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,875::lvm::295::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 obtain_device_list_from_udev=0 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,lv_count,pv_count,pv_name

9a4a80a1-5377-4a94-ade3-e58183e916ae' (cwd None)
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,888::lvm::295::Storage.Misc.excCmd::(cmd) FAILED: <err> = '  
Volume group "9a4a80a1-5377-4a94-ade3-e58183e916ae" not found\n  
Skipping volume group 9a4a80a1-5377-4a94-ade3-e58183e916ae\n'; <rc> = 5
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::WARNING::2014-04-25 
19:58:17,889::lvm::377::Storage.LVM::(_reloadvgs) lvm vgs failed: 5 [] 
['  Volume group "9a4a80a1-5377-4a94-ade3-e58183e916ae" not found',
'  
Skipping volume group 9a4a80a1-5377-4a94-ade3-e58183e916ae']
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,889::lvm::414::OperationMutex::(_reloadvgs) Operation 'lvm 
reload operation' released the operation mutex
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::ERROR::2014-04-25 
19:58:17,899::sdc::143::Storage.StorageDomainCache::(_findDomain) domain 
9a4a80a1-5377-4a94-ade3-e58183e916ae not found
Traceback (most recent call last):
   File "/usr/share/vdsm/storage/sdc.py", line 141, in _findDomain
     dom = findMethod(sdUUID)
   File "/usr/share/vdsm/storage/sdc.py", line 171, in _findUnfetchedDomain
     raise se.StorageDomainDoesNotExist(sdUUID)
StorageDomainDoesNotExist: Storage domain does not exist: 
('9a4a80a1-5377-4a94-ade3-e58183e916ae',)
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::ERROR::2014-04-25 
19:58:17,899::sp::329::Storage.StoragePool::(startSpm) Unexpected error
Traceback (most recent call last):
   File "/usr/share/vdsm/storage/sp.py", line 296, in startSpm
     self._updateDomainsRole()
   File "/usr/share/vdsm/storage/securable.py", line 75, in wrapper
     return method(self, *args, **kwargs)
   File "/usr/share/vdsm/storage/sp.py", line 205, in _updateDomainsRole
     domain = sdCache.produce(sdUUID)
   File "/usr/share/vdsm/storage/sdc.py", line 98, in produce
     domain.getRealDomain()
   File "/usr/share/vdsm/storage/sdc.py", line 52, in getRealDomain
     return self._cache._realProduce(self._sdUUID)
   File "/usr/share/vdsm/storage/sdc.py", line 122, in _realProduce
     domain = self._findDomain(sdUUID)
   File "/usr/share/vdsm/storage/sdc.py", line 141, in _findDomain
     dom = findMethod(sdUUID)
   File "/usr/share/vdsm/storage/sdc.py", line 171, in _findUnfetchedDomain
     raise se.StorageDomainDoesNotExist(sdUUID)
StorageDomainDoesNotExist: Storage domain does not exist: 
('9a4a80a1-5377-4a94-ade3-e58183e916ae',)
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::ERROR::2014-04-25 
19:58:17,900::sp::330::Storage.StoragePool::(startSpm) failed: Storage 
domain does not exist: ('9a4a80a1-5377-4a94-ade3-e58183e916ae',)
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,900::sp::336::Storage.StoragePool::(_shutDownUpgrade) Shutting 
down upgrade process
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,900::resourceManager::198::ResourceManager.Request::(__init__) 
ResName=`Storage.upgrade_c713062f-300f-4256-9ac8-2d3fcfcdb002`ReqID=`1d51aee8-4f09-4c7d-9fad-8b13801dce28`::Request

was made in '/usr/share/vdsm/storage/sp.py' line '338' at
'_shutDownUpgrade'
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,900::resourceManager::542::ResourceManager::(registerResource) 
Trying to register resource 
'Storage.upgrade_c713062f-300f-4256-9ac8-2d3fcfcdb002' for lock type 
'exclusive'
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,900::resourceManager::601::ResourceManager::(registerResource) 
Resource 'Storage.upgrade_c713062f-300f-4256-9ac8-2d3fcfcdb002' is free. 
Now locking as 'exclusive' (1 active user)
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,901::resourceManager::238::ResourceManager.Request::(grant) 
ResName=`Storage.upgrade_c713062f-300f-4256-9ac8-2d3fcfcdb002`ReqID=`1d51aee8-4f09-4c7d-9fad-8b13801dce28`::Granted

request
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,901::resourceManager::198::ResourceManager.Request::(__init__) 
ResName=`Storage.upgrade_9a4a80a1-5377-4a94-ade3-e58183e916ae`ReqID=`7b50d1d9-ac64-4a8a-93df-3faee4744b2b`::Request

was made in '/usr/share/vdsm/storage/sp.py' line '358' at
'_shutDownUpgrade'
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,901::resourceManager::542::ResourceManager::(registerResource) 
Trying to register resource 
'Storage.upgrade_9a4a80a1-5377-4a94-ade3-e58183e916ae' for lock type 
'exclusive'
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,901::resourceManager::601::ResourceManager::(registerResource) 
Resource 'Storage.upgrade_9a4a80a1-5377-4a94-ade3-e58183e916ae' is free. 
Now locking as 'exclusive' (1 active user)
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,901::resourceManager::238::ResourceManager.Request::(grant) 
ResName=`Storage.upgrade_9a4a80a1-5377-4a94-ade3-e58183e916ae`ReqID=`7b50d1d9-ac64-4a8a-93df-3faee4744b2b`::Granted

request
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,902::resourceManager::616::ResourceManager::(releaseResource) 
Trying to release resource 
'Storage.upgrade_9a4a80a1-5377-4a94-ade3-e58183e916ae'
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,902::resourceManager::635::ResourceManager::(releaseResource) 
Released resource 'Storage.upgrade_9a4a80a1-5377-4a94-ade3-e58183e916ae' 
(0 active users)
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,902::resourceManager::641::ResourceManager::(releaseResource) 
Resource 'Storage.upgrade_9a4a80a1-5377-4a94-ade3-e58183e916ae' is free, 
finding out if anyone is waiting for it.
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,902::resourceManager::649::ResourceManager::(releaseResource) 
No one is waiting for resource 
'Storage.upgrade_9a4a80a1-5377-4a94-ade3-e58183e916ae', Clearing records.
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,902::resourceManager::616::ResourceManager::(releaseResource) 
Trying to release resource 
'Storage.upgrade_c713062f-300f-4256-9ac8-2d3fcfcdb002'
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,902::resourceManager::635::ResourceManager::(releaseResource) 
Released resource 'Storage.upgrade_c713062f-300f-4256-9ac8-2d3fcfcdb002' 
(0 active users)
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,902::resourceManager::641::ResourceManager::(releaseResource) 
Resource 'Storage.upgrade_c713062f-300f-4256-9ac8-2d3fcfcdb002' is free, 
finding out if anyone is waiting for it.
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,902::resourceManager::649::ResourceManager::(releaseResource) 
No one is waiting for resource 
'Storage.upgrade_c713062f-300f-4256-9ac8-2d3fcfcdb002', Clearing records.
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,903::persistentDict::167::Storage.PersistentDict::(transaction) 
Starting transaction
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,903::persistentDict::173::Storage.PersistentDict::(transaction) 
Flushing changes
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,903::persistentDict::299::Storage.PersistentDict::(flush) about 
to write lines (FileMetadataRW)=['CLASS=Data', 
'DESCRIPTION=s2data1_s2mgt_boot1', 'IOOPTIMEOUTSEC=10', 
'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 
'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=1', 
'POOL_DESCRIPTION=BDS_DataCentre2', 
'POOL_DOMAINS=7b083758-45f9-4896-913d-11fe02043e6e:Active,e637bb04-a8b7-4c77-809c-d58051494c52:Active,0a897f2e-1b01-4577-9f91-cd136ef4a978:Active,c2c4ade6-049e-4159-a294-a0c151f4983d:Active,9a4a80a1-5377-4a94-ade3-e58183e916ae:Active',

'POOL_SPM_ID=-1', 'POOL_SPM_LVER=0', 
'POOL_UUID=c713062f-300f-4256-9ac8-2d3fcfcdb002', 
'REMOTE_PATH=/vdsm_store/s2data1_s2mgt_boot1', 'ROLE=Master', 
'SDUUID=0a897f2e-1b01-4577-9f91-cd136ef4a978', 'TYPE=LOCALFS', 
'VERSION=3', '_SHA_CKSUM=afe618d7596d75d0fb96453bcdd34a1255534454']
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,904::persistentDict::175::Storage.PersistentDict::(transaction) 
Finished transaction
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::INFO::2014-04-25 
19:58:17,904::clusterlock::409::LocalLock::(release) Releasing local 
lock for domain 0a897f2e-1b01-4577-9f91-cd136ef4a978
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,904::clusterlock::422::LocalLock::(release) Local lock for 
domain 0a897f2e-1b01-4577-9f91-cd136ef4a978 successfully released
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::ERROR::2014-04-25 
19:58:17,905::task::866::TaskManager.Task::(_setError) 
Task=`b9623891-cda5-4ac3-b4ab-efde3cc5ac97`::Unexpected error
Traceback (most recent call last):
   File "/usr/share/vdsm/storage/task.py", line 873, in _run
     return fn(*args, **kargs)
   File "/usr/share/vdsm/storage/task.py", line 334, in run
     return self.cmd(*self.argslist, **self.argsdict)
   File "/usr/share/vdsm/storage/sp.py", line 296, in startSpm
     self._updateDomainsRole()
   File "/usr/share/vdsm/storage/securable.py", line 75, in wrapper
     return method(self, *args, **kwargs)
   File "/usr/share/vdsm/storage/sp.py", line 205, in _updateDomainsRole
     domain = sdCache.produce(sdUUID)
   File "/usr/share/vdsm/storage/sdc.py", line 98, in produce
     domain.getRealDomain()
   File "/usr/share/vdsm/storage/sdc.py", line 52, in getRealDomain
     return self._cache._realProduce(self._sdUUID)
   File "/usr/share/vdsm/storage/sdc.py", line 122, in _realProduce
     domain = self._findDomain(sdUUID)
   File "/usr/share/vdsm/storage/sdc.py", line 141, in _findDomain
     dom = findMethod(sdUUID)
   File "/usr/share/vdsm/storage/sdc.py", line 171, in _findUnfetchedDomain
     raise se.StorageDomainDoesNotExist(sdUUID)
StorageDomainDoesNotExist: Storage domain does not exist: 
('9a4a80a1-5377-4a94-ade3-e58183e916ae',)
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,905::task::885::TaskManager.Task::(_run) 
Task=`b9623891-cda5-4ac3-b4ab-efde3cc5ac97`::Task._run: 
b9623891-cda5-4ac3-b4ab-efde3cc5ac97 () {} failed - stopping task
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,905::task::1211::TaskManager.Task::(stop) 
Task=`b9623891-cda5-4ac3-b4ab-efde3cc5ac97`::stopping in state running 
(force False)
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,905::task::990::TaskManager.Task::(_decref) 
Task=`b9623891-cda5-4ac3-b4ab-efde3cc5ac97`::ref 1 aborting True
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,905::task::916::TaskManager.Task::(_runJobs) 
Task=`b9623891-cda5-4ac3-b4ab-efde3cc5ac97`::aborting: Task is aborted: 
'Storage domain does not exist' - code 358
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,905::task::990::TaskManager.Task::(_decref) 
Task=`b9623891-cda5-4ac3-b4ab-efde3cc5ac97`::ref 0 aborting True
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,906::task::925::TaskManager.Task::(_doAbort) 
Task=`b9623891-cda5-4ac3-b4ab-efde3cc5ac97`::Task._doAbort: force False
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,906::resourceManager::977::ResourceManager.Owner::(cancelAll) 
Owner.cancelAll requests {}
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,906::task::595::TaskManager.Task::(_updateState) 
Task=`b9623891-cda5-4ac3-b4ab-efde3cc5ac97`::moving from state running 
-> state aborting
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,906::task::550::TaskManager.Task::(__state_aborting) 
Task=`b9623891-cda5-4ac3-b4ab-efde3cc5ac97`::_aborting: recover policy auto
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,906::task::595::TaskManager.Task::(_updateState) 
Task=`b9623891-cda5-4ac3-b4ab-efde3cc5ac97`::moving from state aborting 
-> state racquiring
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,906::task::595::TaskManager.Task::(_updateState) 
Task=`b9623891-cda5-4ac3-b4ab-efde3cc5ac97`::moving from state 
racquiring -> state recovering
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,906::task::798::TaskManager.Task::(_recover) 
Task=`b9623891-cda5-4ac3-b4ab-efde3cc5ac97`::_recover
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,906::task::805::TaskManager.Task::(_recover) 
Task=`b9623891-cda5-4ac3-b4ab-efde3cc5ac97`::running recovery None
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,906::task::786::TaskManager.Task::(_recoverDone) 
Task=`b9623891-cda5-4ac3-b4ab-efde3cc5ac97`::Recover Done: state recovering
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,907::task::595::TaskManager.Task::(_updateState) 
Task=`b9623891-cda5-4ac3-b4ab-efde3cc5ac97`::moving from state 
recovering -> state recovered
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,907::resourceManager::940::ResourceManager.Owner::(releaseAll) 
Owner.releaseAll requests {} resources 
{'Storage.c713062f-300f-4256-9ac8-2d3fcfcdb002': < ResourceRef 
'Storage.c713062f-300f-4256-9ac8-2d3fcfcdb002', isValid: 'True' obj: 
'None'>}
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,907::resourceManager::977::ResourceManager.Owner::(cancelAll) 
Owner.cancelAll requests {}
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,907::resourceManager::616::ResourceManager::(releaseResource) 
Trying to release resource 'Storage.c713062f-300f-4256-9ac8-2d3fcfcdb002'
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,907::resourceManager::635::ResourceManager::(releaseResource) 
Released resource 'Storage.c713062f-300f-4256-9ac8-2d3fcfcdb002' (0 
active users)
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,907::resourceManager::641::ResourceManager::(releaseResource) 
Resource 'Storage.c713062f-300f-4256-9ac8-2d3fcfcdb002' is free, finding 
out if anyone is waiting for it.
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,907::resourceManager::649::ResourceManager::(releaseResource) 
No one is waiting for resource 
'Storage.c713062f-300f-4256-9ac8-2d3fcfcdb002', Clearing records.
b9623891-cda5-4ac3-b4ab-efde3cc5ac97::DEBUG::2014-04-25 
19:58:17,907::threadPool::57::Misc.ThreadPool::(setRunningTask) Number 
of running tasks: 0
Thread-180::DEBUG::2014-04-25 
19:58:18,739::BindingXMLRPC::251::vds::(wrapper) client [10.50.0.18] 
flowID [21f7a1a7]
Thread-180::DEBUG::2014-04-25 
19:58:18,739::task::595::TaskManager.Task::(_updateState) 
Task=`c57b61b2-fa6d-437d-b77f-694dda11efee`::moving from state init -> 
state preparing
Thread-180::INFO::2014-04-25 
19:58:18,739::logUtils::44::dispatcher::(wrapper) Run and protect: 
getTaskStatus(taskID='b9623891-cda5-4ac3-b4ab-efde3cc5ac97', 
spUUID=None, options=None)
Thread-180::DEBUG::2014-04-25 
19:58:18,740::taskManager::93::TaskManager::(getTaskStatus) Entry. 
taskID: b9623891-cda5-4ac3-b4ab-efde3cc5ac97
Thread-180::DEBUG::2014-04-25 
19:58:18,740::taskManager::96::TaskManager::(getTaskStatus) Return. 
Response: {'code': 358, 'message': 'Storage domain does not
exist', 
'taskState': 'finished', 'taskResult': 'cleanSuccess',
'taskID': 
'b9623891-cda5-4ac3-b4ab-efde3cc5ac97'}
Thread-180::INFO::2014-04-25 
19:58:18,740::logUtils::47::dispatcher::(wrapper) Run and protect: 
getTaskStatus, Return response: {'taskStatus': {'code': 358,
'message': 
'Storage domain does not exist', 'taskState': 'finished',
'taskResult': 
'cleanSuccess', 'taskID':
'b9623891-cda5-4ac3-b4ab-efde3cc5ac97'}}
Thread-180::DEBUG::2014-04-25 
19:58:18,740::task::1185::TaskManager.Task::(prepare) 
Task=`c57b61b2-fa6d-437d-b77f-694dda11efee`::finished: {'taskStatus': 
{'code': 358, 'message': 'Storage domain does not exist',
'taskState': 
'finished', 'taskResult': 'cleanSuccess', 'taskID': 
'b9623891-cda5-4ac3-b4ab-efde3cc5ac97'}}
Thread-180::DEBUG::2014-04-25 
19:58:18,740::task::595::TaskManager.Task::(_updateState) 
Task=`c57b61b2-fa6d-437d-b77f-694dda11efee`::moving from state preparing 
-> state finished
Thread-180::DEBUG::2014-04-25 
19:58:18,740::resourceManager::940::ResourceManager.Owner::(releaseAll) 
Owner.releaseAll requests {} resources {}
Thread-180::DEBUG::2014-04-25 
19:58:18,740::resourceManager::977::ResourceManager.Owner::(cancelAll) 
Owner.cancelAll requests {}
Thread-180::DEBUG::2014-04-25 
19:58:18,740::task::990::TaskManager.Task::(_decref) 
Task=`c57b61b2-fa6d-437d-b77f-694dda11efee`::ref 0 aborting False
Thread-180::DEBUG::2014-04-25 
19:58:18,745::BindingXMLRPC::251::vds::(wrapper) client [10.50.0.18] 
flowID [21f7a1a7]
Thread-180::DEBUG::2014-04-25 
19:58:18,745::task::595::TaskManager.Task::(_updateState) 
Task=`e3e1bdc1-e68d-40b1-ada1-229a29416c27`::moving from state init -> 
state preparing
Thread-180::INFO::2014-04-25 
19:58:18,746::logUtils::44::dispatcher::(wrapper) Run and protect: 
getSpmStatus(spUUID='c713062f-300f-4256-9ac8-2d3fcfcdb002', options=None)
Thread-180::INFO::2014-04-25 
19:58:18,746::logUtils::47::dispatcher::(wrapper) Run and protect: 
getSpmStatus, Return response: {'spm_st': {'spmId': -1,
'spmStatus': 
'Free', 'spmLver': -1}}
Thread-180::DEBUG::2014-04-25 
19:58:18,746::task::1185::TaskManager.Task::(prepare) 
Task=`e3e1bdc1-e68d-40b1-ada1-229a29416c27`::finished: {'spm_st': 
{'spmId': -1, 'spmStatus': 'Free', 'spmLver': -1}}
Thread-180::DEBUG::2014-04-25 
19:58:18,746::task::595::TaskManager.Task::(_updateState) 
Task=`e3e1bdc1-e68d-40b1-ada1-229a29416c27`::moving from state preparing 
-> state finished
Thread-180::DEBUG::2014-04-25 
19:58:18,746::resourceManager::940::ResourceManager.Owner::(releaseAll) 
Owner.releaseAll requests {} resources {}
Thread-180::DEBUG::2014-04-25 
19:58:18,746::resourceManager::977::ResourceManager.Owner::(cancelAll) 
Owner.cancelAll requests {}
Thread-180::DEBUG::2014-04-25 
19:58:18,746::task::990::TaskManager.Task::(_decref) 
Task=`e3e1bdc1-e68d-40b1-ada1-229a29416c27`::ref 0 aborting False
Thread-180::DEBUG::2014-04-25 
19:58:18,790::BindingXMLRPC::251::vds::(wrapper) client [10.50.0.18] 
flowID [21f7a1a7]
Thread-180::DEBUG::2014-04-25 
19:58:18,791::task::595::TaskManager.Task::(_updateState) 
Task=`bc8109f7-7ca9-4900-afc2-653120a0f0b7`::moving from state init -> 
state preparing
Thread-180::INFO::2014-04-25 
19:58:18,791::logUtils::44::dispatcher::(wrapper) Run and protect: 
clearTask(taskID='b9623891-cda5-4ac3-b4ab-efde3cc5ac97', spUUID=None, 
options=None)
Thread-180::DEBUG::2014-04-25 
19:58:18,791::taskManager::161::TaskManager::(clearTask) Entry. taskID: 
b9623891-cda5-4ac3-b4ab-efde3cc5ac97
Thread-180::DEBUG::2014-04-25 
19:58:18,791::taskManager::166::TaskManager::(clearTask) Return.
Thread-180::INFO::2014-04-25 
19:58:18,791::logUtils::47::dispatcher::(wrapper) Run and protect: 
clearTask, Return response: None
Thread-180::DEBUG::2014-04-25 
19:58:18,791::task::1185::TaskManager.Task::(prepare) 
Task=`bc8109f7-7ca9-4900-afc2-653120a0f0b7`::finished: None
Thread-180::DEBUG::2014-04-25 
19:58:18,791::task::595::TaskManager.Task::(_updateState) 
Task=`bc8109f7-7ca9-4900-afc2-653120a0f0b7`::moving from state preparing 
-> state finished
Thread-180::DEBUG::2014-04-25 
19:58:18,791::resourceManager::940::ResourceManager.Owner::(releaseAll) 
Owner.releaseAll requests {} resources {}
Thread-180::DEBUG::2014-04-25 
19:58:18,792::resourceManager::977::ResourceManager.Owner::(cancelAll) 
Owner.cancelAll requests {}
Thread-180::DEBUG::2014-04-25 
19:58:18,792::task::990::TaskManager.Task::(_decref) 
Task=`bc8109f7-7ca9-4900-afc2-653120a0f0b7`::ref 0 aborting False
Thread-22::DEBUG::2014-04-25 
19:58:24,268::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd 
iflag=direct 
if=/rhev/data-center/mnt/_vdsm__store_s2data1__s2mgt__boot1/0a897f2e-1b01-4577-9f91-cd136ef4a978/dom_md/metadata

bs=4096 count=1' (cwd None)
Thread-22::DEBUG::2014-04-25 
19:58:24,272::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: 
<err> = '0+1 records in\n0+1 records out\n665 bytes (665 B) copied, 
0.000127032 s, 5.2 MB/s\n'; <rc> = 0
Thread-29::ERROR::2014-04-25 
19:58:24,475::sdc::137::Storage.StorageDomainCache::(_findDomain) 
looking for unfetched domain 9a4a80a1-5377-4a94-ade3-e58183e916ae
Thread-29::ERROR::2014-04-25 
19:58:24,475::sdc::154::Storage.StorageDomainCache::(_findUnfetchedDomain) 
looking for domain 9a4a80a1-5377-4a94-ade3-e58183e916ae
Thread-29::DEBUG::2014-04-25 
19:58:24,475::lvm::372::OperationMutex::(_reloadvgs) Operation 'lvm 
reload operation' got the operation mutex
Thread-29::DEBUG::2014-04-25 
19:58:24,476::lvm::295::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 obtain_device_list_from_udev=0 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,lv_count,pv_count,pv_name

9a4a80a1-5377-4a94-ade3-e58183e916ae' (cwd None)
Thread-29::DEBUG::2014-04-25 
19:58:24,489::lvm::295::Storage.Misc.excCmd::(cmd) FAILED: <err> = '  
Volume group "9a4a80a1-5377-4a94-ade3-e58183e916ae" not found\n  
Skipping volume group 9a4a80a1-5377-4a94-ade3-e58183e916ae\n'; <rc> = 5
Thread-29::WARNING::2014-04-25 
19:58:24,490::lvm::377::Storage.LVM::(_reloadvgs) lvm vgs failed: 5 [] 
['  Volume group "9a4a80a1-5377-4a94-ade3-e58183e916ae" not found',
'  
Skipping volume group 9a4a80a1-5377-4a94-ade3-e58183e916ae']
Thread-29::DEBUG::2014-04-25 
19:58:24,490::lvm::414::OperationMutex::(_reloadvgs) Operation 'lvm 
reload operation' released the operation mutex
Thread-29::ERROR::2014-04-25 
19:58:24,501::sdc::143::Storage.StorageDomainCache::(_findDomain) domain 
9a4a80a1-5377-4a94-ade3-e58183e916ae not found
Traceback (most recent call last):
   File "/usr/share/vdsm/storage/sdc.py", line 141, in _findDomain
     dom = findMethod(sdUUID)
   File "/usr/share/vdsm/storage/sdc.py", line 171, in _findUnfetchedDomain
     raise se.StorageDomainDoesNotExist(sdUUID)
StorageDomainDoesNotExist: Storage domain does not exist: 
('9a4a80a1-5377-4a94-ade3-e58183e916ae',)
Thread-29::ERROR::2014-04-25 
19:58:24,501::domainMonitor::239::Storage.DomainMonitorThread::(_monitorDomain) 
Error while collecting domain 9a4a80a1-5377-4a94-ade3-e58183e916ae 
monitoring information
Traceback (most recent call last):
   File "/usr/share/vdsm/storage/domainMonitor.py", line 204, in 
_monitorDomain
     self.domain = sdCache.produce(self.sdUUID)
   File "/usr/share/vdsm/storage/sdc.py", line 98, in produce
     domain.getRealDomain()
   File "/usr/share/vdsm/storage/sdc.py", line 52, in getRealDomain
     return self._cache._realProduce(self._sdUUID)
   File "/usr/share/vdsm/storage/sdc.py", line 122, in _realProduce
     domain = self._findDomain(sdUUID)
   File "/usr/share/vdsm/storage/sdc.py", line 141, in _findDomain
     dom = findMethod(sdUUID)
   File "/usr/share/vdsm/storage/sdc.py", line 171, in _findUnfetchedDomain
     raise se.StorageDomainDoesNotExist(sdUUID)
StorageDomainDoesNotExist: Storage domain does not exist: 
('9a4a80a1-5377-4a94-ade3-e58183e916ae',)
Thread-27::DEBUG::2014-04-25 
19:58:24,628::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd 
iflag=direct 
if=/rhev/data-center/mnt/_vdsm__store_s2data1__s2mgt__app1/c2c4ade6-049e-4159-a294-a0c151f4983d/dom_md/metadata

bs=4096 count=1' (cwd None)
Thread-27::DEBUG::2014-04-25 
19:58:24,633::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: 
<err> = '0+1 records in\n0+1 records out\n367 bytes (367 B) copied, 
0.000137914 s, 2.7 MB/s\n'; <rc> = 0
Thread-18::DEBUG::2014-04-25 
19:58:24,689::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd 
iflag=direct 
if=/rhev/data-center/mnt/_vdsm__store_s2data1__s2usr__boot1/e637bb04-a8b7-4c77-809c-d58051494c52/dom_md/metadata

bs=4096 count=1' (cwd None)
Thread-18::DEBUG::2014-04-25 
19:58:24,694::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: 
<err> = '0+1 records in\n0+1 records out\n369 bytes (369 B) copied, 
0.000117437 s, 3.1 MB/s\n'; <rc> = 0
Thread-17::DEBUG::2014-04-25 
19:58:25,365::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd 
iflag=direct 
if=/rhev/data-center/mnt/bdsvn001d:_iso/7b083758-45f9-4896-913d-11fe02043e6e/dom_md/metadata

bs=4096 count=1' (cwd None)
Thread-17::DEBUG::2014-04-25 
19:58:25,370::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: 
<err> = '0+1 records in\n0+1 records out\n373 bytes (373 B) copied, 
0.000802138 s, 465 kB/s\n'; <rc> = 0

Thanks, Paul

2024

2023

2022

2021

2020

2019

2018

2017

2016

2015

2014

2013

2012

2011

[ovirt-users] Storage Domain Not Found After upgrade from 3.3.2 to 3.4