14.02.2019 19:45, Jiří Sléžka пишет:
Hello,
we are using ovirt 4.2.8.2-1.el7.
One our user probably tried to preview taken snapshot but the task is stucked and never finished. Also disk is locked.
I'm also have this problem. I try to use openbaccus project for backup VMs, and all was good (manual started backup, for example, did his job: take snapshot, copy VM, etc.) But when I configure a task at night (Sheduled backup VM), It was some sort of disaster :) It try to snapshot/copy VM in infinite loop and create dozens images, all of that tasks have "failed" result. I was forced to delete it in ovirtengine by hand, but last created task are stuck. I switch off baccus, because it send queries to snapshots via API indefinitely, In engine log: ------------------------------- 2019-02-12 03:17:00,659+04 INFO [org.ovirt.engine.core.sso.utils.AuthenticationUtils] (default task-2941) [] User admin@internal successfully logged in with scopes: ovirt-app-api ovirt-ext=token-info:authz-search ovirt-ext=token-info:pub lic-authz-search ovirt-ext=token-info:validate ovirt-ext=token:password-access 2019-02-12 03:17:00,697+04 INFO [org.ovirt.engine.core.bll.aaa.CreateUserSessionCommand] (default task-2941) [7feb4bfd] Running command: CreateUserSessionCommand internal: false. 2019-02-12 03:17:00,704+04 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-2941) [7feb4bfd] EVENT_ID: USER_VDC_LOGIN(30), User admin@internal-authz connecting from '172.16.10.41' using session 'K tVU5wRCDZn2ZrPIE4rengdlpt+GdIfjTD6KpPIW45oY4XUfpcUCJH9ry4gRbsO98lQawu8LdMdRZ0zxqUcJKA==' logged in. 2019-02-12 03:17:00,804+04 INFO [org.ovirt.engine.core.sso.utils.AuthenticationUtils] (default task-2941) [] User admin@internal successfully logged in with scopes: ovirt-app-api ovirt-ext=token-info:authz-search ovirt-ext=token-info:pub lic-authz-search ovirt-ext=token-info:validate ovirt-ext=token:password-access 2019-02-12 03:17:00,863+04 INFO [org.ovirt.engine.core.bll.aaa.CreateUserSessionCommand] (default task-2941) [34e0ac0] Running command: CreateUserSessionCommand internal: false. 2019-02-12 03:17:00,984+04 INFO [org.ovirt.engine.core.bll.snapshots.CreateSnapshotForVmCommand] (default task-2941) [2f595966-44e8-4a67-8f55-a3d09836fc4d] Lock Acquired to object 'EngineLock:{exclusiveLocks='[f1029df3-36f3-4746-8c58-ebe cf860776f=VM]', sharedLocks=''}' 2019-02-12 03:17:00,985+04 WARN [org.ovirt.engine.core.bll.snapshots.CreateSnapshotForVmCommand] (default task-2941) [2f595966-44e8-4a67-8f55-a3d09836fc4d] Validation of action 'CreateSnapshotForVm' failed for user admin@internal-authz. Reasons: VAR__ACTION__CREATE,VAR__TYPE__SNAPSHOT,ACTION_TYPE_FAILED_VM_IS_DURING_SNAPSHOT 2019-02-12 03:17:00,985+04 INFO [org.ovirt.engine.core.bll.snapshots.CreateSnapshotForVmCommand] (default task-2941) [2f595966-44e8-4a67-8f55-a3d09836fc4d] Lock freed to object 'EngineLock:{exclusiveLocks='[f1029df3-36f3-4746-8c58-ebecf8 60776f=VM]', sharedLocks=''}' 2019-02-12 03:17:00,990+04 ERROR [org.ovirt.engine.api.restapi.resource.AbstractBackendResource] (default task-2941) [] Operation Failed: [Cannot create Snapshot. The VM is performing an operation on a Snapshot. Please wait for the operat ion to finish, and try again.] 2019-02-12 03:17:01,033+04 INFO [org.ovirt.engine.core.sso.servlets.OAuthRevokeServlet] (default task-2958) [] User admin@internal successfully logged out 2019-02-12 03:17:01,040+04 INFO [org.ovirt.engine.core.bll.aaa.TerminateSessionsForTokenCommand] (default task-2955) [6310d15d] Running command: TerminateSessionsForTokenCommand internal: true. 2019-02-12 03:17:01,231+04 INFO [org.ovirt.engine.core.sso.utils.AuthenticationUtils] (default task-2941) [] User admin@internal successfully logged in with scopes: ovirt-app-api ovirt-ext=token-info:authz-search ovirt-ext=token-info:pub lic-authz-search ovirt-ext=token-info:validate ovirt-ext=token:password-access 2019-02-12 03:17:01,255+04 INFO [org.ovirt.engine.core.bll.aaa.CreateUserSessionCommand] (default task-2941) [584a33cc] Running command: CreateUserSessionCommand internal: false. 2019-02-12 03:17:01,390+04 INFO [org.ovirt.engine.core.sso.utils.AuthenticationUtils] (default task-2941) [] User admin@internal successfully logged in with scopes: ovirt-app-api ovirt-ext=token-info:authz-search ovirt-ext=token-info:pub lic-authz-search ovirt-ext=token-info:validate ovirt-ext=token:password-access 2019-02-12 03:17:01,414+04 INFO [org.ovirt.engine.core.bll.aaa.CreateUserSessionCommand] (default task-2941) [4adc6455] Running command: CreateUserSessionCommand internal: false. 2019-02-12 03:17:01,587+04 INFO [org.ovirt.engine.core.bll.snapshots.CreateSnapshotForVmCommand] (default task-2941) [8b27b7bc-a7d1-4d9a-94f0-fbcad58691d0] Lock Acquired to object 'EngineLock:{exclusiveLocks='[f1029df3-36f3-4746-8c58-ebe cf860776f=VM]', sharedLocks=''}' 2019-02-12 03:17:01,587+04 WARN [org.ovirt.engine.core.bll.snapshots.CreateSnapshotForVmCommand] (default task-2941) [8b27b7bc-a7d1-4d9a-94f0-fbcad58691d0] Validation of action 'CreateSnapshotForVm' failed for user admin@internal-authz. Reasons: VAR__ACTION__CREATE,VAR__TYPE__SNAPSHOT,ACTION_TYPE_FAILED_VM_IS_DURING_SNAPSHOT 2019-02-12 03:17:01,588+04 INFO [org.ovirt.engine.core.bll.snapshots.CreateSnapshotForVmCommand] (default task-2941) [8b27b7bc-a7d1-4d9a-94f0-fbcad58691d0] Lock freed to object 'EngineLock:{exclusiveLocks='[f1029df3-36f3-4746-8c58-ebecf8 60776f=VM]', sharedLocks=''}' 2019-02-12 03:17:01,622+04 ERROR [org.ovirt.engine.api.restapi.resource.AbstractBackendResource] (default task-2941) [] Operation Failed: [Cannot create Snapshot. The VM is performing an operation on a Snapshot. Please wait for the operat ion to finish, and try again.] 2019-02-12 03:17:01,679+04 INFO [org.ovirt.engine.core.sso.servlets.OAuthRevokeServlet] (default task-2958) [] User admin@internal successfully logged out ----------------------------------------------------------------------- Then in log I see some xml dump (134 nested records): ...... <backingStore type='file' index='133'> <format type='qcow2'/> <source file='/rhev/data-center/mnt/glusterSD/ovirtnode1.miac:_vmstore/01f6fd06-9ad1-4957-bcda-df24dc4cc4f5/images/f195597c-d243-486e-b1f2-95810cd93468/2a50a181-d8c9-4012-965c-3f2dea021b70'/> <backingStore type='file' index='134'> <format type='raw'/> <source file='/rhev/data-center/mnt/glusterSD/ovirtnode1.miac:_vmstore/01f6fd06-9ad1-4957-bcda-df24dc4cc4f5/images/f195597c-d243-486e-b1f2-95810cd93468/07d862cd-406d-455b-be64-529d5edd7fc2'/> <backingStore/> Also in log: --------------------------- 2019-02-12 14:25:37,955+04 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-4082) [906e6cae-f040-4ada-9646-e9c2c213c254] EVENT_ID: USER_ADD_VM_STARTED(37), VM bacchus_cryptopro.miac_20190212_14281 0 creation was initiated by admin@internal-authz. 2019-02-12 14:25:37,955+04 INFO [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (default task-4082) [906e6cae-f040-4ada-9646-e9c2c213c254] BaseAsyncTask::startPollingTask: Starting to poll task '2b58becd-e7d2-4a70-955c-0aa153a024e2'. 2019-02-12 14:25:37,955+04 INFO [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (default task-4082) [906e6cae-f040-4ada-9646-e9c2c213c254] BaseAsyncTask::startPollingTask: Starting to poll task '5f6627b7-71aa-4167-9d9a-94a8642cfa8e'. 2019-02-12 14:25:37,963+04 INFO [org.ovirt.engine.core.sso.utils.AuthenticationUtils] (default task-4074) [] User admin@internal successfully logged in with scopes: ovirt-app-api ovirt-ext=token-info:authz-search ovirt-ext=token-info:pub lic-authz-search ovirt-ext=token-info:validate ovirt-ext=token:password-access 2019-02-12 14:25:37,966+04 INFO [org.ovirt.engine.core.bll.snapshots.CreateSnapshotForVmCommand] (default task-4028) [ed551253-1a6f-489e-8d8c-2fde63a3ada4] Lock Acquired to object 'EngineLock:{exclusiveLocks='[f1029df3-36f3-4746-8c58-ebe cf860776f=VM]', sharedLocks=''}' 2019-02-12 14:25:37,966+04 WARN [org.ovirt.engine.core.bll.snapshots.CreateSnapshotForVmCommand] (default task-4028) [ed551253-1a6f-489e-8d8c-2fde63a3ada4] Validation of action 'CreateSnapshotForVm' failed for user admin@internal-authz. Reasons: VAR__ACTION__CREATE,VAR__TYPE__SNAPSHOT,ACTION_TYPE_FAILED_VM_STATUS_ILLEGAL,VAR__VM_STATUS__NOT_RESPONDING 2019-02-12 14:25:37,967+04 INFO [org.ovirt.engine.core.bll.snapshots.CreateSnapshotForVmCommand] (default task-4028) [ed551253-1a6f-489e-8d8c-2fde63a3ada4] Lock freed to object 'EngineLock:{exclusiveLocks='[f1029df3-36f3-4746-8c58-ebecf8 60776f=VM]', sharedLocks=''}' 2019-02-12 14:25:37,972+04 ERROR [org.ovirt.engine.api.restapi.resource.AbstractBackendResource] (default task-4028) [] Operation Failed: [Cannot create Snapshot because the VM is in Not Responding status.] 2019-02-12 14:25:37,989+04 INFO [org.ovirt.engine.core.bll.snapshots.CreateSnapshotForVmCommand] (default task-4080) [7d19cf2a-6e06-4b90-a445-1d047b11529b] Lock Acquired to object 'EngineLock:{exclusiveLocks='[f1029df3-36f3-4746-8c58-ebe cf860776f=VM]', sharedLocks=''}' 2019-02-12 14:25:37,989+04 WARN [org.ovirt.engine.core.bll.snapshots.CreateSnapshotForVmCommand] (default task-4080) [7d19cf2a-6e06-4b90-a445-1d047b11529b] Validation of action 'CreateSnapshotForVm' failed for user admin@internal-authz. Reasons: VAR__ACTION__CREATE,VAR__TYPE__SNAPSHOT,ACTION_TYPE_FAILED_VM_STATUS_ILLEGAL,VAR__VM_STATUS__NOT_RESPONDING 2019-02-12 14:25:37,989+04 INFO [org.ovirt.engine.core.bll.snapshots.CreateSnapshotForVmCommand] (default task-4080) [7d19cf2a-6e06-4b90-a445-1d047b11529b] Lock freed to object 'EngineLock:{exclusiveLocks='[f1029df3-36f3-4746-8c58-ebecf8 60776f=VM]', sharedLocks=''}' 2019-02-12 14:25:37,994+04 ERROR [org.ovirt.engine.api.restapi.resource.AbstractBackendResource] (default task-4080) [] Operation Failed: [Cannot create Snapshot because the VM is in Not Responding status.] 2019-02-12 14:25:38,012+04 INFO [org.ovirt.engine.core.sso.servlets.OAuthRevokeServlet] (default task-4028) [] User admin@internal successfully logged out ..... 2019-02-12 14:25:47,814+04 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-98) [] VM 'f1029df3-36f3-4746-8c58-ebecf860776f'(cryptopro.miac) moved from 'NotResponding' --> 'Up' 2019-02-12 14:25:48,150+04 INFO [org.ovirt.engine.core.sso.utils.AuthenticationUtils] (default task-4070) [] User admin@internal successfully logged in with scopes: ovirt-app-api ovirt-ext=token-info:authz-search ovirt-ext=token-info:pub lic-authz-search ovirt-ext=token-info:validate ovirt-ext=token:password-access 2019-02-12 14:25:48,172+04 INFO [org.ovirt.engine.core.bll.aaa.CreateUserSessionCommand] (default task-4070) [720e0bca] Running command: CreateUserSessionCommand internal: false. 2019-02-12 14:25:48,178+04 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSCommand] (EE-ManagedThreadFactory-engineScheduled-Thread-22) [] Failed in 'HSMGetAllTasksStatusesVDS' method 2019-02-12 14:25:48,184+04 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engineScheduled-Thread-22) [] EVENT_ID: VDS_BROKER_COMMAND_FAILURE(10,802), VDSM ovirtnode6.miac command HSMG etAllTasksStatusesVDS failed: low level Image copy failed: ('Command [\'/usr/bin/taskset\', \'--cpu-list\', \'0-31\', \'/usr/bin/nice\', \'-n\', \'19\', \'/usr/bin/ionice\', \'-c\', \'3\', \'/usr/bin/qemu-img\', \'convert\', \'-p\', \'-t\ ', \'none\', \'-T\', \'none\', \'-f\', \'qcow2\', u\'/rhev/data-center/mnt/glusterSD/ovirtnode1.miac:_vmstore/01f6fd06-9ad1-4957-bcda-df24dc4cc4f5/images/f195597c-d243-486e-b1f2-95810cd93468/069dc3e6-a925-4fda-a740-b40a81e5e561\', \'-O\', \'raw\', u\'/rhev/data-center/mnt/glusterSD/ovirtnode1.miac:_vmstore/01f6fd06-9ad1-4957-bcda-df24dc4cc4f5/images/fd352508-942f-4882-bda4-293aba7616a7/0ba12329-6b6e-4d58-a9fa-f91cf1cf9555\'] failed with rc=1 out=\'\' err=bytearray(b\'qemu -img: Could not open \\\'/rhev/data-center/mnt/glusterSD/ovirtnode1.miac:_vmstore/01f6fd06-9ad1-4957-bcda-df24dc4cc4f5/images/f195597c-d243-486e-b1f2-95810cd93468/069dc3e6-a925-4fda-a740-b40a81e5e561\\\': Failed to get shared "write" lock \\nIs another process using the image?\\n\')',) ...2019-02-12 14:25:48,189+04 ERROR [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (EE-ManagedThreadFactory-engineScheduled-Thread-22) [] BaseAsyncTask::logEndTaskFailure: Task '5f6627b7-71aa-4167-9d9a-94a8642cfa8e' (Parent Command 'AddVmFro mSnapshot', Parameters Type 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters') ended with failure: -- Result: 'cleanSuccess' -- Message: 'VDSGenericException: VDSErrorException: Failed to HSMGetAllTasksStatusesVDS, error = low level Image copy failed: ('Command [\'/usr/bin/taskset\', \'--cpu-list\', \'0-31\', \'/usr/bin/nice\', \'-n\', \'19\', \'/usr/bin/ionice \', \'-c\', \'3\', \'/usr/bin/qemu-img\', \'convert\', \'-p\', \'-t\', \'none\', \'-T\', \'none\', \'-f\', \'qcow2\', u\'/rhev/data-center/mnt/glusterSD/ovirtnode1.miac:_vmstore/01f6fd06-9ad1-4957-bcda-df24dc4cc4f5/images/f195597c-d243-48 6e-b1f2-95810cd93468/069dc3e6-a925-4fda-a740-b40a81e5e561\', \'-O\', \'raw\', u\'/rhev/data-center/mnt/glusterSD/ovirtnode1.miac:_vmstore/01f6fd06-9ad1-4957-bcda-df24dc4cc4f5/images/fd352508-942f-4882-bda4-293aba7616a7/0ba12329-6b6e-4d58- a9fa-f91cf1cf9555\'] failed with rc=1 out=\'\' err=bytearray(b\'qemu-img: Could not open \\\'/rhev/data-center/mnt/glusterSD/ovirtnode1.miac:_vmstore/01f6fd06-9ad1-4957-bcda-df24dc4cc4f5/images/f195597c-d243-486e-b1f2-95810cd93468/069dc3e 6-a925-4fda-a740-b40a81e5e561\\\': Failed to get shared "write" lock\\nIs another process using the image?\\n\')',), code = 261', -- Exception: 'VDSGenericException: VDSErrorException: Failed to HSMGetAllTasksStatusesVDS, error = low level Image copy failed: ('Command [\'/usr/bin/taskset\', \'--cpu-list\', \'0-31\', \'/usr/bin/nice\', \'-n\', \'19\', \'/usr/bin/ioni ce\', \'-c\', \'3\', \'/usr/bin/qemu-img\', \'convert\', \'-p\', \'-t\', \'none\', \'-T\', \'none\', \'-f\', \'qcow2\', u\'/rhev/data-center/mnt/glusterSD/ovirtnode1.miac:_vmstore/01f6fd06-9ad1-4957-bcda-df24dc4cc4f5/images/f195597c-d243- 486e-b1f2-95810cd93468/069dc3e6-a925-4fda-a740-b40a81e5e561\', \'-O\', \'raw\', u\'/rhev/data-center/mnt/glusterSD/ovirtnode1.miac:_vmstore/01f6fd06-9ad1-4957-bcda-df24dc4cc4f5/images/fd352508-942f-4882-bda4-293aba7616a7/0ba12329-6b6e-4d5 8-a9fa-f91cf1cf9555\'] failed with rc=1 out=\'\' err=bytearray(b\'qemu-img: Could not open \\\'/rhev/data-center/mnt/glusterSD/ovirtnode1.miac:_vmstore/01f6fd06-9ad1-4957-bcda-df24dc4cc4f5/images/f195597c-d243-486e-b1f2-95810cd93468/069dc 3e6-a925-4fda-a740-b40a81e5e561\\\': Failed to get shared "write" lock\\nIs another process using the image?\\n\')',), code = 261' 2019-02-12 14:25:48,190+04 INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (EE-ManagedThreadFactory-engineScheduled-Thread-22) [] CommandAsyncTask::endActionIfNecessary: All tasks of command '9bfb0439-89b4-4e2f-be60-0011c43b098f' has ended -> executing 'endAction' 2019-02-12 14:25:48,190+04 INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (EE-ManagedThreadFactory-engineScheduled-Thread-22) [] CommandAsyncTask::endAction: Ending action for '2' tasks (command ID: '9bfb0439-89b4-4e2f-be60-0011 c43b098f'): calling endAction '. 2019-02-12 14:25:48,191+04 INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (EE-ManagedThreadFactory-engine-Thread-2242806) [] CommandAsyncTask::endCommandAction [within thread] context: Attempting to endAction 'AddVmFromSnapshot' , 2019-02-12 14:25:48,241+04 INFO [org.ovirt.engine.core.sso.utils.AuthenticationUtils] (default task-4070) [] User admin@internal successfully logged in with scopes: ovirt-app-api ovirt-ext=token-info:authz-search ovirt-ext=token-info:pub lic-authz-search ovirt-ext=token-info:validate ovirt-ext=token:password-access ... 2019-02-12 14:25:48,665+04 ERROR [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (EE-ManagedThreadFactory-engine-Thread-2242806) [] [within thread]: endAction for action type AddVmFromSnapshot threw an exception.: java.lang.ClassCastEx ception: org.ovirt.engine.core.common.action.VmLeaseParameters cannot be cast to org.ovirt.engine.core.common.action.MoveOrCopyImageGroupParameters at org.ovirt.engine.core.bll.AddVmAndCloneImageCommand.removeVmImages(AddVmAndCloneImageCommand.java:123) [bll.jar:] at org.ovirt.engine.core.bll.AddVmAndCloneImageCommand.removeVmRelatedEntitiesFromDb(AddVmAndCloneImageCommand.java:115) [bll.jar:] at org.ovirt.engine.core.bll.AddVmCommand.endWithFailure(AddVmCommand.java:1413) [bll.jar:] at org.ovirt.engine.core.bll.AddVmFromSnapshotCommand.endWithFailure(AddVmFromSnapshotCommand.java:304) [bll.jar:] ------------------------------------------------------------------------ Here is a full log: https://yadi.sk/d/eCIoFBnhZZgYRQ Task list in ovirtengine webui Creating VM bacchus_cryptopro.miac_20190212_142810 from Snapshot bacchus_cryptopro.miac_20190212_142810 in Cluster Default Started: Feb 12, 2019, 2:25:35 PM Validating Completed: Feb 12, 2019, 2:25:35 PM Executing Completed: Feb 12, 2019, 2:25:48 PM Adding VM lease Completed: Feb 12, 2019, 2:25:38 PM Copying Image (stuck here) Started: Feb 12, 2019, 2:25:37 PM Finalizing I try to use taskcleaner.sh, and I clean 1 task, but that lines in UI are not disappear.
Also I would like to unlock disk and clean this task. I can see locked snapshot and disk
[root@ovirt dbutils]# ./unlock_entity.sh -q -t snapshot -c
Locked snapshots vm_id | snapshot_id --------------------------------------+-------------------------------------- f1029df3-36f3-4746-8c58-ebecf860776f | d95ab426-3fea-4521-b415-284abfbd8d8d
[root@ovirt dbutils]# ./unlock_entity.sh -q -t disk -c Locked disks
vm_id | disk_id --------------------------------------+-------------------------------------- f1029df3-36f3-4746-8c58-ebecf860776f | f195597c-d243-486e-b1f2-95810cd93468
but no runnig tasks
[root@ovirt dbutils]# ./taskcleaner.sh -o t
[root@ovirtengine dbutils]# ./taskcleaner.sh -T t (-o has a tasks ...)
what is best approach to unlock and clean this?
Also interested in it. -- Mike