9:50 a.m.
--========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 /=
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=
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--
4:41 p.m.
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}}
3:54 p.m.
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(a)ovirt.org
http://lists.ovirt.org/mailman/listinfo/users
4115
days inactive
4120
days old
2 comments
3 participants
participants (3)
-
Dan Kenigsberg -
Hans-Joachim -
Itamar Heim