Re: [ovirt-users] can't attach storage domain to data center

Hello, I've been struggling to set up an Ovirt cluster and am now bumping into this problem: When I try to create a new (Gluster) storage domain, it fails to attach to the data center. The error on the node from vdsm.log: Thread-13::DEBUG::2014-06-21 16:17:14,157::BindingXMLRPC::251::vds::(wrapper) client [192.168.10.119] flowID [6e44c0a3] Thread-13::DEBUG::2014-06-21 16:17:14,159::task::595::TaskManager.Task::(_updateState) Task=`97b78287-45d2-4d5a-8336-460987df3840`::moving from state init -> state preparing Thread-13::INFO::2014-06-21 16:17:14,160::logUtils::44::dispatcher::(wrapper) Run and protect: connectStorageServer(domType=7, spUUID='00000000-0000-0000-0000-000000000000', conList=[{'port': '', 'connection': '192.168.10.120:/vmimage', 'iqn': '', 'user': '', 'tpgt': '1', 'vfs_type': 'glusterfs', 'password': '******', 'id': '901b15ec-6b05-43c1-8a50-06b34c8ffdbd'}], options=None) Thread-13::DEBUG::2014-06-21 16:17:14,172::hsm::2340::Storage.HSM::(__prefetchDomains) glusterDomPath: glusterSD/* Thread-13::DEBUG::2014-06-21 16:17:14,185::hsm::2352::Storage.HSM::(__prefetchDomains) Found SD uuids: ('dc661957-c0c1-44ba-a5b9-e6558904207b',) Thread-13::DEBUG::2014-06-21 16:17:14,185::hsm::2408::Storage.HSM::(connectStorageServer) knownSDs: {dc661957-c0c1-44ba-a5b9-e6558904207b: storage.glusterSD.findDomain} Thread-13::INFO::2014-06-21 16:17:14,186::logUtils::47::dispatcher::(wrapper) Run and protect: connectStorageServer, Return response: {'statuslist': [{'status': 0, 'id': '901b15ec-6b05-43c1-8a50-06b34c8ffdbd'}]} Thread-13::DEBUG::2014-06-21 16:17:14,186::task::1185::TaskManager.Task::(prepare) Task=`97b78287-45d2-4d5a-8336-460987df3840`::finished: {'statuslist': [{'status': 0, 'id': '901b15ec-6b05-43c1-8a50-06b34c8ffdbd'}]} Thread-13::DEBUG::2014-06-21 16:17:14,187::task::595::TaskManager.Task::(_updateState) Task=`97b78287-45d2-4d5a-8336-460987df3840`::moving from state preparing -> state finished Thread-13::DEBUG::2014-06-21 16:17:14,187::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-13::DEBUG::2014-06-21 16:17:14,187::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-13::DEBUG::2014-06-21 16:17:14,188::task::990::TaskManager.Task::(_decref) Task=`97b78287-45d2-4d5a-8336-460987df3840`::ref 0 aborting False Thread-13::DEBUG::2014-06-21 16:17:14,195::BindingXMLRPC::251::vds::(wrapper) client [192.168.10.119] flowID [6e44c0a3] Thread-13::DEBUG::2014-06-21 16:17:14,195::task::595::TaskManager.Task::(_updateState) Task=`d815e5e5-0202-4137-94be-21dc5e2b61c9`::moving from state init -> state preparing Thread-13::INFO::2014-06-21 16:17:14,196::logUtils::44::dispatcher::(wrapper) Run and protect: createStoragePool(poolType=None, spUUID='806d2356-12cf-437c-8917-dd13ee823e36', poolName='testing', masterDom='dc661957-c0c1-44ba-a5b9-e6558904207b', domList=['dc661957-c0c1-44ba-a5b9-e6558904207b'], masterVersion=2, lockPolicy=None, lockRenewalIntervalSec=5, leaseTimeSec=60, ioOpTimeoutSec=10, leaseRetries=3, options=None) Thread-13::DEBUG::2014-06-21 16:17:14,196::misc::756::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage) Thread-13::DEBUG::2014-06-21 16:17:14,197::misc::758::SamplingMethod::(__call__) Got in to sampling method Thread-13::DEBUG::2014-06-21 16:17:14,197::misc::756::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan) Thread-13::DEBUG::2014-06-21 16:17:14,198::misc::758::SamplingMethod::(__call__) Got in to sampling method Thread-13::DEBUG::2014-06-21 16:17:14,198::iscsi::407::Storage.ISCSI::(rescan) Performing SCSI scan, this will take up to 30 seconds Thread-13::DEBUG::2014-06-21 16:17:14,199::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None) Thread-13::DEBUG::2014-06-21 16:17:14,228::misc::766::SamplingMethod::(__call__) Returning last result Thread-13::DEBUG::2014-06-21 16:17:14,229::multipath::110::Storage.Misc.excCmd::(rescan) '/usr/bin/sudo -n /sbin/multipath -r' (cwd None) Thread-13::DEBUG::2014-06-21 16:17:14,294::multipath::110::Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0 Thread-13::DEBUG::2014-06-21 16:17:14,295::lvm::497::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex Thread-13::DEBUG::2014-06-21 16:17:14,295::lvm::499::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex Thread-13::DEBUG::2014-06-21 16:17:14,296::lvm::508::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex Thread-13::DEBUG::2014-06-21 16:17:14,296::lvm::510::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex Thread-13::DEBUG::2014-06-21 16:17:14,297::lvm::528::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex Thread-13::DEBUG::2014-06-21 16:17:14,297::lvm::530::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex Thread-13::DEBUG::2014-06-21 16:17:14,298::misc::766::SamplingMethod::(__call__) Returning last result Thread-13::DEBUG::2014-06-21 16:17:14,318::fileSD::150::Storage.StorageDomain::(__init__) Reading domain in path /rhev/data-center/mnt/glusterSD/192.168.10.120:_vmimage/dc661957-c0c1-44ba-a5b9-e6558904207b Thread-13::DEBUG::2014-06-21 16:17:14,322::persistentDict::192::Storage.PersistentDict::(__init__) Created a persistent dict with FileMetadataRW backend Thread-13::DEBUG::2014-06-21 16:17:14,328::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=vmimage', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'POOL_UUID=', 'REMOTE_PATH=192.168.10.120:/vmimage', 'ROLE=Regular', 'SDUUID=dc661957-c0c1-44ba-a5b9-e6558904207b', 'TYPE=GLUSTERFS', 'VERSION=3', '_SHA_CKSUM=9fdc035c398d2cd8b5c31bf5eea2882c8782ed57'] Thread-13::DEBUG::2014-06-21 16:17:14,334::fileSD::609::Storage.StorageDomain::(imageGarbageCollector) Removing remnants of deleted images [] Thread-13::INFO::2014-06-21 16:17:14,335::sd::383::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace dc661957-c0c1-44ba-a5b9-e6558904207b_imageNS already registered Thread-13::INFO::2014-06-21 16:17:14,335::sd::391::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace dc661957-c0c1-44ba-a5b9-e6558904207b_volumeNS already registered Thread-13::INFO::2014-06-21 16:17:14,336::fileSD::350::Storage.StorageDomain::(validate) sdUUID=dc661957-c0c1-44ba-a5b9-e6558904207b Thread-13::DEBUG::2014-06-21 16:17:14,340::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=vmimage', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'POOL_UUID=', 'REMOTE_PATH=192.168.10.120:/vmimage', 'ROLE=Regular', 'SDUUID=dc661957-c0c1-44ba-a5b9-e6558904207b', 'TYPE=GLUSTERFS', 'VERSION=3', '_SHA_CKSUM=9fdc035c398d2cd8b5c31bf5eea2882c8782ed57'] Thread-13::DEBUG::2014-06-21 16:17:14,341::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.806d2356-12cf-437c-8917-dd13ee823e36`ReqID=`de2ede47-22fa-43b8-9f3b-dc714a45b450`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '980' at 'createStoragePool' Thread-13::DEBUG::2014-06-21 16:17:14,342::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.806d2356-12cf-437c-8917-dd13ee823e36' for lock type 'exclusive' Thread-13::DEBUG::2014-06-21 16:17:14,342::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.806d2356-12cf-437c-8917-dd13ee823e36' is free. Now locking as 'exclusive' (1 active user) Thread-13::DEBUG::2014-06-21 16:17:14,343::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.806d2356-12cf-437c-8917-dd13ee823e36`ReqID=`de2ede47-22fa-43b8-9f3b-dc714a45b450`::Granted request Thread-13::DEBUG::2014-06-21 16:17:14,343::task::827::TaskManager.Task::(resourceAcquired) Task=`d815e5e5-0202-4137-94be-21dc5e2b61c9`::_resourcesAcquired: Storage.806d2356-12cf-437c-8917-dd13ee823e36 (exclusive) Thread-13::DEBUG::2014-06-21 16:17:14,344::task::990::TaskManager.Task::(_decref) Task=`d815e5e5-0202-4137-94be-21dc5e2b61c9`::ref 1 aborting False Thread-13::DEBUG::2014-06-21 16:17:14,345::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.dc661957-c0c1-44ba-a5b9-e6558904207b`ReqID=`71bf6917-b501-4016-ad8e-8b84849da8cb`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '982' at 'createStoragePool' Thread-13::DEBUG::2014-06-21 16:17:14,345::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.dc661957-c0c1-44ba-a5b9-e6558904207b' for lock type 'exclusive' Thread-13::DEBUG::2014-06-21 16:17:14,346::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.dc661957-c0c1-44ba-a5b9-e6558904207b' is free. Now locking as 'exclusive' (1 active user) Thread-13::DEBUG::2014-06-21 16:17:14,346::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.dc661957-c0c1-44ba-a5b9-e6558904207b`ReqID=`71bf6917-b501-4016-ad8e-8b84849da8cb`::Granted request Thread-13::DEBUG::2014-06-21 16:17:14,347::task::827::TaskManager.Task::(resourceAcquired) Task=`d815e5e5-0202-4137-94be-21dc5e2b61c9`::_resourcesAcquired: Storage.dc661957-c0c1-44ba-a5b9-e6558904207b (exclusive) Thread-13::DEBUG::2014-06-21 16:17:14,347::task::990::TaskManager.Task::(_decref) Task=`d815e5e5-0202-4137-94be-21dc5e2b61c9`::ref 1 aborting False Thread-13::INFO::2014-06-21 16:17:14,347::sp::133::Storage.StoragePool::(setBackend) updating pool 806d2356-12cf-437c-8917-dd13ee823e36 backend from type NoneType instance 0x39e278bf00 to type StoragePoolDiskBackend instance 0x7f764c093cb0 Thread-13::INFO::2014-06-21 16:17:14,348::sp::548::Storage.StoragePool::(create) spUUID=806d2356-12cf-437c-8917-dd13ee823e36 poolName=testing master_sd=dc661957-c0c1-44ba-a5b9-e6558904207b domList=['dc661957-c0c1-44ba-a5b9-e6558904207b'] masterVersion=2 {'LEASETIMESEC': 60, 'IOOPTIMEOUTSEC': 10, 'LEASERETRIES': 3, 'LOCKRENEWALINTERVALSEC': 5} Thread-13::INFO::2014-06-21 16:17:14,348::fileSD::350::Storage.StorageDomain::(validate) sdUUID=dc661957-c0c1-44ba-a5b9-e6558904207b Thread-13::DEBUG::2014-06-21 16:17:14,352::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=vmimage', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'POOL_UUID=', 'REMOTE_PATH=192.168.10.120:/vmimage', 'ROLE=Regular', 'SDUUID=dc661957-c0c1-44ba-a5b9-e6558904207b', 'TYPE=GLUSTERFS', 'VERSION=3', '_SHA_CKSUM=9fdc035c398d2cd8b5c31bf5eea2882c8782ed57'] Thread-13::DEBUG::2014-06-21 16:17:14,357::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=vmimage', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'POOL_UUID=', 'REMOTE_PATH=192.168.10.120:/vmimage', 'ROLE=Regular', 'SDUUID=dc661957-c0c1-44ba-a5b9-e6558904207b', 'TYPE=GLUSTERFS', 'VERSION=3', '_SHA_CKSUM=9fdc035c398d2cd8b5c31bf5eea2882c8782ed57'] Thread-13::WARNING::2014-06-21 16:17:14,358::fileUtils::167::Storage.fileUtils::(createdir) Dir /rhev/data-center/806d2356-12cf-437c-8917-dd13ee823e36 already exists Thread-13::DEBUG::2014-06-21 16:17:14,358::persistentDict::167::Storage.PersistentDict::(transaction) Starting transaction Thread-13::DEBUG::2014-06-21 16:17:14,359::persistentDict::175::Storage.PersistentDict::(transaction) Finished transaction Thread-13::INFO::2014-06-21 16:17:14,359::clusterlock::184::SANLock::(acquireHostId) Acquiring host id for domain dc661957-c0c1-44ba-a5b9-e6558904207b (id: 250) Thread-24::DEBUG::2014-06-21 16:17:14,394::task::595::TaskManager.Task::(_updateState) Task=`c4430b80-31d9-4a1d-bee8-fae01a438da6`::moving from state init -> state preparing Thread-24::INFO::2014-06-21 16:17:14,395::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None) Thread-24::INFO::2014-06-21 16:17:14,395::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {} Thread-24::DEBUG::2014-06-21 16:17:14,396::task::1185::TaskManager.Task::(prepare) Task=`c4430b80-31d9-4a1d-bee8-fae01a438da6`::finished: {} Thread-24::DEBUG::2014-06-21 16:17:14,396::task::595::TaskManager.Task::(_updateState) Task=`c4430b80-31d9-4a1d-bee8-fae01a438da6`::moving from state preparing -> state finished Thread-24::DEBUG::2014-06-21 16:17:14,396::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-24::DEBUG::2014-06-21 16:17:14,396::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-24::DEBUG::2014-06-21 16:17:14,397::task::990::TaskManager.Task::(_decref) Task=`c4430b80-31d9-4a1d-bee8-fae01a438da6`::ref 0 aborting False Thread-13::ERROR::2014-06-21 16:17:15,361::task::866::TaskManager.Task::(_setError) Task=`d815e5e5-0202-4137-94be-21dc5e2b61c9`::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/logUtils.py", line 45, in wrapper res = f(*args, **kwargs) File "/usr/share/vdsm/storage/hsm.py", line 988, in createStoragePool leaseParams) File "/usr/share/vdsm/storage/sp.py", line 573, in create self._acquireTemporaryClusterLock(msdUUID, leaseParams) File "/usr/share/vdsm/storage/sp.py", line 515, in _acquireTemporaryClusterLock msd.acquireHostId(self.id) File "/usr/share/vdsm/storage/sd.py", line 467, in acquireHostId self._clusterLock.acquireHostId(hostId, async) File "/usr/share/vdsm/storage/clusterlock.py", line 199, in acquireHostId raise se.AcquireHostIdFailure(self._sdUUID, e) AcquireHostIdFailure: Cannot acquire host id: ('dc661957-c0c1-44ba-a5b9-e6558904207b', SanlockException(90, 'Sanlock lockspace add failure', 'Message too long')) Thread-13::DEBUG::2014-06-21 16:17:15,363::task::885::TaskManager.Task::(_run) Task=`d815e5e5-0202-4137-94be-21dc5e2b61c9`::Task._run: d815e5e5-0202-4137-94be-21dc5e2b61c9 (None, '806d2356-12cf-437c-8917-dd13ee823e36', 'testing', 'dc661957-c0c1-44ba-a5b9-e6558904207b', ['dc661957-c0c1-44ba-a5b9-e6558904207b'], 2, None, 5, 60, 10, 3) {} failed - stopping task Thread-13::DEBUG::2014-06-21 16:17:15,364::task::1211::TaskManager.Task::(stop) Task=`d815e5e5-0202-4137-94be-21dc5e2b61c9`::stopping in state preparing (force False) Thread-13::DEBUG::2014-06-21 16:17:15,364::task::990::TaskManager.Task::(_decref) Task=`d815e5e5-0202-4137-94be-21dc5e2b61c9`::ref 1 aborting True Thread-13::INFO::2014-06-21 16:17:15,365::task::1168::TaskManager.Task::(prepare) Task=`d815e5e5-0202-4137-94be-21dc5e2b61c9`::aborting: Task is aborted: 'Cannot acquire host id' - code 661 Thread-13::DEBUG::2014-06-21 16:17:15,365::task::1173::TaskManager.Task::(prepare) Task=`d815e5e5-0202-4137-94be-21dc5e2b61c9`::Prepare: aborted: Cannot acquire host id Thread-13::DEBUG::2014-06-21 16:17:15,365::task::990::TaskManager.Task::(_decref) Task=`d815e5e5-0202-4137-94be-21dc5e2b61c9`::ref 0 aborting True Thread-13::DEBUG::2014-06-21 16:17:15,366::task::925::TaskManager.Task::(_doAbort) Task=`d815e5e5-0202-4137-94be-21dc5e2b61c9`::Task._doAbort: force False Thread-13::DEBUG::2014-06-21 16:17:15,366::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-13::DEBUG::2014-06-21 16:17:15,366::task::595::TaskManager.Task::(_updateState) Task=`d815e5e5-0202-4137-94be-21dc5e2b61c9`::moving from state preparing -> state aborting Thread-13::DEBUG::2014-06-21 16:17:15,366::task::550::TaskManager.Task::(__state_aborting) Task=`d815e5e5-0202-4137-94be-21dc5e2b61c9`::_aborting: recover policy none Thread-13::DEBUG::2014-06-21 16:17:15,367::task::595::TaskManager.Task::(_updateState) Task=`d815e5e5-0202-4137-94be-21dc5e2b61c9`::moving from state aborting -> state failed Thread-13::DEBUG::2014-06-21 16:17:15,367::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.dc661957-c0c1-44ba-a5b9-e6558904207b': < ResourceRef 'Storage.dc661957-c0c1-44ba-a5b9-e6558904207b', isValid: 'True' obj: 'None'>, 'Storage.806d2356-12cf-437c-8917-dd13ee823e36': < ResourceRef 'Storage.806d2356-12cf-437c-8917-dd13ee823e36', isValid: 'True' obj: 'None'>} Thread-13::DEBUG::2014-06-21 16:17:15,367::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-13::DEBUG::2014-06-21 16:17:15,368::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.dc661957-c0c1-44ba-a5b9-e6558904207b' Thread-13::DEBUG::2014-06-21 16:17:15,369::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.dc661957-c0c1-44ba-a5b9-e6558904207b' (0 active users) Thread-13::DEBUG::2014-06-21 16:17:15,369::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.dc661957-c0c1-44ba-a5b9-e6558904207b' is free, finding out if anyone is waiting for it. Thread-13::DEBUG::2014-06-21 16:17:15,369::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.dc661957-c0c1-44ba-a5b9-e6558904207b', Clearing records. Thread-13::DEBUG::2014-06-21 16:17:15,370::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.806d2356-12cf-437c-8917-dd13ee823e36' Thread-13::DEBUG::2014-06-21 16:17:15,370::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.806d2356-12cf-437c-8917-dd13ee823e36' (0 active users) Thread-13::DEBUG::2014-06-21 16:17:15,370::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.806d2356-12cf-437c-8917-dd13ee823e36' is free, finding out if anyone is waiting for it. Thread-13::DEBUG::2014-06-21 16:17:15,371::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.806d2356-12cf-437c-8917-dd13ee823e36', Clearing records. Thread-13::ERROR::2014-06-21 16:17:15,371::dispatcher::65::Storage.Dispatcher.Protect::(run) {'status': {'message': "Cannot acquire host id: ('dc661957-c0c1-44ba-a5b9-e6558904207b', SanlockException(90, 'Sanlock lockspace add failure', 'Message too long'))", 'code': 661}} My oVirt version: 3.4.2-1.el6 (CentOS 6.5) The hypervisor hosts run GlusterFS 3.5.0-3.fc19.(Fedora 19) The two storage servers run GlusterFS 3.5.0-2.el6 (Centos 6.5) So I am NOT using local storage of the hypervisor hosts for the GlusterFS bricks. What can I do to solve this error?