Add a delayed logging handler that delays anything logged before logging is actually configured.

borgmatic/commands/arguments.py

@@ -349,12 +349,12 @@ def make_parsers():
     global_group.add_argument(
         '--log-file-format',
         type=str,
-        help='Log format string used for log messages written to the log file',
+        help='Python format string used for log messages written to the log file',
     )
     global_group.add_argument(
         '--log-json',
         action='store_true',
-        help='Write log messages and console output as one JSON object per log line instead of formatted text',
+        help='Write Borg log messages and console output as one JSON object per log line instead of formatted text',
     )
     global_group.add_argument(
         '--override',

borgmatic/commands/borgmatic.py

@@ -43,6 +43,7 @@ from borgmatic.logger import (
     DISABLED,
     Log_prefix,
     add_custom_log_levels,
+    configure_delayed_logging,
     configure_logging,
     should_do_markup,
 )
@@ -880,6 +881,7 @@ def exit_with_help_link():  # pragma: no cover
 
 def main(extra_summary_logs=[]):  # pragma: no cover
     configure_signals()
+    configure_delayed_logging()
 
     try:
         arguments = parse_arguments(*sys.argv[1:])

borgmatic/logger.py

@@ -263,6 +263,62 @@ class Log_prefix:
         set_log_prefix(self.original_prefix)
 
 
+class Delayed_logging_handler(logging.handlers.BufferingHandler):
+    '''
+    A logging handler that buffers logs and doesn't flush them until explicitly flushed (after
+    target handlers are actually set). It's useful for holding onto messages logged before logging
+    is configured, ensuring those records eventually make their way to the relevant logging
+    handlers.
+    '''
+
+    def __init__(self):
+        super(Delayed_logging_handler, self).__init__(capacity=0)
+
+        self.targets = None
+
+    def shouldFlush(self, record):
+        return self.targets is not None
+
+    def flush(self):
+        self.acquire()
+
+        try:
+            if not self.targets:
+                return
+
+            for record in self.buffer:
+                for target in self.targets:
+                    target.handle(record)
+
+            self.buffer.clear()
+        finally:
+            self.release()
+
+
+def configure_delayed_logging():  # pragma: no cover
+    '''
+    Configure a delayed logging handler to buffer anything that gets logged until we're ready to
+    deal with it.
+    '''
+    logging.basicConfig(
+        level=logging.DEBUG,
+        handlers=[Delayed_logging_handler()],
+    )
+
+
+def flush_delayed_logging(target_handlers):
+    '''
+    Flush any previously buffered logs to our "real" logging handlers.
+    '''
+    root_logger = logging.getLogger()
+
+    if root_logger.handlers and isinstance(root_logger.handlers[0], Delayed_logging_handler):
+        delayed_handler = root_logger.handlers[0]
+        delayed_handler.targets = target_handlers
+        delayed_handler.flush()
+        root_logger.removeHandler(delayed_handler)
+
+
 def configure_logging(
     console_log_level,
     syslog_log_level=None,
@@ -310,7 +366,6 @@ def configure_logging(
         console_handler.setFormatter(Log_prefix_formatter())
 
     console_handler.setLevel(console_log_level)
-
     handlers = [console_handler]
 
     if syslog_log_level != logging.DISABLED:
@@ -343,6 +398,8 @@ def configure_logging(
         file_handler.setLevel(log_file_log_level)
         handlers.append(file_handler)
 
+    flush_delayed_logging(handlers)
+
     logging.basicConfig(
         level=min(handler.level for handler in handlers),
         handlers=handlers,

tests/unit/test_logger.py

@@ -348,6 +348,78 @@ def test_log_prefix_sets_prefix_and_then_restores_original_prefix_after():
         pass
 
 
+def test_delayed_logging_handler_should_flush_without_targets_returns_false():
+    handler = module.Delayed_logging_handler()
+
+    assert handler.shouldFlush(flexmock()) is False
+
+
+def test_delayed_logging_handler_should_flush_with_targets_returns_true():
+    handler = module.Delayed_logging_handler()
+    handler.targets = [flexmock()]
+
+    assert handler.shouldFlush(flexmock()) is True
+
+
+def test_delayed_logging_handler_flush_without_targets_does_not_raise():
+    handler = module.Delayed_logging_handler()
+    flexmock(handler).should_receive('acquire')
+    flexmock(handler).should_receive('release')
+
+    handler.flush()
+
+
+def test_delayed_logging_handler_flush_with_empty_buffer_does_not_raise():
+    handler = module.Delayed_logging_handler()
+    flexmock(handler).should_receive('acquire')
+    flexmock(handler).should_receive('release')
+    handler.targets = [flexmock()]
+
+    handler.flush()
+
+
+def test_delayed_logging_handler_flush_forwards_each_record_to_each_target():
+    handler = module.Delayed_logging_handler()
+    flexmock(handler).should_receive('acquire')
+    flexmock(handler).should_receive('release')
+    handler.targets = [flexmock(), flexmock()]
+    handler.buffer = [flexmock(), flexmock()]
+    handler.targets[0].should_receive('handle').with_args(handler.buffer[0]).once()
+    handler.targets[1].should_receive('handle').with_args(handler.buffer[0]).once()
+    handler.targets[0].should_receive('handle').with_args(handler.buffer[1]).once()
+    handler.targets[1].should_receive('handle').with_args(handler.buffer[1]).once()
+
+    handler.flush()
+
+    assert handler.buffer == []
+
+
+def test_flush_delayed_logging_without_handlers_does_not_raise():
+    root_logger = flexmock(handlers=[])
+    root_logger.should_receive('removeHandler')
+    flexmock(module.logging).should_receive('getLogger').and_return(root_logger)
+
+    module.flush_delayed_logging([flexmock()])
+
+
+def test_flush_delayed_logging_without_delayed_logging_handler_does_not_raise():
+    root_logger = flexmock(handlers=[flexmock()])
+    root_logger.should_receive('removeHandler')
+    flexmock(module.logging).should_receive('getLogger').and_return(root_logger)
+
+    module.flush_delayed_logging([flexmock()])
+
+
+def test_flush_delayed_logging_flushes_delayed_logging_handler():
+    delayed_logging_handler = module.Delayed_logging_handler()
+    root_logger = flexmock(handlers=[delayed_logging_handler])
+    flexmock(module.logging).should_receive('getLogger').and_return(root_logger)
+    flexmock(delayed_logging_handler).should_receive('flush').once()
+    root_logger.should_receive('removeHandler')
+
+    module.flush_delayed_logging([flexmock()])
+
+
 def test_configure_logging_with_syslog_log_level_probes_for_log_socket_on_linux():
     flexmock(module).should_receive('add_custom_log_levels')
     flexmock(module.logging).ANSWER = module.ANSWER
@@ -357,6 +429,7 @@ def test_configure_logging_with_syslog_log_level_probes_for_log_socket_on_linux(
     multi_stream_handler.should_receive('setFormatter').with_args(fake_formatter).once()
     flexmock(module).should_receive('Multi_stream_handler').and_return(multi_stream_handler)
     flexmock(module).should_receive('interactive_console').and_return(False)
+    flexmock(module).should_receive('flush_delayed_logging')
     flexmock(module.logging).should_receive('basicConfig').with_args(
         level=logging.DEBUG, handlers=list
     )
@@ -378,6 +451,7 @@ def test_configure_logging_with_syslog_log_level_probes_for_log_socket_on_macos(
     multi_stream_handler.should_receive('setFormatter').with_args(fake_formatter).once()
     flexmock(module).should_receive('Multi_stream_handler').and_return(multi_stream_handler)
     flexmock(module).should_receive('interactive_console').and_return(False)
+    flexmock(module).should_receive('flush_delayed_logging')
     flexmock(module.logging).should_receive('basicConfig').with_args(
         level=logging.DEBUG, handlers=list
     )
@@ -400,6 +474,7 @@ def test_configure_logging_with_syslog_log_level_probes_for_log_socket_on_freebs
     multi_stream_handler.should_receive('setFormatter').with_args(fake_formatter).once()
     flexmock(module).should_receive('Multi_stream_handler').and_return(multi_stream_handler)
     flexmock(module).should_receive('interactive_console').and_return(False)
+    flexmock(module).should_receive('flush_delayed_logging')
     flexmock(module.logging).should_receive('basicConfig').with_args(
         level=logging.DEBUG, handlers=list
     )
@@ -422,6 +497,7 @@ def test_configure_logging_without_syslog_log_level_skips_syslog():
     multi_stream_handler = flexmock(setLevel=lambda level: None, level=logging.INFO)
     multi_stream_handler.should_receive('setFormatter').with_args(fake_formatter).once()
     flexmock(module).should_receive('Multi_stream_handler').and_return(multi_stream_handler)
+    flexmock(module).should_receive('flush_delayed_logging')
     flexmock(module.logging).should_receive('basicConfig').with_args(
         level=logging.INFO, handlers=list
     )
@@ -439,6 +515,7 @@ def test_configure_logging_skips_syslog_if_not_found():
     multi_stream_handler = flexmock(setLevel=lambda level: None, level=logging.INFO)
     multi_stream_handler.should_receive('setFormatter').with_args(fake_formatter).once()
     flexmock(module).should_receive('Multi_stream_handler').and_return(multi_stream_handler)
+    flexmock(module).should_receive('flush_delayed_logging')
     flexmock(module.logging).should_receive('basicConfig').with_args(
         level=logging.INFO, handlers=list
     )
@@ -457,6 +534,7 @@ def test_configure_logging_skips_log_file_if_log_file_logging_is_disabled():
     multi_stream_handler.should_receive('setFormatter').with_args(fake_formatter).once()
     flexmock(module).should_receive('Multi_stream_handler').and_return(multi_stream_handler)
 
+    flexmock(module).should_receive('flush_delayed_logging')
     flexmock(module.logging).should_receive('basicConfig').with_args(
         level=logging.INFO, handlers=list
     )
@@ -478,6 +556,7 @@ def test_configure_logging_to_log_file_instead_of_syslog():
     multi_stream_handler.should_receive('setFormatter').with_args(fake_formatter).once()
     flexmock(module).should_receive('Multi_stream_handler').and_return(multi_stream_handler)
 
+    flexmock(module).should_receive('flush_delayed_logging')
     flexmock(module.logging).should_receive('basicConfig').with_args(
         level=logging.DEBUG, handlers=list
     )
@@ -505,6 +584,7 @@ def test_configure_logging_to_both_log_file_and_syslog():
     multi_stream_handler.should_receive('setFormatter').with_args(fake_formatter).once()
     flexmock(module).should_receive('Multi_stream_handler').and_return(multi_stream_handler)
 
+    flexmock(module).should_receive('flush_delayed_logging')
     flexmock(module.logging).should_receive('basicConfig').with_args(
         level=logging.DEBUG, handlers=list
     )
@@ -539,6 +619,7 @@ def test_configure_logging_to_log_file_formats_with_custom_log_format():
     flexmock(module).should_receive('Multi_stream_handler').and_return(multi_stream_handler)
 
     flexmock(module).should_receive('interactive_console').and_return(False)
+    flexmock(module).should_receive('flush_delayed_logging')
     flexmock(module.logging).should_receive('basicConfig').with_args(
         level=logging.DEBUG, handlers=list
     )
@@ -566,6 +647,7 @@ def test_configure_logging_skips_log_file_if_argument_is_none():
     multi_stream_handler.should_receive('setFormatter').with_args(fake_formatter).once()
     flexmock(module).should_receive('Multi_stream_handler').and_return(multi_stream_handler)
 
+    flexmock(module).should_receive('flush_delayed_logging')
     flexmock(module.logging).should_receive('basicConfig').with_args(
         level=logging.INFO, handlers=list
     )
@@ -585,6 +667,7 @@ def test_configure_logging_uses_console_no_color_formatter_if_color_disabled():
     multi_stream_handler.should_receive('setFormatter').with_args(fake_formatter).once()
     flexmock(module).should_receive('Multi_stream_handler').and_return(multi_stream_handler)
 
+    flexmock(module).should_receive('flush_delayed_logging')
     flexmock(module.logging).should_receive('basicConfig').with_args(
         level=logging.INFO, handlers=list
     )