[ovirt-users] SPM and Task error ...

Thursday, 25 July 2019

  Hi all,
my ovirt cluster has got 3 Hypervisors runnig Centos 7.5.1804 vdsm is 
4.20.39.1-1.el7,
ovirt engine is 4.2.4.5-1.el7, the storage systems are HP MSA P2000 and 
2050 (fibre channel).

I need to stop one of the hypervisors for maintenance but this system is 
the storage pool manager.

For this reason I decided to manually activate SPM in one of the other 
nodes but this operation is not
successful.

In the ovirt engine (engine.log) the error is this:

2019-07-25 12:39:16,744+02 INFO 
[org.ovirt.engine.core.bll.storage.pool.ForceSelectSPMCommand] (default 
task-30) [7c374384-f884-4dc9-87d0-7af27dce706b] Running command: 
ForceSelectSPMCommand internal: false. Entities affected : ID: 
81c9bd3c-ae0a-467f-bf7f-63ab30cd8d9e Type: VDSAction group 
MANIPULATE_HOST with role type ADMIN
2019-07-25 12:39:16,745+02 INFO 
[org.ovirt.engine.core.vdsbroker.irsbroker.SpmStopOnIrsVDSCommand] 
(default task-30) [7c374384-f884-4dc9-87d0-7af27dce706b] START, 
SpmStopOnIrsVDSCommand( 
SpmStopOnIrsVDSCommandParameters:{storagePoolId='18d57688-6ed4-43b8-bd7c-0665b55950b7',

ignoreFailoverLimit='false'}), log id: 37bf4639
2019-07-25 12:39:16,747+02 INFO 
[org.ovirt.engine.core.vdsbroker.irsbroker.ResetIrsVDSCommand] (default 
task-30) [7c374384-f884-4dc9-87d0-7af27dce706b] START, 
ResetIrsVDSCommand( 
ResetIrsVDSCommandParameters:{storagePoolId='18d57688-6ed4-43b8-bd7c-0665b55950b7',

ignoreFailoverLimit='false', 
vdsId='751f3e99-b95e-4c31-bc38-77f5661a0bdc', 
ignoreStopFailed='false'}), log id: 2522686f
2019-07-25 12:39:16,749+02 INFO 
[org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStopVDSCommand] (default 
task-30) [7c374384-f884-4dc9-87d0-7af27dce706b] START, 
SpmStopVDSCommand(HostName = infn-vm05.management, 
SpmStopVDSCommandParameters:{hostId='751f3e99-b95e-4c31-bc38-77f5661a0bdc', 
storagePoolId='18d57688-6ed4-43b8-bd7c-0665b55950b7'}), log id: 1810fd8b
2019-07-25 12:39:16,758+02 *ERROR* 
[org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStopVDSCommand] (default 
task-30) [7c374384-f884-4dc9-87d0-7af27dce706b] SpmStopVDSCommand::Not 
stopping SPM on vds 'infn-vm05.management', pool id 
'18d57688-6ed4-43b8-bd7c-0665b55950b7' as there are uncleared tasks 
'Task 'fdcf4d1b-82fe-49a6-b233-323ebe568f8e', status 'running''
2019-07-25 12:39:16,758+02 INFO 
[org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStopVDSCommand] (default 
task-30) [7c374384-f884-4dc9-87d0-7af27dce706b] FINISH, 
SpmStopVDSCommand, log id: 1810fd8b
2019-07-25 12:39:16,758+02 INFO 
[org.ovirt.engine.core.vdsbroker.irsbroker.ResetIrsVDSCommand] (default 
task-30) [7c374384-f884-4dc9-87d0-7af27dce706b] FINISH, 
ResetIrsVDSCommand, log id: 2522686f
2019-07-25 12:39:16,758+02 INFO 
[org.ovirt.engine.core.vdsbroker.irsbroker.SpmStopOnIrsVDSCommand] 
(default task-30) [7c374384-f884-4dc9-87d0-7af27dce706b] FINISH, 
SpmStopOnIrsVDSCommand, log id: 37bf4639
2019-07-25 12:39:16,760+02 *ERROR* 
[org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] 
(default task-30) [7c374384-f884-4dc9-87d0-7af27dce706b] EVENT_ID: 
USER_FORCE_SELECTED_SPM_STOP_FAILED(4,096), Failed to force select 
infn-vm07.management as the SPM due to a failure to stop the current SPM.

while in the hypervisor (SPM) vdsm.log:

2019-07-25 12:39:16,744+02 INFO 
[org.ovirt.engine.core.bll.storage.pool.ForceSelectSPMCommand] (default 
task-30) [7c374384-f884-4dc9-87d0-7af27dce706b] Running command: 
ForceSelectSPMCommand internal: false. Entities affected : ID: 
81c9bd3c-ae0a-467f-bf7f-63ab30cd8d9e Type: VDSAction group 
MANIPULATE_HOST with role type ADMIN
2019-07-25 12:39:16,745+02 INFO 
[org.ovirt.engine.core.vdsbroker.irsbroker.SpmStopOnIrsVDSCommand] 
(default task-30) [7c374384-f884-4dc9-87d0-7af27dce706b] START, 
SpmStopOnIrsVDSCommand( 
SpmStopOnIrsVDSCommandParameters:{storagePoolId='18d57688-6ed4-43b8-bd7c-0665b55950b7',

ignoreFailoverLimit='false'}), log id: 37bf4639
2019-07-25 12:39:16,747+02 INFO 
[org.ovirt.engine.core.vdsbroker.irsbroker.ResetIrsVDSCommand] (default 
task-30) [7c374384-f884-4dc9-87d0-7af27dce706b] START, 
ResetIrsVDSCommand( 
ResetIrsVDSCommandParameters:{storagePoolId='18d57688-6ed4-43b8-bd7c-0665b55950b7',

ignoreFailoverLimit='false', 
vdsId='751f3e99-b95e-4c31-bc38-77f5661a0bdc', 
ignoreStopFailed='false'}), log id: 2522686f
2019-07-25 12:39:16,749+02 INFO 
[org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStopVDSCommand] (default 
task-30) [7c374384-f884-4dc9-87d0-7af27dce706b] START, 
SpmStopVDSCommand(HostName = infn-vm05.management, 
SpmStopVDSCommandParameters:{hostId='751f3e99-b95e-4c31-bc38-77f5661a0bdc', 
storagePoolId='18d57688-6ed4-43b8-bd7c-0665b55950b7'}), log id: 1810fd8b
2019-07-25 12:39:16,758+02 *ERROR* 
[org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStopVDSCommand] (default 
task-30) [7c374384-f884-4dc9-87d0-7af27dce706b] SpmStopVDSCommand::Not 
stopping SPM on vds 'infn-vm05.management', pool id 
'18d57688-6ed4-43b8-bd7c-0665b55950b7' as there are uncleared tasks 
'Task 'fdcf4d1b-82fe-49a6-b233-323ebe568f8e', status 'running''
2019-07-25 12:39:16,758+02 INFO 
[org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStopVDSCommand] (default 
task-30) [7c374384-f884-4dc9-87d0-7af27dce706b] FINISH, 
SpmStopVDSCommand, log id: 1810fd8b
2019-07-25 12:39:16,758+02 INFO 
[org.ovirt.engine.core.vdsbroker.irsbroker.ResetIrsVDSCommand] (default 
task-30) [7c374384-f884-4dc9-87d0-7af27dce706b] FINISH, 
ResetIrsVDSCommand, log id: 2522686f
2019-07-25 12:39:16,758+02 INFO 
[org.ovirt.engine.core.vdsbroker.irsbroker.SpmStopOnIrsVDSCommand] 
(default task-30) [7c374384-f884-4dc9-87d0-7af27dce706b] FINISH, 
SpmStopOnIrsVDSCommand, log id: 37bf4639
2019-07-25 12:39:16,760+02 *ERROR* 
[org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] 
(default task-30) [7c374384-f884-4dc9-87d0-7af27dce706b] EVENT_ID: 
USER_FORCE_SELECTED_SPM_STOP_FAILED(4,096), Failed to force select 
infn-vm07.management as the SPM due to a failure to stop the current SPM.
2019-07-25 12:39:18,660+02 INFO 
[org.ovirt.engine.core.bll.tasks.SPMAsyncTask] 
(EE-ManagedThreadFactory-engineScheduled-Thread-67) [] Task id 
'fdcf4d1b-82fe-49a6-b233-323ebe568f8e' has passed pre-polling period 
time and should be polled. Pre-polling period is 60000 millis.
2019-07-25 12:39:18,660+02 INFO 
[org.ovirt.engine.core.bll.tasks.SPMAsyncTask] 
(EE-ManagedThreadFactory-engineScheduled-Thread-67) [] Task id 
'fdcf4d1b-82fe-49a6-b233-323ebe568f8e' has passed pre-polling period 
time and should be polled. Pre-polling period is 60000 millis.
2019-07-25 12:39:18,750+02 INFO 
[org.ovirt.engine.core.bll.tasks.SPMAsyncTask] 
(EE-ManagedThreadFactory-engineScheduled-Thread-67) [] Task id 
'fdcf4d1b-82fe-49a6-b233-323ebe568f8e' has passed pre-polling period 
time and should be polled. Pre-polling period is 60000 millis.
2019-07-25 12:39:18,750+02 *ERROR* 
[org.ovirt.engine.core.bll.tasks.SPMAsyncTask] 
(EE-ManagedThreadFactory-engineScheduled-Thread-67) [] 
BaseAsyncTask::logEndTaskFailure: Task 
'fdcf4d1b-82fe-49a6-b233-323ebe568f8e' (Parent Command 'Unknown', 
Parameters Type 
'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters') ended 
with failure:
2019-07-25 12:39:18,750+02 INFO 
[org.ovirt.engine.core.bll.tasks.SPMAsyncTask] 
(EE-ManagedThreadFactory-engineScheduled-Thread-67) [] 
SPMAsyncTask::ClearAsyncTask: Attempting to clear task 
'fdcf4d1b-82fe-49a6-b233-323ebe568f8e'
2019-07-25 12:39:18,751+02 INFO 
[org.ovirt.engine.core.vdsbroker.irsbroker.SPMClearTaskVDSCommand] 
(EE-ManagedThreadFactory-engineScheduled-Thread-67) [] START, 
SPMClearTaskVDSCommand( 
SPMTaskGuidBaseVDSCommandParameters:{storagePoolId='18d57688-6ed4-43b8-bd7c-0665b55950b7',

ignoreFailoverLimit='false', 
taskId='fdcf4d1b-82fe-49a6-b233-323ebe568f8e'}), log id: 34ae2b2f
2019-07-25 12:39:18,752+02 INFO 
[org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] 
(EE-ManagedThreadFactory-engineScheduled-Thread-67) [] START, 
HSMClearTaskVDSCommand(HostName = infn-vm05.management, 
HSMTaskGuidBaseVDSCommandParameters:{hostId='751f3e99-b95e-4c31-bc38-77f5661a0bdc',

taskId='fdcf4d1b-82fe-49a6-b233-323ebe568f8e'}), log id: d3a78ad
2019-07-25 12:39:18,757+02 INFO 
[org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] 
(EE-ManagedThreadFactory-engineScheduled-Thread-67) [] FINISH, 
HSMClearTaskVDSCommand, log id: d3a78ad
2019-07-25 12:39:18,757+02 INFO 
[org.ovirt.engine.core.vdsbroker.irsbroker.SPMClearTaskVDSCommand] 
(EE-ManagedThreadFactory-engineScheduled-Thread-67) [] FINISH, 
SPMClearTaskVDSCommand, log id: 34ae2b2f
2019-07-25 12:39:18,757+02 INFO 
[org.ovirt.engine.core.bll.tasks.SPMAsyncTask] 
(EE-ManagedThreadFactory-engineScheduled-Thread-67) [] 
SPMAsyncTask::ClearAsyncTask: At time of attempt to clear task 
'fdcf4d1b-82fe-49a6-b233-323ebe568f8e' the response code was 
'TaskStateError' and message was 'Operation is not allowed in this task 
state: ("can't clean in state running",)'. Task will not be cleaned
2019-07-25 12:39:18,757+02 INFO 
[org.ovirt.engine.core.bll.tasks.SPMAsyncTask] 
(EE-ManagedThreadFactory-engineScheduled-Thread-67) [] 
BaseAsyncTask::onTaskEndSuccess: Task 
'fdcf4d1b-82fe-49a6-b233-323ebe568f8e' (Parent Command 'Unknown', 
Parameters Type 
'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters') ended 
successfully.
2019-07-25 12:39:18,757+02 INFO 
[org.ovirt.engine.core.bll.tasks.SPMAsyncTask] 
(EE-ManagedThreadFactory-engineScheduled-Thread-67) [] 
SPMAsyncTask::ClearAsyncTask: Attempting to clear task 
'fdcf4d1b-82fe-49a6-b233-323ebe568f8e'
2019-07-25 12:39:18,758+02 INFO 
[org.ovirt.engine.core.vdsbroker.irsbroker.SPMClearTaskVDSCommand] 
(EE-ManagedThreadFactory-engineScheduled-Thread-67) [] START, 
SPMClearTaskVDSCommand( 
SPMTaskGuidBaseVDSCommandParameters:{storagePoolId='18d57688-6ed4-43b8-bd7c-0665b55950b7',

ignoreFailoverLimit='false', 
taskId='fdcf4d1b-82fe-49a6-b233-323ebe568f8e'}), log id: 42de0c2b
2019-07-25 12:39:18,759+02 INFO 
[org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] 
(EE-ManagedThreadFactory-engineScheduled-Thread-67) [] START, 
HSMClearTaskVDSCommand(HostName = infn-vm05.management, 
HSMTaskGuidBaseVDSCommandParameters:{hostId='751f3e99-b95e-4c31-bc38-77f5661a0bdc',

taskId='fdcf4d1b-82fe-49a6-b233-323ebe568f8e'}), log id: 4895c79c
2019-07-25 12:39:18,764+02 INFO 
[org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] 
(EE-ManagedThreadFactory-engineScheduled-Thread-67) [] FINISH, 
HSMClearTaskVDSCommand, log id: 4895c79c
2019-07-25 12:39:18,764+02 INFO 
[org.ovirt.engine.core.vdsbroker.irsbroker.SPMClearTaskVDSCommand] 
(EE-ManagedThreadFactory-engineScheduled-Thread-67) [] FINISH, 
SPMClearTaskVDSCommand, log id: 42de0c2b
2019-07-25 12:39:18,764+02 INFO 
[org.ovirt.engine.core.bll.tasks.SPMAsyncTask] 
(EE-ManagedThreadFactory-engineScheduled-Thread-67) [] 
SPMAsyncTask::ClearAsyncTask: At time of attempt to clear task 
'fdcf4d1b-82fe-49a6-b233-323ebe568f8e' the response code was 
'TaskStateError' and message was 'Operation is not allowed in this task 
state: ("can't clean in state running",)'. Task will not be cleaned
2019-07-25 12:39:18,764+02 INFO 
[org.ovirt.engine.core.bll.tasks.SPMAsyncTask] 
(EE-ManagedThreadFactory-engineScheduled-Thread-67) [] Task id 
'fdcf4d1b-82fe-49a6-b233-323ebe568f8e' has passed pre-polling period 
time and should be polled. Pre-polling period is 60000 millis.
2019-07-25 12:39:18,764+02 INFO 
[org.ovirt.engine.core.bll.tasks.AsyncTaskManager] 
(EE-ManagedThreadFactory-engineScheduled-Thread-67) [] Cleaning zombie 
tasks: Clearing async task 'Unknown' that started at 'Fri May 03 
14:48:50 CEST 2019'
2019-07-25 12:39:18,764+02 INFO 
[org.ovirt.engine.core.bll.tasks.SPMAsyncTask] 
(EE-ManagedThreadFactory-engineScheduled-Thread-67) [] 
SPMAsyncTask::ClearAsyncTask: Attempting to clear task 
'fdcf4d1b-82fe-49a6-b233-323ebe568f8e'
2019-07-25 12:39:18,765+02 INFO 
[org.ovirt.engine.core.vdsbroker.irsbroker.SPMClearTaskVDSCommand] 
(EE-ManagedThreadFactory-engineScheduled-Thread-67) [] START, 
SPMClearTaskVDSCommand( 
SPMTaskGuidBaseVDSCommandParameters:{storagePoolId='18d57688-6ed4-43b8-bd7c-0665b55950b7',

ignoreFailoverLimit='false', 
taskId='fdcf4d1b-82fe-49a6-b233-323ebe568f8e'}), log id: da77af2
2019-07-25 12:39:18,766+02 INFO 
[org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] 
(EE-ManagedThreadFactory-engineScheduled-Thread-67) [] START, 
HSMClearTaskVDSCommand(HostName = infn-vm05.management, 
HSMTaskGuidBaseVDSCommandParameters:{hostId='751f3e99-b95e-4c31-bc38-77f5661a0bdc',

taskId='fdcf4d1b-82fe-49a6-b233-323ebe568f8e'}), log id: 530694fb
2019-07-25 12:39:18,771+02 INFO 
[org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] 
(EE-ManagedThreadFactory-engineScheduled-Thread-67) [] FINISH, 
HSMClearTaskVDSCommand, log id: 530694fb
2019-07-25 12:39:18,771+02 INFO 
[org.ovirt.engine.core.vdsbroker.irsbroker.SPMClearTaskVDSCommand] 
(EE-ManagedThreadFactory-engineScheduled-Thread-67) [] FINISH, 
SPMClearTaskVDSCommand, log id: da77af2
2019-07-25 12:39:18,771+02 INFO 
[org.ovirt.engine.core.bll.tasks.SPMAsyncTask] 
(EE-ManagedThreadFactory-engineScheduled-Thread-67) [] 
SPMAsyncTask::ClearAsyncTask: At time of attempt to clear task 
'fdcf4d1b-82fe-49a6-b233-323ebe568f8e' the response code was 
'TaskStateError' and message was 'Operation is not allowed in this task 
state: ("can't clean in state running",)'. Task will not be cleaned

there is some relation between this error and a task that has remained 
hanging, from SPM server:

# vdsm-client Task  getInfo taskID=fdcf4d1b-82fe-49a6-b233-323ebe568f8e
{
     "verb": "prepareMerge",
     "id": "fdcf4d1b-82fe-49a6-b233-323ebe568f8e"
}

# vdsm-client Task  getStatus taskID=fdcf4d1b-82fe-49a6-b233-323ebe568f8e
{
     "message": "running job 1 of 1",
     "code": 0,
     "taskID": "fdcf4d1b-82fe-49a6-b233-323ebe568f8e",
     "taskResult": "",
     "taskState": "running"
}

How can I solve this problem ?

Thanks a lot for your help !!
Best Regards
Enrico

-- 
_______________________________________________________________________

Enrico Becchetti                    Servizio di Calcolo e Reti

Istituto Nazionale di Fisica Nucleare - Sezione di Perugia
Via Pascoli,c/o Dipartimento di Fisica  06123 Perugia (ITALY)
Phone:+39 075 5852777             Mail: Enrico.Becchetti<at>pg.infn.it
_______________________________________________________________________

2024

2023

2022

2021

2020

2019

2018

2017

2016

2015

2014

2013

2012

2011

[ovirt-users] SPM and Task error ...