Re: [ovirt-users] vdsm storage problem - maybe cache problem?

Anyone? 09:20:19,763::sp::330::Storage.StoragePool::(startSpm) failed: Storage domain does not exist: ('036b5575-51fa-4f14-8b05-890d7807894c',) engine=> select id,storage,storage_name from storage_domain_static; See: http://fpaste.org/223212/43202019/ Why does the vdsm Node think it must use Storage Domain 036b5575-51fa-4f14-8b05-890d7807894c? Thanks, Mario Am 18.05.15 um 14:40 schrieb ml@ohnewald.net:

Manual mounting works:

[root@ovirt-node01 ~]# mount ovirt.hq.example.net:/export2 /tmp/mnt/ [root@ovirt-node01 ~]# umount /tmp/mnt/

(but i removed the export2 domain from the webgui engine. I still wonder why the node want to access it....)

vdsm log: ================ StorageDomainDoesNotExist: Storage domain does not exist: ('036b5575-51fa-4f14-8b05-890d7807894c',) 47d37321-3f0f-4a1b-a8d5-629065fc1c4c::ERROR::2015-05-18 14:35:35,099::sdc::137::Storage.StorageDomainCache::(_findDomain) looking for unfetched domain 036b5575-51fa-4f14-8b05-890d7807894c 47d37321-3f0f-4a1b-a8d5-629065fc1c4c::ERROR::2015-05-18 14:35:35,099::sdc::154::Storage.StorageDomainCache::(_findUnfetchedDomain) looking for domain 036b5575-51fa-4f14-8b05-890d7807894c 47d37321-3f0f-4a1b-a8d5-629065fc1c4c::DEBUG::2015-05-18 14:35:35,100::lvm::372::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex 47d37321-3f0f-4a1b-a8d5-629065fc1c4c::DEBUG::2015-05-18 14:35:35,100::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 036b5575-51fa-4f14-8b05-890d7807894c' (cwd None) 47d37321-3f0f-4a1b-a8d5-629065fc1c4c::DEBUG::2015-05-18 14:35:35,121::lvm::295::Storage.Misc.excCmd::(cmd) FAILED: <err> = ' Volume group "036b5575-51fa-4f14-8b05-890d7807894c" not found\n Skipping volume group 036b5575-51fa-4f14-8b05-890d7807894c\n'; <rc> = 5 47d37321-3f0f-4a1b-a8d5-629065fc1c4c::WARNING::2015-05-18 14:35:35,122::lvm::377::Storage.LVM::(_reloadvgs) lvm vgs failed: 5 [] [' Volume group "036b5575-51fa-4f14-8b05-890d7807894c" not found', ' Skipping volume group 036b5575-51fa-4f14-8b05-890d7807894c'] 47d37321-3f0f-4a1b-a8d5-629065fc1c4c::DEBUG::2015-05-18 14:35:35,122::lvm::414::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex 47d37321-3f0f-4a1b-a8d5-629065fc1c4c::ERROR::2015-05-18 14:35:35,133::sdc::143::Storage.StorageDomainCache::(_findDomain) domain 036b5575-51fa-4f14-8b05-890d7807894c 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: ('036b5575-51fa-4f14-8b05-890d7807894c',) 47d37321-3f0f-4a1b-a8d5-629065fc1c4c::ERROR::2015-05-18 14:35:35,133::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: ('036b5575-51fa-4f14-8b05-890d7807894c',) 47d37321-3f0f-4a1b-a8d5-629065fc1c4c::ERROR::2015-05-18 14:35:35,134::sp::330::Storage.StoragePool::(startSpm) failed: Storage domain does not exist: ('036b5575-51fa-4f14-8b05-890d7807894c',) 47d37321-3f0f-4a1b-a8d5-629065fc1c4c::DEBUG::2015-05-18 14:35:35,134::sp::336::Storage.StoragePool::(_shutDownUpgrade) Shutting down upgrade process 47d37321-3f0f-4a1b-a8d5-629065fc1c4c::DEBUG::2015-05-18 14:35:35,134::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.upgrade_b384b3da-02a6-44f3-a3f6-56751ce8c26d`ReqID=`24d881e8-eba3-4b51-85e7-32301218b2e9`::Request was made in '/usr/share/vdsm/storage/sp.py' line '338' at '_shutDownUpgrade' 47d37321-3f0f-4a1b-a8d5-629065fc1c4c::DEBUG::2015-05-18 14:35:35,135::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.upgrade_b384b3da-02a6-44f3-a3f6-56751ce8c26d' for lock type 'exclusive' 47d37321-3f0f-4a1b-a8d5-629065fc1c4c::DEBUG::2015-05-18 14:35:35,135::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.upgrade_b384b3da-02a6-44f3-a3f6-56751ce8c26d' is free. Now locking as 'exclusive' (1 active user) 47d37321-3f0f-4a1b-a8d5-629065fc1c4c::DEBUG::2015-05-18 14:35:35,135::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.upgrade_b384b3da-02a6-44f3-a3f6-56751ce8c26d`ReqID=`24d881e8-eba3-4b51-85e7-32301218b2e9`::Granted request 47d37321-3f0f-4a1b-a8d5-629065fc1c4c::DEBUG::2015-05-18 14:35:35,136::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.upgrade_036b5575-51fa-4f14-8b05-890d7807894c`ReqID=`140bc21d-520f-4796-aab0-595f7aba6932`::Request was made in '/usr/share/vdsm/storage/sp.py' line '358' at '_shutDownUpgrade' 47d37321-3f0f-4a1b-a8d5-629065fc1c4c::DEBUG::2015-05-18 14:35:35,136::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.upgrade_036b5575-51fa-4f14-8b05-890d7807894c' for lock type 'exclusive' 47d37321-3f0f-4a1b-a8d5-629065fc1c4c::DEBUG::2015-05-18 14:35:35,136::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.upgrade_036b5575-51fa-4f14-8b05-890d7807894c' is free. Now locking as 'exclusive' (1 active user) 47d37321-3f0f-4a1b-a8d5-629065fc1c4c::DEBUG::2015-05-18 14:35:35,136::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.upgrade_036b5575-51fa-4f14-8b05-890d7807894c`ReqID=`140bc21d-520f-4796-aab0-595f7aba6932`::Granted request 47d37321-3f0f-4a1b-a8d5-629065fc1c4c::DEBUG::2015-05-18 14:35:35,136::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.upgrade_036b5575-51fa-4f14-8b05-890d7807894c' 47d37321-3f0f-4a1b-a8d5-629065fc1c4c::DEBUG::2015-05-18 14:35:35,137::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.upgrade_036b5575-51fa-4f14-8b05-890d7807894c' (0 active users) 47d37321-3f0f-4a1b-a8d5-629065fc1c4c::DEBUG::2015-05-18 14:35:35,137::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.upgrade_036b5575-51fa-4f14-8b05-890d7807894c' is free, finding out if anyone is waiting for it. 47d37321-3f0f-4a1b-a8d5-629065fc1c4c::DEBUG::2015-05-18 14:35:35,137::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.upgrade_036b5575-51fa-4f14-8b05-890d7807894c', Clearing records. 47d37321-3f0f-4a1b-a8d5-629065fc1c4c::DEBUG::2015-05-18 14:35:35,137::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.upgrade_b384b3da-02a6-44f3-a3f6-56751ce8c26d' 47d37321-3f0f-4a1b-a8d5-629065fc1c4c::DEBUG::2015-05-18 14:35:35,137::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.upgrade_b384b3da-02a6-44f3-a3f6-56751ce8c26d' (0 active users) 47d37321-3f0f-4a1b-a8d5-629065fc1c4c::DEBUG::2015-05-18 14:35:35,138::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.upgrade_b384b3da-02a6-44f3-a3f6-56751ce8c26d' is free, finding out if anyone is waiting for it. 47d37321-3f0f-4a1b-a8d5-629065fc1c4c::DEBUG::2015-05-18 14:35:35,138::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.upgrade_b384b3da-02a6-44f3-a3f6-56751ce8c26d', Clearing records. 47d37321-3f0f-4a1b-a8d5-629065fc1c4c::DEBUG::2015-05-18 14:35:35,138::persistentDict::167::Storage.PersistentDict::(transaction) Starting transaction 47d37321-3f0f-4a1b-a8d5-629065fc1c4c::DEBUG::2015-05-18 14:35:35,139::persistentDict::173::Storage.PersistentDict::(transaction) Flushing changes 47d37321-3f0f-4a1b-a8d5-629065fc1c4c::DEBUG::2015-05-18 14:35:35,139::persistentDict::299::Storage.PersistentDict::(flush) about to write lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=RaidVolBGluster', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=1', 'POOL_DESCRIPTION=HP_Proliant_DL180G6', 'POOL_DOMAINS=6d882c77-cdbc-48ef-ae21-1a6d45e7f8a1:Active,036b5575-51fa-4f14-8b05-890d7807894c:Active,abc51e26-7175-4b38-b3a8-95c6928fbc2b:Active,23602741-2967-4fad-a749-d58e1459d5c8:Attached', 'POOL_SPM_ID=-1', 'POOL_SPM_LVER=0', 'POOL_UUID=b384b3da-02a6-44f3-a3f6-56751ce8c26d', 'REMOTE_PATH=127.0.0.1:/RaidVolB', 'ROLE=Master', 'SDUUID=abc51e26-7175-4b38-b3a8-95c6928fbc2b', 'TYPE=GLUSTERFS', 'VERSION=3', '_SHA_CKSUM=401970538872dfd4e17afcb84361851559b18e4c'] 47d37321-3f0f-4a1b-a8d5-629065fc1c4c::DEBUG::2015-05-18 14:35:35,146::persistentDict::175::Storage.PersistentDict::(transaction) Finished transaction 47d37321-3f0f-4a1b-a8d5-629065fc1c4c::INFO::2015-05-18 14:35:35,146::clusterlock::279::SANLock::(release) Releasing cluster lock for domain abc51e26-7175-4b38-b3a8-95c6928fbc2b 47d37321-3f0f-4a1b-a8d5-629065fc1c4c::DEBUG::2015-05-18 14:35:35,151::clusterlock::289::SANLock::(release) Cluster lock for domain abc51e26-7175-4b38-b3a8-95c6928fbc2b successfully released 47d37321-3f0f-4a1b-a8d5-629065fc1c4c::ERROR::2015-05-18 14:35:35,151::task::866::TaskManager.Task::(_setError) Task=`47d37321-3f0f-4a1b-a8d5-629065fc1c4c`::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: ('036b5575-51fa-4f14-8b05-890d7807894c',) 47d37321-3f0f-4a1b-a8d5-629065fc1c4c::DEBUG::2015-05-18 14:35:35,151::task::885::TaskManager.Task::(_run) Task=`47d37321-3f0f-4a1b-a8d5-629065fc1c4c`::Task._run: 47d37321-3f0f-4a1b-a8d5-629065fc1c4c () {} failed - stopping task 47d37321-3f0f-4a1b-a8d5-629065fc1c4c::DEBUG::2015-05-18 14:35:35,152::task::1211::TaskManager.Task::(stop) Task=`47d37321-3f0f-4a1b-a8d5-629065fc1c4c`::stopping in state running (force False) 47d37321-3f0f-4a1b-a8d5-629065fc1c4c::DEBUG::2015-05-18 14:35:35,152::task::990::TaskManager.Task::(_decref) Task=`47d37321-3f0f-4a1b-a8d5-629065fc1c4c`::ref 1 aborting True 47d37321-3f0f-4a1b-a8d5-629065fc1c4c::DEBUG::2015-05-18 14:35:35,152::task::916::TaskManager.Task::(_runJobs) Task=`47d37321-3f0f-4a1b-a8d5-629065fc1c4c`::aborting: Task is aborted: 'Storage domain does not exist' - code 358 47d37321-3f0f-4a1b-a8d5-629065fc1c4c::DEBUG::2015-05-18 14:35:35,152::task::990::TaskManager.Task::(_decref) Task=`47d37321-3f0f-4a1b-a8d5-629065fc1c4c`::ref 0 aborting True 47d37321-3f0f-4a1b-a8d5-629065fc1c4c::DEBUG::2015-05-18 14:35:35,152::task::925::TaskManager.Task::(_doAbort) Task=`47d37321-3f0f-4a1b-a8d5-629065fc1c4c`::Task._doAbort: force False 47d37321-3f0f-4a1b-a8d5-629065fc1c4c::DEBUG::2015-05-18 14:35:35,153::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} 47d37321-3f0f-4a1b-a8d5-629065fc1c4c::DEBUG::2015-05-18 14:35:35,153::task::595::TaskManager.Task::(_updateState) Task=`47d37321-3f0f-4a1b-a8d5-629065fc1c4c`::moving from state running -> state aborting 47d37321-3f0f-4a1b-a8d5-629065fc1c4c::DEBUG::2015-05-18 14:35:35,153::task::550::TaskManager.Task::(__state_aborting) Task=`47d37321-3f0f-4a1b-a8d5-629065fc1c4c`::_aborting: recover policy auto 47d37321-3f0f-4a1b-a8d5-629065fc1c4c::DEBUG::2015-05-18 14:35:35,153::task::595::TaskManager.Task::(_updateState) Task=`47d37321-3f0f-4a1b-a8d5-629065fc1c4c`::moving from state aborting -> state racquiring 47d37321-3f0f-4a1b-a8d5-629065fc1c4c::DEBUG::2015-05-18 14:35:35,153::task::595::TaskManager.Task::(_updateState) Task=`47d37321-3f0f-4a1b-a8d5-629065fc1c4c`::moving from state racquiring -> state recovering 47d37321-3f0f-4a1b-a8d5-629065fc1c4c::DEBUG::2015-05-18 14:35:35,153::task::798::TaskManager.Task::(_recover) Task=`47d37321-3f0f-4a1b-a8d5-629065fc1c4c`::_recover 47d37321-3f0f-4a1b-a8d5-629065fc1c4c::DEBUG::2015-05-18 14:35:35,154::task::805::TaskManager.Task::(_recover) Task=`47d37321-3f0f-4a1b-a8d5-629065fc1c4c`::running recovery None 47d37321-3f0f-4a1b-a8d5-629065fc1c4c::DEBUG::2015-05-18 14:35:35,154::task::786::TaskManager.Task::(_recoverDone) Task=`47d37321-3f0f-4a1b-a8d5-629065fc1c4c`::Recover Done: state recovering 47d37321-3f0f-4a1b-a8d5-629065fc1c4c::DEBUG::2015-05-18 14:35:35,154::task::595::TaskManager.Task::(_updateState) Task=`47d37321-3f0f-4a1b-a8d5-629065fc1c4c`::moving from state recovering -> state recovered 47d37321-3f0f-4a1b-a8d5-629065fc1c4c::DEBUG::2015-05-18 14:35:35,154::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.b384b3da-02a6-44f3-a3f6-56751ce8c26d': < ResourceRef 'Storage.b384b3da-02a6-44f3-a3f6-56751ce8c26d', isValid: 'True' obj: 'None'>} 47d37321-3f0f-4a1b-a8d5-629065fc1c4c::DEBUG::2015-05-18 14:35:35,154::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} 47d37321-3f0f-4a1b-a8d5-629065fc1c4c::DEBUG::2015-05-18 14:35:35,155::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.b384b3da-02a6-44f3-a3f6-56751ce8c26d' 47d37321-3f0f-4a1b-a8d5-629065fc1c4c::DEBUG::2015-05-18 14:35:35,155::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.b384b3da-02a6-44f3-a3f6-56751ce8c26d' (0 active users) 47d37321-3f0f-4a1b-a8d5-629065fc1c4c::DEBUG::2015-05-18 14:35:35,155::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.b384b3da-02a6-44f3-a3f6-56751ce8c26d' is free, finding out if anyone is waiting for it. 47d37321-3f0f-4a1b-a8d5-629065fc1c4c::DEBUG::2015-05-18 14:35:35,155::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.b384b3da-02a6-44f3-a3f6-56751ce8c26d', Clearing records. 47d37321-3f0f-4a1b-a8d5-629065fc1c4c::DEBUG::2015-05-18 14:35:35,155::threadPool::57::Misc.ThreadPool::(setRunningTask) Number of running tasks: 0 Thread-40::DEBUG::2015-05-18 14:35:35,284::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/glusterSD/127.0.0.1:_RaidVolB/abc51e26-7175-4b38-b3a8-95c6928fbc2b/dom_md/metadata bs=4096 count=1' (cwd None) Thread-40::DEBUG::2015-05-18 14:35:35,295::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n613 bytes (613 B) copied, 0.000701751 s, 874 kB/s\n'; <rc> = 0 Thread-5036::DEBUG::2015-05-18 14:35:35,501::task::595::TaskManager.Task::(_updateState) Task=`4ff82d7b-b4a7-48f0-ba5f-7381d2dcee67`::moving from state init -> state preparing Thread-5036::INFO::2015-05-18 14:35:35,501::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None) Thread-5036::INFO::2015-05-18 14:35:35,502::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'6d882c77-cdbc-48ef-ae21-1a6d45e7f8a1': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000757621', 'lastCheck': '1.9', 'valid': True}, '036b5575-51fa-4f14-8b05-890d7807894c': {'code': 358, 'version': -1, 'acquired': False, 'delay': '0', 'lastCheck': '9.1', 'valid': False}, 'abc51e26-7175-4b38-b3a8-95c6928fbc2b': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000701751', 'lastCheck': '0.2', 'valid': True}} Thread-5036::DEBUG::2015-05-18 14:35:35,502::task::1185::TaskManager.Task::(prepare) Task=`4ff82d7b-b4a7-48f0-ba5f-7381d2dcee67`::finished: {'6d882c77-cdbc-48ef-ae21-1a6d45e7f8a1': {'code': 0, 'version': 0, 'acquired': True, 'delay': '0.000757621', 'lastCheck': '1.9', 'valid': True}, '036b5575-51fa-4f14-8b05-890d7807894c': {'code': 358, 'version': -1, 'acquired': False, 'delay': '0', 'lastCheck': '9.1', 'valid': False}, 'abc51e26-7175-4b38-b3a8-95c6928fbc2b': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000701751', 'lastCheck': '0.2', 'valid': True}} Thread-5036::DEBUG::2015-05-18 14:35:35,502::task::595::TaskManager.Task::(_updateState) Task=`4ff82d7b-b4a7-48f0-ba5f-7381d2dcee67`::moving from state preparing -> state finished Thread-5036::DEBUG::2015-05-18 14:35:35,502::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-5036::DEBUG::2015-05-18 14:35:35,503::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-5036::DEBUG::2015-05-18 14:35:35,503::task::990::TaskManager.Task::(_decref) Task=`4ff82d7b-b4a7-48f0-ba5f-7381d2dcee67`::ref 0 aborting False VM Channels Listener::DEBUG::2015-05-18 14:35:35,562::vmChannels::128::vds::(_handle_unconnected) Trying to connect fileno 38. VM Channels Listener::DEBUG::2015-05-18 14:35:35,562::vmChannels::128::vds::(_handle_unconnected) Trying to connect fileno 72. VM Channels Listener::DEBUG::2015-05-18 14:35:35,562::vmChannels::128::vds::(_handle_unconnected) Trying to connect fileno 49. VM Channels Listener::DEBUG::2015-05-18 14:35:35,563::vmChannels::128::vds::(_handle_unconnected) Trying to connect fileno 50. VM Channels Listener::DEBUG::2015-05-18 14:35:35,563::vmChannels::128::vds::(_handle_unconnected) Trying to connect fileno 54. VM Channels Listener::DEBUG::2015-05-18 14:35:35,563::vmChannels::128::vds::(_handle_unconnected) Trying to connect fileno 62. Thread-5036::DEBUG::2015-05-18 14:35:35,938::BindingXMLRPC::251::vds::(wrapper) client [192.168.30.103] flowID [447665f7] Thread-5036::DEBUG::2015-05-18 14:35:35,939::task::595::TaskManager.Task::(_updateState) Task=`c7cd482f-ee37-4b8e-a879-16bd4f317e97`::moving from state init -> state preparing Thread-5036::INFO::2015-05-18 14:35:35,939::logUtils::44::dispatcher::(wrapper) Run and protect: getTaskStatus(taskID='47d37321-3f0f-4a1b-a8d5-629065fc1c4c', spUUID=None, options=None) Thread-5036::DEBUG::2015-05-18 14:35:35,939::taskManager::93::TaskManager::(getTaskStatus) Entry. taskID: 47d37321-3f0f-4a1b-a8d5-629065fc1c4c Thread-5036::DEBUG::2015-05-18 14:35:35,939::taskManager::96::TaskManager::(getTaskStatus) Return. Response: {'code': 358, 'message': 'Storage domain does not exist', 'taskState': 'finished', 'taskResult': 'cleanSuccess', 'taskID': '47d37321-3f0f-4a1b-a8d5-629065fc1c4c'} Thread-5036::INFO::2015-05-18 14:35:35,939::logUtils::47::dispatcher::(wrapper) Run and protect: getTaskStatus, Return response: {'taskStatus': {'code': 358, 'message': 'Storage domain does not exist', 'taskState': 'finished', 'taskResult': 'cleanSuccess', 'taskID': '47d37321-3f0f-4a1b-a8d5-629065fc1c4c'}} Thread-5036::DEBUG::2015-05-18 14:35:35,940::task::1185::TaskManager.Task::(prepare) Task=`c7cd482f-ee37-4b8e-a879-16bd4f317e97`::finished: {'taskStatus': {'code': 358, 'message': 'Storage domain does not exist', 'taskState': 'finished', 'taskResult': 'cleanSuccess', 'taskID': '47d37321-3f0f-4a1b-a8d5-629065fc1c4c'}} Thread-5036::DEBUG::2015-05-18 14:35:35,940::task::595::TaskManager.Task::(_updateState) Task=`c7cd482f-ee37-4b8e-a879-16bd4f317e97`::moving from state preparing -> state finished Thread-5036::DEBUG::2015-05-18 14:35:35,940::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-5036::DEBUG::2015-05-18 14:35:35,940::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-5036::DEBUG::2015-05-18 14:35:35,940::task::990::TaskManager.Task::(_decref) Task=`c7cd482f-ee37-4b8e-a879-16bd4f317e97`::ref 0 aborting False Thread-5036::DEBUG::2015-05-18 14:35:35,952::BindingXMLRPC::251::vds::(wrapper) client [192.168.30.103] flowID [447665f7] Thread-5036::DEBUG::2015-05-18 14:35:35,953::task::595::TaskManager.Task::(_updateState) Task=`e30dd05c-4520-4074-94ea-632be5ffa06d`::moving from state init -> state preparing Thread-5036::INFO::2015-05-18 14:35:35,953::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='b384b3da-02a6-44f3-a3f6-56751ce8c26d', options=None) Thread-5036::INFO::2015-05-18 14:35:35,957::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': -1, 'spmStatus': 'Free', 'spmLver': -1}} Thread-5036::DEBUG::2015-05-18 14:35:35,957::task::1185::TaskManager.Task::(prepare) Task=`e30dd05c-4520-4074-94ea-632be5ffa06d`::finished: {'spm_st': {'spmId': -1, 'spmStatus': 'Free', 'spmLver': -1}} Thread-5036::DEBUG::2015-05-18 14:35:35,958::task::595::TaskManager.Task::(_updateState) Task=`e30dd05c-4520-4074-94ea-632be5ffa06d`::moving from state preparing -> state finished Thread-5036::DEBUG::2015-05-18 14:35:35,958::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-5036::DEBUG::2015-05-18 14:35:35,958::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-5036::DEBUG::2015-05-18 14:35:35,958::task::990::TaskManager.Task::(_decref) Task=`e30dd05c-4520-4074-94ea-632be5ffa06d`::ref 0 aborting False Thread-5036::DEBUG::2015-05-18 14:35:36,062::BindingXMLRPC::251::vds::(wrapper) client [192.168.30.103] flowID [447665f7] Thread-5036::DEBUG::2015-05-18 14:35:36,063::task::595::TaskManager.Task::(_updateState) Task=`a8cae188-5991-4513-a077-2f6d2bc7b3e6`::moving from state init -> state preparing Thread-5036::INFO::2015-05-18 14:35:36,063::logUtils::44::dispatcher::(wrapper) Run and protect: clearTask(taskID='47d37321-3f0f-4a1b-a8d5-629065fc1c4c', spUUID=None, options=None) Thread-5036::DEBUG::2015-05-18 14:35:36,063::taskManager::161::TaskManager::(clearTask) Entry. taskID: 47d37321-3f0f-4a1b-a8d5-629065fc1c4c Thread-5036::DEBUG::2015-05-18 14:35:36,063::taskManager::166::TaskManager::(clearTask) Return. Thread-5036::INFO::2015-05-18 14:35:36,063::logUtils::47::dispatcher::(wrapper) Run and protect: clearTask, Return response: None Thread-5036::DEBUG::2015-05-18 14:35:36,063::task::1185::TaskManager.Task::(prepare) Task=`a8cae188-5991-4513-a077-2f6d2bc7b3e6`::finished: None Thread-5036::DEBUG::2015-05-18 14:35:36,064::task::595::TaskManager.Task::(_updateState) Task=`a8cae188-5991-4513-a077-2f6d2bc7b3e6`::moving from state preparing -> state finished Thread-5036::DEBUG::2015-05-18 14:35:36,064::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-5036::DEBUG::2015-05-18 14:35:36,064::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-5036::DEBUG::2015-05-18 14:35:36,064::task::990::TaskManager.Task::(_decref) Task=`a8cae188-5991-4513-a077-2f6d2bc7b3e6`::ref 0 aborting False Thread-5036::DEBUG::2015-05-18 14:35:36,300::BindingXMLRPC::251::vds::(wrapper) client [192.168.30.103] flowID [4f00b66b] Thread-5036::DEBUG::2015-05-18 14:35:36,301::task::595::TaskManager.Task::(_updateState) Task=`0b2423bc-dbf2-483e-85b9-fbf6f446b305`::moving from state init -> state preparing Thread-5036::INFO::2015-05-18 14:35:36,301::logUtils::44::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID='b384b3da-02a6-44f3-a3f6-56751ce8c26d', options=None) Thread-5036::INFO::2015-05-18 14:35:36,306::logUtils::47::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': -1, 'spmStatus': 'Free', 'spmLver': -1}} Thread-5036::DEBUG::2015-05-18 14:35:36,306::task::1185::TaskManager.Task::(prepare) Task=`0b2423bc-dbf2-483e-85b9-fbf6f446b305`::finished: {'spm_st': {'spmId': -1, 'spmStatus': 'Free', 'spmLver': -1}} Thread-5036::DEBUG::2015-05-18 14:35:36,307::task::595::TaskManager.Task::(_updateState) Task=`0b2423bc-dbf2-483e-85b9-fbf6f446b305`::moving from state preparing -> state finished Thread-5036::DEBUG::2015-05-18 14:35:36,307::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-5036::DEBUG::2015-05-18 14:35:36,307::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-5036::DEBUG::2015-05-18 14:35:36,307::task::990::TaskManager.Task::(_decref) Task=`0b2423bc-dbf2-483e-85b9-fbf6f446b305`::ref 0 aborting False Thread-36::ERROR::2015-05-18 14:35:36,419::sdc::137::Storage.StorageDomainCache::(_findDomain) looking for unfetched domain 036b5575-51fa-4f14-8b05-890d7807894c Thread-36::ERROR::2015-05-18 14:35:36,419::sdc::154::Storage.StorageDomainCache::(_findUnfetchedDomain) looking for domain 036b5575-51fa-4f14-8b05-890d7807894c Thread-36::DEBUG::2015-05-18 14:35:36,419::lvm::372::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex Thread-36::DEBUG::2015-05-18 14:35:36,420::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 036b5575-51fa-4f14-8b05-890d7807894c' (cwd None) Thread-36::DEBUG::2015-05-18 14:35:36,443::lvm::295::Storage.Misc.excCmd::(cmd) FAILED: <err> = ' Volume group "036b5575-51fa-4f14-8b05-890d7807894c" not found\n Skipping volume group 036b5575-51fa-4f14-8b05-890d7807894c\n'; <rc> = 5 Thread-36::WARNING::2015-05-18 14:35:36,444::lvm::377::Storage.LVM::(_reloadvgs) lvm vgs failed: 5 [] [' Volume group "036b5575-51fa-4f14-8b05-890d7807894c" not found', ' Skipping volume group 036b5575-51fa-4f14-8b05-890d7807894c'] Thread-36::DEBUG::2015-05-18 14:35:36,444::lvm::414::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex Thread-36::ERROR::2015-05-18 14:35:36,460::sdc::143::Storage.StorageDomainCache::(_findDomain) domain 036b5575-51fa-4f14-8b05-890d7807894c 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: ('036b5575-51fa-4f14-8b05-890d7807894c',) Thread-36::ERROR::2015-05-18 14:35:36,463::domainMonitor::239::Storage.DomainMonitorThread::(_monitorDomain) Error while collecting domain 036b5575-51fa-4f14-8b05-890d7807894c 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: ('036b5575-51fa-4f14-8b05-890d7807894c',) VM Channels Listener::DEBUG::2015-05-18 14:35:36,564::vmChannels::128::vds::(_handle_unconnected) Trying to connect fileno 38. VM Channels Listener::DEBUG::2015-05-18 14:35:36,564::vmChannels::128::vds::(_handle_unconnected) Trying to connect fileno 72. VM Channels Listener::DEBUG::2015-05-18 14:35:36,565::vmChannels::128::vds::(_handle_unconnected) Trying to connect fileno 49. VM Channels Listener::DEBUG::2015-05-18 14:35:36,565::vmChannels::128::vds::(_handle_unconnected) Trying to connect fileno 50. VM Channels Listener::DEBUG::2015-05-18 14:35:36,565::vmChannels::128::vds::(_handle_unconnected) Trying to connect fileno 54. VM Channels Listener::DEBUG::2015-05-18 14:35:36,565::vmChannels::128::vds::(_handle_unconnected) Trying to connect fileno 62. VM Channels Listener::DEBUG::2015-05-18 14:35:37,566::vmChannels::128::vds::(_handle_unconnected) Trying to connect fileno 38. VM Channels Listener::DEBUG::2015-05-18 14:35:37,566::vmChannels::128::vds::(_handle_unconnected) Trying to connect fileno 72. VM Channels Listener::DEBUG::2015-05-18 14:35:37,566::vmChannels::128::vds::(_handle_unconnected) Trying to connect fileno 49. VM Channels Listener::DEBUG::2015-05-18 14:35:37,566::vmChannels::128::vds::(_handle_unconnected) Trying to connect fileno 50. VM Channels Listener::DEBUG::2015-05-18 14:35:37,566::vmChannels::128::vds::(_handle_unconnected) Trying to connect fileno 54. VM Channels Listener::DEBUG::2015-05-18 14:35:37,566::vmChannels::128::vds::(_handle_unconnected) Trying to connect fileno 62. Thread-27::DEBUG::2015-05-18 14:35:38,253::task::595::TaskManager.Task::(_updateState) Task=`7674d743-bdef-497b-8dd3-98716e8c8f94`::moving from state init -> state preparing Thread-27::INFO::2015-05-18 14:35:38,253::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='abc51e26-7175-4b38-b3a8-95c6928fbc2b', spUUID='b384b3da-02a6-44f3-a3f6-56751ce8c26d', imgUUID='9faa9678-d0c3-4886-bb7d-201032c60901', volUUID='3fd534be-fdd3-4f3a-96f1-e8d73f2660a7', options=None) Thread-27::INFO::2015-05-18 14:35:38,257::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '42949672960', 'apparentsize': '42949672960'} Thread-27::DEBUG::2015-05-18 14:35:38,258::task::1185::TaskManager.Task::(prepare) Task=`7674d743-bdef-497b-8dd3-98716e8c8f94`::finished: {'truesize': '42949672960', 'apparentsize': '42949672960'} Thread-27::DEBUG::2015-05-18 14:35:38,258::task::595::TaskManager.Task::(_updateState) Task=`7674d743-bdef-497b-8dd3-98716e8c8f94`::moving from state preparing -> state finished Thread-27::DEBUG::2015-05-18 14:35:38,258::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-27::DEBUG::2015-05-18 14:35:38,258::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-27::DEBUG::2015-05-18 14:35:38,258::task::990::TaskManager.Task::(_decref) Task=`7674d743-bdef-497b-8dd3-98716e8c8f94`::ref 0 aborting False Thread-5036::DEBUG::2015-05-18 14:35:38,480::BindingXMLRPC::1067::vds::(wrapper) client [192.168.30.103]::call volumesList with () {} flowID [e98fff5] VM Channels Listener::DEBUG::2015-05-18 14:35:38,567::vmChannels::128::vds::(_handle_unconnected) Trying to connect fileno 38. VM Channels Listener::DEBUG::2015-05-18 14:35:38,568::vmChannels::128::vds::(_handle_unconnected) Trying to connect fileno 72. VM Channels Listener::DEBUG::2015-05-18 14:35:38,568::vmChannels::128::vds::(_handle_unconnected) Trying to connect fileno 49. VM Channels Listener::DEBUG::2015-05-18 14:35:38,568::vmChannels::128::vds::(_handle_unconnected) Trying to connect fileno 50. VM Channels Listener::DEBUG::2015-05-18 14:35:38,568::vmChannels::128::vds::(_handle_unconnected) Trying to connect fileno 54. VM Channels Listener::DEBUG::2015-05-18 14:35:38,569::vmChannels::128::vds::(_handle_unconnected) Trying to connect fileno 62. Thread-5036::DEBUG::2015-05-18 14:35:38,592::BindingXMLRPC::1074::vds::(wrapper) return volumesList with {'status': {'message': 'Done', 'code': 0}, 'volumes': {'RaidVolB': {'transportType': ['TCP'], 'uuid': 'd46619e9-9368-4e82-bf3a-a2377b6e85e4', 'bricks': ['ovirt-node01.stuttgart.example.net:/raidvol/volb', 'ovirt-node02.stuttgart.example.net:/raidvol/volb'], 'volumeName': 'RaidVolB', 'volumeType': 'REPLICATE', 'replicaCount': '2', 'brickCount': '2', 'distCount': '2', 'volumeStatus': 'ONLINE', 'stripeCount': '1', 'bricksInfo': [{'name': 'ovirt-node01.stuttgart.example.net:/raidvol/volb', 'hostUuid': 'de2a515f-c728-449d-b91c-d80cabe0539f'}, {'name': 'ovirt-node02.stuttgart.example.net:/raidvol/volb', 'hostUuid': '7540f5c0-c4ba-4520-bdf1-3115c10d0eea'}], 'options': {'user.cifs': 'disable', 'storage.owner-gid': '36', 'storage.owner-uid': '36', 'nfs.disable': 'on', 'auth.allow': '*'}}}} VM Channels Listener::DEBUG::2015-05-18 14:35:39,570::vmChannels::128::vds::(_handle_unconnected) Trying to connect fileno 38. VM Channels Listener::DEBUG::2015-05-18 14:35:39,570::vmChannels::128::vds::(_handle_unconnected) Trying to connect fileno 72. VM Channels Listener::DEBUG::2015-05-18 14:35:39,570::vmChannels::128::vds::(_handle_unconnected) Trying to connect fileno 49. VM Channels Listener::DEBUG::2015-05-18 14:35:39,570::vmChannels::128::vds::(_handle_unconnected) Trying to connect fileno 50. VM Channels Listener::DEBUG::2015-05-18 14:35:39,571::vmChannels::128::vds::(_handle_unconnected) Trying to connect fileno 54. VM Channels Listener::DEBUG::2015-05-18 14:35:39,571::vmChannels::128::vds::(_handle_unconnected) Trying to connect fileno 62. VM Channels Listener::DEBUG::2015-05-18 14:35:40,572::vmChannels::128::vds::(_handle_unconnected) Trying to connect fileno 38. VM Channels Listener::DEBUG::2015-05-18 14:35:40,572::vmChannels::128::vds::(_handle_unconnected) Trying to connect fileno 72. VM Channels Listener::DEBUG::2015-05-18 14:35:40,572::vmChannels::128::vds::(_handle_unconnected) Trying to connect fileno 49. VM Channels Listener::DEBUG::2015-05-18 14:35:40,573::vmChannels::128::vds::(_handle_unconnected) Trying to connect fileno 50. VM Channels Listener::DEBUG::2015-05-18 14:35:40,573::vmChannels::128::vds::(_handle_unconnected) Trying to connect fileno 54. VM Channels Listener::DEBUG::2015-05-18 14:35:40,573::vmChannels::128::vds::(_handle_unconnected) Trying to connect fileno 62. Thread-29::DEBUG::2015-05-18 14:35:41,311::task::595::TaskManager.Task::(_updateState) Task=`23f5dbfe-bfbb-47ef-b456-827361104976`::moving from state init -> state preparing Thread-29::INFO::2015-05-18 14:35:41,312::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='abc51e26-7175-4b38-b3a8-95c6928fbc2b', spUUID='b384b3da-02a6-44f3-a3f6-56751ce8c26d', imgUUID='09e9fba1-19e4-4b51-855f-c7d80c437690', volUUID='cc0219bc-f9ae-487f-bca2-a4aa79bea718', options=None) Thread-28::DEBUG::2015-05-18 14:35:41,315::task::595::TaskManager.Task::(_updateState) Task=`e9fac93e-e64a-487a-bea7-754e164b534f`::moving from state init -> state preparing Thread-28::INFO::2015-05-18 14:35:41,315::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='abc51e26-7175-4b38-b3a8-95c6928fbc2b', spUUID='b384b3da-02a6-44f3-a3f6-56751ce8c26d', imgUUID='12f8ef8a-8bb8-4458-b1a0-eaf9137bfec6', volUUID='29aa0417-953e-4df7-aee1-46ac96966a62', options=None) Thread-29::INFO::2015-05-18 14:35:41,317::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '38558031872', 'apparentsize': '64424509440'} Thread-29::DEBUG::2015-05-18 14:35:41,317::task::1185::TaskManager.Task::(prepare) Task=`23f5dbfe-bfbb-47ef-b456-827361104976`::finished: {'truesize': '38558031872', 'apparentsize': '64424509440'} Thread-29::DEBUG::2015-05-18 14:35:41,318::task::595::TaskManager.Task::(_updateState) Task=`23f5dbfe-bfbb-47ef-b456-827361104976`::moving from state preparing -> state finished Thread-29::DEBUG::2015-05-18 14:35:41,318::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-29::DEBUG::2015-05-18 14:35:41,319::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-29::DEBUG::2015-05-18 14:35:41,320::task::990::TaskManager.Task::(_decref) Task=`23f5dbfe-bfbb-47ef-b456-827361104976`::ref 0 aborting False Thread-28::INFO::2015-05-18 14:35:41,321::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '56300916736', 'apparentsize': '85899345920'} Thread-28::DEBUG::2015-05-18 14:35:41,321::task::1185::TaskManager.Task::(prepare) Task=`e9fac93e-e64a-487a-bea7-754e164b534f`::finished: {'truesize': '56300916736', 'apparentsize': '85899345920'} Thread-28::DEBUG::2015-05-18 14:35:41,321::task::595::TaskManager.Task::(_updateState) Task=`e9fac93e-e64a-487a-bea7-754e164b534f`::moving from state preparing -> state finished Thread-28::DEBUG::2015-05-18 14:35:41,321::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-28::DEBUG::2015-05-18 14:35:41,321::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-28::DEBUG::2015-05-18 14:35:41,322::task::990::TaskManager.Task::(_decref) Task=`e9fac93e-e64a-487a-bea7-754e164b534f`::ref 0 aborting False Thread-32::DEBUG::2015-05-18 14:35:41,375::task::595::TaskManager.Task::(_updateState) Task=`51bc3b9a-a892-404d-9b4a-2bf55b5a0d15`::moving from state init -> state preparing Thread-32::INFO::2015-05-18 14:35:41,375::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='abc51e26-7175-4b38-b3a8-95c6928fbc2b', spUUID='b384b3da-02a6-44f3-a3f6-56751ce8c26d', imgUUID='0963f2b7-d352-4d92-91bf-4bac9ec6b660', volUUID='6c7c2109-353a-4324-8cb0-8b719876b2dc', options=None) Thread-32::INFO::2015-05-18 14:35:41,378::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '5368709120', 'apparentsize': '5368709120'} Thread-32::DEBUG::2015-05-18 14:35:41,378::task::1185::TaskManager.Task::(prepare) Task=`51bc3b9a-a892-404d-9b4a-2bf55b5a0d15`::finished: {'truesize': '5368709120', 'apparentsize': '5368709120'} Thread-32::DEBUG::2015-05-18 14:35:41,378::task::595::TaskManager.Task::(_updateState) Task=`51bc3b9a-a892-404d-9b4a-2bf55b5a0d15`::moving from state preparing -> state finished Thread-32::DEBUG::2015-05-18 14:35:41,378::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-32::DEBUG::2015-05-18 14:35:41,379::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-32::DEBUG::2015-05-18 14:35:41,379::task::990::TaskManager.Task::(_decref) Task=`51bc3b9a-a892-404d-9b4a-2bf55b5a0d15`::ref 0 aborting False Thread-31::DEBUG::2015-05-18 14:35:41,386::task::595::TaskManager.Task::(_updateState) Task=`66eaac56-77c7-4329-87a6-57a6d9763b6f`::moving from state init -> state preparing Thread-31::INFO::2015-05-18 14:35:41,387::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='abc51e26-7175-4b38-b3a8-95c6928fbc2b', spUUID='b384b3da-02a6-44f3-a3f6-56751ce8c26d', imgUUID='c7b196de-b8a4-46c9-be72-193d765e3a1b', volUUID='286fb5c6-095c-4872-936b-343dbe4b8106', options=None) Thread-31::INFO::2015-05-18 14:35:41,390::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '3243724800', 'apparentsize': '21474836480'} Thread-31::DEBUG::2015-05-18 14:35:41,390::task::1185::TaskManager.Task::(prepare) Task=`66eaac56-77c7-4329-87a6-57a6d9763b6f`::finished: {'truesize': '3243724800', 'apparentsize': '21474836480'} Thread-31::DEBUG::2015-05-18 14:35:41,390::task::595::TaskManager.Task::(_updateState) Task=`66eaac56-77c7-4329-87a6-57a6d9763b6f`::moving from state preparing -> state finished Thread-31::DEBUG::2015-05-18 14:35:41,390::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-31::DEBUG::2015-05-18 14:35:41,391::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-31::DEBUG::2015-05-18 14:35:41,391::task::990::TaskManager.Task::(_decref) Task=`66eaac56-77c7-4329-87a6-57a6d9763b6f`::ref 0 aborting False VM Channels Listener::DEBUG::2015-05-18 14:35:41,573::vmChannels::128::vds::(_handle_unconnected) Trying to connect fileno 38. VM Channels Listener::DEBUG::2015-05-18 14:35:41,574::vmChannels::128::vds::(_handle_unconnected) Trying to connect fileno 72. VM Channels Listener::DEBUG::2015-05-18 14:35:41,574::vmChannels::128::vds::(_handle_unconnected) Trying to connect fileno 49. VM Channels Listener::DEBUG::2015-05-18 14:35:41,574::vmChannels::128::vds::(_handle_unconnected) Trying to connect fileno 50. VM Channels Listener::DEBUG::2015-05-18 14:35:41,574::vmChannels::128::vds::(_handle_unconnected) Trying to connect fileno 54. VM Channels Listener::DEBUG::2015-05-18 14:35:41,575::vmChannels::128::vds::(_handle_unconnected) Trying to connect fileno 62. VM Channels Listener::DEBUG::2015-05-18 14:35:42,576::vmChannels::128::vds::(_handle_unconnected) Trying to connect fileno 38. VM Channels Listener::DEBUG::2015-05-18 14:35:42,576::vmChannels::128::vds::(_handle_unconnected) Trying to connect fileno 72. VM Channels Listener::DEBUG::2015-05-18 14:35:42,576::vmChannels::128::vds::(_handle_unconnected) Trying to connect fileno 49. VM Channels Listener::DEBUG::2015-05-18 14:35:42,576::vmChannels::128::vds::(_handle_unconnected) Trying to connect fileno 50. VM Channels Listener::DEBUG::2015-05-18 14:35:42,577::vmChannels::128::vds::(_handle_unconnected) Trying to connect fileno 54. VM Channels Listener::DEBUG::2015-05-18 14:35:42,577::vmChannels::128::vds::(_handle_unconnected) Trying to connect fileno 62. Thread-35::DEBUG::2015-05-18 14:35:43,570::fileSD::225::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/ovirt.hq.example.net:_var_lib_exports_iso-20140618114713/6d882c77-cdbc-48ef-ae21-1a6d45e7f8a1/dom_md/metadata bs=4096 count=1' (cwd None) VM Channels Listener::DEBUG::2015-05-18 14:35:43,579::vmChannels::128::vds::(_handle_unconnected) Trying to connect fileno 38. VM Channels Listener::DEBUG::2015-05-18 14:35:43,580::vmChannels::128::vds::(_handle_unconnected) Trying to connect fileno 72. VM Channels Listener::DEBUG::2015-05-18 14:35:43,581::vmChannels::128::vds::(_handle_unconnected) Trying to connect fileno 49. VM Channels Listener::DEBUG::2015-05-18 14:35:43,583::vmChannels::128::vds::(_handle_unconnected) Trying to connect fileno 50. VM Channels Listener::DEBUG::2015-05-18 14:35:43,584::vmChannels::128::vds::(_handle_unconnected) Trying to connect fileno 54. VM Channels Listener::DEBUG::2015-05-18 14:35:43,585::vmChannels::128::vds::(_handle_unconnected) Trying to connect fileno 62. Thread-35::DEBUG::2015-05-18 14:35:43,587::fileSD::225::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n560 bytes (560 B) copied, 0.000340492 s, 1.6 MB/s\n'; <rc> = 0 Thread-30::DEBUG::2015-05-18 14:35:43,695::task::595::TaskManager.Task::(_updateState) Task=`df8a42f5-b6d4-4059-8586-ad3d2f60f040`::moving from state init -> state preparing Thread-30::INFO::2015-05-18 14:35:43,696::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='abc51e26-7175-4b38-b3a8-95c6928fbc2b', spUUID='b384b3da-02a6-44f3-a3f6-56751ce8c26d', imgUUID='b68d3a83-d422-4882-a3bf-14809d7ef3a1', volUUID='0a17d461-4fd6-483c-91a9-86796d4aa6bf', options=None) Thread-30::INFO::2015-05-18 14:35:43,701::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '20731297792', 'apparentsize': '21474836480'} Thread-30::DEBUG::2015-05-18 14:35:43,701::task::1185::TaskManager.Task::(prepare) Task=`df8a42f5-b6d4-4059-8586-ad3d2f60f040`::finished: {'truesize': '20731297792', 'apparentsize': '21474836480'} Thread-30::DEBUG::2015-05-18 14:35:43,701::task::595::TaskManager.Task::(_updateState) Task=`df8a42f5-b6d4-4059-8586-ad3d2f60f040`::moving from state preparing -> state finished Thread-30::DEBUG::2015-05-18 14:35:43,701::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-30::DEBUG::2015-05-18 14:35:43,701::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-30::DEBUG::2015-05-18 14:35:43,702::task::990::TaskManager.Task::(_decref) Task=`df8a42f5-b6d4-4059-8586-ad3d2f60f040`::ref 0 aborting False Thread-30::DEBUG::2015-05-18 14:35:43,702::task::595::TaskManager.Task::(_updateState) Task=`7f25c7ef-49c2-4dbf-b785-902efecf0cc3`::moving from state init -> state preparing Thread-30::INFO::2015-05-18 14:35:43,702::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='abc51e26-7175-4b38-b3a8-95c6928fbc2b', spUUID='b384b3da-02a6-44f3-a3f6-56751ce8c26d', imgUUID='174aa201-cfea-4ad4-8b54-f04205b0830c', volUUID='9a39b0ff-e3bc-42ae-bedb-0c809e60665d', options=None) Thread-30::INFO::2015-05-18 14:35:43,705::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '18952265728', 'apparentsize': '21474836480'} Thread-30::DEBUG::2015-05-18 14:35:43,705::task::1185::TaskManager.Task::(prepare) Task=`7f25c7ef-49c2-4dbf-b785-902efecf0cc3`::finished: {'truesize': '18952265728', 'apparentsize': '21474836480'} Thread-30::DEBUG::2015-05-18 14:35:43,705::task::595::TaskManager.Task::(_updateState) Task=`7f25c7ef-49c2-4dbf-b785-902efecf0cc3`::moving from state preparing -> state finished Thread-30::DEBUG::2015-05-18 14:35:43,706::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-30::DEBUG::2015-05-18 14:35:43,706::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-30::DEBUG::2015-05-18 14:35:43,706::task::990::TaskManager.Task::(_decref) Task=`7f25c7ef-49c2-4dbf-b785-902efecf0cc3`::ref 0 aborting False Thread-30::DEBUG::2015-05-18 14:35:43,706::task::595::TaskManager.Task::(_updateState) Task=`87a5d5d2-ad55-4dd4-9a53-584831e91fe1`::moving from state init -> state preparing Thread-30::INFO::2015-05-18 14:35:43,706::logUtils::44::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID='abc51e26-7175-4b38-b3a8-95c6928fbc2b', spUUID='b384b3da-02a6-44f3-a3f6-56751ce8c26d', imgUUID='423535cb-3a9c-41b7-a1a0-19da94b72e21', volUUID='747dfb7c-f2e6-4cdc-a76c-2c37c243ab4d', options=None) Thread-30::INFO::2015-05-18 14:35:43,709::logUtils::47::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '25580142592', 'apparentsize': '26843545600'} Thread-30::DEBUG::2015-05-18 14:35:43,709::task::1185::TaskManager.Task::(prepare) Task=`87a5d5d2-ad55-4dd4-9a53-584831e91fe1`::finished: {'truesize': '25580142592', 'apparentsize': '26843545600'} Thread-30::DEBUG::2015-05-18 14:35:43,709::task::595::TaskManager.Task::(_updateState) Task=`87a5d5d2-ad55-4dd4-9a53-584831e91fe1`::moving from state preparing -> state finished Thread-30::DEBUG::2015-05-18 14:35:43,710::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-30::DEBUG::2015-05-18 14:35:43,710::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-30::DEBUG::2015-05-18 14:35:43,710::task::990::TaskManager.Task::(_decref) Task=`87a5d5d2-ad55-4dd4-9a53-584831e91fe1`::ref 0 aborting False (END)

engine.log: ================ 2015-05-18 14:35:48,069 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSCommand] (DefaultQuartzScheduler_Worker-46) HostName = ovirt-node02.stuttgart.example.net 2015-05-18 14:35:48,070 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSCommand] (DefaultQuartzScheduler_Worker-46) Command HSMGetAllTasksStatusesVDSCommand(HostName = ovirt-node02.stuttgart.example.net, HostId = 6948da12-0b8a-4b6d-a9af-162e6c25dad3) execution failed. Exception: IRSNonOperationalException: IRSGenericException: IRSErrorException: IRSNonOperationalException: Not SPM 2015-05-18 14:35:48,172 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.IrsProxyData] (DefaultQuartzScheduler_Worker-46) hostFromVds::selectedVds - ovirt-node01.stuttgart.example.net, spmStatus Free, storage pool HP_Proliant_DL180G6 2015-05-18 14:35:48,176 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.IrsProxyData] (DefaultQuartzScheduler_Worker-46) starting spm on vds ovirt-node01.stuttgart.example.net, storage pool HP_Proliant_DL180G6, prevId -1, LVER -1 2015-05-18 14:35:48,209 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-46) START, SpmStartVDSCommand(HostName = ovirt-node01.stuttgart.example.net, HostId = 2e8cec66-23d7-4a5c-b6f3-9758d1d87f5c, storagePoolId = b384b3da-02a6-44f3-a3f6-56751ce8c26d, prevId=-1, prevLVER=-1, storagePoolFormatType=V3, recoveryMode=Manual, SCSIFencing=false), log id: e0b2b6e 2015-05-18 14:35:48,220 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-46) spmStart polling started: taskId = 5a51fe50-7803-4518-a4d8-f2a369c2490a 2015-05-18 14:35:49,227 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetTaskStatusVDSCommand] (DefaultQuartzScheduler_Worker-46) Failed in HSMGetTaskStatusVDS method 2015-05-18 14:35:49,228 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-46) spmStart polling ended: taskId = 5a51fe50-7803-4518-a4d8-f2a369c2490a task status = finished 2015-05-18 14:35:49,229 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-46) Start SPM Task failed - result: cleanSuccess, message: VDSGenericException: VDSErrorException: Failed to HSMGetTaskStatusVDS, error = Storage domain does not exist, code = 358 2015-05-18 14:35:49,281 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-46) spmStart polling ended, spm status: Free 2015-05-18 14:35:49,319 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (DefaultQuartzScheduler_Worker-46) START, HSMClearTaskVDSCommand(HostName = ovirt-node01.stuttgart.example.net, HostId = 2e8cec66-23d7-4a5c-b6f3-9758d1d87f5c, taskId=5a51fe50-7803-4518-a4d8-f2a369c2490a), log id: 621a07b5 2015-05-18 14:35:49,327 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (DefaultQuartzScheduler_Worker-46) FINISH, HSMClearTaskVDSCommand, log id: 621a07b5 2015-05-18 14:35:49,328 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-46) FINISH, SpmStartVDSCommand, return: org.ovirt.engine.core.common.businessentities.SpmStatusResult@3addfc90, log id: e0b2b6e 2015-05-18 14:35:49,343 INFO [org.ovirt.engine.core.bll.storage.SetStoragePoolStatusCommand] (DefaultQuartzScheduler_Worker-46) [43f07021] Running command: SetStoragePoolStatusCommand internal: true. Entities affected : ID: b384b3da-02a6-44f3-a3f6-56751ce8c26d Type: StoragePool 2015-05-18 14:35:49,395 ERROR [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (DefaultQuartzScheduler_Worker-46) [43f07021] IrsBroker::Failed::GetStoragePoolInfoVDS due to: IrsSpmStartFailedException: IRSGenericException: IRSErrorException: SpmStart failed 2015-05-18 14:35:49,470 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.IrsProxyData] (DefaultQuartzScheduler_Worker-46) [43f07021] Irs placed on server 2e8cec66-23d7-4a5c-b6f3-9758d1d87f5c failed. Proceed Failover 2015-05-18 14:35:49,546 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.IrsProxyData] (DefaultQuartzScheduler_Worker-46) [43f07021] hostFromVds::selectedVds - ovirt-node02.stuttgart.example.net, spmStatus Free, storage pool HP_Proliant_DL180G6 2015-05-18 14:35:49,549 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.IrsProxyData] (DefaultQuartzScheduler_Worker-46) [43f07021] starting spm on vds ovirt-node02.stuttgart.example.net, storage pool HP_Proliant_DL180G6, prevId -1, LVER -1 2015-05-18 14:35:49,581 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-46) [43f07021] START, SpmStartVDSCommand(HostName = ovirt-node02.stuttgart.example.net, HostId = 6948da12-0b8a-4b6d-a9af-162e6c25dad3, storagePoolId = b384b3da-02a6-44f3-a3f6-56751ce8c26d, prevId=-1, prevLVER=-1, storagePoolFormatType=V3, recoveryMode=Manual, SCSIFencing=false), log id: 63b55478 2015-05-18 14:35:49,591 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-46) [43f07021] spmStart polling started: taskId = 85b96d7e-429c-45a5-acc3-2359d1ad4c53 2015-05-18 14:35:50,155 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-43) START, GlusterVolumesListVDSCommand(HostName = ovirt-node01.stuttgart.example.net, HostId = 2e8cec66-23d7-4a5c-b6f3-9758d1d87f5c), log id: 5203a336 2015-05-18 14:35:50,345 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-43) FINISH, GlusterVolumesListVDSCommand, return: {d46619e9-9368-4e82-bf3a-a2377b6e85e4=org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeEntity@a584232}, log id: 5203a336 2015-05-18 14:35:50,513 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-43) START, GlusterVolumesListVDSCommand(HostName = ovirt-node04.stuttgart.example.net, HostId = 073c24e1-003f-412a-be56-0c41a435829a), log id: 6316c75 2015-05-18 14:35:50,598 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-43) FINISH, GlusterVolumesListVDSCommand, return: {e952fd41-45bf-42d9-b494-8e0195cb9756=org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeEntity@383d74c4}, log id: 6316c75 2015-05-18 14:35:50,599 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetTaskStatusVDSCommand] (DefaultQuartzScheduler_Worker-46) [43f07021] Failed in HSMGetTaskStatusVDS method 2015-05-18 14:35:50,600 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-46) [43f07021] spmStart polling ended: taskId = 85b96d7e-429c-45a5-acc3-2359d1ad4c53 task status = finished 2015-05-18 14:35:50,602 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-46) [43f07021] Start SPM Task failed - result: cleanSuccess, message: VDSGenericException: VDSErrorException: Failed to HSMGetTaskStatusVDS, error = Storage domain does not exist, code = 358 2015-05-18 14:35:50,617 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-43) START, GlusterVolumesListVDSCommand(HostName = ovirt-node07-stgt.stuttgart.example.net, HostId = 32dfc1f1-c474-4410-94c0-38776c121289), log id: 2d300f8a 2015-05-18 14:35:50,653 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-46) [43f07021] spmStart polling ended, spm status: Free 2015-05-18 14:35:50,658 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-43) FINISH, GlusterVolumesListVDSCommand, return: {8786357b-9d11-4c01-a34b-aee949c116e9=org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeEntity@bf0d67a0}, log id: 2d300f8a 2015-05-18 14:35:50,685 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (DefaultQuartzScheduler_Worker-46) [43f07021] START, HSMClearTaskVDSCommand(HostName = ovirt-node02.stuttgart.example.net, HostId = 6948da12-0b8a-4b6d-a9af-162e6c25dad3, taskId=85b96d7e-429c-45a5-acc3-2359d1ad4c53), log id: 541fc1 2015-05-18 14:35:50,731 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (DefaultQuartzScheduler_Worker-46) [43f07021] FINISH, HSMClearTaskVDSCommand, log id: 541fc1 2015-05-18 14:35:50,732 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-46) [43f07021] FINISH, SpmStartVDSCommand, return: org.ovirt.engine.core.common.businessentities.SpmStatusResult@605bfeda, log id: 63b55478 2015-05-18 14:35:50,736 INFO [org.ovirt.engine.core.bll.storage.SetStoragePoolStatusCommand] (DefaultQuartzScheduler_Worker-46) [37b8cba2] Running command: SetStoragePoolStatusCommand internal: true. Entities affected : ID: b384b3da-02a6-44f3-a3f6-56751ce8c26d Type: StoragePool 2015-05-18 14:35:50,775 ERROR [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (DefaultQuartzScheduler_Worker-46) [37b8cba2] IrsBroker::Failed::GetStoragePoolInfoVDS due to: IrsSpmStartFailedException: IRSGenericException: IRSErrorException: SpmStart failed 2015-05-18 14:35:55,931 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-75) START, GlusterVolumesListVDSCommand(HostName = ovirt-node01.stuttgart.example.net, HostId = 2e8cec66-23d7-4a5c-b6f3-9758d1d87f5c), log id: 758f88b3 2015-05-18 14:35:56,130 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-75) FINISH, GlusterVolumesListVDSCommand, return: {d46619e9-9368-4e82-bf3a-a2377b6e85e4=org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeEntity@ef0011fe}, log id: 758f88b3 2015-05-18 14:35:56,297 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-75) START, GlusterVolumesListVDSCommand(HostName = ovirt-node04.stuttgart.example.net, HostId = 073c24e1-003f-412a-be56-0c41a435829a), log id: 2d1069c1 2015-05-18 14:35:56,381 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-75) FINISH, GlusterVolumesListVDSCommand, return: {e952fd41-45bf-42d9-b494-8e0195cb9756=org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeEntity@971a4c5a}, log id: 2d1069c1 2015-05-18 14:35:56,397 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-75) START, GlusterVolumesListVDSCommand(HostName = ovirt-node07-stgt.stuttgart.example.net, HostId = 32dfc1f1-c474-4410-94c0-38776c121289), log id: 2adb5e6b 2015-05-18 14:35:56,437 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-75) FINISH, GlusterVolumesListVDSCommand, return: {8786357b-9d11-4c01-a34b-aee949c116e9=org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeEntity@319748ff}, log id: 2adb5e6b 2015-05-18 14:36:01,017 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSCommand] (DefaultQuartzScheduler_Worker-3) Command org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSCommand return value

TaskStatusListReturnForXmlRpc [mStatus=StatusForXmlRpc [mCode=654, mMessage=Not SPM]]

2015-05-18 14:36:01,077 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSCommand] (DefaultQuartzScheduler_Worker-3) HostName = ovirt-node02.stuttgart.example.net 2015-05-18 14:36:01,079 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSCommand] (DefaultQuartzScheduler_Worker-3) Command HSMGetAllTasksStatusesVDSCommand(HostName = ovirt-node02.stuttgart.example.net, HostId = 6948da12-0b8a-4b6d-a9af-162e6c25dad3) execution failed. Exception: IRSNonOperationalException: IRSGenericException: IRSErrorException: IRSNonOperationalException: Not SPM 2015-05-18 14:36:01,234 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.IrsProxyData] (DefaultQuartzScheduler_Worker-3) hostFromVds::selectedVds - ovirt-node01.stuttgart.example.net, spmStatus Free, storage pool HP_Proliant_DL180G6 2015-05-18 14:36:01,239 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.IrsProxyData] (DefaultQuartzScheduler_Worker-3) starting spm on vds ovirt-node01.stuttgart.example.net, storage pool HP_Proliant_DL180G6, prevId -1, LVER -1 2015-05-18 14:36:01,271 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-3) START, SpmStartVDSCommand(HostName = ovirt-node01.stuttgart.example.net, HostId = 2e8cec66-23d7-4a5c-b6f3-9758d1d87f5c, storagePoolId = b384b3da-02a6-44f3-a3f6-56751ce8c26d, prevId=-1, prevLVER=-1, storagePoolFormatType=V3, recoveryMode=Manual, SCSIFencing=false), log id: 73b21fc3 2015-05-18 14:36:01,287 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-3) spmStart polling started: taskId = cbf7b7bd-2beb-4479-a1f1-a65bcff6ca81 2015-05-18 14:36:01,714 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-16) START, GlusterVolumesListVDSCommand(HostName = ovirt-node01.stuttgart.example.net, HostId = 2e8cec66-23d7-4a5c-b6f3-9758d1d87f5c), log id: 6973c795 2015-05-18 14:36:01,917 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-16) FINISH, GlusterVolumesListVDSCommand, return: {d46619e9-9368-4e82-bf3a-a2377b6e85e4=org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeEntity@93671002}, log id: 6973c795 2015-05-18 14:36:02,160 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-16) START, GlusterVolumesListVDSCommand(HostName = ovirt-node04.stuttgart.example.net, HostId = 073c24e1-003f-412a-be56-0c41a435829a), log id: 673a67af 2015-05-18 14:36:02,246 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-16) FINISH, GlusterVolumesListVDSCommand, return: {e952fd41-45bf-42d9-b494-8e0195cb9756=org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeEntity@7cc34691}, log id: 673a67af 2015-05-18 14:36:02,260 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-16) START, GlusterVolumesListVDSCommand(HostName = ovirt-node07-stgt.stuttgart.example.net, HostId = 32dfc1f1-c474-4410-94c0-38776c121289), log id: 4839bf55 2015-05-18 14:36:02,295 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetTaskStatusVDSCommand] (DefaultQuartzScheduler_Worker-3) Failed in HSMGetTaskStatusVDS method 2015-05-18 14:36:02,296 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-3) spmStart polling ended: taskId = cbf7b7bd-2beb-4479-a1f1-a65bcff6ca81 task status = finished 2015-05-18 14:36:02,297 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-3) Start SPM Task failed - result: cleanSuccess, message: VDSGenericException: VDSErrorException: Failed to HSMGetTaskStatusVDS, error = Storage domain does not exist, code = 358 2015-05-18 14:36:02,303 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-16) FINISH, GlusterVolumesListVDSCommand, return: {8786357b-9d11-4c01-a34b-aee949c116e9=org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeEntity@d92bb04f}, log id: 4839bf55 2015-05-18 14:36:02,348 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-3) spmStart polling ended, spm status: Free 2015-05-18 14:36:02,380 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (DefaultQuartzScheduler_Worker-3) START, HSMClearTaskVDSCommand(HostName = ovirt-node01.stuttgart.example.net, HostId = 2e8cec66-23d7-4a5c-b6f3-9758d1d87f5c, taskId=cbf7b7bd-2beb-4479-a1f1-a65bcff6ca81), log id: c94020 2015-05-18 14:36:02,428 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (DefaultQuartzScheduler_Worker-3) FINISH, HSMClearTaskVDSCommand, log id: c94020 2015-05-18 14:36:02,429 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-3) FINISH, SpmStartVDSCommand, return: org.ovirt.engine.core.common.businessentities.SpmStatusResult@270252f6, log id: 73b21fc3 2015-05-18 14:36:02,436 INFO [org.ovirt.engine.core.bll.storage.SetStoragePoolStatusCommand] (DefaultQuartzScheduler_Worker-3) [994a87c] Running command: SetStoragePoolStatusCommand internal: true. Entities affected : ID: b384b3da-02a6-44f3-a3f6-56751ce8c26d Type: StoragePool 2015-05-18 14:36:02,506 ERROR [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (DefaultQuartzScheduler_Worker-3) [994a87c] IrsBroker::Failed::GetStoragePoolInfoVDS due to: IrsSpmStartFailedException: IRSGenericException: IRSErrorException: SpmStart failed 2015-05-18 14:36:02,659 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.IrsProxyData] (DefaultQuartzScheduler_Worker-3) [994a87c] Irs placed on server 2e8cec66-23d7-4a5c-b6f3-9758d1d87f5c failed. Proceed Failover 2015-05-18 14:36:02,789 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.IrsProxyData] (DefaultQuartzScheduler_Worker-3) [994a87c] hostFromVds::selectedVds - ovirt-node02.stuttgart.example.net, spmStatus Free, storage pool HP_Proliant_DL180G6 2015-05-18 14:36:02,795 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.IrsProxyData] (DefaultQuartzScheduler_Worker-3) [994a87c] starting spm on vds ovirt-node02.stuttgart.example.net, storage pool HP_Proliant_DL180G6, prevId -1, LVER -1 2015-05-18 14:36:02,864 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-3) [994a87c] START, SpmStartVDSCommand(HostName = ovirt-node02.stuttgart.example.net, HostId = 6948da12-0b8a-4b6d-a9af-162e6c25dad3, storagePoolId = b384b3da-02a6-44f3-a3f6-56751ce8c26d, prevId=-1, prevLVER=-1, storagePoolFormatType=V3, recoveryMode=Manual, SCSIFencing=false), log id: 51eb1e47 2015-05-18 14:36:02,879 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-3) [994a87c] spmStart polling started: taskId = a23e67b5-28e4-4572-970e-2cb1c8c589be 2015-05-18 14:36:03,888 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetTaskStatusVDSCommand] (DefaultQuartzScheduler_Worker-3) [994a87c] Failed in HSMGetTaskStatusVDS method 2015-05-18 14:36:03,890 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-3) [994a87c] spmStart polling ended: taskId = a23e67b5-28e4-4572-970e-2cb1c8c589be task status = finished 2015-05-18 14:36:03,892 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-3) [994a87c] Start SPM Task failed - result: cleanSuccess, message: VDSGenericException: VDSErrorException: Failed to HSMGetTaskStatusVDS, error = Storage domain does not exist, code = 358 2015-05-18 14:36:03,945 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-3) [994a87c] spmStart polling ended, spm status: Free 2015-05-18 14:36:04,003 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (DefaultQuartzScheduler_Worker-3) [994a87c] START, HSMClearTaskVDSCommand(HostName = ovirt-node02.stuttgart.example.net, HostId = 6948da12-0b8a-4b6d-a9af-162e6c25dad3, taskId=a23e67b5-28e4-4572-970e-2cb1c8c589be), log id: 79674a9b 2015-05-18 14:36:04,012 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (DefaultQuartzScheduler_Worker-3) [994a87c] FINISH, HSMClearTaskVDSCommand, log id: 79674a9b 2015-05-18 14:36:04,014 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-3) [994a87c] FINISH, SpmStartVDSCommand, return: org.ovirt.engine.core.common.businessentities.SpmStatusResult@57b706d5, log id: 51eb1e47 2015-05-18 14:36:04,030 INFO [org.ovirt.engine.core.bll.storage.SetStoragePoolStatusCommand] (DefaultQuartzScheduler_Worker-3) [3121b6f0] Running command: SetStoragePoolStatusCommand internal: true. Entities affected : ID: b384b3da-02a6-44f3-a3f6-56751ce8c26d Type: StoragePool 2015-05-18 14:36:04,078 ERROR [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (DefaultQuartzScheduler_Worker-3) [3121b6f0] IrsBroker::Failed::GetStoragePoolInfoVDS due to: IrsSpmStartFailedException: IRSGenericException: IRSErrorException: SpmStart failed 2015-05-18 14:36:04,777 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterTasksListVDSCommand] (DefaultQuartzScheduler_Worker-35) START, GlusterTasksListVDSCommand(HostName = ovirt-node01.stuttgart.example.net, HostId = 2e8cec66-23d7-4a5c-b6f3-9758d1d87f5c), log id: 68a5fa4c 2015-05-18 14:36:04,899 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterTasksListVDSCommand] (DefaultQuartzScheduler_Worker-35) FINISH, GlusterTasksListVDSCommand, return: [], log id: 68a5fa4c 2015-05-18 14:36:05,046 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterTasksListVDSCommand] (DefaultQuartzScheduler_Worker-35) START, GlusterTasksListVDSCommand(HostName = ovirt-node03.stuttgart.example.net, HostId = 58c3a03d-d289-45ad-a5e5-f3d37d66cca7), log id: 3dde7be5 2015-05-18 14:36:05,074 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterTasksListVDSCommand] (DefaultQuartzScheduler_Worker-35) FINISH, GlusterTasksListVDSCommand, return: [], log id: 3dde7be5 2015-05-18 14:36:05,078 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterTasksListVDSCommand] (DefaultQuartzScheduler_Worker-35) START, GlusterTasksListVDSCommand(HostName = ovirt-node06-stgt.stuttgart.example.net, HostId = e15b95d4-96a5-40f7-97d0-9ec2fccd39f0), log id: 68d3acc2 2015-05-18 14:36:05,157 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterTasksListVDSCommand] (DefaultQuartzScheduler_Worker-35) FINISH, GlusterTasksListVDSCommand, return: [], log id: 68d3acc2 2015-05-18 14:36:07,647 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-38) START, GlusterVolumesListVDSCommand(HostName = ovirt-node01.stuttgart.example.net, HostId = 2e8cec66-23d7-4a5c-b6f3-9758d1d87f5c), log id: 7192b532 2015-05-18 14:36:07,830 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-38) FINISH, GlusterVolumesListVDSCommand, return: {d46619e9-9368-4e82-bf3a-a2377b6e85e4=org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeEntity@d1d19f6}, log id: 7192b532 2015-05-18 14:36:08,002 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-38) START, GlusterVolumesListVDSCommand(HostName = ovirt-node04.stuttgart.example.net, HostId = 073c24e1-003f-412a-be56-0c41a435829a), log id: 40023b20 2015-05-18 14:36:08,090 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-38) FINISH, GlusterVolumesListVDSCommand, return: {e952fd41-45bf-42d9-b494-8e0195cb9756=org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeEntity@81f414aa}, log id: 40023b20 2015-05-18 14:36:08,106 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-38) START, GlusterVolumesListVDSCommand(HostName = ovirt-node07-stgt.stuttgart.example.net, HostId = 32dfc1f1-c474-4410-94c0-38776c121289), log id: 3901fba 2015-05-18 14:36:08,144 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-38) FINISH, GlusterVolumesListVDSCommand, return: {8786357b-9d11-4c01-a34b-aee949c116e9=org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeEntity@8043d5d4}, log id: 3901fba 2015-05-18 14:36:13,378 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-74) START, GlusterVolumesListVDSCommand(HostName = ovirt-node01.stuttgart.example.net, HostId = 2e8cec66-23d7-4a5c-b6f3-9758d1d87f5c), log id: 1c08397d 2015-05-18 14:36:13,610 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-74) FINISH, GlusterVolumesListVDSCommand, return: {d46619e9-9368-4e82-bf3a-a2377b6e85e4=org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeEntity@3f192277}, log id: 1c08397d 2015-05-18 14:36:13,892 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-74) START, GlusterVolumesListVDSCommand(HostName = ovirt-node04.stuttgart.example.net, HostId = 073c24e1-003f-412a-be56-0c41a435829a), log id: e80f14a 2015-05-18 14:36:13,975 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-74) FINISH, GlusterVolumesListVDSCommand, return: {e952fd41-45bf-42d9-b494-8e0195cb9756=org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeEntity@b4518810}, log id: e80f14a 2015-05-18 14:36:13,995 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-74) START, GlusterVolumesListVDSCommand(HostName = ovirt-node07-stgt.stuttgart.example.net, HostId = 32dfc1f1-c474-4410-94c0-38776c121289), log id: 3f6f3ea0 2015-05-18 14:36:14,392 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSCommand] (DefaultQuartzScheduler_Worker-86) Command org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSCommand return value

TaskStatusListReturnForXmlRpc [mStatus=StatusForXmlRpc [mCode=654, mMessage=Not SPM]]

2015-05-18 14:36:14,425 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSCommand] (DefaultQuartzScheduler_Worker-86) HostName = ovirt-node02.stuttgart.example.net 2015-05-18 14:36:14,427 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSCommand] (DefaultQuartzScheduler_Worker-86) Command HSMGetAllTasksStatusesVDSCommand(HostName = ovirt-node02.stuttgart.example.net, HostId = 6948da12-0b8a-4b6d-a9af-162e6c25dad3) execution failed. Exception: IRSNonOperationalException: IRSGenericException: IRSErrorException: IRSNonOperationalException: Not SPM 2015-05-18 14:36:14,429 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-74) FINISH, GlusterVolumesListVDSCommand, return: {8786357b-9d11-4c01-a34b-aee949c116e9=org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeEntity@7da28ce6}, log id: 3f6f3ea0 2015-05-18 14:36:14,619 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.IrsProxyData] (DefaultQuartzScheduler_Worker-86) hostFromVds::selectedVds - ovirt-node01.stuttgart.example.net, spmStatus Free, storage pool HP_Proliant_DL180G6 2015-05-18 14:36:14,622 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.IrsProxyData] (DefaultQuartzScheduler_Worker-86) starting spm on vds ovirt-node01.stuttgart.example.net, storage pool HP_Proliant_DL180G6, prevId -1, LVER -1 2015-05-18 14:36:14,655 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-86) START, SpmStartVDSCommand(HostName = ovirt-node01.stuttgart.example.net, HostId = 2e8cec66-23d7-4a5c-b6f3-9758d1d87f5c, storagePoolId = b384b3da-02a6-44f3-a3f6-56751ce8c26d, prevId=-1, prevLVER=-1, storagePoolFormatType=V3, recoveryMode=Manual, SCSIFencing=false), log id: 26ddbe34 2015-05-18 14:36:14,669 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-86) spmStart polling started: taskId = f23ede06-d1ff-4398-aa8d-fec60a9b169a 2015-05-18 14:36:15,678 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetTaskStatusVDSCommand] (DefaultQuartzScheduler_Worker-86) Failed in HSMGetTaskStatusVDS method 2015-05-18 14:36:15,680 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-86) spmStart polling ended: taskId = f23ede06-d1ff-4398-aa8d-fec60a9b169a task status = finished 2015-05-18 14:36:15,682 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-86) Start SPM Task failed - result: cleanSuccess, message: VDSGenericException: VDSErrorException: Failed to HSMGetTaskStatusVDS, error = Storage domain does not exist, code = 358 2015-05-18 14:36:15,737 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-86) spmStart polling ended, spm status: Free 2015-05-18 14:36:15,796 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (DefaultQuartzScheduler_Worker-86) START, HSMClearTaskVDSCommand(HostName = ovirt-node01.stuttgart.example.net, HostId = 2e8cec66-23d7-4a5c-b6f3-9758d1d87f5c, taskId=f23ede06-d1ff-4398-aa8d-fec60a9b169a), log id: 1120709c 2015-05-18 14:36:15,810 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (DefaultQuartzScheduler_Worker-86) FINISH, HSMClearTaskVDSCommand, log id: 1120709c 2015-05-18 14:36:15,811 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-86) FINISH, SpmStartVDSCommand, return: org.ovirt.engine.core.common.businessentities.SpmStatusResult@52c0b61e, log id: 26ddbe34 2015-05-18 14:36:15,818 INFO [org.ovirt.engine.core.bll.storage.SetStoragePoolStatusCommand] (DefaultQuartzScheduler_Worker-86) [169f4d5c] Running command: SetStoragePoolStatusCommand internal: true. Entities affected : ID: b384b3da-02a6-44f3-a3f6-56751ce8c26d Type: StoragePool 2015-05-18 14:36:15,858 ERROR [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (DefaultQuartzScheduler_Worker-86) [169f4d5c] IrsBroker::Failed::GetStoragePoolInfoVDS due to: IrsSpmStartFailedException: IRSGenericException: IRSErrorException: SpmStart failed 2015-05-18 14:36:15,934 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.IrsProxyData] (DefaultQuartzScheduler_Worker-86) [169f4d5c] Irs placed on server 2e8cec66-23d7-4a5c-b6f3-9758d1d87f5c failed. Proceed Failover 2015-05-18 14:36:16,019 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.IrsProxyData] (DefaultQuartzScheduler_Worker-86) [169f4d5c] hostFromVds::selectedVds - ovirt-node02.stuttgart.example.net, spmStatus Free, storage pool HP_Proliant_DL180G6 2015-05-18 14:36:16,023 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.IrsProxyData] (DefaultQuartzScheduler_Worker-86) [169f4d5c] starting spm on vds ovirt-node02.stuttgart.example.net, storage pool HP_Proliant_DL180G6, prevId -1, LVER -1 2015-05-18 14:36:16,055 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-86) [169f4d5c] START, SpmStartVDSCommand(HostName = ovirt-node02.stuttgart.example.net, HostId = 6948da12-0b8a-4b6d-a9af-162e6c25dad3, storagePoolId = b384b3da-02a6-44f3-a3f6-56751ce8c26d, prevId=-1, prevLVER=-1, storagePoolFormatType=V3, recoveryMode=Manual, SCSIFencing=false), log id: 3a33371d 2015-05-18 14:36:16,065 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-86) [169f4d5c] spmStart polling started: taskId = c730e46a-57b3-4996-9916-a428c9a9ac3b 2015-05-18 14:36:17,076 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetTaskStatusVDSCommand] (DefaultQuartzScheduler_Worker-86) [169f4d5c] Failed in HSMGetTaskStatusVDS method 2015-05-18 14:36:17,078 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-86) [169f4d5c] spmStart polling ended: taskId = c730e46a-57b3-4996-9916-a428c9a9ac3b task status = finished 2015-05-18 14:36:17,080 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-86) [169f4d5c] Start SPM Task failed - result: cleanSuccess, message: VDSGenericException: VDSErrorException: Failed to HSMGetTaskStatusVDS, error = Storage domain does not exist, code = 358 2015-05-18 14:36:17,169 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-86) [169f4d5c] spmStart polling ended, spm status: Free 2015-05-18 14:36:17,236 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (DefaultQuartzScheduler_Worker-86) [169f4d5c] START, HSMClearTaskVDSCommand(HostName = ovirt-node02.stuttgart.example.net, HostId = 6948da12-0b8a-4b6d-a9af-162e6c25dad3, taskId=c730e46a-57b3-4996-9916-a428c9a9ac3b), log id: 77422494 2015-05-18 14:36:17,245 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (DefaultQuartzScheduler_Worker-86) [169f4d5c] FINISH, HSMClearTaskVDSCommand, log id: 77422494 2015-05-18 14:36:17,246 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-86) [169f4d5c] FINISH, SpmStartVDSCommand, return: org.ovirt.engine.core.common.businessentities.SpmStatusResult@6db1c38e, log id: 3a33371d 2015-05-18 14:36:17,260 INFO [org.ovirt.engine.core.bll.storage.SetStoragePoolStatusCommand] (DefaultQuartzScheduler_Worker-86) [319dd7e5] Running command: SetStoragePoolStatusCommand internal: true. Entities affected : ID: b384b3da-02a6-44f3-a3f6-56751ce8c26d Type: StoragePool 2015-05-18 14:36:17,366 ERROR [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (DefaultQuartzScheduler_Worker-86) [319dd7e5] IrsBroker::Failed::GetStoragePoolInfoVDS due to: IrsSpmStartFailedException: IRSGenericException: IRSErrorException: SpmStart failed 2015-05-18 14:36:19,702 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-14) START, GlusterVolumesListVDSCommand(HostName = ovirt-node01.stuttgart.example.net, HostId = 2e8cec66-23d7-4a5c-b6f3-9758d1d87f5c), log id: 39b26495 2015-05-18 14:36:19,941 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-14) FINISH, GlusterVolumesListVDSCommand, return: {d46619e9-9368-4e82-bf3a-a2377b6e85e4=org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeEntity@9c2a93b7}, log id: 39b26495 2015-05-18 14:36:20,111 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-14) START, GlusterVolumesListVDSCommand(HostName = ovirt-node04.stuttgart.example.net, HostId = 073c24e1-003f-412a-be56-0c41a435829a), log id: 67d54c4a 2015-05-18 14:36:20,194 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-14) FINISH, GlusterVolumesListVDSCommand, return: {e952fd41-45bf-42d9-b494-8e0195cb9756=org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeEntity@8a6b9152}, log id: 67d54c4a 2015-05-18 14:36:20,217 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-14) START, GlusterVolumesListVDSCommand(HostName = ovirt-node07-stgt.stuttgart.example.net, HostId = 32dfc1f1-c474-4410-94c0-38776c121289), log id: 2e5e3f07 2015-05-18 14:36:20,255 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-14) FINISH, GlusterVolumesListVDSCommand, return: {8786357b-9d11-4c01-a34b-aee949c116e9=org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeEntity@409317cd}, log id: 2e5e3f07 2015-05-18 14:36:25,485 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-8) [1f6e11f1] START, GlusterVolumesListVDSCommand(HostName = ovirt-node01.stuttgart.example.net, HostId = 2e8cec66-23d7-4a5c-b6f3-9758d1d87f5c), log id: 16543222 2015-05-18 14:36:25,670 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-8) [1f6e11f1] FINISH, GlusterVolumesListVDSCommand, return: {d46619e9-9368-4e82-bf3a-a2377b6e85e4=org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeEntity@fd879447}, log id: 16543222 2015-05-18 14:36:25,836 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-8) [1f6e11f1] START, GlusterVolumesListVDSCommand(HostName = ovirt-node04.stuttgart.example.net, HostId = 073c24e1-003f-412a-be56-0c41a435829a), log id: 7ac850fa 2015-05-18 14:36:25,919 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-8) [1f6e11f1] FINISH, GlusterVolumesListVDSCommand, return: {e952fd41-45bf-42d9-b494-8e0195cb9756=org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeEntity@f3e7b162}, log id: 7ac850fa 2015-05-18 14:36:25,933 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-8) [1f6e11f1] START, GlusterVolumesListVDSCommand(HostName = ovirt-node07-stgt.stuttgart.example.net, HostId = 32dfc1f1-c474-4410-94c0-38776c121289), log id: 1857ade7 2015-05-18 14:36:25,970 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-8) [1f6e11f1] FINISH, GlusterVolumesListVDSCommand, return: {8786357b-9d11-4c01-a34b-aee949c116e9=org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeEntity@11bc654c}, log id: 1857ade7 2015-05-18 14:36:27,612 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSCommand] (DefaultQuartzScheduler_Worker-24) [3f3a55ac] Command org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSCommand return value

TaskStatusListReturnForXmlRpc [mStatus=StatusForXmlRpc [mCode=654, mMessage=Not SPM]]

2015-05-18 14:36:27,684 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSCommand] (DefaultQuartzScheduler_Worker-24) [3f3a55ac] HostName = ovirt-node02.stuttgart.example.net 2015-05-18 14:36:27,686 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSCommand] (DefaultQuartzScheduler_Worker-24) [3f3a55ac] Command HSMGetAllTasksStatusesVDSCommand(HostName = ovirt-node02.stuttgart.example.net, HostId = 6948da12-0b8a-4b6d-a9af-162e6c25dad3) execution failed. Exception: IRSNonOperationalException: IRSGenericException: IRSErrorException: IRSNonOperationalException: Not SPM 2015-05-18 14:36:27,826 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.IrsProxyData] (DefaultQuartzScheduler_Worker-24) [3f3a55ac] hostFromVds::selectedVds - ovirt-node02.stuttgart.example.net, spmStatus Free, storage pool HP_Proliant_DL180G6 2015-05-18 14:36:27,832 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.IrsProxyData] (DefaultQuartzScheduler_Worker-24) [3f3a55ac] starting spm on vds ovirt-node02.stuttgart.example.net, storage pool HP_Proliant_DL180G6, prevId -1, LVER -1 2015-05-18 14:36:27,867 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-24) [3f3a55ac] START, SpmStartVDSCommand(HostName = ovirt-node02.stuttgart.example.net, HostId = 6948da12-0b8a-4b6d-a9af-162e6c25dad3, storagePoolId = b384b3da-02a6-44f3-a3f6-56751ce8c26d, prevId=-1, prevLVER=-1, storagePoolFormatType=V3, recoveryMode=Manual, SCSIFencing=false), log id: 40dee17b 2015-05-18 14:36:27,880 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-24) [3f3a55ac] spmStart polling started: taskId = a80f5b5f-6507-44f7-ae03-798fb2bd7d28 2015-05-18 14:36:28,888 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetTaskStatusVDSCommand] (DefaultQuartzScheduler_Worker-24) [3f3a55ac] Failed in HSMGetTaskStatusVDS method 2015-05-18 14:36:28,890 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-24) [3f3a55ac] spmStart polling ended: taskId = a80f5b5f-6507-44f7-ae03-798fb2bd7d28 task status = finished 2015-05-18 14:36:28,893 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-24) [3f3a55ac] Start SPM Task failed - result: cleanSuccess, message: VDSGenericException: VDSErrorException: Failed to HSMGetTaskStatusVDS, error = Storage domain does not exist, code = 358 2015-05-18 14:36:28,945 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-24) [3f3a55ac] spmStart polling ended, spm status: Free 2015-05-18 14:36:29,003 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (DefaultQuartzScheduler_Worker-24) [3f3a55ac] START, HSMClearTaskVDSCommand(HostName = ovirt-node02.stuttgart.example.net, HostId = 6948da12-0b8a-4b6d-a9af-162e6c25dad3, taskId=a80f5b5f-6507-44f7-ae03-798fb2bd7d28), log id: 65247d54 2015-05-18 14:36:29,012 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (DefaultQuartzScheduler_Worker-24) [3f3a55ac] FINISH, HSMClearTaskVDSCommand, log id: 65247d54 2015-05-18 14:36:29,015 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-24) [3f3a55ac] FINISH, SpmStartVDSCommand, return: org.ovirt.engine.core.common.businessentities.SpmStatusResult@20a417c8, log id: 40dee17b 2015-05-18 14:36:29,022 INFO [org.ovirt.engine.core.bll.storage.SetStoragePoolStatusCommand] (DefaultQuartzScheduler_Worker-24) [75155c35] Running command: SetStoragePoolStatusCommand internal: true. Entities affected : ID: b384b3da-02a6-44f3-a3f6-56751ce8c26d Type: StoragePool 2015-05-18 14:36:29,108 ERROR [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (DefaultQuartzScheduler_Worker-24) [75155c35] IrsBroker::Failed::GetStoragePoolInfoVDS due to: IrsSpmStartFailedException: IRSGenericException: IRSErrorException: SpmStart failed 2015-05-18 14:36:29,241 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.IrsProxyData] (DefaultQuartzScheduler_Worker-24) [75155c35] Irs placed on server 6948da12-0b8a-4b6d-a9af-162e6c25dad3 failed. Proceed Failover 2015-05-18 14:36:29,347 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.IrsProxyData] (DefaultQuartzScheduler_Worker-24) [75155c35] hostFromVds::selectedVds - ovirt-node01.stuttgart.example.net, spmStatus Free, storage pool HP_Proliant_DL180G6 2015-05-18 14:36:29,355 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.IrsProxyData] (DefaultQuartzScheduler_Worker-24) [75155c35] starting spm on vds ovirt-node01.stuttgart.example.net, storage pool HP_Proliant_DL180G6, prevId -1, LVER -1 2015-05-18 14:36:29,388 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-24) [75155c35] START, SpmStartVDSCommand(HostName = ovirt-node01.stuttgart.example.net, HostId = 2e8cec66-23d7-4a5c-b6f3-9758d1d87f5c, storagePoolId = b384b3da-02a6-44f3-a3f6-56751ce8c26d, prevId=-1, prevLVER=-1, storagePoolFormatType=V3, recoveryMode=Manual, SCSIFencing=false), log id: 1ddc1476 2015-05-18 14:36:29,401 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-24) [75155c35] spmStart polling started: taskId = e30a8353-fc32-4300-adba-f51a876246b4 2015-05-18 14:36:30,410 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetTaskStatusVDSCommand] (DefaultQuartzScheduler_Worker-24) [75155c35] Failed in HSMGetTaskStatusVDS method 2015-05-18 14:36:30,412 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-24) [75155c35] spmStart polling ended: taskId = e30a8353-fc32-4300-adba-f51a876246b4 task status = finished 2015-05-18 14:36:30,414 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-24) [75155c35] Start SPM Task failed - result: cleanSuccess, message: VDSGenericException: VDSErrorException: Failed to HSMGetTaskStatusVDS, error = Storage domain does not exist, code = 358 2015-05-18 14:36:30,467 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-24) [75155c35] spmStart polling ended, spm status: Free 2015-05-18 14:36:30,528 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (DefaultQuartzScheduler_Worker-24) [75155c35] START, HSMClearTaskVDSCommand(HostName = ovirt-node01.stuttgart.example.net, HostId = 2e8cec66-23d7-4a5c-b6f3-9758d1d87f5c, taskId=e30a8353-fc32-4300-adba-f51a876246b4), log id: 7dd12ea9 2015-05-18 14:36:30,538 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (DefaultQuartzScheduler_Worker-24) [75155c35] FINISH, HSMClearTaskVDSCommand, log id: 7dd12ea9 2015-05-18 14:36:30,540 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-24) [75155c35] FINISH, SpmStartVDSCommand, return: org.ovirt.engine.core.common.businessentities.SpmStatusResult@6d54458d, log id: 1ddc1476 2015-05-18 14:36:30,547 INFO [org.ovirt.engine.core.bll.storage.SetStoragePoolStatusCommand] (DefaultQuartzScheduler_Worker-24) [37a2640e] Running command: SetStoragePoolStatusCommand internal: true. Entities affected : ID: b384b3da-02a6-44f3-a3f6-56751ce8c26d Type: StoragePool 2015-05-18 14:36:30,617 ERROR [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (DefaultQuartzScheduler_Worker-24) [37a2640e] IrsBroker::Failed::GetStoragePoolInfoVDS due to: IrsSpmStartFailedException: IRSGenericException: IRSErrorException: SpmStart failed 2015-05-18 14:36:31,176 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-71) START, GlusterVolumesListVDSCommand(HostName = ovirt-node01.stuttgart.example.net, HostId = 2e8cec66-23d7-4a5c-b6f3-9758d1d87f5c), log id: 7845333d 2015-05-18 14:36:31,413 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-71) FINISH, GlusterVolumesListVDSCommand, return: {d46619e9-9368-4e82-bf3a-a2377b6e85e4=org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeEntity@621cee87}, log id: 7845333d 2015-05-18 14:36:31,667 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-71) START, GlusterVolumesListVDSCommand(HostName = ovirt-node04.stuttgart.example.net, HostId = 073c24e1-003f-412a-be56-0c41a435829a), log id: 54f77549 2015-05-18 14:36:31,751 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-71) FINISH, GlusterVolumesListVDSCommand, return: {e952fd41-45bf-42d9-b494-8e0195cb9756=org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeEntity@c710ae5}, log id: 54f77549 2015-05-18 14:36:31,766 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-71) START, GlusterVolumesListVDSCommand(HostName = ovirt-node07-stgt.stuttgart.example.net, HostId = 32dfc1f1-c474-4410-94c0-38776c121289), log id: 4c70d07 2015-05-18 14:36:31,799 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-71) FINISH, GlusterVolumesListVDSCommand, return: {8786357b-9d11-4c01-a34b-aee949c116e9=org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeEntity@2136a7e7}, log id: 4c70d07 2015-05-18 14:36:37,034 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-1) START, GlusterVolumesListVDSCommand(HostName = ovirt-node01.stuttgart.example.net, HostId = 2e8cec66-23d7-4a5c-b6f3-9758d1d87f5c), log id: 613a7dbb 2015-05-18 14:36:37,261 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-1) FINISH, GlusterVolumesListVDSCommand, return: {d46619e9-9368-4e82-bf3a-a2377b6e85e4=org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeEntity@65925efa}, log id: 613a7dbb 2015-05-18 14:36:37,512 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-1) START, GlusterVolumesListVDSCommand(HostName = ovirt-node04.stuttgart.example.net, HostId = 073c24e1-003f-412a-be56-0c41a435829a), log id: b285af5 2015-05-18 14:36:37,594 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-1) FINISH, GlusterVolumesListVDSCommand, return: {e952fd41-45bf-42d9-b494-8e0195cb9756=org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeEntity@4ed42f1a}, log id: b285af5 2015-05-18 14:36:37,609 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-1) START, GlusterVolumesListVDSCommand(HostName = ovirt-node07-stgt.stuttgart.example.net, HostId = 32dfc1f1-c474-4410-94c0-38776c121289), log id: 40264885 2015-05-18 14:36:37,643 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-1) FINISH, GlusterVolumesListVDSCommand, return: {8786357b-9d11-4c01-a34b-aee949c116e9=org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeEntity@baf0c0d5}, log id: 40264885 2015-05-18 14:36:40,911 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSCommand] (DefaultQuartzScheduler_Worker-9) [59e67616] Command org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSCommand return value

TaskStatusListReturnForXmlRpc [mStatus=StatusForXmlRpc [mCode=654, mMessage=Not SPM]]

2015-05-18 14:36:40,972 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSCommand] (DefaultQuartzScheduler_Worker-9) [59e67616] HostName = ovirt-node01.stuttgart.example.net 2015-05-18 14:36:40,974 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSCommand] (DefaultQuartzScheduler_Worker-9) [59e67616] Command HSMGetAllTasksStatusesVDSCommand(HostName = ovirt-node01.stuttgart.example.net, HostId = 2e8cec66-23d7-4a5c-b6f3-9758d1d87f5c) execution failed. Exception: IRSNonOperationalException: IRSGenericException: IRSErrorException: IRSNonOperationalException: Not SPM 2015-05-18 14:36:41,091 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.IrsProxyData] (DefaultQuartzScheduler_Worker-9) [59e67616] hostFromVds::selectedVds - ovirt-node01.stuttgart.example.net, spmStatus Free, storage pool HP_Proliant_DL180G6 2015-05-18 14:36:41,095 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.IrsProxyData] (DefaultQuartzScheduler_Worker-9) [59e67616] starting spm on vds ovirt-node01.stuttgart.example.net, storage pool HP_Proliant_DL180G6, prevId -1, LVER -1 2015-05-18 14:36:41,128 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-9) [59e67616] START, SpmStartVDSCommand(HostName = ovirt-node01.stuttgart.example.net, HostId = 2e8cec66-23d7-4a5c-b6f3-9758d1d87f5c, storagePoolId = b384b3da-02a6-44f3-a3f6-56751ce8c26d, prevId=-1, prevLVER=-1, storagePoolFormatType=V3, recoveryMode=Manual, SCSIFencing=false), log id: 225ad910 2015-05-18 14:36:41,139 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-9) [59e67616] spmStart polling started: taskId = 64e3d616-9a75-411f-a4d5-f7bd770a4cb8 2015-05-18 14:36:42,148 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetTaskStatusVDSCommand] (DefaultQuartzScheduler_Worker-9) [59e67616] Failed in HSMGetTaskStatusVDS method 2015-05-18 14:36:42,150 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-9) [59e67616] spmStart polling ended: taskId = 64e3d616-9a75-411f-a4d5-f7bd770a4cb8 task status = finished 2015-05-18 14:36:42,152 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-9) [59e67616] Start SPM Task failed - result: cleanSuccess, message: VDSGenericException: VDSErrorException: Failed to HSMGetTaskStatusVDS, error = Storage domain does not exist, code = 358 2015-05-18 14:36:42,204 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-9) [59e67616] spmStart polling ended, spm status: Free 2015-05-18 14:36:42,263 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (DefaultQuartzScheduler_Worker-9) [59e67616] START, HSMClearTaskVDSCommand(HostName = ovirt-node01.stuttgart.example.net, HostId = 2e8cec66-23d7-4a5c-b6f3-9758d1d87f5c, taskId=64e3d616-9a75-411f-a4d5-f7bd770a4cb8), log id: 6918f975 2015-05-18 14:36:42,272 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (DefaultQuartzScheduler_Worker-9) [59e67616] FINISH, HSMClearTaskVDSCommand, log id: 6918f975 2015-05-18 14:36:42,275 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-9) [59e67616] FINISH, SpmStartVDSCommand, return: org.ovirt.engine.core.common.businessentities.SpmStatusResult@29ac1cac, log id: 225ad910 2015-05-18 14:36:42,286 INFO [org.ovirt.engine.core.bll.storage.SetStoragePoolStatusCommand] (DefaultQuartzScheduler_Worker-9) [76c93871] Running command: SetStoragePoolStatusCommand internal: true. Entities affected : ID: b384b3da-02a6-44f3-a3f6-56751ce8c26d Type: StoragePool 2015-05-18 14:36:42,383 WARN [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (DefaultQuartzScheduler_Worker-9) [76c93871] Correlation ID: 76c93871, Call Stack: null, Custom Event ID: -1, Message: Invalid status on Data Center HP_Proliant_DL180G6. Setting status to Non Responsive. 2015-05-18 14:36:42,390 ERROR [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (DefaultQuartzScheduler_Worker-9) [76c93871] IrsBroker::Failed::GetStoragePoolInfoVDS due to: IrsSpmStartFailedException: IRSGenericException: IRSErrorException: SpmStart failed 2015-05-18 14:36:42,521 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.IrsProxyData] (DefaultQuartzScheduler_Worker-9) [76c93871] Irs placed on server 2e8cec66-23d7-4a5c-b6f3-9758d1d87f5c failed. Proceed Failover 2015-05-18 14:36:42,602 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.IrsProxyData] (DefaultQuartzScheduler_Worker-9) [76c93871] hostFromVds::selectedVds - ovirt-node02.stuttgart.example.net, spmStatus Free, storage pool HP_Proliant_DL180G6 2015-05-18 14:36:42,612 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.IrsProxyData] (DefaultQuartzScheduler_Worker-9) [76c93871] starting spm on vds ovirt-node02.stuttgart.example.net, storage pool HP_Proliant_DL180G6, prevId -1, LVER -1 2015-05-18 14:36:42,657 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-9) [76c93871] START, SpmStartVDSCommand(HostName = ovirt-node02.stuttgart.example.net, HostId = 6948da12-0b8a-4b6d-a9af-162e6c25dad3, storagePoolId = b384b3da-02a6-44f3-a3f6-56751ce8c26d, prevId=-1, prevLVER=-1, storagePoolFormatType=V3, recoveryMode=Manual, SCSIFencing=false), log id: 39ed2e0a 2015-05-18 14:36:42,676 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-9) [76c93871] spmStart polling started: taskId = caa54bef-a0c9-40e7-9a1c-ead9b7b10dd3 2015-05-18 14:36:42,839 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-31) START, GlusterVolumesListVDSCommand(HostName = ovirt-node01.stuttgart.example.net, HostId = 2e8cec66-23d7-4a5c-b6f3-9758d1d87f5c), log id: 5a5cc3b2 2015-05-18 14:36:43,075 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-31) FINISH, GlusterVolumesListVDSCommand, return: {d46619e9-9368-4e82-bf3a-a2377b6e85e4=org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeEntity@b94fa000}, log id: 5a5cc3b2 2015-05-18 14:36:43,341 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-31) START, GlusterVolumesListVDSCommand(HostName = ovirt-node04.stuttgart.example.net, HostId = 073c24e1-003f-412a-be56-0c41a435829a), log id: 74a38188 2015-05-18 14:36:43,429 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-31) FINISH, GlusterVolumesListVDSCommand, return: {e952fd41-45bf-42d9-b494-8e0195cb9756=org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeEntity@b7eeb15b}, log id: 74a38188 2015-05-18 14:36:43,444 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-31) START, GlusterVolumesListVDSCommand(HostName = ovirt-node07-stgt.stuttgart.example.net, HostId = 32dfc1f1-c474-4410-94c0-38776c121289), log id: 71a18ff2 2015-05-18 14:36:43,486 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-31) FINISH, GlusterVolumesListVDSCommand, return: {8786357b-9d11-4c01-a34b-aee949c116e9=org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeEntity@694b34c3}, log id: 71a18ff2 2015-05-18 14:36:43,685 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetTaskStatusVDSCommand] (DefaultQuartzScheduler_Worker-9) [76c93871] Failed in HSMGetTaskStatusVDS method 2015-05-18 14:36:43,687 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-9) [76c93871] spmStart polling ended: taskId = caa54bef-a0c9-40e7-9a1c-ead9b7b10dd3 task status = finished 2015-05-18 14:36:43,689 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-9) [76c93871] Start SPM Task failed - result: cleanSuccess, message: VDSGenericException: VDSErrorException: Failed to HSMGetTaskStatusVDS, error = Storage domain does not exist, code = 358 2015-05-18 14:36:43,744 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-9) [76c93871] spmStart polling ended, spm status: Free 2015-05-18 14:36:43,801 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (DefaultQuartzScheduler_Worker-9) [76c93871] START, HSMClearTaskVDSCommand(HostName = ovirt-node02.stuttgart.example.net, HostId = 6948da12-0b8a-4b6d-a9af-162e6c25dad3, taskId=caa54bef-a0c9-40e7-9a1c-ead9b7b10dd3), log id: 137e2e59 2015-05-18 14:36:43,811 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (DefaultQuartzScheduler_Worker-9) [76c93871] FINISH, HSMClearTaskVDSCommand, log id: 137e2e59 2015-05-18 14:36:43,812 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-9) [76c93871] FINISH, SpmStartVDSCommand, return: org.ovirt.engine.core.common.businessentities.SpmStatusResult@14bd85e2, log id: 39ed2e0a 2015-05-18 14:36:43,819 INFO [org.ovirt.engine.core.bll.storage.SetStoragePoolStatusCommand] (DefaultQuartzScheduler_Worker-9) [26a0c311] Running command: SetStoragePoolStatusCommand internal: true. Entities affected : ID: b384b3da-02a6-44f3-a3f6-56751ce8c26d Type: StoragePool 2015-05-18 14:36:43,889 WARN [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (DefaultQuartzScheduler_Worker-9) [26a0c311] Correlation ID: 26a0c311, Call Stack: null, Custom Event ID: -1, Message: Invalid status on Data Center HP_Proliant_DL180G6. Setting status to Non Responsive. 2015-05-18 14:36:43,895 ERROR [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (DefaultQuartzScheduler_Worker-9) [26a0c311] IrsBroker::Failed::GetStoragePoolInfoVDS due to: IrsSpmStartFailedException: IRSGenericException: IRSErrorException: SpmStart failed 2015-05-18 14:36:48,689 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-62) START, GlusterVolumesListVDSCommand(HostName = ovirt-node01.stuttgart.example.net, HostId = 2e8cec66-23d7-4a5c-b6f3-9758d1d87f5c), log id: 5cf2af7b 2015-05-18 14:36:48,958 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-62) FINISH, GlusterVolumesListVDSCommand, return: {d46619e9-9368-4e82-bf3a-a2377b6e85e4=org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeEntity@7b61fce}, log id: 5cf2af7b 2015-05-18 14:36:49,136 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-62) START, GlusterVolumesListVDSCommand(HostName = ovirt-node04.stuttgart.example.net, HostId = 073c24e1-003f-412a-be56-0c41a435829a), log id: 58b3a1f1 2015-05-18 14:36:49,241 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-62) FINISH, GlusterVolumesListVDSCommand, return: {e952fd41-45bf-42d9-b494-8e0195cb9756=org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeEntity@a2b43ca1}, log id: 58b3a1f1 2015-05-18 14:36:49,255 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-62) START, GlusterVolumesListVDSCommand(HostName = ovirt-node07-stgt.stuttgart.example.net, HostId = 32dfc1f1-c474-4410-94c0-38776c121289), log id: 231ed250 2015-05-18 14:36:49,293 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-62) FINISH, GlusterVolumesListVDSCommand, return: {8786357b-9d11-4c01-a34b-aee949c116e9=org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeEntity@878a1db8}, log id: 231ed250 2015-05-18 14:36:54,186 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSCommand] (DefaultQuartzScheduler_Worker-84) Command org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSCommand return value

TaskStatusListReturnForXmlRpc [mStatus=StatusForXmlRpc [mCode=654, mMessage=Not SPM]]

2015-05-18 14:36:54,247 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSCommand] (DefaultQuartzScheduler_Worker-84) HostName = ovirt-node02.stuttgart.example.net 2015-05-18 14:36:54,249 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSCommand] (DefaultQuartzScheduler_Worker-84) Command HSMGetAllTasksStatusesVDSCommand(HostName = ovirt-node02.stuttgart.example.net, HostId = 6948da12-0b8a-4b6d-a9af-162e6c25dad3) execution failed. Exception: IRSNonOperationalException: IRSGenericException: IRSErrorException: IRSNonOperationalException: Not SPM 2015-05-18 14:36:54,411 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.IrsProxyData] (DefaultQuartzScheduler_Worker-84) hostFromVds::selectedVds - ovirt-node01.stuttgart.example.net, spmStatus Free, storage pool HP_Proliant_DL180G6 2015-05-18 14:36:54,415 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.IrsProxyData] (DefaultQuartzScheduler_Worker-84) starting spm on vds ovirt-node01.stuttgart.example.net, storage pool HP_Proliant_DL180G6, prevId -1, LVER -1 2015-05-18 14:36:54,448 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-84) START, SpmStartVDSCommand(HostName = ovirt-node01.stuttgart.example.net, HostId = 2e8cec66-23d7-4a5c-b6f3-9758d1d87f5c, storagePoolId = b384b3da-02a6-44f3-a3f6-56751ce8c26d, prevId=-1, prevLVER=-1, storagePoolFormatType=V3, recoveryMode=Manual, SCSIFencing=false), log id: 6b7e937c 2015-05-18 14:36:54,458 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-84) spmStart polling started: taskId = 1df26d40-a863-4be2-8e4d-cc63e144b0e1 2015-05-18 14:36:54,500 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-81) START, GlusterVolumesListVDSCommand(HostName = ovirt-node01.stuttgart.example.net, HostId = 2e8cec66-23d7-4a5c-b6f3-9758d1d87f5c), log id: 21a76860 2015-05-18 14:36:54,732 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-81) FINISH, GlusterVolumesListVDSCommand, return: {d46619e9-9368-4e82-bf3a-a2377b6e85e4=org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeEntity@236c3904}, log id: 21a76860 2015-05-18 14:36:54,898 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-81) START, GlusterVolumesListVDSCommand(HostName = ovirt-node04.stuttgart.example.net, HostId = 073c24e1-003f-412a-be56-0c41a435829a), log id: 697b317e 2015-05-18 14:36:54,981 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-81) FINISH, GlusterVolumesListVDSCommand, return: {e952fd41-45bf-42d9-b494-8e0195cb9756=org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeEntity@17d1446c}, log id: 697b317e 2015-05-18 14:36:54,995 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-81) START, GlusterVolumesListVDSCommand(HostName = ovirt-node07-stgt.stuttgart.example.net, HostId = 32dfc1f1-c474-4410-94c0-38776c121289), log id: 7d8aa4d 2015-05-18 14:36:55,030 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-81) FINISH, GlusterVolumesListVDSCommand, return: {8786357b-9d11-4c01-a34b-aee949c116e9=org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeEntity@7c985d32}, log id: 7d8aa4d 2015-05-18 14:36:55,467 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetTaskStatusVDSCommand] (DefaultQuartzScheduler_Worker-84) Failed in HSMGetTaskStatusVDS method 2015-05-18 14:36:55,469 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-84) spmStart polling ended: taskId = 1df26d40-a863-4be2-8e4d-cc63e144b0e1 task status = finished 2015-05-18 14:36:55,471 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-84) Start SPM Task failed - result: cleanSuccess, message: VDSGenericException: VDSErrorException: Failed to HSMGetTaskStatusVDS, error = Storage domain does not exist, code = 358 2015-05-18 14:36:55,524 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-84) spmStart polling ended, spm status: Free 2015-05-18 14:36:55,582 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (DefaultQuartzScheduler_Worker-84) START, HSMClearTaskVDSCommand(HostName = ovirt-node01.stuttgart.example.net, HostId = 2e8cec66-23d7-4a5c-b6f3-9758d1d87f5c, taskId=1df26d40-a863-4be2-8e4d-cc63e144b0e1), log id: 1e686f88 2015-05-18 14:36:55,593 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (DefaultQuartzScheduler_Worker-84) FINISH, HSMClearTaskVDSCommand, log id: 1e686f88 2015-05-18 14:36:55,595 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-84) FINISH, SpmStartVDSCommand, return: org.ovirt.engine.core.common.businessentities.SpmStatusResult@60d70516, log id: 6b7e937c 2015-05-18 14:36:55,605 INFO [org.ovirt.engine.core.bll.storage.SetStoragePoolStatusCommand] (DefaultQuartzScheduler_Worker-84) [448f1905] Running command: SetStoragePoolStatusCommand internal: true. Entities affected : ID: b384b3da-02a6-44f3-a3f6-56751ce8c26d Type: StoragePool 2015-05-18 14:36:55,686 ERROR [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (DefaultQuartzScheduler_Worker-84) [448f1905] IrsBroker::Failed::GetStoragePoolInfoVDS due to: IrsSpmStartFailedException: IRSGenericException: IRSErrorException: SpmStart failed 2015-05-18 14:36:55,814 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.IrsProxyData] (DefaultQuartzScheduler_Worker-84) [448f1905] Irs placed on server 2e8cec66-23d7-4a5c-b6f3-9758d1d87f5c failed. Proceed Failover 2015-05-18 14:36:55,892 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.IrsProxyData] (DefaultQuartzScheduler_Worker-84) [448f1905] hostFromVds::selectedVds - ovirt-node02.stuttgart.example.net, spmStatus Free, storage pool HP_Proliant_DL180G6 2015-05-18 14:36:55,898 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.IrsProxyData] (DefaultQuartzScheduler_Worker-84) [448f1905] starting spm on vds ovirt-node02.stuttgart.example.net, storage pool HP_Proliant_DL180G6, prevId -1, LVER -1 2015-05-18 14:36:55,958 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-84) [448f1905] START, SpmStartVDSCommand(HostName = ovirt-node02.stuttgart.example.net, HostId = 6948da12-0b8a-4b6d-a9af-162e6c25dad3, storagePoolId = b384b3da-02a6-44f3-a3f6-56751ce8c26d, prevId=-1, prevLVER=-1, storagePoolFormatType=V3, recoveryMode=Manual, SCSIFencing=false), log id: 3bcd36d4 2015-05-18 14:36:55,969 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-84) [448f1905] spmStart polling started: taskId = 8ebae0ff-b0cd-4e78-ac98-1ffa2de94c2c 2015-05-18 14:36:56,978 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetTaskStatusVDSCommand] (DefaultQuartzScheduler_Worker-84) [448f1905] Failed in HSMGetTaskStatusVDS method 2015-05-18 14:36:56,980 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-84) [448f1905] spmStart polling ended: taskId = 8ebae0ff-b0cd-4e78-ac98-1ffa2de94c2c task status = finished 2015-05-18 14:36:56,982 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-84) [448f1905] Start SPM Task failed - result: cleanSuccess, message: VDSGenericException: VDSErrorException: Failed to HSMGetTaskStatusVDS, error = Storage domain does not exist, code = 358 2015-05-18 14:36:57,034 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-84) [448f1905] spmStart polling ended, spm status: Free 2015-05-18 14:36:57,092 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (DefaultQuartzScheduler_Worker-84) [448f1905] START, HSMClearTaskVDSCommand(HostName = ovirt-node02.stuttgart.example.net, HostId = 6948da12-0b8a-4b6d-a9af-162e6c25dad3, taskId=8ebae0ff-b0cd-4e78-ac98-1ffa2de94c2c), log id: aa83196 2015-05-18 14:36:57,103 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (DefaultQuartzScheduler_Worker-84) [448f1905] FINISH, HSMClearTaskVDSCommand, log id: aa83196 2015-05-18 14:36:57,104 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-84) [448f1905] FINISH, SpmStartVDSCommand, return: org.ovirt.engine.core.common.businessentities.SpmStatusResult@31dc73ed, log id: 3bcd36d4 2015-05-18 14:36:57,111 INFO [org.ovirt.engine.core.bll.storage.SetStoragePoolStatusCommand] (DefaultQuartzScheduler_Worker-84) [3ee62e] Running command: SetStoragePoolStatusCommand internal: true. Entities affected : ID: b384b3da-02a6-44f3-a3f6-56751ce8c26d Type: StoragePool 2015-05-18 14:36:57,180 ERROR [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (DefaultQuartzScheduler_Worker-84) [3ee62e] IrsBroker::Failed::GetStoragePoolInfoVDS due to: IrsSpmStartFailedException: IRSGenericException: IRSErrorException: SpmStart failed 2015-05-18 14:37:00,260 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-16) START, GlusterVolumesListVDSCommand(HostName = ovirt-node01.stuttgart.example.net, HostId = 2e8cec66-23d7-4a5c-b6f3-9758d1d87f5c), log id: 5f3899c0 2015-05-18 14:37:00,453 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.GetFileStatsVDSCommand] (org.ovirt.thread.pool-8-thread-46) START, GetFileStatsVDSCommand( storagePoolId = cf165524-0971-434c-8a5e-f2d5cb877506, ignoreFailoverLimit = false), log id: 672df19 2015-05-18 14:37:00,478 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-16) FINISH, GlusterVolumesListVDSCommand, return: {d46619e9-9368-4e82-bf3a-a2377b6e85e4=org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeEntity@c4308c6f}, log id: 5f3899c0 2015-05-18 14:37:00,544 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.GetFileStatsVDSCommand] (org.ovirt.thread.pool-8-thread-46) FINISH, GetFileStatsVDSCommand, return: {KNOPPIX_V5.0.1CD-2006-06-01-DE.iso={status=0, ctime=1424080000.0, size=730036224}, 5.4-RELEASE-i386-disc1.iso={status=0, ctime=1431100000.0, size=563701760}, debian-31r8-i386-netinst.iso={status=0, ctime=1424080000.0, size=110628864}, grml64-small_2013.09.iso={status=0, ctime=1424080000.0, size=188743680}, debian-7.3.0-amd64-netinst.iso={status=0, ctime=1424080000.0, size=231735296}, debian-7.8.0-amd64-netinst.iso={status=0, ctime=1424080000.0, size=232783872}, debian-7.7.0-amd64-netinst.iso={status=0, ctime=1424080000.0, size=232783872}, grml32-small_2014.03.iso={status=0, ctime=1424080000.0, size=207618048}}, log id: 672df19 2015-05-18 14:37:00,593 INFO [org.ovirt.engine.core.bll.IsoDomainListSyncronizer] (org.ovirt.thread.pool-8-thread-46) Finished automatic refresh process for ISO file type with success, for storage domain id 6d882c77-cdbc-48ef-ae21-1a6d45e7f8a1. 2015-05-18 14:37:00,756 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-16) START, GlusterVolumesListVDSCommand(HostName = ovirt-node04.stuttgart.example.net, HostId = 073c24e1-003f-412a-be56-0c41a435829a), log id: 72f57b74 2015-05-18 14:37:00,841 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-16) FINISH, GlusterVolumesListVDSCommand, return: {e952fd41-45bf-42d9-b494-8e0195cb9756=org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeEntity@999d3275}, log id: 72f57b74 2015-05-18 14:37:00,860 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-16) START, GlusterVolumesListVDSCommand(HostName = ovirt-node07-stgt.stuttgart.example.net, HostId = 32dfc1f1-c474-4410-94c0-38776c121289), log id: 23b84657 2015-05-18 14:37:00,900 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-16) FINISH, GlusterVolumesListVDSCommand, return: {8786357b-9d11-4c01-a34b-aee949c116e9=org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeEntity@106e5ec1}, log id: 23b84657 2015-05-18 14:37:02,992 INFO [org.ovirt.engine.core.vdsbroker.gluster.GetGlusterVolumeAdvancedDetailsVDSCommand] (DefaultQuartzScheduler_Worker-8) [1f6e11f1] START, GetGlusterVolumeAdvancedDetailsVDSCommand(HostName = ovirt-node02.stuttgart.example.net, HostId = 6948da12-0b8a-4b6d-a9af-162e6c25dad3), log id: 1bad432c 2015-05-18 14:37:03,005 INFO [org.ovirt.engine.core.bll.scheduling.HaReservationHandling] (DefaultQuartzScheduler_Worker-31) HA reservation status for cluster HP_Proliant_DL180G6_Cluster_II is OK 2015-05-18 14:37:03,322 INFO [org.ovirt.engine.core.vdsbroker.gluster.GetGlusterVolumeAdvancedDetailsVDSCommand] (DefaultQuartzScheduler_Worker-8) [1f6e11f1] FINISH, GetGlusterVolumeAdvancedDetailsVDSCommand, return: org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeAdvancedDetails@68b72574, log id: 1bad432c 2015-05-18 14:37:03,485 INFO [org.ovirt.engine.core.vdsbroker.gluster.GetGlusterVolumeAdvancedDetailsVDSCommand] (DefaultQuartzScheduler_Worker-8) [1f6e11f1] START, GetGlusterVolumeAdvancedDetailsVDSCommand(HostName = ovirt-node03.stuttgart.example.net, HostId = 58c3a03d-d289-45ad-a5e5-f3d37d66cca7), log id: 2b6cf052 2015-05-18 14:37:03,611 INFO [org.ovirt.engine.core.vdsbroker.gluster.GetGlusterVolumeAdvancedDetailsVDSCommand] (DefaultQuartzScheduler_Worker-8) [1f6e11f1] FINISH, GetGlusterVolumeAdvancedDetailsVDSCommand, return: org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeAdvancedDetails@cf009849, log id: 2b6cf052 2015-05-18 14:37:03,629 INFO [org.ovirt.engine.core.vdsbroker.gluster.GetGlusterVolumeAdvancedDetailsVDSCommand] (DefaultQuartzScheduler_Worker-8) [1f6e11f1] START, GetGlusterVolumeAdvancedDetailsVDSCommand(HostName = ovirt-node07-stgt.stuttgart.example.net, HostId = 32dfc1f1-c474-4410-94c0-38776c121289), log id: 18cc227c 2015-05-18 14:37:04,024 INFO [org.ovirt.engine.core.vdsbroker.gluster.GetGlusterVolumeAdvancedDetailsVDSCommand] (DefaultQuartzScheduler_Worker-8) [1f6e11f1] FINISH, GetGlusterVolumeAdvancedDetailsVDSCommand, return: org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeAdvancedDetails@e7361042, log id: 18cc227c 2015-05-18 14:37:05,479 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterTasksListVDSCommand] (DefaultQuartzScheduler_Worker-49) START, GlusterTasksListVDSCommand(HostName = ovirt-node02.stuttgart.example.net, HostId = 6948da12-0b8a-4b6d-a9af-162e6c25dad3), log id: f8356a4 2015-05-18 14:37:05,593 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterTasksListVDSCommand] (DefaultQuartzScheduler_Worker-49) FINISH, GlusterTasksListVDSCommand, return: [], log id: f8356a4 2015-05-18 14:37:05,789 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterTasksListVDSCommand] (DefaultQuartzScheduler_Worker-49) START, GlusterTasksListVDSCommand(HostName = ovirt-node04.stuttgart.example.net, HostId = 073c24e1-003f-412a-be56-0c41a435829a), log id: 1707c285 2015-05-18 14:37:05,816 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterTasksListVDSCommand] (DefaultQuartzScheduler_Worker-49) FINISH, GlusterTasksListVDSCommand, return: [], log id: 1707c285 2015-05-18 14:37:05,821 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterTasksListVDSCommand] (DefaultQuartzScheduler_Worker-49) START, GlusterTasksListVDSCommand(HostName = ovirt-node05-stgt.stuttgart.example.net, HostId = 4ca44033-4f16-413d-828a-cbfe4dacf891), log id: 29e4ebc3 2015-05-18 14:37:05,885 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterTasksListVDSCommand] (DefaultQuartzScheduler_Worker-49) FINISH, GlusterTasksListVDSCommand, return: [], log id: 29e4ebc3 2015-05-18 14:37:06,071 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-61) START, GlusterVolumesListVDSCommand(HostName = ovirt-node01.stuttgart.example.net, HostId = 2e8cec66-23d7-4a5c-b6f3-9758d1d87f5c), log id: 377c4636 2015-05-18 14:37:06,250 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-61) FINISH, GlusterVolumesListVDSCommand, return: {d46619e9-9368-4e82-bf3a-a2377b6e85e4=org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeEntity@d9e03a61}, log id: 377c4636 2015-05-18 14:37:06,429 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-61) START, GlusterVolumesListVDSCommand(HostName = ovirt-node04.stuttgart.example.net, HostId = 073c24e1-003f-412a-be56-0c41a435829a), log id: 2c323dc0 2015-05-18 14:37:06,577 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-61) FINISH, GlusterVolumesListVDSCommand, return: {e952fd41-45bf-42d9-b494-8e0195cb9756=org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeEntity@bd6050c7}, log id: 2c323dc0 2015-05-18 14:37:06,603 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-61) START, GlusterVolumesListVDSCommand(HostName = ovirt-node07-stgt.stuttgart.example.net, HostId = 32dfc1f1-c474-4410-94c0-38776c121289), log id: 3159e468 2015-05-18 14:37:06,637 INFO [org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand] (DefaultQuartzScheduler_Worker-61) FINISH, GlusterVolumesListVDSCommand, return: {8786357b-9d11-4c01-a34b-aee949c116e9=org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeEntity@9d150a0a}, log id: 3159e468 2015-05-18 14:37:07,468 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSCommand] (DefaultQuartzScheduler_Worker-70) Command org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSCommand return value

TaskStatusListReturnForXmlRpc [mStatus=StatusForXmlRpc [mCode=654, mMessage=Not SPM]]

2015-05-18 14:37:07,527 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSCommand] (DefaultQuartzScheduler_Worker-70) HostName = ovirt-node02.stuttgart.example.net 2015-05-18 14:37:07,529 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSCommand] (DefaultQuartzScheduler_Worker-70) Command HSMGetAllTasksStatusesVDSCommand(HostName = ovirt-node02.stuttgart.example.net, HostId = 6948da12-0b8a-4b6d-a9af-162e6c25dad3) execution failed. Exception: IRSNonOperationalException: IRSGenericException: IRSErrorException: IRSNonOperationalException: Not SPM 2015-05-18 14:37:07,734 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.IrsProxyData] (DefaultQuartzScheduler_Worker-70) hostFromVds::selectedVds - ovirt-node02.stuttgart.example.net, spmStatus Free, storage pool HP_Proliant_DL180G6 2015-05-18 14:37:07,740 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.IrsProxyData] (DefaultQuartzScheduler_Worker-70) starting spm on vds ovirt-node02.stuttgart.example.net, storage pool HP_Proliant_DL180G6, prevId -1, LVER -1 2015-05-18 14:37:07,780 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-70) START, SpmStartVDSCommand(HostName = ovirt-node02.stuttgart.example.net, HostId = 6948da12-0b8a-4b6d-a9af-162e6c25dad3, storagePoolId = b384b3da-02a6-44f3-a3f6-56751ce8c26d, prevId=-1, prevLVER=-1, storagePoolFormatType=V3, recoveryMode=Manual, SCSIFencing=false), log id: 2cf7641 2015-05-18 14:37:07,792 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (DefaultQuartzScheduler_Worker-70) spmStart polling started: taskId = 9370fc1f-e128-469f-afd1-67dfa4815089 (END)

Thanks, Mario

Am 18.05.15 um 14:21 schrieb Maor Lipchuk:

...

Hi Mario,

Can u try to mount this directly from the Host? Can u please attach the VDSM and engine logs

Thanks, Maor

----- Original Message -----

...

From: ml@ohnewald.net To: "Maor Lipchuk" <mlipchuk@redhat.com> Cc: users@ovirt.org Sent: Monday, May 18, 2015 2:36:38 PM Subject: Re: [ovirt-users] vdsm storage problem - maybe cache problem?

Hi Maor,

thanks for the quick reply.

Am 18.05.15 um 13:25 schrieb Maor Lipchuk:

...

...

Now my Question: Why does the vdsm node not know that i deleted the storage? Has the vdsm cached this mount informations? Why does it still try to access 036b5575-51fa-4f14-8b05-890d7807894c?

Yes, the vdsm use a cache for Storage Domains, you can try to restart the vdsmd service instead of rebooting the host.

I am still getting the same error.

[root@ovirt-node01 ~]# /etc/init.d/vdsmd stop Shutting down vdsm daemon: vdsm watchdog stop [ OK ] vdsm: Running run_final_hooks [ OK ] vdsm stop [ OK ] [root@ovirt-node01 ~]# [root@ovirt-node01 ~]# [root@ovirt-node01 ~]# [root@ovirt-node01 ~]# ps aux | grep vdsmd root 3198 0.0 0.0 11304 740 ? S< May07 0:00 /bin/bash -e /usr/share/vdsm/respawn --minlifetime 10 --daemon --masterpid /var/run/vdsm/supervdsm_respawn.pid /usr/share/vdsm/supervdsmServer --sockfile /var/run/vdsm/svdsm.sock --pidfile /var/run/vdsm/supervdsmd.pid root 3205 0.0 0.0 922368 26724 ? S<l May07 12:10 /usr/bin/python /usr/share/vdsm/supervdsmServer --sockfile /var/run/vdsm/svdsm.sock --pidfile /var/run/vdsm/supervdsmd.pid root 15842 0.0 0.0 103248 900 pts/0 S+ 13:35 0:00 grep vdsmd

[root@ovirt-node01 ~]# /etc/init.d/vdsmd start initctl: Job is already running: libvirtd vdsm: Running mkdirs vdsm: Running configure_coredump vdsm: Running configure_vdsm_logs vdsm: Running run_init_hooks vdsm: Running gencerts vdsm: Running check_is_configured libvirt is already configured for vdsm sanlock service is already configured vdsm: Running validate_configuration SUCCESS: ssl configured to true. No conflicts vdsm: Running prepare_transient_repository vdsm: Running syslog_available vdsm: Running nwfilter vdsm: Running dummybr vdsm: Running load_needed_modules vdsm: Running tune_system vdsm: Running test_space vdsm: Running test_lo vdsm: Running restore_nets vdsm: Running unified_network_persistence_upgrade vdsm: Running upgrade_300_nets Starting up vdsm daemon: vdsm start [ OK ] [root@ovirt-node01 ~]#

[root@ovirt-node01 ~]# grep ERROR /var/log/vdsm/vdsm.log | tail -n 20 Thread-13::ERROR::2015-05-18 13:35:03,631::sdc::137::Storage.StorageDomainCache::(_findDomain) looking for unfetched domain abc51e26-7175-4b38-b3a8-95c6928fbc2b Thread-13::ERROR::2015-05-18 13:35:03,632::sdc::154::Storage.StorageDomainCache::(_findUnfetchedDomain)

looking for domain abc51e26-7175-4b38-b3a8-95c6928fbc2b Thread-36::ERROR::2015-05-18 13:35:11,607::sdc::137::Storage.StorageDomainCache::(_findDomain) looking for unfetched domain 036b5575-51fa-4f14-8b05-890d7807894c Thread-36::ERROR::2015-05-18 13:35:11,621::sdc::154::Storage.StorageDomainCache::(_findUnfetchedDomain)

looking for domain 036b5575-51fa-4f14-8b05-890d7807894c Thread-36::ERROR::2015-05-18 13:35:11,960::sdc::143::Storage.StorageDomainCache::(_findDomain) domain 036b5575-51fa-4f14-8b05-890d7807894c not found Thread-36::ERROR::2015-05-18 13:35:11,960::domainMonitor::239::Storage.DomainMonitorThread::(_monitorDomain)

Error while collecting domain 036b5575-51fa-4f14-8b05-890d7807894c monitoring information Thread-36::ERROR::2015-05-18 13:35:21,962::sdc::137::Storage.StorageDomainCache::(_findDomain) looking for unfetched domain 036b5575-51fa-4f14-8b05-890d7807894c Thread-36::ERROR::2015-05-18 13:35:21,965::sdc::154::Storage.StorageDomainCache::(_findUnfetchedDomain)

looking for domain 036b5575-51fa-4f14-8b05-890d7807894c Thread-36::ERROR::2015-05-18 13:35:22,068::sdc::143::Storage.StorageDomainCache::(_findDomain) domain 036b5575-51fa-4f14-8b05-890d7807894c not found Thread-36::ERROR::2015-05-18 13:35:22,072::domainMonitor::239::Storage.DomainMonitorThread::(_monitorDomain)

Error while collecting domain 036b5575-51fa-4f14-8b05-890d7807894c monitoring information Thread-15::ERROR::2015-05-18 13:35:33,821::task::866::TaskManager.Task::(_setError) Task=`54bdfc77-f63a-493b-b24e-e5a3bc4977bb`::Unexpected error Thread-15::ERROR::2015-05-18 13:35:33,864::dispatcher::65::Storage.Dispatcher.Protect::(run) {'status': {'message': "Unknown pool id, pool not connected: ('b384b3da-02a6-44f3-a3f6-56751ce8c26d',)", 'code': 309}} Thread-13::ERROR::2015-05-18 13:35:33,930::sdc::137::Storage.StorageDomainCache::(_findDomain) looking for unfetched domain abc51e26-7175-4b38-b3a8-95c6928fbc2b Thread-15::ERROR::2015-05-18 13:35:33,928::task::866::TaskManager.Task::(_setError) Task=`fe9bb0fa-cf1e-4b21-af00-0698c6d1718f`::Unexpected error Thread-13::ERROR::2015-05-18 13:35:33,932::sdc::154::Storage.StorageDomainCache::(_findUnfetchedDomain)

looking for domain abc51e26-7175-4b38-b3a8-95c6928fbc2b Thread-15::ERROR::2015-05-18 13:35:33,978::dispatcher::65::Storage.Dispatcher.Protect::(run) {'status': {'message': 'Not SPM: ()', 'code': 654}} Thread-36::ERROR::2015-05-18 13:35:41,117::sdc::137::Storage.StorageDomainCache::(_findDomain) looking for unfetched domain 036b5575-51fa-4f14-8b05-890d7807894c Thread-36::ERROR::2015-05-18 13:35:41,131::sdc::154::Storage.StorageDomainCache::(_findUnfetchedDomain)

looking for domain 036b5575-51fa-4f14-8b05-890d7807894c Thread-36::ERROR::2015-05-18 13:35:41,452::sdc::143::Storage.StorageDomainCache::(_findDomain) domain 036b5575-51fa-4f14-8b05-890d7807894c not found Thread-36::ERROR::2015-05-18 13:35:41,453::domainMonitor::239::Storage.DomainMonitorThread::(_monitorDomain)

Error while collecting domain 036b5575-51fa-4f14-8b05-890d7807894c monitoring information

Thanks, Mario