Note: This bug is displayed in read-only format because the product is no longer active in Red Hat Bugzilla.

Bug 1849370

Summary:	External VM is created by the engine after creating template from snapshot
Product:	Red Hat Enterprise Virtualization Manager	Reporter:	Evelina Shames <eshames>
Component:	ovirt-engine	Assignee:	Liran Rotenberg <lrotenbe>
Status:	CLOSED ERRATA	QA Contact:	Evelina Shames <eshames>
Severity:	medium	Docs Contact:
Priority:	medium
Version:	4.3.11	CC:	aefrat, ahadas, bugs, lrotenbe, pelauter, qiyuan, rdlugyhe, sfishbai
Target Milestone:	ovirt-4.3.11	Keywords:	Automation, ZStream
Target Release:	4.3.11	Flags:	ahadas: needinfo-
Hardware:	Unspecified
OS:	Unspecified
Whiteboard:
Fixed In Version:	ovirt-engine-4.3.11.1	Doc Type:	No Doc Update
Doc Text:		Story Points:	---
Clone Of:	1831742	Environment:
Last Closed:	2020-09-30 10:07:13 UTC	Type:	---
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:	1831742
Bug Blocks:

Description Evelina Shames 2020-06-21 05:41:06 UTC

+++ This bug was initially created as a clone of Bug #1831742 +++

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.

--- Additional comment from Liran Rotenberg on 2020-05-07 14:27:15 UTC ---

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.

--- Additional comment from Arik on 2020-06-04 11:36:37 UTC ---

merged to 4.4.0.1

--- Additional comment from Qin Yuan on 2020-06-11 06:20:02 UTC ---

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.

Comment 4 Sandro Bonazzola 2020-07-06 14:57:11 UTC

$ git tag --contains 52463f3c16edec7e21f2b7dd5abb094234dd0216
ovirt-engine-4.3.11.1

Comment 8 Evelina Shames 2020-07-21 11:05:51 UTC

Verified on engine-4.3.11.2-0.1.el7

Comment 13 errata-xmlrpc 2020-09-30 10:07:13 UTC

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory (Red Hat Virtualization Engine security, bug fix 4.3.11), and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHBA-2020:4112