Added debug message that logs borg version for every config

borgmatic/commands/borgmatic.py

@@ -75,6 +75,9 @@ def run_configuration(config_filename, config, arguments):
 
     try:
         local_borg_version = borg_version.local_borg_version(config, local_path)
+        yield from log_error_records(
+            f'{config_filename}: Local Borg version: {local_borg_version}', levelno=logging.DEBUG
+        )
     except (OSError, CalledProcessError, ValueError) as error:
         yield from log_error_records(f'{config_filename}: Error getting local Borg version', error)
         return

tests/unit/commands/test_borgmatic.py

@@ -10,10 +10,11 @@ from borgmatic.commands import borgmatic as module
 
 def test_run_configuration_runs_actions_for_each_repository():
     flexmock(module).should_receive('verbosity_to_log_level').and_return(logging.INFO)
+    expected_results = [flexmock(), flexmock(), flexmock()]
+    flexmock(module).should_receive('log_error_records').and_return(expected_results[0])
     flexmock(module.borg_version).should_receive('local_borg_version').and_return(flexmock())
-    expected_results = [flexmock(), flexmock()]
-    flexmock(module).should_receive('run_actions').and_return(expected_results[:1]).and_return(
-        expected_results[1:]
+    flexmock(module).should_receive('run_actions').and_return(expected_results[1:2]).and_return(
+        expected_results[2:]
     )
     config = {'repositories': [{'path': 'foo'}, {'path': 'bar'}]}
     arguments = {'global': flexmock(monitoring_verbosity=1)}
@@ -52,7 +53,8 @@ def test_run_configuration_logs_monitor_start_error():
         None
     ).and_return(None).and_return(None)
     expected_results = [flexmock()]
-    flexmock(module).should_receive('log_error_records').and_return(expected_results)
+    expected_results.append(expected_results[0])
+    flexmock(module).should_receive('log_error_records').and_return(expected_results[0])
     flexmock(module).should_receive('run_actions').never()
     config = {'repositories': ['foo']}
     arguments = {'global': flexmock(monitoring_verbosity=1, dry_run=False), 'create': flexmock()}
@@ -67,14 +69,15 @@ def test_run_configuration_bails_for_monitor_start_soft_failure():
     flexmock(module.borg_version).should_receive('local_borg_version').and_return(flexmock())
     error = subprocess.CalledProcessError(borgmatic.hooks.command.SOFT_FAIL_EXIT_CODE, 'try again')
     flexmock(module.dispatch).should_receive('call_hooks').and_raise(error)
-    flexmock(module).should_receive('log_error_records').never()
+    expected_results = [flexmock()]
+    flexmock(module).should_receive('log_error_records').once().and_return(expected_results[0])
     flexmock(module).should_receive('run_actions').never()
     config = {'repositories': ['foo']}
     arguments = {'global': flexmock(monitoring_verbosity=1, dry_run=False), 'create': flexmock()}
 
     results = list(module.run_configuration('test.yaml', config, arguments))
 
-    assert results == []
+    assert results == expected_results
 
 
 def test_run_configuration_logs_actions_error():
@@ -83,7 +86,8 @@ def test_run_configuration_logs_actions_error():
     flexmock(module.command).should_receive('execute_hook')
     flexmock(module.dispatch).should_receive('call_hooks')
     expected_results = [flexmock()]
-    flexmock(module).should_receive('log_error_records').and_return(expected_results)
+    expected_results.append(expected_results[0])
+    flexmock(module).should_receive('log_error_records').and_return(expected_results[0])
     flexmock(module).should_receive('run_actions').and_raise(OSError)
     config = {'repositories': [{'path': 'foo'}]}
     arguments = {'global': flexmock(monitoring_verbosity=1, dry_run=False)}
@@ -99,14 +103,15 @@ def test_run_configuration_bails_for_actions_soft_failure():
     flexmock(module.dispatch).should_receive('call_hooks')
     error = subprocess.CalledProcessError(borgmatic.hooks.command.SOFT_FAIL_EXIT_CODE, 'try again')
     flexmock(module).should_receive('run_actions').and_raise(error)
-    flexmock(module).should_receive('log_error_records').never()
+    expected_results = [flexmock()]
+    flexmock(module).should_receive('log_error_records').once().and_return(expected_results)
     flexmock(module.command).should_receive('considered_soft_failure').and_return(True)
     config = {'repositories': [{'path': 'foo'}]}
     arguments = {'global': flexmock(monitoring_verbosity=1, dry_run=False), 'create': flexmock()}
 
     results = list(module.run_configuration('test.yaml', config, arguments))
 
-    assert results == []
+    assert results == expected_results
 
 
 def test_run_configuration_logs_monitor_log_error():
@@ -116,7 +121,8 @@ def test_run_configuration_logs_monitor_log_error():
         None
     ).and_raise(OSError)
     expected_results = [flexmock()]
-    flexmock(module).should_receive('log_error_records').and_return(expected_results)
+    expected_results.append(expected_results[0])
+    flexmock(module).should_receive('log_error_records').and_return(expected_results[0])
     flexmock(module).should_receive('run_actions').and_return([])
     config = {'repositories': [{'path': 'foo'}]}
     arguments = {'global': flexmock(monitoring_verbosity=1, dry_run=False), 'create': flexmock()}
@@ -133,7 +139,8 @@ def test_run_configuration_bails_for_monitor_log_soft_failure():
     flexmock(module.dispatch).should_receive('call_hooks').and_return(None).and_return(
         None
     ).and_raise(error)
-    flexmock(module).should_receive('log_error_records').never()
+    expected_results = [flexmock()]
+    flexmock(module).should_receive('log_error_records').once().and_return(expected_results)
     flexmock(module).should_receive('run_actions').and_return([])
     flexmock(module.command).should_receive('considered_soft_failure').and_return(True)
     config = {'repositories': [{'path': 'foo'}]}
@@ -141,7 +148,7 @@ def test_run_configuration_bails_for_monitor_log_soft_failure():
 
     results = list(module.run_configuration('test.yaml', config, arguments))
 
-    assert results == []
+    assert results == expected_results
 
 
 def test_run_configuration_logs_monitor_finish_error():
@@ -151,7 +158,8 @@ def test_run_configuration_logs_monitor_finish_error():
         None
     ).and_return(None).and_raise(OSError)
     expected_results = [flexmock()]
-    flexmock(module).should_receive('log_error_records').and_return(expected_results)
+    expected_results.append(expected_results[0])
+    flexmock(module).should_receive('log_error_records').and_return(expected_results[0])
     flexmock(module).should_receive('run_actions').and_return([])
     config = {'repositories': [{'path': 'foo'}]}
     arguments = {'global': flexmock(monitoring_verbosity=1, dry_run=False), 'create': flexmock()}
@@ -168,7 +176,8 @@ def test_run_configuration_bails_for_monitor_finish_soft_failure():
     flexmock(module.dispatch).should_receive('call_hooks').and_return(None).and_return(
         None
     ).and_raise(None).and_raise(error)
-    flexmock(module).should_receive('log_error_records').never()
+    expected_results = [flexmock()]
+    flexmock(module).should_receive('log_error_records').once().and_return(expected_results)
     flexmock(module).should_receive('run_actions').and_return([])
     flexmock(module.command).should_receive('considered_soft_failure').and_return(True)
     config = {'repositories': [{'path': 'foo'}]}
@@ -176,7 +185,7 @@ def test_run_configuration_bails_for_monitor_finish_soft_failure():
 
     results = list(module.run_configuration('test.yaml', config, arguments))
 
-    assert results == []
+    assert results == expected_results
 
 
 def test_run_configuration_does_not_call_monitoring_hooks_if_monitoring_hooks_are_disabled():
@@ -186,20 +195,22 @@ def test_run_configuration_does_not_call_monitoring_hooks_if_monitoring_hooks_ar
     flexmock(module.dispatch).should_receive('call_hooks').never()
     flexmock(module).should_receive('run_actions').and_return([])
 
+    expected_results = [flexmock()]
+    flexmock(module).should_receive('log_error_records').once().and_return(expected_results)
     config = {'repositories': [{'path': 'foo'}]}
     arguments = {'global': flexmock(monitoring_verbosity=-2, dry_run=False), 'create': flexmock()}
     results = list(module.run_configuration('test.yaml', config, arguments))
-    assert results == []
+    assert results == expected_results
 
 
 def test_run_configuration_logs_on_error_hook_error():
     flexmock(module).should_receive('verbosity_to_log_level').and_return(logging.INFO)
     flexmock(module.borg_version).should_receive('local_borg_version').and_return(flexmock())
     flexmock(module.command).should_receive('execute_hook').and_raise(OSError)
-    expected_results = [flexmock(), flexmock()]
-    flexmock(module).should_receive('log_error_records').and_return(
-        expected_results[:1]
-    ).and_return(expected_results[1:])
+    expected_results = [flexmock(), flexmock(), flexmock()]
+    flexmock(module).should_receive('log_error_records').and_return(expected_results[0]).and_return(
+        expected_results[1]
+    ).and_return(expected_results[2])
     flexmock(module).should_receive('run_actions').and_raise(OSError)
     config = {'repositories': [{'path': 'foo'}]}
     arguments = {'global': flexmock(monitoring_verbosity=1, dry_run=False), 'create': flexmock()}
@@ -214,8 +225,10 @@ def test_run_configuration_bails_for_on_error_hook_soft_failure():
     flexmock(module.borg_version).should_receive('local_borg_version').and_return(flexmock())
     error = subprocess.CalledProcessError(borgmatic.hooks.command.SOFT_FAIL_EXIT_CODE, 'try again')
     flexmock(module.command).should_receive('execute_hook').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[0]).and_return(
+        expected_results[1]
+    )
     flexmock(module).should_receive('run_actions').and_raise(OSError)
     config = {'repositories': [{'path': 'foo'}]}
     arguments = {'global': flexmock(monitoring_verbosity=1, dry_run=False), 'create': flexmock()}
@@ -231,11 +244,12 @@ def test_run_configuration_retries_soft_error():
     flexmock(module.borg_version).should_receive('local_borg_version').and_return(flexmock())
     flexmock(module.command).should_receive('execute_hook')
     flexmock(module).should_receive('run_actions').and_raise(OSError).and_return([])
-    flexmock(module).should_receive('log_error_records').and_return([flexmock()]).once()
+    expected_results = [flexmock()]
+    flexmock(module).should_receive('log_error_records').and_return(expected_results).times(2)
     config = {'repositories': [{'path': 'foo'}], 'retries': 1}
     arguments = {'global': flexmock(monitoring_verbosity=1, dry_run=False), 'create': flexmock()}
     results = list(module.run_configuration('test.yaml', config, arguments))
-    assert results == []
+    assert results == expected_results
 
 
 def test_run_configuration_retries_hard_error():
@@ -243,18 +257,19 @@ def test_run_configuration_retries_hard_error():
     flexmock(module).should_receive('verbosity_to_log_level').and_return(logging.INFO)
     flexmock(module.borg_version).should_receive('local_borg_version').and_return(flexmock())
     flexmock(module.command).should_receive('execute_hook')
+    error_logs = [flexmock(), flexmock()]
     flexmock(module).should_receive('run_actions').and_raise(OSError).times(2)
+    flexmock(module).should_receive('log_error_records').and_return(error_logs[0])
     flexmock(module).should_receive('log_error_records').with_args(
         'foo: Error running actions for repository',
         OSError,
         levelno=logging.WARNING,
         log_command_error_output=True,
     ).and_return([flexmock()])
-    error_logs = [flexmock()]
     flexmock(module).should_receive('log_error_records').with_args(
         'foo: Error running actions for repository',
         OSError,
-    ).and_return(error_logs)
+    ).and_return(error_logs[1])
     config = {'repositories': [{'path': 'foo'}], 'retries': 1}
     arguments = {'global': flexmock(monitoring_verbosity=1, dry_run=False), 'create': flexmock()}
     results = list(module.run_configuration('test.yaml', config, arguments))
@@ -266,13 +281,14 @@ def test_run_configuration_repos_ordered():
     flexmock(module.borg_version).should_receive('local_borg_version').and_return(flexmock())
     flexmock(module.command).should_receive('execute_hook')
     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').and_return(expected_results[0])
     flexmock(module).should_receive('log_error_records').with_args(
         'foo: Error running actions for repository', OSError
-    ).and_return(expected_results[:1]).ordered()
+    ).and_return(expected_results[1]).ordered()
     flexmock(module).should_receive('log_error_records').with_args(
         'bar: Error running actions for repository', OSError
-    ).and_return(expected_results[1:]).ordered()
+    ).and_return(expected_results[2]).ordered()
     config = {'repositories': [{'path': 'foo'}, {'path': 'bar'}]}
     arguments = {'global': flexmock(monitoring_verbosity=1, dry_run=False), 'create': flexmock()}
     results = list(module.run_configuration('test.yaml', config, arguments))
@@ -284,6 +300,8 @@ def test_run_configuration_retries_round_robin():
     flexmock(module.borg_version).should_receive('local_borg_version').and_return(flexmock())
     flexmock(module.command).should_receive('execute_hook')
     flexmock(module).should_receive('run_actions').and_raise(OSError).times(4)
+    version_log = [flexmock()]
+    flexmock(module).should_receive('log_error_records').and_return(version_log)
     flexmock(module).should_receive('log_error_records').with_args(
         'foo: Error running actions for repository',
         OSError,
@@ -310,7 +328,7 @@ def test_run_configuration_retries_round_robin():
     }
     arguments = {'global': flexmock(monitoring_verbosity=1, dry_run=False), 'create': flexmock()}
     results = list(module.run_configuration('test.yaml', config, arguments))
-    assert results == foo_error_logs + bar_error_logs
+    assert results == version_log + foo_error_logs + bar_error_logs
 
 
 def test_run_configuration_retries_one_passes():
@@ -320,6 +338,8 @@ def test_run_configuration_retries_one_passes():
     flexmock(module).should_receive('run_actions').and_raise(OSError).and_raise(OSError).and_return(
         []
     ).and_raise(OSError).times(4)
+    error_logs = [flexmock(), flexmock()]
+    flexmock(module).should_receive('log_error_records').and_return(error_logs[0])
     flexmock(module).should_receive('log_error_records').with_args(
         'foo: Error running actions for repository',
         OSError,
@@ -332,10 +352,9 @@ def test_run_configuration_retries_one_passes():
         levelno=logging.WARNING,
         log_command_error_output=True,
     ).and_return(flexmock()).ordered()
-    error_logs = [flexmock()]
     flexmock(module).should_receive('log_error_records').with_args(
         'bar: Error running actions for repository', OSError
-    ).and_return(error_logs).ordered()
+    ).and_return(error_logs[1]).ordered()
     config = {
         'repositories': [{'path': 'foo'}, {'path': 'bar'}],
         'retries': 1,
@@ -350,6 +369,8 @@ def test_run_configuration_retry_wait():
     flexmock(module.borg_version).should_receive('local_borg_version').and_return(flexmock())
     flexmock(module.command).should_receive('execute_hook')
     flexmock(module).should_receive('run_actions').and_raise(OSError).times(4)
+    error_logs = [flexmock(), flexmock()]
+    flexmock(module).should_receive('log_error_records').and_return(error_logs[0])
     flexmock(module).should_receive('log_error_records').with_args(
         'foo: Error running actions for repository',
         OSError,
@@ -374,10 +395,9 @@ def test_run_configuration_retry_wait():
     ).and_return([flexmock()]).ordered()
 
     flexmock(time).should_receive('sleep').with_args(30).and_return().ordered()
-    error_logs = [flexmock()]
     flexmock(module).should_receive('log_error_records').with_args(
         'foo: Error running actions for repository', OSError
-    ).and_return(error_logs).ordered()
+    ).and_return(error_logs[1]).ordered()
     config = {
         'repositories': [{'path': 'foo'}],
         'retries': 3,
@@ -395,6 +415,8 @@ def test_run_configuration_retries_timeout_multiple_repos():
     flexmock(module).should_receive('run_actions').and_raise(OSError).and_raise(OSError).and_return(
         []
     ).and_raise(OSError).times(4)
+    error_logs = [flexmock(), flexmock()]
+    flexmock(module).should_receive('log_error_records').and_return(error_logs[0])
     flexmock(module).should_receive('log_error_records').with_args(
         'foo: Error running actions for repository',
         OSError,
@@ -413,10 +435,9 @@ def test_run_configuration_retries_timeout_multiple_repos():
 
     # Sleep before retrying bar (and failing)
     flexmock(time).should_receive('sleep').with_args(10).and_return().ordered()
-    error_logs = [flexmock()]
     flexmock(module).should_receive('log_error_records').with_args(
         'bar: Error running actions for repository', OSError
-    ).and_return(error_logs).ordered()
+    ).and_return(error_logs[1]).ordered()
     config = {
         'repositories': [{'path': 'foo'}, {'path': 'bar'}],
         'retries': 1,