From 6f075f52fd63736e5b005d7de3498d47ffeea2fc Mon Sep 17 00:00:00 2001 From: Dan Helfman Date: Thu, 1 Jan 2026 22:24:56 -0800 Subject: [PATCH] Get unit/integration tests passing. --- borgmatic/commands/borgmatic.py | 31 +++++----- borgmatic/logger.py | 22 ++++--- tests/integration/test_logger.py | 15 +++++ tests/unit/test_logger.py | 99 +++++++++++++++++++++++++++++++- 4 files changed, 141 insertions(+), 26 deletions(-) create mode 100644 tests/integration/test_logger.py diff --git a/borgmatic/commands/borgmatic.py b/borgmatic/commands/borgmatic.py index e1725182..e1fea6de 100644 --- a/borgmatic/commands/borgmatic.py +++ b/borgmatic/commands/borgmatic.py @@ -1080,6 +1080,23 @@ def get_singular_option_value(configs, option_name): return None +def display_summary(summary_logs, log_json): # pragma: no cover + summary_logs_max_level = max(log.levelno for log in summary_logs) + + for message in ('summary:',) if log_json else ('', 'summary:'): + log_record( + levelno=summary_logs_max_level, + levelname=logging.getLevelName(summary_logs_max_level), + msg=message, + ) + + for log in summary_logs: + logger.handle(log) + + if summary_logs_max_level >= logging.CRITICAL: + exit_with_help_link() + + def main(extra_summary_logs=()): # pragma: no cover configure_signals() configure_delayed_logging() @@ -1178,17 +1195,5 @@ def main(extra_summary_logs=()): # pragma: no cover ) ) ) - summary_logs_max_level = max(log.levelno for log in summary_logs) - for message in ('summary:',) if log_json else ('', 'summary:'): - log_record( - levelno=summary_logs_max_level, - levelname=logging.getLevelName(summary_logs_max_level), - msg=message, - ) - - for log in summary_logs: - logger.handle(log) - - if summary_logs_max_level >= logging.CRITICAL: - exit_with_help_link() + display_summary(summary_logs, log_json) diff --git a/borgmatic/logger.py b/borgmatic/logger.py index 26f81a44..09414615 100644 --- a/borgmatic/logger.py +++ b/borgmatic/logger.py @@ -112,26 +112,26 @@ class JournaldHandler(logging.Handler): try: message_parts = [] entry = dict( - LOGGER_NAME=record.name, MESSAGE=record.getMessage(), PRIORITY=self.log_level_to_journald_priority.get( record.levelno, DEFAULT_JOURNALD_PRIORITY ), SYSLOG_IDENTIFIER='borgmatic', SYSLOG_PID=os.getpid(), - UNIT=record.name, ) for key, value in entry.items(): - key = key.upper().encode('utf-8') - value = str(value).encode('utf-8') + encoded_key = key.upper().encode('utf-8') + encoded_value = str(value).encode('utf-8') # Multi-line and single-line values use different formats on the wire. - if b'\n' in value: - message_parts.extend((key, b'\n')) - message_parts.extend((len(value).to_bytes(8, 'little'), value, b'\n')) + if b'\n' in encoded_value: + message_parts.extend((encoded_key, b'\n')) + message_parts.extend( + (len(encoded_value).to_bytes(8, 'little'), encoded_value, b'\n') + ) else: - message_parts.extend((key, b'=', value, b'\n')) + message_parts.extend((encoded_key, b'=', encoded_value, b'\n')) sock.sendto(b''.join(message_parts), self.journald_socket_path) finally: @@ -150,10 +150,9 @@ class Log_prefix_formatter(logging.Formatter): return super().format(record) -def log_record_to_json(record, **extra): +def log_record_to_json(record): ''' Given a logging.LogRecord, return it as a JSON-encoded string containing relevant attributes. - Add in any extra kwargs that are given. ''' return json.dumps( dict( @@ -162,7 +161,6 @@ def log_record_to_json(record, **extra): message=record.getMessage(), levelname=record.levelname, name=record.name, - **extra, ) ) @@ -171,7 +169,7 @@ class Json_formatter(logging.Formatter): def __init__(self, fmt='{message}', *args, style='{', **kwargs): super().__init__(*args, fmt=fmt, style=style, **kwargs) - def format(self, record): + def format(self, record): # noqa: PLR6301 return log_record_to_json(record) diff --git a/tests/integration/test_logger.py b/tests/integration/test_logger.py new file mode 100644 index 00000000..4aea2eb2 --- /dev/null +++ b/tests/integration/test_logger.py @@ -0,0 +1,15 @@ +from flexmock import flexmock + +import borgmatic.logger as module + + +def test_json_formatter_format_does_not_raise(): + module.Json_formatter().format( + flexmock( + created=12345, + levelno=module.logging.INFO, + levelname='INFO', + name='borg.something', + getMessage=lambda: 'All done', + ) + ) diff --git a/tests/unit/test_logger.py b/tests/unit/test_logger.py index c30d5ca6..272fe5c9 100644 --- a/tests/unit/test_logger.py +++ b/tests/unit/test_logger.py @@ -182,6 +182,67 @@ def test_multi_stream_handler_logs_to_handler_for_log_level(): multi_handler.emit(flexmock(levelno=module.logging.ERROR)) +LOGGING_ANSWER = flexmock() + + +def test_journald_handler_serializes_log_record_to_socket(): + flexmock(module).should_receive('add_custom_log_levels') + flexmock(module.logging).ANSWER = LOGGING_ANSWER + flexmock(module.os).should_receive('getpid').and_return(12345) + socket = flexmock() + socket.should_receive('sendto').with_args( + b'MESSAGE=All done\nPRIORITY=6\nSYSLOG_IDENTIFIER=borgmatic\nSYSLOG_PID=12345\n', + '/socket/path', + ).once() + socket.should_receive('close') + flexmock(module.socket).should_receive('socket').and_return(socket) + + module.JournaldHandler('/socket/path').emit( + flexmock( + levelno=module.logging.INFO, + getMessage=lambda: 'All done', + ) + ) + + +def test_journald_handler_serializes_multi_line_log_record_to_socket(): + flexmock(module).should_receive('add_custom_log_levels') + flexmock(module.logging).ANSWER = LOGGING_ANSWER + flexmock(module.os).should_receive('getpid').and_return(12345) + socket = flexmock() + socket.should_receive('sendto').with_args( + b'MESSAGE\n' + b'\x08\x00\x00\x00\x00\x00\x00\x00' # Message length, serialized. + b'All\ndone\nPRIORITY=6\nSYSLOG_IDENTIFIER=borgmatic\nSYSLOG_PID=12345\n', + '/socket/path', + ).once() + socket.should_receive('close') + flexmock(module.socket).should_receive('socket').and_return(socket) + + module.JournaldHandler('/socket/path').emit( + flexmock( + levelno=module.logging.INFO, + getMessage=lambda: 'All\ndone', + ) + ) + + +def test_log_record_to_json_formats_record_at_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', + ) + ) + == '{"type": "log_message", "time": 12345, "message": "All done", "levelname": "INFO", "name": "borg.something"}' + ) + + def test_console_color_formatter_format_includes_log_message(): flexmock(module).should_receive('add_custom_log_levels') flexmock(module.logging).ANSWER = module.ANSWER @@ -449,6 +510,7 @@ def test_configure_logging_with_syslog_log_level_probes_for_log_socket_on_linux( flexmock(module.logging).ANSWER = module.ANSWER flexmock(module.logging).DISABLED = module.DISABLED fake_formatter = flexmock() + flexmock(module).should_receive('Json_formatter').never() flexmock(module).should_receive('Console_color_formatter').and_return(fake_formatter) multi_stream_handler = flexmock(setLevel=lambda level: None, level=logging.INFO) multi_stream_handler.should_receive('setFormatter').with_args(fake_formatter).once() @@ -480,6 +542,7 @@ def test_configure_logging_with_syslog_log_level_probes_for_log_socket_on_macos( flexmock(module.logging).ANSWER = module.ANSWER flexmock(module.logging).DISABLED = module.DISABLED fake_formatter = flexmock() + flexmock(module).should_receive('Json_formatter').never() flexmock(module).should_receive('Console_color_formatter').and_return(fake_formatter) multi_stream_handler = flexmock(setLevel=lambda level: None, level=logging.INFO) multi_stream_handler.should_receive('setFormatter').with_args(fake_formatter).once() @@ -512,6 +575,7 @@ def test_configure_logging_with_syslog_log_level_probes_for_log_socket_on_freebs flexmock(module.logging).ANSWER = module.ANSWER flexmock(module.logging).DISABLED = module.DISABLED fake_formatter = flexmock() + flexmock(module).should_receive('Json_formatter').never() flexmock(module).should_receive('Console_color_formatter').and_return(fake_formatter) multi_stream_handler = flexmock(setLevel=lambda level: None, level=logging.INFO) multi_stream_handler.should_receive('setFormatter').with_args(fake_formatter).once() @@ -545,6 +609,7 @@ def test_configure_logging_with_journald_probes_for_log_socket(): flexmock(module.logging).ANSWER = module.ANSWER flexmock(module.logging).DISABLED = module.DISABLED fake_formatter = flexmock() + flexmock(module).should_receive('Json_formatter').never() flexmock(module).should_receive('Console_color_formatter').and_return(fake_formatter) multi_stream_handler = flexmock(setLevel=lambda level: None, level=logging.INFO) multi_stream_handler.should_receive('setFormatter').with_args(fake_formatter).once() @@ -572,6 +637,7 @@ def test_configure_logging_without_syslog_log_level_skips_syslog(): flexmock(module).should_receive('add_custom_log_levels') flexmock(module.logging).ANSWER = module.ANSWER fake_formatter = flexmock() + flexmock(module).should_receive('Json_formatter').never() flexmock(module).should_receive('Console_color_formatter').and_return(fake_formatter) multi_stream_handler = flexmock(setLevel=lambda level: None, level=logging.INFO) multi_stream_handler.should_receive('setFormatter').with_args(fake_formatter).once() @@ -591,6 +657,7 @@ def test_configure_logging_skips_syslog_if_not_found(): flexmock(module).should_receive('add_custom_log_levels') flexmock(module.logging).ANSWER = module.ANSWER fake_formatter = flexmock() + flexmock(module).should_receive('Json_formatter').never() flexmock(module).should_receive('Console_color_formatter').and_return(fake_formatter) multi_stream_handler = flexmock(setLevel=lambda level: None, level=logging.INFO) multi_stream_handler.should_receive('setFormatter').with_args(fake_formatter).once() @@ -610,6 +677,7 @@ def test_configure_logging_skips_log_file_if_log_file_logging_is_disabled(): flexmock(module).should_receive('add_custom_log_levels') flexmock(module.logging).DISABLED = module.DISABLED fake_formatter = flexmock() + flexmock(module).should_receive('Json_formatter').never() flexmock(module).should_receive('Console_color_formatter').and_return(fake_formatter) multi_stream_handler = flexmock(setLevel=lambda level: None, level=logging.INFO) multi_stream_handler.should_receive('setFormatter').with_args(fake_formatter).once() @@ -635,6 +703,7 @@ def test_configure_logging_to_log_file_instead_of_syslog(): flexmock(module).should_receive('add_custom_log_levels') flexmock(module.logging).ANSWER = module.ANSWER fake_formatter = flexmock() + flexmock(module).should_receive('Json_formatter').never() flexmock(module).should_receive('Console_color_formatter').and_return(fake_formatter) multi_stream_handler = flexmock(setLevel=lambda level: None, level=logging.INFO) multi_stream_handler.should_receive('setFormatter').with_args(fake_formatter).once() @@ -664,6 +733,7 @@ def test_configure_logging_to_both_log_file_and_syslog(): flexmock(module).should_receive('add_custom_log_levels') flexmock(module.logging).ANSWER = module.ANSWER fake_formatter = flexmock() + flexmock(module).should_receive('Json_formatter').never() flexmock(module).should_receive('Console_color_formatter').and_return(fake_formatter) multi_stream_handler = flexmock(setLevel=lambda level: None, level=logging.INFO) multi_stream_handler.should_receive('setFormatter').with_args(fake_formatter).once() @@ -702,6 +772,7 @@ def test_configure_logging_to_log_file_formats_with_custom_log_format(): '{message}', ).once() fake_formatter = flexmock() + flexmock(module).should_receive('Json_formatter').never() flexmock(module).should_receive('Console_color_formatter').and_return(fake_formatter) multi_stream_handler = flexmock(setLevel=lambda level: None, level=logging.INFO) multi_stream_handler.should_receive('setFormatter').with_args(fake_formatter).once() @@ -732,6 +803,7 @@ def test_configure_logging_skips_log_file_if_argument_is_none(): flexmock(module).should_receive('add_custom_log_levels') flexmock(module.logging).ANSWER = module.ANSWER fake_formatter = flexmock() + flexmock(module).should_receive('Json_formatter').never() flexmock(module).should_receive('Console_color_formatter').and_return(fake_formatter) multi_stream_handler = flexmock(setLevel=lambda level: None, level=logging.INFO) multi_stream_handler.should_receive('setFormatter').with_args(fake_formatter).once() @@ -748,10 +820,11 @@ def test_configure_logging_skips_log_file_if_argument_is_none(): module.configure_logging(console_log_level=logging.INFO, log_file=None) -def test_configure_logging_uses_console_no_color_formatter_if_color_disabled(): +def test_configure_logging_with_color_disabled_uses_console_no_color_formatter(): flexmock(module).should_receive('add_custom_log_levels') flexmock(module.logging).ANSWER = module.ANSWER fake_formatter = flexmock() + flexmock(module).should_receive('Json_formatter').never() flexmock(module).should_receive('Console_color_formatter').never() flexmock(module).should_receive('Log_prefix_formatter').and_return(fake_formatter) multi_stream_handler = flexmock(setLevel=lambda level: None, level=logging.INFO) @@ -767,3 +840,27 @@ def test_configure_logging_uses_console_no_color_formatter_if_color_disabled(): flexmock(module.logging.handlers).should_receive('WatchedFileHandler').never() module.configure_logging(console_log_level=logging.INFO, log_file=None, color_enabled=False) + + +def test_configure_logging_with_log_json_uses_json_formatter(): + flexmock(module).should_receive('add_custom_log_levels') + flexmock(module.logging).ANSWER = module.ANSWER + fake_formatter = flexmock() + flexmock(module).should_receive('Json_formatter').and_return(fake_formatter).once() + flexmock(module).should_receive('Console_color_formatter').never() + flexmock(module).should_receive('Log_prefix_formatter').never() + 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, + ) + flexmock(module.os.path).should_receive('exists').and_return(False) + flexmock(module.logging.handlers).should_receive('WatchedFileHandler').never() + + module.configure_logging( + console_log_level=logging.INFO, log_file=None, log_json=True, color_enabled=False + )