Simplify logging logic (#665).

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

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',

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,
     )

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():

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,116 +240,120 @@ 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(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)
-
-    module.configure_logging(console_log_level=logging.INFO, syslog_log_level=logging.DEBUG)
-
-
-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.os.path).should_receive('exists').never()
     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():
+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).should_receive('interactive_console').and_return(True)
     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').with_args('/dev/log').and_return(True)
+    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)
+    module.configure_logging(console_log_level=logging.INFO, syslog_log_level=logging.DEBUG)
 
 
-def test_configure_logging_skips_syslog_if_syslog_logging_is_disabled():
+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
+        )
     )
-    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
+        level=logging.INFO, handlers=list
     )
-    flexmock(module.os.path).should_receive('exists').with_args('/dev/log').and_return(True)
+    flexmock(module.os.path).should_receive('exists').never()
     flexmock(module.logging.handlers).should_receive('SysLogHandler').never()
+    flexmock(module.logging.handlers).should_receive('WatchedFileHandler').never()
 
-    module.configure_logging(console_log_level=logging.INFO, syslog_log_level=logging.DISABLED)
+    module.configure_logging(
+        console_log_level=logging.INFO, log_file_log_level=logging.DISABLED, log_file='/tmp/logfile'
+    )
 
 
-def test_configure_logging_skips_log_file_if_log_file_logging_is_disabled():
+def test_configure_logging_to_log_file_instead_of_syslog():
     flexmock(module).should_receive('add_custom_log_levels')
-    flexmock(module.logging).DISABLED = module.DISABLED
+    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.INFO, handlers=tuple
+        level=logging.DEBUG, handlers=list
     )
     flexmock(module.os.path).should_receive('exists').never()
     flexmock(module.logging.handlers).should_receive('SysLogHandler').never()
-    flexmock(module.logging.handlers).should_receive('WatchedFileHandler').never()
+    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, log_file_log_level=logging.DISABLED, 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_log_file_instead_of_syslog():
+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)
+        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()
+    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, log_file_log_level=logging.DEBUG, log_file='/tmp/logfile'
+        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()