[ovirt-users] Storage Domain Not Found After upgrade from 3.3.2 to 3.4
Gadi Ickowicz
gickowic at redhat.com
Mon Apr 28 06:07:19 UTC 2014
Hi Paul,
I am still looking into this log, but from a quick first assessment, it looks like (for some reason I don't know yet...) there is a storage domain that is missing. This is visible in the following error traceback in the vdsm log:
Thread-29::ERROR::2014-04-27 12:43:05,825::domainMonitor::239::Storage.DomainMonitorThread::(_monitorDomain) Error while collecting domain 9a4a80a1-5377-4a94-ade3-e58183e916ae m
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',)
However, I do not see any information in the vdsm log itself about what this domain is (yet - it may be there and I am still looking). The reason vdsm is trying to access this storage domain (9a4a80a1-5377-4a94-ade3-e58183e916ae) is that it appears to be part of the storage pool (datacenter) according to the pool's metadata, as seen in the following lines from the initial connection to the datacenter, when vdsm first starts up:
Thread-13::DEBUG::2014-04-27 12:42:05,604::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,0a897ff2e-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']
Is it possible you had another domain attached to this datacenter before the upgrade that is somehow on the root vg partitions and gets destroyed along the upgrade process, and then reverting brings them back?
If you have this system currently back to 3.3.2 it should be up, could you run the following commands on the ovirt-node:
vdsClient -s 0 getStorageDomainsList <- This lists all storage domains' ids that vdsm (the ovirt-node) can currently see (hopefully the domain in question's ID should be listed there)
vdsClient -s 0 getStorageDomainInfo 9a4a80a1-5377-4a94-ade3-e58183e916ae <- displays information about the storage domain. If this succeeds we should know a bit more about the domain
Thanks,
Gadi Ickowicz
----- Original Message -----
From: regpm at mccleary.me.uk
To: "Gadi Ickowicz" <gickowic at redhat.com>, users at ovirt.org
Sent: Sunday, April 27, 2014 3:10:27 PM
Subject: Re: [ovirt-users] Storage Domain Not Found After upgrade from 3.3.2 to 3.4
Hi,
Yes, you're correct, Gadi. I have a single Ovirt engine, which has two
Datacenters; one is local storage on the Engine server and the other is
local storage on the Ovirt Node. I've renamed the servers in the
attached vdsm log output (from the ovirt-node) to ovirt-engine
(10.50.0.18) and ovirt-node (10.50.0.19).
BDS_DataCentre1 is on the ovirt-engine server and this works fine after
the upgrade.
BDS_DataCentre2 is on the ovirt-node and this is the one that fails to
activate due to the storage domains not being accessible.
The Master storage domain on the ovirt-node is s2data1_s2mgt_boot1.
There are two other storage domains as well: s2data1_s2mgt_app1 and
s2data1_s2usr_boot1. The underlying filesystems are mounted fine, and
as I said, if I restore the server (root vg partitions; the storage
domain filesystems are not touched) then it works fine again. So the
upgrade is not playing nicely for some reason, but it's not clear to me
from the log what the issue is.
Thanks,
Paul
On 27/04/2014 07:56, Gadi Ickowicz wrote:
> Hi,
>
> Could you please attach the vdsm log as a file (it is easier to read) for the failing node?
>
> Also - I am a bit confused regarding what exactly your setup is - Do you have only a single engine (the all-in-one) and 2 dcs, one for the all in one and one for the oVirt node, which is the one that is failing?
>
> Thanks,
> Gadi Ickowicz
>
> ----- Original Message -----
> From: regpm at mccleary.me.uk
> To: users at ovirt.org
> Sent: Friday, April 25, 2014 10:46:35 PM
> Subject: [ovirt-users] Storage Domain Not Found After upgrade from 3.3.2 to 3.4
>
> 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
> _______________________________________________
> Users mailing list
> Users at ovirt.org
> http://lists.ovirt.org/mailman/listinfo/users
More information about the Users
mailing list