[Users] oVIRT 3.3 Failed to acces Master Domain
Thread-98::DEBUG::2013-09-11 16:35:06,864::misc::809::SamplingMethod::(__c= all__) Got in to sampling method<br />Thread-98::DEBUG::2013-09-11 16:35:06= ,864::iscsiadm::91::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/= iscsiadm -m session -R' (cwd None)<br />Thread-98::DEBUG::2013-09-11 16:35:= 06,875::iscsiadm::91::Storage.Misc.excCmd::(_runCmd) FAILED: <err> = =3D 'iscsiadm: No session found.\n'; <rc> =3D 21<br />Thread-98::DEBU= G::2013-09-11 16:35:06,875::misc::817::SamplingMethod::(__call__) Returning= last result<br />Thread-98::DEBUG::2013-09-11 16:35:08,902::multipath::111= ::Storage.Misc.excCmd::(rescan) '/usr/bin/sudo -n /sbin/multipath' (cwd Non= e)<br />Thread-98::DEBUG::2013-09-11 16:35:08,916::multipath::111::Storage.= Misc.excCmd::(rescan) SUCCESS: <err> =3D ''; <rc> =3D 0<br />Th= read-98::DEBUG::2013-09-11 16:35:08,917::lvm::483::OperationMutex::(_invali= dateAllPvs) Operation 'lvm invalidate operation' got the operation mutex<br= />Thread-98::DEBUG::2013-09-11 16:35:08,917::lvm::485::OperationMutex::(_i= nvalidateAllPvs) Operation 'lvm invalidate operation' released the operatio= n mutex<br />Thread-98::DEBUG::2013-09-11 16:35:08,918::lvm::494::Operation= Mutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the ope= ration mutex<br />Thread-98::DEBUG::2013-09-11 16:35:08,918::lvm::496::Oper= ationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' releas= ed the operation mutex<br />Thread-98::DEBUG::2013-09-11 16:35:08,918::lvm:= :514::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operati= on' got the operation mutex<br />Thread-98::DEBUG::2013-09-11 16:35:08,918:= :lvm::516::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate op= eration' released the operation mutex<br />Thread-98::DEBUG::2013-09-11 16:= 35:08,919::misc::817::SamplingMethod::(__call__) Returning last result<br /= Thread-98::ERROR::2013-09-11 16:35:08,919::sdc::137::Storage.StorageDomain= Cache::(_findDomain) looking for unfetched domain 3401420d-6918-49f9-b9e2-2= 3ba47949f29<br />Thread-98::ERROR::2013-09-11 16:35:08,919::sdc::154::Stora= ge.StorageDomainCache::(_findUnfetchedDomain) looking for domain 3401420d-6= 918-49f9-b9e2-23ba47949f29<br />Thread-98::DEBUG::2013-09-11 16:35:08,919::= lvm::374::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got=
--========GMXBoundary239291378911044835950 Content-Type: text/plain; charset="utf-8" Content-Transfer-Encoding: 8bit Hello, I run in troubles.... For a testing I completly powered off the oVirt Cluster (Engine as well as the the host).. and now my host is unable to fine the Master Domain System: CentOS 6.4, vdsm-4.12.1-1.el6, oVirt Engine Version: 3.3.0-1.el6 Trace vdsm.log Thread-98::DEBUG::2013-09-11 16:35:06,859::BindingXMLRPC::177::vds::(wrapper) client [192.168.1.29] Thread-98::DEBUG::2013-09-11 16:35:06,859::task::579::TaskManager.Task::(_updateState) Task=`b2a7a44f-8cb0-453a-bf52-16a200f992f9`::moving from state init -> state preparing Thread-98::INFO::2013-09-11 16:35:06,860::logUtils::44::dispatcher::(wrapper) Run and protect: connectStoragePool(spUUID='5849b030-626e-47cb-ad90-3ce782d831b3', hostID=1, scsiKey='5849b030-626e-47cb-ad90-3ce782d831b3', msdUUID='3401420d-6918-49f9-b9e2-23ba47949f29', masterVersion=1, options=None) Thread-98::DEBUG::2013-09-11 16:35:06,860::resourceManager::197::ResourceManager.Request::(__init__) ResName=`Storage.5849b030-626e-47cb-ad90-3ce782d831b3`ReqID=`079c6f43-9453-4598-a9f3-7056ad3a595e`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '1020' at '_connectStoragePool' Thread-98::DEBUG::2013-09-11 16:35:06,860::resourceManager::541::ResourceManager::(registerResource) Trying to register resource 'Storage.5849b030-626e-47cb-ad90-3ce782d831b3' for lock type 'exclusive' Thread-98::DEBUG::2013-09-11 16:35:06,861::resourceManager::600::ResourceManager::(registerResource) Resource 'Storage.5849b030-626e-47cb-ad90-3ce782d831b3' is free. Now locking as 'exclusive' (1 active user) Thread-98::DEBUG::2013-09-11 16:35:06,861::resourceManager::237::ResourceManager.Request::(grant) ResName=`Storage.5849b030-626e-47cb-ad90-3ce782d831b3`ReqID=`079c6f43-9453-4598-a9f3-7056ad3a595e`::Granted request Thread-98::INFO::2013-09-11 16:35:06,861::sp::680::Storage.StoragePool::(connect) Connect host #1 to the storage pool 5849b030-626e-47cb-ad90-3ce782d831b3 with master domain: 3401420d-6918-49f9-b9e2-23ba47949f29 (ver = 1) Thread-98::DEBUG::2013-09-11 16:35:06,862::lvm::483::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex Thread-98::DEBUG::2013-09-11 16:35:06,862::lvm::485::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex Thread-98::DEBUG::2013-09-11 16:35:06,862::lvm::494::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex Thread-98::DEBUG::2013-09-11 16:35:06,862::lvm::496::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex Thread-98::DEBUG::2013-09-11 16:35:06,863::lvm::514::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex Thread-98::DEBUG::2013-09-11 16:35:06,863::lvm::516::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex Thread-98::DEBUG::2013-09-11 16:35:06,863::misc::807::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage) Thread-98::DEBUG::2013-09-11 16:35:06,863::misc::809::SamplingMethod::(__call__) Got in to sampling method Thread-98::DEBUG::2013-09-11 16:35:06,863::misc::807::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan) Thread-98::DEBUG::2013-09-11 16:35:06,864::misc::809::SamplingMethod::(__call__) Got in to sampling method Thread-98::DEBUG::2013-09-11 16:35:06,864::iscsiadm::91::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None) Thread-98::DEBUG::2013-09-11 16:35:06,875::iscsiadm::91::Storage.Misc.excCmd::(_runCmd) FAILED: <err> = 'iscsiadm: No session found.\n'; <rc> = 21 Thread-98::DEBUG::2013-09-11 16:35:06,875::misc::817::SamplingMethod::(__call__) Returning last result Thread-98::DEBUG::2013-09-11 16:35:08,902::multipath::111::Storage.Misc.excCmd::(rescan) '/usr/bin/sudo -n /sbin/multipath' (cwd None) Thread-98::DEBUG::2013-09-11 16:35:08,916::multipath::111::Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0 Thread-98::DEBUG::2013-09-11 16:35:08,917::lvm::483::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex Thread-98::DEBUG::2013-09-11 16:35:08,917::lvm::485::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex Thread-98::DEBUG::2013-09-11 16:35:08,918::lvm::494::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex Thread-98::DEBUG::2013-09-11 16:35:08,918::lvm::496::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex Thread-98::DEBUG::2013-09-11 16:35:08,918::lvm::514::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex Thread-98::DEBUG::2013-09-11 16:35:08,918::lvm::516::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex Thread-98::DEBUG::2013-09-11 16:35:08,919::misc::817::SamplingMethod::(__call__) Returning last result Thread-98::ERROR::2013-09-11 16:35:08,919::sdc::137::Storage.StorageDomainCache::(_findDomain) looking for unfetched domain 3401420d-6918-49f9-b9e2-23ba47949f29 Thread-98::ERROR::2013-09-11 16:35:08,919::sdc::154::Storage.StorageDomainCache::(_findUnfetchedDomain) looking for domain 3401420d-6918-49f9-b9e2-23ba47949f29 Thread-98::DEBUG::2013-09-11 16:35:08,919::lvm::374::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex Thread-98::DEBUG::2013-09-11 16:35:08,921::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 = [ \'a|/dev/mapper/3600508b1001052395359564d53570200|\', \'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 3401420d-6918-49f9-b9e2-23ba47949f29' (cwd None) Thread-98::DEBUG::2013-09-11 16:35:09,096::lvm::311::Storage.Misc.excCmd::(cmd) FAILED: <err> = ' Volume group "3401420d-6918-49f9-b9e2-23ba47949f29" not found\n'; <rc> = 5 Thread-98::WARNING::2013-09-11 16:35:09,097::lvm::379::Storage.LVM::(_reloadvgs) lvm vgs failed: 5 [] [' Volume group "3401420d-6918-49f9-b9e2-23ba47949f29" not found'] Thread-98::DEBUG::2013-09-11 16:35:09,097::lvm::403::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex Thread-98::ERROR::2013-09-11 16:35:09,098::sdc::143::Storage.StorageDomainCache::(_findDomain) domain 3401420d-6918-49f9-b9e2-23ba47949f29 not found Thread-98::DEBUG::2013-09-11 16:35:09,099::resourceManager::615::ResourceManager::(releaseResource) Trying to release resource 'Storage.5849b030-626e-47cb-ad90-3ce782d831b3' Thread-98::DEBUG::2013-09-11 16:35:09,099::resourceManager::634::ResourceManager::(releaseResource) Released resource 'Storage.5849b030-626e-47cb-ad90-3ce782d831b3' (0 active users) Thread-98::DEBUG::2013-09-11 16:35:09,099::resourceManager::640::ResourceManager::(releaseResource) Resource 'Storage.5849b030-626e-47cb-ad90-3ce782d831b3' is free, finding out if anyone is waiting for it. Thread-98::DEBUG::2013-09-11 16:35:09,099::resourceManager::648::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.5849b030-626e-47cb-ad90-3ce782d831b3', Clearing records. Thread-98::ERROR::2013-09-11 16:35:09,100::task::850::TaskManager.Task::(_setError) Task=`b2a7a44f-8cb0-453a-bf52-16a200f992f9`::Unexpected error Thread-98::DEBUG::2013-09-11 16:35:09,100::task::869::TaskManager.Task::(_run) Task=`b2a7a44f-8cb0-453a-bf52-16a200f992f9`::Task._run: b2a7a44f-8cb0-453a-bf52-16a200f992f9 ('5849b030-626e-47cb-ad90-3ce782d831b3', 1, '5849b030-626e-47cb-ad90-3ce782d831b3', '3401420d-6918-49f9-b9e2-23ba47949f29', 1) {} failed - stopping task Thread-98::DEBUG::2013-09-11 16:35:09,100::task::1194::TaskManager.Task::(stop) Task=`b2a7a44f-8cb0-453a-bf52-16a200f992f9`::stopping in state preparing (force False) Thread-98::DEBUG::2013-09-11 16:35:09,101::task::974::TaskManager.Task::(_decref) Task=`b2a7a44f-8cb0-453a-bf52-16a200f992f9`::ref 1 aborting True Thread-98::INFO::2013-09-11 16:35:09,101::task::1151::TaskManager.Task::(prepare) Task=`b2a7a44f-8cb0-453a-bf52-16a200f992f9`::aborting: Task is aborted: 'Cannot find master domain' - code 304 Thread-98::DEBUG::2013-09-11 16:35:09,101::task::1156::TaskManager.Task::(prepare) Task=`b2a7a44f-8cb0-453a-bf52-16a200f992f9`::Prepare: aborted: Cannot find master domain Thread-98::DEBUG::2013-09-11 16:35:09,101::task::974::TaskManager.Task::(_decref) Task=`b2a7a44f-8cb0-453a-bf52-16a200f992f9`::ref 0 aborting True Thread-98::DEBUG::2013-09-11 16:35:09,102::task::909::TaskManager.Task::(_doAbort) Task=`b2a7a44f-8cb0-453a-bf52-16a200f992f9`::Task._doAbort: force False Thread-98::DEBUG::2013-09-11 16:35:09,102::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-98::DEBUG::2013-09-11 16:35:09,102::task::579::TaskManager.Task::(_updateState) Task=`b2a7a44f-8cb0-453a-bf52-16a200f992f9`::moving from state preparing -> state aborting Thread-98::DEBUG::2013-09-11 16:35:09,102::task::534::TaskManager.Task::(__state_aborting) Task=`b2a7a44f-8cb0-453a-bf52-16a200f992f9`::_aborting: recover policy none Thread-98::DEBUG::2013-09-11 16:35:09,102::task::579::TaskManager.Task::(_updateState) Task=`b2a7a44f-8cb0-453a-bf52-16a200f992f9`::moving from state aborting -> state failed Thread-98::DEBUG::2013-09-11 16:35:09,103::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-98::DEBUG::2013-09-11 16:35:09,103::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-98::ERROR::2013-09-11 16:35:09,103::dispatcher::67::Storage.Dispatcher.Protect::(run) {'status': {'message': "Cannot find master domain: 'spUUID=5849b030-626e-47cb-ad90-3ce782d831b3, msdUUID=3401420d-6918-49f9-b9e2-23ba47949f29'", 'code': 304}} and engine.log 2013-09-10 16:35:16,652 INFO [org.ovirt.engine.core.bll.SPMAsyncTask] (DefaultQuartzScheduler_Worker-68) BaseAsyncTask::OnTaskEndSuccess: Task f587a842-272f-4a86-8c15-7451a39a7f42 (Parent Command ImportVm, Parameters Type org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters) ended successfully. 2013-09-10 16:35:16,654 INFO [org.ovirt.engine.core.bll.CommandMultiAsyncTasks] (DefaultQuartzScheduler_Worker-68) Task with DB Task ID a0fc43a0-3f25-4c65-a7e8-8f60762c64c8 and VDSM Task ID 1f3a3700-cfca-40dd-95b4-28b141756e8e is in state Polling. End action for command f61efb6b-d3a4-4e04-a79e-3b7c61920ff2 will proceed when all the entitys tasks are completed. 2013-09-10 16:35:36,817 INFO [org.ovirt.engine.core.bll.SPMAsyncTask] (DefaultQuartzScheduler_Worker-95) SPMAsyncTask::PollTask: Polling task 1f3a3700-cfca-40dd-95b4-28b141756e8e (Parent Command ImportVm, Parameters Type org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters) returned status finished, result 'success'. 2013-09-10 16:35:36,893 INFO [org.ovirt.engine.core.bll.SPMAsyncTask] (DefaultQuartzScheduler_Worker-95) BaseAsyncTask::OnTaskEndSuccess: Task 1f3a3700-cfca-40dd-95b4-28b141756e8e (Parent Command ImportVm, Parameters Type org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters) ended successfully. 2013-09-10 16:35:36,895 INFO [org.ovirt.engine.core.bll.CommandAsyncTask] (DefaultQuartzScheduler_Worker-95) CommandAsyncTask::EndActionIfNecessary: All tasks of command f61efb6b-d3a4-4e04-a79e-3b7c61920ff2 has ended -> executing EndAction 2013-09-10 16:35:36,896 INFO [org.ovirt.engine.core.bll.CommandAsyncTask] (DefaultQuartzScheduler_Worker-95) CommandAsyncTask::EndAction: Ending action for 2 tasks (command ID: f61efb6b-d3a4-4e04-a79e-3b7c61920ff2): calling EndAction . 2013-09-10 16:35:36,899 INFO [org.ovirt.engine.core.bll.CommandAsyncTask] (pool-6-thread-48) CommandAsyncTask::EndCommandAction [within thread] context: Attempting to EndAction ImportVm, executionIndex: 0 2013-09-10 16:35:36,919 INFO [org.ovirt.engine.core.bll.ImportVmCommand] (pool-6-thread-48) Ending command successfully: org.ovirt.engine.core.bll.ImportVmCommand 2013-09-10 16:35:36,948 INFO [org.ovirt.engine.core.bll.CopyImageGroupCommand] (pool-6-thread-48) [1c5353e0] Ending command successfully: org.ovirt.engine.core.bll.CopyImageGroupCommand 2013-09-10 16:35:36,971 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.GetImageInfoVDSCommand] (pool-6-thread-48) [1c5353e0] START, GetImageInfoVDSCommand( storagePoolId = 5849b030-626e-47cb-ad90-3ce782d831b3, ignoreFailoverLimit = false, storageDomainId = 3401420d-6918-49f9-b9e2-23ba47949f29, imageGroupId = 8061a702-792f-4219-8bf0-8f10ba576c01, imageId = 4b2a7aed-bc11-45c8-8bf1-9c195c5a29ab), log id: 51fca824 2013-09-10 16:35:42,430 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.GetImageInfoVDSCommand] (pool-6-thread-48) [1c5353e0] FINISH, GetImageInfoVDSCommand, return: org.ovirt.engine.core.common.businessentities.DiskImage@285e00dd, log id: 51fca824 2013-09-10 16:35:42,449 INFO [org.ovirt.engine.core.bll.CopyImageGroupCommand] (pool-6-thread-48) [57faac34] Ending command successfully: org.ovirt.engine.core.bll.CopyImageGroupCommand 2013-09-10 16:35:42,453 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.GetImageInfoVDSCommand] (pool-6-thread-48) [57faac34] START, GetImageInfoVDSCommand( storagePoolId = 5849b030-626e-47cb-ad90-3ce782d831b3, ignoreFailoverLimit = false, storageDomainId = 3401420d-6918-49f9-b9e2-23ba47949f29, imageGroupId = 374e7d38-ebfe-4fab-a6ec-727e9ef9733c, imageId = 54e3344d-45f0-4876-b4a9-cdad98fac7a5), log id: 51aaf563 2013-09-10 16:35:56,954 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.GetImageInfoVDSCommand] (pool-6-thread-48) [57faac34] FINISH, GetImageInfoVDSCommand, return: org.ovirt.engine.core.common.businessentities.DiskImage@dd64762e, log id: 51aaf563 2013-09-10 16:35:57,000 INFO [org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand] (pool-6-thread-48) START, SetVmStatusVDSCommand( vmId = dc1ac7da-fef2-48e4-ab91-309b3a1fd2c0, status = Down), log id: 45208621 2013-09-10 16:35:57,007 INFO [org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand] (pool-6-thread-48) FINISH, SetVmStatusVDSCommand, log id: 45208621 2013-09-10 16:35:57,008 INFO [org.ovirt.engine.core.bll.ImportVmCommand] (pool-6-thread-48) Lock freed to object EngineLock [exclusiveLocks= key: VM1 value: VM_NAME 2013-09-10 16:35:57,051 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (pool-6-thread-48) Correlation ID: 62df3606, Job ID: 7134d7b0-7878-4bb3-970f-4128c1e818e7, Call Stack: null, Custom Event ID: -1, Message: Vm VM1 was imported successfully to Data Center Default, Cluster Default 2013-09-10 16:35:57,053 INFO [org.ovirt.engine.core.bll.CommandAsyncTask] (pool-6-thread-48) CommandAsyncTask::HandleEndActionResult [within thread]: EndAction for action type ImportVm completed, handling the result. 2013-09-10 16:35:57,054 INFO [org.ovirt.engine.core.bll.CommandAsyncTask] (pool-6-thread-48) CommandAsyncTask::HandleEndActionResult [within thread]: EndAction for action type ImportVm succeeded, clearing tasks. 2013-09-10 16:35:57,068 INFO [org.ovirt.engine.core.bll.SPMAsyncTask] (pool-6-thread-48) SPMAsyncTask::ClearAsyncTask: Attempting to clear task f587a842-272f-4a86-8c15-7451a39a7f42 2013-09-10 16:35:57,070 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SPMClearTaskVDSCommand] (pool-6-thread-48) START, SPMClearTaskVDSCommand( storagePoolId = 5849b030-626e-47cb-ad90-3ce782d831b3, ignoreFailoverLimit = false, taskId = f587a842-272f-4a86-8c15-7451a39a7f42), log id: 57f89137 2013-09-10 16:35:57,102 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (pool-6-thread-48) START, HSMClearTaskVDSCommand(HostName = HOST1, HostId = 6593afcd-9e7f-4928-a914-5ad1eeaa3999, taskId=f587a842-272f-4a86-8c15-7451a39a7f42), log id: 5df00 2013-09-11 16:35:01,795 INFO [org.ovirt.engine.core.bll.InitVdsOnUpCommand] (DefaultQuartzScheduler_Worker-81) Running command: InitVdsOnUpCommand internal: true. Entities affected : ID: 5849b030-626e-47cb-ad90-3ce782d831b3 Type: StoragePool 2013-09-11 16:35:01,799 INFO [org.ovirt.engine.core.bll.storage.ConnectHostToStoragePoolServersCommand] (DefaultQuartzScheduler_Worker-81) Running command: ConnectHostToStoragePoolServersCommand internal: true. Entities affected : ID: 5849b030-626e-47cb-ad90-3ce782d831b3 Type: StoragePool 2013-09-11 16:35:01,854 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStoragePoolVDSCommand] (pool-6-thread-50) START, ConnectStoragePoolVDSCommand(HostName = BBGLU012, HostId = 6593afcd-9e7f-4928-a914-5ad1eeaa3999, storagePoolId = 5849b030-626e-47cb-ad90-3ce782d831b3, vds_spm_id = 1, masterDomainId = 3401420d-6918-49f9-b9e2-23ba47949f29, masterVersion = 1), log id: 14e339aa 2013-09-11 16:35:09,112 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStoragePoolVDSCommand] (pool-6-thread-50) Command org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStoragePoolVDSCommand return value 2013-09-11 16:35:09,114 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStoragePoolVDSCommand] (pool-6-thread-50) HostName = HOST1 2013-09-11 16:35:09,114 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStoragePoolVDSCommand] (pool-6-thread-50) Command ConnectStoragePoolVDS execution failed. Exception: IRSNoMasterDomainException: IRSGenericException: IRSErrorException: IRSNoMasterDomainException: Cannot find master domain: 'spUUID=5849b030-626e-47cb-ad90-3ce782d831b3, msdUUID=3401420d-6918-49f9-b9e2-23ba47949f29' 2013-09-11 16:35:09,115 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStoragePoolVDSCommand] (pool-6-thread-50) FINISH, ConnectStoragePoolVDSCommand, log id: 14e339aa 2013-09-11 16:35:09,116 ERROR [org.ovirt.engine.core.bll.InitVdsOnUpCommand] (pool-6-thread-50) Could not connect host HOST1 to pool Default 2013-09-11 16:35:09,184 INFO [org.ovirt.engine.core.bll.SetNonOperationalVdsCommand] (DefaultQuartzScheduler_Worker-81) Running command: SetNonOperationalVdsCommand internal: true. Entities affected : ID: 6593afcd-9e7f-4928-a914-5ad1eeaa3999 Type: VDS 2013-09-11 16:35:09,207 INFO [org.ovirt.engine.core.vdsbroker.SetVdsStatusVDSCommand] (DefaultQuartzScheduler_Worker-81) START, SetVdsStatusVDSCommand(HostName = HOST1, HostId = 6593afcd-9e7f-4928-a914-5ad1eeaa3999, status=NonOperational, nonOperationalReason=STORAGE_DOMAIN_UNREACHABLE), log id: 3c9dbd47 2013-09-11 16:35:09,217 INFO [org.ovirt.engine.core.vdsbroker.SetVdsStatusVDSCommand] (DefaultQuartzScheduler_Worker-81) FINISH, SetVdsStatusVDSCommand, log id: 3c9dbd47 2013-09-11 16:35:09,225 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (DefaultQuartzScheduler_Worker-81) Correlation ID: 64e68249, Job ID: 355b71e9-f7b9-4554-800b-7b08a09d9a12, Call Stack: null, Custom Event ID: -1, Message: Host HOST1 cannot access one of the Storage Domains attached to the Data Center Default. Setting Host state to Non-Operational. 2013-09-11 16:35:09,266 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (DefaultQuartzScheduler_Worker-81) Correlation ID: null, Call Stack: null, Custom Event ID: -1, Message: Power Management test failed for Host BBGLU012.There is no other host in the data center that can be used to test the power management settings. 2013-09-11 16:35:09,275 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (DefaultQuartzScheduler_Worker-81) Correlation ID: 1a32fa26, Call Stack: null, Custom Event ID: -1, Message: Failed to connect Host HOST1 to Storage Pool Default 2013-09-11 16:35:09,320 INFO [org.ovirt.engine.core.bll.HandleVdsCpuFlagsOrClusterChangedCommand] (DefaultQuartzScheduler_Worker-81) Running command: HandleVdsCpuFlagsOrClusterChangedCommand internal: true. Entities affected : ID: 6593afcd-9e7f-4928-a914-5ad1eeaa3999 Type: VDS 2013-09-11 16:35:09,352 INFO [org.ovirt.engine.core.bll.HandleVdsVersionCommand] (DefaultQuartzScheduler_Worker-81) Running command: HandleVdsVersionCommand internal: true. Entities affected : ID: 6593afcd-9e7f-4928-a914-5ad1eeaa3999 Type: VDS 2013-09-11 16:35:09,354 INFO [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (DefaultQuartzScheduler_Worker-81) Host 6593afcd-9e7f-4928-a914-5ad1eeaa3999 : HOST1 is already in NonOperational status. SetNonOperationalVds command is skipped. [root@bbgpas129 ovirt-engine]# 2013-09-11 16:35:09,184 INFO [org.ovirt.engine.core.bll.SetNonOperationalVdsCommand] (DefaultQuartzScheduler_Worker-81) Running command: SetNonOperationalVdsCommand internal: true. Entities affected : ID: 6593afcd-9e7f-4928-a914-5ad1eeaa3999 Type: VDS --========GMXBoundary239291378911044835950 Content-Type: text/html; charset="utf-8" Content-Transfer-Encoding: quoted-printable <span style=3D'font-family:Verdana'><span style=3D'font-size:12px'>Hello,<b= r /><br />I run in troubles....<br /><br />For a testing I completly powere= d off the oVirt Cluster (Engine as well as the the host).. and now my host<= br />is unable to fine the Master Domain<br /><br />System: CentOS 6.4,&nbs= p; <span class=3D"formPanel_detailViewItemValue">vdsm-4.12.1-1.el6, </span>= <span class=3D"gwt-InlineLabel">oVirt Engine Version: 3.3.0-1.el6<br /><br = />Trace vdsm.log<br /><br />Thread-98::DEBUG::2013-09-11 16:35:06,859::Bind= ingXMLRPC::177::vds::(wrapper) client [192.168.1.29]<br />Thread-98::DEBUG:= :2013-09-11 16:35:06,859::task::579::TaskManager.Task::(_updateState) Task= =3D`b2a7a44f-8cb0-453a-bf52-16a200f992f9`::moving from state init -> sta= te preparing<br />Thread-98::INFO::2013-09-11 16:35:06,860::logUtils::44::d= ispatcher::(wrapper) Run and protect: connectStoragePool(spUUID=3D'5849b030= -626e-47cb-ad90-3ce782d831b3', hostID=3D1, scsiKey=3D'5849b030-626e-47cb-ad= 90-3ce782d831b3', msdUUID=3D'3401420d-6918-49f9-b9e2-23ba47949f29', masterV= ersion=3D1, options=3DNone)<br />Thread-98::DEBUG::2013-09-11 16:35:06,860:= :resourceManager::197::ResourceManager.Request::(__init__) ResName=3D`Stora= ge.5849b030-626e-47cb-ad90-3ce782d831b3`ReqID=3D`079c6f43-9453-4598-a9f3-70= 56ad3a595e`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '102= 0' at '_connectStoragePool'<br />Thread-98::DEBUG::2013-09-11 16:35:06,860:= :resourceManager::541::ResourceManager::(registerResource) Trying to regist= er resource 'Storage.5849b030-626e-47cb-ad90-3ce782d831b3' for lock type 'e= xclusive'<br />Thread-98::DEBUG::2013-09-11 16:35:06,861::resourceManager::= 600::ResourceManager::(registerResource) Resource 'Storage.5849b030-626e-47= cb-ad90-3ce782d831b3' is free. Now locking as 'exclusive' (1 active user)<b= r />Thread-98::DEBUG::2013-09-11 16:35:06,861::resourceManager::237::Resour= ceManager.Request::(grant) ResName=3D`Storage.5849b030-626e-47cb-ad90-3ce78= 2d831b3`ReqID=3D`079c6f43-9453-4598-a9f3-7056ad3a595e`::Granted request<br = />Thread-98::INFO::2013-09-11 16:35:06,861::sp::680::Storage.StoragePool::(= connect) Connect host #1 to the storage pool 5849b030-626e-47cb-ad90-3ce782= d831b3 with master domain: 3401420d-6918-49f9-b9e2-23ba47949f29 (ver =3D 1)= <br />Thread-98::DEBUG::2013-09-11 16:35:06,862::lvm::483::OperationMutex::= (_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation = mutex<br />Thread-98::DEBUG::2013-09-11 16:35:06,862::lvm::485::OperationMu= tex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the = operation mutex<br />Thread-98::DEBUG::2013-09-11 16:35:06,862::lvm::494::O= perationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got= the operation mutex<br />Thread-98::DEBUG::2013-09-11 16:35:06,862::lvm::4= 96::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation= ' released the operation mutex<br />Thread-98::DEBUG::2013-09-11 16:35:06,8= 63::lvm::514::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate= operation' got the operation mutex<br />Thread-98::DEBUG::2013-09-11 16:35= :06,863::lvm::516::OperationMutex::(_invalidateAllLvs) Operation 'lvm inval= idate operation' released the operation mutex<br />Thread-98::DEBUG::2013-0= 9-11 16:35:06,863::misc::807::SamplingMethod::(__call__) Trying to enter sa= mpling method (storage.sdc.refreshStorage)<br />Thread-98::DEBUG::2013-09-1= 1 16:35:06,863::misc::809::SamplingMethod::(__call__) Got in to sampling me= thod<br />Thread-98::DEBUG::2013-09-11 16:35:06,863::misc::807::SamplingMet= hod::(__call__) Trying to enter sampling method (storage.iscsi.rescan)<br /= the operation mutex<br />Thread-98::DEBUG::2013-09-11 16:35:08,921::lvm::3= 11::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n /sbin/lvm vgs --config " d= evices { preferred_names =3D [\\"^/dev/mapper/\\"] ignore_suspended_devices= =3D1 write_cache_state=3D0 disable_after_error_count=3D3 filter =3D [ \'a|/= dev/mapper/3600508b1001052395359564d53570200|\', \'r|.*|\' ] } global= { locking_type=3D1 prioritise_write_locks=3D1 wait_for_l= ocks=3D1 } backup { retain_min =3D 50 retain_days =3D 0 }= " --noheadings --units b --nosuffix --separator | -o uuid,name,attr,size,f= ree,extent_size,extent_count,free_count,tags,vg_mda_size,vg_mda_free 340142= 0d-6918-49f9-b9e2-23ba47949f29' (cwd None)<br />Thread-98::DEBUG::2013-09-1= 1 16:35:09,096::lvm::311::Storage.Misc.excCmd::(cmd) FAILED: <err> = =3D ' Volume group "3401420d-6918-49f9-b9e2-23ba47949f29" not found\n= '; <rc> =3D 5<br />Thread-98::WARNING::2013-09-11 16:35:09,097::lvm::= 379::Storage.LVM::(_reloadvgs) lvm vgs failed: 5 [] [' Volume group "= 3401420d-6918-49f9-b9e2-23ba47949f29" not found']<br />Thread-98::DEBUG::20= 13-09-11 16:35:09,097::lvm::403::OperationMutex::(_reloadvgs) Operation 'lv= m reload operation' released the operation mutex<br />Thread-98::ERROR::201= 3-09-11 16:35:09,098::sdc::143::Storage.StorageDomainCache::(_findDomain) d= omain 3401420d-6918-49f9-b9e2-23ba47949f29 not found<br />Thread-98::DEBUG:= :2013-09-11 16:35:09,099::resourceManager::615::ResourceManager::(releaseRe= source) Trying to release resource 'Storage.5849b030-626e-47cb-ad90-3ce782d= 831b3'<br />Thread-98::DEBUG::2013-09-11 16:35:09,099::resourceManager::634= ::ResourceManager::(releaseResource) Released resource 'Storage.5849b030-62= 6e-47cb-ad90-3ce782d831b3' (0 active users)<br />Thread-98::DEBUG::2013-09-= 11 16:35:09,099::resourceManager::640::ResourceManager::(releaseResource) R= esource 'Storage.5849b030-626e-47cb-ad90-3ce782d831b3' is free, finding out= if anyone is waiting for it.<br />Thread-98::DEBUG::2013-09-11 16:35:09,09= 9::resourceManager::648::ResourceManager::(releaseResource) No one is waiti= ng for resource 'Storage.5849b030-626e-47cb-ad90-3ce782d831b3', Clearing re= cords.<br />Thread-98::ERROR::2013-09-11 16:35:09,100::task::850::TaskManag= er.Task::(_setError) Task=3D`b2a7a44f-8cb0-453a-bf52-16a200f992f9`::Unexpec= ted error<br />Thread-98::DEBUG::2013-09-11 16:35:09,100::task::869::TaskMa= nager.Task::(_run) Task=3D`b2a7a44f-8cb0-453a-bf52-16a200f992f9`::Task._run= : b2a7a44f-8cb0-453a-bf52-16a200f992f9 ('5849b030-626e-47cb-ad90-3ce782d831= b3', 1, '5849b030-626e-47cb-ad90-3ce782d831b3', '3401420d-6918-49f9-b9e2-23= ba47949f29', 1) {} failed - stopping task<br />Thread-98::DEBUG::2013-09-11= 16:35:09,100::task::1194::TaskManager.Task::(stop) Task=3D`b2a7a44f-8cb0-4= 53a-bf52-16a200f992f9`::stopping in state preparing (force False)<br />Thre= ad-98::DEBUG::2013-09-11 16:35:09,101::task::974::TaskManager.Task::(_decre= f) Task=3D`b2a7a44f-8cb0-453a-bf52-16a200f992f9`::ref 1 aborting True<br />= Thread-98::INFO::2013-09-11 16:35:09,101::task::1151::TaskManager.Task::(pr= epare) Task=3D`b2a7a44f-8cb0-453a-bf52-16a200f992f9`::aborting: Task is abo= rted: 'Cannot find master domain' - code 304<br />Thread-98::DEBUG::2013-09= -11 16:35:09,101::task::1156::TaskManager.Task::(prepare) Task=3D`b2a7a44f-= 8cb0-453a-bf52-16a200f992f9`::Prepare: aborted: Cannot find master domain<b= r />Thread-98::DEBUG::2013-09-11 16:35:09,101::task::974::TaskManager.Task:= :(_decref) Task=3D`b2a7a44f-8cb0-453a-bf52-16a200f992f9`::ref 0 aborting Tr= ue<br />Thread-98::DEBUG::2013-09-11 16:35:09,102::task::909::TaskManager.T= ask::(_doAbort) Task=3D`b2a7a44f-8cb0-453a-bf52-16a200f992f9`::Task._doAbor= t: force False<br />Thread-98::DEBUG::2013-09-11 16:35:09,102::resourceMana= ger::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}<br= />Thread-98::DEBUG::2013-09-11 16:35:09,102::task::579::TaskManager.Task::= (_updateState) Task=3D`b2a7a44f-8cb0-453a-bf52-16a200f992f9`::moving from s= tate preparing -> state aborting<br />Thread-98::DEBUG::2013-09-11 16:35= :09,102::task::534::TaskManager.Task::(__state_aborting) Task=3D`b2a7a44f-8= cb0-453a-bf52-16a200f992f9`::_aborting: recover policy none<br />Thread-98:= :DEBUG::2013-09-11 16:35:09,102::task::579::TaskManager.Task::(_updateState= ) Task=3D`b2a7a44f-8cb0-453a-bf52-16a200f992f9`::moving from state aborting= -> state failed<br />Thread-98::DEBUG::2013-09-11 16:35:09,103::resourc= eManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll request= s {} resources {}<br />Thread-98::DEBUG::2013-09-11 16:35:09,103::resourceM= anager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}= <br />Thread-98::ERROR::2013-09-11 16:35:09,103::dispatcher::67::Storage.Di= spatcher.Protect::(run) {'status': {'message': "Cannot find master domain: = 'spUUID=3D5849b030-626e-47cb-ad90-3ce782d831b3, msdUUID=3D3401420d-6918-49f= 9-b9e2-23ba47949f29'", 'code': 304}}</span><br /><br />and engine.log<br />= <br />2013-09-10 16:35:16,652 INFO [org.ovirt.engine.core.bll.SPMAsyn= cTask] (DefaultQuartzScheduler_Worker-68) BaseAsyncTask::OnTaskEndSuccess: = Task f587a842-272f-4a86-8c15-7451a39a7f42 (Parent Command ImportVm, Paramet= ers Type org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters) ended= successfully.<br />2013-09-10 16:35:16,654 INFO [org.ovirt.engine.co= re.bll.CommandMultiAsyncTasks] (DefaultQuartzScheduler_Worker-68) Task with= DB Task ID a0fc43a0-3f25-4c65-a7e8-8f60762c64c8 and VDSM Task ID 1f3a3700-= cfca-40dd-95b4-28b141756e8e is in state Polling. End action for command f61= efb6b-d3a4-4e04-a79e-3b7c61920ff2 will proceed when all the entitys tasks a= re completed.<br />2013-09-10 16:35:36,817 INFO [org.ovirt.engine.cor= e.bll.SPMAsyncTask] (DefaultQuartzScheduler_Worker-95) SPMAsyncTask::PollTa= sk: Polling task 1f3a3700-cfca-40dd-95b4-28b141756e8e (Parent Command Impor= tVm, Parameters Type org.ovirt.engine.core.common.asynctasks.AsyncTaskParam= eters) returned status finished, result 'success'.<br />2013-09-10 16:35:36= ,893 INFO [org.ovirt.engine.core.bll.SPMAsyncTask] (DefaultQuartzSche= duler_Worker-95) BaseAsyncTask::OnTaskEndSuccess: Task 1f3a3700-cfca-40dd-9= 5b4-28b141756e8e (Parent Command ImportVm, Parameters Type org.ovirt.engine= .core.common.asynctasks.AsyncTaskParameters) ended successfully.<br />2013-= 09-10 16:35:36,895 INFO [org.ovirt.engine.core.bll.CommandAsyncTask] = (DefaultQuartzScheduler_Worker-95) CommandAsyncTask::EndActionIfNecessary: = All tasks of command f61efb6b-d3a4-4e04-a79e-3b7c61920ff2 has ended -> e= xecuting EndAction<br />2013-09-10 16:35:36,896 INFO [org.ovirt.engin= e.core.bll.CommandAsyncTask] (DefaultQuartzScheduler_Worker-95) CommandAsyn= cTask::EndAction: Ending action for 2 tasks (command ID: f61efb6b-d3a4-4e04= -a79e-3b7c61920ff2): calling EndAction .<br />2013-09-10 16:35:36,899 INFO&= nbsp; [org.ovirt.engine.core.bll.CommandAsyncTask] (pool-6-thread-48) Comma= ndAsyncTask::EndCommandAction [within thread] context: Attempting to EndAct= ion ImportVm, executionIndex: 0<br />2013-09-10 16:35:36,919 INFO [or= g.ovirt.engine.core.bll.ImportVmCommand] (pool-6-thread-48) Ending command = successfully: org.ovirt.engine.core.bll.ImportVmCommand<br />2013-09-10 16:= 35:36,948 INFO [org.ovirt.engine.core.bll.CopyImageGroupCommand] (poo= l-6-thread-48) [1c5353e0] Ending command successfully: org.ovirt.engine.cor= e.bll.CopyImageGroupCommand<br />2013-09-10 16:35:36,971 INFO [org.ov= irt.engine.core.vdsbroker.irsbroker.GetImageInfoVDSCommand] (pool-6-thread-= 48) [1c5353e0] START, GetImageInfoVDSCommand( storagePoolId =3D 5849b030-62= 6e-47cb-ad90-3ce782d831b3, ignoreFailoverLimit =3D false, storageDomainId = =3D 3401420d-6918-49f9-b9e2-23ba47949f29, imageGroupId =3D 8061a702-792f-42= 19-8bf0-8f10ba576c01, imageId =3D 4b2a7aed-bc11-45c8-8bf1-9c195c5a29ab), lo= g id: 51fca824<br />2013-09-10 16:35:42,430 INFO [org.ovirt.engine.co= re.vdsbroker.irsbroker.GetImageInfoVDSCommand] (pool-6-thread-48) [1c5353e0= ] FINISH, GetImageInfoVDSCommand, return: org.ovirt.engine.core.common.busi= nessentities.DiskImage@285e00dd, log id: 51fca824<br />2013-09-10 16:35:42,= 449 INFO [org.ovirt.engine.core.bll.CopyImageGroupCommand] (pool-6-th= read-48) [57faac34] Ending command successfully: org.ovirt.engine.core.bll.= CopyImageGroupCommand<br />2013-09-10 16:35:42,453 INFO [org.ovirt.en= gine.core.vdsbroker.irsbroker.GetImageInfoVDSCommand] (pool-6-thread-48) [5= 7faac34] START, GetImageInfoVDSCommand( storagePoolId =3D 5849b030-626e-47c= b-ad90-3ce782d831b3, ignoreFailoverLimit =3D false, storageDomainId =3D 340= 1420d-6918-49f9-b9e2-23ba47949f29, imageGroupId =3D 374e7d38-ebfe-4fab-a6ec= -727e9ef9733c, imageId =3D 54e3344d-45f0-4876-b4a9-cdad98fac7a5), log id: 5= 1aaf563<br />2013-09-10 16:35:56,954 INFO [org.ovirt.engine.core.vdsb= roker.irsbroker.GetImageInfoVDSCommand] (pool-6-thread-48) [57faac34] FINIS= H, GetImageInfoVDSCommand, return: org.ovirt.engine.core.common.businessent= ities.DiskImage@dd64762e, log id: 51aaf563<br />2013-09-10 16:35:57,000 INF= O [org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand] (pool-6-thr= ead-48) START, SetVmStatusVDSCommand( vmId =3D dc1ac7da-fef2-48e4-ab91-309b= 3a1fd2c0, status =3D Down), log id: 45208621<br />2013-09-10 16:35:57,007 I= NFO [org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand] (pool-6-t= hread-48) FINISH, SetVmStatusVDSCommand, log id: 45208621<br />2013-09-10 1= 6:35:57,008 INFO [org.ovirt.engine.core.bll.ImportVmCommand] (pool-6-= thread-48) Lock freed to object EngineLock [exclusiveLocks=3D key: VM1 valu= e: VM_NAME<br />2013-09-10 16:35:57,051 INFO [org.ovirt.engine.core.d= al.dbbroker.auditloghandling.AuditLogDirector] (pool-6-thread-48) Correlati= on ID: 62df3606, Job ID: 7134d7b0-7878-4bb3-970f-4128c1e818e7, Call Stack: = null, Custom Event ID: -1, Message: Vm VM1 was imported successfully to Dat= a Center Default, Cluster Default<br />2013-09-10 16:35:57,053 INFO [= org.ovirt.engine.core.bll.CommandAsyncTask] (pool-6-thread-48) CommandAsync= Task::HandleEndActionResult [within thread]: EndAction for action type Impo= rtVm completed, handling the result.<br />2013-09-10 16:35:57,054 INFO = ; [org.ovirt.engine.core.bll.CommandAsyncTask] (pool-6-thread-48) CommandAs= yncTask::HandleEndActionResult [within thread]: EndAction for action type I= mportVm succeeded, clearing tasks.<br />2013-09-10 16:35:57,068 INFO = [org.ovirt.engine.core.bll.SPMAsyncTask] (pool-6-thread-48) SPMAsyncTask::C= learAsyncTask: Attempting to clear task f587a842-272f-4a86-8c15-7451a39a7f4= 2<br />2013-09-10 16:35:57,070 INFO [org.ovirt.engine.core.vdsbroker.= irsbroker.SPMClearTaskVDSCommand] (pool-6-thread-48) START, SPMClearTaskVDS= Command( storagePoolId =3D 5849b030-626e-47cb-ad90-3ce782d831b3, ignoreFail= overLimit =3D false, taskId =3D f587a842-272f-4a86-8c15-7451a39a7f42), log = id: 57f89137<br />2013-09-10 16:35:57,102 INFO [org.ovirt.engine.core= .vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (pool-6-thread-48) START, HSMC= learTaskVDSCommand(HostName =3D HOST1, HostId =3D 6593afcd-9e7f-4928-a914-5= ad1eeaa3999, taskId=3Df587a842-272f-4a86-8c15-7451a39a7f42), log id: 5df00<= br />2013-09-11 16:35:01,795 INFO [org.ovirt.engine.core.bll.InitVdsO= nUpCommand] (DefaultQuartzScheduler_Worker-81) Running command: InitVdsOnUp= Command internal: true. Entities affected : ID: 5849b030-626e-47cb-ad= 90-3ce782d831b3 Type: StoragePool<br />2013-09-11 16:35:01,799 INFO [= org.ovirt.engine.core.bll.storage.ConnectHostToStoragePoolServersCommand] (= DefaultQuartzScheduler_Worker-81) Running command: ConnectHostToStoragePool= ServersCommand internal: true. Entities affected : ID: 5849b030-626e-= 47cb-ad90-3ce782d831b3 Type: StoragePool<br />2013-09-11 16:35:01,854 INFO&= nbsp; [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStoragePoolVDSComma= nd] (pool-6-thread-50) START, ConnectStoragePoolVDSCommand(HostName =3D BBG= LU012, HostId =3D 6593afcd-9e7f-4928-a914-5ad1eeaa3999, storagePoolId =3D 5= 849b030-626e-47cb-ad90-3ce782d831b3, vds_spm_id =3D 1, masterDomainId =3D 3= 401420d-6918-49f9-b9e2-23ba47949f29, masterVersion =3D 1), log id: 14e339aa= <br />2013-09-11 16:35:09,112 INFO [org.ovirt.engine.core.vdsbroker.v= dsbroker.ConnectStoragePoolVDSCommand] (pool-6-thread-50) Command org.ovirt= .engine.core.vdsbroker.vdsbroker.ConnectStoragePoolVDSCommand return value<= br />2013-09-11 16:35:09,114 INFO [org.ovirt.engine.core.vdsbroker.vd= sbroker.ConnectStoragePoolVDSCommand] (pool-6-thread-50) HostName =3D HOST1= <br />2013-09-11 16:35:09,114 ERROR [org.ovirt.engine.core.vdsbroker.vdsbro= ker.ConnectStoragePoolVDSCommand] (pool-6-thread-50) Command ConnectStorage= PoolVDS execution failed. Exception: IRSNoMasterDomainException: IRSGeneric= Exception: IRSErrorException: IRSNoMasterDomainException: Cannot find maste= r domain: 'spUUID=3D5849b030-626e-47cb-ad90-3ce782d831b3, msdUUID=3D3401420= d-6918-49f9-b9e2-23ba47949f29'<br />2013-09-11 16:35:09,115 INFO [org= .ovirt.engine.core.vdsbroker.vdsbroker.ConnectStoragePoolVDSCommand] (pool-= 6-thread-50) FINISH, ConnectStoragePoolVDSCommand, log id: 14e339aa<br />20= 13-09-11 16:35:09,116 ERROR [org.ovirt.engine.core.bll.InitVdsOnUpCommand] = (pool-6-thread-50) Could not connect host HOST1 to pool Default<br />2013-0= 9-11 16:35:09,184 INFO [org.ovirt.engine.core.bll.SetNonOperationalVd= sCommand] (DefaultQuartzScheduler_Worker-81) Running command: SetNonOperati= onalVdsCommand internal: true. Entities affected : ID: 6593afcd-9e7f-= 4928-a914-5ad1eeaa3999 Type: VDS<br />2013-09-11 16:35:09,207 INFO [o= rg.ovirt.engine.core.vdsbroker.SetVdsStatusVDSCommand] (DefaultQuartzSchedu= ler_Worker-81) START, SetVdsStatusVDSCommand(HostName =3D HOST1, HostId =3D= 6593afcd-9e7f-4928-a914-5ad1eeaa3999, status=3DNonOperational, nonOperatio= nalReason=3DSTORAGE_DOMAIN_UNREACHABLE), log id: 3c9dbd47<br />2013-09-11 1= 6:35:09,217 INFO [org.ovirt.engine.core.vdsbroker.SetVdsStatusVDSComm= and] (DefaultQuartzScheduler_Worker-81) FINISH, SetVdsStatusVDSCommand, log= id: 3c9dbd47<br />2013-09-11 16:35:09,225 INFO [org.ovirt.engine.cor= e.dal.dbbroker.auditloghandling.AuditLogDirector] (DefaultQuartzScheduler_W= orker-81) Correlation ID: 64e68249, Job ID: 355b71e9-f7b9-4554-800b-7b08a09= d9a12, Call Stack: null, Custom Event ID: -1, Message: Host HOST1 cannot ac= cess one of the Storage Domains attached to the Data Center Default. Settin= g Host state to Non-Operational.<br />2013-09-11 16:35:09,266 INFO [o= rg.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (Defau= ltQuartzScheduler_Worker-81) Correlation ID: null, Call Stack: null, Custom= Event ID: -1, Message: Power Management test failed for Host BBGLU012.Ther= e is no other host in the data center that can be used to test the power ma= nagement settings.<br />2013-09-11 16:35:09,275 INFO [org.ovirt.engin= e.core.dal.dbbroker.auditloghandling.AuditLogDirector] (DefaultQuartzSchedu= ler_Worker-81) Correlation ID: 1a32fa26, Call Stack: null, Custom Event ID:= -1, Message: Failed to connect Host HOST1 to Storage Pool Default<br />201= 3-09-11 16:35:09,320 INFO [org.ovirt.engine.core.bll.HandleVdsCpuFlag= sOrClusterChangedCommand] (DefaultQuartzScheduler_Worker-81) Running comman= d: HandleVdsCpuFlagsOrClusterChangedCommand internal: true. Entities affect= ed : ID: 6593afcd-9e7f-4928-a914-5ad1eeaa3999 Type: VDS<br />2013-09-= 11 16:35:09,352 INFO [org.ovirt.engine.core.bll.HandleVdsVersionComma= nd] (DefaultQuartzScheduler_Worker-81) Running command: HandleVdsVersionCom= mand internal: true. Entities affected : ID: 6593afcd-9e7f-4928-a914-= 5ad1eeaa3999 Type: VDS<br />2013-09-11 16:35:09,354 INFO [org.ovirt.e= ngine.core.vdsbroker.VdsUpdateRunTimeInfo] (DefaultQuartzScheduler_Worker-8= 1) Host 6593afcd-9e7f-4928-a914-5ad1eeaa3999 : HOST1 is already in NonOpera= tional status. SetNonOperationalVds command is skipped.<br />[root@bbgpas12= 9 ovirt-engine]# 2013-09-11 16:35:09,184 INFO [org.ovirt.engine.core.= bll.SetNonOperationalVdsCommand] (DefaultQuartzScheduler_Worker-81) Running= command: SetNonOperationalVdsCommand internal: true. Entities affected :&n= bsp; ID: 6593afcd-9e7f-4928-a914-5ad1eeaa3999 Type: VDS<br /><br />=C2=A0</= span></span> --========GMXBoundary239291378911044835950--
On Wed, Sep 11, 2013 at 10:50:44AM -0400, Hans-Joachim wrote:
Hello,
I run in troubles....
For a testing I completly powered off the oVirt Cluster (Engine as well as the the host).. and now my host is unable to fine the Master Domain
System: CentOS 6.4, vdsm-4.12.1-1.el6, oVirt Engine Version: 3.3.0-1.el6
Trace vdsm.log
Thread-98::DEBUG::2013-09-11 16:35:06,859::BindingXMLRPC::177::vds::(wrapper) client [192.168.1.29] Thread-98::DEBUG::2013-09-11 16:35:06,859::task::579::TaskManager.Task::(_updateState) Task=`b2a7a44f-8cb0-453a-bf52-16a200f992f9`::moving from state init -> state preparing Thread-98::INFO::2013-09-11 16:35:06,860::logUtils::44::dispatcher::(wrapper) Run and protect: connectStoragePool(spUUID='5849b030-626e-47cb-ad90-3ce782d831b3', hostID=1, scsiKey='5849b030-626e-47cb-ad90-3ce782d831b3', msdUUID='3401420d-6918-49f9-b9e2-23ba47949f29', masterVersion=1, options=None) Thread-98::DEBUG::2013-09-11 16:35:06,860::resourceManager::197::ResourceManager.Request::(__init__) ResName=`Storage.5849b030-626e-47cb-ad90-3ce782d831b3`ReqID=`079c6f43-9453-4598-a9f3-7056ad3a595e`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '1020' at '_connectStoragePool' Thread-98::DEBUG::2013-09-11 16:35:06,860::resourceManager::541::ResourceManager::(registerResource) Trying to register resource 'Storage.5849b030-626e-47cb-ad90-3ce782d831b3' for lock type 'exclusive' Thread-98::DEBUG::2013-09-11 16:35:06,861::resourceManager::600::ResourceManager::(registerResource) Resource 'Storage.5849b030-626e-47cb-ad90-3ce782d831b3' is free. Now locking as 'exclusive' (1 active user) Thread-98::DEBUG::2013-09-11 16:35:06,861::resourceManager::237::ResourceManager.Request::(grant) ResName=`Storage.5849b030-626e-47cb-ad90-3ce782d831b3`ReqID=`079c6f43-9453-4598-a9f3-7056ad3a595e`::Granted request Thread-98::INFO::2013-09-11 16:35:06,861::sp::680::Storage.StoragePool::(connect) Connect host #1 to the storage pool 5849b030-626e-47cb-ad90-3ce782d831b3 with master domain: 3401420d-6918-49f9-b9e2-23ba47949f29 (ver = 1) Thread-98::DEBUG::2013-09-11 16:35:06,862::lvm::483::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex Thread-98::DEBUG::2013-09-11 16:35:06,862::lvm::485::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex Thread-98::DEBUG::2013-09-11 16:35:06,862::lvm::494::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex Thread-98::DEBUG::2013-09-11 16:35:06,862::lvm::496::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex Thread-98::DEBUG::2013-09-11 16:35:06,863::lvm::514::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex Thread-98::DEBUG::2013-09-11 16:35:06,863::lvm::516::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex Thread-98::DEBUG::2013-09-11 16:35:06,863::misc::807::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage) Thread-98::DEBUG::2013-09-11 16:35:06,863::misc::809::SamplingMethod::(__call__) Got in to sampling method Thread-98::DEBUG::2013-09-11 16:35:06,863::misc::807::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan) Thread-98::DEBUG::2013-09-11 16:35:06,864::misc::809::SamplingMethod::(__call__) Got in to sampling method Thread-98::DEBUG::2013-09-11 16:35:06,864::iscsiadm::91::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None) Thread-98::DEBUG::2013-09-11 16:35:06,875::iscsiadm::91::Storage.Misc.excCmd::(_runCmd) FAILED: <err> = 'iscsiadm: No session found.\n'; <rc> = 21
Before the connectStoragePool attempt, vdsm.log should have had connectStorageServer. Does it? Is it successful?
Thread-98::DEBUG::2013-09-11 16:35:06,875::misc::817::SamplingMethod::(__call__) Returning last result Thread-98::DEBUG::2013-09-11 16:35:08,902::multipath::111::Storage.Misc.excCmd::(rescan) '/usr/bin/sudo -n /sbin/multipath' (cwd None) Thread-98::DEBUG::2013-09-11 16:35:08,916::multipath::111::Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0 Thread-98::DEBUG::2013-09-11 16:35:08,917::lvm::483::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex Thread-98::DEBUG::2013-09-11 16:35:08,917::lvm::485::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex Thread-98::DEBUG::2013-09-11 16:35:08,918::lvm::494::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex Thread-98::DEBUG::2013-09-11 16:35:08,918::lvm::496::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex Thread-98::DEBUG::2013-09-11 16:35:08,918::lvm::514::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex Thread-98::DEBUG::2013-09-11 16:35:08,918::lvm::516::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex Thread-98::DEBUG::2013-09-11 16:35:08,919::misc::817::SamplingMethod::(__call__) Returning last result Thread-98::ERROR::2013-09-11 16:35:08,919::sdc::137::Storage.StorageDomainCache::(_findDomain) looking for unfetched domain 3401420d-6918-49f9-b9e2-23ba47949f29 Thread-98::ERROR::2013-09-11 16:35:08,919::sdc::154::Storage.StorageDomainCache::(_findUnfetchedDomain) looking for domain 3401420d-6918-49f9-b9e2-23ba47949f29 Thread-98::DEBUG::2013-09-11 16:35:08,919::lvm::374::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex Thread-98::DEBUG::2013-09-11 16:35:08,921::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 = [ \'a|/dev/mapper/3600508b1001052395359564d53570200|\', \'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 3401420d-6918-49f9-b9e2-23ba47949f29' (cwd None) Thread-98::DEBUG::2013-09-11 16:35:09,096::lvm::311::Storage.Misc.excCmd::(cmd) FAILED: <err> = ' Volume group "3401420d-6918-49f9-b9e2-23ba47949f29" not found\n'; <rc> = 5 Thread-98::WARNING::2013-09-11 16:35:09,097::lvm::379::Storage.LVM::(_reloadvgs) lvm vgs failed: 5 [] [' Volume group "3401420d-6918-49f9-b9e2-23ba47949f29" not found'] Thread-98::DEBUG::2013-09-11 16:35:09,097::lvm::403::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex Thread-98::ERROR::2013-09-11 16:35:09,098::sdc::143::Storage.StorageDomainCache::(_findDomain) domain 3401420d-6918-49f9-b9e2-23ba47949f29 not found Thread-98::DEBUG::2013-09-11 16:35:09,099::resourceManager::615::ResourceManager::(releaseResource) Trying to release resource 'Storage.5849b030-626e-47cb-ad90-3ce782d831b3' Thread-98::DEBUG::2013-09-11 16:35:09,099::resourceManager::634::ResourceManager::(releaseResource) Released resource 'Storage.5849b030-626e-47cb-ad90-3ce782d831b3' (0 active users) Thread-98::DEBUG::2013-09-11 16:35:09,099::resourceManager::640::ResourceManager::(releaseResource) Resource 'Storage.5849b030-626e-47cb-ad90-3ce782d831b3' is free, finding out if anyone is waiting for it. Thread-98::DEBUG::2013-09-11 16:35:09,099::resourceManager::648::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.5849b030-626e-47cb-ad90-3ce782d831b3', Clearing records. Thread-98::ERROR::2013-09-11 16:35:09,100::task::850::TaskManager.Task::(_setError) Task=`b2a7a44f-8cb0-453a-bf52-16a200f992f9`::Unexpected error
Any idea, anyone, why this line is not followed by a proper traceback? (utterly unrelated - but worrisome - question)
Thread-98::DEBUG::2013-09-11 16:35:09,100::task::869::TaskManager.Task::(_run) Task=`b2a7a44f-8cb0-453a-bf52-16a200f992f9`::Task._run: b2a7a44f-8cb0-453a-bf52-16a200f992f9 ('5849b030-626e-47cb-ad90-3ce782d831b3', 1, '5849b030-626e-47cb-ad90-3ce782d831b3', '3401420d-6918-49f9-b9e2-23ba47949f29', 1) {} failed - stopping task Thread-98::DEBUG::2013-09-11 16:35:09,100::task::1194::TaskManager.Task::(stop) Task=`b2a7a44f-8cb0-453a-bf52-16a200f992f9`::stopping in state preparing (force False) Thread-98::DEBUG::2013-09-11 16:35:09,101::task::974::TaskManager.Task::(_decref) Task=`b2a7a44f-8cb0-453a-bf52-16a200f992f9`::ref 1 aborting True Thread-98::INFO::2013-09-11 16:35:09,101::task::1151::TaskManager.Task::(prepare) Task=`b2a7a44f-8cb0-453a-bf52-16a200f992f9`::aborting: Task is aborted: 'Cannot find master domain' - code 304 Thread-98::DEBUG::2013-09-11 16:35:09,101::task::1156::TaskManager.Task::(prepare) Task=`b2a7a44f-8cb0-453a-bf52-16a200f992f9`::Prepare: aborted: Cannot find master domain Thread-98::DEBUG::2013-09-11 16:35:09,101::task::974::TaskManager.Task::(_decref) Task=`b2a7a44f-8cb0-453a-bf52-16a200f992f9`::ref 0 aborting True Thread-98::DEBUG::2013-09-11 16:35:09,102::task::909::TaskManager.Task::(_doAbort) Task=`b2a7a44f-8cb0-453a-bf52-16a200f992f9`::Task._doAbort: force False Thread-98::DEBUG::2013-09-11 16:35:09,102::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-98::DEBUG::2013-09-11 16:35:09,102::task::579::TaskManager.Task::(_updateState) Task=`b2a7a44f-8cb0-453a-bf52-16a200f992f9`::moving from state preparing -> state aborting Thread-98::DEBUG::2013-09-11 16:35:09,102::task::534::TaskManager.Task::(__state_aborting) Task=`b2a7a44f-8cb0-453a-bf52-16a200f992f9`::_aborting: recover policy none Thread-98::DEBUG::2013-09-11 16:35:09,102::task::579::TaskManager.Task::(_updateState) Task=`b2a7a44f-8cb0-453a-bf52-16a200f992f9`::moving from state aborting -> state failed Thread-98::DEBUG::2013-09-11 16:35:09,103::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-98::DEBUG::2013-09-11 16:35:09,103::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-98::ERROR::2013-09-11 16:35:09,103::dispatcher::67::Storage.Dispatcher.Protect::(run) {'status': {'message': "Cannot find master domain: 'spUUID=5849b030-626e-47cb-ad90-3ce782d831b3, msdUUID=3401420d-6918-49f9-b9e2-23ba47949f29'", 'code': 304}}
On 09/12/2013 12:41 AM, Dan Kenigsberg wrote:
On Wed, Sep 11, 2013 at 10:50:44AM -0400, Hans-Joachim wrote:
Hello,
I run in troubles....
For a testing I completly powered off the oVirt Cluster (Engine as well as the the host).. and now my host is unable to fine the Master Domain
was this resolved? is there a bug tracking this?
System: CentOS 6.4, vdsm-4.12.1-1.el6, oVirt Engine Version: 3.3.0-1.el6
Trace vdsm.log
Thread-98::DEBUG::2013-09-11 16:35:06,859::BindingXMLRPC::177::vds::(wrapper) client [192.168.1.29] Thread-98::DEBUG::2013-09-11 16:35:06,859::task::579::TaskManager.Task::(_updateState) Task=`b2a7a44f-8cb0-453a-bf52-16a200f992f9`::moving from state init -> state preparing Thread-98::INFO::2013-09-11 16:35:06,860::logUtils::44::dispatcher::(wrapper) Run and protect: connectStoragePool(spUUID='5849b030-626e-47cb-ad90-3ce782d831b3', hostID=1, scsiKey='5849b030-626e-47cb-ad90-3ce782d831b3', msdUUID='3401420d-6918-49f9-b9e2-23ba47949f29', masterVersion=1, options=None) Thread-98::DEBUG::2013-09-11 16:35:06,860::resourceManager::197::ResourceManager.Request::(__init__) ResName=`Storage.5849b030-626e-47cb-ad90-3ce782d831b3`ReqID=`079c6f43-9453-4598-a9f3-7056ad3a595e`::Request was made in '/usr/share/vdsm/storage/hsm.py' line '1020' at '_connectStoragePool' Thread-98::DEBUG::2013-09-11 16:35:06,860::resourceManager::541::ResourceManager::(registerResource) Trying to register resource 'Storage.5849b030-626e-47cb-ad90-3ce782d831b3' for lock type 'exclusive' Thread-98::DEBUG::2013-09-11 16:35:06,861::resourceManager::600::ResourceManager::(registerResource) Resource 'Storage.5849b030-626e-47cb-ad90-3ce782d831b3' is free. Now locking as 'exclusive' (1 active user) Thread-98::DEBUG::2013-09-11 16:35:06,861::resourceManager::237::ResourceManager.Request::(grant) ResName=`Storage.5849b030-626e-47cb-ad90-3ce782d831b3`ReqID=`079c6f43-9453-4598-a9f3-7056ad3a595e`::Granted request Thread-98::INFO::2013-09-11 16:35:06,861::sp::680::Storage.StoragePool::(connect) Connect host #1 to the storage pool 5849b030-626e-47cb-ad90-3ce782d831b3 with master domain: 3401420d-6918-49f9-b9e2-23ba47949f29 (ver = 1) Thread-98::DEBUG::2013-09-11 16:35:06,862::lvm::483::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex Thread-98::DEBUG::2013-09-11 16:35:06,862::lvm::485::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex Thread-98::DEBUG::2013-09-11 16:35:06,862::lvm::494::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex Thread-98::DEBUG::2013-09-11 16:35:06,862::lvm::496::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex Thread-98::DEBUG::2013-09-11 16:35:06,863::lvm::514::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex Thread-98::DEBUG::2013-09-11 16:35:06,863::lvm::516::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex Thread-98::DEBUG::2013-09-11 16:35:06,863::misc::807::SamplingMethod::(__call__) Trying to enter sampling method (storage.sdc.refreshStorage) Thread-98::DEBUG::2013-09-11 16:35:06,863::misc::809::SamplingMethod::(__call__) Got in to sampling method Thread-98::DEBUG::2013-09-11 16:35:06,863::misc::807::SamplingMethod::(__call__) Trying to enter sampling method (storage.iscsi.rescan) Thread-98::DEBUG::2013-09-11 16:35:06,864::misc::809::SamplingMethod::(__call__) Got in to sampling method Thread-98::DEBUG::2013-09-11 16:35:06,864::iscsiadm::91::Storage.Misc.excCmd::(_runCmd) '/usr/bin/sudo -n /sbin/iscsiadm -m session -R' (cwd None) Thread-98::DEBUG::2013-09-11 16:35:06,875::iscsiadm::91::Storage.Misc.excCmd::(_runCmd) FAILED: <err> = 'iscsiadm: No session found.\n'; <rc> = 21
Before the connectStoragePool attempt, vdsm.log should have had connectStorageServer. Does it? Is it successful?
Thread-98::DEBUG::2013-09-11 16:35:06,875::misc::817::SamplingMethod::(__call__) Returning last result Thread-98::DEBUG::2013-09-11 16:35:08,902::multipath::111::Storage.Misc.excCmd::(rescan) '/usr/bin/sudo -n /sbin/multipath' (cwd None) Thread-98::DEBUG::2013-09-11 16:35:08,916::multipath::111::Storage.Misc.excCmd::(rescan) SUCCESS: <err> = ''; <rc> = 0 Thread-98::DEBUG::2013-09-11 16:35:08,917::lvm::483::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' got the operation mutex Thread-98::DEBUG::2013-09-11 16:35:08,917::lvm::485::OperationMutex::(_invalidateAllPvs) Operation 'lvm invalidate operation' released the operation mutex Thread-98::DEBUG::2013-09-11 16:35:08,918::lvm::494::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' got the operation mutex Thread-98::DEBUG::2013-09-11 16:35:08,918::lvm::496::OperationMutex::(_invalidateAllVgs) Operation 'lvm invalidate operation' released the operation mutex Thread-98::DEBUG::2013-09-11 16:35:08,918::lvm::514::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' got the operation mutex Thread-98::DEBUG::2013-09-11 16:35:08,918::lvm::516::OperationMutex::(_invalidateAllLvs) Operation 'lvm invalidate operation' released the operation mutex Thread-98::DEBUG::2013-09-11 16:35:08,919::misc::817::SamplingMethod::(__call__) Returning last result Thread-98::ERROR::2013-09-11 16:35:08,919::sdc::137::Storage.StorageDomainCache::(_findDomain) looking for unfetched domain 3401420d-6918-49f9-b9e2-23ba47949f29 Thread-98::ERROR::2013-09-11 16:35:08,919::sdc::154::Storage.StorageDomainCache::(_findUnfetchedDomain) looking for domain 3401420d-6918-49f9-b9e2-23ba47949f29 Thread-98::DEBUG::2013-09-11 16:35:08,919::lvm::374::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' got the operation mutex Thread-98::DEBUG::2013-09-11 16:35:08,921::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 = [ \'a|/dev/mapper/3600508b1001052395359564d53570200|\', \'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 3401420d-6918-49f9-b9e2-23ba47949f29' (cwd None) Thread-98::DEBUG::2013-09-11 16:35:09,096::lvm::311::Storage.Misc.excCmd::(cmd) FAILED: <err> = ' Volume group "3401420d-6918-49f9-b9e2-23ba47949f29" not found\n'; <rc> = 5 Thread-98::WARNING::2013-09-11 16:35:09,097::lvm::379::Storage.LVM::(_reloadvgs) lvm vgs failed: 5 [] [' Volume group "3401420d-6918-49f9-b9e2-23ba47949f29" not found'] Thread-98::DEBUG::2013-09-11 16:35:09,097::lvm::403::OperationMutex::(_reloadvgs) Operation 'lvm reload operation' released the operation mutex Thread-98::ERROR::2013-09-11 16:35:09,098::sdc::143::Storage.StorageDomainCache::(_findDomain) domain 3401420d-6918-49f9-b9e2-23ba47949f29 not found Thread-98::DEBUG::2013-09-11 16:35:09,099::resourceManager::615::ResourceManager::(releaseResource) Trying to release resource 'Storage.5849b030-626e-47cb-ad90-3ce782d831b3' Thread-98::DEBUG::2013-09-11 16:35:09,099::resourceManager::634::ResourceManager::(releaseResource) Released resource 'Storage.5849b030-626e-47cb-ad90-3ce782d831b3' (0 active users) Thread-98::DEBUG::2013-09-11 16:35:09,099::resourceManager::640::ResourceManager::(releaseResource) Resource 'Storage.5849b030-626e-47cb-ad90-3ce782d831b3' is free, finding out if anyone is waiting for it. Thread-98::DEBUG::2013-09-11 16:35:09,099::resourceManager::648::ResourceManager::(releaseResource) No one is waiting for resource 'Storage.5849b030-626e-47cb-ad90-3ce782d831b3', Clearing records. Thread-98::ERROR::2013-09-11 16:35:09,100::task::850::TaskManager.Task::(_setError) Task=`b2a7a44f-8cb0-453a-bf52-16a200f992f9`::Unexpected error
Any idea, anyone, why this line is not followed by a proper traceback? (utterly unrelated - but worrisome - question)
is there a bug tracking this?
Thread-98::DEBUG::2013-09-11 16:35:09,100::task::869::TaskManager.Task::(_run) Task=`b2a7a44f-8cb0-453a-bf52-16a200f992f9`::Task._run: b2a7a44f-8cb0-453a-bf52-16a200f992f9 ('5849b030-626e-47cb-ad90-3ce782d831b3', 1, '5849b030-626e-47cb-ad90-3ce782d831b3', '3401420d-6918-49f9-b9e2-23ba47949f29', 1) {} failed - stopping task Thread-98::DEBUG::2013-09-11 16:35:09,100::task::1194::TaskManager.Task::(stop) Task=`b2a7a44f-8cb0-453a-bf52-16a200f992f9`::stopping in state preparing (force False) Thread-98::DEBUG::2013-09-11 16:35:09,101::task::974::TaskManager.Task::(_decref) Task=`b2a7a44f-8cb0-453a-bf52-16a200f992f9`::ref 1 aborting True Thread-98::INFO::2013-09-11 16:35:09,101::task::1151::TaskManager.Task::(prepare) Task=`b2a7a44f-8cb0-453a-bf52-16a200f992f9`::aborting: Task is aborted: 'Cannot find master domain' - code 304 Thread-98::DEBUG::2013-09-11 16:35:09,101::task::1156::TaskManager.Task::(prepare) Task=`b2a7a44f-8cb0-453a-bf52-16a200f992f9`::Prepare: aborted: Cannot find master domain Thread-98::DEBUG::2013-09-11 16:35:09,101::task::974::TaskManager.Task::(_decref) Task=`b2a7a44f-8cb0-453a-bf52-16a200f992f9`::ref 0 aborting True Thread-98::DEBUG::2013-09-11 16:35:09,102::task::909::TaskManager.Task::(_doAbort) Task=`b2a7a44f-8cb0-453a-bf52-16a200f992f9`::Task._doAbort: force False Thread-98::DEBUG::2013-09-11 16:35:09,102::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-98::DEBUG::2013-09-11 16:35:09,102::task::579::TaskManager.Task::(_updateState) Task=`b2a7a44f-8cb0-453a-bf52-16a200f992f9`::moving from state preparing -> state aborting Thread-98::DEBUG::2013-09-11 16:35:09,102::task::534::TaskManager.Task::(__state_aborting) Task=`b2a7a44f-8cb0-453a-bf52-16a200f992f9`::_aborting: recover policy none Thread-98::DEBUG::2013-09-11 16:35:09,102::task::579::TaskManager.Task::(_updateState) Task=`b2a7a44f-8cb0-453a-bf52-16a200f992f9`::moving from state aborting -> state failed Thread-98::DEBUG::2013-09-11 16:35:09,103::resourceManager::939::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {} Thread-98::DEBUG::2013-09-11 16:35:09,103::resourceManager::976::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-98::ERROR::2013-09-11 16:35:09,103::dispatcher::67::Storage.Dispatcher.Protect::(run) {'status': {'message': "Cannot find master domain: 'spUUID=5849b030-626e-47cb-ad90-3ce782d831b3, msdUUID=3401420d-6918-49f9-b9e2-23ba47949f29'", 'code': 304}}
_______________________________________________ Users mailing list Users@ovirt.org http://lists.ovirt.org/mailman/listinfo/users
participants (3)
-
Dan Kenigsberg -
Hans-Joachim -
Itamar Heim