Bug 1831742
| Summary: | External VM is created by the engine after creating template from snapshot | ||||||
|---|---|---|---|---|---|---|---|
| Product: | [oVirt] ovirt-engine | Reporter: | Evelina Shames <eshames> | ||||
| Component: | BLL.Virt | Assignee: | Liran Rotenberg <lrotenbe> | ||||
| Status: | CLOSED CURRENTRELEASE | QA Contact: | Qin Yuan <qiyuan> | ||||
| Severity: | medium | Docs Contact: | |||||
| Priority: | unspecified | ||||||
| Version: | 4.4.0 | CC: | ahadas, bugs, lrotenbe | ||||
| Target Milestone: | ovirt-4.4.1 | Keywords: | Automation | ||||
| Target Release: | --- | Flags: | pm-rhel:
ovirt-4.4+
|
||||
| Hardware: | Unspecified | ||||||
| OS: | Unspecified | ||||||
| Whiteboard: | |||||||
| Fixed In Version: | 4.4.0.1 | Doc Type: | No Doc Update | ||||
| Doc Text: | Story Points: | --- | |||||
| Clone Of: | |||||||
| : | 1849370 (view as bug list) | Environment: | |||||
| Last Closed: | 2020-07-08 08:25:13 UTC | Type: | Bug | ||||
| Regression: | --- | Mount Type: | --- | ||||
| Documentation: | --- | CRM: | |||||
| Verified Versions: | Category: | --- | |||||
| oVirt Team: | Virt | RHEL 7.3 requirements from Atomic Host: | |||||
| Cloudforms Team: | --- | Target Upstream Version: | |||||
| Embargoed: | |||||||
| Bug Depends On: | |||||||
| Bug Blocks: | 1849370 | ||||||
| Attachments: |
|
||||||
This bug happened on the third case but can happen every time the VM is running and creating a template from snapshot which is not the active one.
VM UP:
2020-05-05 13:11:20,945+03 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-80) [] VM '197feac0-98ae-40d7-a9
fa-52c83f856ff7'(vm_TestCaseCreateTemplateF_0513092870) moved from 'PoweringUp' --> 'Up'
2020-05-05 13:11:20,982+03 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-80) [] EVENT_ID:
USER_RUN_VM(32), VM vm_TestCaseCreateTemplateF_0513092870 started on Host host_mixed_2
Starting template creation from snapshot:
2020-05-05 13:13:45,217+03 INFO [org.ovirt.engine.core.bll.AddVmTemplateFromSnapshotCommand] (default task-118) [templates_create_bd09141e-daf9-42f3] Lock Acquired to object 'EngineLock:{exclusiveLocks='[40e91ef6-c7ec-4606-bc18-480b32b28c73=DISK, templ_test_create_template_fr_0513134315=TEMPLATE_NAME, c599974a-8d9c-48e1-bf64-321be7f31c77=TEMPLATE]', sharedLocks='[197feac0-98ae-40d7-a9fa-52c83f856ff7=VM]'}'
2020-05-05 13:13:45,800+03 INFO [org.ovirt.engine.core.bll.AddVmTemplateFromSnapshotCommand] (default task-118) [templates_create_bd09141e-daf9-42f3] Running command: AddVmTemplateFromSnapshotCommand internal: false. Entities affected : ID: 5cc84d21-26ff-49ff-bccd-de20f3891179 Type: StoragePoolAction group CREATE_TEMPLATE with role type USER
2020-05-05 13:13:45,806+03 INFO [org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand] (default task-118) [templates_create_bd09141e-daf9-42f3] START, SetVmStatusVDSCommand( SetVmStatusVDSCommandParameters:{vmId='197feac0-98ae-40d7-a9fa-52c83f856ff7', status='ImageLocked', exitStatus='Normal'}), log id: 305ff84d
2020-05-05 13:13:45,811+03 INFO [org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand] (default task-118) [templates_create_bd09141e-daf9-42f3] FINISH, SetVmStatusVDSCommand, return: , log id: 305ff84d
OOPS?
2020-05-05 13:13:50,958+03 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-118) [templates_create_bd09141e-daf9-42f3] EVENT_ID: USER_ADD_VM_TEMPLAT
E(48), Creation of Template templ_test_create_template_fr_0513134315 from VM templ_test_create_template_fr_0513134315 was initiated by admin@internal-authz.
2020-05-05 13:13:51,569+03 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-39) [] VM '197feac0-98ae-40d7-a9fa-52c83f856ff7'(vm_TestCaseCreateTemplateF_0513092870) was unexpectedly detected as 'Up' on VDS '75c2b03a-5d42-444d-ab87-40cae382af74'(host_mixed_2) (expected on 'null')
Setting the VM down:
2020-05-05 13:14:24,759+03 INFO [org.ovirt.engine.core.bll.AddVmTemplateFromSnapshotCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-40) [templates_create_bd09141e-daf9-42f3] Ending command 'org.ovirt.engine.core.bll.AddVmTemplateFromSnapshotCommand' successfully.
2020-05-05 13:14:24,766+03 INFO [org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-40) [templates_create_bd09141e-daf9-42f3] START, SetVmStatusVDSCommand( SetVmStatusVDSCommandParameters:{vmId='197feac0-98ae-40d7-a9fa-52c83f856ff7', status='Down', exitStatus='Normal'}), log id: e2a0ccb
2020-05-05 13:14:24,770+03 INFO [org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-40) [templates_create_bd09141e-daf9-42f3] FINISH, SetVmStatusVDSCommand, return: , log id: e2a0ccb
2020-05-05 13:14:24,790+03 INFO [org.ovirt.engine.core.bll.AddVmTemplateFromSnapshotCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-40) [templates_create_bd09141e-daf9-42f3] Lock freed to object 'EngineLock:{exclusiveLocks='[40e91ef6-c7ec-4606-bc18-480b32b28c73=DISK, templ_test_create_template_fr_0513134315=TEMPLATE_NAME, c599974a-8d9c-48e1-bf64-321be7f31c77=TEMPLATE]', sharedLocks='[197feac0-98ae-40d7-a9fa-52c83f856ff7=VM]'}'
2020-05-05 13:14:24,812+03 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-40) [templates_create_bd09141e-daf9-42f3] EVENT_ID: USER_ADD_VM_TEMPLATE_FINISHED_SUCCESS(51), Creation of Template templ_test_create_template_fr_0513134315 from VM templ_test_create_template_fr_0513134315 has been completed.
At this point we have the VM as down in the engine, but UP on the host!
Removing the VM...
2020-05-05 13:14:34,465+03 INFO [org.ovirt.engine.core.bll.RemoveVmCommand] (EE-ManagedThreadFactory-engine-Thread-108304) [vms_delete_366d7457-bfe5-4fdf] Ending command 'org.ovirt.engine.core.bll.RemoveVmCommand' successfully.
Suddenly:
2020-05-05 13:14:36,765+03 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-91) [] VM '197feac0-98ae-40d7-a9fa-52c83f856ff7' was discovered as 'Up' on VDS '75c2b03a-5d42-444d-ab87-40cae382af74'(host_mixed_2)
2020-05-05 13:14:36,836+03 INFO [org.ovirt.engine.core.bll.AddUnmanagedVmsCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-91) [27353c4b] Running command: AddUnmanagedVmsCommand internal: true.
In 'AddVmTemplateFromSnapshotCommand' we shouldn't change the VM status at all. While we are calling the parent class AddVmTemplateCommand it does change it.
In the right timing, the engine will monitor the VM and re-set it to UP. But for bad timing, the VM showed down, letting it continue to do operation such as remove it.
For this bug, the VM removed in the engine but it's still running on the host, the engine detects it and add it as external VM.
merged to 4.4.0.1 Verified with:
ovirt-engine-4.4.1-0.1.el8ev.noarch
vdsm-4.40.17-1.el8ev.x86_64
Steps:
1. Create a VM.
2. Create a snapshot.
3. Run VM.
4. Create a template from snapshot.
5. Remove VM.
Results:
1. There is no changing vm status process when running AddVmTemplateFromSnapshotCommand
- no setting vm status to ImageLocked action when starting AddVmTemplateFromSnapshotCommand
- no setting vm status to Down action when ending AddVmTemplateFromSnapshotCommand
2. No external VM after the VM was removed.
enging log:
2020-06-11 07:06:07,798+03 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-18) [] VM '500153cb-0a01-4373-b19e-c2cf24620a9b'(vm_TestCaseCreateTemplateF_1112020810) moved from 'PoweringUp' --> 'Up'
2020-06-11 07:06:07,846+03 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-18) [] EVENT_ID: USER_RUN_VM(32), VM vm_TestCaseCreateTemplateF_1112020810 started on Host host_mixed_2
2020-06-11 07:08:09,370+03 INFO [org.ovirt.engine.core.bll.AddVmTemplateFromSnapshotCommand] (default task-1750) [templates_create_df8775b9-7e65-48cd] Lock Acquired to object 'EngineLock:{exclusiveLocks='[13fa927b-7941-48cd-ab99-dd493b959cb0=DISK, templ_test_create_template_fr_1112074519=TEMPLATE_NAME, 253dfef4-13b5-4704-a571-0643ab809508=TEMPLATE]', sharedLocks='[500153cb-0a01-4373-b19e-c2cf24620a9b=VM]'}'
2020-06-11 07:08:10,285+03 INFO [org.ovirt.engine.core.bll.AddVmTemplateFromSnapshotCommand] (default task-1750) [templates_create_df8775b9-7e65-48cd] Running command: AddVmTemplateFromSnapshotCommand internal: false. Entities affected : ID: f61083e2-6a2b-4a3a-9e72-03b8ec399dd2 Type: StoragePoolAction group CREATE_TEMPLATE with role type USER
2020-06-11 07:08:14,232+03 INFO [org.ovirt.engine.core.bll.storage.disk.CreateAllTemplateDisksFromSnapshotCommand] (default task-1750) [templates_create_df8775b9-7e65-48cd] Running command: CreateAllTemplateDisksFromSnapshotCommand internal: true.
2020-06-11 07:08:14,273+03 INFO [org.ovirt.engine.core.bll.storage.disk.image.CreateImageTemplateCommand] (default task-1750) [templates_create_df8775b9-7e65-48cd] Running command: CreateImageTemplateCommand internal: true. Entities affected : ID: 2b7c95fa-4d95-4850-b308-edce6ef606b2 Type: Storage
2020-06-11 07:08:14,877+03 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.CopyImageVDSCommand] (default task-1750) [templates_create_df8775b9-7e65-48cd] START, CopyImageVDSCommand( CopyImageVDSCommandParameters:{storagePoolId='f61083e2-6a2b-4a3a-9e72-03b8ec399dd2', ignoreFailoverLimit='false', storageDomainId='2b7c95fa-4d95-4850-b308-edce6ef606b2', imageGroupId='af279e2d-5f25-4e08-89d9-93ca8bc0025e', imageId='5c779d81-15b8-478f-9644-5700a17091f1', dstImageGroupId='aae0a5d1-cc70-4f2b-a836-8869da37a64d', vmId='500153cb-0a01-4373-b19e-c2cf24620a9b', dstImageId='93a9e0af-c330-4571-956d-d57c732e1549', imageDescription='{"DiskAlias":"vm_TestCaseCreateTemplateF_1112020810_Disk_0","DiskDescription":"latest-rhel-guest-image-8.2-infra (3083daa)"}', dstStorageDomainId='fc13d885-8ab4-41fc-8d75-ee5fdf1ece71', copyVolumeType='SharedVol', volumeFormat='COW', preallocate='Sparse', postZero='false', discard='false', force='false'}), log id: b59d7eb
...
2020-06-11 07:08:49,024+03 INFO [org.ovirt.engine.core.bll.AddVmTemplateFromSnapshotCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-86) [templates_create_df8775b9-7e65-48cd] Ending command 'org.ovirt.engine.core.bll.AddVmTemplateFromSnapshotCommand' successfully.
2020-06-11 07:08:49,065+03 INFO [org.ovirt.engine.core.bll.AddVmTemplateFromSnapshotCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-86) [templates_create_df8775b9-7e65-48cd] Lock freed to object 'EngineLock:{exclusiveLocks='[13fa927b-7941-48cd-ab99-dd493b959cb0=DISK, templ_test_create_template_fr_1112074519=TEMPLATE_NAME, 253dfef4-13b5-4704-a571-0643ab809508=TEMPLATE]', sharedLocks='[500153cb-0a01-4373-b19e-c2cf24620a9b=VM]'}'
2020-06-11 07:08:49,115+03 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-86) [templates_create_df8775b9-7e65-48cd] EVENT_ID: USER_ADD_VM_TEMPLATE_FINISHED_SUCCESS(51), Creation of Template templ_test_create_template_fr_1112074519 from VM templ_test_create_template_fr_1112074519 has been completed.
...
2020-06-11 07:09:18,583+03 INFO [org.ovirt.engine.core.bll.StopVmCommand] (default task-1751) [vms_syncAction_c659db23-f391-4f15] Running command: StopVmCommand internal: false. Entities affected : ID: 500153cb-0a01-4373-b19e-c2cf24620a9b Type: VMAction group STOP_VM with role type USER
2020-06-11 07:09:18,646+03 INFO [org.ovirt.engine.core.vdsbroker.DestroyVmVDSCommand] (default task-1751) [vms_syncAction_c659db23-f391-4f15] START, DestroyVmVDSCommand( DestroyVmVDSCommandParameters:{hostId='3ea271cf-a3bf-4349-a8ef-74b9b44395db', vmId='500153cb-0a01-4373-b19e-c2cf24620a9b', secondsToWait='0', gracefully='false', reason='', ignoreNoVm='false'}), log id: 655d742
2020-06-11 07:09:51,594+03 INFO [org.ovirt.engine.core.bll.RemoveVmCommand] (EE-ManagedThreadFactory-engine-Thread-564580) [vms_delete_aa347552-7300-4076] Ending command 'org.ovirt.engine.core.bll.RemoveVmCommand' successfully.
This bugzilla is included in oVirt 4.4.1 release, published on July 8th 2020. Since the problem described in this bug report should be resolved in oVirt 4.4.1 release, it has been closed with a resolution of CURRENT RELEASE. If the solution does not work for you, please open a new bug report. |
Created attachment 1685247 [details] Logs Description of problem: We have an automation TC that creates template from snapshot with and without memory when the vm_status is up or down (4 cases for this test). Sometimes, after we remove the VM at the end of the test, the engine creates an external-VM: 2020-05-05 13:14:33,688+03 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-126) [vms_delete_366d7457-bfe5-4fdf] EVENT_ID: USER_REMOVE_VM_FINISHED(113), VM vm_TestCaseCreateTemplateF_0513092870 was successfully removed by admin@internal-authz. 2020-05-05 13:14:36,765+03 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-91) [] VM '197feac0-98ae-40d7-a9fa-52c83f856ff7' was discovered as 'Up' on VDS '75c2b03a-5d42-444d-ab87-40cae382af74'(host_mixed_2) 2020-05-05 13:14:36,942+03 INFO [org.ovirt.engine.core.bll.AddVmFromScratchCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-91) [cbd08b8] Lock Acquired to object 'EngineLock:{exclusiveLocks='[external-vm_Test CaseCreateTemplateF_0513092870=VM_NAME]', sharedLocks=''}' 2020-05-05 13:14:37,420+03 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-91) [] EVENT_ID: USER_ADD_VM(34), VM external-vm_TestCaseCreateTe mplateF_0513092870 was created by SYSTEM. 2020-05-05 13:14:37,422+03 INFO [org.ovirt.engine.core.bll.AddVmFromScratchCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-91) [] Lock freed to object 'EngineLock:{exclusiveLocks='[external-vm_TestCaseCreate TemplateF_0513092870=VM_NAME]', sharedLocks=''}' 2020-05-05 13:14:37,458+03 INFO [org.ovirt.engine.core.bll.AddUnmanagedVmsCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-91) [] Importing VM 'vm_TestCaseCreateTemplateF_0513092870' as 'external-vm_TestCaseCreateTemplateF_0513092870', as it is running on the on Host, but does not exist in the engine. Version-Release number of selected component (if applicable): ovirt-engine-4.4.0-0.33.master.el8ev.noarch vdsm-4.40.13-1.el8ev.x86_64 How reproducible: Not sure. Happened several times in our automation. Most of the time it is reproduced by the following automation TC. Steps to Reproduce: Create template from snapshot with and without memory when the vm_status is up or down (4 cases for this test): 1. Create a VM 2. If memory snapshot is chosen start the VM 3. If vm_status isn't chosen, shut down the VM 4. If vm_status is chosen, start the VM 5. Create snapshot 6. Create a template from snapshot by snapshot object Actual results: VM is removed, but a new external-VM is created in status UP. Expected results: external-VM is not created. Additional info: Logs are attached.