diff --git a/NEWS b/NEWS index 9c439f1c..fc24cd3d 100644 --- a/NEWS +++ b/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 diff --git a/borgmatic/logger.py b/borgmatic/logger.py index ce9be04a..b20f89e3 100644 --- a/borgmatic/logger.py +++ b/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) diff --git a/tests/unit/test_logger.py b/tests/unit/test_logger.py index 8eeb6be6..707376bc 100644 --- a/tests/unit/test_logger.py +++ b/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(