Bug 1372320

Attaching the logs. Also there is no related information in the engine log during this time.

Eli, could you please investigate?

Seems as a result of 
packaging/bin/engine-backup.sh.in

Its calling notify_engine and one of the params is "Started"/"Finished"
then this is passed to the SP engine_backup_log_sp.sql::LogEngineBackupEvent and recorded to the audit_log table 

I suggest to remove the parameter from the packaging/bin/engine-backup.sh.in:: notify_engine and setting it correctly in engine_backup_log_sp.sql::LogEngineBackupEvent

Is that acceptable ?

Taking the BZ

(In reply to Eli Mesika from comment #5)
> Seems as a result of 
> packaging/bin/engine-backup.sh.in
> 
> Its calling notify_engine and one of the params is "Started"/"Finished"
> then this is passed to the SP engine_backup_log_sp.sql::LogEngineBackupEvent
> and recorded to the audit_log table 
> 
> I suggest to remove the parameter from the
> packaging/bin/engine-backup.sh.in:: notify_engine and setting it correctly
> in engine_backup_log_sp.sql::LogEngineBackupEvent
> 
> Is that acceptable ?
> 
> Taking the BZ

Sounds good to me

(In reply to Martin Perina from comment #6)
> Sounds good to me

I noticed that this is used also to pass error messages, so I can not omit that, only change the "Started"/"Finished" to "Backup Started"/"Backup Finished" in 
packaging/bin/engine-backup.sh.in

*** Bug 1365808 has been marked as a duplicate of this bug. ***

Please note bug 1365808 comment 4.

(In reply to Yedidyah Bar David from comment #9)
> Please note bug 1365808 comment 4.

Otherwise, perhaps consider patching the function notify_engine to always prepend 'engine-backup:' to $message - it's called also in other places.

(In reply to Yedidyah Bar David from comment #10)
> (In reply to Yedidyah Bar David from comment #9)
> > Please note bug 1365808 comment 4.
> 
> Otherwise, perhaps consider patching the function notify_engine to always
> prepend 'engine-backup:' to $message - it's called also in other places.

The message is generated in shell script and we don't have any support for localization in shell scripts. So for 4.0.z we cannot do anything else then it's contained in the patch.

Moving back to MODIFIED for 4.1 as 4.0.5 clone has been created

Hello,
now in 4.0.5 
I get in console where I run the engine-backup command:
# engine-backup --mode=backup --scope=all --file=/root/engine-backup.archive_$(date +%d-%m-%Y) --log=/root/engine-backup_$(date +%d-%m-%Y).log
Backing up:
Notifying engine
- Files
- Engine database 'engine'
- DWH database 'ovirt_engine_history'
Packing into file '/root/engine-backup.archive_16-11-2016'
Notifying engine
Done.

So it seems there are 3 different backups...

And in fact engine web admin I get 6 messages:

Nov 16, 2016 11:30:02 AM Backup Finished
	
Nov 16, 2016 11:30:02 AM Backup Finished
	
Nov 16, 2016 11:30:02 AM Backup Finished
	
Nov 16, 2016 11:29:57 AM Backup Started
	
Nov 16, 2016 11:29:57 AM Backup Started
	
Nov 16, 2016 11:29:57 AM Backup Started

Is this what intended? Eventually could it be possible to add the target of the backup action (files, engine db and dwh db)?
So that if one of the three fails for any reason, I can see which one was... ?
Thanks

(In reply to Gianluca Cecchi from comment #14)
> Hello,
> now in 4.0.5 
> I get in console where I run the engine-backup command:
> # engine-backup --mode=backup --scope=all
> --file=/root/engine-backup.archive_$(date +%d-%m-%Y)
> --log=/root/engine-backup_$(date +%d-%m-%Y).log
> Backing up:
> Notifying engine
> - Files
> - Engine database 'engine'
> - DWH database 'ovirt_engine_history'
> Packing into file '/root/engine-backup.archive_16-11-2016'
> Notifying engine
> Done.
> 
> So it seems there are 3 different backups...
> 
> And in fact engine web admin I get 6 messages:
> 
> Nov 16, 2016 11:30:02 AM Backup Finished
> 	
> Nov 16, 2016 11:30:02 AM Backup Finished
> 	
> Nov 16, 2016 11:30:02 AM Backup Finished
> 	
> Nov 16, 2016 11:29:57 AM Backup Started
> 	
> Nov 16, 2016 11:29:57 AM Backup Started
> 	
> Nov 16, 2016 11:29:57 AM Backup Started
> 
> Is this what intended? Eventually could it be possible to add the target of
> the backup action (files, engine db and dwh db)?

Already done on master (4.1) - see [1]. Decided it's not important enough for 4.0 - feel free to open a bug asking to get it included anyway.

[1] https://gerrit.ovirt.org/65981

> So that if one of the three fails for any reason, I can see which one was...
> ?

Not really.

We notify for all of them in the beginning, then backup, then notify about all in the end.

If it fails in the middle, you'll see 3 mostly-identical errors. To see what actually failed, you'll have to check the log.

The original reason for notifying about all wasn't to allow you to see which was backed up and which was not, but to allow the engine to know if "enough" was backed up (i.e. at least files + engine db), or it should annoy you saying you should run backups. Not sure what's actually implemented eventually in that logic, current bug (and [1] above) affects only the log.

Verification builds:
ovirt-engine-4.1.0.3-0.1.el7
libvirt-client-2.0.0-10.el7_3.4.x86_64
vdsm-4.19.4-1.el7ev.x86_64
qemu-kvm-rhev-2.6.0-28.el7_3.3.x86_64
sanlock-3.4.0-1.el7.x86_64

Verification scenario:
1. run engine-backup command. 
2. Verify Backup Started and Backup Finished events are listed in events tab stating which process has started/finished. for example:

Feb 2, 2017 4:05:21 PM engine-backup: Backup Finished, scope=dwhdb, log=/root/engine-backup.log
Feb 2, 2017 4:05:21 PM engine-backup: Backup Finished, scope=db, log=/root/engine-backup.log
Feb 2, 2017 4:05:21 PM engine-backup: Backup Finished, scope=files, log=/root/engine-backup.log
Feb 2, 2017 4:05:17 PM engine-backup: Backup Started, scope=dwhdb, log=/root/engine-backup.log
Feb 2, 2017 4:05:17 PM engine-backup: Backup Started, scope=db, log=/root/engine-backup.log
Feb 2, 2017 4:05:17 PM engine-backup: Backup Started, scope=files, log=/root/engine-backup.log