From 37cc22974906f6808364a9421d69235918cc6cf9 Mon Sep 17 00:00:00 2001 From: Dan Helfman Date: Tue, 23 Jun 2020 11:01:03 -0700 Subject: [PATCH] Fix duplicate logging to Healthchecks and send "after_*" hooks output to Healthchecks (#328). --- NEWS | 1 + borgmatic/commands/borgmatic.py | 54 +++++++++++++------- borgmatic/hooks/healthchecks.py | 12 +++++ docs/how-to/monitor-your-backups.md | 12 ++--- tests/integration/hooks/test_healthchecks.py | 24 +++++++++ 5 files changed, 78 insertions(+), 25 deletions(-) create mode 100644 tests/integration/hooks/test_healthchecks.py diff --git a/NEWS b/NEWS index de82c4f68..4ac6ec324 100644 --- a/NEWS +++ b/NEWS @@ -1,5 +1,6 @@ 1.5.7.dev0 * #327: Fix broken pass-through of BORG_* environment variables to Borg. + * #328: Fix duplicate logging to Healthchecks and send "after_*" hooks output to Healthchecks. * #331: Add SSL support to PostgreSQL database configuration. * #333: Fix for potential data loss (data not getting backed up) when borgmatic omitted configured source directories in certain situations. Specifically, this occurred when two source directories diff --git a/borgmatic/commands/borgmatic.py b/borgmatic/commands/borgmatic.py index dc52cbeed..3420d30fa 100644 --- a/borgmatic/commands/borgmatic.py +++ b/borgmatic/commands/borgmatic.py @@ -132,16 +132,6 @@ def run_configuration(config_filename, config, arguments): if not encountered_error: try: - if prune_create_or_check: - dispatch.call_hooks( - 'ping_monitor', - hooks, - config_filename, - monitor.MONITOR_HOOK_NAMES, - monitor.State.FINISH, - monitoring_log_level, - global_arguments.dry_run, - ) if 'prune' in arguments: command.execute_hook( hooks.get('after_prune'), @@ -174,6 +164,24 @@ def run_configuration(config_filename, config, arguments): 'post-check', global_arguments.dry_run, ) + if prune_create_or_check: + dispatch.call_hooks( + 'ping_monitor', + hooks, + config_filename, + monitor.MONITOR_HOOK_NAMES, + monitor.State.FINISH, + monitoring_log_level, + global_arguments.dry_run, + ) + dispatch.call_hooks( + 'destroy_monitor', + hooks, + config_filename, + monitor.MONITOR_HOOK_NAMES, + monitoring_log_level, + global_arguments.dry_run, + ) except (OSError, CalledProcessError) as error: if command.considered_soft_failure(config_filename, error): return @@ -185,15 +193,6 @@ def run_configuration(config_filename, config, arguments): if encountered_error and prune_create_or_check: try: - dispatch.call_hooks( - 'ping_monitor', - hooks, - config_filename, - monitor.MONITOR_HOOK_NAMES, - monitor.State.FAIL, - monitoring_log_level, - global_arguments.dry_run, - ) command.execute_hook( hooks.get('on_error'), hooks.get('umask'), @@ -204,6 +203,23 @@ def run_configuration(config_filename, config, arguments): error=encountered_error, output=getattr(encountered_error, 'output', ''), ) + dispatch.call_hooks( + 'ping_monitor', + hooks, + config_filename, + monitor.MONITOR_HOOK_NAMES, + monitor.State.FAIL, + monitoring_log_level, + global_arguments.dry_run, + ) + dispatch.call_hooks( + 'destroy_monitor', + hooks, + config_filename, + monitor.MONITOR_HOOK_NAMES, + monitoring_log_level, + global_arguments.dry_run, + ) except (OSError, CalledProcessError) as error: if command.considered_soft_failure(config_filename, error): return diff --git a/borgmatic/hooks/healthchecks.py b/borgmatic/hooks/healthchecks.py index ceeee2571..86986ef33 100644 --- a/borgmatic/hooks/healthchecks.py +++ b/borgmatic/hooks/healthchecks.py @@ -107,3 +107,15 @@ def ping_monitor(ping_url_or_uuid, config_filename, state, monitoring_log_level, if not dry_run: logging.getLogger('urllib3').setLevel(logging.ERROR) requests.post(ping_url, data=payload.encode('utf-8')) + + +def destroy_monitor(ping_url_or_uuid, config_filename, monitoring_log_level, dry_run): + ''' + Remove the monitor handler that was added to the root logger. This prevents the handler from + getting reused by other instances of this monitor. + ''' + logger = logging.getLogger() + + for handler in tuple(logger.handlers): + if isinstance(handler, Forgetful_buffering_handler): + logger.removeHandler(handler) diff --git a/docs/how-to/monitor-your-backups.md b/docs/how-to/monitor-your-backups.md index 1f4b93e8d..d53cd63dc 100644 --- a/docs/how-to/monitor-your-backups.md +++ b/docs/how-to/monitor-your-backups.md @@ -123,13 +123,13 @@ hooks run, borgmatic lets Healthchecks know that it has started if any of the `prune`, `create`, or `check` actions are run. Then, if the actions complete successfully, borgmatic notifies Healthchecks of -the success before the `after_backup` hooks run, and includes borgmatic logs in +the success after the `after_backup` hooks run, and includes borgmatic logs in the payload data sent to Healthchecks. This means that borgmatic logs show up in the Healthchecks UI, although be aware that Healthchecks currently has a 10-kilobyte limit for the logs in each ping. If an error occurs during any action or hook, borgmatic notifies Healthchecks -before the `on_error` hooks run, also tacking on logs including the error +after the `on_error` hooks run, also tacking on logs including the error itself. But the logs are only included for errors that occur when a `prune`, `create`, or `check` action is run. @@ -161,9 +161,9 @@ begins, ends, or errors. Specifically, after the `before_backup` hooks run, borgmatic lets Cronitor know that it has started if any of the `prune`, `create`, or `check` actions are run. Then, if the actions complete -successfully, borgmatic notifies Cronitor of the success before the +successfully, borgmatic notifies Cronitor of the success after the `after_backup` hooks run. And if an error occurs during any action or hook, -borgmatic notifies Cronitor before the `on_error` hooks run. +borgmatic notifies Cronitor after the `on_error` hooks run. You can configure Cronitor to notify you by a [variety of mechanisms](https://cronitor.io/docs/cron-job-notifications) when backups fail @@ -189,9 +189,9 @@ begins, ends, or errors. Specifically, after the `before_backup` hooks run, borgmatic lets Cronhub know that it has started if any of the `prune`, `create`, or `check` actions are run. Then, if the actions complete -successfully, borgmatic notifies Cronhub of the success before the +successfully, borgmatic notifies Cronhub of the success after the `after_backup` hooks run. And if an error occurs during any action or hook, -borgmatic notifies Cronhub before the `on_error` hooks run. +borgmatic notifies Cronhub after the `on_error` hooks run. Note that even though you configure borgmatic with the "start" variant of the ping URL, borgmatic substitutes the correct state into the URL when pinging diff --git a/tests/integration/hooks/test_healthchecks.py b/tests/integration/hooks/test_healthchecks.py new file mode 100644 index 000000000..0c37013bd --- /dev/null +++ b/tests/integration/hooks/test_healthchecks.py @@ -0,0 +1,24 @@ +import logging + +from flexmock import flexmock + +from borgmatic.hooks import healthchecks as module + + +def test_destroy_monitor_removes_healthchecks_handler(): + logger = logging.getLogger() + original_handlers = list(logger.handlers) + logger.addHandler(module.Forgetful_buffering_handler(byte_capacity=100, log_level=1)) + + module.destroy_monitor(flexmock(), flexmock(), flexmock(), flexmock()) + + assert logger.handlers == original_handlers + + +def test_destroy_monitor_without_healthchecks_handler_does_not_raise(): + logger = logging.getLogger() + original_handlers = list(logger.handlers) + + module.destroy_monitor(flexmock(), flexmock(), flexmock(), flexmock()) + + assert logger.handlers == original_handlers