Fix duplicate logging to Healthchecks and send "after_*" hooks output to Healthchecks (#328).

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

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,6 +193,16 @@ def run_configuration(config_filename, config, arguments):
 
     if encountered_error and prune_create_or_check:
         try:
+            command.execute_hook(
+                hooks.get('on_error'),
+                hooks.get('umask'),
+                config_filename,
+                'on-error',
+                global_arguments.dry_run,
+                repository=error_repository,
+                error=encountered_error,
+                output=getattr(encountered_error, 'output', ''),
+            )
             dispatch.call_hooks(
                 'ping_monitor',
                 hooks,
@@ -194,15 +212,13 @@ def run_configuration(config_filename, config, arguments):
                 monitoring_log_level,
                 global_arguments.dry_run,
             )
-            command.execute_hook(
-                hooks.get('on_error'),
-                hooks.get('umask'),
+            dispatch.call_hooks(
+                'destroy_monitor',
+                hooks,
                 config_filename,
-                'on-error',
+                monitor.MONITOR_HOOK_NAMES,
+                monitoring_log_level,
                 global_arguments.dry_run,
-                repository=error_repository,
-                error=encountered_error,
-                output=getattr(encountered_error, 'output', ''),
             )
         except (OSError, CalledProcessError) as error:
             if command.considered_soft_failure(config_filename, error):

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)

docs/how-to/monitor-your-backups.md

@@ -123,13 +123,13 @@ hooks</a> 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 <a
 href="https://torsion.org/borgmatic/docs/how-to/add-preparation-and-cleanup-steps-to-backups/">`before_backup`
 hooks</a> 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 <a
 href="https://torsion.org/borgmatic/docs/how-to/add-preparation-and-cleanup-steps-to-backups/">`before_backup`
 hooks</a> 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

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