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@mccleary.me.uk To: users@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@ovirt.org http://lists.ovirt.org/mailman/listinfo/users