Fix a regression in monitoring hooks in which an error pinged the finish state instead of the fail state (#1065).

NEWS

@@ -1,3 +1,7 @@
+2.0.3.dev0
+ * #1065: Fix a regression in monitoring hooks in which an error pinged the finish state instead of
+   the fail state.
+
 2.0.2
  * #1035: Document potential performance issues and workarounds with the ZFS, Btrfs, and LVM hooks:
    https://torsion.org/borgmatic/docs/how-to/snapshot-your-filesystems/

borgmatic/commands/borgmatic.py

@@ -279,8 +279,19 @@ def run_configuration(config_filename, config, config_paths, arguments):
                             encountered_error = error
                             error_repository = repository
 
+                # Re-raise any error, so that the Monitoring_hooks context manager wrapping this
+                # code can see the error and act accordingly. Do this here rather than as soon as
+                # the error is encountered so that an error with one repository doesn't prevent
+                # other repositories from running.
+                if encountered_error:
+                    raise encountered_error
+
     except (OSError, CalledProcessError, ValueError) as error:
-        yield from log_error_records('Error running configuration', error)
+        # No need to repeat logging of the error if it was already logged above.
+        if error_repository:
+            yield from log_error_records('Error running configuration')
+        else:
+            yield from log_error_records('Error running configuration', error)
 
         encountered_error = error
 

pyproject.toml

@@ -1,6 +1,6 @@
 [project]
 name = "borgmatic"
-version = "2.0.2"
+version = "2.0.3.dev0"
 authors = [
   { name="Dan Helfman", email="witten@torsion.org" },
 ]

tests/integration/commands/test_borgmatic.py

@@ -12,3 +12,59 @@ def test_borgmatic_version_matches_news_version():
     news_version = open('NEWS').readline()
 
     assert borgmatic_version == news_version
+
+
+def test_run_configuration_without_error_pings_monitoring_hooks_start_and_finish():
+    config = {'repositories': [{'path': 'foo'}]}
+    arguments = {'global': flexmock(monitoring_verbosity=1, dry_run=False), 'create': flexmock()}
+    flexmock(module.borg_version).should_receive('local_borg_version').and_return(flexmock())
+    flexmock(module).should_receive('run_actions').and_return([])
+    flexmock(module.dispatch).should_receive('call_hooks')
+    flexmock(module.dispatch).should_receive('call_hooks').with_args(
+        'ping_monitor',
+        config,
+        module.dispatch.Hook_type.MONITORING,
+        'test.yaml',
+        module.monitor.State.START,
+        object,
+        object,
+    ).once()
+    flexmock(module.dispatch).should_receive('call_hooks').with_args(
+        'ping_monitor',
+        config,
+        module.dispatch.Hook_type.MONITORING,
+        'test.yaml',
+        module.monitor.State.FINISH,
+        object,
+        object,
+    ).once()
+
+    list(module.run_configuration('test.yaml', config, ['/tmp/test.yaml'], arguments))
+
+
+def test_run_configuration_with_action_error_pings_monioring_hooks_start_and_fail():
+    config = {'repositories': [{'path': 'foo'}]}
+    arguments = {'global': flexmock(monitoring_verbosity=1, dry_run=False), 'create': flexmock()}
+    flexmock(module.borg_version).should_receive('local_borg_version').and_return(flexmock())
+    flexmock(module).should_receive('run_actions').and_raise(OSError)
+    flexmock(module.dispatch).should_receive('call_hooks')
+    flexmock(module.dispatch).should_receive('call_hooks').with_args(
+        'ping_monitor',
+        config,
+        module.dispatch.Hook_type.MONITORING,
+        'test.yaml',
+        module.monitor.State.START,
+        object,
+        object,
+    ).once()
+    flexmock(module.dispatch).should_receive('call_hooks').with_args(
+        'ping_monitor',
+        config,
+        module.dispatch.Hook_type.MONITORING,
+        'test.yaml',
+        module.monitor.State.FAIL,
+        object,
+        object,
+    ).once()
+
+    list(module.run_configuration('test.yaml', config, ['/tmp/test.yaml'], arguments))

tests/unit/commands/test_borgmatic.py

@@ -465,8 +465,10 @@ def test_run_configuration_logs_actions_error():
     flexmock(module).should_receive('Monitoring_hooks').and_return(flexmock())
     flexmock(module.command).should_receive('Before_after_hooks').and_return(flexmock())
     flexmock(module.borg_version).should_receive('local_borg_version').and_return(flexmock())
-    expected_results = [flexmock()]
-    flexmock(module).should_receive('log_error_records').and_return(expected_results)
+    expected_results = [flexmock(), flexmock()]
+    flexmock(module).should_receive('log_error_records').and_return(
+        expected_results[:1]
+    ).and_return(expected_results[1:])
     flexmock(module).should_receive('Log_prefix').and_return(flexmock())
     flexmock(module).should_receive('run_actions').and_raise(OSError)
     flexmock(module.command).should_receive('filter_hooks')
@@ -532,7 +534,7 @@ def test_run_configuration_logs_on_error_hook_error():
     expected_results = [flexmock(), flexmock()]
     flexmock(module).should_receive('log_error_records').and_return(
         expected_results[:1]
-    ).and_return(expected_results[1:])
+    ).and_return(expected_results[1:2]).and_return(expected_results[2:])
     flexmock(module).should_receive('Log_prefix').and_return(flexmock())
     flexmock(module).should_receive('run_actions').and_raise(OSError)
     config = {'repositories': [{'path': 'foo'}]}
@@ -601,8 +603,10 @@ def test_run_configuration_bails_for_on_error_hook_soft_failure():
     error = subprocess.CalledProcessError(borgmatic.hooks.command.SOFT_FAIL_EXIT_CODE, 'try again')
     flexmock(module.command).should_receive('filter_hooks')
     flexmock(module.command).should_receive('execute_hooks').and_raise(error)
-    expected_results = [flexmock()]
-    flexmock(module).should_receive('log_error_records').and_return(expected_results)
+    expected_results = [flexmock(), flexmock()]
+    flexmock(module).should_receive('log_error_records').and_return(
+        expected_results[:1]
+    ).and_return(expected_results[1:])
     flexmock(module).should_receive('Log_prefix').and_return(flexmock())
     flexmock(module).should_receive('run_actions').and_raise(OSError)
     config = {'repositories': [{'path': 'foo'}]}
@@ -654,11 +658,14 @@ def test_run_configuration_retries_hard_error():
         levelno=logging.WARNING,
         log_command_error_output=True,
     ).and_return([flexmock()])
-    error_logs = [flexmock()]
+    error_logs = [flexmock(), flexmock()]
     flexmock(module).should_receive('log_error_records').with_args(
         'Error running actions for repository',
         OSError,
-    ).and_return(error_logs)
+    ).and_return(error_logs[:1]).ordered()
+    flexmock(module).should_receive('log_error_records').with_args(
+        'Error running configuration',
+    ).and_return(error_logs[1:]).ordered()
     flexmock(module.command).should_receive('filter_hooks')
     flexmock(module.command).should_receive('execute_hooks')
     config = {'repositories': [{'path': 'foo'}], 'retries': 1}
@@ -680,13 +687,16 @@ def test_run_configuration_retries_repositories_in_order():
     flexmock(module.borg_version).should_receive('local_borg_version').and_return(flexmock())
     flexmock(module).should_receive('Log_prefix').and_return(flexmock())
     flexmock(module).should_receive('run_actions').and_raise(OSError).times(2)
-    expected_results = [flexmock(), flexmock()]
+    expected_results = [flexmock(), flexmock(), flexmock()]
     flexmock(module).should_receive('log_error_records').with_args(
         'Error running actions for repository', OSError
     ).and_return(expected_results[:1]).ordered()
     flexmock(module).should_receive('log_error_records').with_args(
         'Error running actions for repository', OSError
-    ).and_return(expected_results[1:]).ordered()
+    ).and_return(expected_results[1:2]).ordered()
+    flexmock(module).should_receive('log_error_records').with_args(
+        'Error running configuration',
+    ).and_return(expected_results[2:]).ordered()
     flexmock(module.command).should_receive('filter_hooks')
     flexmock(module.command).should_receive('execute_hooks')
     config = {'repositories': [{'path': 'foo'}, {'path': 'bar'}]}
@@ -728,6 +738,10 @@ def test_run_configuration_retries_round_robin():
     flexmock(module).should_receive('log_error_records').with_args(
         'Error running actions for repository', OSError
     ).and_return(bar_error_logs).ordered()
+    config_error_logs = [flexmock()]
+    flexmock(module).should_receive('log_error_records').with_args(
+        'Error running configuration',
+    ).and_return(config_error_logs).ordered()
     flexmock(module.command).should_receive('filter_hooks')
     flexmock(module.command).should_receive('execute_hooks')
     config = {
@@ -741,7 +755,7 @@ def test_run_configuration_retries_round_robin():
 
     results = list(module.run_configuration('test.yaml', config, ['/tmp/test.yaml'], arguments))
 
-    assert results == foo_error_logs + bar_error_logs
+    assert results == foo_error_logs + bar_error_logs + config_error_logs
 
 
 def test_run_configuration_with_one_retry():
@@ -766,10 +780,13 @@ def test_run_configuration_with_one_retry():
         levelno=logging.WARNING,
         log_command_error_output=True,
     ).and_return(flexmock()).ordered()
-    error_logs = [flexmock()]
+    error_logs = [flexmock(), flexmock()]
     flexmock(module).should_receive('log_error_records').with_args(
         'Error running actions for repository', OSError
-    ).and_return(error_logs).ordered()
+    ).and_return(error_logs[:1]).ordered()
+    flexmock(module).should_receive('log_error_records').with_args(
+        'Error running configuration',
+    ).and_return(error_logs[1:]).ordered()
     flexmock(module.command).should_receive('filter_hooks')
     flexmock(module.command).should_receive('execute_hooks')
     config = {
@@ -818,10 +835,13 @@ def test_run_configuration_with_retry_wait_does_backoff_after_each_retry():
     ).and_return([flexmock()]).ordered()
 
     flexmock(time).should_receive('sleep').with_args(30).and_return().ordered()
-    error_logs = [flexmock()]
+    error_logs = [flexmock(), flexmock()]
     flexmock(module).should_receive('log_error_records').with_args(
         'Error running actions for repository', OSError
-    ).and_return(error_logs).ordered()
+    ).and_return(error_logs[:1]).ordered()
+    flexmock(module).should_receive('log_error_records').with_args(
+        'Error running configuration',
+    ).and_return(error_logs[1:]).ordered()
     flexmock(module.command).should_receive('filter_hooks')
     flexmock(module.command).should_receive('execute_hooks')
     config = {
@@ -867,10 +887,13 @@ def test_run_configuration_with_multiple_repositories_retries_with_timeout():
 
     # Sleep before retrying bar (and failing)
     flexmock(time).should_receive('sleep').with_args(10).and_return().ordered()
-    error_logs = [flexmock()]
+    error_logs = [flexmock(), flexmock()]
     flexmock(module).should_receive('log_error_records').with_args(
         'Error running actions for repository', OSError
-    ).and_return(error_logs).ordered()
+    ).and_return(error_logs[:1]).ordered()
+    flexmock(module).should_receive('log_error_records').with_args(
+        'Error running configuration',
+    ).and_return(error_logs[1:]).ordered()
     flexmock(module.command).should_receive('filter_hooks')
     flexmock(module.command).should_receive('execute_hooks')
     config = {