Description of problem: RHEV-M is logging message as "started" and "finished" messages in the audit log without any other information what is started/finished. This is happening thrice everyday at same time ended up in 6 unnecessary email notification to customer. == 2016-08-15 13:00:47.29152+05:30 | Finished 2016-08-15 13:00:47.26449+05:30 | Finished 2016-08-15 13:00:47.254057+05:30 | Finished 2016-08-15 13:00:47.142476+05:30 | Finished 2016-08-15 13:00:02.432429+05:30 | Started 2016-08-15 13:00:02.422776+05:30 | Started 2016-08-15 13:00:02.413265+05:30 | Started 2016-08-15 13:00:01.987011+05:30 | Started 2016-08-14 13:00:47.870784+05:30 | Finished 2016-08-14 13:00:47.859678+05:30 | Finished 2016-08-14 13:00:47.837872+05:30 | Finished 2016-08-14 13:00:47.732752+05:30 | Finished 2016-08-14 13:00:02.442924+05:30 | Started 2016-08-14 13:00:02.428725+05:30 | Started 2016-08-14 13:00:02.417798+05:30 | Started 2016-08-14 13:00:02.228046+05:30 | Started === Notification log === 2016-08-14 03:31:46,173 INFO [org.ovirt.engine.core.notifier.transport.smtp.Smtp idle] Send mail subject='alertMessage (rhevm-1.mgmt.hss.int), [Started]' to='' 2016-08-14 03:31:46,761 INFO [org.ovirt.engine.core.notifier.transport.smtp.Smtp idle] Send mail subject='alertMessage (rhevm-1.mgmt.hss.int), [Finished]' to='' 2016-08-15 03:32:16,686 INFO [org.ovirt.engine.core.notifier.transport.smtp.Smtp idle] Send mail subject='alertMessage (rhevm-1.mgmt.hss.int), [Started]' to='' 2016-08-15 03:32:17,062 INFO [org.ovirt.engine.core.notifier.transport.smtp.Smtp idle] Send mail subject='alertMessage (rhevm-1.mgmt.hss.int), [Finished]' to='' === Version-Release number of selected component (if applicable): rhevm-3.6.7.5-0.1.el6.noarch How reproducible: Unknown Steps to Reproduce: Unknown Actual results: Events does not have clear information Expected results: Events should be having information what is started/finished. Additional info:
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