Attachment 918983 Details for Bug 1119828 – Vdsm log

Vdsm log

vdsm.log (text/x-log), 64.33 KB, created by Maël Lavault on 2014-07-18 07:29:39 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: Maël Lavault

Created: 2014-07-18 07:29:39 UTC

Size: 64.33 KB

patch

obsolete

>Thread-13::DEBUG::2014-07-18 09:24:59,116::BindingXMLRPC::1067::vds::(wrapper) client [127.0.0.1]::call getHardwareInfo with () {}
>Thread-13::DEBUG::2014-07-18 09:24:59,274::BindingXMLRPC::1074::vds::(wrapper) return getHardwareInfo with {'status': {'message': 'Done', 'code': 0}, 'info': {'systemProductName': 'H8QM8', 'systemSerialNumber': '1234567890', 'systemFamily': 'To Be Filled By O.E.M.', 'systemVersion': '1234567890', 'systemUUID': '00020003-0004-0005-0006-000700080009', 'systemManufacturer': 'Supermicro'}}
>Thread-15::DEBUG::2014-07-18 09:24:59,411::BindingXMLRPC::251::vds::(wrapper) client [127.0.0.1]
>Thread-15::DEBUG::2014-07-18 09:24:59,412::task::595::TaskManager.Task::(_updateState) Task=`97ddae91-99bc-4225-ac5c-7eb4e8f2c73e`::moving from state init -> state preparing
>Thread-15::INFO::2014-07-18 09:24:59,413::logUtils::44::dispatcher::(wrapper) Run and protect: getConnectedStoragePoolsList(options=None)
>Thread-15::INFO::2014-07-18 09:24:59,413::logUtils::47::dispatcher::(wrapper) Run and protect: getConnectedStoragePoolsList, Return response: {'poollist': []}
>Thread-15::DEBUG::2014-07-18 09:24:59,413::task::1185::TaskManager.Task::(prepare) Task=`97ddae91-99bc-4225-ac5c-7eb4e8f2c73e`::finished: {'poollist': []}
>Thread-15::DEBUG::2014-07-18 09:24:59,413::task::595::TaskManager.Task::(_updateState) Task=`97ddae91-99bc-4225-ac5c-7eb4e8f2c73e`::moving from state preparing -> state finished
>Thread-15::DEBUG::2014-07-18 09:24:59,413::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-15::DEBUG::2014-07-18 09:24:59,414::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-15::DEBUG::2014-07-18 09:24:59,414::task::990::TaskManager.Task::(_decref) Task=`97ddae91-99bc-4225-ac5c-7eb4e8f2c73e`::ref 0 aborting False
>Thread-16::DEBUG::2014-07-18 09:25:08,708::BindingXMLRPC::251::vds::(wrapper) client [127.0.0.1]
>Thread-16::DEBUG::2014-07-18 09:25:08,710::task::595::TaskManager.Task::(_updateState) Task=`f0ca26d1-7015-4387-9b0c-8b4055fff1ec`::moving from state init -> state preparing
>Thread-16::INFO::2014-07-18 09:25:08,711::logUtils::44::dispatcher::(wrapper) Run and protect: connectStorageServer(domType=1, spUUID='00000000-0000-0000-0000-000000000000', conList=[{'port': '', 'connection': 'gluster.voxtest.fr:/engine', 'iqn': '', 'portal': '', 'user': 'kvm', 'protocol_version': '3', 'password': '******', 'id': 'aa5a35d9-86b5-42d8-b51f-018f6d80bea0'}], options=None)
>Thread-16::DEBUG::2014-07-18 09:25:08,721::mount::202::Storage.Misc.excCmd::(_runcmd) '/usr/bin/sudo -n /bin/mount -t nfs -o soft,nosharecache,timeo=600,retrans=6,nfsvers=3 gluster.voxtest.fr:/engine /rhev/data-center/mnt/gluster.voxtest.fr:_engine' (cwd None)
>Thread-16::DEBUG::2014-07-18 09:25:09,440::hsm::2328::Storage.HSM::(__prefetchDomains) nfs local path: /rhev/data-center/mnt/gluster.voxtest.fr:_engine
>Thread-16::DEBUG::2014-07-18 09:25:09,445::hsm::2352::Storage.HSM::(__prefetchDomains) Found SD uuids: ('c58f4345-45e3-449e-937c-d02ffc443c5b',)
>Thread-16::DEBUG::2014-07-18 09:25:09,446::hsm::2408::Storage.HSM::(connectStorageServer) knownSDs: {c58f4345-45e3-449e-937c-d02ffc443c5b: storage.nfsSD.findDomain}
>Thread-16::INFO::2014-07-18 09:25:09,446::logUtils::47::dispatcher::(wrapper) Run and protect: connectStorageServer, Return response: {'statuslist': [{'status': 0, 'id': 'aa5a35d9-86b5-42d8-b51f-018f6d80bea0'}]}
>Thread-16::DEBUG::2014-07-18 09:25:09,457::task::1185::TaskManager.Task::(prepare) Task=`f0ca26d1-7015-4387-9b0c-8b4055fff1ec`::finished: {'statuslist': [{'status': 0, 'id': 'aa5a35d9-86b5-42d8-b51f-018f6d80bea0'}]}
>Thread-16::DEBUG::2014-07-18 09:25:09,457::task::595::TaskManager.Task::(_updateState) Task=`f0ca26d1-7015-4387-9b0c-8b4055fff1ec`::moving from state preparing -> state finished
>Thread-16::DEBUG::2014-07-18 09:25:09,457::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-16::DEBUG::2014-07-18 09:25:09,458::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-16::DEBUG::2014-07-18 09:25:09,458::task::990::TaskManager.Task::(_decref) Task=`f0ca26d1-7015-4387-9b0c-8b4055fff1ec`::ref 0 aborting False
>Thread-17::DEBUG::2014-07-18 09:25:09,518::BindingXMLRPC::251::vds::(wrapper) client [127.0.0.1]
>Thread-17::DEBUG::2014-07-18 09:25:09,519::task::595::TaskManager.Task::(_updateState) Task=`30aab2ec-bad1-49a7-b2d2-f07a713c797e`::moving from state init -> state preparing
>Thread-17::INFO::2014-07-18 09:25:09,520::logUtils::44::dispatcher::(wrapper) Run and protect: getStorageDomainsList(spUUID='00000000-0000-0000-0000-000000000000', domainClass=None, storageType=None, remotePath=None, options=None)
>Thread-17::DEBUG::2014-07-18 09:25:09,520::misc::756::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
>Thread-17::DEBUG::2014-07-18 09:25:09,520::misc::758::SamplingMethod::(__call__) Got in to sampling method
>Thread-17::DEBUG::2014-07-18 09:25:09,521::misc::756::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
>Thread-17::DEBUG::2014-07-18 09:25:09,521::misc::758::SamplingMethod::(__call__) Got in to sampling method
>Thread-17::DEBUG::2014-07-18 09:25:09,521::iscsi::407::Storage.ISCSI::(rescan) Performing SCSI scan, this will take up to 30 seconds
>Thread-17::DEBUG::2014-07-18 09:25:09,522::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
>Thread-17::DEBUG::2014-07-18 09:25:09,549::misc::766::SamplingMethod::(__call__) Returning last result
>Thread-17::DEBUG::2014-07-18 09:25:09,550::multipath::110::Storage.Misc.excCmd::(rescan) '/usr/bin/sudo -n /sbin/multipath -r' (cwd None)
>Thread-17::DEBUG::2014-07-18 09:25:09,729::multipath::110::Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0
>Thread-17::DEBUG::2014-07-18 09:25:09,731::lvm::497::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-17::DEBUG::2014-07-18 09:25:09,731::lvm::499::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-17::DEBUG::2014-07-18 09:25:09,731::lvm::508::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-17::DEBUG::2014-07-18 09:25:09,732::lvm::510::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-17::DEBUG::2014-07-18 09:25:09,732::lvm::528::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-17::DEBUG::2014-07-18 09:25:09,732::lvm::530::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-17::DEBUG::2014-07-18 09:25:09,733::misc::766::SamplingMethod::(__call__) Returning last result
>Thread-17::DEBUG::2014-07-18 09:25:09,733::lvm::373::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
>Thread-17::DEBUG::2014-07-18 09:25:09,735::lvm::296::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  use_lvmetad=0 }  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' (cwd None)
>Thread-17::DEBUG::2014-07-18 09:25:10,143::lvm::296::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = '  No volume groups found\n'; <rc> = 0
>Thread-17::DEBUG::2014-07-18 09:25:10,144::lvm::415::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
>Thread-17::DEBUG::2014-07-18 09:25:10,377::fileSD::150::Storage.StorageDomain::(__init__) Reading domain in path /rhev/data-center/mnt/gluster.voxtest.fr:_engine/c58f4345-45e3-449e-937c-d02ffc443c5b
>Thread-17::DEBUG::2014-07-18 09:25:10,591::persistentDict::192::Storage.PersistentDict::(__init__) Created a persistent dict with FileMetadataRW backend
>Thread-17::DEBUG::2014-07-18 09:25:10,618::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=hosted_storage', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=ON', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=1', 'POOL_DESCRIPTION=hosted_datacenter', 'POOL_DOMAINS=c58f4345-45e3-449e-937c-d02ffc443c5b:Active', 'POOL_SPM_ID=-1', 'POOL_SPM_LVER=0', 'POOL_UUID=9a371fa0-c27d-4a3e-a35f-1a9fb1960b7f', 'REMOTE_PATH=gluster.voxtest.fr:/engine', 'ROLE=Master', 'SDUUID=c58f4345-45e3-449e-937c-d02ffc443c5b', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=851bdb258bbf1071232a6de6288b6a2ffd8c8154']
>Thread-17::DEBUG::2014-07-18 09:25:10,641::fileSD::609::Storage.StorageDomain::(imageGarbageCollector) Removing remnants of deleted images []
>Thread-17::DEBUG::2014-07-18 09:25:10,642::resourceManager::421::ResourceManager::(registerNamespace) Registering namespace 'c58f4345-45e3-449e-937c-d02ffc443c5b_imageNS'
>Thread-17::DEBUG::2014-07-18 09:25:10,642::resourceManager::421::ResourceManager::(registerNamespace) Registering namespace 'c58f4345-45e3-449e-937c-d02ffc443c5b_volumeNS'
>Thread-17::INFO::2014-07-18 09:25:10,643::logUtils::47::dispatcher::(wrapper) Run and protect: getStorageDomainsList, Return response: {'domlist': ['c58f4345-45e3-449e-937c-d02ffc443c5b']}
>Thread-17::DEBUG::2014-07-18 09:25:10,643::task::1185::TaskManager.Task::(prepare) Task=`30aab2ec-bad1-49a7-b2d2-f07a713c797e`::finished: {'domlist': ['c58f4345-45e3-449e-937c-d02ffc443c5b']}
>Thread-17::DEBUG::2014-07-18 09:25:10,644::task::595::TaskManager.Task::(_updateState) Task=`30aab2ec-bad1-49a7-b2d2-f07a713c797e`::moving from state preparing -> state finished
>Thread-17::DEBUG::2014-07-18 09:25:10,644::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-17::DEBUG::2014-07-18 09:25:10,644::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-17::DEBUG::2014-07-18 09:25:10,645::task::990::TaskManager.Task::(_decref) Task=`30aab2ec-bad1-49a7-b2d2-f07a713c797e`::ref 0 aborting False
>Thread-20::DEBUG::2014-07-18 09:25:10,714::BindingXMLRPC::251::vds::(wrapper) client [127.0.0.1]
>Thread-20::DEBUG::2014-07-18 09:25:10,715::task::595::TaskManager.Task::(_updateState) Task=`df1c0bfc-a696-4694-a269-238fba74df3f`::moving from state init -> state preparing
>Thread-20::INFO::2014-07-18 09:25:10,716::logUtils::44::dispatcher::(wrapper) Run and protect: getStorageDomainInfo(sdUUID='c58f4345-45e3-449e-937c-d02ffc443c5b', options=None)
>Thread-20::INFO::2014-07-18 09:25:10,716::fileSD::350::Storage.StorageDomain::(validate) sdUUID=c58f4345-45e3-449e-937c-d02ffc443c5b
>Thread-20::DEBUG::2014-07-18 09:25:10,723::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=hosted_storage', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=ON', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=1', 'POOL_DESCRIPTION=hosted_datacenter', 'POOL_DOMAINS=c58f4345-45e3-449e-937c-d02ffc443c5b:Active', 'POOL_SPM_ID=-1', 'POOL_SPM_LVER=0', 'POOL_UUID=9a371fa0-c27d-4a3e-a35f-1a9fb1960b7f', 'REMOTE_PATH=gluster.voxtest.fr:/engine', 'ROLE=Master', 'SDUUID=c58f4345-45e3-449e-937c-d02ffc443c5b', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=851bdb258bbf1071232a6de6288b6a2ffd8c8154']
>Thread-20::DEBUG::2014-07-18 09:25:10,724::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.c58f4345-45e3-449e-937c-d02ffc443c5b`ReqID=`35dff09a-6c1b-4604-a51e-f419938bdbf8`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2768' at 'getStorageDomainInfo'
>Thread-20::DEBUG::2014-07-18 09:25:10,725::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.c58f4345-45e3-449e-937c-d02ffc443c5b' for lock type 'shared'
>Thread-20::DEBUG::2014-07-18 09:25:10,725::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.c58f4345-45e3-449e-937c-d02ffc443c5b' is free. Now locking as 'shared' (1 active user)
>Thread-20::DEBUG::2014-07-18 09:25:10,725::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.c58f4345-45e3-449e-937c-d02ffc443c5b`ReqID=`35dff09a-6c1b-4604-a51e-f419938bdbf8`::Granted request
>Thread-20::DEBUG::2014-07-18 09:25:10,726::task::827::TaskManager.Task::(resourceAcquired) Task=`df1c0bfc-a696-4694-a269-238fba74df3f`::_resourcesAcquired: Storage.c58f4345-45e3-449e-937c-d02ffc443c5b (shared)
>Thread-20::DEBUG::2014-07-18 09:25:10,726::task::990::TaskManager.Task::(_decref) Task=`df1c0bfc-a696-4694-a269-238fba74df3f`::ref 1 aborting False
>Thread-20::INFO::2014-07-18 09:25:10,730::logUtils::47::dispatcher::(wrapper) Run and protect: getStorageDomainInfo, Return response: {'info': {'uuid': 'c58f4345-45e3-449e-937c-d02ffc443c5b', 'version': '3', 'role': 'Master', 'remotePath': 'gluster.voxtest.fr:/engine', 'type': 'NFS', 'class': 'Data', 'pool': ['9a371fa0-c27d-4a3e-a35f-1a9fb1960b7f'], 'name': 'hosted_storage'}}
>Thread-20::DEBUG::2014-07-18 09:25:10,730::task::1185::TaskManager.Task::(prepare) Task=`df1c0bfc-a696-4694-a269-238fba74df3f`::finished: {'info': {'uuid': 'c58f4345-45e3-449e-937c-d02ffc443c5b', 'version': '3', 'role': 'Master', 'remotePath': 'gluster.voxtest.fr:/engine', 'type': 'NFS', 'class': 'Data', 'pool': ['9a371fa0-c27d-4a3e-a35f-1a9fb1960b7f'], 'name': 'hosted_storage'}}
>Thread-20::DEBUG::2014-07-18 09:25:10,731::task::595::TaskManager.Task::(_updateState) Task=`df1c0bfc-a696-4694-a269-238fba74df3f`::moving from state preparing -> state finished
>Thread-20::DEBUG::2014-07-18 09:25:10,731::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.c58f4345-45e3-449e-937c-d02ffc443c5b': < ResourceRef 'Storage.c58f4345-45e3-449e-937c-d02ffc443c5b', isValid: 'True' obj: 'None'>}
>Thread-20::DEBUG::2014-07-18 09:25:10,731::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-20::DEBUG::2014-07-18 09:25:10,732::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.c58f4345-45e3-449e-937c-d02ffc443c5b'
>Thread-20::DEBUG::2014-07-18 09:25:10,732::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.c58f4345-45e3-449e-937c-d02ffc443c5b' (0 active users)
>Thread-20::DEBUG::2014-07-18 09:25:10,732::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.c58f4345-45e3-449e-937c-d02ffc443c5b' is free, finding out if anyone is waiting for it.
>Thread-20::DEBUG::2014-07-18 09:25:10,732::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.c58f4345-45e3-449e-937c-d02ffc443c5b', Clearing records.
>Thread-20::DEBUG::2014-07-18 09:25:10,733::task::990::TaskManager.Task::(_decref) Task=`df1c0bfc-a696-4694-a269-238fba74df3f`::ref 0 aborting False
>Thread-21::DEBUG::2014-07-18 09:25:13,325::BindingXMLRPC::251::vds::(wrapper) client [127.0.0.1]
>Thread-21::DEBUG::2014-07-18 09:25:13,326::task::595::TaskManager.Task::(_updateState) Task=`709028ba-cbba-4511-b22b-0c1e87510ff7`::moving from state init -> state preparing
>Thread-21::INFO::2014-07-18 09:25:13,326::logUtils::44::dispatcher::(wrapper) Run and protect: connectStoragePool(spUUID='9a371fa0-c27d-4a3e-a35f-1a9fb1960b7f', hostID=2, msdUUID='c58f4345-45e3-449e-937c-d02ffc443c5b', masterVersion=1, domainsMap=None, options=None)
>Thread-21::DEBUG::2014-07-18 09:25:13,327::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.HsmDomainMonitorLock`ReqID=`790f9712-017f-4925-a943-90346ed76609`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '1018' at 'connectStoragePool'
>Thread-21::DEBUG::2014-07-18 09:25:13,327::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.HsmDomainMonitorLock' for lock type 'exclusive'
>Thread-21::DEBUG::2014-07-18 09:25:13,328::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.HsmDomainMonitorLock' is free. Now locking as 'exclusive' (1 active user)
>Thread-21::DEBUG::2014-07-18 09:25:13,328::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.HsmDomainMonitorLock`ReqID=`790f9712-017f-4925-a943-90346ed76609`::Granted request
>Thread-21::DEBUG::2014-07-18 09:25:13,329::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.9a371fa0-c27d-4a3e-a35f-1a9fb1960b7f`ReqID=`95d010dd-d019-47bd-8342-d27023588dae`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '1066' at '_connectStoragePool'
>Thread-21::DEBUG::2014-07-18 09:25:13,329::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.9a371fa0-c27d-4a3e-a35f-1a9fb1960b7f' for lock type 'exclusive'
>Thread-21::DEBUG::2014-07-18 09:25:13,329::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.9a371fa0-c27d-4a3e-a35f-1a9fb1960b7f' is free. Now locking as 'exclusive' (1 active user)
>Thread-21::DEBUG::2014-07-18 09:25:13,329::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.9a371fa0-c27d-4a3e-a35f-1a9fb1960b7f`ReqID=`95d010dd-d019-47bd-8342-d27023588dae`::Granted request
>Thread-21::INFO::2014-07-18 09:25:13,330::sp::133::Storage.StoragePool::(setBackend) updating pool 9a371fa0-c27d-4a3e-a35f-1a9fb1960b7f backend from type NoneType instance 0x7fe15c191210 to type StoragePoolDiskBackend instance 0x7fe1080cf638
>Thread-21::INFO::2014-07-18 09:25:13,330::sp::623::Storage.StoragePool::(connect) Connect host #2 to the storage pool 9a371fa0-c27d-4a3e-a35f-1a9fb1960b7f with master domain: c58f4345-45e3-449e-937c-d02ffc443c5b (ver = 1)
>Thread-21::DEBUG::2014-07-18 09:25:13,331::lvm::497::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-21::DEBUG::2014-07-18 09:25:13,331::lvm::499::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-21::DEBUG::2014-07-18 09:25:13,331::lvm::508::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-21::DEBUG::2014-07-18 09:25:13,331::lvm::510::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-21::DEBUG::2014-07-18 09:25:13,332::lvm::528::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-21::DEBUG::2014-07-18 09:25:13,332::lvm::530::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-21::DEBUG::2014-07-18 09:25:13,332::misc::756::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
>Thread-21::DEBUG::2014-07-18 09:25:13,333::misc::758::SamplingMethod::(__call__) Got in to sampling method
>Thread-21::DEBUG::2014-07-18 09:25:13,333::misc::756::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
>Thread-21::DEBUG::2014-07-18 09:25:13,333::misc::758::SamplingMethod::(__call__) Got in to sampling method
>Thread-21::DEBUG::2014-07-18 09:25:13,333::iscsi::407::Storage.ISCSI::(rescan) Performing SCSI scan, this will take up to 30 seconds
>Thread-21::DEBUG::2014-07-18 09:25:13,334::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
>Thread-21::DEBUG::2014-07-18 09:25:13,359::misc::766::SamplingMethod::(__call__) Returning last result
>Thread-21::DEBUG::2014-07-18 09:25:13,360::multipath::110::Storage.Misc.excCmd::(rescan) '/usr/bin/sudo -n /sbin/multipath -r' (cwd None)
>Thread-21::DEBUG::2014-07-18 09:25:13,434::multipath::110::Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0
>Thread-21::DEBUG::2014-07-18 09:25:13,435::lvm::497::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-21::DEBUG::2014-07-18 09:25:13,436::lvm::499::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-21::DEBUG::2014-07-18 09:25:13,436::lvm::508::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-21::DEBUG::2014-07-18 09:25:13,436::lvm::510::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-21::DEBUG::2014-07-18 09:25:13,437::lvm::528::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
>Thread-21::DEBUG::2014-07-18 09:25:13,437::lvm::530::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
>Thread-21::DEBUG::2014-07-18 09:25:13,437::misc::766::SamplingMethod::(__call__) Returning last result
>Thread-21::DEBUG::2014-07-18 09:25:13,446::fileSD::150::Storage.StorageDomain::(__init__) Reading domain in path /rhev/data-center/mnt/gluster.voxtest.fr:_engine/c58f4345-45e3-449e-937c-d02ffc443c5b
>Thread-21::DEBUG::2014-07-18 09:25:13,448::persistentDict::192::Storage.PersistentDict::(__init__) Created a persistent dict with FileMetadataRW backend
>Thread-21::DEBUG::2014-07-18 09:25:13,454::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=hosted_storage', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=ON', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=1', 'POOL_DESCRIPTION=hosted_datacenter', 'POOL_DOMAINS=c58f4345-45e3-449e-937c-d02ffc443c5b:Active', 'POOL_SPM_ID=-1', 'POOL_SPM_LVER=0', 'POOL_UUID=9a371fa0-c27d-4a3e-a35f-1a9fb1960b7f', 'REMOTE_PATH=gluster.voxtest.fr:/engine', 'ROLE=Master', 'SDUUID=c58f4345-45e3-449e-937c-d02ffc443c5b', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=851bdb258bbf1071232a6de6288b6a2ffd8c8154']
>Thread-21::DEBUG::2014-07-18 09:25:13,457::fileSD::609::Storage.StorageDomain::(imageGarbageCollector) Removing remnants of deleted images []
>Thread-21::INFO::2014-07-18 09:25:13,457::sd::383::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace c58f4345-45e3-449e-937c-d02ffc443c5b_imageNS already registered
>Thread-21::INFO::2014-07-18 09:25:13,457::sd::391::Storage.StorageDomain::(_registerResourceNamespaces) Resource namespace c58f4345-45e3-449e-937c-d02ffc443c5b_volumeNS already registered
>Thread-21::DEBUG::2014-07-18 09:25:13,458::sp::1375::Storage.StoragePool::(setMasterDomain) Master domain c58f4345-45e3-449e-937c-d02ffc443c5b verified, version 1
>Thread-21::DEBUG::2014-07-18 09:25:13,458::misc::756::SamplingMethod::(__call__) Trying to enter sampling method (storage.sp.updateMonitoringThreads)
>Thread-21::DEBUG::2014-07-18 09:25:13,458::misc::758::SamplingMethod::(__call__) Got in to sampling method
>Thread-21::DEBUG::2014-07-18 09:25:13,464::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=hosted_storage', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=ON', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=1', 'POOL_DESCRIPTION=hosted_datacenter', 'POOL_DOMAINS=c58f4345-45e3-449e-937c-d02ffc443c5b:Active', 'POOL_SPM_ID=-1', 'POOL_SPM_LVER=0', 'POOL_UUID=9a371fa0-c27d-4a3e-a35f-1a9fb1960b7f', 'REMOTE_PATH=gluster.voxtest.fr:/engine', 'ROLE=Master', 'SDUUID=c58f4345-45e3-449e-937c-d02ffc443c5b', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=851bdb258bbf1071232a6de6288b6a2ffd8c8154']
>Thread-21::INFO::2014-07-18 09:25:13,465::domainMonitor::99::Storage.DomainMonitor::(startMonitoring) Start monitoring c58f4345-45e3-449e-937c-d02ffc443c5b
>Thread-21::DEBUG::2014-07-18 09:25:13,466::sp::1404::Storage.StoragePool::(updateMonitoringThreads) Storage Pool `9a371fa0-c27d-4a3e-a35f-1a9fb1960b7f` started monitoring domain `c58f4345-45e3-449e-937c-d02ffc443c5b`
>Thread-23::DEBUG::2014-07-18 09:25:13,466::domainMonitor::165::Storage.DomainMonitorThread::(_monitorLoop) Starting domain monitor for c58f4345-45e3-449e-937c-d02ffc443c5b
>Thread-21::DEBUG::2014-07-18 09:25:13,467::misc::766::SamplingMethod::(__call__) Returning last result
>Thread-21::DEBUG::2014-07-18 09:25:13,496::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=hosted_storage', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=ON', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=1', 'POOL_DESCRIPTION=hosted_datacenter', 'POOL_DOMAINS=c58f4345-45e3-449e-937c-d02ffc443c5b:Active', 'POOL_SPM_ID=-1', 'POOL_SPM_LVER=0', 'POOL_UUID=9a371fa0-c27d-4a3e-a35f-1a9fb1960b7f', 'REMOTE_PATH=gluster.voxtest.fr:/engine', 'ROLE=Master', 'SDUUID=c58f4345-45e3-449e-937c-d02ffc443c5b', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=851bdb258bbf1071232a6de6288b6a2ffd8c8154']
>Thread-21::DEBUG::2014-07-18 09:25:13,498::lvm::373::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
>Thread-21::DEBUG::2014-07-18 09:25:13,500::lvm::296::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  use_lvmetad=0 }  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' (cwd None)
>Thread-23::DEBUG::2014-07-18 09:25:13,690::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/gluster.voxtest.fr:_engine/c58f4345-45e3-449e-937c-d02ffc443c5b/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-23::DEBUG::2014-07-18 09:25:13,707::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n479 bytes (479 B) copied, 0.00101316 s, 473 kB/s\n'; <rc> = 0
>Thread-23::DEBUG::2014-07-18 09:25:13,758::domainMonitor::247::Storage.DomainMonitorThread::(_monitorDomain) Domain c58f4345-45e3-449e-937c-d02ffc443c5b changed its status to Valid
>Thread-24::DEBUG::2014-07-18 09:25:13,760::misc::878::Event.Storage.DomainMonitor.onDomainStateChange::(_emit) Emitting event
>Thread-23::INFO::2014-07-18 09:25:13,760::clusterlock::184::SANLock::(acquireHostId) Acquiring host id for domain c58f4345-45e3-449e-937c-d02ffc443c5b (id: 2)
>Thread-24::DEBUG::2014-07-18 09:25:13,762::misc::888::Event.Storage.DomainMonitor.onDomainStateChange::(_emit) Calling registered method `_onDomainStateChange`
>Thread-23::DEBUG::2014-07-18 09:25:13,763::clusterlock::202::SANLock::(acquireHostId) Host id for domain c58f4345-45e3-449e-937c-d02ffc443c5b successfully acquired (id: 2)
>Thread-24::DEBUG::2014-07-18 09:25:13,764::misc::888::Event.Storage.DomainMonitor.onDomainStateChange::(_emit) Calling registered method `contEIOVms`
>Thread-24::DEBUG::2014-07-18 09:25:13,768::misc::898::Event.Storage.DomainMonitor.onDomainStateChange::(_emit) Event emitted
>Thread-26::INFO::2014-07-18 09:25:13,769::clientIF::126::vds::(contEIOVms) vmContainerLock acquired
>Thread-21::DEBUG::2014-07-18 09:25:13,837::lvm::296::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = '  No volume groups found\n'; <rc> = 0
>Thread-21::DEBUG::2014-07-18 09:25:13,838::lvm::415::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
>Thread-21::INFO::2014-07-18 09:25:13,841::sp::1113::Storage.StoragePool::(_linkStorageDomain) Linking /rhev/data-center/mnt/gluster.voxtest.fr:_engine/c58f4345-45e3-449e-937c-d02ffc443c5b to /rhev/data-center/9a371fa0-c27d-4a3e-a35f-1a9fb1960b7f/c58f4345-45e3-449e-937c-d02ffc443c5b
>Thread-21::INFO::2014-07-18 09:25:13,843::sp::1113::Storage.StoragePool::(_linkStorageDomain) Linking /rhev/data-center/mnt/gluster.voxtest.fr:_engine/c58f4345-45e3-449e-937c-d02ffc443c5b to /rhev/data-center/9a371fa0-c27d-4a3e-a35f-1a9fb1960b7f/mastersd
>Thread-21::DEBUG::2014-07-18 09:25:13,860::threadPool::35::Misc.ThreadPool::(__init__) Enter - numThreads: 5.0, waitTimeout: 3, maxTasks: 500.0
>Thread-21::DEBUG::2014-07-18 09:25:13,866::storage_mailbox::84::Storage.Misc.excCmd::(_mboxExecCmd) '/bin/dd if=/rhev/data-center/9a371fa0-c27d-4a3e-a35f-1a9fb1960b7f/mastersd/dom_md/outbox iflag=direct,fullblock bs=512 count=8 skip=16' (cwd None)
>Thread-21::DEBUG::2014-07-18 09:25:13,895::storage_mailbox::84::Storage.Misc.excCmd::(_mboxExecCmd) SUCCESS: <err> = '8+0 records in\n8+0 records out\n4096 bytes (4.1 kB) copied, 0.0102709 s, 399 kB/s\n'; <rc> = 0
>Thread-21::INFO::2014-07-18 09:25:13,896::storage_mailbox::385::Storage.MailBox.HsmMailMonitor::(_sendMail) HSM_MailMonitor sending mail to SPM - ['/bin/dd', 'of=/rhev/data-center/9a371fa0-c27d-4a3e-a35f-1a9fb1960b7f/mastersd/dom_md/inbox', 'iflag=fullblock', 'oflag=direct', 'conv=notrunc', 'bs=512', 'seek=16']
>Thread-21::DEBUG::2014-07-18 09:25:13,896::storage_mailbox::84::Storage.Misc.excCmd::(_mboxExecCmd) '/bin/dd of=/rhev/data-center/9a371fa0-c27d-4a3e-a35f-1a9fb1960b7f/mastersd/dom_md/inbox iflag=fullblock oflag=direct conv=notrunc bs=512 seek=16' (cwd None)
>Thread-21::DEBUG::2014-07-18 09:25:14,096::storage_mailbox::84::Storage.Misc.excCmd::(_mboxExecCmd) SUCCESS: <err> = '8+0 records in\n8+0 records out\n4096 bytes (4.1 kB) copied, 0.181437 s, 22.6 kB/s\n'; <rc> = 0
>Thread-21::DEBUG::2014-07-18 09:25:14,097::storage_mailbox::207::Storage.Mailbox.HSM::(__init__) HSM_MailboxMonitor created for pool 9a371fa0-c27d-4a3e-a35f-1a9fb1960b7f
>Thread-21::DEBUG::2014-07-18 09:25:14,098::sp::465::Storage.StoragePool::(__createMailboxMonitor) HSM mailbox ready for pool 9a371fa0-c27d-4a3e-a35f-1a9fb1960b7f on master domain c58f4345-45e3-449e-937c-d02ffc443c5b
>Thread-21::DEBUG::2014-07-18 09:25:14,098::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.9a371fa0-c27d-4a3e-a35f-1a9fb1960b7f'
>Thread-21::DEBUG::2014-07-18 09:25:14,099::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.9a371fa0-c27d-4a3e-a35f-1a9fb1960b7f' (0 active users)
>Thread-21::DEBUG::2014-07-18 09:25:14,099::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.9a371fa0-c27d-4a3e-a35f-1a9fb1960b7f' is free, finding out if anyone is waiting for it.
>Thread-21::DEBUG::2014-07-18 09:25:14,099::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.9a371fa0-c27d-4a3e-a35f-1a9fb1960b7f', Clearing records.
>Thread-21::DEBUG::2014-07-18 09:25:14,100::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.HsmDomainMonitorLock'
>Thread-21::DEBUG::2014-07-18 09:25:14,100::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.HsmDomainMonitorLock' (0 active users)
>Thread-21::DEBUG::2014-07-18 09:25:14,100::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.HsmDomainMonitorLock' is free, finding out if anyone is waiting for it.
>Thread-21::DEBUG::2014-07-18 09:25:14,101::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.HsmDomainMonitorLock', Clearing records.
>Thread-21::INFO::2014-07-18 09:25:14,101::logUtils::47::dispatcher::(wrapper) Run and protect: connectStoragePool, Return response: True
>Thread-21::DEBUG::2014-07-18 09:25:14,101::task::1185::TaskManager.Task::(prepare) Task=`709028ba-cbba-4511-b22b-0c1e87510ff7`::finished: True
>Thread-21::DEBUG::2014-07-18 09:25:14,102::task::595::TaskManager.Task::(_updateState) Task=`709028ba-cbba-4511-b22b-0c1e87510ff7`::moving from state preparing -> state finished
>Thread-21::DEBUG::2014-07-18 09:25:14,102::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-21::DEBUG::2014-07-18 09:25:14,102::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-21::DEBUG::2014-07-18 09:25:14,103::task::990::TaskManager.Task::(_decref) Task=`709028ba-cbba-4511-b22b-0c1e87510ff7`::ref 0 aborting False
>Thread-34::DEBUG::2014-07-18 09:25:14,154::BindingXMLRPC::251::vds::(wrapper) client [127.0.0.1]
>Thread-34::DEBUG::2014-07-18 09:25:14,155::task::595::TaskManager.Task::(_updateState) Task=`a6fafcbe-43dd-4538-b09e-f56b974ac8ff`::moving from state init -> state preparing
>Thread-34::INFO::2014-07-18 09:25:14,156::logUtils::44::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID='9a371fa0-c27d-4a3e-a35f-1a9fb1960b7f', options=None)
>Thread-34::DEBUG::2014-07-18 09:25:14,156::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.9a371fa0-c27d-4a3e-a35f-1a9fb1960b7f`ReqID=`bb2f7be6-c331-41d6-a969-9b0457ee9276`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '2572' at 'getStoragePoolInfo'
>Thread-34::DEBUG::2014-07-18 09:25:14,157::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.9a371fa0-c27d-4a3e-a35f-1a9fb1960b7f' for lock type 'shared'
>Thread-34::DEBUG::2014-07-18 09:25:14,157::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.9a371fa0-c27d-4a3e-a35f-1a9fb1960b7f' is free. Now locking as 'shared' (1 active user)
>Thread-34::DEBUG::2014-07-18 09:25:14,158::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.9a371fa0-c27d-4a3e-a35f-1a9fb1960b7f`ReqID=`bb2f7be6-c331-41d6-a969-9b0457ee9276`::Granted request
>Thread-34::DEBUG::2014-07-18 09:25:14,158::task::827::TaskManager.Task::(resourceAcquired) Task=`a6fafcbe-43dd-4538-b09e-f56b974ac8ff`::_resourcesAcquired: Storage.9a371fa0-c27d-4a3e-a35f-1a9fb1960b7f (shared)
>Thread-34::DEBUG::2014-07-18 09:25:14,158::task::990::TaskManager.Task::(_decref) Task=`a6fafcbe-43dd-4538-b09e-f56b974ac8ff`::ref 1 aborting False
>Thread-34::DEBUG::2014-07-18 09:25:14,169::persistentDict::234::Storage.PersistentDict::(refresh) read lines (FileMetadataRW)=['CLASS=Data', 'DESCRIPTION=hosted_storage', 'IOOPTIMEOUTSEC=10', 'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=ON', 'LOCKRENEWALINTERVALSEC=5', 'MASTER_VERSION=1', 'POOL_DESCRIPTION=hosted_datacenter', 'POOL_DOMAINS=c58f4345-45e3-449e-937c-d02ffc443c5b:Active', 'POOL_SPM_ID=-1', 'POOL_SPM_LVER=0', 'POOL_UUID=9a371fa0-c27d-4a3e-a35f-1a9fb1960b7f', 'REMOTE_PATH=gluster.voxtest.fr:/engine', 'ROLE=Master', 'SDUUID=c58f4345-45e3-449e-937c-d02ffc443c5b', 'TYPE=NFS', 'VERSION=3', '_SHA_CKSUM=851bdb258bbf1071232a6de6288b6a2ffd8c8154']
>Thread-34::INFO::2014-07-18 09:25:14,170::logUtils::47::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'name': 'hosted_datacenter', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': 'c58f4345-45e3-449e-937c-d02ffc443c5b:Active', 'master_uuid': 'c58f4345-45e3-449e-937c-d02ffc443c5b', 'version': '3', 'spm_id': -1, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'c58f4345-45e3-449e-937c-d02ffc443c5b': {'status': 'Active', 'diskfree': '547420635136', 'isoprefix': '', 'alerts': [], 'disktotal': '559343992832', 'version': 3}}}
>Thread-34::DEBUG::2014-07-18 09:25:14,171::task::1185::TaskManager.Task::(prepare) Task=`a6fafcbe-43dd-4538-b09e-f56b974ac8ff`::finished: {'info': {'name': 'hosted_datacenter', 'isoprefix': '', 'pool_status': 'connected', 'lver': 0, 'domains': 'c58f4345-45e3-449e-937c-d02ffc443c5b:Active', 'master_uuid': 'c58f4345-45e3-449e-937c-d02ffc443c5b', 'version': '3', 'spm_id': -1, 'type': 'NFS', 'master_ver': 1}, 'dominfo': {'c58f4345-45e3-449e-937c-d02ffc443c5b': {'status': 'Active', 'diskfree': '547420635136', 'isoprefix': '', 'alerts': [], 'disktotal': '559343992832', 'version': 3}}}
>Thread-34::DEBUG::2014-07-18 09:25:14,171::task::595::TaskManager.Task::(_updateState) Task=`a6fafcbe-43dd-4538-b09e-f56b974ac8ff`::moving from state preparing -> state finished
>Thread-34::DEBUG::2014-07-18 09:25:14,171::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.9a371fa0-c27d-4a3e-a35f-1a9fb1960b7f': < ResourceRef 'Storage.9a371fa0-c27d-4a3e-a35f-1a9fb1960b7f', isValid: 'True' obj: 'None'>}
>Thread-34::DEBUG::2014-07-18 09:25:14,171::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-34::DEBUG::2014-07-18 09:25:14,172::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.9a371fa0-c27d-4a3e-a35f-1a9fb1960b7f'
>Thread-34::DEBUG::2014-07-18 09:25:14,172::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.9a371fa0-c27d-4a3e-a35f-1a9fb1960b7f' (0 active users)
>Thread-34::DEBUG::2014-07-18 09:25:14,172::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.9a371fa0-c27d-4a3e-a35f-1a9fb1960b7f' is free, finding out if anyone is waiting for it.
>Thread-34::DEBUG::2014-07-18 09:25:14,173::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.9a371fa0-c27d-4a3e-a35f-1a9fb1960b7f', Clearing records.
>Thread-34::DEBUG::2014-07-18 09:25:14,173::task::990::TaskManager.Task::(_decref) Task=`a6fafcbe-43dd-4538-b09e-f56b974ac8ff`::ref 0 aborting False
>Thread-23::DEBUG::2014-07-18 09:25:23,775::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/gluster.voxtest.fr:_engine/c58f4345-45e3-449e-937c-d02ffc443c5b/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-23::DEBUG::2014-07-18 09:25:23,796::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n479 bytes (479 B) copied, 0.00104424 s, 459 kB/s\n'; <rc> = 0
>Thread-23::INFO::2014-07-18 09:25:23,803::clusterlock::184::SANLock::(acquireHostId) Acquiring host id for domain c58f4345-45e3-449e-937c-d02ffc443c5b (id: 2)
>Thread-23::DEBUG::2014-07-18 09:25:23,803::clusterlock::202::SANLock::(acquireHostId) Host id for domain c58f4345-45e3-449e-937c-d02ffc443c5b successfully acquired (id: 2)
>Thread-23::DEBUG::2014-07-18 09:25:33,812::fileSD::259::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/rhev/data-center/mnt/gluster.voxtest.fr:_engine/c58f4345-45e3-449e-937c-d02ffc443c5b/dom_md/metadata bs=4096 count=1' (cwd None)
>Thread-23::DEBUG::2014-07-18 09:25:33,834::fileSD::259::Storage.Misc.excCmd::(getReadDelay) SUCCESS: <err> = '0+1 records in\n0+1 records out\n479 bytes (479 B) copied, 0.00102477 s, 467 kB/s\n'; <rc> = 0
>Thread-23::INFO::2014-07-18 09:25:33,849::clusterlock::184::SANLock::(acquireHostId) Acquiring host id for domain c58f4345-45e3-449e-937c-d02ffc443c5b (id: 2)
>Thread-23::DEBUG::2014-07-18 09:25:33,850::clusterlock::202::SANLock::(acquireHostId) Host id for domain c58f4345-45e3-449e-937c-d02ffc443c5b successfully acquired (id: 2)
>MainThread::DEBUG::2014-07-18 09:25:38,773::vdsm::55::vds::(sigtermHandler) Received signal 15
>MainThread::INFO::2014-07-18 09:25:39,144::vmChannels::187::vds::(stop) VM channels listener was stopped.
>MainThread::INFO::2014-07-18 09:25:39,145::momIF::91::MOM::(stop) Shutting down MOM
>MainThread::DEBUG::2014-07-18 09:25:39,146::task::595::TaskManager.Task::(_updateState) Task=`abd67289-36b9-440a-91a4-b01aba002012`::moving from state init -> state preparing
>MainThread::INFO::2014-07-18 09:25:39,147::logUtils::44::dispatcher::(wrapper) Run and protect: prepareForShutdown(options=None)
>Thread-11::DEBUG::2014-07-18 09:25:39,147::storageServer::698::ConnectionMonitor::(_monitorConnections) Monitoring stopped
>VM Channels Listener::INFO::2014-07-18 09:25:39,195::vmChannels::182::vds::(run) VM channels listener thread has ended.
>MainThread::INFO::2014-07-18 09:25:40,866::domainMonitor::125::Storage.DomainMonitor::(close) Stopping domain monitors
>MainThread::INFO::2014-07-18 09:25:40,867::domainMonitor::113::Storage.DomainMonitor::(stopMonitoring) Stop monitoring c58f4345-45e3-449e-937c-d02ffc443c5b
>Thread-23::DEBUG::2014-07-18 09:25:40,868::domainMonitor::175::Storage.DomainMonitorThread::(_monitorLoop) Stopping domain monitor for c58f4345-45e3-449e-937c-d02ffc443c5b
>Thread-23::INFO::2014-07-18 09:25:40,868::clusterlock::207::SANLock::(releaseHostId) Releasing host id for domain c58f4345-45e3-449e-937c-d02ffc443c5b (id: 2)
>Thread-23::DEBUG::2014-07-18 09:25:40,881::clusterlock::217::SANLock::(releaseHostId) Host id for domain c58f4345-45e3-449e-937c-d02ffc443c5b released successfully (id: 2)
>MainThread::DEBUG::2014-07-18 09:25:40,882::taskManager::80::TaskManager::(prepareForShutdown) Request to stop all tasks
>MainThread::INFO::2014-07-18 09:25:40,882::logUtils::47::dispatcher::(wrapper) Run and protect: prepareForShutdown, Return response: None
>MainThread::DEBUG::2014-07-18 09:25:40,882::task::1185::TaskManager.Task::(prepare) Task=`abd67289-36b9-440a-91a4-b01aba002012`::finished: None
>MainThread::DEBUG::2014-07-18 09:25:40,882::task::595::TaskManager.Task::(_updateState) Task=`abd67289-36b9-440a-91a4-b01aba002012`::moving from state preparing -> state finished
>MainThread::DEBUG::2014-07-18 09:25:40,883::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>MainThread::DEBUG::2014-07-18 09:25:40,883::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>MainThread::DEBUG::2014-07-18 09:25:40,883::task::990::TaskManager.Task::(_decref) Task=`abd67289-36b9-440a-91a4-b01aba002012`::ref 0 aborting False
>MainThread::INFO::2014-07-18 09:25:40,883::vdsm::125::vds::(run) VDSM main thread ended. Waiting for 16 other threads...
>MainThread::INFO::2014-07-18 09:25:40,883::vdsm::129::vds::(run) <_MainThread(MainThread, started 140605891905280)>
>MainThread::INFO::2014-07-18 09:25:40,884::vdsm::129::vds::(run) <Thread(libvirtEventLoop, started daemon 140605622888192)>
>MainThread::INFO::2014-07-18 09:25:40,884::vdsm::129::vds::(run) <WorkerThread(Thread-9, started daemon 140605453747968)>
>MainThread::INFO::2014-07-18 09:25:40,884::vdsm::129::vds::(run) <PolicyEngine(PolicyEngine, started daemon 140604715550464)>
>MainThread::INFO::2014-07-18 09:25:40,884::vdsm::129::vds::(run) <WorkerThread(Thread-10, started daemon 140605443258112)>
>MainThread::INFO::2014-07-18 09:25:40,884::vdsm::129::vds::(run) <HostMonitor(HostMonitor, started daemon 140604266768128)>
>MainThread::INFO::2014-07-18 09:25:40,885::vdsm::129::vds::(run) <GuestManager(GuestManager, started daemon 140604256278272)>
>MainThread::INFO::2014-07-18 09:25:40,885::vdsm::129::vds::(run) <WorkerThread(Thread-7, started daemon 140605474727680)>
>MainThread::INFO::2014-07-18 09:25:40,885::vdsm::129::vds::(run) <WorkerThread(Thread-2, started daemon 140605485217536)>
>MainThread::INFO::2014-07-18 09:25:40,885::momIF::91::MOM::(stop) Shutting down MOM
>MainThread::INFO::2014-07-18 09:25:40,885::vdsm::129::vds::(run) <MomThread(MOM, started 140604726040320)>
>MainThread::INFO::2014-07-18 09:25:40,886::vdsm::129::vds::(run) <WorkerThread(Thread-6, started daemon 140605570438912)>
>MainThread::INFO::2014-07-18 09:25:40,886::vdsm::129::vds::(run) <WorkerThread(Thread-5, started daemon 140605580928768)>
>MainThread::INFO::2014-07-18 09:25:40,886::vdsm::129::vds::(run) <WorkerThread(Thread-4, started daemon 140605591418624)>
>MainThread::INFO::2014-07-18 09:25:40,886::vdsm::129::vds::(run) <WorkerThread(Thread-3, started daemon 140605601908480)>
>MainThread::INFO::2014-07-18 09:25:40,886::vdsm::129::vds::(run) <HSM_MailMonitor(Thread-33, started daemon 140603843135232)>
>MainThread::INFO::2014-07-18 09:25:40,886::vdsm::129::vds::(run) <WorkerThread(Thread-1, started daemon 140605612398336)>
>MainThread::INFO::2014-07-18 09:25:40,886::vdsm::129::vds::(run) <WorkerThread(Thread-8, started daemon 140605464237824)>
>MainThread::INFO::2014-07-18 09:25:45,125::vdsm::119::vds::(run) (PID: 3322) I am the actual vdsm 4.14.9-0.el6 node2.voxtest.fr (2.6.32-431.20.3.el6.x86_64)
>MainThread::DEBUG::2014-07-18 09:25:45,127::resourceManager::421::ResourceManager::(registerNamespace) Registering namespace 'Storage'
>MainThread::DEBUG::2014-07-18 09:25:45,127::threadPool::35::Misc.ThreadPool::(__init__) Enter - numThreads: 10.0, waitTimeout: 3, maxTasks: 500.0
>MainThread::WARNING::2014-07-18 09:25:45,134::fileUtils::167::Storage.fileUtils::(createdir) Dir /rhev/data-center/mnt already exists
>MainThread::DEBUG::2014-07-18 09:25:46,570::supervdsm::77::SuperVdsmProxy::(_connect) Trying to connect to Super Vdsm
>MainThread::DEBUG::2014-07-18 09:25:46,607::multipath::142::Storage.Multipath::(isEnabled) Current revision of multipath.conf detected, preserving
>MainThread::DEBUG::2014-07-18 09:25:46,607::hsm::434::Storage.Misc.excCmd::(__validateLvmLockingType) '/usr/bin/sudo -n /sbin/lvm dumpconfig global/locking_type' (cwd None)
>MainThread::DEBUG::2014-07-18 09:25:46,986::hsm::434::Storage.Misc.excCmd::(__validateLvmLockingType) SUCCESS: <err> = ''; <rc> = 0
>MainThread::DEBUG::2014-07-18 09:25:46,988::hsm::458::Storage.HSM::(__cleanStorageRepository) Started cleaning storage repository at '/rhev/data-center'
>MainThread::DEBUG::2014-07-18 09:25:46,994::hsm::490::Storage.HSM::(__cleanStorageRepository) White list: ['/rhev/data-center/hsm-tasks', '/rhev/data-center/hsm-tasks/*', '/rhev/data-center/mnt']
>MainThread::DEBUG::2014-07-18 09:25:46,994::hsm::491::Storage.HSM::(__cleanStorageRepository) Mount list: ['/rhev/data-center/mnt/gluster.voxtest.fr:_engine']
>MainThread::DEBUG::2014-07-18 09:25:46,994::hsm::493::Storage.HSM::(__cleanStorageRepository) Cleaning leftovers
>MainThread::DEBUG::2014-07-18 09:25:46,997::hsm::536::Storage.HSM::(__cleanStorageRepository) Finished cleaning storage repository at '/rhev/data-center'
>storageRefresh::DEBUG::2014-07-18 09:25:46,998::misc::756::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage)
>MainThread::INFO::2014-07-18 09:25:47,001::dispatcher::97::Storage.Dispatcher::(__init__) Starting StorageDispatcher...
>storageRefresh::DEBUG::2014-07-18 09:25:47,001::misc::758::SamplingMethod::(__call__) Got in to sampling method
>storageRefresh::DEBUG::2014-07-18 09:25:47,030::misc::756::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)
>storageRefresh::DEBUG::2014-07-18 09:25:47,048::misc::758::SamplingMethod::(__call__) Got in to sampling method
>storageRefresh::DEBUG::2014-07-18 09:25:47,051::iscsi::407::Storage.ISCSI::(rescan) Performing SCSI scan, this will take up to 30 seconds
>storageRefresh::DEBUG::2014-07-18 09:25:47,053::iscsiadm::92::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None)
>storageRefresh::DEBUG::2014-07-18 09:25:47,080::misc::766::SamplingMethod::(__call__) Returning last result
>storageRefresh::DEBUG::2014-07-18 09:25:47,081::multipath::110::Storage.Misc.excCmd::(rescan) '/usr/bin/sudo -n /sbin/multipath -r' (cwd None)
>MainThread::DEBUG::2014-07-18 09:25:47,102::task::595::TaskManager.Task::(_updateState) Task=`50a80ada-ea8c-4cd3-bed2-b6c2c7c99777`::moving from state init -> state preparing
>MainThread::INFO::2014-07-18 09:25:47,103::logUtils::44::dispatcher::(wrapper) Run and protect: registerDomainStateChangeCallback(callbackFunc=<bound method clientIF.contEIOVms of <clientIF.clientIF instance at 0x1c643b0>>)
>MainThread::INFO::2014-07-18 09:25:47,103::logUtils::47::dispatcher::(wrapper) Run and protect: registerDomainStateChangeCallback, Return response: None
>MainThread::DEBUG::2014-07-18 09:25:47,103::task::1185::TaskManager.Task::(prepare) Task=`50a80ada-ea8c-4cd3-bed2-b6c2c7c99777`::finished: None
>MainThread::DEBUG::2014-07-18 09:25:47,103::task::595::TaskManager.Task::(_updateState) Task=`50a80ada-ea8c-4cd3-bed2-b6c2c7c99777`::moving from state preparing -> state finished
>MainThread::DEBUG::2014-07-18 09:25:47,103::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>MainThread::DEBUG::2014-07-18 09:25:47,103::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>MainThread::DEBUG::2014-07-18 09:25:47,104::task::990::TaskManager.Task::(_decref) Task=`50a80ada-ea8c-4cd3-bed2-b6c2c7c99777`::ref 0 aborting False
>MainThread::INFO::2014-07-18 09:25:47,120::momIF::49::MOM::(__init__) Starting up MOM
>MainThread::INFO::2014-07-18 09:25:47,123::vmChannels::191::vds::(settimeout) Setting channels' timeout to 30 seconds.
>VM Channels Listener::INFO::2014-07-18 09:25:47,202::vmChannels::174::vds::(run) Starting VM channels listener thread.
>clientIFinit::DEBUG::2014-07-18 09:25:47,209::libvirtconnection::145::root::(get) trying to connect libvirt
>MainThread::WARNING::2014-07-18 09:25:47,229::clientIF::181::vds::(_prepareBindings) Unable to load the json rpc server module. Please make sure it is installed.
>storageRefresh::DEBUG::2014-07-18 09:25:47,242::multipath::110::Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0
>storageRefresh::DEBUG::2014-07-18 09:25:47,243::lvm::497::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex
>storageRefresh::DEBUG::2014-07-18 09:25:47,243::lvm::499::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex
>storageRefresh::DEBUG::2014-07-18 09:25:47,243::lvm::508::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex
>storageRefresh::DEBUG::2014-07-18 09:25:47,244::lvm::510::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex
>storageRefresh::DEBUG::2014-07-18 09:25:47,244::lvm::528::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex
>storageRefresh::DEBUG::2014-07-18 09:25:47,244::lvm::530::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex
>storageRefresh::DEBUG::2014-07-18 09:25:47,245::misc::766::SamplingMethod::(__call__) Returning last result
>storageRefresh::DEBUG::2014-07-18 09:25:47,245::lvm::325::OperationMutex::(_reloadpvs) Operation 'lvm reload operation' got the operation mutex
>storageRefresh::DEBUG::2014-07-18 09:25:47,248::lvm::296::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm pvs --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  use_lvmetad=0 }  backup {  retain_min = 50  retain_days = 0 } " --noheadings --units b --nosuffix --separator | -o uuid,name,size,vg_name,vg_uuid,pe_start,pe_count,pe_alloc_count,mda_count,dev_size' (cwd None)
>storageRefresh::DEBUG::2014-07-18 09:25:47,649::lvm::296::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = ''; <rc> = 0
>storageRefresh::DEBUG::2014-07-18 09:25:47,650::lvm::350::OperationMutex::(_reloadpvs) Operation 'lvm reload operation' released the operation mutex
>storageRefresh::DEBUG::2014-07-18 09:25:47,651::lvm::373::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
>storageRefresh::DEBUG::2014-07-18 09:25:47,651::lvm::296::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  use_lvmetad=0 }  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' (cwd None)
>Thread-13::DEBUG::2014-07-18 09:25:47,803::BindingXMLRPC::1067::vds::(wrapper) client [127.0.0.1]::call getHardwareInfo with () {}
>Thread-13::DEBUG::2014-07-18 09:25:47,803::BindingXMLRPC::1074::vds::(wrapper) return getHardwareInfo with {'status': {'message': 'Recovering from crash or Initializing', 'code': 99}}
>storageRefresh::DEBUG::2014-07-18 09:25:48,010::lvm::296::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = '  No volume groups found\n'; <rc> = 0
>storageRefresh::DEBUG::2014-07-18 09:25:48,011::lvm::415::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
>storageRefresh::DEBUG::2014-07-18 09:25:48,012::lvm::296::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm lvs --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  use_lvmetad=0 }  backup {  retain_min = 50  retain_days = 0 } " --noheadings --units b --nosuffix --separator | -o uuid,name,vg_name,attr,size,seg_start_pe,devices,tags' (cwd None)
>storageRefresh::DEBUG::2014-07-18 09:25:48,345::lvm::296::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = '  No volume groups found\n'; <rc> = 0
>storageRefresh::DEBUG::2014-07-18 09:25:48,346::lvm::373::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex
>storageRefresh::DEBUG::2014-07-18 09:25:48,347::lvm::296::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  use_lvmetad=0 }  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' (cwd None)
>storageRefresh::DEBUG::2014-07-18 09:25:48,680::lvm::296::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = '  No volume groups found\n'; <rc> = 0
>storageRefresh::DEBUG::2014-07-18 09:25:48,681::lvm::415::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex
>storageRefresh::WARNING::2014-07-18 09:25:48,682::fileUtils::167::Storage.fileUtils::(createdir) Dir /rhev/data-center/hsm-tasks already exists
>storageRefresh::DEBUG::2014-07-18 09:25:48,682::hsm::393::Storage.HSM::(storageRefresh) HSM is ready
>Thread-14::DEBUG::2014-07-18 09:25:48,857::BindingXMLRPC::1067::vds::(wrapper) client [127.0.0.1]::call getHardwareInfo with () {}
>Thread-14::DEBUG::2014-07-18 09:25:48,873::BindingXMLRPC::1074::vds::(wrapper) return getHardwareInfo with {'status': {'message': 'Done', 'code': 0}, 'info': {'systemProductName': 'H8QM8', 'systemSerialNumber': '1234567890', 'systemFamily': 'To Be Filled By O.E.M.', 'systemVersion': '1234567890', 'systemUUID': '00020003-0004-0005-0006-000700080009', 'systemManufacturer': 'Supermicro'}}
>Thread-15::DEBUG::2014-07-18 09:25:48,927::BindingXMLRPC::251::vds::(wrapper) client [127.0.0.1]
>Thread-15::DEBUG::2014-07-18 09:25:48,928::task::595::TaskManager.Task::(_updateState) Task=`2118f047-afb6-4eb5-ab2f-3f487c1673d2`::moving from state init -> state preparing
>Thread-15::INFO::2014-07-18 09:25:48,929::logUtils::44::dispatcher::(wrapper) Run and protect: getConnectedStoragePoolsList(options=None)
>Thread-15::INFO::2014-07-18 09:25:48,929::logUtils::47::dispatcher::(wrapper) Run and protect: getConnectedStoragePoolsList, Return response: {'poollist': []}
>Thread-15::DEBUG::2014-07-18 09:25:48,929::task::1185::TaskManager.Task::(prepare) Task=`2118f047-afb6-4eb5-ab2f-3f487c1673d2`::finished: {'poollist': []}
>Thread-15::DEBUG::2014-07-18 09:25:48,929::task::595::TaskManager.Task::(_updateState) Task=`2118f047-afb6-4eb5-ab2f-3f487c1673d2`::moving from state preparing -> state finished
>Thread-15::DEBUG::2014-07-18 09:25:48,930::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-15::DEBUG::2014-07-18 09:25:48,930::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-15::DEBUG::2014-07-18 09:25:48,930::task::990::TaskManager.Task::(_decref) Task=`2118f047-afb6-4eb5-ab2f-3f487c1673d2`::ref 0 aborting False
>Thread-16::DEBUG::2014-07-18 09:25:48,982::BindingXMLRPC::251::vds::(wrapper) client [127.0.0.1]
>Thread-16::DEBUG::2014-07-18 09:25:48,982::task::595::TaskManager.Task::(_updateState) Task=`3be63ff9-1808-4ab2-89a0-55c8d5c59fa7`::moving from state init -> state preparing
>Thread-16::INFO::2014-07-18 09:25:48,983::logUtils::44::dispatcher::(wrapper) Run and protect: connectStorageServer(domType=1, spUUID='00000000-0000-0000-0000-000000000000', conList=[{'port': '', 'connection': 'gluster.voxtest.fr:/engine', 'iqn': '', 'portal': '', 'user': 'kvm', 'protocol_version': '3', 'password': '******', 'id': '1430e8ce-1e1a-403f-a450-63de3330627f'}], options=None)
>Thread-16::DEBUG::2014-07-18 09:25:48,988::hsm::2328::Storage.HSM::(__prefetchDomains) nfs local path: /rhev/data-center/mnt/gluster.voxtest.fr:_engine
>Thread-16::DEBUG::2014-07-18 09:25:49,210::hsm::2352::Storage.HSM::(__prefetchDomains) Found SD uuids: ('c58f4345-45e3-449e-937c-d02ffc443c5b',)
>Thread-16::DEBUG::2014-07-18 09:25:49,211::hsm::2408::Storage.HSM::(connectStorageServer) knownSDs: {c58f4345-45e3-449e-937c-d02ffc443c5b: storage.nfsSD.findDomain}
>Thread-16::INFO::2014-07-18 09:25:49,211::logUtils::47::dispatcher::(wrapper) Run and protect: connectStorageServer, Return response: {'statuslist': [{'status': 0, 'id': '1430e8ce-1e1a-403f-a450-63de3330627f'}]}
>Thread-16::DEBUG::2014-07-18 09:25:49,211::task::1185::TaskManager.Task::(prepare) Task=`3be63ff9-1808-4ab2-89a0-55c8d5c59fa7`::finished: {'statuslist': [{'status': 0, 'id': '1430e8ce-1e1a-403f-a450-63de3330627f'}]}
>Thread-16::DEBUG::2014-07-18 09:25:49,212::task::595::TaskManager.Task::(_updateState) Task=`3be63ff9-1808-4ab2-89a0-55c8d5c59fa7`::moving from state preparing -> state finished
>Thread-16::DEBUG::2014-07-18 09:25:49,212::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-16::DEBUG::2014-07-18 09:25:49,212::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-16::DEBUG::2014-07-18 09:25:49,213::task::990::TaskManager.Task::(_decref) Task=`3be63ff9-1808-4ab2-89a0-55c8d5c59fa7`::ref 0 aborting False
>Thread-17::DEBUG::2014-07-18 09:26:03,082::BindingXMLRPC::1067::vds::(wrapper) client [127.0.0.1]::call vmDestroy with ('0ae2cd9f-eb1f-4487-853b-9987feaf277c',) {}
>Thread-17::INFO::2014-07-18 09:26:03,096::API::326::vds::(destroy) vmContainerLock acquired by vm 0ae2cd9f-eb1f-4487-853b-9987feaf277c
>Thread-17::DEBUG::2014-07-18 09:26:03,096::BindingXMLRPC::1074::vds::(wrapper) return vmDestroy with {'status': {'message': 'Virtual machine does not exist', 'code': 1}}
>Thread-18::DEBUG::2014-07-18 09:26:03,206::BindingXMLRPC::251::vds::(wrapper) client [127.0.0.1]
>Thread-18::DEBUG::2014-07-18 09:26:03,207::task::595::TaskManager.Task::(_updateState) Task=`7a38c8a4-100e-4235-8a8d-be1ed6f59206`::moving from state init -> state preparing
>Thread-18::INFO::2014-07-18 09:26:03,208::logUtils::44::dispatcher::(wrapper) Run and protect: spmStop(spUUID='9a371fa0-c27d-4a3e-a35f-1a9fb1960b7f', options=None)
>Thread-18::DEBUG::2014-07-18 09:26:03,208::resourceManager::198::ResourceManager.Request::(__init__) ResName=`Storage.9a371fa0-c27d-4a3e-a35f-1a9fb1960b7f`ReqID=`c48db6a8-231e-45c2-8dee-a9f5b5e2c3f0`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '616' at 'spmStop'
>Thread-18::DEBUG::2014-07-18 09:26:03,209::resourceManager::542::ResourceManager::(registerResource) Trying to register resource 'Storage.9a371fa0-c27d-4a3e-a35f-1a9fb1960b7f' for lock type 'exclusive'
>Thread-18::DEBUG::2014-07-18 09:26:03,209::resourceManager::601::ResourceManager::(registerResource) Resource 'Storage.9a371fa0-c27d-4a3e-a35f-1a9fb1960b7f' is free. Now locking as 'exclusive' (1 active user)
>Thread-18::DEBUG::2014-07-18 09:26:03,210::resourceManager::238::ResourceManager.Request::(grant) ResName=`Storage.9a371fa0-c27d-4a3e-a35f-1a9fb1960b7f`ReqID=`c48db6a8-231e-45c2-8dee-a9f5b5e2c3f0`::Granted request
>Thread-18::DEBUG::2014-07-18 09:26:03,210::task::827::TaskManager.Task::(resourceAcquired) Task=`7a38c8a4-100e-4235-8a8d-be1ed6f59206`::_resourcesAcquired: Storage.9a371fa0-c27d-4a3e-a35f-1a9fb1960b7f (exclusive)
>Thread-18::DEBUG::2014-07-18 09:26:03,211::task::990::TaskManager.Task::(_decref) Task=`7a38c8a4-100e-4235-8a8d-be1ed6f59206`::ref 1 aborting False
>Thread-18::ERROR::2014-07-18 09:26:03,211::task::866::TaskManager.Task::(_setError) Task=`7a38c8a4-100e-4235-8a8d-be1ed6f59206`::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 618, in spmStop
>    pool = self.getPool(spUUID)
>  File "/usr/share/vdsm/storage/hsm.py", line 326, in getPool
>    raise se.StoragePoolUnknown(spUUID)
>StoragePoolUnknown: Unknown pool id, pool not connected: ('9a371fa0-c27d-4a3e-a35f-1a9fb1960b7f',)
>Thread-18::DEBUG::2014-07-18 09:26:03,232::task::885::TaskManager.Task::(_run) Task=`7a38c8a4-100e-4235-8a8d-be1ed6f59206`::Task._run: 7a38c8a4-100e-4235-8a8d-be1ed6f59206 ('9a371fa0-c27d-4a3e-a35f-1a9fb1960b7f',) {} failed - stopping task
>Thread-18::DEBUG::2014-07-18 09:26:03,232::task::1211::TaskManager.Task::(stop) Task=`7a38c8a4-100e-4235-8a8d-be1ed6f59206`::stopping in state preparing (force False)
>Thread-18::DEBUG::2014-07-18 09:26:03,232::task::990::TaskManager.Task::(_decref) Task=`7a38c8a4-100e-4235-8a8d-be1ed6f59206`::ref 1 aborting True
>Thread-18::INFO::2014-07-18 09:26:03,233::task::1168::TaskManager.Task::(prepare) Task=`7a38c8a4-100e-4235-8a8d-be1ed6f59206`::aborting: Task is aborted: 'Unknown pool id, pool not connected' - code 309
>Thread-18::DEBUG::2014-07-18 09:26:03,233::task::1173::TaskManager.Task::(prepare) Task=`7a38c8a4-100e-4235-8a8d-be1ed6f59206`::Prepare: aborted: Unknown pool id, pool not connected
>Thread-18::DEBUG::2014-07-18 09:26:03,233::task::990::TaskManager.Task::(_decref) Task=`7a38c8a4-100e-4235-8a8d-be1ed6f59206`::ref 0 aborting True
>Thread-18::DEBUG::2014-07-18 09:26:03,233::task::925::TaskManager.Task::(_doAbort) Task=`7a38c8a4-100e-4235-8a8d-be1ed6f59206`::Task._doAbort: force False
>Thread-18::DEBUG::2014-07-18 09:26:03,233::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-18::DEBUG::2014-07-18 09:26:03,234::task::595::TaskManager.Task::(_updateState) Task=`7a38c8a4-100e-4235-8a8d-be1ed6f59206`::moving from state preparing -> state aborting
>Thread-18::DEBUG::2014-07-18 09:26:03,234::task::550::TaskManager.Task::(__state_aborting) Task=`7a38c8a4-100e-4235-8a8d-be1ed6f59206`::_aborting: recover policy none
>Thread-18::DEBUG::2014-07-18 09:26:03,234::task::595::TaskManager.Task::(_updateState) Task=`7a38c8a4-100e-4235-8a8d-be1ed6f59206`::moving from state aborting -> state failed
>Thread-18::DEBUG::2014-07-18 09:26:03,234::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {'Storage.9a371fa0-c27d-4a3e-a35f-1a9fb1960b7f': < ResourceRef 'Storage.9a371fa0-c27d-4a3e-a35f-1a9fb1960b7f', isValid: 'True' obj: 'None'>}
>Thread-18::DEBUG::2014-07-18 09:26:03,235::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-18::DEBUG::2014-07-18 09:26:03,235::resourceManager::616::ResourceManager::(releaseResource) Trying to release resource 'Storage.9a371fa0-c27d-4a3e-a35f-1a9fb1960b7f'
>Thread-18::DEBUG::2014-07-18 09:26:03,235::resourceManager::635::ResourceManager::(releaseResource) Released resource 'Storage.9a371fa0-c27d-4a3e-a35f-1a9fb1960b7f' (0 active users)
>Thread-18::DEBUG::2014-07-18 09:26:03,236::resourceManager::641::ResourceManager::(releaseResource) Resource 'Storage.9a371fa0-c27d-4a3e-a35f-1a9fb1960b7f' is free, finding out if anyone is waiting for it.
>Thread-18::DEBUG::2014-07-18 09:26:03,236::resourceManager::649::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.9a371fa0-c27d-4a3e-a35f-1a9fb1960b7f', Clearing records.
>Thread-18::ERROR::2014-07-18 09:26:03,236::dispatcher::65::Storage.Dispatcher.Protect::(run) {'status': {'message': "Unknown pool id, pool not connected: ('9a371fa0-c27d-4a3e-a35f-1a9fb1960b7f',)", 'code': 309}}
>Thread-19::DEBUG::2014-07-18 09:26:03,293::BindingXMLRPC::251::vds::(wrapper) client [127.0.0.1]
>Thread-19::DEBUG::2014-07-18 09:26:03,294::task::595::TaskManager.Task::(_updateState) Task=`dca965ef-60e3-479d-8af6-87f48fe5d90b`::moving from state init -> state preparing
>Thread-19::INFO::2014-07-18 09:26:03,294::logUtils::44::dispatcher::(wrapper) Run and protect: disconnectStoragePool(spUUID='9a371fa0-c27d-4a3e-a35f-1a9fb1960b7f', hostID=2, remove=False, options=None)
>Thread-19::WARNING::2014-07-18 09:26:03,295::hsm::1126::Storage.HSM::(disconnectStoragePool) disconnect sp: 9a371fa0-c27d-4a3e-a35f-1a9fb1960b7f failed. Known pools {}
>Thread-19::INFO::2014-07-18 09:26:03,295::logUtils::47::dispatcher::(wrapper) Run and protect: disconnectStoragePool, Return response: None
>Thread-19::DEBUG::2014-07-18 09:26:03,295::task::1185::TaskManager.Task::(prepare) Task=`dca965ef-60e3-479d-8af6-87f48fe5d90b`::finished: None
>Thread-19::DEBUG::2014-07-18 09:26:03,295::task::595::TaskManager.Task::(_updateState) Task=`dca965ef-60e3-479d-8af6-87f48fe5d90b`::moving from state preparing -> state finished
>Thread-19::DEBUG::2014-07-18 09:26:03,295::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}
>Thread-19::DEBUG::2014-07-18 09:26:03,296::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}
>Thread-19::DEBUG::2014-07-18 09:26:03,296::task::990::TaskManager.Task::(_decref) Task=`dca965ef-60e3-479d-8af6-87f48fe5d90b`::ref 0 aborting False

Actions: View

Attachments on bug 1119828: 918341 | 918342 | 918983 | 919549