Fix the log message code to avoid using Python 3.10+ logging features (#989).

NEWS

@@ -2,6 +2,8 @@
  * #987: Fix a "list" action error when the "encryption_passcommand" option is set.
  * #987: When both "encryption_passcommand" and "encryption_passphrase" are configured, prefer
    "encryption_passphrase" even if it's an empty value.
+ * #989: Fix the log message code to avoid using Python 3.10+ logging features. Now borgmatic will
+   work with Python 3.9 again.
 
 1.9.9
  * #635: Log the repository path or label on every relevant log message, not just some logs.

borgmatic/logger.py

@@ -87,11 +87,16 @@ class Multi_stream_handler(logging.Handler):
             handler.setLevel(level)
 
 
-class Console_no_color_formatter(logging.Formatter):
-    def __init__(self, *args, **kwargs):  # pragma: no cover
-        super(Console_no_color_formatter, self).__init__(
-            '{prefix}{message}', style='{', defaults={'prefix': ''}, *args, **kwargs
-        )
+class Log_prefix_formatter(logging.Formatter):
+    def __init__(self, fmt='{prefix}{message}', style='{', *args, **kwargs):  # pragma: no cover
+        self.prefix = None
+
+        super(Log_prefix_formatter, self).__init__(fmt=fmt, style=style, *args, **kwargs)
+
+    def format(self, record):  # pragma: no cover
+        record.prefix = f'{self.prefix}: ' if self.prefix else ''
+
+        return super(Log_prefix_formatter, self).format(record)
 
 
 class Color(enum.Enum):
@@ -105,8 +110,9 @@ class Color(enum.Enum):
 
 class Console_color_formatter(logging.Formatter):
     def __init__(self, *args, **kwargs):
+        self.prefix = None
         super(Console_color_formatter, self).__init__(
-            '{prefix}{message}', style='{', defaults={'prefix': ''}, *args, **kwargs
+            '{prefix}{message}', style='{', *args, **kwargs
         )
 
     def format(self, record):
@@ -124,6 +130,7 @@ class Console_color_formatter(logging.Formatter):
             .get(record.levelno)
             .value
         )
+        record.prefix = f'{self.prefix}: ' if self.prefix else ''
 
         return color_text(color, super(Console_color_formatter, self).format(record))
 
@@ -188,28 +195,32 @@ def add_custom_log_levels():  # pragma: no cover
 
 def get_log_prefix():
     '''
-    Return the current log prefix from the defaults for the formatter on the first logging handler,
-    set by set_log_prefix(). Return None if no such prefix exists.
+    Return the current log prefix set by set_log_prefix(). Return None if no such prefix exists.
+
+    It would be a whole lot easier to use logger.Formatter(defaults=...) instead, but that argument
+    doesn't exist until Python 3.10+.
     '''
     try:
-        return next(
-            handler.formatter._style._defaults.get('prefix').rstrip().rstrip(':')
+        formatter = next(
+            handler.formatter
             for handler in logging.getLogger().handlers
+            if handler.formatter
+            if hasattr(handler.formatter, 'prefix')
         )
-    except (StopIteration, AttributeError):
+    except StopIteration:
         return None
 
+    return formatter.prefix
+
 
 def set_log_prefix(prefix):
     '''
-    Given a log prefix as a string, set it into the defaults for the formatters on all logging
-    handlers. Note that this overwrites any existing defaults.
+    Given a log prefix as a string, set it into the each handler's formatter so that it can inject
+    the prefix into each logged record.
     '''
     for handler in logging.getLogger().handlers:
-        try:
-            handler.formatter._style._defaults = {'prefix': f'{prefix}: ' if prefix else ''}
-        except AttributeError:
-            pass
+        if handler.formatter and hasattr(handler.formatter, 'prefix'):
+            handler.formatter.prefix = prefix
 
 
 class Log_prefix:
@@ -296,7 +307,7 @@ def configure_logging(
     if color_enabled:
         console_handler.setFormatter(Console_color_formatter())
     else:
-        console_handler.setFormatter(Console_no_color_formatter())
+        console_handler.setFormatter(Log_prefix_formatter())
 
     console_handler.setLevel(console_log_level)
 
@@ -315,10 +326,8 @@ def configure_logging(
         if syslog_path:
             syslog_handler = logging.handlers.SysLogHandler(address=syslog_path)
             syslog_handler.setFormatter(
-                logging.Formatter(
+                Log_prefix_formatter(
                     'borgmatic: {levelname} {prefix}{message}',  # noqa: FS003
-                    style='{',
-                    defaults={'prefix': ''},
                 )
             )
             syslog_handler.setLevel(syslog_log_level)
@@ -327,10 +336,8 @@ def configure_logging(
     if log_file and log_file_log_level != logging.DISABLED:
         file_handler = logging.handlers.WatchedFileHandler(log_file)
         file_handler.setFormatter(
-            logging.Formatter(
+            Log_prefix_formatter(
                 log_file_format or '[{asctime}] {levelname}: {prefix}{message}',  # noqa: FS003
-                style='{',
-                defaults={'prefix': ''},
             )
         )
         file_handler.setLevel(log_file_log_level)

tests/unit/test_logger.py

@@ -228,16 +228,12 @@ def test_add_logging_level_skips_global_setting_if_already_set():
     module.add_logging_level('PLAID', 99)
 
 
-def test_get_log_prefix_gets_prefix_from_first_handler():
+def test_get_log_prefix_gets_prefix_from_first_handler_formatter_with_prefix():
     flexmock(module.logging).should_receive('getLogger').and_return(
         flexmock(
             handlers=[
-                flexmock(
-                    formatter=flexmock(
-                        _style=flexmock(_defaults=flexmock(get=lambda name: 'myprefix: '))
-                    )
-                ),
-                flexmock(),
+                flexmock(formatter=flexmock()),
+                flexmock(formatter=flexmock(prefix='myprefix')),
             ],
             removeHandler=lambda handler: None,
         )
@@ -261,8 +257,8 @@ def test_get_log_prefix_with_no_formatters_does_not_raise():
     flexmock(module.logging).should_receive('getLogger').and_return(
         flexmock(
             handlers=[
-                flexmock(),
-                flexmock(),
+                flexmock(formatter=None),
+                flexmock(formatter=None),
             ],
             removeHandler=lambda handler: None,
         )
@@ -276,9 +272,8 @@ def test_get_log_prefix_with_no_prefix_does_not_raise():
         flexmock(
             handlers=[
                 flexmock(
-                    formatter=flexmock(_style=flexmock(_defaults=flexmock(get=lambda name: None)))
+                    formatter=flexmock(),
                 ),
-                flexmock(),
             ],
             removeHandler=lambda handler: None,
         )
@@ -287,24 +282,20 @@ def test_get_log_prefix_with_no_prefix_does_not_raise():
     assert module.get_log_prefix() is None
 
 
-def test_set_log_prefix_updates_all_handlers():
-    styles = (
-        flexmock(_defaults=None),
-        flexmock(_defaults=None),
+def test_set_log_prefix_updates_all_handler_formatters():
+    formatters = (
+        flexmock(prefix=None),
+        flexmock(prefix=None),
     )
 
     flexmock(module.logging).should_receive('getLogger').and_return(
         flexmock(
             handlers=[
                 flexmock(
-                    formatter=flexmock(
-                        _style=styles[0],
-                    )
+                    formatter=formatters[0],
                 ),
                 flexmock(
-                    formatter=flexmock(
-                        _style=styles[1],
-                    )
+                    formatter=formatters[1],
                 ),
             ],
             removeHandler=lambda handler: None,
@@ -313,12 +304,12 @@ def test_set_log_prefix_updates_all_handlers():
 
     module.set_log_prefix('myprefix')
 
-    for style in styles:
-        assert style._defaults == {'prefix': 'myprefix: '}
+    for formatter in formatters:
+        assert formatter.prefix == 'myprefix'
 
 
 def test_set_log_prefix_skips_handlers_without_a_formatter():
-    style = flexmock(_defaults=None)
+    formatter = flexmock(prefix=None)
 
     flexmock(module.logging).should_receive('getLogger').and_return(
         flexmock(
@@ -326,11 +317,8 @@ def test_set_log_prefix_skips_handlers_without_a_formatter():
                 flexmock(
                     formatter=None,
                 ),
-                flexmock(),
                 flexmock(
-                    formatter=flexmock(
-                        _style=style,
-                    )
+                    formatter=formatter,
                 ),
             ],
             removeHandler=lambda handler: None,
@@ -339,7 +327,7 @@ def test_set_log_prefix_skips_handlers_without_a_formatter():
 
     module.set_log_prefix('myprefix')
 
-    assert style._defaults == {'prefix': 'myprefix: '}
+    assert formatter.prefix == 'myprefix'
 
 
 def test_log_prefix_sets_prefix_and_then_restores_no_prefix_after():
@@ -541,10 +529,8 @@ def test_configure_logging_to_both_log_file_and_syslog():
 def test_configure_logging_to_log_file_formats_with_custom_log_format():
     flexmock(module).should_receive('add_custom_log_levels')
     flexmock(module.logging).ANSWER = module.ANSWER
-    flexmock(module.logging).should_receive('Formatter').with_args(
+    flexmock(module).should_receive('Log_prefix_formatter').with_args(
         '{message}',  # noqa: FS003
-        style='{',
-        defaults={'prefix': ''},
     ).once()
     fake_formatter = flexmock()
     flexmock(module).should_receive('Console_color_formatter').and_return(fake_formatter)
@@ -594,7 +580,7 @@ def test_configure_logging_uses_console_no_color_formatter_if_color_disabled():
     flexmock(module.logging).ANSWER = module.ANSWER
     fake_formatter = flexmock()
     flexmock(module).should_receive('Console_color_formatter').never()
-    flexmock(module).should_receive('Console_no_color_formatter').and_return(fake_formatter)
+    flexmock(module).should_receive('Log_prefix_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()
     flexmock(module).should_receive('Multi_stream_handler').and_return(multi_stream_handler)