Bug 2037334 - Confusing event log messages in case of premature backup stop command
Summary: Confusing event log messages in case of premature backup stop command
Keywords:
Status: CLOSED WONTFIX
Alias: None
Product: ovirt-engine
Classification: oVirt
Component: Backup-Restore.VMs
Version: 4.4.10
Hardware: Unspecified
OS: Unspecified
unspecified
medium
Target Milestone: ---
: ---
Assignee: Mark Kemel
QA Contact: Evelina Shames
bugs@ovirt.org
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2022-01-05 13:14 UTC by Pavel Bar
Modified: 2022-04-18 11:24 UTC (History)
2 users (show)

Fixed In Version:
Clone Of:
Environment:
Last Closed: 2022-04-18 11:23:03 UTC
oVirt Team: Storage
Embargoed:
pm-rhel: ovirt-4.5?


Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Red Hat Bugzilla 1900552 1 unspecified CLOSED [CBT][incremental backup] VmBackup.finalize synchronous instead of asynchronous 2022-08-23 19:40:48 UTC
Red Hat Issue Tracker RHV-44427 0 None None None 2022-01-05 13:21:02 UTC

Description Pavel Bar 2022-01-05 13:14:33 UTC
Description of problem:
In case of a premature 'backup stop' command (backup phase is one of: "INITIALIZING" / "CREATING_SCRATCH_DISKS" / "PREPARING_SCRATCH_DISK" / "STARTING" / "ADDING_BITMAPS" / "WAITING_FOR_BITMAPS"), the event log is slightly confusing - it complains about failure to finalize backup which is not 100% precise. The more correct message would be to state that the backup was finished prematurely and probably change it to warning log level.

Version-Release number of selected component (if applicable):
4.4.10

How reproducible:
Run full backup and at the same time (pretty much at the beginning of the full backup, before the backup phase changed to "READY") execute 'backup stop' command.

Steps to Reproduce:
1. Run full backup.
2. Shortly after that, execute 'backup stop' using the backup UUID of the above full backup.
3. The event log will contain: "Backup XYZ failed to finalize" confusing message.

Actual results:
Event log contains a confusing error message as if there was an issue with backup finalization, while in fact that was not the case. The engine log and the 'backup stop' command output contain the correct reason.

The event log will contain the following:
NORMAL  Backup ebf0ddbb-ae70-41c2-bce8-c8ce5fcf2db0 for VM VM1 started (User: admin@internal-authz).
ERROR   Backup ebf0ddbb-ae70-41c2-bce8-c8ce5fcf2db0 for VM VM1 failed to finalize (User: admin@internal-authz).
ERROR   Backup ebf0ddbb-ae70-41c2-bce8-c8ce5fcf2db0 for VM VM1 failed (User: admin@internal-authz).

The log will also contain the premature log message.
2022-01-05 14:03:14,066+02 WARN  [org.ovirt.engine.core.bll.storage.backup.StopVmBackupCommand] (default task-29) [3387e48c-5aa5-4308-8fc4-dc711b3088ed] Backup 'ebf0ddbb-ae70-41c2-bce8-c8ce5fcf2db0' is in 'CREATING_SCRATCH_DISKS' phase, premature backup stop was initiated.

The 'backup stop' command will end with the following error:
ovirtsdk4.Error: Fault reason is "Operation Failed". Fault detail is "[backup 'ebf0ddbb-ae70-41c2-bce8-c8ce5fcf2db0' is in 'creating scratch disks' phase, premature backup stop was initiated.]". HTTP response code is 400.

Expected results:
1) The event log should contain a "backup finished prematurely" warning message vs. the current "backup failed to finalize" error message.
2) Something to consider: the final "backup failed" error message might be better updated to something like "backup was canceled/stopped" and also changed to warning log level.

Comment 2 Mark Kemel 2022-04-18 11:23:03 UTC
In https://bugzilla.redhat.com/1900552 we are changing the way StopVmBackupCommand stops/finalizes Hybrid backup, 
which eliminates the above ERROR audit message, and there will be the same message if stop done both before and 
after READY state:

INFO: Backup ${backupId} for VM ${VmName} stopped (User: ${UserName}).

This covers fixing audit messages reported here, closing


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