From eb5c9e6bf3422aca9dda8d8ed19572cde9016726 Mon Sep 17 00:00:00 2001 From: Dan Helfman Date: Thu, 16 Jul 2026 11:58:10 -0700 Subject: [PATCH] Fix the "repo-create" action to more surgically suppress Borg "Repository does not exist" logs and avoid inadvertently suppressing other error logs (#1331). --- NEWS | 2 + borgmatic/borg/repo_create.py | 27 +++--- borgmatic/borg/repo_info.py | 1 - borgmatic/execute.py | 3 + borgmatic/logger.py | 88 +++++++++++++++++++ tests/unit/borg/test_repo_create.py | 3 + tests/unit/borg/test_repo_info.py | 6 +- tests/unit/test_execute.py | 45 ++++++++++ tests/unit/test_logger.py | 128 ++++++++++++++++++++++++++++ 9 files changed, 288 insertions(+), 15 deletions(-) diff --git a/NEWS b/NEWS index cf602361..acba5c75 100644 --- a/NEWS +++ b/NEWS @@ -10,6 +10,8 @@ with a default port. * #1324: For the MariaDB and MySQL hooks, add "events", "routines", and "tablespaces" options for disabling dumping of scheduled events, stored routines, and tablespaces, respectively. + * #1331: Fix the "repo-create" action to more surgically suppress Borg "Repository does not exist" + logs and avoid inadvertently suppressing other error logs. * #1333: Fix the "--progress" flag on the "compact" action to actually update the progress of segment compaction. * #1334: Add the "CAP_FOWNER" capability to "CapabilityBoundingSet" in the sample systemd service, diff --git a/borgmatic/borg/repo_create.py b/borgmatic/borg/repo_create.py index 0ff84a9b..4fac925d 100644 --- a/borgmatic/borg/repo_create.py +++ b/borgmatic/borg/repo_create.py @@ -5,6 +5,7 @@ import shlex import subprocess import borgmatic.config.paths +import borgmatic.logger from borgmatic.borg import environment, feature, flags, repo_info from borgmatic.execute import DO_NOT_CAPTURE, execute_command @@ -40,17 +41,21 @@ def create_repository( Raise subprocess.CalledProcessError if "borg info" returns an error exit code. ''' try: - info_data = json.loads( - repo_info.display_repository_info( - repository_path, - config, - local_borg_version, - argparse.Namespace(json=True), - global_arguments, - local_path, - remote_path, - ), - ) + # Suppress Borg's "repository does not exist" error log, so the user isn't confused by + # seeing an error during successful repository creation. + with borgmatic.logger.Logs_suppressed(msgid='Repository.DoesNotExist'): + info_data = json.loads( + repo_info.display_repository_info( + repository_path, + config, + local_borg_version, + argparse.Namespace(json=True), + global_arguments, + local_path, + remote_path, + ), + ) + repository_encryption_mode = info_data.get('encryption', {}).get('mode') if repository_encryption_mode != encryption_mode: diff --git a/borgmatic/borg/repo_info.py b/borgmatic/borg/repo_info.py index 93d3a6b2..31c21d9d 100644 --- a/borgmatic/borg/repo_info.py +++ b/borgmatic/borg/repo_info.py @@ -37,7 +37,6 @@ def display_repository_info( if feature.available(feature.Feature.REPO_INFO, local_borg_version) else ('info',) ) - + (('--critical',) if repo_info_arguments.json else ()) + ( ('--info',) if logger.getEffectiveLevel() == logging.INFO and not repo_info_arguments.json diff --git a/borgmatic/execute.py b/borgmatic/execute.py index 14f4d428..d3223053 100644 --- a/borgmatic/execute.py +++ b/borgmatic/execute.py @@ -157,6 +157,7 @@ def borg_json_log_line_to_record(line, log_level): levelno=log_level, created=log_data.get('time'), msg=log_data.get('message'), + msgid=log_data.get('msgid'), levelname=logging.getLevelName(log_level), name=log_data.get('name'), ) @@ -167,6 +168,7 @@ def borg_json_log_line_to_record(line, log_level): levelno=borg_log_level, created=log_data.get('time'), msg=log_data.get('message'), + msgid=log_data.get('msgid'), levelname=log_data.get('levelname'), name=log_data.get('name'), ) @@ -178,6 +180,7 @@ def borg_json_log_line_to_record(line, log_level): levelno=log_level, created=time.time(), msg=f'{log_data.get("status")} {log_data.get("path")}', + msgid=log_data.get('msgid'), levelname=logging.getLevelName(log_level), name='borg.file_status', ) diff --git a/borgmatic/logger.py b/borgmatic/logger.py index fad810df..5c080594 100644 --- a/borgmatic/logger.py +++ b/borgmatic/logger.py @@ -154,6 +154,8 @@ def log_record_to_json(record): ''' Given a logging.LogRecord, return it as a JSON-encoded string containing relevant attributes. ''' + message_id = getattr(record, 'msgid', None) + return json.dumps( dict( type='log_message', @@ -162,6 +164,7 @@ def log_record_to_json(record): levelname=record.levelname, name=record.name, ) + | ({'msgid': message_id} if message_id is not None else {}) ) @@ -336,6 +339,91 @@ class Log_prefix: set_log_prefix(self.original_prefix) +class Log_exclude_filter(logging.Filter): + ''' + A Python log filter that omits log records matching given attributes. + ''' + + def __init__(self, name, filter_attributes): + ''' + Given a unique name for this filter and a dict of attributes to filter on, set the filter + name and save the attributes for use below. + ''' + self.filter_attributes = filter_attributes + + super().__init__(name) + + def filter(self, log_record): + ''' + Given a log record, return False (indicating the record should be omitted) if the record's + attributes match any of the saved filter attributes. Return True (indicating do not omit) + otherwise. + ''' + for attribute_name, value in self.filter_attributes.items(): + if getattr(log_record, attribute_name, None) == value: + return False + + return True + + +def add_log_exclude_filter(name, filter_attributes): + ''' + Given a unique filter name and a dict of attributes to filter on, create a log exclude filter + with them and add the filter to each log handler. + ''' + for handler in logging.getLogger().handlers: + handler.addFilter(Log_exclude_filter(name, filter_attributes)) + + +def remove_log_exclude_filter(name): + ''' + Given a unique filter name, remove matching filters from each log handler. + ''' + for handler in logging.getLogger().handlers: + for filter in handler.filters: + if getattr(filter, 'name', None) == name: + handler.removeFilter(filter) + + +class Logs_suppressed: + ''' + A Python context manager for temporarily adding a log filter that suppresses requested log + records for the duration of the context manager. + + Example use: + + + with borgmatic.logger.Logs_suppressed(msgid='Repository.DoesNotExist'): + do_something_that_logs() + + For the scope of that "with" statement, any records logged with the given message ID are + filtered out of the log output. "msgid" is just an example; any logging.LogRecord attributes + (standard or custom) can be passed in to filter on. + + Multiple instances of this context manager with different filter attributes can be in use at + once. + ''' + + def __init__(self, **filter_attributes): + ''' + Given the desired log record filter attributes as keyword arguments, save them for use below. + ''' + self.filter_attributes = filter_attributes + + def __enter__(self): + ''' + Create a log filter with the saved filter attributes and add the filter to every logging + handler, so that they filter out the desired log records. + ''' + add_log_exclude_filter(name=str(id(self)), filter_attributes=self.filter_attributes) + + def __exit__(self, exception_type, exception, traceback): + ''' + Remove the previously added filter from every logging handler. + ''' + remove_log_exclude_filter(name=str(id(self))) + + class Delayed_logging_handler(logging.handlers.BufferingHandler): ''' A logging handler that buffers logs and doesn't flush them until explicitly flushed (after diff --git a/tests/unit/borg/test_repo_create.py b/tests/unit/borg/test_repo_create.py index 981f8561..5f21044d 100644 --- a/tests/unit/borg/test_repo_create.py +++ b/tests/unit/borg/test_repo_create.py @@ -13,12 +13,14 @@ REPO_CREATE_COMMAND = ('borg', 'repo-create', '--encryption', 'repokey') def insert_repo_info_command_found_mock(): + flexmock(module.borgmatic.logger).should_receive('Logs_suppressed').and_return(flexmock()) flexmock(module.repo_info).should_receive('display_repository_info').and_return( '{"encryption": {"mode": "repokey"}}', ) def insert_repo_info_command_not_found_mock(): + flexmock(module.borgmatic.logger).should_receive('Logs_suppressed').and_return(flexmock()) flexmock(module.repo_info).should_receive('display_repository_info').and_raise( subprocess.CalledProcessError( sorted(module.REPO_INFO_REPOSITORY_NOT_FOUND_EXIT_CODES)[0], @@ -158,6 +160,7 @@ def test_create_repository_errors_when_repository_with_differing_encryption_mode def test_create_repository_raises_for_unknown_repo_info_command_error(): + flexmock(module.borgmatic.logger).should_receive('Logs_suppressed').and_return(flexmock()) flexmock(module.repo_info).should_receive('display_repository_info').and_raise( subprocess.CalledProcessError(REPO_INFO_SOME_UNKNOWN_EXIT_CODE, []), ) diff --git a/tests/unit/borg/test_repo_info.py b/tests/unit/borg/test_repo_info.py index 628faec2..0dd74c6c 100644 --- a/tests/unit/borg/test_repo_info.py +++ b/tests/unit/borg/test_repo_info.py @@ -144,7 +144,7 @@ def test_display_repository_info_with_log_info_and_json_suppresses_most_borg_out flexmock(module.environment).should_receive('make_environment') flexmock(module.borgmatic.config.paths).should_receive('get_working_directory').and_return(None) flexmock(module).should_receive('execute_command_and_capture_output').with_args( - ('borg', 'repo-info', '--critical', '--log-json', '--json', '--repo', 'repo'), + ('borg', 'repo-info', '--log-json', '--json', '--repo', 'repo'), environment=None, working_directory=None, borg_local_path='borg', @@ -222,7 +222,7 @@ def test_display_repository_info_with_log_debug_and_json_suppresses_most_borg_ou flexmock(module.environment).should_receive('make_environment') flexmock(module.borgmatic.config.paths).should_receive('get_working_directory').and_return(None) flexmock(module).should_receive('execute_command_and_capture_output').with_args( - ('borg', 'repo-info', '--critical', '--log-json', '--json', '--repo', 'repo'), + ('borg', 'repo-info', '--log-json', '--json', '--repo', 'repo'), environment=None, working_directory=None, borg_local_path='borg', @@ -258,7 +258,7 @@ def test_display_repository_info_with_json_calls_borg_with_json_flag(): flexmock(module.environment).should_receive('make_environment') flexmock(module.borgmatic.config.paths).should_receive('get_working_directory').and_return(None) flexmock(module).should_receive('execute_command_and_capture_output').with_args( - ('borg', 'repo-info', '--critical', '--log-json', '--json', '--repo', 'repo'), + ('borg', 'repo-info', '--log-json', '--json', '--repo', 'repo'), environment=None, working_directory=None, borg_local_path='borg', diff --git a/tests/unit/test_execute.py b/tests/unit/test_execute.py index 77f9053e..8694e48d 100644 --- a/tests/unit/test_execute.py +++ b/tests/unit/test_execute.py @@ -124,6 +124,20 @@ def test_borg_json_log_line_to_record_parses_log_message_line(): assert record.levelno == module.logging.INFO assert record.created == 12345 assert record.msg == 'All done' + assert record.msgid is None + assert record.levelname == 'INFO' + assert record.name == 'borg.something' + + +def test_borg_json_log_line_to_record_parses_log_message_line_with_message_id(): + line = '{"type": "log_message", "levelname": "INFO", "time": 12345, "message": "All done", "msgid": "all.done", "name": "borg.something"}' + + record = module.borg_json_log_line_to_record(line, module.logging.INFO) + + assert record.levelno == module.logging.INFO + assert record.created == 12345 + assert record.msg == 'All done' + assert record.msgid == 'all.done' assert record.levelname == 'INFO' assert record.name == 'borg.something' @@ -136,6 +150,20 @@ def test_borg_json_log_line_to_record_elevates_log_message_info_level_to_small_j assert record.levelno == 25 assert record.created == 12345 assert record.msg == 'All done' + assert record.msgid is None + assert record.levelname in {'ANSWER', 'Level 25'} + assert record.name == 'borg.something' + + +def test_borg_json_log_line_to_record_elevates_log_message_and_includes_message_id(): + line = '{"type": "log_message", "levelname": "INFO", "time": 12345, "message": "All done", "msgid": "all.done", "name": "borg.something"}' + + record = module.borg_json_log_line_to_record(line, 25) + + assert record.levelno == 25 + assert record.created == 12345 + assert record.msg == 'All done' + assert record.msgid == 'all.done' assert record.levelname in {'ANSWER', 'Level 25'} assert record.name == 'borg.something' @@ -148,6 +176,7 @@ def test_borg_json_log_line_to_record_does_not_elevate_log_message_info_level_to assert record.levelno == module.logging.INFO assert record.created == 12345 assert record.msg == 'All done' + assert record.msgid is None assert record.levelname == 'INFO' assert record.name == 'borg.something' @@ -160,6 +189,7 @@ def test_borg_json_log_line_with_none_log_level_parses_log_message_line(): assert record.levelno == module.logging.INFO assert record.created == 12345 assert record.msg == 'All done' + assert record.msgid is None assert record.levelname == 'INFO' assert record.name == 'borg.something' @@ -173,6 +203,21 @@ def test_borg_json_log_line_to_record_parses_file_status_line(): assert record.levelno == module.logging.INFO assert record.created == 12345 assert record.msg == '- /foo/bar' + assert record.msgid is None + assert record.levelname == 'INFO' + assert record.name == 'borg.file_status' + + +def test_borg_json_log_line_to_record_parses_file_status_line_with_message_id(): + flexmock(module.time).should_receive('time').and_return(12345) + line = '{"type": "file_status", "status": "-", "path": "/foo/bar", "msgid": "hi.there"}' + + record = module.borg_json_log_line_to_record(line, module.logging.INFO) + + assert record.levelno == module.logging.INFO + assert record.created == 12345 + assert record.msg == '- /foo/bar' + assert record.msgid == 'hi.there' assert record.levelname == 'INFO' assert record.name == 'borg.file_status' diff --git a/tests/unit/test_logger.py b/tests/unit/test_logger.py index 36b6de15..88202840 100644 --- a/tests/unit/test_logger.py +++ b/tests/unit/test_logger.py @@ -243,6 +243,23 @@ def test_log_record_to_json_formats_record_as_json(): ) +def test_log_record_to_json_with_message_id_formats_record_as_json(): + assert ( + module.log_record_to_json( + flexmock( + created=12345, + levelno=module.logging.INFO, + levelname='INFO', + name='borg.something', + extra='ignored', + getMessage=lambda: 'All done', + msgid='all.done', + ) + ) + == '{"type": "log_message", "time": 12345, "message": "All done", "levelname": "INFO", "name": "borg.something", "msgid": "all.done"}' + ) + + def test_console_color_formatter_format_includes_log_message(): flexmock(module).should_receive('add_custom_log_levels') flexmock(module.logging).ANSWER = module.ANSWER @@ -417,6 +434,117 @@ def test_log_prefix_sets_prefix_and_then_restores_original_prefix_after(): pass +def test_log_exclude_filter_filter_omits_log_matching_any_attributes(): + filter = module.Log_exclude_filter('my filter', {'foo': 'bar', 'baz': 'quux'}) + + assert filter.filter(flexmock(foo='nope', baz='quux')) is False + + +def test_log_exclude_filter_filter_includes_log_matching_no_attributes(): + filter = module.Log_exclude_filter('my filter', {'foo': 'bar', 'baz': 'quux'}) + + assert filter.filter(flexmock(foo='nope', baz='uh uh')) is True + + +def test_log_exclude_filter_filter_includes_log_matching_no_attributes_and_in_fact_missing_them_entirely(): + filter = module.Log_exclude_filter('my filter', {'foo': 'bar', 'baz': 'quux'}) + + assert filter.filter(flexmock(other='nope', thing='uh uh')) is True + + +def test_add_log_exclude_filter_adds_filter_to_each_handler(): + flexmock(module).should_receive('Log_exclude_filter').and_return(flexmock()) + handlers = [flexmock(), flexmock()] + handlers[0].should_receive('addFilter').once() + handlers[1].should_receive('addFilter').once() + + flexmock(module.logging).should_receive('getLogger').and_return( + flexmock(handlers=handlers, removeHandler=lambda handler: None) + ) + + module.add_log_exclude_filter('my filter', {'foo': 'bar', 'baz': 'quux'}) + + +def test_remove_log_exclude_filter_removes_filter_from_each_handler(): + handlers = [ + flexmock( + filters=[ + flexmock(name='my filter'), + flexmock(name='my filter'), + ], + ), + flexmock( + filters=[ + flexmock(name='my filter'), + ], + ), + ] + handlers[0].should_receive('removeFilter').twice() + handlers[1].should_receive('removeFilter').once() + + flexmock(module.logging).should_receive('getLogger').and_return( + flexmock(handlers=handlers, removeHandler=lambda handler: None), + ) + + module.remove_log_exclude_filter(name='my filter') + + +def test_remove_log_exclude_filter_skips_remove_for_filter_without_matching_name(): + handlers = [ + flexmock( + filters=[ + flexmock(name='other filter'), + flexmock(name='my filter'), + ], + ), + flexmock( + filters=[ + flexmock(name='my filter'), + ], + ), + ] + handlers[0].should_receive('removeFilter').once() + handlers[1].should_receive('removeFilter').once() + + flexmock(module.logging).should_receive('getLogger').and_return( + flexmock(handlers=handlers, removeHandler=lambda handler: None), + ) + + module.remove_log_exclude_filter(name='my filter') + + +def test_remove_log_exclude_filter_skips_remove_for_filter_without_name_attribute(): + handlers = [ + flexmock( + filters=[ + flexmock(), + flexmock(name='my filter'), + ], + ), + flexmock( + filters=[ + flexmock(name='my filter'), + ], + ), + ] + handlers[0].should_receive('removeFilter').once() + handlers[1].should_receive('removeFilter').once() + + flexmock(module.logging).should_receive('getLogger').and_return( + flexmock(handlers=handlers, removeHandler=lambda handler: None), + ) + + module.remove_log_exclude_filter(name='my filter') + + +def test_logs_suppressed_adds_and_removes_log_exclude_filter(): + flexmock(module).should_receive('add_log_exclude_filter').once() + flexmock(module).should_receive('remove_log_exclude_filter').once() + + with module.Logs_suppressed(foo='bar', baz='quux'): + pass + + def test_delayed_logging_handler_should_flush_without_targets_returns_false(): handler = module.Delayed_logging_handler()