From f66fd1caaac68569b1aad7e32a5e97129d2682a5 Mon Sep 17 00:00:00 2001 From: Dan Helfman Date: Wed, 22 Jan 2020 15:10:47 -0800 Subject: [PATCH] Customize Healthchecks log level via borgmatic "--monitoring-verbosity" flag (#277). --- NEWS | 1 + borgmatic/commands/arguments.py | 7 ++++ borgmatic/commands/borgmatic.py | 5 +++ borgmatic/hooks/cronhub.py | 2 +- borgmatic/hooks/cronitor.py | 2 +- borgmatic/hooks/healthchecks.py | 13 +++++--- borgmatic/logger.py | 11 ++++-- docs/how-to/monitor-your-backups.md | 6 ++-- tests/unit/commands/test_borgmatic.py | 24 +++++++------- tests/unit/hooks/test_cronhub.py | 20 ++++++++--- tests/unit/hooks/test_cronitor.py | 16 ++++++--- tests/unit/hooks/test_healthchecks.py | 48 ++++++++++++++++++++++----- 12 files changed, 113 insertions(+), 42 deletions(-) diff --git a/NEWS b/NEWS index dca9bd7..6e02211 100644 --- a/NEWS +++ b/NEWS @@ -1,5 +1,6 @@ 1.4.23.dev0 * #274: Add ~/.config/borgmatic.d as another configuration directory default. + * #277: Customize Healthchecks log level via borgmatic "--monitoring-verbosity" flag. * For "create" and "prune" actions, no longer list files or show detailed stats at verbosity 1. You can opt back in with "--files" or "--stats" flags. diff --git a/borgmatic/commands/arguments.py b/borgmatic/commands/arguments.py index 61b9cfc..61a754d 100644 --- a/borgmatic/commands/arguments.py +++ b/borgmatic/commands/arguments.py @@ -159,6 +159,13 @@ def parse_arguments(*unparsed_arguments): default=0, help='Log verbose progress to log file (from only errors to very verbose: -1, 0, 1, or 2). Only used when --log-file is given', ) + global_group.add_argument( + '--monitoring-verbosity', + type=int, + choices=range(-1, 3), + default=1, + help='Log verbose progress to monitoring integrations that support logging (from only errors to very verbose: -1, 0, 1, or 2)', + ) global_group.add_argument( '--log-file', type=str, diff --git a/borgmatic/commands/borgmatic.py b/borgmatic/commands/borgmatic.py index df50bb7..4c9b0d8 100644 --- a/borgmatic/commands/borgmatic.py +++ b/borgmatic/commands/borgmatic.py @@ -53,6 +53,7 @@ def run_configuration(config_filename, config, arguments): encountered_error = None error_repository = '' prune_create_or_check = {'prune', 'create', 'check'}.intersection(arguments) + monitoring_log_level = verbosity_to_log_level(global_arguments.monitoring_verbosity) try: if prune_create_or_check: @@ -62,6 +63,7 @@ def run_configuration(config_filename, config, arguments): config_filename, monitor.MONITOR_HOOK_NAMES, monitor.State.START, + monitoring_log_level, global_arguments.dry_run, ) if 'create' in arguments: @@ -132,6 +134,7 @@ def run_configuration(config_filename, config, arguments): config_filename, monitor.MONITOR_HOOK_NAMES, monitor.State.FINISH, + monitoring_log_level, global_arguments.dry_run, ) except (OSError, CalledProcessError) as error: @@ -158,6 +161,7 @@ def run_configuration(config_filename, config, arguments): config_filename, monitor.MONITOR_HOOK_NAMES, monitor.State.FAIL, + monitoring_log_level, global_arguments.dry_run, ) except (OSError, CalledProcessError) as error: @@ -601,6 +605,7 @@ def main(): # pragma: no cover verbosity_to_log_level(global_arguments.verbosity), verbosity_to_log_level(global_arguments.syslog_verbosity), verbosity_to_log_level(global_arguments.log_file_verbosity), + verbosity_to_log_level(global_arguments.monitoring_verbosity), global_arguments.log_file, ) except (FileNotFoundError, PermissionError) as error: diff --git a/borgmatic/hooks/cronhub.py b/borgmatic/hooks/cronhub.py index a0d0ac9..f95abe6 100644 --- a/borgmatic/hooks/cronhub.py +++ b/borgmatic/hooks/cronhub.py @@ -13,7 +13,7 @@ MONITOR_STATE_TO_CRONHUB = { } -def ping_monitor(ping_url, config_filename, state, dry_run): +def ping_monitor(ping_url, config_filename, state, monitoring_log_level, dry_run): ''' Ping the given Cronhub URL, modified with the monitor.State. Use the given configuration filename in any log entries. If this is a dry run, then don't actually ping anything. diff --git a/borgmatic/hooks/cronitor.py b/borgmatic/hooks/cronitor.py index 65ad109..e4bc7c4 100644 --- a/borgmatic/hooks/cronitor.py +++ b/borgmatic/hooks/cronitor.py @@ -13,7 +13,7 @@ MONITOR_STATE_TO_CRONITOR = { } -def ping_monitor(ping_url, config_filename, state, dry_run): +def ping_monitor(ping_url, config_filename, state, monitoring_log_level, dry_run): ''' Ping the given Cronitor URL, modified with the monitor.State. Use the given configuration filename in any log entries. If this is a dry run, then don't actually ping anything. diff --git a/borgmatic/hooks/healthchecks.py b/borgmatic/hooks/healthchecks.py index a116205..e16dfc7 100644 --- a/borgmatic/hooks/healthchecks.py +++ b/borgmatic/hooks/healthchecks.py @@ -22,13 +22,14 @@ class Forgetful_buffering_handler(logging.Handler): first) once a particular capacity in bytes is reached. ''' - def __init__(self, byte_capacity): + def __init__(self, byte_capacity, log_level): super().__init__() self.byte_capacity = byte_capacity self.byte_count = 0 self.buffer = [] self.forgot = False + self.setLevel(log_level) def emit(self, record): message = record.getMessage() + '\n' @@ -64,16 +65,18 @@ def format_buffered_logs_for_payload(): return payload -def ping_monitor(ping_url_or_uuid, config_filename, state, dry_run): +def ping_monitor(ping_url_or_uuid, config_filename, state, monitoring_log_level, dry_run): ''' Ping the given Healthchecks URL or UUID, modified with the monitor.State. Use the given - configuration filename in any log entries. If this is a dry run, then don't actually ping - anything. + configuration filename in any log entries, and log to Healthchecks with the giving log level. + If this is a dry run, then don't actually ping anything. ''' if state is monitor.State.START: # Add a handler to the root logger that stores in memory the most recent logs emitted. That # way, we can send them all to Healthchecks upon a finish or failure state. - logging.getLogger().addHandler(Forgetful_buffering_handler(PAYLOAD_LIMIT_BYTES)) + logging.getLogger().addHandler( + Forgetful_buffering_handler(PAYLOAD_LIMIT_BYTES, monitoring_log_level) + ) payload = '' ping_url = ( diff --git a/borgmatic/logger.py b/borgmatic/logger.py index b20f89e..7099230 100644 --- a/borgmatic/logger.py +++ b/borgmatic/logger.py @@ -110,7 +110,11 @@ def color_text(color, message): def configure_logging( - console_log_level, syslog_log_level=None, log_file_log_level=None, log_file=None + console_log_level, + syslog_log_level=None, + log_file_log_level=None, + monitoring_log_level=None, + log_file=None, ): ''' Configure logging to go to both the console and (syslog or log file). Use the given log levels, @@ -122,6 +126,8 @@ def configure_logging( syslog_log_level = console_log_level if log_file_log_level is None: log_file_log_level = console_log_level + if monitoring_log_level is None: + monitoring_log_level = console_log_level # Log certain log levels to console stderr and others to stdout. This supports use cases like # grepping (non-error) output. @@ -160,5 +166,6 @@ def configure_logging( handlers = (console_handler,) logging.basicConfig( - level=min(console_log_level, syslog_log_level, log_file_log_level), handlers=handlers + level=min(console_log_level, syslog_log_level, log_file_log_level, monitoring_log_level), + handlers=handlers, ) diff --git a/docs/how-to/monitor-your-backups.md b/docs/how-to/monitor-your-backups.md index 6f6f150..c56a151 100644 --- a/docs/how-to/monitor-your-backups.md +++ b/docs/how-to/monitor-your-backups.md @@ -131,9 +131,9 @@ the `on_error` hooks run, also tacking on logs including the error itself. But the logs are only included for errors that occur when a `prune`, `create`, or `check` action is run. -Note that borgmatic sends logs to Healthchecks by applying the maximum of any -other borgmatic verbosity levels (`--verbosity`, `--syslog-verbosity`, etc.), -as there is not currently a dedicated Healthchecks verbosity setting. +You can customize the verbosity of the logs that are sent to Healthchecks with +borgmatic's `--monitoring-verbosity` flag. The `--files` and `--stats` flags +may also be of use. See `borgmatic --help` for more information. You can configure Healthchecks to notify you by a [variety of mechanisms](https://healthchecks.io/#welcome-integrations) when backups fail diff --git a/tests/unit/commands/test_borgmatic.py b/tests/unit/commands/test_borgmatic.py index ccc6375..488872f 100644 --- a/tests/unit/commands/test_borgmatic.py +++ b/tests/unit/commands/test_borgmatic.py @@ -13,7 +13,7 @@ def test_run_configuration_runs_actions_for_each_repository(): expected_results[1:] ) config = {'location': {'repositories': ['foo', 'bar']}} - arguments = {'global': flexmock()} + arguments = {'global': flexmock(monitoring_verbosity=1)} results = list(module.run_configuration('test.yaml', config, arguments)) @@ -26,7 +26,7 @@ def test_run_configuration_calls_hooks_for_prune_action(): flexmock(module.dispatch).should_receive('call_hooks').at_least().twice() flexmock(module).should_receive('run_actions').and_return([]) config = {'location': {'repositories': ['foo']}} - arguments = {'global': flexmock(dry_run=False), 'prune': flexmock()} + arguments = {'global': flexmock(monitoring_verbosity=1, dry_run=False), 'prune': flexmock()} list(module.run_configuration('test.yaml', config, arguments)) @@ -37,7 +37,7 @@ def test_run_configuration_executes_and_calls_hooks_for_create_action(): flexmock(module.dispatch).should_receive('call_hooks').at_least().twice() flexmock(module).should_receive('run_actions').and_return([]) config = {'location': {'repositories': ['foo']}} - arguments = {'global': flexmock(dry_run=False), 'create': flexmock()} + arguments = {'global': flexmock(monitoring_verbosity=1, dry_run=False), 'create': flexmock()} list(module.run_configuration('test.yaml', config, arguments)) @@ -48,7 +48,7 @@ def test_run_configuration_calls_hooks_for_check_action(): flexmock(module.dispatch).should_receive('call_hooks').at_least().twice() flexmock(module).should_receive('run_actions').and_return([]) config = {'location': {'repositories': ['foo']}} - arguments = {'global': flexmock(dry_run=False), 'check': flexmock()} + arguments = {'global': flexmock(monitoring_verbosity=1, dry_run=False), 'check': flexmock()} list(module.run_configuration('test.yaml', config, arguments)) @@ -59,7 +59,7 @@ def test_run_configuration_does_not_trigger_hooks_for_list_action(): flexmock(module.dispatch).should_receive('call_hooks').never() flexmock(module).should_receive('run_actions').and_return([]) config = {'location': {'repositories': ['foo']}} - arguments = {'global': flexmock(dry_run=False), 'list': flexmock()} + arguments = {'global': flexmock(monitoring_verbosity=1, dry_run=False), 'list': flexmock()} list(module.run_configuration('test.yaml', config, arguments)) @@ -72,7 +72,7 @@ def test_run_configuration_logs_actions_error(): 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)} + arguments = {'global': flexmock(monitoring_verbosity=1, dry_run=False)} results = list(module.run_configuration('test.yaml', config, arguments)) @@ -86,7 +86,7 @@ def test_run_configuration_logs_pre_hook_error(): 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()} + arguments = {'global': flexmock(monitoring_verbosity=1, dry_run=False), 'create': flexmock()} results = list(module.run_configuration('test.yaml', config, arguments)) @@ -103,7 +103,7 @@ def test_run_configuration_logs_post_hook_error(): 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()} + arguments = {'global': flexmock(monitoring_verbosity=1, dry_run=False), 'create': flexmock()} results = list(module.run_configuration('test.yaml', config, arguments)) @@ -119,7 +119,7 @@ def test_run_configuration_logs_on_error_hook_error(): ).and_return(expected_results[1:]) flexmock(module).should_receive('run_actions').and_raise(OSError) config = {'location': {'repositories': ['foo']}} - arguments = {'global': flexmock(dry_run=False), 'create': flexmock()} + arguments = {'global': flexmock(monitoring_verbosity=1, dry_run=False), 'create': flexmock()} results = list(module.run_configuration('test.yaml', config, arguments)) @@ -228,7 +228,7 @@ def test_collect_configuration_run_summary_logs_info_for_success(): def test_collect_configuration_run_summary_executes_hooks_for_create(): flexmock(module).should_receive('run_configuration').and_return([]) - arguments = {'create': flexmock(), 'global': flexmock(dry_run=False)} + arguments = {'create': flexmock(), 'global': flexmock(monitoring_verbosity=1, dry_run=False)} logs = tuple( module.collect_configuration_run_summary_logs({'test.yaml': {}}, arguments=arguments) @@ -305,7 +305,7 @@ def test_collect_configuration_run_summary_logs_pre_hook_error(): flexmock(module.command).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)} + arguments = {'create': flexmock(), 'global': flexmock(monitoring_verbosity=1, dry_run=False)} logs = tuple( module.collect_configuration_run_summary_logs({'test.yaml': {}}, arguments=arguments) @@ -319,7 +319,7 @@ def test_collect_configuration_run_summary_logs_post_hook_error(): 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)} + arguments = {'create': flexmock(), 'global': flexmock(monitoring_verbosity=1, dry_run=False)} logs = tuple( module.collect_configuration_run_summary_logs({'test.yaml': {}}, arguments=arguments) diff --git a/tests/unit/hooks/test_cronhub.py b/tests/unit/hooks/test_cronhub.py index 3201811..a258283 100644 --- a/tests/unit/hooks/test_cronhub.py +++ b/tests/unit/hooks/test_cronhub.py @@ -7,32 +7,42 @@ def test_ping_monitor_rewrites_ping_url_for_start_state(): ping_url = 'https://example.com/start/abcdef' flexmock(module.requests).should_receive('get').with_args('https://example.com/start/abcdef') - module.ping_monitor(ping_url, 'config.yaml', module.monitor.State.START, dry_run=False) + module.ping_monitor( + ping_url, 'config.yaml', module.monitor.State.START, monitoring_log_level=1, dry_run=False + ) def test_ping_monitor_rewrites_ping_url_and_state_for_start_state(): ping_url = 'https://example.com/ping/abcdef' flexmock(module.requests).should_receive('get').with_args('https://example.com/start/abcdef') - module.ping_monitor(ping_url, 'config.yaml', module.monitor.State.START, dry_run=False) + module.ping_monitor( + ping_url, 'config.yaml', module.monitor.State.START, monitoring_log_level=1, dry_run=False + ) def test_ping_monitor_rewrites_ping_url_for_finish_state(): ping_url = 'https://example.com/start/abcdef' flexmock(module.requests).should_receive('get').with_args('https://example.com/finish/abcdef') - module.ping_monitor(ping_url, 'config.yaml', module.monitor.State.FINISH, dry_run=False) + module.ping_monitor( + ping_url, 'config.yaml', module.monitor.State.FINISH, monitoring_log_level=1, dry_run=False + ) def test_ping_monitor_rewrites_ping_url_for_fail_state(): ping_url = 'https://example.com/start/abcdef' flexmock(module.requests).should_receive('get').with_args('https://example.com/fail/abcdef') - module.ping_monitor(ping_url, 'config.yaml', module.monitor.State.FAIL, dry_run=False) + module.ping_monitor( + ping_url, 'config.yaml', module.monitor.State.FAIL, monitoring_log_level=1, dry_run=False + ) def test_ping_monitor_dry_run_does_not_hit_ping_url(): ping_url = 'https://example.com' flexmock(module.requests).should_receive('get').never() - module.ping_monitor(ping_url, 'config.yaml', module.monitor.State.START, dry_run=True) + module.ping_monitor( + ping_url, 'config.yaml', module.monitor.State.START, monitoring_log_level=1, dry_run=True + ) diff --git a/tests/unit/hooks/test_cronitor.py b/tests/unit/hooks/test_cronitor.py index 73bcffa..e006508 100644 --- a/tests/unit/hooks/test_cronitor.py +++ b/tests/unit/hooks/test_cronitor.py @@ -7,25 +7,33 @@ def test_ping_monitor_hits_ping_url_for_start_state(): ping_url = 'https://example.com' flexmock(module.requests).should_receive('get').with_args('{}/{}'.format(ping_url, 'run')) - module.ping_monitor(ping_url, 'config.yaml', module.monitor.State.START, dry_run=False) + module.ping_monitor( + ping_url, 'config.yaml', module.monitor.State.START, monitoring_log_level=1, dry_run=False + ) def test_ping_monitor_hits_ping_url_for_finish_state(): ping_url = 'https://example.com' flexmock(module.requests).should_receive('get').with_args('{}/{}'.format(ping_url, 'complete')) - module.ping_monitor(ping_url, 'config.yaml', module.monitor.State.FINISH, dry_run=False) + module.ping_monitor( + ping_url, 'config.yaml', module.monitor.State.FINISH, monitoring_log_level=1, dry_run=False + ) def test_ping_monitor_hits_ping_url_for_fail_state(): ping_url = 'https://example.com' flexmock(module.requests).should_receive('get').with_args('{}/{}'.format(ping_url, 'fail')) - module.ping_monitor(ping_url, 'config.yaml', module.monitor.State.FAIL, dry_run=False) + module.ping_monitor( + ping_url, 'config.yaml', module.monitor.State.FAIL, monitoring_log_level=1, dry_run=False + ) def test_ping_monitor_dry_run_does_not_hit_ping_url(): ping_url = 'https://example.com' flexmock(module.requests).should_receive('get').never() - module.ping_monitor(ping_url, 'config.yaml', module.monitor.State.START, dry_run=True) + module.ping_monitor( + ping_url, 'config.yaml', module.monitor.State.START, monitoring_log_level=1, dry_run=True + ) diff --git a/tests/unit/hooks/test_healthchecks.py b/tests/unit/hooks/test_healthchecks.py index 24e8fca..7f90438 100644 --- a/tests/unit/hooks/test_healthchecks.py +++ b/tests/unit/hooks/test_healthchecks.py @@ -4,7 +4,7 @@ from borgmatic.hooks import healthchecks as module def test_forgetful_buffering_handler_emit_collects_log_records(): - handler = module.Forgetful_buffering_handler(byte_capacity=100) + handler = module.Forgetful_buffering_handler(byte_capacity=100, log_level=1) handler.emit(flexmock(getMessage=lambda: 'foo')) handler.emit(flexmock(getMessage=lambda: 'bar')) @@ -13,7 +13,7 @@ def test_forgetful_buffering_handler_emit_collects_log_records(): def test_forgetful_buffering_handler_emit_forgets_log_records_when_capacity_reached(): - handler = module.Forgetful_buffering_handler(byte_capacity=len('foo\nbar\n')) + handler = module.Forgetful_buffering_handler(byte_capacity=len('foo\nbar\n'), log_level=1) handler.emit(flexmock(getMessage=lambda: 'foo')) assert handler.buffer == ['foo\n'] handler.emit(flexmock(getMessage=lambda: 'bar')) @@ -26,7 +26,7 @@ def test_forgetful_buffering_handler_emit_forgets_log_records_when_capacity_reac def test_format_buffered_logs_for_payload_flattens_log_buffer(): - handler = module.Forgetful_buffering_handler(byte_capacity=100) + handler = module.Forgetful_buffering_handler(byte_capacity=100, log_level=1) handler.buffer = ['foo\n', 'bar\n'] flexmock(module.logging).should_receive('getLogger').and_return(flexmock(handlers=[handler])) @@ -36,7 +36,7 @@ def test_format_buffered_logs_for_payload_flattens_log_buffer(): def test_format_buffered_logs_for_payload_inserts_truncation_indicator_when_logs_forgotten(): - handler = module.Forgetful_buffering_handler(byte_capacity=100) + handler = module.Forgetful_buffering_handler(byte_capacity=100, log_level=1) handler.buffer = ['foo\n', 'bar\n'] handler.forgot = True flexmock(module.logging).should_receive('getLogger').and_return(flexmock(handlers=[handler])) @@ -63,7 +63,13 @@ def test_ping_monitor_hits_ping_url_for_start_state(): '{}/{}'.format(ping_url, 'start'), data=''.encode('utf-8') ) - module.ping_monitor(ping_url, 'config.yaml', state=module.monitor.State.START, dry_run=False) + module.ping_monitor( + ping_url, + 'config.yaml', + state=module.monitor.State.START, + monitoring_log_level=1, + dry_run=False, + ) def test_ping_monitor_hits_ping_url_for_finish_state(): @@ -74,7 +80,13 @@ def test_ping_monitor_hits_ping_url_for_finish_state(): ping_url, data=payload.encode('utf-8') ) - module.ping_monitor(ping_url, 'config.yaml', state=module.monitor.State.FINISH, dry_run=False) + module.ping_monitor( + ping_url, + 'config.yaml', + state=module.monitor.State.FINISH, + monitoring_log_level=1, + dry_run=False, + ) def test_ping_monitor_hits_ping_url_for_fail_state(): @@ -85,7 +97,13 @@ def test_ping_monitor_hits_ping_url_for_fail_state(): '{}/{}'.format(ping_url, 'fail'), data=payload.encode('utf') ) - module.ping_monitor(ping_url, 'config.yaml', state=module.monitor.State.FAIL, dry_run=False) + module.ping_monitor( + ping_url, + 'config.yaml', + state=module.monitor.State.FAIL, + monitoring_log_level=1, + dry_run=False, + ) def test_ping_monitor_with_ping_uuid_hits_corresponding_url(): @@ -96,7 +114,13 @@ def test_ping_monitor_with_ping_uuid_hits_corresponding_url(): 'https://hc-ping.com/{}'.format(ping_uuid), data=payload.encode('utf-8') ) - module.ping_monitor(ping_uuid, 'config.yaml', state=module.monitor.State.FINISH, dry_run=False) + module.ping_monitor( + ping_uuid, + 'config.yaml', + state=module.monitor.State.FINISH, + monitoring_log_level=1, + dry_run=False, + ) def test_ping_monitor_dry_run_does_not_hit_ping_url(): @@ -104,4 +128,10 @@ def test_ping_monitor_dry_run_does_not_hit_ping_url(): ping_url = 'https://example.com' flexmock(module.requests).should_receive('post').never() - module.ping_monitor(ping_url, 'config.yaml', state=module.monitor.State.START, dry_run=True) + module.ping_monitor( + ping_url, + 'config.yaml', + state=module.monitor.State.START, + monitoring_log_level=1, + dry_run=True, + )