Bug 2039717

Summary: Confusing event log messages in case of multiple parallel backup stop commands
Product: [oVirt] ovirt-engine Reporter: Pavel Bar <pbar>
Component: Backup-Restore.VMsAssignee: Mark Kemel <mkemel>
Status: CLOSED DUPLICATE QA Contact: Avihai <aefrat>
Severity: medium Docs Contact: bugs <bugs>
Priority: unspecified    
Version: 4.4.10CC: ahadas, bugs, michal.skrivanek
Target Milestone: ---Flags: pm-rhel: ovirt-4.5?
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2022-04-20 14:32:55 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: Storage RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Description Pavel Bar 2022-01-12 09:49:21 UTC
Description of problem:
If 2 (or more) 'backup stop' operations are executed in parallel in backup "READY" or "FINALIZING" phases or 'backup stop' operation is executed in "SUCCEEDED" phase, the event log is slightly confusing - both "backup failed to finalize" and "backup finalized" messages appear for the same backup UUID.

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

How reproducible:
The most simple way is to run 'backup start', optionally run 'backup download', and then 'backup stop' 2 (or more) times in parallel.
Another (more difficult) option is to execute a full backup and try to schedule a separate 'backup stop' when the full backup also started/starting the finalization.

Steps to Reproduce:
1. Run 'backup start'.
2. Optionally can run 'backup download'.
3. Run 'backup stop' several times in parallel.

Actual results:
Event log contains contradicting error messages: ones that says that there was an issue with backup finalization, the other states that everything worked successfully. While in fact backup completed successfully, the 2nd (3rd, etc.) 'backup stop' executions failed. The engine log and the 'backup stop' command output contain the correct reason.

The event log will contain the following:
NORMAL  Backup 7e0f5995-40e8-4c58-876f-b9b95553d453 for VM VM1 finalized (User: admin@internal-authz).
ERROR   Backup 7e0f5995-40e8-4c58-876f-b9b95553d453 for VM VM1 failed to finalize (User: admin@internal-authz).
NORMAL   Backup 7e0f5995-40e8-4c58-876f-b9b95553d453 for VM VM1 completed successfully (User: admin@internal-authz).

The log will also contain the premature log message.
2022-01-12 11:29:28,698+02 WARN  [org.ovirt.engine.core.bll.storage.backup.StopVmBackupCommand] (default task-12) [7817cf43-ada0-4ed9-8f44-cfed96786e72] VM 'ebcf2f06-92a8-4437-907c-4e4465b7cf92' backup '7e0f5995-40e8-4c58-876f-b9b95553d453' is already in 'FINALIZING' phase, no need to stop the backup again

The 'backup stop' command #1 will end successfully:
Backup '7e0f5995-40e8-4c58-876f-b9b95553d453' completed successfully
The 'backup stop' command #2 (#3, ...) will end with the following error:
ovirtsdk4.Error: Fault reason is "Operation Failed". Fault detail is "[vm 'ebcf2f06-92a8-4437-907c-4e4465b7cf92' backup '7e0f5995-40e8-4c58-876f-b9b95553d453' is already in 'finalizing' phase, no need to stop the backup again]". HTTP response code is 400.

Expected results:
The event log should contain a "backup  already in 'XYZ' phase, no need to stop the backup again" warning message vs. the current "backup failed to finalize" error message (where XYZ is either "finalizing" or "finalizing_failure" or "succeeded" or "failed").

Comment 2 Michal Skrivanek 2022-04-11 08:54:50 UTC
still relevant? either fix or close please

Comment 3 Arik 2022-04-20 14:32:55 UTC

*** This bug has been marked as a duplicate of bug 1900552 ***