From 6b6e1e0336dc298df03141c4c1f70021fa51b7ed Mon Sep 17 00:00:00 2001 From: Dan Helfman <witten@torsion.org> Date: Wed, 12 Mar 2025 14:13:29 -0700 Subject: [PATCH] Make the "configuration" command hook support "error" hooks and also pinging monitoring on failure (#790). --- borgmatic/commands/borgmatic.py | 424 ++++++------ borgmatic/config/paths.py | 2 +- borgmatic/hooks/command.py | 4 +- borgmatic/hooks/monitoring/cronhub.py | 2 +- borgmatic/hooks/monitoring/cronitor.py | 2 +- borgmatic/hooks/monitoring/pagerduty.py | 2 +- borgmatic/logger.py | 2 +- ...reparation-and-cleanup-steps-to-backups.md | 5 +- tests/unit/commands/test_borgmatic.py | 606 +++++++++++++----- 9 files changed, 670 insertions(+), 379 deletions(-) diff --git a/borgmatic/commands/borgmatic.py b/borgmatic/commands/borgmatic.py index b7c6ad52..5691df71 100644 --- a/borgmatic/commands/borgmatic.py +++ b/borgmatic/commands/borgmatic.py @@ -67,6 +67,113 @@ def get_skip_actions(config, arguments): return skip_actions +class Monitoring_hooks: + ''' + A Python context manager for pinging monitoring hooks for the start state before the wrapped + code and log and finish (or failure) after the wrapped code. Also responsible for + initializing/destroying the monitoring hooks. + + Example use as a context manager: + + with Monitoring_hooks(config_filename, config, arguments, global_arguments): + do_stuff() + ''' + + def __init__(self, config_filename, config, arguments, global_arguments): + ''' + Given a configuration filename, a configuration dict, command-line arguments as an + argparse.Namespace, and global arguments as an argparse.Namespace, save relevant data points + for use below. + ''' + using_primary_action = {'create', 'prune', 'compact', 'check'}.intersection(arguments) + self.config_filename = config_filename + self.config = config + self.dry_run = global_arguments.dry_run + self.monitoring_log_level = verbosity_to_log_level(global_arguments.monitoring_verbosity) + self.monitoring_hooks_are_activated = ( + using_primary_action and self.monitoring_log_level != DISABLED + ) + + def __enter__(self): + ''' + If monitoring hooks are enabled and a primary action is in use, initialize monitoring hooks + and ping them for the "start" state. + ''' + if not self.monitoring_hooks_are_activated: + return + + dispatch.call_hooks( + 'initialize_monitor', + self.config, + dispatch.Hook_type.MONITORING, + self.config_filename, + self.monitoring_log_level, + self.dry_run, + ) + + try: + dispatch.call_hooks( + 'ping_monitor', + self.config, + dispatch.Hook_type.MONITORING, + self.config_filename, + monitor.State.START, + self.monitoring_log_level, + self.dry_run, + ) + except (OSError, CalledProcessError) as error: + raise ValueError(f'Error pinging monitor: {error}') + + def __exit__(self, exception_type, exception, traceback): + ''' + If monitoring hooks are enabled and a primary action is in use, ping monitoring hooks for + the "log" state and also the "finish" or "fail" states (depending on whether there's an + exception). Lastly, destroy monitoring hooks. + ''' + if not self.monitoring_hooks_are_activated: + return + + # Send logs irrespective of error. + try: + dispatch.call_hooks( + 'ping_monitor', + self.config, + dispatch.Hook_type.MONITORING, + self.config_filename, + monitor.State.LOG, + self.monitoring_log_level, + self.dry_run, + ) + except (OSError, CalledProcessError) as error: + raise ValueError(f'Error pinging monitor: {error}') + + try: + dispatch.call_hooks( + 'ping_monitor', + self.config, + dispatch.Hook_type.MONITORING, + self.config_filename, + monitor.State.FAIL if exception else monitor.State.FINISH, + self.monitoring_log_level, + self.dry_run, + ) + except (OSError, CalledProcessError) as error: + # If the wrapped code errored, prefer raising that exception, as it's probably more + # important than a monitor failing to ping. + if exception: + return + + raise ValueError(f'Error pinging monitor: {error}') + + dispatch.call_hooks( + 'destroy_monitor', + self.config, + dispatch.Hook_type.MONITORING, + self.monitoring_log_level, + self.dry_run, + ) + + def run_configuration(config_filename, config, config_paths, arguments): ''' Given a config filename, the corresponding parsed config dict, a sequence of loaded @@ -84,11 +191,9 @@ def run_configuration(config_filename, config, config_paths, arguments): remote_path = config.get('remote_path') retries = config.get('retries', 0) retry_wait = config.get('retry_wait', 0) + repo_queue = Queue() encountered_error = None error_repository = None - using_primary_action = {'create', 'prune', 'compact', 'check'}.intersection(arguments) - monitoring_log_level = verbosity_to_log_level(global_arguments.monitoring_verbosity) - monitoring_hooks_are_activated = using_primary_action and monitoring_log_level != DISABLED skip_actions = get_skip_actions(config, arguments) if skip_actions: @@ -96,187 +201,104 @@ def run_configuration(config_filename, config, config_paths, arguments): f"Skipping {'/'.join(skip_actions)} action{'s' if len(skip_actions) > 1 else ''} due to configured skip_actions" ) - with borgmatic.hooks.command.Before_after_hooks( - command_hooks=config.get('commands'), - before_after='configuration', - umask=config.get('umask'), - dry_run=global_arguments.dry_run, - action_names=arguments.keys(), - configuration_filename=config_filename, - log_file=arguments['global'].log_file or '', - ): - try: - local_borg_version = borg_version.local_borg_version(config, local_path) - logger.debug(f'Borg {local_borg_version}') - except (OSError, CalledProcessError, ValueError) as error: - yield from log_error_records( - f'{config_filename}: Error getting local Borg version', error - ) - return - - try: - if monitoring_hooks_are_activated: - dispatch.call_hooks( - 'initialize_monitor', - config, - dispatch.Hook_type.MONITORING, - config_filename, - monitoring_log_level, - global_arguments.dry_run, - ) - - dispatch.call_hooks( - 'ping_monitor', - config, - dispatch.Hook_type.MONITORING, - config_filename, - monitor.State.START, - monitoring_log_level, - global_arguments.dry_run, - ) - except (OSError, CalledProcessError) as error: - if command.considered_soft_failure(error): - return - - encountered_error = error - yield from log_error_records(f'{config_filename}: Error pinging monitor', error) - - if not encountered_error: - repo_queue = Queue() - for repo in config['repositories']: - repo_queue.put( - (repo, 0), - ) - - while not repo_queue.empty(): - repository, retry_num = repo_queue.get() - - with Log_prefix(repository.get('label', repository['path'])): - logger.debug('Running actions for repository') - timeout = retry_num * retry_wait - if timeout: - logger.warning(f'Sleeping {timeout}s before next retry') - time.sleep(timeout) - try: - yield from run_actions( - arguments=arguments, - config_filename=config_filename, - config=config, - config_paths=config_paths, - local_path=local_path, - remote_path=remote_path, - local_borg_version=local_borg_version, - repository=repository, - ) - except (OSError, CalledProcessError, ValueError) as error: - if retry_num < retries: - repo_queue.put( - (repository, retry_num + 1), - ) - tuple( # Consume the generator so as to trigger logging. - log_error_records( - 'Error running actions for repository', - error, - levelno=logging.WARNING, - log_command_error_output=True, - ) - ) - logger.warning(f'Retrying... attempt {retry_num + 1}/{retries}') - continue - - if command.considered_soft_failure(error): - continue - - yield from log_error_records( - 'Error running actions for repository', - error, - ) - encountered_error = error - error_repository = repository - - try: - if monitoring_hooks_are_activated: - # Send logs irrespective of error. - dispatch.call_hooks( - 'ping_monitor', - config, - dispatch.Hook_type.MONITORING, - config_filename, - monitor.State.LOG, - monitoring_log_level, - global_arguments.dry_run, - ) - except (OSError, CalledProcessError) as error: - encountered_error = error - yield from log_error_records('Error pinging monitor', error) - - if not encountered_error: - try: - if monitoring_hooks_are_activated: - dispatch.call_hooks( - 'ping_monitor', - config, - dispatch.Hook_type.MONITORING, - config_filename, - monitor.State.FINISH, - monitoring_log_level, - global_arguments.dry_run, - ) - dispatch.call_hooks( - 'destroy_monitor', - config, - dispatch.Hook_type.MONITORING, - monitoring_log_level, - global_arguments.dry_run, - ) - except (OSError, CalledProcessError) as error: - encountered_error = error - yield from log_error_records(f'{config_filename}: Error pinging monitor', error) - else: - return - - try: - command.execute_hooks( - command.filter_hooks( - config.get('commands'), after='error', action_names=arguments.keys() - ), - config.get('umask'), - global_arguments.dry_run, + try: + with Monitoring_hooks(config_filename, config, arguments, global_arguments): + with borgmatic.hooks.command.Before_after_hooks( + command_hooks=config.get('commands'), + before_after='configuration', + umask=config.get('umask'), + dry_run=global_arguments.dry_run, + action_names=arguments.keys(), configuration_filename=config_filename, log_file=arguments['global'].log_file or '', - repository=error_repository.get('path', '') if error_repository else '', - repository_label=error_repository.get('label', '') if error_repository else '', - error=encountered_error, - output=getattr(encountered_error, 'output', ''), - ) - except (OSError, CalledProcessError) as error: - if command.considered_soft_failure(error): - return + ): + try: + local_borg_version = borg_version.local_borg_version(config, local_path) + logger.debug(f'Borg {local_borg_version}') + except (OSError, CalledProcessError, ValueError) as error: + yield from log_error_records( + f'{config_filename}: Error getting local Borg version', error + ) + return - yield from log_error_records( - f'{config_filename}: Error running after error hook', error - ) + for repo in config['repositories']: + repo_queue.put( + (repo, 0), + ) - try: - if monitoring_hooks_are_activated: - dispatch.call_hooks( - 'ping_monitor', - config, - dispatch.Hook_type.MONITORING, - config_filename, - monitor.State.FAIL, - monitoring_log_level, - global_arguments.dry_run, - ) - dispatch.call_hooks( - 'destroy_monitor', - config, - dispatch.Hook_type.MONITORING, - monitoring_log_level, - global_arguments.dry_run, - ) - except (OSError, CalledProcessError) as error: - yield from log_error_records(f'{config_filename}: Error pinging monitor', error) + while not repo_queue.empty(): + repository, retry_num = repo_queue.get() + + with Log_prefix(repository.get('label', repository['path'])): + logger.debug('Running actions for repository') + timeout = retry_num * retry_wait + if timeout: + logger.warning(f'Sleeping {timeout}s before next retry') + time.sleep(timeout) + try: + yield from run_actions( + arguments=arguments, + config_filename=config_filename, + config=config, + config_paths=config_paths, + local_path=local_path, + remote_path=remote_path, + local_borg_version=local_borg_version, + repository=repository, + ) + except (OSError, CalledProcessError, ValueError) as error: + if retry_num < retries: + repo_queue.put( + (repository, retry_num + 1), + ) + tuple( # Consume the generator so as to trigger logging. + log_error_records( + 'Error running actions for repository', + error, + levelno=logging.WARNING, + log_command_error_output=True, + ) + ) + logger.warning(f'Retrying... attempt {retry_num + 1}/{retries}') + continue + + if command.considered_soft_failure(error): + continue + + yield from log_error_records( + 'Error running actions for repository', + error, + ) + encountered_error = error + error_repository = repository + + except (OSError, CalledProcessError, ValueError) as error: + yield from log_error_records('Error running configuration', error) + + encountered_error = error + + if not encountered_error: + return + + try: + command.execute_hooks( + command.filter_hooks( + config.get('commands'), after='error', action_names=arguments.keys() + ), + config.get('umask'), + global_arguments.dry_run, + configuration_filename=config_filename, + log_file=arguments['global'].log_file or '', + repository=error_repository.get('path', '') if error_repository else '', + repository_label=error_repository.get('label', '') if error_repository else '', + error=encountered_error, + output=getattr(encountered_error, 'output', ''), + ) + except (OSError, CalledProcessError) as error: + if command.considered_soft_failure(error): + return + + yield from log_error_records(f'{config_filename}: Error running after error hook', error) def run_actions( @@ -845,33 +867,25 @@ def collect_configuration_run_summary_logs(configs, config_paths, arguments): for config_filename, config in configs.items(): with Log_prefix(config_filename): - try: - results = list(run_configuration(config_filename, config, config_paths, arguments)) - except (OSError, CalledProcessError, ValueError) as error: - yield from log_error_records( - 'Error running configuration file', - error, - levelno=logging.CRITICAL, - log_command_error_output=True, - ) - else: - error_logs = tuple( - result for result in results if isinstance(result, logging.LogRecord) - ) + results = list(run_configuration(config_filename, config, config_paths, arguments)) - if error_logs: - yield from log_error_records('An error occurred') - yield from error_logs - else: - yield logging.makeLogRecord( - dict( - levelno=logging.INFO, - levelname='INFO', - msg='Successfully ran configuration file', - ) + error_logs = tuple( + result for result in results if isinstance(result, logging.LogRecord) + ) + + if error_logs: + yield from log_error_records('An error occurred') + yield from error_logs + else: + yield logging.makeLogRecord( + dict( + levelno=logging.INFO, + levelname='INFO', + msg='Successfully ran configuration file', ) - if results: - json_results.extend(results) + ) + if results: + json_results.extend(results) if 'umount' in arguments: logger.info(f"Unmounting mount point {arguments['umount'].mount_point}") diff --git a/borgmatic/config/paths.py b/borgmatic/config/paths.py index 7b13d306..48dff228 100644 --- a/borgmatic/config/paths.py +++ b/borgmatic/config/paths.py @@ -134,7 +134,7 @@ class Runtime_directory: ''' return self.runtime_path - def __exit__(self, exception, value, traceback): + def __exit__(self, exception_type, exception, traceback): ''' Delete any temporary directory that was created as part of initialization. ''' diff --git a/borgmatic/hooks/command.py b/borgmatic/hooks/command.py index 5403f574..14c766ca 100644 --- a/borgmatic/hooks/command.py +++ b/borgmatic/hooks/command.py @@ -195,7 +195,7 @@ class Before_after_hooks: raise ValueError(f'Error running before {self.before_after} hook: {error}') - def __exit__(self, exception, value, traceback): + def __exit__(self, exception_type, exception, traceback): ''' Run the configured "after" command hooks that match the initialized data points. ''' @@ -215,7 +215,7 @@ class Before_after_hooks: if considered_soft_failure(error): return - raise ValueError(f'Error running before {self.before_after} hook: {error}') + raise ValueError(f'Error running after {self.before_after} hook: {error}') def considered_soft_failure(error): diff --git a/borgmatic/hooks/monitoring/cronhub.py b/borgmatic/hooks/monitoring/cronhub.py index 837d770b..8d64957d 100644 --- a/borgmatic/hooks/monitoring/cronhub.py +++ b/borgmatic/hooks/monitoring/cronhub.py @@ -28,7 +28,7 @@ def ping_monitor(hook_config, config, config_filename, state, monitoring_log_lev filename in any log entries. If this is a dry run, then don't actually ping anything. ''' if state not in MONITOR_STATE_TO_CRONHUB: - logger.debug(f'Ignoring unsupported monitoring {state.name.lower()} in Cronhub hook') + logger.debug(f'Ignoring unsupported monitoring state {state.name.lower()} in Cronhub hook') return dry_run_label = ' (dry run; not actually pinging)' if dry_run else '' diff --git a/borgmatic/hooks/monitoring/cronitor.py b/borgmatic/hooks/monitoring/cronitor.py index e8169312..2a176dc1 100644 --- a/borgmatic/hooks/monitoring/cronitor.py +++ b/borgmatic/hooks/monitoring/cronitor.py @@ -28,7 +28,7 @@ def ping_monitor(hook_config, config, config_filename, state, monitoring_log_lev filename in any log entries. If this is a dry run, then don't actually ping anything. ''' if state not in MONITOR_STATE_TO_CRONITOR: - logger.debug(f'Ignoring unsupported monitoring {state.name.lower()} in Cronitor hook') + logger.debug(f'Ignoring unsupported monitoring state {state.name.lower()} in Cronitor hook') return dry_run_label = ' (dry run; not actually pinging)' if dry_run else '' diff --git a/borgmatic/hooks/monitoring/pagerduty.py b/borgmatic/hooks/monitoring/pagerduty.py index d98375d9..cd63f633 100644 --- a/borgmatic/hooks/monitoring/pagerduty.py +++ b/borgmatic/hooks/monitoring/pagerduty.py @@ -46,7 +46,7 @@ def ping_monitor(hook_config, config, config_filename, state, monitoring_log_lev ''' if state != monitor.State.FAIL: logger.debug( - f'Ignoring unsupported monitoring {state.name.lower()} in PagerDuty hook', + f'Ignoring unsupported monitoring state {state.name.lower()} in PagerDuty hook', ) return diff --git a/borgmatic/logger.py b/borgmatic/logger.py index 07b4de76..8e327b62 100644 --- a/borgmatic/logger.py +++ b/borgmatic/logger.py @@ -256,7 +256,7 @@ class Log_prefix: self.original_prefix = get_log_prefix() set_log_prefix(self.prefix) - def __exit__(self, exception, value, traceback): + def __exit__(self, exception_type, exception, traceback): ''' Restore any original prefix. ''' diff --git a/docs/how-to/add-preparation-and-cleanup-steps-to-backups.md b/docs/how-to/add-preparation-and-cleanup-steps-to-backups.md index 614e1a47..578601e2 100644 --- a/docs/how-to/add-preparation-and-cleanup-steps-to-backups.md +++ b/docs/how-to/add-preparation-and-cleanup-steps-to-backups.md @@ -61,14 +61,11 @@ Each command in the `commands:` list has the following options: * `action` runs before each action for each repository. This replaces the deprecated `before_create`, `after_prune`, etc. * `repository` runs before or after all actions for each repository. This replaces the deprecated `before_actions` and `after_actions`. * `configuration` runs before or after all actions and repositories in the current configuration file. - * `everything` runs before or after all configuration files. This replaces the deprecated `before_everything` and `after_everything`. + * `everything` runs before or after all configuration files. Errors here do not trigger `error` hooks or the `fail` state in monitoring hooks. This replaces the deprecated `before_everything` and `after_everything`. * `error` runs after an error occurs—and it's only available for `after`. This replaces the deprecated `on_error` hook. * `when`: Only trigger the hook when borgmatic is run with particular actions (`create`, `prune`, etc.) listed here. Defaults to running for all actions. * `run`: List of one or more shell commands or scripts to run when this command hook is triggered. -borgmatic does not run `error` hooks if an error occurs within an `everything` -hook. - There's also another command hook that works a little differently: ```yaml diff --git a/tests/unit/commands/test_borgmatic.py b/tests/unit/commands/test_borgmatic.py index e85a6792..c31cf904 100644 --- a/tests/unit/commands/test_borgmatic.py +++ b/tests/unit/commands/test_borgmatic.py @@ -27,9 +27,392 @@ def test_get_skip_actions_uses_config_and_arguments(config, arguments, expected_ assert module.get_skip_actions(config, arguments) == expected_actions +def test_monitoring_hooks_with_monioring_disabled_bails(): + flexmock(module).should_receive('verbosity_to_log_level').and_return(module.DISABLED) + flexmock(module.dispatch).should_receive('call_hooks').never() + + with module.Monitoring_hooks( + config_filename='test.yaml', + config={}, + arguments={'create': flexmock()}, + global_arguments=flexmock(monitoring_verbosity=99, dry_run=False), + ): + pass + + +def test_monitoring_hooks_with_non_primary_action_bails(): + flexmock(module).should_receive('verbosity_to_log_level').and_return(flexmock()) + flexmock(module.dispatch).should_receive('call_hooks').never() + + with module.Monitoring_hooks( + config_filename='test.yaml', + config={}, + arguments={'extract': flexmock()}, + global_arguments=flexmock(monitoring_verbosity=99, dry_run=False), + ): + pass + + +def test_monitoring_hooks_pings_monitors(): + flexmock(module).should_receive('verbosity_to_log_level').and_return(flexmock()) + flexmock(module.dispatch).should_receive('call_hooks').with_args( + 'initialize_monitor', + object, + object, + object, + object, + object, + ).once() + flexmock(module.dispatch).should_receive('call_hooks').with_args( + 'ping_monitor', + object, + object, + object, + module.monitor.State.START, + object, + object, + ).once() + flexmock(module.dispatch).should_receive('call_hooks').with_args( + 'ping_monitor', + object, + object, + object, + module.monitor.State.LOG, + object, + object, + ).once() + flexmock(module.dispatch).should_receive('call_hooks').with_args( + 'ping_monitor', + object, + object, + object, + module.monitor.State.FINISH, + object, + object, + ).once() + flexmock(module.dispatch).should_receive('call_hooks').with_args( + 'ping_monitor', + object, + object, + object, + module.monitor.State.FAIL, + object, + object, + ).never() + flexmock(module.dispatch).should_receive('call_hooks').with_args( + 'destroy_monitor', + object, + object, + object, + object, + ).once() + + with module.Monitoring_hooks( + config_filename='test.yaml', + config={}, + arguments={'create': flexmock()}, + global_arguments=flexmock(monitoring_verbosity=99, dry_run=False), + ): + pass + + +def test_monitoring_hooks_with_start_ping_error_raises(): + flexmock(module).should_receive('verbosity_to_log_level').and_return(flexmock()) + flexmock(module.dispatch).should_receive('call_hooks').with_args( + 'initialize_monitor', + object, + object, + object, + object, + object, + ).once() + flexmock(module.dispatch).should_receive('call_hooks').with_args( + 'ping_monitor', + object, + object, + object, + module.monitor.State.START, + object, + object, + ).and_raise(OSError).once() + flexmock(module.dispatch).should_receive('call_hooks').with_args( + 'ping_monitor', + object, + object, + object, + module.monitor.State.LOG, + object, + object, + ).never() + flexmock(module.dispatch).should_receive('call_hooks').with_args( + 'ping_monitor', + object, + object, + object, + module.monitor.State.FINISH, + object, + object, + ).never() + flexmock(module.dispatch).should_receive('call_hooks').with_args( + 'destroy_monitor', + object, + object, + object, + object, + ).never() + + with pytest.raises(ValueError): + with module.Monitoring_hooks( + config_filename='test.yaml', + config={}, + arguments={'create': flexmock()}, + global_arguments=flexmock(monitoring_verbosity=99, dry_run=False), + ): + assert False # This should never get called. + + +def test_monitoring_hooks_with_log_ping_error_raises(): + flexmock(module).should_receive('verbosity_to_log_level').and_return(flexmock()) + flexmock(module.dispatch).should_receive('call_hooks').with_args( + 'initialize_monitor', + object, + object, + object, + object, + object, + ).once() + flexmock(module.dispatch).should_receive('call_hooks').with_args( + 'ping_monitor', + object, + object, + object, + module.monitor.State.START, + object, + object, + ).once() + flexmock(module.dispatch).should_receive('call_hooks').with_args( + 'ping_monitor', + object, + object, + object, + module.monitor.State.LOG, + object, + object, + ).and_raise(OSError).once() + flexmock(module.dispatch).should_receive('call_hooks').with_args( + 'ping_monitor', + object, + object, + object, + module.monitor.State.FINISH, + object, + object, + ).never() + flexmock(module.dispatch).should_receive('call_hooks').with_args( + 'destroy_monitor', + object, + object, + object, + object, + ).never() + + with pytest.raises(ValueError): + with module.Monitoring_hooks( + config_filename='test.yaml', + config={}, + arguments={'create': flexmock()}, + global_arguments=flexmock(monitoring_verbosity=99, dry_run=False), + ): + pass + + +def test_monitoring_hooks_with_finish_ping_error_raises(): + flexmock(module).should_receive('verbosity_to_log_level').and_return(flexmock()) + flexmock(module.dispatch).should_receive('call_hooks').with_args( + 'initialize_monitor', + object, + object, + object, + object, + object, + ).once() + flexmock(module.dispatch).should_receive('call_hooks').with_args( + 'ping_monitor', + object, + object, + object, + module.monitor.State.START, + object, + object, + ).once() + flexmock(module.dispatch).should_receive('call_hooks').with_args( + 'ping_monitor', + object, + object, + object, + module.monitor.State.LOG, + object, + object, + ).once() + flexmock(module.dispatch).should_receive('call_hooks').with_args( + 'ping_monitor', + object, + object, + object, + module.monitor.State.FINISH, + object, + object, + ).and_raise(OSError).once() + flexmock(module.dispatch).should_receive('call_hooks').with_args( + 'destroy_monitor', + object, + object, + object, + object, + ).never() + + with pytest.raises(ValueError): + with module.Monitoring_hooks( + config_filename='test.yaml', + config={}, + arguments={'create': flexmock()}, + global_arguments=flexmock(monitoring_verbosity=99, dry_run=False), + ): + pass + + +def test_monitoring_with_wrapped_code_error_pings_fail(): + flexmock(module).should_receive('verbosity_to_log_level').and_return(flexmock()) + flexmock(module.dispatch).should_receive('call_hooks').with_args( + 'initialize_monitor', + object, + object, + object, + object, + object, + ).once() + flexmock(module.dispatch).should_receive('call_hooks').with_args( + 'ping_monitor', + object, + object, + object, + module.monitor.State.START, + object, + object, + ).once() + flexmock(module.dispatch).should_receive('call_hooks').with_args( + 'ping_monitor', + object, + object, + object, + module.monitor.State.LOG, + object, + object, + ).once() + flexmock(module.dispatch).should_receive('call_hooks').with_args( + 'ping_monitor', + object, + object, + object, + module.monitor.State.FINISH, + object, + object, + ).never() + flexmock(module.dispatch).should_receive('call_hooks').with_args( + 'ping_monitor', + object, + object, + object, + module.monitor.State.FAIL, + object, + object, + ).once() + flexmock(module.dispatch).should_receive('call_hooks').with_args( + 'destroy_monitor', + object, + object, + object, + object, + ).once() + + with pytest.raises(OSError): + with module.Monitoring_hooks( + config_filename='test.yaml', + config={}, + arguments={'create': flexmock()}, + global_arguments=flexmock(monitoring_verbosity=99, dry_run=False), + ): + raise OSError() + + +def test_monitoring_with_fail_ping_error_raise_original_error(): + flexmock(module).should_receive('verbosity_to_log_level').and_return(flexmock()) + flexmock(module.dispatch).should_receive('call_hooks').with_args( + 'initialize_monitor', + object, + object, + object, + object, + object, + ).once() + flexmock(module.dispatch).should_receive('call_hooks').with_args( + 'ping_monitor', + object, + object, + object, + module.monitor.State.START, + object, + object, + ).once() + flexmock(module.dispatch).should_receive('call_hooks').with_args( + 'ping_monitor', + object, + object, + object, + module.monitor.State.LOG, + object, + object, + ).once() + flexmock(module.dispatch).should_receive('call_hooks').with_args( + 'ping_monitor', + object, + object, + object, + module.monitor.State.FINISH, + object, + object, + ).never() + flexmock(module.dispatch).should_receive('call_hooks').with_args( + 'ping_monitor', + object, + object, + object, + module.monitor.State.FAIL, + object, + object, + ).and_raise(OSError).once() + flexmock(module.dispatch).should_receive('call_hooks').with_args( + 'destroy_monitor', + object, + object, + object, + object, + ).never() + + with pytest.raises(OSError): + with module.Monitoring_hooks( + config_filename='test.yaml', + config={}, + arguments={'create': flexmock()}, + global_arguments=flexmock(monitoring_verbosity=99, dry_run=False), + ): + raise OSError() + + def test_run_configuration_runs_actions_for_each_repository(): flexmock(module).should_receive('verbosity_to_log_level').and_return(logging.INFO) flexmock(module).should_receive('get_skip_actions').and_return([]) + 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()] @@ -48,6 +431,7 @@ def test_run_configuration_runs_actions_for_each_repository(): def test_run_configuration_with_skip_actions_does_not_raise(): flexmock(module).should_receive('verbosity_to_log_level').and_return(logging.INFO) flexmock(module).should_receive('get_skip_actions').and_return(['compact']) + 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()) flexmock(module).should_receive('Log_prefix').and_return(flexmock()) @@ -61,9 +445,9 @@ def test_run_configuration_with_skip_actions_does_not_raise(): def test_run_configuration_with_invalid_borg_version_errors(): flexmock(module).should_receive('verbosity_to_log_level').and_return(logging.INFO) flexmock(module).should_receive('get_skip_actions').and_return([]) + 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_raise(ValueError) - flexmock(module.dispatch).should_receive('call_hooks').never() flexmock(module).should_receive('Log_prefix').and_return(flexmock()) flexmock(module).should_receive('run_actions').never() config = {'repositories': [{'path': 'foo'}]} @@ -75,58 +459,12 @@ def test_run_configuration_with_invalid_borg_version_errors(): list(module.run_configuration('test.yaml', config, ['/tmp/test.yaml'], arguments)) -def test_run_configuration_logs_monitor_start_error(): - flexmock(module).should_receive('verbosity_to_log_level').and_return(logging.INFO) - flexmock(module).should_receive('get_skip_actions').and_return([]) - flexmock(module.command).should_receive('Before_after_hooks').and_return(flexmock()) - flexmock(module.borg_version).should_receive('local_borg_version').and_return(flexmock()) - flexmock(module.dispatch).should_receive('call_hooks').and_raise(OSError).and_return( - None - ).and_return(None).and_return(None) - expected_results = [flexmock()] - flexmock(module).should_receive('log_error_records').and_return(expected_results) - flexmock(module).should_receive('Log_prefix').and_return(flexmock()) - flexmock(module).should_receive('run_actions').never() - flexmock(module.command).should_receive('filter_hooks') - flexmock(module.command).should_receive('execute_hooks') - config = {'repositories': [{'path': 'foo'}]} - arguments = { - 'global': flexmock(monitoring_verbosity=1, dry_run=False, log_file=flexmock()), - 'create': flexmock(), - } - - results = list(module.run_configuration('test.yaml', config, ['/tmp/test.yaml'], arguments)) - - assert results == expected_results - - -def test_run_configuration_bails_for_monitor_start_soft_failure(): - flexmock(module).should_receive('verbosity_to_log_level').and_return(logging.INFO) - flexmock(module).should_receive('get_skip_actions').and_return([]) - flexmock(module.command).should_receive('Before_after_hooks').and_return(flexmock()) - 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).and_return(None) - flexmock(module).should_receive('log_error_records').never() - flexmock(module).should_receive('Log_prefix').and_return(flexmock()) - flexmock(module).should_receive('run_actions').never() - config = {'repositories': [{'path': 'foo'}, {'path': 'bar'}]} - arguments = { - 'global': flexmock(monitoring_verbosity=1, dry_run=False, log_file=flexmock()), - 'create': flexmock(), - } - - results = list(module.run_configuration('test.yaml', config, ['/tmp/test.yaml'], arguments)) - - assert results == [] - - def test_run_configuration_logs_actions_error(): flexmock(module).should_receive('verbosity_to_log_level').and_return(logging.INFO) flexmock(module).should_receive('get_skip_actions').and_return([]) + 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()) - flexmock(module.dispatch).should_receive('call_hooks') expected_results = [flexmock()] flexmock(module).should_receive('log_error_records').and_return(expected_results) flexmock(module).should_receive('Log_prefix').and_return(flexmock()) @@ -144,9 +482,9 @@ def test_run_configuration_logs_actions_error(): def test_run_configuration_skips_remaining_actions_for_actions_soft_failure_but_still_runs_next_repository_actions(): flexmock(module).should_receive('verbosity_to_log_level').and_return(logging.INFO) flexmock(module).should_receive('get_skip_actions').and_return([]) + 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()) - flexmock(module.dispatch).should_receive('call_hooks').times(5) error = subprocess.CalledProcessError(borgmatic.hooks.command.SOFT_FAIL_EXIT_CODE, 'try again') log = flexmock() flexmock(module).should_receive('Log_prefix').and_return(flexmock()) @@ -164,106 +502,13 @@ def test_run_configuration_skips_remaining_actions_for_actions_soft_failure_but_ assert results == [log] -def test_run_configuration_logs_monitor_log_error(): - flexmock(module).should_receive('verbosity_to_log_level').and_return(logging.INFO) - flexmock(module).should_receive('get_skip_actions').and_return([]) - flexmock(module.command).should_receive('Before_after_hooks').and_return(flexmock()) - flexmock(module.borg_version).should_receive('local_borg_version').and_return(flexmock()) - flexmock(module.dispatch).should_receive('call_hooks').and_return(None).and_return( - None - ).and_raise(OSError) - expected_results = [flexmock()] - flexmock(module).should_receive('log_error_records').and_return(expected_results) - flexmock(module).should_receive('Log_prefix').and_return(flexmock()) - flexmock(module).should_receive('run_actions').and_return([]) - flexmock(module.command).should_receive('filter_hooks') - flexmock(module.command).should_receive('execute_hooks') - config = {'repositories': [{'path': 'foo'}]} - arguments = { - 'global': flexmock(monitoring_verbosity=1, dry_run=False, log_file=flexmock()), - 'create': flexmock(), - } - - results = list(module.run_configuration('test.yaml', config, ['/tmp/test.yaml'], arguments)) - - assert results == expected_results - - -def test_run_configuration_logs_monitor_finish_error(): - flexmock(module).should_receive('verbosity_to_log_level').and_return(logging.INFO) - flexmock(module).should_receive('get_skip_actions').and_return([]) - flexmock(module.command).should_receive('Before_after_hooks').and_return(flexmock()) - flexmock(module.borg_version).should_receive('local_borg_version').and_return(flexmock()) - flexmock(module.dispatch).should_receive('call_hooks').and_return(None).and_return( - None - ).and_return(None).and_raise(OSError) - expected_results = [flexmock()] - flexmock(module).should_receive('log_error_records').and_return(expected_results) - flexmock(module).should_receive('Log_prefix').and_return(flexmock()) - flexmock(module).should_receive('run_actions').and_return([]) - flexmock(module.command).should_receive('filter_hooks') - flexmock(module.command).should_receive('execute_hooks') - config = {'repositories': [{'path': 'foo'}]} - arguments = { - 'global': flexmock(monitoring_verbosity=1, dry_run=False, log_file=flexmock()), - 'create': flexmock(), - } - - results = list(module.run_configuration('test.yaml', config, ['/tmp/test.yaml'], arguments)) - - assert results == expected_results - - -def test_run_configuration_logs_monitor_fail_error(): - flexmock(module).should_receive('verbosity_to_log_level').and_return(logging.INFO) - flexmock(module).should_receive('get_skip_actions').and_return([]) - flexmock(module.command).should_receive('Before_after_hooks').and_return(flexmock()) - flexmock(module.borg_version).should_receive('local_borg_version').and_return(flexmock()) - flexmock(module.dispatch).should_receive('call_hooks') - - # Trigger an error in the monitor finish so that the monitor fail also gets triggered. - flexmock(module.dispatch).should_receive('call_hooks').with_args( - 'ping_monitor', - object, - module.dispatch.Hook_type.MONITORING, - object, - module.monitor.State.FINISH, - object, - object, - ).and_raise(OSError) - flexmock(module.dispatch).should_receive('call_hooks').with_args( - 'ping_monitor', - object, - module.dispatch.Hook_type.MONITORING, - object, - module.monitor.State.FAIL, - object, - object, - ).and_raise(OSError).once() - expected_results = [flexmock()] - flexmock(module).should_receive('log_error_records').and_return(expected_results) - flexmock(module).should_receive('Log_prefix').and_return(flexmock()) - flexmock(module).should_receive('run_actions').and_return([]) - flexmock(module.command).should_receive('filter_hooks') - flexmock(module.command).should_receive('execute_hooks') - config = {'repositories': [{'path': 'foo'}]} - arguments = { - 'global': flexmock(monitoring_verbosity=1, dry_run=False, log_file=flexmock()), - 'create': flexmock(), - } - - results = list(module.run_configuration('test.yaml', config, ['/tmp/test.yaml'], arguments)) - - assert results == expected_results + expected_results - - def test_run_configuration_does_not_call_monitoring_hooks_if_monitoring_hooks_are_disabled(): flexmock(module).should_receive('verbosity_to_log_level').and_return(module.DISABLED) flexmock(module).should_receive('get_skip_actions').and_return([]) + 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()) - flexmock(module.dispatch).should_receive('call_hooks').never() flexmock(module).should_receive('Log_prefix').and_return(flexmock()) flexmock(module).should_receive('run_actions').and_return([]) @@ -279,6 +524,7 @@ def test_run_configuration_does_not_call_monitoring_hooks_if_monitoring_hooks_ar def test_run_configuration_logs_on_error_hook_error(): flexmock(module).should_receive('verbosity_to_log_level').and_return(logging.INFO) flexmock(module).should_receive('get_skip_actions').and_return([]) + 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()) flexmock(module.command).should_receive('filter_hooks') @@ -300,9 +546,56 @@ def test_run_configuration_logs_on_error_hook_error(): assert results == expected_results +def test_run_configuration_logs_on_before_command_hook_error(): + flexmock(module).should_receive('verbosity_to_log_level').and_return(logging.INFO) + flexmock(module).should_receive('get_skip_actions').and_return([]) + flexmock(module).should_receive('Monitoring_hooks').and_return(flexmock()) + flexmock(module.command).should_receive('Before_after_hooks').and_raise(OSError) + flexmock(module.borg_version).should_receive('local_borg_version').never() + flexmock(module.command).should_receive('filter_hooks') + flexmock(module.command).should_receive('execute_hooks') + expected_results = [flexmock()] + flexmock(module).should_receive('log_error_records').and_return(expected_results) + flexmock(module).should_receive('Log_prefix').never() + flexmock(module).should_receive('run_actions').never() + config = {'repositories': [{'path': 'foo'}]} + arguments = { + 'global': flexmock(monitoring_verbosity=1, dry_run=False, log_file=flexmock()), + 'create': flexmock(), + } + + results = list(module.run_configuration('test.yaml', config, ['/tmp/test.yaml'], arguments)) + + assert results == expected_results + + +def test_run_configuration_logs_on_monitoring_hook_error(): + flexmock(module).should_receive('verbosity_to_log_level').and_return(logging.INFO) + flexmock(module).should_receive('get_skip_actions').and_return([]) + flexmock(module).should_receive('Monitoring_hooks').and_raise(OSError) + flexmock(module.command).should_receive('Before_after_hooks').never() + flexmock(module.borg_version).should_receive('local_borg_version').never() + flexmock(module.command).should_receive('filter_hooks') + flexmock(module.command).should_receive('execute_hooks') + expected_results = [flexmock()] + flexmock(module).should_receive('log_error_records').and_return(expected_results) + flexmock(module).should_receive('Log_prefix').never() + flexmock(module).should_receive('run_actions').never() + config = {'repositories': [{'path': 'foo'}]} + arguments = { + 'global': flexmock(monitoring_verbosity=1, dry_run=False, log_file=flexmock()), + 'create': flexmock(), + } + + results = list(module.run_configuration('test.yaml', config, ['/tmp/test.yaml'], arguments)) + + assert results == expected_results + + def test_run_configuration_bails_for_on_error_hook_soft_failure(): flexmock(module).should_receive('verbosity_to_log_level').and_return(logging.INFO) flexmock(module).should_receive('get_skip_actions').and_return([]) + 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()) error = subprocess.CalledProcessError(borgmatic.hooks.command.SOFT_FAIL_EXIT_CODE, 'try again') @@ -327,6 +620,7 @@ def test_run_configuration_retries_soft_error(): # Run action first fails, second passes. flexmock(module).should_receive('verbosity_to_log_level').and_return(logging.INFO) flexmock(module).should_receive('get_skip_actions').and_return([]) + 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()) flexmock(module).should_receive('Log_prefix').and_return(flexmock()) @@ -349,6 +643,7 @@ def test_run_configuration_retries_hard_error(): # Run action fails twice. flexmock(module).should_receive('verbosity_to_log_level').and_return(logging.INFO) flexmock(module).should_receive('get_skip_actions').and_return([]) + 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()) flexmock(module).should_receive('Log_prefix').and_return(flexmock()) @@ -380,6 +675,7 @@ def test_run_configuration_retries_hard_error(): def test_run_configuration_retries_repositories_in_order(): flexmock(module).should_receive('verbosity_to_log_level').and_return(logging.INFO) flexmock(module).should_receive('get_skip_actions').and_return([]) + 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()) flexmock(module).should_receive('Log_prefix').and_return(flexmock()) @@ -407,6 +703,7 @@ def test_run_configuration_retries_repositories_in_order(): def test_run_configuration_retries_round_robin(): flexmock(module).should_receive('verbosity_to_log_level').and_return(logging.INFO) flexmock(module).should_receive('get_skip_actions').and_return([]) + 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()) flexmock(module).should_receive('Log_prefix').and_return(flexmock()) @@ -450,6 +747,7 @@ def test_run_configuration_retries_round_robin(): def test_run_configuration_with_one_retry(): flexmock(module).should_receive('verbosity_to_log_level').and_return(logging.INFO) flexmock(module).should_receive('get_skip_actions').and_return([]) + 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()) flexmock(module).should_receive('Log_prefix').and_return(flexmock()) @@ -491,6 +789,7 @@ def test_run_configuration_with_one_retry(): def test_run_configuration_with_retry_wait_does_backoff_after_each_retry(): flexmock(module).should_receive('verbosity_to_log_level').and_return(logging.INFO) flexmock(module).should_receive('get_skip_actions').and_return([]) + 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()) flexmock(module).should_receive('Log_prefix').and_return(flexmock()) @@ -543,6 +842,7 @@ def test_run_configuration_with_retry_wait_does_backoff_after_each_retry(): def test_run_configuration_with_multiple_repositories_retries_with_timeout(): flexmock(module).should_receive('verbosity_to_log_level').and_return(logging.INFO) flexmock(module).should_receive('get_skip_actions').and_return([]) + 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()) flexmock(module).should_receive('Log_prefix').and_return(flexmock()) @@ -1715,26 +2015,6 @@ def test_collect_configuration_run_summary_logs_run_configuration_error_logs(): assert {log.levelno for log in logs} == {logging.CRITICAL} -def test_collect_configuration_run_summary_logs_run_configuration_exception(): - flexmock(module.validate).should_receive('guard_configuration_contains_repository') - flexmock(module.command).should_receive('filter_hooks') - flexmock(module.command).should_receive('execute_hooks') - flexmock(module).should_receive('Log_prefix').and_return(flexmock()) - flexmock(module).should_receive('run_configuration').and_raise(ValueError) - flexmock(module).should_receive('log_error_records').and_return( - [flexmock(levelno=logging.CRITICAL)] - ) - arguments = {'global': flexmock(dry_run=False, log_file=flexmock())} - - logs = tuple( - module.collect_configuration_run_summary_logs( - {'test.yaml': {}}, config_paths=['/tmp/test.yaml'], arguments=arguments - ) - ) - - assert {log.levelno for log in logs} == {logging.CRITICAL} - - def test_collect_configuration_run_summary_logs_run_umount_error(): flexmock(module.validate).should_receive('guard_configuration_contains_repository') flexmock(module.command).should_receive('filter_hooks')