diff --git a/NEWS b/NEWS index f4388135..f821f5c3 100644 --- a/NEWS +++ b/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. diff --git a/borgmatic/execute.py b/borgmatic/execute.py index 1bbe1bd3..798f5226 100644 --- a/borgmatic/execute.py +++ b/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'), diff --git a/pyproject.toml b/pyproject.toml index 33f6cdf2..3f2596e2 100644 --- a/pyproject.toml +++ b/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" }, ] diff --git a/tests/unit/test_execute.py b/tests/unit/test_execute.py index 308e759e..afc9942c 100644 --- a/tests/unit/test_execute.py +++ b/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"}'