Initial work on putting logging and verbosity options into configuration.

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/config/schema.yaml

@@ -751,12 +751,112 @@ properties:
             Restrict the number of checked archives to the last n. Applies only
             to the "archives" check. Defaults to checking all archives.
         example: 3
-    color:
-        type: boolean
+    logging:
+        type: object
+        additionalProperties: false
+        properties:
+            console:
+                type: object
+                additionalProperties: false
+                properties:
+                    verbosity:
+                        type: integer
+                        enum:
+                            - -2
+                            - -1
+                            - 0
+                            - 1
+                            - 2
+                        description: |
+                            Display verbose progress to the console: -2
+                            (disabled), -1 (errors only), 0 (responses to
+                            actions, the default), 1 (info about steps borgmatic
+                            is taking), or 2 (debug).
+                        example: 2
+                    color:
+                        type: boolean
+                        description: |
+                            Apply color to console output. Can be overridden with --no-color
+                            command-line flag. Defaults to true.
+                        example: false
+            syslog:
+                type: object
+                additionalProperties: false
+                properties:
+                    verbosity:
+                        type: integer
+                        enum:
+                            - -2
+                            - -1
+                            - 0
+                            - 1
+                            - 2
+                        description: |
+                            Log verbose progress to syslog: -2 (disabled, the
+                            default), -1 (errors only), 0 (responses to
+                            actions), 1 (info about steps borgmatic is taking),
+                            or 2 (debug).
+                        example: 2
+            file:
+                type: object
+                required: ['path']
+                additionalProperties: false
+                properties:
+                    verbosity:
+                        type: integer
+                        enum:
+                            - -2
+                            - -1
+                            - 0
+                            - 1
+                            - 2
+                        description: |
+                            Log verbose progress to file: -2 (disabled), -1
+                            (errors only), 0 (responses to actions), 1 (info
+                            about steps borgmatic is taking, the default), or 2
+                            (debug).
+                        example: 2
+                    path:
+                        type: string
+                        description: |
+                            Write log messages to this file instead of syslog.
+                        example: /var/log/borgmatic/logfile.txt
+                    format:
+                        type: string
+                        description: |
+                            Python format string used for log messages written
+                            to the log file.
+                        example: "%(asctime)s %(message)s"
+                            
+            monitoring:
+                type: object
+                additionalProperties: false
+                properties:
+                    verbosity:
+                        type: integer
+                        enum:
+                            - -2
+                            - -1
+                            - 0
+                            - 1
+                            - 2
+                        description: |
+                            When a monitoring integration supporting logging is
+                            configured, log verbose progress to it: -2
+                            (disabled), -1 (errors only), responses to actions
+                            (0), 1 (info about steps borgmatic is taking, the
+                            default), or 2 (debug).
+                        example: 2
+            json:
+                type: boolean
+                description: |
+                    Write Borg log messages and console output as one JSON
+                    object per log line instead of formatted text. Defaults to
+                    false.
+                example: true
         description: |
-            Apply color to console output. Can be overridden with --no-color
-            command-line flag. Defaults to true.
-        example: false
+            Settings for where to log borgmatic progress and how verbose those
+            logs should be.
     skip_actions:
         type: array
         items:

borgmatic/logger.py

@@ -252,6 +252,61 @@ 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 logged records from before logging is
+    configured to ensure 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,
@@ -299,7 +354,6 @@ def configure_logging(
         console_handler.setFormatter(Console_no_color_formatter())
 
     console_handler.setLevel(console_log_level)
-
     handlers = [console_handler]
 
     if syslog_log_level != logging.DISABLED:
@@ -336,6 +390,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

@@ -360,6 +360,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
@@ -369,6 +441,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
     )
@@ -390,6 +463,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
     )
@@ -412,6 +486,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
     )
@@ -434,6 +509,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
     )
@@ -451,6 +527,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
     )
@@ -469,6 +546,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
     )
@@ -490,6 +568,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
     )
@@ -517,6 +596,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
     )
@@ -553,6 +633,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
     )
@@ -580,6 +661,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
     )
@@ -599,6 +681,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
     )