[ovirt-users] vdsm storage problem - maybe cache problem?
ml at ohnewald.net
ml at ohnewald.net
Tue May 19 07:25:45 UTC 2015
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 at ohnewald.net:
> Manual mounting works:
>
> [root at ovirt-node01 ~]# mount ovirt.hq.example.net:/export2 /tmp/mnt/
> [root at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at ohnewald.net
>>> To: "Maor Lipchuk" <mlipchuk at redhat.com>
>>> Cc: users at 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 at 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 at ovirt-node01 ~]#
>>> [root at ovirt-node01 ~]#
>>> [root at ovirt-node01 ~]#
>>> [root at 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 at 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 at ovirt-node01 ~]#
>>>
>>> [root at 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
>>>
>>>
>
More information about the Users
mailing list