Fix a regression in which the "--stats" flag hides statistics at default verbosity (#1250).

NEWS

@@ -1,3 +1,6 @@
+2.1.2.dev0
+ * #1250: Fix a regression in which the "--stats" flag hides statistics at default verbosity.
+
 2.1.1
  * #1241: For the "recreate" action, actually pass the "--dry-run" flag through to Borg instead of
    just skipping the Borg call.

borgmatic/execute.py

@@ -105,19 +105,41 @@ def output_buffers_for_process(process, exclude_stdouts):
     )
 
 
+BORG_LOG_LEVEL_ELEVATION_THRESHOLD = 10
+
+
 def borg_json_log_line_to_record(line, log_level):
     '''
     Given a single Borg "--log-json"-style log line and a log level, return the line converted to a
     logging.LogRecord instance. Return None if the line can't be parsed as JSON.
+
+    If Borg provides a log level in its JSON, prefer logging at that level. But if Borg doesn't
+    provide a log level—or the log level given to this function is just a little bit higher than
+    Borg's—elevate to that level. This supports use cases like elevating Borg's INFO level logs to
+    borgmatic's custom ANSWER level so that requested data shows up even at the default verbosity.
     '''
     with contextlib.suppress(json.JSONDecodeError, TypeError, KeyError, AttributeError):
         log_data = json.loads(line)
         log_type = log_data.get('type')
 
         if log_type == 'log_message':
+            borg_log_level = logging._nameToLevel.get(log_data.get('levelname'))
+            log_level_delta = log_level - borg_log_level
+
+            if log_level_delta > 0 and log_level_delta < BORG_LOG_LEVEL_ELEVATION_THRESHOLD:
+                return logging.makeLogRecord(
+                    dict(
+                        levelno=log_level,
+                        created=log_data.get('time'),
+                        msg=log_data.get('message'),
+                        levelname=logging.getLevelName(log_level),
+                        name=log_data.get('name'),
+                    )
+                )
+
             return logging.makeLogRecord(
                 dict(
-                    levelno=logging._nameToLevel.get(log_data.get('levelname')),
+                    levelno=borg_log_level,
                     created=log_data.get('time'),
                     msg=log_data.get('message'),
                     levelname=log_data.get('levelname'),

pyproject.toml

@@ -1,6 +1,6 @@
 [project]
 name = "borgmatic"
-version = "2.1.1"
+version = "2.1.2dev0"
 authors = [
   { name="Dan Helfman", email="witten@torsion.org" },
 ]

tests/unit/test_execute.py

@@ -122,6 +122,30 @@ def test_borg_json_log_line_to_record_parses_log_message_line():
     assert record.name == 'borg.something'
 
 
+def test_borg_json_log_line_to_record_elevates_log_message_info_level_to_small_jump_in_log_level():
+    line = '{"type": "log_message", "levelname": "INFO", "time": 12345, "message": "All done", "name": "borg.something"}'
+
+    record = module.borg_json_log_line_to_record(line, 25)
+
+    assert record.levelno == 25
+    assert record.created == 12345
+    assert record.msg == 'All done'
+    assert record.levelname in {'ANSWER', 'Level 25'}
+    assert record.name == 'borg.something'
+
+
+def test_borg_json_log_line_to_record_does_not_elevate_log_message_info_level_to_big_jump_in_log_level():
+    line = '{"type": "log_message", "levelname": "INFO", "time": 12345, "message": "All done", "name": "borg.something"}'
+
+    record = module.borg_json_log_line_to_record(line, 40)
+
+    assert record.levelno == module.logging.INFO
+    assert record.created == 12345
+    assert record.msg == 'All done'
+    assert record.levelname == 'INFO'
+    assert record.name == 'borg.something'
+
+
 def test_borg_json_log_line_to_record_parses_file_status_line():
     flexmock(module.time).should_receive('time').and_return(12345)
     line = '{"type": "file_status", "status": "-", "path": "/foo/bar"}'