I'm assuming that UUID shouldn't be zero's...
Thread-488::DEBUG::2013-10-15 17:17:07,316::BindingXMLRPC::177::vds::(wrapper) client [10.0.6.22]
Thread-488::DEBUG::2013-10-15 17:17:07,317::task::579::TaskManager.Task::(_updateState) Task=`6a1db668-e38b-4698-8a34-554f55182850`::moving from state init -> state preparing
Thread-488::INFO::2013-10-15 17:17:07,318::logUtils::44::dispatcher::(wrapper) Run and protect: connectStorageServer(domType=7, spUUID='00000000-0000-0000-0000-000000000000', conList=[{'port': '', 'connection': 'ovirt001:rep2-virt', 'iqn': '', 'portal': '', 'user': '', 'vfs_type': 'glusterfs', 'password': '******', 'id': '00000000-0000-0000-0000-000000000000'}], options=None)
Thread-488::DEBUG::2013-10-15 17:17:07,323::mount::226::Storage.Misc.excCmd::(_runcmd) '/usr/bin/sudo -n /usr/bin/mount -t glusterfs ovirt001:rep2-virt /rhev/data-center/mnt/glusterSD/ovirt001:rep2-virt' (cwd None)
Thread-488::DEBUG::2013-10-15 17:17:07,423::hsm::2333::Storage.HSM::(__prefetchDomains) glusterDomPath: glusterSD/*
Thread-488::DEBUG::2013-10-15 17:17:07,506::hsm::2345::Storage.HSM::(__prefetchDomains) Found SD uuids: ()
Thread-488::DEBUG::2013-10-15 17:17:07,507::hsm::2396::Storage.HSM::(connectStorageServer) knownSDs: {4a81a0e0-a95a-4e02-853f-68df420a7ce4: storage.glusterSD.findDomain}
Thread-488::INFO::2013-10-15 17:17:07,507::logUtils::47::dispatcher::(wrapper) Run and protect: connectStorageServer, Return response: {'statuslist': [{'status': 0, 'id': '00000000-0000-0000-0000-000000000000'}]}
Thread-488::DEBUG::2013-10-15 17:17:07,507::task::1168::TaskManager.Task::(prepare) Task=`6a1db668-e38b-4698-8a34-554f55182850`::finished: {'statuslist': [{'status': 0, 'id': '00000000-0000-0000-0000-000000000000'}]}
Thread-488::DEBUG::2013-10-15 17:17:07,507::task::579::TaskManager.Task::(_updateState) Task=`6a1db668-e38b-4698-8a34-554f55182850`::moving from state preparing -> state finished
Thread-488::DEBUG::2013-10-15 17:17:07,507::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-488::DEBUG::2013-10-15 17:17:07,508::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-488::DEBUG::2013-10-15 17:17:07,508::task::974::TaskManager.Task::(_decref) Task=`6a1db668-e38b-4698-8a34-554f55182850`::ref 0 aborting False
Thread-490::DEBUG::2013-10-15 17:17:07,709::BindingXMLRPC::177::vds::(wrapper) client [10.0.6.22]
Thread-490::DEBUG::2013-10-15 17:17:07,710::task::579::TaskManager.Task::(_updateState) Task=`95b7da65-b45f-4836-9103-b64c6b5fc15a`::moving from state init -> state preparing
Thread-490::INFO::2013-10-15 17:17:07,710::logUtils::44::dispatcher::(wrapper) Run and protect: createStorageDomain(storageType=7, sdUUID='636abf41-5133-4252-9aef-8a32ec10668e', domainName='rep2-virt', typeSpecificArg='ovirt001:rep2-virt', domClass=1, domVersion='3', options=None)
Thread-490::DEBUG::2013-10-15 17:17:07,710::misc::807::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
Thread-490::DEBUG::2013-10-15 17:17:07,710::misc::809::SamplingMethod::(__call__) Got in to sampling method
Thread-490::DEBUG::2013-10-15 17:17:07,711::misc::807::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
Thread-490::DEBUG::2013-10-15 17:17:07,711::misc::809::SamplingMethod::(__call__) Got in to sampling method
Thread-490::DEBUG::2013-10-15 17:17:07,711::iscsiadm::91::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
Thread-490::DEBUG::2013-10-15 17:17:07,727::iscsiadm::91::Storage.Misc.excCmd::(_runCmd) FAILED: <err> = 'iscsiadm: No session found.\n'; <rc> = 21
Thread-490::DEBUG::2013-10-15 17:17:07,727::misc::817::SamplingMethod::(__call__) Returning last result
Thread-490::DEBUG::2013-10-15 17:17:09,750::multipath::111::Storage.Misc.excCmd::(rescan) '/usr/bin/sudo -n /sbin/multipath' (cwd None)
Thread-490::DEBUG::2013-10-15 17:17:09,943::multipath::111::Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0
Thread-490::DEBUG::2013-10-15 17:17:09,944::lvm::483::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-490::DEBUG::2013-10-15 17:17:09,944::lvm::485::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-490::DEBUG::2013-10-15 17:17:09,944::lvm::494::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
Thread-490::DEBUG::2013-10-15 17:17:09,945::lvm::496::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
Thread-490::DEBUG::2013-10-15 17:17:09,945::lvm::514::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
Thread-490::DEBUG::2013-10-15 17:17:09,945::lvm::516::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
Thread-490::DEBUG::2013-10-15 17:17:09,945::misc::817::SamplingMethod::(__call__) Returning last result
Thread-490::ERROR::2013-10-15 17:17:09,945::sdc::137::Storage.StorageDomainCache::(_findDomain) looking for unfetched domain 636abf41-5133-4252-9aef-8a32ec10668e
Thread-490::ERROR::2013-10-15 17:17:09,945::sdc::154::Storage.StorageDomainCache::(_findUnfetchedDomain) looking for domain 636abf41-5133-4252-9aef-8a32ec10668e
Thread-490::DEBUG::2013-10-15 17:17:09,946::lvm::374::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
Thread-490::DEBUG::2013-10-15 17:17:09,947::lvm::311::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 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 636abf41-5133-4252-9aef-8a32ec10668e' (cwd None)
Thread-490::DEBUG::2013-10-15 17:17:09,974::lvm::311::Storage.Misc.excCmd::(cmd) FAILED: <err> = ' Volume group "636abf41-5133-4252-9aef-8a32ec10668e" not found\n'; <rc> = 5
Thread-490::WARNING::2013-10-15 17:17:09,975::lvm::379::Storage.LVM::(_reloadvgs) lvm vgs failed: 5 [] [' Volume group "636abf41-5133-4252-9aef-8a32ec10668e" not found']
Thread-490::DEBUG::2013-10-15 17:17:09,975::lvm::403::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
Thread-490::ERROR::2013-10-15 17:17:09,981::sdc::143::Storage.StorageDomainCache::(_findDomain) domain 636abf41-5133-4252-9aef-8a32ec10668e 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: ('636abf41-5133-4252-9aef-8a32ec10668e',)
Thread-490::INFO::2013-10-15 17:17:09,982::nfsSD::69::Storage.StorageDomain::(create) sdUUID=636abf41-5133-4252-9aef-8a32ec10668e domainName=rep2-virt remotePath=ovirt001:rep2-virt domClass=1
Thread-490::DEBUG::2013-10-15 17:17:10,104::persistentDict::192::Storage.PersistentDict::(__init__) Created a persistent dict with FileMetadataRW backend
Thread-490::DEBUG::2013-10-15 17:17:10,115::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=[]
Thread-490::WARNING::2013-10-15 17:17:10,115::persistentDict::256::Storage.PersistentDict::(refresh) data has no embedded checksum - trust it as it is
Thread-490::DEBUG::2013-10-15 17:17:10,115::persistentDict::167::Storage.PersistentDict::(transaction) Starting transaction
Thread-490::DEBUG::2013-10-15 17:17:10,115::persistentDict::173::Storage.PersistentDict::(transaction) Flushing changes
Thread-490::DEBUG::2013-10-15 17:17:10,115::persistentDict::299::Storage.PersistentDict::(flush) about to write lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=rep2-virt', 'IOOPTIMEOUTSEC=1', 'LEASERETRIES=3', 'LEASETIMESEC=5', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'POOL_UUID=', 'REMOTE_PATH=ovirt001:rep2-virt', 'ROLE=Regular', 'SDUUID=636abf41-5133-4252-9aef-8a32ec10668e', 'TYPE=GLUSTERFS', 'VERSION=3', '_SHA_CKSUM=a38d3de67a9f2b5bc3979eb5f4dfbce7d48986d7']
Thread-490::DEBUG::2013-10-15 17:17:10,119::persistentDict::175::Storage.PersistentDict::(transaction) Finished transaction
Thread-490::DEBUG::2013-10-15 17:17:10,122::fileSD::153::Storage.StorageDomain::(__init__) Reading domain in path /rhev/data-center/mnt/glusterSD/ovirt001:rep2-virt/636abf41-5133-4252-9aef-8a32ec10668e
Thread-490::DEBUG::2013-10-15 17:17:10,122::persistentDict::192::Storage.PersistentDict::(__init__) Created a persistent dict with FileMetadataRW backend
Thread-490::DEBUG::2013-10-15 17:17:10,133::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=rep2-virt', 'IOOPTIMEOUTSEC=1', 'LEASERETRIES=3', 'LEASETIMESEC=5', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'POOL_UUID=', 'REMOTE_PATH=ovirt001:rep2-virt', 'ROLE=Regular', 'SDUUID=636abf41-5133-4252-9aef-8a32ec10668e', 'TYPE=GLUSTERFS', 'VERSION=3', '_SHA_CKSUM=a38d3de67a9f2b5bc3979eb5f4dfbce7d48986d7']
Thread-490::DEBUG::2013-10-15 17:17:10,135::fileSD::535::Storage.StorageDomain::(imageGarbageCollector) Removing remnants of deleted images []
Thread-490::DEBUG::2013-10-15 17:17:10,136::resourceManager::420::ResourceManager::(registerNamespace) Registering namespace '636abf41-5133-4252-9aef-8a32ec10668e_imageNS'
Thread-490::DEBUG::2013-10-15 17:17:10,136::resourceManager::420::ResourceManager::(registerNamespace) Registering namespace '636abf41-5133-4252-9aef-8a32ec10668e_volumeNS'
Thread-490::DEBUG::2013-10-15 17:17:10,136::clusterlock::137::initSANLock::(initSANLock) Initializing SANLock for domain 636abf41-5133-4252-9aef-8a32ec10668e
Thread-490::ERROR::2013-10-15 17:17:10,731::clusterlock::145::initSANLock::(initSANLock) Cannot initialize SANLock for domain 636abf41-5133-4252-9aef-8a32ec10668e
Traceback (most recent call last):
File "/usr/share/vdsm/storage/clusterlock.py", line 140, in initSANLock
sanlock.init_lockspace(sdUUID, idsPath)
SanlockException: (22, 'Sanlock lockspace init failure', 'Invalid argument')
Thread-490::WARNING::2013-10-15 17:17:10,732::sd::428::Storage.StorageDomain::(initSPMlease) lease did not initialize successfully
Traceback (most recent call last):
File "/usr/share/vdsm/storage/sd.py", line 423, in initSPMlease
self._clusterLock.initLock()
File "/usr/share/vdsm/storage/clusterlock.py", line 163, in initLock
initSANLock(self._sdUUID, self._idsPath, self._leasesPath)
File "/usr/share/vdsm/storage/clusterlock.py", line 146, in initSANLock
raise se.ClusterLockInitError()
ClusterLockInitError: Could not initialize cluster lock: ()
Thread-490::DEBUG::2013-10-15 17:17:10,732::hsm::2624::Storage.HSM::(createStorageDomain) knownSDs: {636abf41-5133-4252-9aef-8a32ec10668e: storage.glusterSD.findDomain, 4a81a0e0-a95a-4e02-853f-68df420a7ce4: storage.glusterSD.findDomain}
Thread-490::INFO::2013-10-15 17:17:10,732::logUtils::47::dispatcher::(wrapper) Run and protect: createStorageDomain, Return response: None
Thread-490::DEBUG::2013-10-15 17:17:10,732::task::1168::TaskManager.Task::(prepare) Task=`95b7da65-b45f-4836-9103-b64c6b5fc15a`::finished: None
Thread-490::DEBUG::2013-10-15 17:17:10,733::task::579::TaskManager.Task::(_updateState) Task=`95b7da65-b45f-4836-9103-b64c6b5fc15a`::moving from state preparing -> state finished
Thread-490::DEBUG::2013-10-15 17:17:10,733::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-490::DEBUG::2013-10-15 17:17:10,733::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-490::DEBUG::2013-10-15 17:17:10,733::task::974::TaskManager.Task::(_decref) Task=`95b7da65-b45f-4836-9103-b64c6b5fc15a`::ref 0 aborting False
Thread-494::DEBUG::2013-10-15 17:17:10,739::BindingXMLRPC::177::vds::(wrapper) client [10.0.6.22]
Thread-494::DEBUG::2013-10-15 17:17:10,740::task::579::TaskManager.Task::(_updateState) Task=`7b5b467e-a1e5-413c-934d-18e337cf6dd8`::moving from state init -> state preparing
Thread-494::INFO::2013-10-15 17:17:10,740::logUtils::44::dispatcher::(wrapper) Run and protect: getStorageDomainStats(sdUUID='636abf41-5133-4252-9aef-8a32ec10668e', options=None)
Thread-494::DEBUG::2013-10-15 17:17:10,741::resourceManager::197::ResourceManager.Request::(__init__) ResName=`Storage.636abf41-5133-4252-9aef-8a32ec10668e`ReqID=`0602d0b9-a7ff-4f3f-80bd-c886fe4e3270`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2784' at 'getStorageDomainStats'
Thread-494::DEBUG::2013-10-15 17:17:10,741::resourceManager::541::ResourceManager::(registerResource) Trying to register resource 'Storage.636abf41-5133-4252-9aef-8a32ec10668e' for lock type 'shared'
Thread-494::DEBUG::2013-10-15 17:17:10,741::resourceManager::600::ResourceManager::(registerResource) Resource 'Storage.636abf41-5133-4252-9aef-8a32ec10668e' is free. Now locking as 'shared' (1 active user)
Thread-494::DEBUG::2013-10-15 17:17:10,741::resourceManager::237::ResourceManager.Request::(grant) ResName=`Storage.636abf41-5133-4252-9aef-8a32ec10668e`ReqID=`0602d0b9-a7ff-4f3f-80bd-c886fe4e3270`::Granted request
Thread-494::DEBUG::2013-10-15 17:17:10,742::task::811::TaskManager.Task::(resourceAcquired) Task=`7b5b467e-a1e5-413c-934d-18e337cf6dd8`::_resourcesAcquired: Storage.636abf41-5133-4252-9aef-8a32ec10668e (shared)
Thread-494::DEBUG::2013-10-15 17:17:10,742::task::974::TaskManager.Task::(_decref) Task=`7b5b467e-a1e5-413c-934d-18e337cf6dd8`::ref 1 aborting False
Thread-494::INFO::2013-10-15 17:17:10,743::logUtils::47::dispatcher::(wrapper) Run and protect: getStorageDomainStats, Return response: {'stats': {'mdasize': 0, 'mdathreshold': True, 'mdavalid': True, 'diskfree': '14144560824320', 'disktotal': '14199600185344', 'mdafree': 0}}
Thread-494::DEBUG::2013-10-15 17:17:10,744::task::1168::TaskManager.Task::(prepare) Task=`7b5b467e-a1e5-413c-934d-18e337cf6dd8`::finished: {'stats': {'mdasize': 0, 'mdathreshold': True, 'mdavalid': True, 'diskfree': '14144560824320', 'disktotal': '14199600185344', 'mdafree': 0}}
Thread-494::DEBUG::2013-10-15 17:17:10,744::task::579::TaskManager.Task::(_updateState) Task=`7b5b467e-a1e5-413c-934d-18e337cf6dd8`::moving from state preparing -> state finished
Thread-494::DEBUG::2013-10-15 17:17:10,744::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.636abf41-5133-4252-9aef-8a32ec10668e': < ResourceRef 'Storage.636abf41-5133-4252-9aef-8a32ec10668e', isValid: 'True' obj: 'None'>}
Thread-494::DEBUG::2013-10-15 17:17:10,744::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-494::DEBUG::2013-10-15 17:17:10,744::resourceManager::615::ResourceManager::(releaseResource) Trying to release resource 'Storage.636abf41-5133-4252-9aef-8a32ec10668e'
Thread-494::DEBUG::2013-10-15 17:17:10,745::resourceManager::634::ResourceManager::(releaseResource) Released resource 'Storage.636abf41-5133-4252-9aef-8a32ec10668e' (0 active users)
Thread-494::DEBUG::2013-10-15 17:17:10,745::resourceManager::640::ResourceManager::(releaseResource) Resource 'Storage.636abf41-5133-4252-9aef-8a32ec10668e' is free, finding out if anyone is waiting for it.
Thread-494::DEBUG::2013-10-15 17:17:10,745::resourceManager::648::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.636abf41-5133-4252-9aef-8a32ec10668e', Clearing records.
Thread-494::DEBUG::2013-10-15 17:17:10,745::task::974::TaskManager.Task::(_decref) Task=`7b5b467e-a1e5-413c-934d-18e337cf6dd8`::ref 0 aborting False
Thread-495::DEBUG::2013-10-15 17:17:11,113::BindingXMLRPC::177::vds::(wrapper) client [10.0.6.22]
Thread-495::DEBUG::2013-10-15 17:17:11,113::task::579::TaskManager.Task::(_updateState) Task=`d217edaf-c57b-4c28-aceb-5d68ec306531`::moving from state init -> state preparing
Thread-495::INFO::2013-10-15 17:17:11,114::logUtils::44::dispatcher::(wrapper) Run and protect: connectStorageServer(domType=7, spUUID='00000000-0000-0000-0000-000000000000', conList=[{'port': '', 'connection': 'ovirt001:rep2-virt', 'iqn': '', 'portal': '', 'user': '', 'vfs_type': 'glusterfs', 'password': '******', 'id': '648e518f-11eb-48d1-b7cd-64c7b7cf6204'}], options=None)
Thread-495::DEBUG::2013-10-15 17:17:11,119::hsm::2333::Storage.HSM::(__prefetchDomains) glusterDomPath: glusterSD/*
Thread-495::DEBUG::2013-10-15 17:17:11,125::hsm::2345::Storage.HSM::(__prefetchDomains) Found SD uuids: ('636abf41-5133-4252-9aef-8a32ec10668e',)
Thread-495::DEBUG::2013-10-15 17:17:11,126::hsm::2396::Storage.HSM::(connectStorageServer) knownSDs: {636abf41-5133-4252-9aef-8a32ec10668e: storage.glusterSD.findDomain, 4a81a0e0-a95a-4e02-853f-68df420a7ce4: storage.glusterSD.findDomain}
Thread-495::INFO::2013-10-15 17:17:11,126::logUtils::47::dispatcher::(wrapper) Run and protect: connectStorageServer, Return response: {'statuslist': [{'status': 0, 'id': '648e518f-11eb-48d1-b7cd-64c7b7cf6204'}]}
Thread-495::DEBUG::2013-10-15 17:17:11,126::task::1168::TaskManager.Task::(prepare) Task=`d217edaf-c57b-4c28-aceb-5d68ec306531`::finished: {'statuslist': [{'status': 0, 'id': '648e518f-11eb-48d1-b7cd-64c7b7cf6204'}]}
Thread-495::DEBUG::2013-10-15 17:17:11,126::task::579::TaskManager.Task::(_updateState) Task=`d217edaf-c57b-4c28-aceb-5d68ec306531`::moving from state preparing -> state finished
Thread-495::DEBUG::2013-10-15 17:17:11,126::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-495::DEBUG::2013-10-15 17:17:11,127::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-495::DEBUG::2013-10-15 17:17:11,127::task::974::TaskManager.Task::(_decref) Task=`d217edaf-c57b-4c28-aceb-5d68ec306531`::ref 0 aborting False
Thread-497::DEBUG::2013-10-15 17:17:11,133::BindingXMLRPC::177::vds::(wrapper) client [10.0.6.22]
Thread-497::DEBUG::2013-10-15 17:17:11,133::task::579::TaskManager.Task::(_updateState) Task=`e53f26ec-66b9-4f01-aa10-053a738780b8`::moving from state init -> state preparing
Thread-497::INFO::2013-10-15 17:17:11,134::logUtils::44::dispatcher::(wrapper) Run and protect: createStoragePool(poolType=None, spUUID='5849b030-626e-47cb-ad90-3ce782d831b3', poolName='Default', masterDom='636abf41-5133-4252-9aef-8a32ec10668e', domList=['636abf41-5133-4252-9aef-8a32ec10668e'], masterVersion=12, lockPolicy=None, lockRenewalIntervalSec=5, leaseTimeSec=60, ioOpTimeoutSec=10, leaseRetries=3, options=None)
Thread-497::INFO::2013-10-15 17:17:11,134::fileSD::315::Storage.StorageDomain::(validate) sdUUID=636abf41-5133-4252-9aef-8a32ec10668e
Thread-497::DEBUG::2013-10-15 17:17:11,144::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=rep2-virt', 'IOOPTIMEOUTSEC=1', 'LEASERETRIES=3', 'LEASETIMESEC=5', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'POOL_UUID=', 'REMOTE_PATH=ovirt001:rep2-virt', 'ROLE=Regular', 'SDUUID=636abf41-5133-4252-9aef-8a32ec10668e', 'TYPE=GLUSTERFS', 'VERSION=3', '_SHA_CKSUM=a38d3de67a9f2b5bc3979eb5f4dfbce7d48986d7']
Thread-497::DEBUG::2013-10-15 17:17:11,145::resourceManager::197::ResourceManager.Request::(__init__) ResName=`Storage.5849b030-626e-47cb-ad90-3ce782d831b3`ReqID=`938eb5db-1766-43df-8a91-ef34759cfc06`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '954' at 'createStoragePool'
Thread-497::DEBUG::2013-10-15 17:17:11,145::resourceManager::541::ResourceManager::(registerResource) Trying to register resource 'Storage.5849b030-626e-47cb-ad90-3ce782d831b3' for lock type 'exclusive'
Thread-497::DEBUG::2013-10-15 17:17:11,146::resourceManager::600::ResourceManager::(registerResource) Resource 'Storage.5849b030-626e-47cb-ad90-3ce782d831b3' is free. Now locking as 'exclusive' (1 active user)
Thread-497::DEBUG::2013-10-15 17:17:11,146::resourceManager::237::ResourceManager.Request::(grant) ResName=`Storage.5849b030-626e-47cb-ad90-3ce782d831b3`ReqID=`938eb5db-1766-43df-8a91-ef34759cfc06`::Granted request
Thread-497::DEBUG::2013-10-15 17:17:11,146::task::811::TaskManager.Task::(resourceAcquired) Task=`e53f26ec-66b9-4f01-aa10-053a738780b8`::_resourcesAcquired: Storage.5849b030-626e-47cb-ad90-3ce782d831b3 (exclusive)
Thread-497::DEBUG::2013-10-15 17:17:11,146::task::974::TaskManager.Task::(_decref) Task=`e53f26ec-66b9-4f01-aa10-053a738780b8`::ref 1 aborting False
Thread-497::DEBUG::2013-10-15 17:17:11,147::resourceManager::197::ResourceManager.Request::(__init__) ResName=`Storage.636abf41-5133-4252-9aef-8a32ec10668e`ReqID=`79bba45b-37b7-417f-bfbf-fc96603ed997`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '956' at 'createStoragePool'
Thread-497::DEBUG::2013-10-15 17:17:11,147::resourceManager::541::ResourceManager::(registerResource) Trying to register resource 'Storage.636abf41-5133-4252-9aef-8a32ec10668e' for lock type 'exclusive'
Thread-497::DEBUG::2013-10-15 17:17:11,147::resourceManager::600::ResourceManager::(registerResource) Resource 'Storage.636abf41-5133-4252-9aef-8a32ec10668e' is free. Now locking as 'exclusive' (1 active user)
Thread-497::DEBUG::2013-10-15 17:17:11,147::resourceManager::237::ResourceManager.Request::(grant) ResName=`Storage.636abf41-5133-4252-9aef-8a32ec10668e`ReqID=`79bba45b-37b7-417f-bfbf-fc96603ed997`::Granted request
Thread-497::DEBUG::2013-10-15 17:17:11,147::task::811::TaskManager.Task::(resourceAcquired) Task=`e53f26ec-66b9-4f01-aa10-053a738780b8`::_resourcesAcquired: Storage.636abf41-5133-4252-9aef-8a32ec10668e (exclusive)
Thread-497::DEBUG::2013-10-15 17:17:11,148::task::974::TaskManager.Task::(_decref) Task=`e53f26ec-66b9-4f01-aa10-053a738780b8`::ref 1 aborting False
Thread-497::INFO::2013-10-15 17:17:11,148::sp::592::Storage.StoragePool::(create) spUUID=5849b030-626e-47cb-ad90-3ce782d831b3 poolName=Default master_sd=636abf41-5133-4252-9aef-8a32ec10668e domList=['636abf41-5133-4252-9aef-8a32ec10668e'] masterVersion=12 {'LEASETIMESEC': 60, 'IOOPTIMEOUTSEC': 10, 'LEASERETRIES': 3, 'LOCKRENEWALINTERVALSEC': 5}
Thread-497::INFO::2013-10-15 17:17:11,148::fileSD::315::Storage.StorageDomain::(validate) sdUUID=636abf41-5133-4252-9aef-8a32ec10668e
Thread-497::DEBUG::2013-10-15 17:17:11,158::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=rep2-virt', 'IOOPTIMEOUTSEC=1', 'LEASERETRIES=3', 'LEASETIMESEC=5', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'POOL_UUID=', 'REMOTE_PATH=ovirt001:rep2-virt', 'ROLE=Regular', 'SDUUID=636abf41-5133-4252-9aef-8a32ec10668e', 'TYPE=GLUSTERFS', 'VERSION=3', '_SHA_CKSUM=a38d3de67a9f2b5bc3979eb5f4dfbce7d48986d7']
Thread-497::DEBUG::2013-10-15 17:17:11,168::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=rep2-virt', 'IOOPTIMEOUTSEC=1', 'LEASERETRIES=3', 'LEASETIMESEC=5', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'POOL_UUID=', 'REMOTE_PATH=ovirt001:rep2-virt', 'ROLE=Regular', 'SDUUID=636abf41-5133-4252-9aef-8a32ec10668e', 'TYPE=GLUSTERFS', 'VERSION=3', '_SHA_CKSUM=a38d3de67a9f2b5bc3979eb5f4dfbce7d48986d7']
Thread-497::WARNING::2013-10-15 17:17:11,168::fileUtils::167::Storage.fileUtils::(createdir) Dir /rhev/data-center/5849b030-626e-47cb-ad90-3ce782d831b3 already exists
Thread-497::DEBUG::2013-10-15 17:17:11,168::persistentDict::167::Storage.PersistentDict::(transaction) Starting transaction
Thread-497::DEBUG::2013-10-15 17:17:11,169::persistentDict::173::Storage.PersistentDict::(transaction) Flushing changes
Thread-497::DEBUG::2013-10-15 17:17:11,169::persistentDict::299::Storage.PersistentDict::(flush) about to write lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=rep2-virt', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=', 'LOCKRENEWALINTERVALSEC=5', 'POOL_UUID=', 'REMOTE_PATH=ovirt001:rep2-virt', 'ROLE=Regular', 'SDUUID=636abf41-5133-4252-9aef-8a32ec10668e', 'TYPE=GLUSTERFS', 'VERSION=3', '_SHA_CKSUM=acf2b6bfff3dc3de8e33a5b08af5fc959a01bddc']
Thread-497::DEBUG::2013-10-15 17:17:11,184::persistentDict::175::Storage.PersistentDict::(transaction) Finished transaction
Thread-497::INFO::2013-10-15 17:17:11,184::clusterlock::174::SANLock::(acquireHostId) Acquiring host id for domain 636abf41-5133-4252-9aef-8a32ec10668e (id: 250)
Thread-498::DEBUG::2013-10-15 17:17:11,697::task::579::TaskManager.Task::(_updateState) Task=`7f1a4313-262f-4458-96af-8e5a0d3626d1`::moving from state init -> state preparing
Thread-498::INFO::2013-10-15 17:17:11,698::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-498::INFO::2013-10-15 17:17:11,698::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-498::DEBUG::2013-10-15 17:17:11,698::task::1168::TaskManager.Task::(prepare) Task=`7f1a4313-262f-4458-96af-8e5a0d3626d1`::finished: {}
Thread-498::DEBUG::2013-10-15 17:17:11,698::task::579::TaskManager.Task::(_updateState) Task=`7f1a4313-262f-4458-96af-8e5a0d3626d1`::moving from state preparing -> state finished
Thread-498::DEBUG::2013-10-15 17:17:11,698::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-498::DEBUG::2013-10-15 17:17:11,698::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-498::DEBUG::2013-10-15 17:17:11,699::task::974::TaskManager.Task::(_decref) Task=`7f1a4313-262f-4458-96af-8e5a0d3626d1`::ref 0 aborting False
Thread-497::ERROR::2013-10-15 17:17:12,186::task::850::TaskManager.Task::(_setError) Task=`e53f26ec-66b9-4f01-aa10-053a738780b8`::Unexpected error
Traceback (most recent call last):
File "/usr/share/vdsm/storage/task.py", line 857, 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 960, in createStoragePool
masterVersion, leaseParams)
File "/usr/share/vdsm/storage/sp.py", line 617, in create
self._acquireTemporaryClusterLock(msdUUID, leaseParams)
File "/usr/share/vdsm/storage/sp.py", line 559, in _acquireTemporaryClusterLock
File "/usr/share/vdsm/storage/sd.py", line 458, in acquireHostId
self._clusterLock.acquireHostId(hostId, async)
File "/usr/share/vdsm/storage/clusterlock.py", line 189, in acquireHostId
raise se.AcquireHostIdFailure(self._sdUUID, e)
AcquireHostIdFailure: Cannot acquire host id: ('636abf41-5133-4252-9aef-8a32ec10668e', SanlockException(22, 'Sanlock lockspace add failure', 'Invalid argument'))
Thread-497::DEBUG::2013-10-15 17:17:12,186::task::869::TaskManager.Task::(_run) Task=`e53f26ec-66b9-4f01-aa10-053a738780b8`::Task._run: e53f26ec-66b9-4f01-aa10-053a738780b8 (None, '5849b030-626e-47cb-ad90-3ce782d831b3', 'Default', '636abf41-5133-4252-9aef-8a32ec10668e', ['636abf41-5133-4252-9aef-8a32ec10668e'], 12, None, 5, 60, 10, 3) {} failed - stopping task
Thread-497::DEBUG::2013-10-15 17:17:12,187::task::1194::TaskManager.Task::(stop) Task=`e53f26ec-66b9-4f01-aa10-053a738780b8`::stopping in state preparing (force False)
Thread-497::DEBUG::2013-10-15 17:17:12,187::task::974::TaskManager.Task::(_decref) Task=`e53f26ec-66b9-4f01-aa10-053a738780b8`::ref 1 aborting True
Thread-497::INFO::2013-10-15 17:17:12,187::task::1151::TaskManager.Task::(prepare) Task=`e53f26ec-66b9-4f01-aa10-053a738780b8`::aborting: Task is aborted: 'Cannot acquire host id' - code 661
Thread-497::DEBUG::2013-10-15 17:17:12,187::task::1156::TaskManager.Task::(prepare) Task=`e53f26ec-66b9-4f01-aa10-053a738780b8`::Prepare: aborted: Cannot acquire host id
Thread-497::DEBUG::2013-10-15 17:17:12,187::task::974::TaskManager.Task::(_decref) Task=`e53f26ec-66b9-4f01-aa10-053a738780b8`::ref 0 aborting True
Thread-497::DEBUG::2013-10-15 17:17:12,187::task::909::TaskManager.Task::(_doAbort) Task=`e53f26ec-66b9-4f01-aa10-053a738780b8`::Task._doAbort: force False
Thread-497::DEBUG::2013-10-15 17:17:12,188::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-497::DEBUG::2013-10-15 17:17:12,188::task::579::TaskManager.Task::(_updateState) Task=`e53f26ec-66b9-4f01-aa10-053a738780b8`::moving from state preparing -> state aborting
Thread-497::DEBUG::2013-10-15 17:17:12,188::task::534::TaskManager.Task::(__state_aborting) Task=`e53f26ec-66b9-4f01-aa10-053a738780b8`::_aborting: recover policy none
Thread-497::DEBUG::2013-10-15 17:17:12,188::task::579::TaskManager.Task::(_updateState) Task=`e53f26ec-66b9-4f01-aa10-053a738780b8`::moving from state aborting -> state failed
Thread-497::DEBUG::2013-10-15 17:17:12,188::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.5849b030-626e-47cb-ad90-3ce782d831b3': < ResourceRef 'Storage.5849b030-626e-47cb-ad90-3ce782d831b3', isValid: 'True' obj: 'None'>, 'Storage.636abf41-5133-4252-9aef-8a32ec10668e': < ResourceRef 'Storage.636abf41-5133-4252-9aef-8a32ec10668e', isValid: 'True' obj: 'None'>}
Thread-497::DEBUG::2013-10-15 17:17:12,188::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-497::DEBUG::2013-10-15 17:17:12,189::resourceManager::615::ResourceManager::(releaseResource) Trying to release resource 'Storage.5849b030-626e-47cb-ad90-3ce782d831b3'
Thread-497::DEBUG::2013-10-15 17:17:12,189::resourceManager::634::ResourceManager::(releaseResource) Released resource 'Storage.5849b030-626e-47cb-ad90-3ce782d831b3' (0 active users)
Thread-497::DEBUG::2013-10-15 17:17:12,189::resourceManager::640::ResourceManager::(releaseResource) Resource 'Storage.5849b030-626e-47cb-ad90-3ce782d831b3' is free, finding out if anyone is waiting for it.
Thread-497::DEBUG::2013-10-15 17:17:12,189::resourceManager::648::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.5849b030-626e-47cb-ad90-3ce782d831b3', Clearing records.
Thread-497::DEBUG::2013-10-15 17:17:12,189::resourceManager::615::ResourceManager::(releaseResource) Trying to release resource 'Storage.636abf41-5133-4252-9aef-8a32ec10668e'
Thread-497::DEBUG::2013-10-15 17:17:12,190::resourceManager::634::ResourceManager::(releaseResource) Released resource 'Storage.636abf41-5133-4252-9aef-8a32ec10668e' (0 active users)
Thread-497::DEBUG::2013-10-15 17:17:12,190::resourceManager::640::ResourceManager::(releaseResource) Resource 'Storage.636abf41-5133-4252-9aef-8a32ec10668e' is free, finding out if anyone is waiting for it.
Thread-497::DEBUG::2013-10-15 17:17:12,190::resourceManager::648::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.636abf41-5133-4252-9aef-8a32ec10668e', Clearing records.
Thread-497::ERROR::2013-10-15 17:17:12,190::dispatcher::67::Storage.Dispatcher.Protect::(run) {'status': {'message': "Cannot acquire host id: ('636abf41-5133-4252-9aef-8a32ec10668e', SanlockException(22, 'Sanlock lockspace add failure', 'Invalid argument'))", 'code': 661}}
Thread-504::DEBUG::2013-10-15 17:17:27,018::task::579::TaskManager.Task::(_updateState) Task=`4df542ea-0b2a-489a-b3d7-9299841ca2d6`::moving from state init -> state preparing
Thread-504::INFO::2013-10-15 17:17:27,019::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-504::INFO::2013-10-15 17:17:27,019::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-504::DEBUG::2013-10-15 17:17:27,019::task::1168::TaskManager.Task::(prepare) Task=`4df542ea-0b2a-489a-b3d7-9299841ca2d6`::finished: {}
Thread-504::DEBUG::2013-10-15 17:17:27,019::task::579::TaskManager.Task::(_updateState) Task=`4df542ea-0b2a-489a-b3d7-9299841ca2d6`::moving from state preparing -> state finished
Thread-504::DEBUG::2013-10-15 17:17:27,019::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-504::DEBUG::2013-10-15 17:17:27,019::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-504::DEBUG::2013-10-15 17:17:27,019::task::974::TaskManager.Task::(_decref) Task=`4df542ea-0b2a-489a-b3d7-9299841ca2d6`::ref 0 aborting False
Thread-510::DEBUG::2013-10-15 17:17:42,194::task::579::TaskManager.Task::(_updateState) Task=`03b081b7-430b-4207-9272-ba5785f63cb1`::moving from state init -> state preparing
Thread-510::INFO::2013-10-15 17:17:42,194::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-510::INFO::2013-10-15 17:17:42,194::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-510::DEBUG::2013-10-15 17:17:42,195::task::1168::TaskManager.Task::(prepare) Task=`03b081b7-430b-4207-9272-ba5785f63cb1`::finished: {}
Thread-510::DEBUG::2013-10-15 17:17:42,195::task::579::TaskManager.Task::(_updateState) Task=`03b081b7-430b-4207-9272-ba5785f63cb1`::moving from state preparing -> state finished
Thread-510::DEBUG::2013-10-15 17:17:42,195::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-510::DEBUG::2013-10-15 17:17:42,195::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-510::DEBUG::2013-10-15 17:17:42,195::task::974::TaskManager.Task::(_decref) Task=`03b081b7-430b-4207-9272-ba5785f63cb1`::ref 0 aborting False
Thread-516::DEBUG::2013-10-15 17:17:57,328::task::579::TaskManager.Task::(_updateState) Task=`535b1567-e5de-4a2d-9a34-080f3cea5de6`::moving from state init -> state preparing
Thread-516::INFO::2013-10-15 17:17:57,328::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)
Thread-516::INFO::2013-10-15 17:17:57,328::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {}
Thread-516::DEBUG::2013-10-15 17:17:57,328::task::1168::TaskManager.Task::(prepare) Task=`535b1567-e5de-4a2d-9a34-080f3cea5de6`::finished: {}
Thread-516::DEBUG::2013-10-15 17:17:57,329::task::579::TaskManager.Task::(_updateState) Task=`535b1567-e5de-4a2d-9a34-080f3cea5de6`::moving from state preparing -> state finished
Thread-516::DEBUG::2013-10-15 17:17:57,329::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
Thread-516::DEBUG::2013-10-15 17:17:57,329::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
Thread-516::DEBUG::2013-10-15 17:17:57,329::task::974::TaskManager.Task::(_decref) Task=`535b1567-e5de-4a2d-9a34-080f3cea5de6`::ref 0 aborting False