diff --git a/borgmatic/commands/arguments.py b/borgmatic/commands/arguments.py index 1252270b..e95ec5f4 100644 --- a/borgmatic/commands/arguments.py +++ b/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', diff --git a/borgmatic/commands/borgmatic.py b/borgmatic/commands/borgmatic.py index 76f16a43..8f677191 100644 --- a/borgmatic/commands/borgmatic.py +++ b/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:]) diff --git a/borgmatic/logger.py b/borgmatic/logger.py index 4fb03a58..1fc0da52 100644 --- a/borgmatic/logger.py +++ b/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, diff --git a/tests/unit/test_logger.py b/tests/unit/test_logger.py index 5f0fae12..a1222862 100644 --- a/tests/unit/test_logger.py +++ b/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 )