Fix the "repo-create" action to more surgically suppress Borg "Repository does not exist" logs and avoid inadvertently suppressing other error logs (#1331).

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,

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:

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

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',
                 )

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

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, []),
     )

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',

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'
 

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()