diff --git a/NEWS b/NEWS index 000c35cb..287602ec 100644 --- a/NEWS +++ b/NEWS @@ -4,6 +4,7 @@ resulting in "400 Bad Request" from ntfy. * #1258: Fix a "codec can't decode byte" error when running commands that output multi-byte unicode characters. + * #1260: Fix for SSH warnings from Borg showing up as JSON logs even without the "--log-json" flag. 2.1.1 * #1241: For the "recreate" action, actually pass the "--dry-run" flag through to Borg instead of diff --git a/borgmatic/execute.py b/borgmatic/execute.py index e358f0d3..5fde85c7 100644 --- a/borgmatic/execute.py +++ b/borgmatic/execute.py @@ -29,6 +29,19 @@ class Exit_status(enum.Enum): ERROR = 4 +def command_is_borg(command, borg_local_path): + ''' + Given a command as a sequence and the Borg local path, return whether that command is a call to + Borg. + ''' + parsed_command = command.split(' ', 1) if isinstance(command, str) else command + + if not parsed_command: + return False + + return bool(borg_local_path and parsed_command[0] == borg_local_path) + + def interpret_exit_code(command, exit_code, borg_local_path=None, borg_exit_codes=None): # noqa: PLR0911 ''' Return an Exit_status value (e.g. SUCCESS, ERROR, or WARNING) based on interpreting the given @@ -42,9 +55,7 @@ def interpret_exit_code(command, exit_code, borg_local_path=None, borg_exit_code if exit_code == 0: return Exit_status.SUCCESS - parsed_command = command.split(' ', 1) if isinstance(command, str) else command - - if borg_local_path and parsed_command[0] == borg_local_path: + if command_is_borg(command, borg_local_path): # First try looking for the exit code in the borg_exit_codes configuration. for entry in borg_exit_codes or (): if entry.get('code') == exit_code: @@ -124,7 +135,7 @@ def borg_json_log_line_to_record(line, log_level): if log_type == 'log_message': borg_log_level = logging._nameToLevel.get(log_data.get('levelname')) - log_level_delta = log_level - borg_log_level + log_level_delta = 0 if log_level is None else log_level - borg_log_level if log_level_delta > 0 and log_level_delta < BORG_LOG_LEVEL_ELEVATION_THRESHOLD: return logging.makeLogRecord( @@ -188,9 +199,7 @@ def parse_log_line(line, log_level, elevate_stderr, borg_local_path, command): came from stderr and the string "warning:" appears at the start of the log line. In that case, just elevate the log level to a WARN. ''' - parsed_command = command.split(' ', 1) if isinstance(command, str) else command - - if borg_local_path and parsed_command[0] == borg_local_path: + if command_is_borg(command, borg_local_path): log_record = borg_json_log_line_to_record(line, log_level) if log_record: @@ -636,7 +645,9 @@ def execute_command_and_capture_output( command, stdin=input_file, stdout=subprocess.PIPE, - stderr=subprocess.PIPE if capture_stderr else None, + stderr=subprocess.PIPE + if capture_stderr or command_is_borg(command, borg_local_path) + else None, shell=shell, env=environment, cwd=working_directory, diff --git a/tests/unit/test_execute.py b/tests/unit/test_execute.py index afc9942c..4807002a 100644 --- a/tests/unit/test_execute.py +++ b/tests/unit/test_execute.py @@ -7,72 +7,80 @@ from borgmatic import execute as module @pytest.mark.parametrize( - 'command,exit_code,borg_local_path,borg_exit_codes,expected_result', + 'command,borg_local_path,expected_result', ( - (['grep'], 2, None, None, module.Exit_status.ERROR), - (['grep'], 2, 'borg', None, module.Exit_status.ERROR), - (['borg'], 2, 'borg', None, module.Exit_status.ERROR), - (['borg1'], 2, 'borg1', None, module.Exit_status.ERROR), - (['grep'], 1, None, None, module.Exit_status.ERROR), - (['grep'], 1, 'borg', None, module.Exit_status.ERROR), - (['borg'], 1, 'borg', None, module.Exit_status.WARNING), - (['borg1'], 1, 'borg1', None, module.Exit_status.WARNING), - (['grep'], 100, None, None, module.Exit_status.ERROR), - (['grep'], 100, 'borg', None, module.Exit_status.ERROR), - ('grep', 2, None, None, module.Exit_status.ERROR), - ('borg', 2, 'borg', None, module.Exit_status.ERROR), - (['borg'], 100, 'borg', None, module.Exit_status.WARNING), - (['borg1'], 100, 'borg1', None, module.Exit_status.WARNING), - ('borg', 100, 'borg', None, module.Exit_status.WARNING), - ('borg1', 100, 'borg1', None, module.Exit_status.WARNING), - (['grep'], 0, None, None, module.Exit_status.SUCCESS), - (['grep'], 0, 'borg', None, module.Exit_status.SUCCESS), - (['borg'], 0, 'borg', None, module.Exit_status.SUCCESS), - (['borg1'], 0, 'borg1', None, module.Exit_status.SUCCESS), - ('grep', 0, None, None, module.Exit_status.SUCCESS), - ('grep', 0, 'borg', None, module.Exit_status.SUCCESS), + (['foo', 'bar'], 'borg', False), + (['borg', 'list'], 'borg', True), + (['borg1', 'list'], 'borg', False), + (['borg', 'list'], 'borg1', False), + ([], 'borg', False), + ('foo bar', 'borg', False), + ('borg list', 'borg', True), + ('', 'borg', False), + ), +) +def test_command_is_borg_matches_local_path_to_command(command, borg_local_path, expected_result): + assert module.command_is_borg(command, borg_local_path) == expected_result + + +@pytest.mark.parametrize( + 'command_is_borg,exit_code,borg_exit_codes,expected_result', + ( + (False, 2, None, module.Exit_status.ERROR), + (True, 2, None, module.Exit_status.ERROR), + (False, 1, None, module.Exit_status.ERROR), + (True, 1, None, module.Exit_status.WARNING), + (False, 100, None, module.Exit_status.ERROR), + (False, 2, None, module.Exit_status.ERROR), + (True, 2, None, module.Exit_status.ERROR), + (True, 100, None, module.Exit_status.WARNING), + (False, 0, None, module.Exit_status.SUCCESS), + (True, 0, None, module.Exit_status.SUCCESS), # -9 exit code occurs when child process get SIGKILLed. - (['grep'], -9, None, None, module.Exit_status.ERROR), - (['grep'], -9, 'borg', None, module.Exit_status.ERROR), - (['borg'], -9, 'borg', None, module.Exit_status.ERROR), - (['borg1'], -9, 'borg1', None, module.Exit_status.ERROR), - (['borg'], None, None, None, module.Exit_status.STILL_RUNNING), - (['borg'], 1, 'borg', [], module.Exit_status.WARNING), - (['borg'], 1, 'borg', [{}], module.Exit_status.WARNING), - (['borg'], 1, 'borg', [{'code': 1}], module.Exit_status.WARNING), - (['grep'], 1, 'borg', [{'code': 100, 'treat_as': 'error'}], module.Exit_status.ERROR), - (['borg'], 1, 'borg', [{'code': 100, 'treat_as': 'error'}], module.Exit_status.WARNING), - (['borg'], 1, 'borg', [{'code': 1, 'treat_as': 'error'}], module.Exit_status.ERROR), - (['borg'], 2, 'borg', [{'code': 99, 'treat_as': 'warning'}], module.Exit_status.ERROR), - (['borg'], 2, 'borg', [{'code': 2, 'treat_as': 'warning'}], module.Exit_status.WARNING), - (['borg'], 100, 'borg', [{'code': 1, 'treat_as': 'error'}], module.Exit_status.WARNING), - (['borg'], 100, 'borg', [], module.Exit_status.WARNING), - (['borg'], 100, 'borg', [{'code': 100, 'treat_as': 'error'}], module.Exit_status.ERROR), - (['borg'], 101, 'borg', [], module.Exit_status.ERROR), - (['borg'], 101, 'borg', [{'code': 101, 'treat_as': 'warning'}], module.Exit_status.WARNING), - (['borg'], 102, 'borg', [], module.Exit_status.ERROR), - (['borg'], 102, 'borg', [{'code': 102, 'treat_as': 'warning'}], module.Exit_status.WARNING), - (['borg'], 103, 'borg', [], module.Exit_status.WARNING), - (['borg'], 103, 'borg', [{'code': 103, 'treat_as': 'error'}], module.Exit_status.ERROR), - (['borg'], 104, 'borg', [], module.Exit_status.ERROR), - (['borg'], 104, 'borg', [{'code': 104, 'treat_as': 'warning'}], module.Exit_status.WARNING), - (['borg'], 105, 'borg', [], module.Exit_status.ERROR), - (['borg'], 105, 'borg', [{'code': 105, 'treat_as': 'warning'}], module.Exit_status.WARNING), - (['borg'], 106, 'borg', [], module.Exit_status.ERROR), - (['borg'], 106, 'borg', [{'code': 106, 'treat_as': 'warning'}], module.Exit_status.WARNING), - (['borg'], 107, 'borg', [], module.Exit_status.ERROR), - (['borg'], 107, 'borg', [{'code': 107, 'treat_as': 'warning'}], module.Exit_status.WARNING), + (False, -9, None, module.Exit_status.ERROR), + (True, -9, None, module.Exit_status.ERROR), + (True, None, None, module.Exit_status.STILL_RUNNING), + (True, 1, [], module.Exit_status.WARNING), + (True, 1, [{'code': 1}], module.Exit_status.WARNING), + (False, 1, [{'code': 100, 'treat_as': 'error'}], module.Exit_status.ERROR), + (True, 1, [{'code': 100, 'treat_as': 'error'}], module.Exit_status.WARNING), + (True, 1, [{'code': 1, 'treat_as': 'error'}], module.Exit_status.ERROR), + (True, 2, [{'code': 99, 'treat_as': 'warning'}], module.Exit_status.ERROR), + (True, 2, [{'code': 2, 'treat_as': 'warning'}], module.Exit_status.WARNING), + (True, 100, [{'code': 1, 'treat_as': 'error'}], module.Exit_status.WARNING), + (True, 100, [], module.Exit_status.WARNING), + (True, 100, [{'code': 100, 'treat_as': 'error'}], module.Exit_status.ERROR), + (True, 101, [], module.Exit_status.ERROR), + (True, 101, [{'code': 101, 'treat_as': 'warning'}], module.Exit_status.WARNING), + (True, 102, [], module.Exit_status.ERROR), + (True, 102, [{'code': 102, 'treat_as': 'warning'}], module.Exit_status.WARNING), + (True, 103, [], module.Exit_status.WARNING), + (True, 103, [{'code': 103, 'treat_as': 'error'}], module.Exit_status.ERROR), + (True, 104, [], module.Exit_status.ERROR), + (True, 104, [{'code': 104, 'treat_as': 'warning'}], module.Exit_status.WARNING), + (True, 105, [], module.Exit_status.ERROR), + (True, 105, [{'code': 105, 'treat_as': 'warning'}], module.Exit_status.WARNING), + (True, 106, [], module.Exit_status.ERROR), + (True, 106, [{'code': 106, 'treat_as': 'warning'}], module.Exit_status.WARNING), + (True, 107, [], module.Exit_status.ERROR), + (True, 107, [{'code': 107, 'treat_as': 'warning'}], module.Exit_status.WARNING), ), ) def test_interpret_exit_code_respects_exit_code_and_borg_local_path( - command, + command_is_borg, exit_code, - borg_local_path, borg_exit_codes, expected_result, ): + flexmock(module).should_receive('command_is_borg').and_return(command_is_borg) + assert ( - module.interpret_exit_code(command, exit_code, borg_local_path, borg_exit_codes) + module.interpret_exit_code( + command=flexmock(), + exit_code=exit_code, + borg_local_path=flexmock(), + borg_exit_codes=borg_exit_codes, + ) is expected_result ) @@ -146,6 +154,18 @@ def test_borg_json_log_line_to_record_does_not_elevate_log_message_info_level_to assert record.name == 'borg.something' +def test_borg_json_log_line_with_none_log_level_parses_log_message_line(): + line = '{"type": "log_message", "levelname": "INFO", "time": 12345, "message": "All done", "name": "borg.something"}' + + record = module.borg_json_log_line_to_record(line, None) + + 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"}' @@ -1404,6 +1424,7 @@ def test_execute_command_without_run_to_completion_returns_process(): def test_execute_command_and_capture_output_returns_stdout(): full_command = ['foo', 'bar'] flexmock(module).should_receive('log_command') + flexmock(module).should_receive('command_is_borg').and_return(False) process = flexmock() flexmock(module.subprocess).should_receive('Popen').with_args( full_command, @@ -1423,8 +1444,10 @@ def test_execute_command_and_capture_output_returns_stdout(): assert output_lines == ('out',) -def test_execute_command_and_capture_output_with_capture_stderr_returns_stderr(): +def test_execute_command_and_capture_output_with_capture_stderr_popens_stderr(): full_command = ['foo', 'bar'] + flexmock(module).should_receive('log_command') + flexmock(module).should_receive('command_is_borg').and_return(False) process = flexmock() flexmock(module.subprocess).should_receive('Popen').with_args( full_command, @@ -1446,10 +1469,34 @@ def test_execute_command_and_capture_output_with_capture_stderr_returns_stderr() assert output_lines == ('out',) +def test_execute_command_and_capture_output_with_borg_command_popens_stderr(): + full_command = ['borg', 'list'] + flexmock(module).should_receive('log_command') + flexmock(module).should_receive('command_is_borg').and_return(True) + process = flexmock() + flexmock(module.subprocess).should_receive('Popen').with_args( + full_command, + stdin=None, + stdout=subprocess.PIPE, + stderr=subprocess.PIPE, + shell=False, + env=None, + cwd=None, + close_fds=False, + ).and_return(process).once() + flexmock(module.borgmatic.logger).should_receive('Log_prefix').and_return(flexmock()) + flexmock(module).should_receive('log_outputs').and_yield('out') + + output_lines = tuple(module.execute_command_and_capture_output(full_command)) + + assert output_lines == ('out',) + + def test_execute_command_and_capture_output_returns_output_when_process_error_is_not_considered_an_error(): full_command = ['foo', 'bar'] err_output = b'[]' flexmock(module).should_receive('log_command') + flexmock(module).should_receive('command_is_borg').and_return(False) flexmock(module.subprocess).should_receive('Popen').with_args( full_command, stdin=None, @@ -1472,6 +1519,7 @@ def test_execute_command_and_capture_output_returns_output_when_process_error_is def test_execute_command_and_capture_output_raises_when_command_errors(): full_command = ['foo', 'bar'] flexmock(module).should_receive('log_command') + flexmock(module).should_receive('command_is_borg').and_return(False) flexmock(module.subprocess).should_receive('Popen').with_args( full_command, stdin=None, @@ -1493,6 +1541,7 @@ def test_execute_command_and_capture_output_raises_when_command_errors(): def test_execute_command_and_capture_output_with_shell_returns_output(): full_command = ['foo', 'bar'] flexmock(module).should_receive('log_command') + flexmock(module).should_receive('command_is_borg').and_return(False) process = flexmock() flexmock(module.subprocess).should_receive('Popen').with_args( 'foo bar', @@ -1515,6 +1564,7 @@ def test_execute_command_and_capture_output_with_shell_returns_output(): def test_execute_command_and_capture_output_with_enviroment_returns_output(): full_command = ['foo', 'bar'] flexmock(module).should_receive('log_command') + flexmock(module).should_receive('command_is_borg').and_return(False) process = flexmock() flexmock(module.subprocess).should_receive('Popen').with_args( full_command, @@ -1543,6 +1593,7 @@ def test_execute_command_and_capture_output_with_enviroment_returns_output(): def test_execute_command_and_capture_output_returns_output_with_working_directory(): full_command = ['foo', 'bar'] flexmock(module).should_receive('log_command') + flexmock(module).should_receive('command_is_borg').and_return(False) process = flexmock() flexmock(module.subprocess).should_receive('Popen').with_args( full_command,