Created attachment 1657900 [details] Logs Description of problem: Filed to create live snapshot with the following errors: engine: 2020-01-25 05:54:04,699+02 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.SnapshotVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-40) [snapshots_create_b2ac89d5-8875-4da7] Failed in 'SnapshotVDS' method 2020-01-25 05:54:04,728+02 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-40) [snapshots_create_b2ac89d5-8875-4da7] EVENT_ID: VDS_BROKER_COMMAND_FAILURE(10,802), VDSM host_mixed_1 command SnapshotVDS failed: General Exception: ("VM 'd4819a61-6d48-4a27-a37c-a196f89947a7' was not defined yet or was undefined",) 2020-01-25 05:54:04,825+02 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SnapshotVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-40) [snapshots_create_b2ac89d5-8875-4da7] Command 'org.ovirt.engine.core.vdsbroker.vdsbroker.SnapshotVDSCommand' return value 'StatusOnlyReturn [status=Status [code=100, message=General Exception: ("VM 'd4819a61-6d48-4a27-a37c-a196f89947a7' was not defined yet or was undefined",)]]' 2020-01-25 05:54:04,825+02 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SnapshotVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-40) [snapshots_create_b2ac89d5-8875-4da7] HostName = host_mixed_1 2020-01-25 05:54:04,825+02 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.SnapshotVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-40) [snapshots_create_b2ac89d5-8875-4da7] Command 'SnapshotVDSCommand(HostName = host_mixed_1, SnapshotVDSCommandParameters:{hostId='3547f231-fb80-4a0c-a9e0-0f2bdba62a38', vmId='d4819a61-6d48-4a27-a37c-a196f89947a7'})' execution failed: VDSGenericException: VDSErrorException: Failed to SnapshotVDS, error = General Exception: ("VM 'd4819a61-6d48-4a27-a37c-a196f89947a7' was not defined yet or was undefined",), code = 100 2020-01-25 05:54:04,825+02 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SnapshotVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-40) [snapshots_create_b2ac89d5-8875-4da7] FINISH, SnapshotVDSCommand, return: , log id: 2b07cd14 2020-01-25 05:54:04,830+02 WARN [org.ovirt.engine.core.bll.snapshots.CreateSnapshotForVmCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-40) [snapshots_create_b2ac89d5-8875-4da7] Could not perform live snapshot due to error, VM will still be configured to the new created snapshot: EngineException: org.ovirt.engine.core.vdsbroker.vdsbroker.VDSErrorException: VDSGenericException: VDSErrorException: Failed to SnapshotVDS, error = General Exception: ("VM 'd4819a61-6d48-4a27-a37c-a196f89947a7' was not defined yet or was undefined",), code = 100 (Failed with error GeneralException and code 100) 2020-01-25 05:54:04,852+02 WARN [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-40) [snapshots_create_b2ac89d5-8875-4da7] EVENT_ID: USER_CREATE_LIVE_SNAPSHOT_FINISHED_FAILURE(170), Failed to create live snapshot 'snap_TestCase11660_2505484173' for VM 'vm_TestCase11660_2505481958'. VM restart is recommended. Note that using the created snapshot might cause data inconsistency. 2020-01-25 05:54:05,208+02 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (ForkJoinPool-1-worker-19) [799e95fa] EVENT_ID: VM_DOWN_ERROR(119), VM vm_TestCase11660_2505481958 is down with error. Exit message: Lost connection with qemu process. 2020-01-25 05:54:05,873+02 ERROR [org.ovirt.engine.core.bll.snapshots.CreateSnapshotForVmCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-14) [snapshots_create_b2ac89d5-8875-4da7] Ending command 'org.ovirt.engine.core.bll.snapshots.CreateSnapshotForVmCommand' with failure. 2020-01-25 05:54:05,882+02 INFO [org.ovirt.engine.core.bll.RemoveMemoryVolumesCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-14) [481e7ac3] Running command: RemoveMemoryVolumesCommand internal: true. 2020-01-25 05:54:05,911+02 INFO [org.ovirt.engine.core.bll.storage.disk.RemoveDiskCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-14) [172797bd] Lock Acquired to object 'EngineLock:{exclusiveLocks='[5c5e341c-c313-47ae-816e-f1535d0574da=DISK]', sharedLocks=''}' 2020-01-25 05:54:05,921+02 WARN [org.ovirt.engine.core.bll.storage.disk.RemoveDiskCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-14) [172797bd] Validation of action 'RemoveDisk' failed for user admin@internal-authz. Reasons: VAR__ACTION__REMOVE,VAR__TYPE__DISK,ACTION_TYPE_FAILED_OBJECT_LOCKED 2020-01-25 05:54:05,921+02 INFO [org.ovirt.engine.core.bll.storage.disk.RemoveDiskCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-14) [172797bd] Lock freed to object 'EngineLock:{exclusiveLocks='[5c5e341c-c313-47ae-816e-f1535d0574da=DISK]', sharedLocks=''}' 2020-01-25 05:54:05,926+02 ERROR [org.ovirt.engine.core.bll.snapshots.CreateSnapshotDiskCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-14) [snapshots_create_b2ac89d5-8875-4da7] Ending command 'org.ovirt.engine.core.bll.snapshots.CreateSnapshotDiskCommand' with failure. 2020-01-25 05:54:05,930+02 ERROR [org.ovirt.engine.core.bll.snapshots.CreateSnapshotCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-14) [snapshots_create_b2ac89d5-8875-4da7] Ending command 'org.ovirt.engine.core.bll.snapshots.CreateSnapshotCommand' with failure. 2020-01-25 05:54:05,980+02 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMRevertTaskVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-14) [snapshots_create_b2ac89d5-8875-4da7] Trying to revert unknown task '932ae92a-9af0-48ed-bcf9-8a6c8373573f' 2020-01-25 05:54:06,208+02 ERROR [org.ovirt.engine.core.bll.storage.disk.AddDiskCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-14) [snapshots_create_b2ac89d5-8875-4da7] Ending command 'org.ovirt.engine.core.bll.storage.disk.AddDiskCommand' with failure. 2020-01-25 05:54:06,212+02 ERROR [org.ovirt.engine.core.bll.storage.disk.image.AddImageFromScratchCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-14) [snapshots_create_b2ac89d5-8875-4da7] Ending command 'org.ovirt.engine.core.bll.storage.disk.image.AddImageFromScratchCommand' with failure. 2020-01-25 05:54:06,229+02 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMRevertTaskVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-14) [snapshots_create_b2ac89d5-8875-4da7] Trying to revert unknown task 'cb70fb1f-fca7-4cdc-a590-9191104e4bb9' 2020-01-25 05:54:06,251+02 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-14) [] EVENT_ID: USER_ADD_DISK_FINISHED_FAILURE(2,022), Add-Disk operation failed to complete. 2020-01-25 05:54:06,253+02 ERROR [org.ovirt.engine.core.bll.storage.disk.AddDiskCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-14) [snapshots_create_b2ac89d5-8875-4da7] Ending command 'org.ovirt.engine.core.bll.storage.disk.AddDiskCommand' with failure. 2020-01-25 05:54:06,258+02 ERROR [org.ovirt.engine.core.bll.storage.disk.image.AddImageFromScratchCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-14) [snapshots_create_b2ac89d5-8875-4da7] Ending command 'org.ovirt.engine.core.bll.storage.disk.image.AddImageFromScratchCommand' with failure. 2020-01-25 05:54:06,267+02 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMRevertTaskVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-14) [snapshots_create_b2ac89d5-8875-4da7] Trying to revert unknown task 'c17c19ee-5287-436e-b6a4-2918f875623e' 2020-01-25 05:54:06,288+02 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-14) [] EVENT_ID: USER_ADD_DISK_FINISHED_FAILURE(2,022), Add-Disk operation failed to complete. 2020-01-25 05:54:06,298+02 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-14) [] EVENT_ID: USER_CREATE_SNAPSHOT_FINISHED_FAILURE(69), Failed to complete snapshot 'snap_TestCase11660_2505484173' creation for VM 'vm_TestCase11660_2505481958'. vdsm: 2020-01-24 22:54:04,629-0500 ERROR (jsonrpc/3) [api] FINISH snapshot error=VM 'd4819a61-6d48-4a27-a37c-a196f89947a7' was not defined yet or was undefined (api:134) Traceback (most recent call last): File "/usr/lib/python3.6/site-packages/vdsm/common/api.py", line 124, in method ret = func(*args, **kwargs) File "/usr/lib/python3.6/site-packages/vdsm/API.py", line 694, in snapshot return vm.snapshot(snapDrives, memoryParams, frozen=frozen) File "<decorator-gen-267>", line 2, in snapshot File "/usr/lib/python3.6/site-packages/vdsm/common/api.py", line 101, in method return func(*args, **kwargs) File "/usr/lib/python3.6/site-packages/vdsm/virt/vm.py", line 4136, in snapshot self.clear_drive_threshold(drive_obj, old_volume_id) File "/usr/lib/python3.6/site-packages/vdsm/virt/vm.py", line 3814, in clear_drive_threshold chains = self._driveGetActualVolumeChain([drive]) File "/usr/lib/python3.6/site-packages/vdsm/virt/vm.py", line 5553, in _driveGetActualVolumeChain self._updateDomainDescriptor() File "/usr/lib/python3.6/site-packages/vdsm/virt/vm.py", line 4695, in _updateDomainDescriptor domxml = self._dom.XMLDesc(0) if xml is None else xml File "/usr/lib/python3.6/site-packages/vdsm/virt/virdomain.py", line 50, in __getattr__ % self.vmid) vdsm.virt.virdomain.NotConnectedError: VM 'd4819a61-6d48-4a27-a37c-a196f89947a7' was not defined yet or was undefined 2020-01-24 22:54:04,696-0500 INFO (jsonrpc/3) [api.virt] FINISH snapshot return={'status': {'code': 100, 'message': 'General Exception: ("VM \'d4819a61-6d48-4a27-a37c-a196f89947a7\' was not defined yet or was undefined",)'}} from=::ffff:10.46.16.85,49584, flow_id=snapshots_create_b2ac89d5-8875-4da7, vmId=d4819a61-6d48-4a27-a37c-a196f89947a7 (api:54) Version-Release number of selected component (if applicable): ovirt-engine-4.4.0-0.17.master.el7.noarch vdsm-4.40.1-1.el8ev.x86_64 How reproducible: Once Steps to Reproduce: 1. Try to create live snapshot Actual results: Operation failed Expected results: Operation should succeed Additional info: Relevant logs are attached.
Evelina, can you please add the full steps to reproduce? It means that the VM doesn't exist when we try to create the memory disks to it which sounds strange to me.
1. Create VM with disk 2. Run VM 3. Try to create live snapshot Happened again in our automation, attaching relevant logs
Created attachment 1662381 [details] logs
Benny, can you please have a look?
the qemu process probably died: 2020-02-04 22:01:16,565-0500 INFO (libvirt/events) [virt.vm] (vmId='b60078c1-a2c9-46b5-beaf-6e7fc3970113') underlying process disconnected (vm:968) 2020-02-04 22:01:16,566-0500 INFO (libvirt/events) [virt.vm] (vmId='b60078c1-a2c9-46b5-beaf-6e7fc3970113') Release VM resources (vm:4758) 2020-02-04 22:01:16,566-0500 INFO (libvirt/events) [virt.vm] (vmId='b60078c1-a2c9-46b5-beaf-6e7fc3970113') Stopping connection (guestagent:441) 2020-02-04 22:01:16,566-0500 DEBUG (libvirt/events) [storage.TaskManager.Task] (Task='25a2f38a-4dfb-4ab8-b1cf-b3f8f01bcca0') moving from state preparing -> state preparing (task:618) 2020-02-04 22:01:17,843-0500 INFO (libvirt/events) [virt.vm] (vmId='b60078c1-a2c9-46b5-beaf-6e7fc3970113') Changed state to Down: Lost connection with qemu process (code=2) (vm:1592) 2020-02-04 22:01:17,883-0500 INFO (libvirt/events) [virt.vm] (vmId='b60078c1-a2c9-46b5-beaf-6e7fc3970113') Stopping connection (guestagent:441) 2020-02-04 22:01:17,890-0500 INFO (jsonrpc/2) [api.virt] START destroy(gracefulAttempts=1) from=::ffff:10.46.16.132,48560, vmId=b60078c1-a2c9-46b5-beaf-6e7fc3970113 (api:48) please provide qemu logs
Created attachment 1662435 [details] qemu-log
qemu-kvm: block/io.c:1879: bdrv_co_write_req_prepare: Assertion `child->perm & BLK_PERM_WRITE' failed. 2020-02-05 03:01:14.645+0000: shutting down, reason=crashed what versions of qemu/libvirt are used?
anyway it's this one https://bugzilla.redhat.com/show_bug.cgi?id=1781637
Thanks Benny. Evelina, can you please close it as duplication?
if we don't have an engine bug for this, it should depend on the qemu bug
(In reply to Benny Zlotnik from comment #11) > if we don't have an engine bug for this, it should depend on the qemu bug Right.
(In reply to Benny Zlotnik from comment #8) > qemu-kvm: block/io.c:1879: bdrv_co_write_req_prepare: Assertion `child->perm > & BLK_PERM_WRITE' failed. > 2020-02-05 03:01:14.645+0000: shutting down, reason=crashed > > what versions of qemu/libvirt are used? libvirt-6.0.0-2.module+el8.2.0+5513+34927b6c.x86_64
*** This bug has been marked as a duplicate of bug 1781637 ***
This bug report has Keywords: Regression or TestBlocker. Since no regressions or test blockers are allowed between releases, it is also being identified as a blocker for this release. Please resolve ASAP.
crash is fixed, but 1798072 still prevents live merge to work, so the only thing you can verify is that qemu no longer crashes
Verified that qemu is no longer crashes. libvirt-6.0.0-16.module+el8.2.0+6131+4e715f3b.x86_64 vdsm-4.40.11-1.el8ev.x86_64 ovirt-engine-4.4.0-0.31.master.el8ev.noarch
This bugzilla is included in oVirt 4.4.0 release, published on May 20th 2020. Since the problem described in this bug report should be resolved in oVirt 4.4.0 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.