From ac1e1a9407a2d29d647f0ade4b72487faf62cd0d Mon Sep 17 00:00:00 2001 From: Dan Helfman Date: Fri, 29 Sep 2023 14:16:47 -0700 Subject: [PATCH] Simplify logging logic (#665). --- NEWS | 5 + borgmatic/commands/arguments.py | 14 +- borgmatic/logger.py | 32 ++-- tests/integration/commands/test_arguments.py | 20 ++- tests/unit/test_logger.py | 152 ++++++++++--------- 5 files changed, 124 insertions(+), 99 deletions(-) diff --git a/NEWS b/NEWS index 7467262..b8a43fe 100644 --- a/NEWS +++ b/NEWS @@ -1,4 +1,9 @@ 1.8.3.dev0 + * #665: BREAKING: Simplify logging logic as follows: Syslog verbosity is now disabled by + default, but setting the "--syslog-verbosity" flag enables it regardless of whether you're at an + interactive console. Additionally, "--log-file-verbosity" and "--monitoring-verbosity" now + default to 1 (info about steps borgmatic is taking) instead of 0. And both syslog logging and + file logging can be enabled simultaneously. * #743: Add a monitoring hook for sending backup status and logs to to Grafana Loki. See the documentation for more information: https://torsion.org/borgmatic/docs/how-to/monitor-your-backups/#loki-hook diff --git a/borgmatic/commands/arguments.py b/borgmatic/commands/arguments.py index 5fdec82..b6ac2d9 100644 --- a/borgmatic/commands/arguments.py +++ b/borgmatic/commands/arguments.py @@ -259,28 +259,28 @@ def make_parsers(): type=int, choices=range(-2, 3), default=0, - help='Display verbose progress to the console (disabled, errors only, default, some, or lots: -2, -1, 0, 1, or 2)', + help='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)', ) global_group.add_argument( '--syslog-verbosity', type=int, choices=range(-2, 3), - default=0, - help='Log verbose progress to syslog (disabled, errors only, default, some, or lots: -2, -1, 0, 1, or 2). Ignored when console is interactive or --log-file is given', + default=-2, + help='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)', ) global_group.add_argument( '--log-file-verbosity', type=int, choices=range(-2, 3), - default=0, - help='Log verbose progress to log file (disabled, errors only, default, some, or lots: -2, -1, 0, 1, or 2). Only used when --log-file is given', + default=1, + help='When --log-file is given, 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)', ) global_group.add_argument( '--monitoring-verbosity', type=int, choices=range(-2, 3), - default=0, - help='Log verbose progress to monitoring integrations that support logging (from disabled, errors only, default, some, or lots: -2, -1, 0, 1, or 2)', + default=1, + help='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)', ) global_group.add_argument( '--log-file', diff --git a/borgmatic/logger.py b/borgmatic/logger.py index cda5151..5fb67f3 100644 --- a/borgmatic/logger.py +++ b/borgmatic/logger.py @@ -167,7 +167,7 @@ def configure_logging( Raise FileNotFoundError or PermissionError if the log file could not be opened for writing. ''' if syslog_log_level is None: - syslog_log_level = console_log_level + syslog_log_level = logging.DISABLED if log_file_log_level is None: log_file_log_level = console_log_level if monitoring_log_level is None: @@ -194,8 +194,11 @@ def configure_logging( console_handler.setFormatter(Console_color_formatter()) console_handler.setLevel(console_log_level) - syslog_path = None - if log_file is None and syslog_log_level != logging.DISABLED: + handlers = [console_handler] + + if syslog_log_level != logging.DISABLED: + syslog_path = None + if os.path.exists('/dev/log'): syslog_path = '/dev/log' elif os.path.exists('/var/run/syslog'): @@ -203,14 +206,15 @@ def configure_logging( elif os.path.exists('/var/run/log'): syslog_path = '/var/run/log' - if syslog_path and not interactive_console(): - syslog_handler = logging.handlers.SysLogHandler(address=syslog_path) - syslog_handler.setFormatter( - logging.Formatter('borgmatic: {levelname} {message}', style='{') # noqa: FS003 - ) - syslog_handler.setLevel(syslog_log_level) - handlers = (console_handler, syslog_handler) - elif log_file and log_file_log_level != logging.DISABLED: + if syslog_path: + syslog_handler = logging.handlers.SysLogHandler(address=syslog_path) + syslog_handler.setFormatter( + logging.Formatter('borgmatic: {levelname} {message}', style='{') # noqa: FS003 + ) + syslog_handler.setLevel(syslog_log_level) + handlers.append(syslog_handler) + + if log_file and log_file_log_level != logging.DISABLED: file_handler = logging.handlers.WatchedFileHandler(log_file) file_handler.setFormatter( logging.Formatter( @@ -218,11 +222,9 @@ def configure_logging( ) ) file_handler.setLevel(log_file_log_level) - handlers = (console_handler, file_handler) - else: - handlers = (console_handler,) + handlers.append(file_handler) logging.basicConfig( - level=min(console_log_level, syslog_log_level, log_file_log_level, monitoring_log_level), + level=min(handler.level for handler in handlers), handlers=handlers, ) diff --git a/tests/integration/commands/test_arguments.py b/tests/integration/commands/test_arguments.py index 74d056a..e64030c 100644 --- a/tests/integration/commands/test_arguments.py +++ b/tests/integration/commands/test_arguments.py @@ -13,8 +13,9 @@ def test_parse_arguments_with_no_arguments_uses_defaults(): global_arguments = arguments['global'] assert global_arguments.config_paths == config_paths assert global_arguments.verbosity == 0 - assert global_arguments.syslog_verbosity == 0 - assert global_arguments.log_file_verbosity == 0 + assert global_arguments.syslog_verbosity == -2 + assert global_arguments.log_file_verbosity == 1 + assert global_arguments.monitoring_verbosity == 1 def test_parse_arguments_with_multiple_config_flags_parses_as_list(): @@ -25,8 +26,9 @@ def test_parse_arguments_with_multiple_config_flags_parses_as_list(): global_arguments = arguments['global'] assert global_arguments.config_paths == ['myconfig', 'otherconfig'] assert global_arguments.verbosity == 0 - assert global_arguments.syslog_verbosity == 0 - assert global_arguments.log_file_verbosity == 0 + assert global_arguments.syslog_verbosity == -2 + assert global_arguments.log_file_verbosity == 1 + assert global_arguments.monitoring_verbosity == 1 def test_parse_arguments_with_action_after_config_path_omits_action(): @@ -71,8 +73,9 @@ def test_parse_arguments_with_verbosity_overrides_default(): global_arguments = arguments['global'] assert global_arguments.config_paths == config_paths assert global_arguments.verbosity == 1 - assert global_arguments.syslog_verbosity == 0 - assert global_arguments.log_file_verbosity == 0 + assert global_arguments.syslog_verbosity == -2 + assert global_arguments.log_file_verbosity == 1 + assert global_arguments.monitoring_verbosity == 1 def test_parse_arguments_with_syslog_verbosity_overrides_default(): @@ -85,6 +88,8 @@ def test_parse_arguments_with_syslog_verbosity_overrides_default(): assert global_arguments.config_paths == config_paths assert global_arguments.verbosity == 0 assert global_arguments.syslog_verbosity == 2 + assert global_arguments.log_file_verbosity == 1 + assert global_arguments.monitoring_verbosity == 1 def test_parse_arguments_with_log_file_verbosity_overrides_default(): @@ -96,8 +101,9 @@ def test_parse_arguments_with_log_file_verbosity_overrides_default(): global_arguments = arguments['global'] assert global_arguments.config_paths == config_paths assert global_arguments.verbosity == 0 - assert global_arguments.syslog_verbosity == 0 + assert global_arguments.syslog_verbosity == -2 assert global_arguments.log_file_verbosity == -1 + assert global_arguments.monitoring_verbosity == 1 def test_parse_arguments_with_single_override_parses(): diff --git a/tests/unit/test_logger.py b/tests/unit/test_logger.py index f86aacd..71348a4 100644 --- a/tests/unit/test_logger.py +++ b/tests/unit/test_logger.py @@ -174,16 +174,18 @@ def test_add_logging_level_skips_global_setting_if_already_set(): module.add_logging_level('PLAID', 99) -def test_configure_logging_probes_for_log_socket_on_linux(): +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 flexmock(module).should_receive('Multi_stream_handler').and_return( - flexmock(setFormatter=lambda formatter: None, setLevel=lambda level: None) + flexmock( + setFormatter=lambda formatter: None, setLevel=lambda level: None, level=logging.INFO + ) ) flexmock(module).should_receive('Console_color_formatter') flexmock(module).should_receive('interactive_console').and_return(False) flexmock(module.logging).should_receive('basicConfig').with_args( - level=logging.INFO, handlers=tuple + level=logging.DEBUG, handlers=list ) flexmock(module.os.path).should_receive('exists').with_args('/dev/log').and_return(True) syslog_handler = logging.handlers.SysLogHandler() @@ -191,19 +193,21 @@ def test_configure_logging_probes_for_log_socket_on_linux(): address='/dev/log' ).and_return(syslog_handler).once() - module.configure_logging(logging.INFO) + module.configure_logging(logging.INFO, syslog_log_level=logging.DEBUG) -def test_configure_logging_probes_for_log_socket_on_macos(): +def test_configure_logging_with_syslog_log_level_probes_for_log_socket_on_macos(): flexmock(module).should_receive('add_custom_log_levels') flexmock(module.logging).ANSWER = module.ANSWER flexmock(module).should_receive('Multi_stream_handler').and_return( - flexmock(setFormatter=lambda formatter: None, setLevel=lambda level: None) + flexmock( + setFormatter=lambda formatter: None, setLevel=lambda level: None, level=logging.INFO + ) ) flexmock(module).should_receive('Console_color_formatter') flexmock(module).should_receive('interactive_console').and_return(False) flexmock(module.logging).should_receive('basicConfig').with_args( - level=logging.INFO, handlers=tuple + level=logging.DEBUG, handlers=list ) flexmock(module.os.path).should_receive('exists').with_args('/dev/log').and_return(False) flexmock(module.os.path).should_receive('exists').with_args('/var/run/syslog').and_return(True) @@ -212,19 +216,21 @@ def test_configure_logging_probes_for_log_socket_on_macos(): address='/var/run/syslog' ).and_return(syslog_handler).once() - module.configure_logging(logging.INFO) + module.configure_logging(logging.INFO, syslog_log_level=logging.DEBUG) -def test_configure_logging_probes_for_log_socket_on_freebsd(): +def test_configure_logging_with_syslog_log_level_probes_for_log_socket_on_freebsd(): flexmock(module).should_receive('add_custom_log_levels') flexmock(module.logging).ANSWER = module.ANSWER flexmock(module).should_receive('Multi_stream_handler').and_return( - flexmock(setFormatter=lambda formatter: None, setLevel=lambda level: None) + flexmock( + setFormatter=lambda formatter: None, setLevel=lambda level: None, level=logging.INFO + ) ) flexmock(module).should_receive('Console_color_formatter') flexmock(module).should_receive('interactive_console').and_return(False) flexmock(module.logging).should_receive('basicConfig').with_args( - level=logging.INFO, handlers=tuple + level=logging.DEBUG, handlers=list ) flexmock(module.os.path).should_receive('exists').with_args('/dev/log').and_return(False) flexmock(module.os.path).should_receive('exists').with_args('/var/run/syslog').and_return(False) @@ -234,85 +240,56 @@ def test_configure_logging_probes_for_log_socket_on_freebsd(): address='/var/run/log' ).and_return(syslog_handler).once() - module.configure_logging(logging.INFO) + module.configure_logging(logging.INFO, syslog_log_level=logging.DEBUG) -def test_configure_logging_sets_global_logger_to_most_verbose_log_level(): +def test_configure_logging_without_syslog_log_level_skips_syslog(): flexmock(module).should_receive('add_custom_log_levels') flexmock(module.logging).ANSWER = module.ANSWER flexmock(module).should_receive('Multi_stream_handler').and_return( - flexmock(setFormatter=lambda formatter: None, setLevel=lambda level: None) + flexmock( + setFormatter=lambda formatter: None, setLevel=lambda level: None, level=logging.INFO + ) ) flexmock(module).should_receive('Console_color_formatter') flexmock(module.logging).should_receive('basicConfig').with_args( - level=logging.DEBUG, handlers=tuple - ).once() - flexmock(module.os.path).should_receive('exists').and_return(False) + level=logging.INFO, handlers=list + ) + flexmock(module.os.path).should_receive('exists').never() + flexmock(module.logging.handlers).should_receive('SysLogHandler').never() - module.configure_logging(console_log_level=logging.INFO, syslog_log_level=logging.DEBUG) + module.configure_logging(console_log_level=logging.INFO) def test_configure_logging_skips_syslog_if_not_found(): flexmock(module).should_receive('add_custom_log_levels') flexmock(module.logging).ANSWER = module.ANSWER flexmock(module).should_receive('Multi_stream_handler').and_return( - flexmock(setFormatter=lambda formatter: None, setLevel=lambda level: None) + flexmock( + setFormatter=lambda formatter: None, setLevel=lambda level: None, level=logging.INFO + ) ) flexmock(module).should_receive('Console_color_formatter') flexmock(module.logging).should_receive('basicConfig').with_args( - level=logging.INFO, handlers=tuple + level=logging.INFO, handlers=list ) flexmock(module.os.path).should_receive('exists').and_return(False) flexmock(module.logging.handlers).should_receive('SysLogHandler').never() - module.configure_logging(console_log_level=logging.INFO) - - -def test_configure_logging_skips_syslog_if_interactive_console(): - flexmock(module).should_receive('add_custom_log_levels') - flexmock(module.logging).ANSWER = module.ANSWER - 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( - level=logging.INFO, handlers=tuple - ) - flexmock(module.os.path).should_receive('exists').with_args('/dev/log').and_return(True) - flexmock(module.logging.handlers).should_receive('SysLogHandler').never() - - module.configure_logging(console_log_level=logging.INFO) - - -def test_configure_logging_skips_syslog_if_syslog_logging_is_disabled(): - flexmock(module).should_receive('add_custom_log_levels') - flexmock(module.logging).DISABLED = module.DISABLED - 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').never() - flexmock(module.logging).should_receive('basicConfig').with_args( - level=logging.INFO, handlers=tuple - ) - flexmock(module.os.path).should_receive('exists').with_args('/dev/log').and_return(True) - flexmock(module.logging.handlers).should_receive('SysLogHandler').never() - - module.configure_logging(console_log_level=logging.INFO, syslog_log_level=logging.DISABLED) + module.configure_logging(console_log_level=logging.INFO, syslog_log_level=logging.DEBUG) 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 flexmock(module).should_receive('Multi_stream_handler').and_return( - flexmock(setFormatter=lambda formatter: None, setLevel=lambda level: None) + flexmock( + setFormatter=lambda formatter: None, setLevel=lambda level: None, level=logging.INFO + ) ) - # 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( - level=logging.INFO, handlers=tuple + level=logging.INFO, handlers=list ) flexmock(module.os.path).should_receive('exists').never() flexmock(module.logging.handlers).should_receive('SysLogHandler').never() @@ -327,13 +304,13 @@ def test_configure_logging_to_log_file_instead_of_syslog(): flexmock(module).should_receive('add_custom_log_levels') flexmock(module.logging).ANSWER = module.ANSWER flexmock(module).should_receive('Multi_stream_handler').and_return( - flexmock(setFormatter=lambda formatter: None, setLevel=lambda level: None) + flexmock( + setFormatter=lambda formatter: None, setLevel=lambda level: None, level=logging.INFO + ) ) - # 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( - level=logging.DEBUG, handlers=tuple + level=logging.DEBUG, handlers=list ) flexmock(module.os.path).should_receive('exists').never() flexmock(module.logging.handlers).should_receive('SysLogHandler').never() @@ -343,7 +320,40 @@ def test_configure_logging_to_log_file_instead_of_syslog(): ).and_return(file_handler).once() module.configure_logging( - console_log_level=logging.INFO, log_file_log_level=logging.DEBUG, log_file='/tmp/logfile' + console_log_level=logging.INFO, + syslog_log_level=logging.DISABLED, + log_file_log_level=logging.DEBUG, + log_file='/tmp/logfile', + ) + + +def test_configure_logging_to_both_log_file_and_syslog(): + flexmock(module).should_receive('add_custom_log_levels') + flexmock(module.logging).ANSWER = module.ANSWER + flexmock(module).should_receive('Multi_stream_handler').and_return( + flexmock( + setFormatter=lambda formatter: None, setLevel=lambda level: None, level=logging.INFO + ) + ) + + flexmock(module.logging).should_receive('basicConfig').with_args( + level=logging.DEBUG, handlers=list + ) + flexmock(module.os.path).should_receive('exists').with_args('/dev/log').and_return(True) + syslog_handler = logging.handlers.SysLogHandler() + flexmock(module.logging.handlers).should_receive('SysLogHandler').with_args( + address='/dev/log' + ).and_return(syslog_handler).once() + file_handler = logging.handlers.WatchedFileHandler('/tmp/logfile') + flexmock(module.logging.handlers).should_receive('WatchedFileHandler').with_args( + '/tmp/logfile' + ).and_return(file_handler).once() + + module.configure_logging( + console_log_level=logging.INFO, + syslog_log_level=logging.DEBUG, + log_file_log_level=logging.DEBUG, + log_file='/tmp/logfile', ) @@ -354,12 +364,14 @@ def test_configure_logging_to_log_file_formats_with_custom_log_format(): '{message}', style='{' # noqa: FS003 ).once() flexmock(module).should_receive('Multi_stream_handler').and_return( - flexmock(setFormatter=lambda formatter: None, setLevel=lambda level: None) + flexmock( + setFormatter=lambda formatter: None, setLevel=lambda level: None, level=logging.INFO + ) ) flexmock(module).should_receive('interactive_console').and_return(False) flexmock(module.logging).should_receive('basicConfig').with_args( - level=logging.DEBUG, handlers=tuple + level=logging.DEBUG, handlers=list ) flexmock(module.os.path).should_receive('exists').with_args('/dev/log').and_return(True) flexmock(module.logging.handlers).should_receive('SysLogHandler').never() @@ -380,13 +392,13 @@ 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 flexmock(module).should_receive('Multi_stream_handler').and_return( - flexmock(setFormatter=lambda formatter: None, setLevel=lambda level: None) + flexmock( + setFormatter=lambda formatter: None, setLevel=lambda level: None, level=logging.INFO + ) ) - # 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( - level=logging.INFO, handlers=tuple + level=logging.INFO, handlers=list ) flexmock(module.os.path).should_receive('exists').and_return(False) flexmock(module.logging.handlers).should_receive('WatchedFileHandler').never()