From 6c617eddd5f20462034947a1c288a36f9f3b4bd0 Mon Sep 17 00:00:00 2001 From: Dan Helfman Date: Mon, 30 Sep 2019 22:19:31 -0700 Subject: [PATCH] When backups to one of several repositories fails, keep backing up to the other repositories (#144). --- NEWS | 4 + borgmatic/commands/borgmatic.py | 144 +++++++++++++-------- setup.py | 2 +- tests/unit/commands/test_borgmatic.py | 179 +++++++++++++++++++------- 4 files changed, 225 insertions(+), 104 deletions(-) diff --git a/NEWS b/NEWS index 1ae86d6..ab67d6f 100644 --- a/NEWS +++ b/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: diff --git a/borgmatic/commands/borgmatic.py b/borgmatic/commands/borgmatic.py index b1001bb..e59898d 100644 --- a/borgmatic/commands/borgmatic.py +++ b/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, ) - - 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, + except (OSError, CalledProcessError) as error: + encountered_error = True + yield from make_error_log_records( + '{}: Error running pre-backup hook'.format(config_filename), error ) - if 'create' in arguments: + if not encountered_error: + for repository_path in location['repositories']: + 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 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 diff --git a/setup.py b/setup.py index b7c7532..013fb6f 100644 --- a/setup.py +++ b/setup.py @@ -1,6 +1,6 @@ from setuptools import find_packages, setup -VERSION = '1.3.21' +VERSION = '1.3.22' setup( diff --git a/tests/unit/commands/test_borgmatic.py b/tests/unit/commands/test_borgmatic.py index 61161e4..a6c419c 100644 --- a/tests/unit/commands/test_borgmatic.py +++ b/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_critical_for_pre_hook_error(): +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_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}