Get unit/integration tests passing.

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)

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)
 
 

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

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