When backups to one of several repositories fails, keep backing up to the other repositories (#144).

NEWS

@@ -1,3 +1,7 @@
+1.3.22
+ * #144: When backups to one of several repositories fails, keep backing up to the other
+   repositories and report errors afterwards.
+
 1.3.21
  * #192: User-defined hooks for global setup or cleanup that run before/after all actions. See the
    documentation for more information:

borgmatic/commands/borgmatic.py

@@ -28,13 +28,16 @@ logger = logging.getLogger(__name__)
 LEGACY_CONFIG_PATH = '/etc/borgmatic/config'
 
 
-def run_configuration(config_filename, config, arguments):  # pragma: no cover
+def run_configuration(config_filename, config, arguments):
     '''
     Given a config filename, the corresponding parsed config dict, and command-line arguments as a
     dict from subparser name to a namespace of parsed arguments, execute its defined pruning,
     backups, consistency checks, and/or other actions.
 
-    Yield JSON output strings from executing any actions that produce JSON.
+    Yield a combination of:
+
+      * JSON output strings from successfully executing any actions that produce JSON
+      * logging.LogRecord instances containing errors from any actions or backup hooks that fail
     '''
     (location, storage, retention, consistency, hooks) = (
         config.get(section_name, {})
@@ -42,12 +45,13 @@ def run_configuration(config_filename, config, arguments):  # pragma: no cover
     )
     global_arguments = arguments['global']
 
-    try:
-        local_path = location.get('local_path', 'borg')
-        remote_path = location.get('remote_path')
-        borg_environment.initialize(storage)
+    local_path = location.get('local_path', 'borg')
+    remote_path = location.get('remote_path')
+    borg_environment.initialize(storage)
+    encountered_error = False
 
-        if 'create' in arguments:
+    if 'create' in arguments:
+        try:
             hook.execute_hook(
                 hooks.get('before_backup'),
                 hooks.get('umask'),
@@ -55,20 +59,33 @@ def run_configuration(config_filename, config, arguments):  # pragma: no cover
                 'pre-backup',
                 global_arguments.dry_run,
             )
+        except (OSError, CalledProcessError) as error:
+            encountered_error = True
+            yield from make_error_log_records(
+                '{}: Error running pre-backup hook'.format(config_filename), error
+            )
 
+    if not encountered_error:
         for repository_path in location['repositories']:
-            yield from run_actions(
-                arguments=arguments,
-                location=location,
-                storage=storage,
-                retention=retention,
-                consistency=consistency,
-                local_path=local_path,
-                remote_path=remote_path,
-                repository_path=repository_path,
-            )
+            try:
+                yield from run_actions(
+                    arguments=arguments,
+                    location=location,
+                    storage=storage,
+                    retention=retention,
+                    consistency=consistency,
+                    local_path=local_path,
+                    remote_path=remote_path,
+                    repository_path=repository_path,
+                )
+            except (OSError, CalledProcessError) as error:
+                encountered_error = True
+                yield from make_error_log_records(
+                    '{}: Error running actions for repository'.format(repository_path), error
+                )
 
-        if 'create' in arguments:
+    if 'create' in arguments and not encountered_error:
+        try:
             hook.execute_hook(
                 hooks.get('after_backup'),
                 hooks.get('umask'),
@@ -76,15 +93,25 @@ def run_configuration(config_filename, config, arguments):  # pragma: no cover
                 'post-backup',
                 global_arguments.dry_run,
             )
-    except (OSError, CalledProcessError):
-        hook.execute_hook(
-            hooks.get('on_error'),
-            hooks.get('umask'),
-            config_filename,
-            'on-error',
-            global_arguments.dry_run,
-        )
-        raise
+        except (OSError, CalledProcessError) as error:
+            encountered_error = True
+            yield from make_error_log_records(
+                '{}: Error running post-backup hook'.format(config_filename), error
+            )
+
+    if encountered_error:
+        try:
+            hook.execute_hook(
+                hooks.get('on_error'),
+                hooks.get('umask'),
+                config_filename,
+                'on-error',
+                global_arguments.dry_run,
+            )
+        except (OSError, CalledProcessError) as error:
+            yield from make_error_log_records(
+                '{}: Error running on-error hook'.format(config_filename), error
+            )
 
 
 def run_actions(
@@ -231,11 +258,17 @@ def load_configurations(config_filenames):
     return (configs, logs)
 
 
-def make_error_log_records(error, message):
+def make_error_log_records(message, error=None):
     '''
-    Given an exception object and error message text, yield a series of logging.LogRecord instances
-    with error summary information.
+    Given error message text and an optional exception object, yield a series of logging.LogRecord
+    instances with error summary information.
     '''
+    if not error:
+        yield logging.makeLogRecord(
+            dict(levelno=logging.CRITICAL, levelname='CRITICAL', msg=message)
+        )
+        return
+
     try:
         raise error
     except CalledProcessError as error:
@@ -279,25 +312,17 @@ def collect_configuration_run_summary_logs(configs, arguments):
         try:
             validate.guard_configuration_contains_repository(repository, configs)
         except ValueError as error:
-            yield logging.makeLogRecord(
-                dict(levelno=logging.CRITICAL, levelname='CRITICAL', msg=error)
-            )
+            yield from make_error_log_records(str(error))
             return
 
     if not configs:
-        yield logging.makeLogRecord(
-            dict(
-                levelno=logging.CRITICAL,
-                levelname='CRITICAL',
-                msg='{}: No configuration files found'.format(
-                    ' '.join(arguments['global'].config_paths)
-                ),
-            )
+        yield from make_error_log_records(
+            '{}: No configuration files found'.format(' '.join(arguments['global'].config_paths))
         )
         return
 
-    try:
-        if 'create' in arguments:
+    if 'create' in arguments:
+        try:
             for config_filename, config in configs.items():
                 hooks = config.get('hooks', {})
                 hook.execute_hook(
@@ -307,15 +332,22 @@ def collect_configuration_run_summary_logs(configs, arguments):
                     'pre-everything',
                     arguments['global'].dry_run,
                 )
-    except (CalledProcessError, ValueError, OSError) as error:
-        yield from make_error_log_records(error, 'Error running pre-everything hook')
-        return
+        except (CalledProcessError, ValueError, OSError) as error:
+            yield from make_error_log_records('Error running pre-everything hook', error)
+            return
 
     # Execute the actions corresponding to each configuration file.
     json_results = []
     for config_filename, config in configs.items():
-        try:
-            json_results.extend(list(run_configuration(config_filename, config, arguments)))
+        results = list(run_configuration(config_filename, config, arguments))
+        error_logs = tuple(result for result in results if isinstance(result, logging.LogRecord))
+
+        if error_logs:
+            yield from make_error_log_records(
+                '{}: Error running configuration file'.format(config_filename)
+            )
+            yield from error_logs
+        else:
             yield logging.makeLogRecord(
                 dict(
                     levelno=logging.INFO,
@@ -323,16 +355,14 @@ def collect_configuration_run_summary_logs(configs, arguments):
                     msg='{}: Successfully ran configuration file'.format(config_filename),
                 )
             )
-        except (CalledProcessError, ValueError, OSError) as error:
-            yield from make_error_log_records(
-                error, '{}: Error running configuration file'.format(config_filename)
-            )
+            if results:
+                json_results.extend(results)
 
     if json_results:
         sys.stdout.write(json.dumps(json_results))
 
-    try:
-        if 'create' in arguments:
+    if 'create' in arguments:
+        try:
             for config_filename, config in configs.items():
                 hooks = config.get('hooks', {})
                 hook.execute_hook(
@@ -342,8 +372,8 @@ def collect_configuration_run_summary_logs(configs, arguments):
                     'post-everything',
                     arguments['global'].dry_run,
                 )
-    except (CalledProcessError, ValueError, OSError) as error:
-        yield from make_error_log_records(error, 'Error running post-everything hook')
+        except (CalledProcessError, ValueError, OSError) as error:
+            yield from make_error_log_records('Error running post-everything hook', error)
 
 
 def exit_with_help_link():  # pragma: no cover

setup.py

@@ -1,6 +1,6 @@
 from setuptools import find_packages, setup
 
-VERSION = '1.3.21'
+VERSION = '1.3.22'
 
 
 setup(

tests/unit/commands/test_borgmatic.py

@@ -1,3 +1,4 @@
+import logging
 import subprocess
 
 from flexmock import flexmock
@@ -5,6 +6,90 @@ from flexmock import flexmock
 from borgmatic.commands import borgmatic as module
 
 
+def test_run_configuration_runs_actions_for_each_repository():
+    flexmock(module.borg_environment).should_receive('initialize')
+    expected_results = [flexmock(), flexmock()]
+    flexmock(module).should_receive('run_actions').and_return(expected_results[:1]).and_return(
+        expected_results[1:]
+    )
+    config = {'location': {'repositories': ['foo', 'bar']}}
+    arguments = {'global': flexmock()}
+
+    results = list(module.run_configuration('test.yaml', config, arguments))
+
+    assert results == expected_results
+
+
+def test_run_configuration_executes_hooks_for_create_action():
+    flexmock(module.borg_environment).should_receive('initialize')
+    flexmock(module.hook).should_receive('execute_hook').twice()
+    flexmock(module).should_receive('run_actions').and_return([])
+    config = {'location': {'repositories': ['foo']}}
+    arguments = {'global': flexmock(dry_run=False), 'create': flexmock()}
+
+    list(module.run_configuration('test.yaml', config, arguments))
+
+
+def test_run_configuration_logs_actions_error():
+    flexmock(module.borg_environment).should_receive('initialize')
+    flexmock(module.hook).should_receive('execute_hook')
+    expected_results = [flexmock()]
+    flexmock(module).should_receive('make_error_log_records').and_return(expected_results)
+    flexmock(module).should_receive('run_actions').and_raise(OSError)
+    config = {'location': {'repositories': ['foo']}}
+    arguments = {'global': flexmock(dry_run=False)}
+
+    results = list(module.run_configuration('test.yaml', config, arguments))
+
+    assert results == expected_results
+
+
+def test_run_configuration_logs_pre_hook_error():
+    flexmock(module.borg_environment).should_receive('initialize')
+    flexmock(module.hook).should_receive('execute_hook').and_raise(OSError).and_return(None)
+    expected_results = [flexmock()]
+    flexmock(module).should_receive('make_error_log_records').and_return(expected_results)
+    flexmock(module).should_receive('run_actions').never()
+    config = {'location': {'repositories': ['foo']}}
+    arguments = {'global': flexmock(dry_run=False), 'create': flexmock()}
+
+    results = list(module.run_configuration('test.yaml', config, arguments))
+
+    assert results == expected_results
+
+
+def test_run_configuration_logs_post_hook_error():
+    flexmock(module.borg_environment).should_receive('initialize')
+    flexmock(module.hook).should_receive('execute_hook').and_return(None).and_raise(
+        OSError
+    ).and_return(None)
+    expected_results = [flexmock()]
+    flexmock(module).should_receive('make_error_log_records').and_return(expected_results)
+    flexmock(module).should_receive('run_actions').and_return([])
+    config = {'location': {'repositories': ['foo']}}
+    arguments = {'global': flexmock(dry_run=False), 'create': flexmock()}
+
+    results = list(module.run_configuration('test.yaml', config, arguments))
+
+    assert results == expected_results
+
+
+def test_run_configuration_logs_on_error_hook_error():
+    flexmock(module.borg_environment).should_receive('initialize')
+    flexmock(module.hook).should_receive('execute_hook').and_raise(OSError)
+    expected_results = [flexmock(), flexmock()]
+    flexmock(module).should_receive('make_error_log_records').and_return(
+        expected_results[:1]
+    ).and_return(expected_results[1:])
+    flexmock(module).should_receive('run_actions').and_raise(OSError)
+    config = {'location': {'repositories': ['foo']}}
+    arguments = {'global': flexmock(dry_run=False)}
+
+    results = list(module.run_configuration('test.yaml', config, arguments))
+
+    assert results == expected_results
+
+
 def test_load_configurations_collects_parsed_configurations():
     configuration = flexmock()
     other_configuration = flexmock()
@@ -24,34 +109,40 @@ def test_load_configurations_logs_critical_for_parse_error():
     configs, logs = tuple(module.load_configurations(('test.yaml',)))
 
     assert configs == {}
-    assert {log.levelno for log in logs} == {module.logging.CRITICAL}
+    assert {log.levelno for log in logs} == {logging.CRITICAL}
+
+
+def test_make_error_log_records_generates_output_logs_for_message_only():
+    logs = tuple(module.make_error_log_records('Error'))
+
+    assert {log.levelno for log in logs} == {logging.CRITICAL}
 
 
 def test_make_error_log_records_generates_output_logs_for_called_process_error():
     logs = tuple(
         module.make_error_log_records(
-            subprocess.CalledProcessError(1, 'ls', 'error output'), 'Error'
+            'Error', subprocess.CalledProcessError(1, 'ls', 'error output')
         )
     )
 
-    assert {log.levelno for log in logs} == {module.logging.CRITICAL}
+    assert {log.levelno for log in logs} == {logging.CRITICAL}
     assert any(log for log in logs if 'error output' in str(log))
 
 
 def test_make_error_log_records_generates_logs_for_value_error():
-    logs = tuple(module.make_error_log_records(ValueError(), 'Error'))
+    logs = tuple(module.make_error_log_records('Error', ValueError()))
 
-    assert {log.levelno for log in logs} == {module.logging.CRITICAL}
+    assert {log.levelno for log in logs} == {logging.CRITICAL}
 
 
 def test_make_error_log_records_generates_logs_for_os_error():
-    logs = tuple(module.make_error_log_records(OSError(), 'Error'))
+    logs = tuple(module.make_error_log_records('Error', OSError()))
 
-    assert {log.levelno for log in logs} == {module.logging.CRITICAL}
+    assert {log.levelno for log in logs} == {logging.CRITICAL}
 
 
 def test_make_error_log_records_generates_nothing_for_other_error():
-    logs = tuple(module.make_error_log_records(KeyError(), 'Error'))
+    logs = tuple(module.make_error_log_records('Error', KeyError()))
 
     assert logs == ()
 
@@ -65,7 +156,7 @@ def test_collect_configuration_run_summary_logs_info_for_success():
         module.collect_configuration_run_summary_logs({'test.yaml': {}}, arguments=arguments)
     )
 
-    assert {log.levelno for log in logs} == {module.logging.INFO}
+    assert {log.levelno for log in logs} == {logging.INFO}
 
 
 def test_collect_configuration_run_summary_executes_hooks_for_create():
@@ -76,7 +167,7 @@ def test_collect_configuration_run_summary_executes_hooks_for_create():
         module.collect_configuration_run_summary_logs({'test.yaml': {}}, arguments=arguments)
     )
 
-    assert {log.levelno for log in logs} == {module.logging.INFO}
+    assert {log.levelno for log in logs} == {logging.INFO}
 
 
 def test_collect_configuration_run_summary_logs_info_for_success_with_extract():
@@ -88,56 +179,74 @@ def test_collect_configuration_run_summary_logs_info_for_success_with_extract():
         module.collect_configuration_run_summary_logs({'test.yaml': {}}, arguments=arguments)
     )
 
-    assert {log.levelno for log in logs} == {module.logging.INFO}
+    assert {log.levelno for log in logs} == {logging.INFO}
 
 
-def test_collect_configuration_run_summary_logs_critical_for_extract_with_repository_error():
+def test_collect_configuration_run_summary_logs_extract_with_repository_error():
     flexmock(module.validate).should_receive('guard_configuration_contains_repository').and_raise(
         ValueError
     )
+    expected_logs = (flexmock(),)
+    flexmock(module).should_receive('make_error_log_records').and_return(expected_logs)
     arguments = {'extract': flexmock(repository='repo')}
 
     logs = tuple(
         module.collect_configuration_run_summary_logs({'test.yaml': {}}, arguments=arguments)
     )
 
-    assert {log.levelno for log in logs} == {module.logging.CRITICAL}
+    assert logs == expected_logs
+
+
+def test_collect_configuration_run_summary_logs_missing_configs_error():
+    arguments = {'global': flexmock(config_paths=[])}
+    expected_logs = (flexmock(),)
+    flexmock(module).should_receive('make_error_log_records').and_return(expected_logs)
+
+    logs = tuple(module.collect_configuration_run_summary_logs({}, arguments=arguments))
 
+    assert logs == expected_logs
 
-def test_collect_configuration_run_summary_logs_critical_for_pre_hook_error():
+
+def test_collect_configuration_run_summary_logs_pre_hook_error():
     flexmock(module.hook).should_receive('execute_hook').and_raise(ValueError)
+    expected_logs = (flexmock(),)
+    flexmock(module).should_receive('make_error_log_records').and_return(expected_logs)
     arguments = {'create': flexmock(), 'global': flexmock(dry_run=False)}
 
     logs = tuple(
         module.collect_configuration_run_summary_logs({'test.yaml': {}}, arguments=arguments)
     )
 
-    assert {log.levelno for log in logs} == {module.logging.CRITICAL}
+    assert logs == expected_logs
 
 
-def test_collect_configuration_run_summary_logs_critical_for_post_hook_error():
+def test_collect_configuration_run_summary_logs_post_hook_error():
     flexmock(module.hook).should_receive('execute_hook').and_return(None).and_raise(ValueError)
     flexmock(module).should_receive('run_configuration').and_return([])
+    expected_logs = (flexmock(),)
+    flexmock(module).should_receive('make_error_log_records').and_return(expected_logs)
     arguments = {'create': flexmock(), 'global': flexmock(dry_run=False)}
 
     logs = tuple(
         module.collect_configuration_run_summary_logs({'test.yaml': {}}, arguments=arguments)
     )
 
-    assert {log.levelno for log in logs} == {module.logging.INFO, module.logging.CRITICAL}
+    assert expected_logs[0] in logs
 
 
-def test_collect_configuration_run_summary_logs_critical_for_list_with_archive_and_repository_error():
+def test_collect_configuration_run_summary_logs_for_list_with_archive_and_repository_error():
     flexmock(module.validate).should_receive('guard_configuration_contains_repository').and_raise(
         ValueError
     )
+    expected_logs = (flexmock(),)
+    flexmock(module).should_receive('make_error_log_records').and_return(expected_logs)
     arguments = {'list': flexmock(repository='repo', archive='test')}
 
     logs = tuple(
         module.collect_configuration_run_summary_logs({'test.yaml': {}}, arguments=arguments)
     )
 
-    assert {log.levelno for log in logs} == {module.logging.CRITICAL}
+    assert logs == expected_logs
 
 
 def test_collect_configuration_run_summary_logs_info_for_success_with_list():
@@ -148,25 +257,13 @@ def test_collect_configuration_run_summary_logs_info_for_success_with_list():
         module.collect_configuration_run_summary_logs({'test.yaml': {}}, arguments=arguments)
     )
 
-    assert {log.levelno for log in logs} == {module.logging.INFO}
+    assert {log.levelno for log in logs} == {logging.INFO}
 
 
-def test_collect_configuration_run_summary_logs_critical_for_run_value_error():
+def test_collect_configuration_run_summary_logs_run_configuration_error():
     flexmock(module.validate).should_receive('guard_configuration_contains_repository')
-    flexmock(module).should_receive('run_configuration').and_raise(ValueError)
-    arguments = {}
-
-    logs = tuple(
-        module.collect_configuration_run_summary_logs({'test.yaml': {}}, arguments=arguments)
-    )
-
-    assert {log.levelno for log in logs} == {module.logging.CRITICAL}
-
-
-def test_collect_configuration_run_summary_logs_critical_including_output_for_run_process_error():
-    flexmock(module.validate).should_receive('guard_configuration_contains_repository')
-    flexmock(module).should_receive('run_configuration').and_raise(
-        subprocess.CalledProcessError(1, 'command', 'error output')
+    flexmock(module).should_receive('run_configuration').and_return(
+        [logging.makeLogRecord(dict(levelno=logging.CRITICAL, levelname='CRITICAL', msg='Error'))]
     )
     arguments = {}
 
@@ -174,8 +271,7 @@ def test_collect_configuration_run_summary_logs_critical_including_output_for_ru
         module.collect_configuration_run_summary_logs({'test.yaml': {}}, arguments=arguments)
     )
 
-    assert {log.levelno for log in logs} == {module.logging.CRITICAL}
-    assert any(log for log in logs if 'error output' in str(log))
+    assert {log.levelno for log in logs} == {logging.CRITICAL}
 
 
 def test_collect_configuration_run_summary_logs_outputs_merged_json_results():
@@ -190,12 +286,3 @@ def test_collect_configuration_run_summary_logs_outputs_merged_json_results():
             {'test.yaml': {}, 'test2.yaml': {}}, arguments=arguments
         )
     )
-
-
-def test_collect_configuration_run_summary_logs_critical_for_missing_configs():
-    flexmock(module).should_receive('run_configuration').and_return([])
-    arguments = {'global': flexmock(config_paths=[])}
-
-    logs = tuple(module.collect_configuration_run_summary_logs({}, arguments=arguments))
-
-    assert {log.levelno for log in logs} == {module.logging.CRITICAL}