Merge branch 'master' into end-to-end-database-tests

NEWS

@@ -1,6 +1,9 @@
 1.4.19
  * #259: Optionally change the internal database dump path via "borgmatic_source_directory" option
    in location configuration section.
+ * #271: Support piping "borgmatic list" output to grep by logging certain log levels to console
+   stdout and others to stderr.
+ * Retain colored output when piping or redirecting output in an interactive terminal.
  * Add end-to-end tests for database dump and restore.
 
 1.4.18

borgmatic/logger.py

@@ -26,7 +26,7 @@ def interactive_console():
     Return whether the current console is "interactive". Meaning: Capable of
     user input and not just something like a cron job.
     '''
-    return sys.stdout.isatty() and os.environ.get('TERM') != 'dumb'
+    return sys.stderr.isatty() and os.environ.get('TERM') != 'dumb'
 
 
 def should_do_markup(no_color, configs):
@@ -48,6 +48,42 @@ def should_do_markup(no_color, configs):
     return interactive_console()
 
 
+class Multi_stream_handler(logging.Handler):
+    '''
+    A logging handler that dispatches each log record to one of multiple stream handlers depending
+    on the record's log level.
+    '''
+
+    def __init__(self, log_level_to_stream_handler):
+        super(Multi_stream_handler, self).__init__()
+        self.log_level_to_handler = log_level_to_stream_handler
+        self.handlers = set(self.log_level_to_handler.values())
+
+    def flush(self):  # pragma: no cover
+        super(Multi_stream_handler, self).flush()
+
+        for handler in self.handlers:
+            handler.flush()
+
+    def emit(self, record):
+        '''
+        Dispatch the log record to the approriate stream handler for the record's log level.
+        '''
+        self.log_level_to_handler[record.levelno].emit(record)
+
+    def setFormatter(self, formatter):  # pragma: no cover
+        super(Multi_stream_handler, self).setFormatter(formatter)
+
+        for handler in self.handlers:
+            handler.setFormatter(formatter)
+
+    def setLevel(self, level):  # pragma: no cover
+        super(Multi_stream_handler, self).setLevel(level)
+
+        for handler in self.handlers:
+            handler.setLevel(level)
+
+
 LOG_LEVEL_TO_COLOR = {
     logging.CRITICAL: colorama.Fore.RED,
     logging.ERROR: colorama.Fore.RED,
@@ -87,7 +123,19 @@ def configure_logging(
     if log_file_log_level is None:
         log_file_log_level = console_log_level
 
-    console_handler = logging.StreamHandler()
+    # Log certain log levels to console stderr and others to stdout. This supports use cases like
+    # grepping (non-error) output.
+    console_error_handler = logging.StreamHandler(sys.stderr)
+    console_standard_handler = logging.StreamHandler(sys.stdout)
+    console_handler = Multi_stream_handler(
+        {
+            logging.CRITICAL: console_error_handler,
+            logging.ERROR: console_error_handler,
+            logging.WARN: console_standard_handler,
+            logging.INFO: console_standard_handler,
+            logging.DEBUG: console_standard_handler,
+        }
+    )
     console_handler.setFormatter(Console_color_formatter())
     console_handler.setLevel(console_log_level)
 

tests/unit/test_logger.py

@@ -22,14 +22,14 @@ def test_to_bool_passes_none_through():
 
 def test_interactive_console_false_when_not_isatty(capsys):
     with capsys.disabled():
-        flexmock(module.sys.stdout).should_receive('isatty').and_return(False)
+        flexmock(module.sys.stderr).should_receive('isatty').and_return(False)
 
         assert module.interactive_console() is False
 
 
 def test_interactive_console_false_when_TERM_is_dumb(capsys):
     with capsys.disabled():
-        flexmock(module.sys.stdout).should_receive('isatty').and_return(True)
+        flexmock(module.sys.stderr).should_receive('isatty').and_return(True)
         flexmock(module.os.environ).should_receive('get').with_args('TERM').and_return('dumb')
 
         assert module.interactive_console() is False
@@ -37,7 +37,7 @@ def test_interactive_console_false_when_TERM_is_dumb(capsys):
 
 def test_interactive_console_true_when_isatty_and_TERM_is_not_dumb(capsys):
     with capsys.disabled():
-        flexmock(module.sys.stdout).should_receive('isatty').and_return(True)
+        flexmock(module.sys.stderr).should_receive('isatty').and_return(True)
         flexmock(module.os.environ).should_receive('get').with_args('TERM').and_return('smart')
 
         assert module.interactive_console() is True
@@ -113,6 +113,17 @@ def test_should_do_markup_prefers_PY_COLORS_to_interactive_console_value():
     assert module.should_do_markup(no_color=False, configs={}) is True
 
 
+def test_multi_stream_handler_logs_to_handler_for_log_level():
+    error_handler = flexmock()
+    error_handler.should_receive('emit').once()
+    info_handler = flexmock()
+
+    multi_handler = module.Multi_stream_handler(
+        {module.logging.ERROR: error_handler, module.logging.INFO: info_handler}
+    )
+    multi_handler.emit(flexmock(levelno=module.logging.ERROR))
+
+
 def test_console_color_formatter_format_includes_log_message():
     plain_message = 'uh oh'
     record = flexmock(levelno=logging.CRITICAL, msg=plain_message)
@@ -132,6 +143,9 @@ def test_color_text_without_color_does_not_raise():
 
 
 def test_configure_logging_probes_for_log_socket_on_linux():
+    flexmock(module).should_receive('Multi_stream_handler').and_return(
+        flexmock(setFormatter=lambda formatter: None, setLevel=lambda level: None)
+    )
     flexmock(module).should_receive('Console_color_formatter')
     flexmock(module).should_receive('interactive_console').and_return(False)
     flexmock(module.logging).should_receive('basicConfig').with_args(
@@ -147,6 +161,9 @@ def test_configure_logging_probes_for_log_socket_on_linux():
 
 
 def test_configure_logging_probes_for_log_socket_on_macos():
+    flexmock(module).should_receive('Multi_stream_handler').and_return(
+        flexmock(setFormatter=lambda formatter: None, setLevel=lambda level: None)
+    )
     flexmock(module).should_receive('Console_color_formatter')
     flexmock(module).should_receive('interactive_console').and_return(False)
     flexmock(module.logging).should_receive('basicConfig').with_args(
@@ -163,6 +180,9 @@ def test_configure_logging_probes_for_log_socket_on_macos():
 
 
 def test_configure_logging_sets_global_logger_to_most_verbose_log_level():
+    flexmock(module).should_receive('Multi_stream_handler').and_return(
+        flexmock(setFormatter=lambda formatter: None, setLevel=lambda level: None)
+    )
     flexmock(module).should_receive('Console_color_formatter')
     flexmock(module.logging).should_receive('basicConfig').with_args(
         level=logging.DEBUG, handlers=tuple
@@ -173,6 +193,9 @@ def test_configure_logging_sets_global_logger_to_most_verbose_log_level():
 
 
 def test_configure_logging_skips_syslog_if_not_found():
+    flexmock(module).should_receive('Multi_stream_handler').and_return(
+        flexmock(setFormatter=lambda formatter: None, setLevel=lambda level: None)
+    )
     flexmock(module).should_receive('Console_color_formatter')
     flexmock(module.logging).should_receive('basicConfig').with_args(
         level=logging.INFO, handlers=tuple
@@ -184,6 +207,9 @@ def test_configure_logging_skips_syslog_if_not_found():
 
 
 def test_configure_logging_skips_syslog_if_interactive_console():
+    flexmock(module).should_receive('Multi_stream_handler').and_return(
+        flexmock(setFormatter=lambda formatter: None, setLevel=lambda level: None)
+    )
     flexmock(module).should_receive('Console_color_formatter')
     flexmock(module).should_receive('interactive_console').and_return(True)
     flexmock(module.logging).should_receive('basicConfig').with_args(
@@ -196,6 +222,10 @@ def test_configure_logging_skips_syslog_if_interactive_console():
 
 
 def test_configure_logging_to_logfile_instead_of_syslog():
+    flexmock(module).should_receive('Multi_stream_handler').and_return(
+        flexmock(setFormatter=lambda formatter: None, setLevel=lambda level: None)
+    )
+
     # syslog skipped in non-interactive console if --log-file argument provided
     flexmock(module).should_receive('interactive_console').and_return(False)
     flexmock(module.logging).should_receive('basicConfig').with_args(
@@ -214,6 +244,10 @@ def test_configure_logging_to_logfile_instead_of_syslog():
 
 
 def test_configure_logging_skips_logfile_if_argument_is_none():
+    flexmock(module).should_receive('Multi_stream_handler').and_return(
+        flexmock(setFormatter=lambda formatter: None, setLevel=lambda level: None)
+    )
+
     # No WatchedFileHandler added if argument --log-file is None
     flexmock(module).should_receive('interactive_console').and_return(False)
     flexmock(module.logging).should_receive('basicConfig').with_args(