Bug 2074112 - [Veeam] VM does not have a disk after restored from backup
Summary: [Veeam] VM does not have a disk after restored from backup
Keywords:
Status: CLOSED CURRENTRELEASE
Alias: None
Product: ovirt-engine
Classification: oVirt
Component: Backup-Restore.VMs
Version: 4.5.0
Hardware: x86_64
OS: Linux
unspecified
high
Target Milestone: ovirt-4.5.0-1
: ---
Assignee: Arik
QA Contact: Evelina Shames
bugs@ovirt.org
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2022-04-11 14:55 UTC by Roni
Modified: 2022-05-23 06:21 UTC (History)
11 users (show)

Fixed In Version: ovirt-engine-4.5.0.6
Clone Of:
Environment:
Last Closed: 2022-05-23 06:21:25 UTC
oVirt Team: Storage
Embargoed:
pm-rhel: ovirt-4.5?
lsvaty: blocker-
michal.skrivanek: exception+


Attachments (Terms of Use)
Engine logs during Backup and during Restore (17.75 KB, application/gzip)
2022-04-11 14:55 UTC, Roni
no flags Details
veeam error in log (69.06 KB, image/png)
2022-04-11 14:59 UTC, Roni
no flags Details
the support bundle pic (18.61 KB, image/png)
2022-04-12 14:05 UTC, Yury.Panchenko
no flags Details
support bundle (4.63 MB, application/zip)
2022-04-20 15:20 UTC, Arik
no flags Details
support_bundle log_level_5 during restore for comment #19 (15.46 MB, application/gzip)
2022-04-24 08:09 UTC, Roni
no flags Details
support_bundle log_level_5 during backup for comment #19 (15.34 MB, application/gzip)
2022-04-24 08:11 UTC, Roni
no flags Details


Links
System ID Private Priority Status Summary Last Updated
Github oVirt ovirt-engine pull 318 0 None open Block on execution of ImportVmFromConfiguration 2022-04-28 06:42:21 UTC
Github oVirt ovirt-engine pull 323 0 None open Block on execution of ImportVmFromConfiguration - backport 2022-05-03 07:41:30 UTC
Red Hat Issue Tracker RHV-45621 0 None None None 2022-04-11 15:07:35 UTC

Description Roni 2022-04-11 14:55:48 UTC
Created attachment 1871828 [details]
Engine logs during Backup and during Restore

Created attachment 1871828 [details]
Engine logs during Backup and during Restore

Created attachment 1871828 [details]
Engine logs during Backup and during Restore

Description of problem:
VM does not have a disk after being restored from 'Veeam' backup server

Version-Release number of selected component (if applicable):
RHV: 4.5.0.1-605.90f87fe14688.14.el8ev
Veeam: 1.0.1488

How reproducible:
100%

Steps to Reproduce:
1. Deploy Veeam backup vendor over RHV
2. Create a VM based on the guest-image template
3. Backup the VM using Veeam (with default setting)
4. Restore the VM using Veeam (with default setting)
5. Try to run the VM

Actual results:
Got an error: "Cannot run VM without at least one bootable disk."


Expected results:
VM should start successfully

Additional info:
- See attached logs and screen capture of the Veeam error
- The same scenario works well in 4.4.10

Comment 2 RHEL Program Management 2022-04-11 15:25:14 UTC
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.

Comment 3 Arik 2022-04-11 17:06:31 UTC
Yury, it looks like the backup application doesn't try to upload images when working against RHV 4.4 SP1 during "Restore" and it works fine during "Disk Restore". The same backup application works fine in both cases against RHV 4.4.10. Any idea what can go wrong?

Comment 4 Yury.Panchenko 2022-04-12 13:49:17 UTC
Hello there,
Unfortunately, I don't have access to the logs.
Could you solve that?
Thanks.

Comment 5 Arik 2022-04-12 13:59:30 UTC
The error presented on the Veeam side is now available but maybe you can point us to a relevant log that will be more informative? :)

Comment 6 Yury.Panchenko 2022-04-12 14:04:14 UTC
Could you upload a support bundle from the proxy and also engine.log ?

Comment 7 Yury.Panchenko 2022-04-12 14:05:10 UTC
Created attachment 1871969 [details]
the support bundle pic

Comment 8 Arik 2022-04-12 14:12:16 UTC
Roni, can you attach it please?

Comment 11 Roni 2022-04-12 14:40:26 UTC
(In reply to Yury.Panchenko from comment #6)
> Could you upload a support bundle from the proxy and also engine.log ?

Yury,
The engine logs are already attached I remove the private flag (maybe that's why you didn't see it)
I add the support bandle as well now!
As a result, the Engine logs and the Veeam logs do not belong to the same flow
If that does not help, please let me know, I will take logs again

Comment 12 Yury.Panchenko 2022-04-12 15:41:50 UTC
Are there any changes in disk attach API?
2022-04-11 13:36:59,463Z WARN  [org.ovirt.engine.core.bll.storage.disk.AttachDiskToVmCommand] (default task-355) [3db16e07] Validation of action 'AttachDiskToVm' failed for user admin@internal-authz. Reasons: VAR__ACTION__ATTACH_ACTION_TO,VAR__TYPE__DISK,ACTION_TYPE_FAILED_DISK_NOT_EXIST
2022-04-11 13:36:59,467Z WARN  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-355) [3db16e07] EVENT_ID: VM_IMPORT_FROM_CONFIGURATION_ATTACH_DISKS_FAILED(175), VM roni_test_4 has been imported from the given configuration but the following disk(s) failed to attach: latest-rhel-guest-image-8.6-infra.

Comment 13 Arik 2022-04-12 15:45:27 UTC
(In reply to Yury.Panchenko from comment #12)
> Are there any changes in disk attach API?

That's what I suspected as well but that didn't change
I saw no indication of transfer image in the log - the disks were not uploaded and so this error is correct, the disk really doesn't exist

Comment 14 Roni 2022-04-12 16:47:30 UTC
Note that the issue is also reproduced manually, and as a WA you can run Disk Restore to restore the missing disk

Comment 15 Roni 2022-04-12 20:50:56 UTC
Yury,
Any idea what is the 'No description' error we see in the Veeam log (please see attached 'veeam error in log')

Comment 16 Arik 2022-04-20 07:24:20 UTC
We suspected this has something to do with the changes for hybrid backup but we disabled hybrid backup on 4.7 cluster level, took a backup of a VM and we were still unable to restore it. We really need assistance from Veeam with that - it seems the backup application is affected by some change in oVirt 4.5 but hard to tell which one

Comment 17 Yury.Panchenko 2022-04-20 11:48:27 UTC
Hello there,
could you upload the veeam proxy support bundle?
https://helpcenter.veeam.com/docs/vbrhv/userguide/export_logs.html?ver=10

Comment 18 Arik 2022-04-20 15:20:50 UTC
Created attachment 1873825 [details]
support bundle

Comment 19 Yury.Panchenko 2022-04-20 17:10:09 UTC
Thank you.
The app creates the vm by import it from the configuration without disks.
According to the logs the app couldn't create the vm, and it got Reason: 'Operation failed', Detail: 'No description' from the RHV
[2022-04-11] [13:36:59.010] [84223] [Info ] [Backup] Sent info: Creating VM...
[2022-04-11] [13:36:59.010] [84223] [Info ] [RHEVClient] Creating VM.
	 ClusterId: ce5e4aef-d9f4-4142-9cc4-863a3736317b
	 RegenerateIds: 0
	 Init Data (length):9633
[2022-04-11] [13:36:59.557] [84223] [Info ] [Backup] Sent event (3): Unable to create VM: Reason: 'Operation failed', Detail: 'No description'


in the engine log I see the same error, but the vm was created
2022-04-11 13:36:59,359Z INFO  [org.ovirt.engine.core.bll.exportimport.ImportVmFromConfigurationCommand] (default task-355) [3e2cab0f-80de-4561-8080-ee51021b6fe9] Running command: ImportVmFromConfigurationCommand internal: false. Entities affected :  ID: ce5e4aef-d9f4-4142-9cc4-863a3736317b Type: ClusterAction group CREATE_VM with role type USER,  ID: 00000000-0000-0000-0000-000000000000 Type: StorageAction group IMPORT_EXPORT_VM with role type ADMIN
2022-04-11 13:36:59,408Z INFO  [org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand] (default task-355) [3e2cab0f-80de-4561-8080-ee51021b6fe9] START, SetVmStatusVDSCommand( SetVmStatusVDSCommandParameters:{vmId='d2be4905-d8bd-4409-aa57-c536131c2fbe', status='Down', exitStatus='Normal'}), log id: 579aec2c
2022-04-11 13:36:59,416Z INFO  [org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand] (default task-355) [3e2cab0f-80de-4561-8080-ee51021b6fe9] FINISH, SetVmStatusVDSCommand, return: , log id: 579aec2c
2022-04-11 13:36:59,463Z WARN  [org.ovirt.engine.core.bll.storage.disk.AttachDiskToVmCommand] (default task-355) [3db16e07] Validation of action 'AttachDiskToVm' failed for user admin@internal-authz. Reasons: VAR__ACTION__ATTACH_ACTION_TO,VAR__TYPE__DISK,ACTION_TYPE_FAILED_DISK_NOT_EXIST
2022-04-11 13:36:59,467Z WARN  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-355) [3db16e07] EVENT_ID: VM_IMPORT_FROM_CONFIGURATION_ATTACH_DISKS_FAILED(175), VM roni_test_4 has been imported from the given configuration but the following disk(s) failed to attach: latest-rhel-guest-image-8.6-infra.

Could you increase the app log level by editing
/opt/VeeamBackupAgent/appsettings.json and setting "LogLevel" : 5
then restart the proxy and repeat the test
Thank you.

Comment 20 Arik 2022-04-20 17:41:23 UTC
Thanks for your feedback Yury
This would need to wait for Roni until he's back next week
One question from my side though - we've noticed that when using the same Veeam application against RHV 4.4.10, it first uploads the disks and only then calling the import-from-configuration command and so the disk attachment succeeds, do you see in the log of the Veeam application any hint why the disk is not being uploaded first?

Comment 21 Roni 2022-04-24 08:09:16 UTC
Created attachment 1874645 [details]
support_bundle log_level_5 during restore for comment #19

Comment 22 Roni 2022-04-24 08:11:31 UTC
Created attachment 1874646 [details]
support_bundle log_level_5 during backup for comment #19

Comment 23 Roni 2022-04-24 08:17:42 UTC
(In reply to Yury.Panchenko from comment #19)
> Thank you.
> The app creates the vm by import it from the configuration without disks.
> According to the logs the app couldn't create the vm, and it got Reason:
> 'Operation failed', Detail: 'No description' from the RHV
> [2022-04-11] [13:36:59.010] [84223] [Info ] [Backup] Sent info: Creating
> VM...
> [2022-04-11] [13:36:59.010] [84223] [Info ] [RHEVClient] Creating VM.
> 	 ClusterId: ce5e4aef-d9f4-4142-9cc4-863a3736317b
> 	 RegenerateIds: 0
> 	 Init Data (length):9633
> [2022-04-11] [13:36:59.557] [84223] [Info ] [Backup] Sent event (3): Unable
> to create VM: Reason: 'Operation failed', Detail: 'No description'
> 
> 
> in the engine log I see the same error, but the vm was created
> 2022-04-11 13:36:59,359Z INFO 
> [org.ovirt.engine.core.bll.exportimport.ImportVmFromConfigurationCommand]
> (default task-355) [3e2cab0f-80de-4561-8080-ee51021b6fe9] Running command:
> ImportVmFromConfigurationCommand internal: false. Entities affected :  ID:
> ce5e4aef-d9f4-4142-9cc4-863a3736317b Type: ClusterAction group CREATE_VM
> with role type USER,  ID: 00000000-0000-0000-0000-000000000000 Type:
> StorageAction group IMPORT_EXPORT_VM with role type ADMIN
> 2022-04-11 13:36:59,408Z INFO 
> [org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand] (default task-355)
> [3e2cab0f-80de-4561-8080-ee51021b6fe9] START, SetVmStatusVDSCommand(
> SetVmStatusVDSCommandParameters:{vmId='d2be4905-d8bd-4409-aa57-c536131c2fbe',
> status='Down', exitStatus='Normal'}), log id: 579aec2c
> 2022-04-11 13:36:59,416Z INFO 
> [org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand] (default task-355)
> [3e2cab0f-80de-4561-8080-ee51021b6fe9] FINISH, SetVmStatusVDSCommand,
> return: , log id: 579aec2c
> 2022-04-11 13:36:59,463Z WARN 
> [org.ovirt.engine.core.bll.storage.disk.AttachDiskToVmCommand] (default
> task-355) [3db16e07] Validation of action 'AttachDiskToVm' failed for user
> admin@internal-authz. Reasons:
> VAR__ACTION__ATTACH_ACTION_TO,VAR__TYPE__DISK,
> ACTION_TYPE_FAILED_DISK_NOT_EXIST
> 2022-04-11 13:36:59,467Z WARN 
> [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
> (default task-355) [3db16e07] EVENT_ID:
> VM_IMPORT_FROM_CONFIGURATION_ATTACH_DISKS_FAILED(175), VM roni_test_4 has
> been imported from the given configuration but the following disk(s) failed
> to attach: latest-rhel-guest-image-8.6-infra.
> 
> Could you increase the app log level by editing
> /opt/VeeamBackupAgent/appsettings.json and setting "LogLevel" : 5
> then restart the proxy and repeat the test
> Thank you.

Hi Yury

Sorry for the delay just return from a long vacation
Please see attached:   
1. "support_bundle log_level_5 during backup for comment #19"    veeam level5 & engine logs taken during backup
2. "support_bundle log_level_5 during restore for comment #19"   veeam level5 & engine logs taken during restore

Thx
Roni

Comment 24 Yury.Panchenko 2022-04-27 14:16:18 UTC
Hello Roni and Arik,
We've found the problem.
Before 4.4 SP1 the app used to get code "201 Created" from import vm request.
Now you're returning "202 Accepted", so the app don't expect this.

Comment 25 Arik 2022-04-27 15:18:11 UTC
Thanks Yury, that's probably a consequence of a change I've made for 4.5:
https://github.com/oVirt/ovirt-engine/commit/a309569546d7cf43e5f586f6cca7180ee8e8cd85

I can argue that you should also check for "202 Accepted" but as I understand it would affect existing clients, we'll see if we can return "Created" for calls like you do (for which the import operation should really complete before you get the results)

Comment 26 Yury.Panchenko 2022-04-27 15:34:02 UTC
It's ok for us to check both codes in the next version, but I'd like to ask you to keep API compatibiliy when it possible

Comment 27 Arik 2022-04-28 06:42:21 UTC
(In reply to Yury.Panchenko from comment #26)
> It's ok for us to check both codes in the next version, but I'd like to ask
> you to keep API compatibiliy when it possible

Yeah, so please do check both as from the next version
I posted a PR that can change back the response to "201 Created" and still address the issues we had with the previous mechanism, let's see how it goes

Comment 28 Roni 2022-05-08 08:52:12 UTC
Verified on 4.5.0.6-0.7.el8ev
vdsm-4.50.0.13-1.el8ev.x86_64


Note You need to log in before you can comment on or make changes to this bug.