From e8dbca9d6809f6f60730e38ee5608472124e223f Mon Sep 17 00:00:00 2001 From: Dan Helfman Date: Mon, 10 Jul 2023 11:16:18 -0700 Subject: [PATCH] Truncate long command output without assuming an encoded byte string. --- borgmatic/borg/create.py | 2 ++ borgmatic/borg/info.py | 1 + borgmatic/borg/list.py | 2 ++ borgmatic/borg/rinfo.py | 1 + borgmatic/borg/rlist.py | 5 ++++- borgmatic/borg/version.py | 1 + borgmatic/commands/borgmatic.py | 26 ++++++++++++++++++------- borgmatic/execute.py | 7 +++++-- tests/unit/borg/test_create.py | 7 ++++++- tests/unit/borg/test_info.py | 3 +++ tests/unit/borg/test_list.py | 2 ++ tests/unit/borg/test_rinfo.py | 3 +++ tests/unit/borg/test_rlist.py | 8 ++++++++ tests/unit/borg/test_version.py | 1 + tests/unit/commands/test_borgmatic.py | 28 ++++++++++++++++++++++++++- 15 files changed, 85 insertions(+), 12 deletions(-) diff --git a/borgmatic/borg/create.py b/borgmatic/borg/create.py index 018f447d..d778e565 100644 --- a/borgmatic/borg/create.py +++ b/borgmatic/borg/create.py @@ -292,6 +292,7 @@ def collect_special_file_paths( capture_stderr=True, working_directory=working_directory, extra_environment=borg_environment, + borg_local_path=local_path, ) paths = tuple( @@ -510,6 +511,7 @@ def create_archive( create_command, working_directory=working_directory, extra_environment=borg_environment, + borg_local_path=local_path, ) else: execute_command( diff --git a/borgmatic/borg/info.py b/borgmatic/borg/info.py index 9a8bdda2..3e596ca4 100644 --- a/borgmatic/borg/info.py +++ b/borgmatic/borg/info.py @@ -66,6 +66,7 @@ def display_archives_info( return execute_command_and_capture_output( full_command, extra_environment=environment.make_environment(config), + borg_local_path=local_path, ) else: execute_command( diff --git a/borgmatic/borg/list.py b/borgmatic/borg/list.py index b3db8e90..5a245d97 100644 --- a/borgmatic/borg/list.py +++ b/borgmatic/borg/list.py @@ -123,6 +123,7 @@ def capture_archive_listing( remote_path, ), extra_environment=borg_environment, + borg_local_path=local_path, ) .strip('\n') .split('\n') @@ -217,6 +218,7 @@ def list_archive( remote_path, ), extra_environment=borg_environment, + borg_local_path=local_path, ) .strip('\n') .split('\n') diff --git a/borgmatic/borg/rinfo.py b/borgmatic/borg/rinfo.py index a7ae8229..ab4197e6 100644 --- a/borgmatic/borg/rinfo.py +++ b/borgmatic/borg/rinfo.py @@ -54,6 +54,7 @@ def display_repository_info( return execute_command_and_capture_output( full_command, extra_environment=extra_environment, + borg_local_path=local_path, ) else: execute_command( diff --git a/borgmatic/borg/rlist.py b/borgmatic/borg/rlist.py index b532a6aa..b6ceca31 100644 --- a/borgmatic/borg/rlist.py +++ b/borgmatic/borg/rlist.py @@ -43,6 +43,7 @@ def resolve_archive_name( output = execute_command_and_capture_output( full_command, extra_environment=environment.make_environment(config), + borg_local_path=local_path, ) try: latest_archive = output.strip().splitlines()[-1] @@ -138,7 +139,9 @@ def list_repository( ) if rlist_arguments.json: - return execute_command_and_capture_output(main_command, extra_environment=borg_environment) + return execute_command_and_capture_output( + main_command, extra_environment=borg_environment, borg_local_path=local_path + ) else: execute_command( main_command, diff --git a/borgmatic/borg/version.py b/borgmatic/borg/version.py index feb677ad..9ded62a7 100644 --- a/borgmatic/borg/version.py +++ b/borgmatic/borg/version.py @@ -21,6 +21,7 @@ def local_borg_version(config, local_path='borg'): output = execute_command_and_capture_output( full_command, extra_environment=environment.make_environment(config), + borg_local_path=local_path, ) try: diff --git a/borgmatic/commands/borgmatic.py b/borgmatic/commands/borgmatic.py index af87ad67..8f61a0d3 100644 --- a/borgmatic/commands/borgmatic.py +++ b/borgmatic/commands/borgmatic.py @@ -141,6 +141,7 @@ def run_configuration(config_filename, config, arguments): f'{repository.get("label", repository["path"])}: Error running actions for repository', error, levelno=logging.WARNING, + log_command_error_output=True, ) ) logger.warning( @@ -530,24 +531,29 @@ def load_configurations(config_filenames, overrides=None, resolve_env=True): return (configs, logs) -def log_record(**kwargs): +def log_record(suppress_log=False, **kwargs): ''' Create a log record based on the given makeLogRecord() arguments, one of which must be - named "levelno". Log the record and return it. + named "levelno". Log the record (unless suppress log is set) and return it. ''' record = logging.makeLogRecord(kwargs) - logger.handle(record) + if suppress_log: + return record + logger.handle(record) return record MAX_CAPTURED_OUTPUT_LENGTH = 1000 -def log_error_records(message, error=None, levelno=logging.CRITICAL): +def log_error_records( + message, error=None, levelno=logging.CRITICAL, log_command_error_output=False +): ''' - Given error message text, an optional exception object, and an optional log level, log error - summary information and also yield it as a series of logging.LogRecord instances. + Given error message text, an optional exception object, an optional log level, and whether to + log the error output of a CalledProcessError (if any), log error summary information and also + yield it as a series of logging.LogRecord instances. Note that because the logs are yielded as a generator, logs won't get logged unless you consume the generator output. @@ -563,12 +569,18 @@ def log_error_records(message, error=None, levelno=logging.CRITICAL): except CalledProcessError as error: yield log_record(levelno=levelno, levelname=level_name, msg=message) if error.output: - output = error.output.decode('utf-8') + try: + output = error.output.decode('utf-8') + except (UnicodeDecodeError, AttributeError): + output = error.output + + # Suppress these logs for now and save full error output for the log summary at the end. yield log_record( levelno=levelno, levelname=level_name, msg=output[:MAX_CAPTURED_OUTPUT_LENGTH] + ' ...' * (len(output) > MAX_CAPTURED_OUTPUT_LENGTH), + suppress_log=True, ) yield log_record(levelno=levelno, levelname=level_name, msg=error) except (ValueError, OSError) as error: diff --git a/borgmatic/execute.py b/borgmatic/execute.py index 39691dac..9238a0c3 100644 --- a/borgmatic/execute.py +++ b/borgmatic/execute.py @@ -241,13 +241,16 @@ def execute_command_and_capture_output( shell=False, extra_environment=None, working_directory=None, + borg_local_path=None, ): ''' Execute the given command (a sequence of command/argument strings), capturing and returning its output (stdout). If capture stderr is True, then capture and return stderr in addition to stdout. If shell is True, execute the command within a shell. If an extra environment dict is given, then use it to augment the current environment, and pass the result into the command. If - a working directory is given, use that as the present working directory when running the command. + a working directory is given, use that as the present working directory when running the + command. If a Borg local path is given, and the command matches it (regardless of arguments), + treat exit code 1 as a warning instead of an error. Raise subprocesses.CalledProcessError if an error occurs while running the command. ''' @@ -264,7 +267,7 @@ def execute_command_and_capture_output( cwd=working_directory, ) except subprocess.CalledProcessError as error: - if exit_code_indicates_error(command, error.returncode): + if exit_code_indicates_error(command, error.returncode, borg_local_path): raise output = error.output diff --git a/tests/unit/borg/test_create.py b/tests/unit/borg/test_create.py index 5b196d9b..dfea86e2 100644 --- a/tests/unit/borg/test_create.py +++ b/tests/unit/borg/test_create.py @@ -451,13 +451,14 @@ def test_collect_special_file_paths_omits_exclude_no_dump_flag_from_command(): capture_stderr=True, working_directory=None, extra_environment=None, + borg_local_path='borg', ).and_return('Processing files ...\n- /foo\n+ /bar\n- /baz').once() flexmock(module).should_receive('special_file').and_return(True) flexmock(module).should_receive('any_parent_directories').and_return(False) module.collect_special_file_paths( ('borg', 'create', '--exclude-nodump'), - local_path=None, + local_path='borg', working_directory=None, borg_environment=None, skip_directories=flexmock(), @@ -758,6 +759,7 @@ def test_create_archive_with_log_info_and_json_suppresses_most_borg_output(): ('borg', 'create') + REPO_ARCHIVE_WITH_PATHS + ('--json',), working_directory=None, extra_environment=None, + borg_local_path='borg', ) insert_logging_mock(logging.INFO) @@ -842,6 +844,7 @@ def test_create_archive_with_log_debug_and_json_suppresses_most_borg_output(): ('borg', 'create') + REPO_ARCHIVE_WITH_PATHS + ('--json',), working_directory=None, extra_environment=None, + borg_local_path='borg', ) insert_logging_mock(logging.DEBUG) @@ -2235,6 +2238,7 @@ def test_create_archive_with_json_calls_borg_with_json_parameter(): ('borg', 'create') + REPO_ARCHIVE_WITH_PATHS + ('--json',), working_directory=None, extra_environment=None, + borg_local_path='borg', ).and_return('[]') json_output = module.create_archive( @@ -2277,6 +2281,7 @@ def test_create_archive_with_stats_and_json_calls_borg_without_stats_parameter() ('borg', 'create') + REPO_ARCHIVE_WITH_PATHS + ('--json',), working_directory=None, extra_environment=None, + borg_local_path='borg', ).and_return('[]') json_output = module.create_archive( diff --git a/tests/unit/borg/test_info.py b/tests/unit/borg/test_info.py index 3e93bb73..107c4863 100644 --- a/tests/unit/borg/test_info.py +++ b/tests/unit/borg/test_info.py @@ -73,6 +73,7 @@ def test_display_archives_info_with_log_info_and_json_suppresses_most_borg_outpu flexmock(module).should_receive('execute_command_and_capture_output').with_args( ('borg', 'info', '--json', '--repo', 'repo'), extra_environment=None, + borg_local_path='borg', ).and_return('[]') insert_logging_mock(logging.INFO) @@ -127,6 +128,7 @@ def test_display_archives_info_with_log_debug_and_json_suppresses_most_borg_outp flexmock(module).should_receive('execute_command_and_capture_output').with_args( ('borg', 'info', '--json', '--repo', 'repo'), extra_environment=None, + borg_local_path='borg', ).and_return('[]') insert_logging_mock(logging.DEBUG) @@ -154,6 +156,7 @@ def test_display_archives_info_with_json_calls_borg_with_json_parameter(): flexmock(module).should_receive('execute_command_and_capture_output').with_args( ('borg', 'info', '--json', '--repo', 'repo'), extra_environment=None, + borg_local_path='borg', ).and_return('[]') json_output = module.display_archives_info( diff --git a/tests/unit/borg/test_list.py b/tests/unit/borg/test_list.py index 2f82b802..4d1d5346 100644 --- a/tests/unit/borg/test_list.py +++ b/tests/unit/borg/test_list.py @@ -429,6 +429,7 @@ def test_list_archive_calls_borg_multiple_times_with_find_paths(): flexmock(module).should_receive('execute_command_and_capture_output').with_args( ('borg', 'list', 'repo'), extra_environment=None, + borg_local_path='borg', ).and_return('archive1\narchive2').once() flexmock(module).should_receive('make_list_command').and_return( ('borg', 'list', 'repo::archive1') @@ -667,6 +668,7 @@ def test_list_archive_with_find_paths_allows_archive_filter_flag_but_only_passes flexmock(module).should_receive('execute_command_and_capture_output').with_args( ('borg', 'rlist', '--repo', 'repo'), extra_environment=None, + borg_local_path='borg', ).and_return('archive1\narchive2').once() flexmock(module).should_receive('make_list_command').with_args( diff --git a/tests/unit/borg/test_rinfo.py b/tests/unit/borg/test_rinfo.py index 8628b9aa..ee5e5c24 100644 --- a/tests/unit/borg/test_rinfo.py +++ b/tests/unit/borg/test_rinfo.py @@ -97,6 +97,7 @@ def test_display_repository_info_with_log_info_and_json_suppresses_most_borg_out flexmock(module).should_receive('execute_command_and_capture_output').with_args( ('borg', 'rinfo', '--json', '--repo', 'repo'), extra_environment=None, + borg_local_path='borg', ).and_return('[]') insert_logging_mock(logging.INFO) @@ -153,6 +154,7 @@ def test_display_repository_info_with_log_debug_and_json_suppresses_most_borg_ou flexmock(module).should_receive('execute_command_and_capture_output').with_args( ('borg', 'rinfo', '--json', '--repo', 'repo'), extra_environment=None, + borg_local_path='borg', ).and_return('[]') insert_logging_mock(logging.DEBUG) @@ -181,6 +183,7 @@ def test_display_repository_info_with_json_calls_borg_with_json_flag(): flexmock(module).should_receive('execute_command_and_capture_output').with_args( ('borg', 'rinfo', '--json', '--repo', 'repo'), extra_environment=None, + borg_local_path='borg', ).and_return('[]') json_output = module.display_repository_info( diff --git a/tests/unit/borg/test_rlist.py b/tests/unit/borg/test_rlist.py index 65fcef1d..a61a837e 100644 --- a/tests/unit/borg/test_rlist.py +++ b/tests/unit/borg/test_rlist.py @@ -37,6 +37,7 @@ def test_resolve_archive_name_calls_borg_with_flags(): flexmock(module).should_receive('execute_command_and_capture_output').with_args( ('borg', 'list') + BORG_LIST_LATEST_ARGUMENTS, extra_environment=None, + borg_local_path='borg', ).and_return(expected_archive + '\n') assert ( @@ -57,6 +58,7 @@ def test_resolve_archive_name_with_log_info_calls_borg_without_info_flag(): flexmock(module).should_receive('execute_command_and_capture_output').with_args( ('borg', 'list') + BORG_LIST_LATEST_ARGUMENTS, extra_environment=None, + borg_local_path='borg', ).and_return(expected_archive + '\n') insert_logging_mock(logging.INFO) @@ -78,6 +80,7 @@ def test_resolve_archive_name_with_log_debug_calls_borg_without_debug_flag(): flexmock(module).should_receive('execute_command_and_capture_output').with_args( ('borg', 'list') + BORG_LIST_LATEST_ARGUMENTS, extra_environment=None, + borg_local_path='borg', ).and_return(expected_archive + '\n') insert_logging_mock(logging.DEBUG) @@ -99,6 +102,7 @@ def test_resolve_archive_name_with_local_path_calls_borg_via_local_path(): flexmock(module).should_receive('execute_command_and_capture_output').with_args( ('borg1', 'list') + BORG_LIST_LATEST_ARGUMENTS, extra_environment=None, + borg_local_path='borg1', ).and_return(expected_archive + '\n') assert ( @@ -120,6 +124,7 @@ def test_resolve_archive_name_with_remote_path_calls_borg_with_remote_path_flags flexmock(module).should_receive('execute_command_and_capture_output').with_args( ('borg', 'list', '--remote-path', 'borg1') + BORG_LIST_LATEST_ARGUMENTS, extra_environment=None, + borg_local_path='borg', ).and_return(expected_archive + '\n') assert ( @@ -140,6 +145,7 @@ def test_resolve_archive_name_without_archives_raises(): flexmock(module).should_receive('execute_command_and_capture_output').with_args( ('borg', 'list') + BORG_LIST_LATEST_ARGUMENTS, extra_environment=None, + borg_local_path='borg', ).and_return('') with pytest.raises(ValueError): @@ -159,6 +165,7 @@ def test_resolve_archive_name_with_log_json_calls_borg_with_log_json_flags(): flexmock(module).should_receive('execute_command_and_capture_output').with_args( ('borg', 'list', '--log-json') + BORG_LIST_LATEST_ARGUMENTS, extra_environment=None, + borg_local_path='borg', ).and_return(expected_archive + '\n') assert ( @@ -180,6 +187,7 @@ def test_resolve_archive_name_with_lock_wait_calls_borg_with_lock_wait_flags(): flexmock(module).should_receive('execute_command_and_capture_output').with_args( ('borg', 'list', '--lock-wait', 'okay') + BORG_LIST_LATEST_ARGUMENTS, extra_environment=None, + borg_local_path='borg', ).and_return(expected_archive + '\n') assert ( diff --git a/tests/unit/borg/test_version.py b/tests/unit/borg/test_version.py index a051f693..a00235a5 100644 --- a/tests/unit/borg/test_version.py +++ b/tests/unit/borg/test_version.py @@ -17,6 +17,7 @@ def insert_execute_command_and_capture_output_mock( flexmock(module).should_receive('execute_command_and_capture_output').with_args( command, extra_environment=None, + borg_local_path=borg_local_path, ).once().and_return(version_output) diff --git a/tests/unit/commands/test_borgmatic.py b/tests/unit/commands/test_borgmatic.py index 2867a408..1c44e281 100644 --- a/tests/unit/commands/test_borgmatic.py +++ b/tests/unit/commands/test_borgmatic.py @@ -238,6 +238,7 @@ def test_run_configuration_retries_hard_error(): 'foo: Error running actions for repository', OSError, levelno=logging.WARNING, + log_command_error_output=True, ).and_return([flexmock()]) error_logs = [flexmock()] flexmock(module).should_receive('log_error_records').with_args( @@ -277,11 +278,13 @@ def test_run_configuration_retries_round_robin(): 'foo: Error running actions for repository', OSError, levelno=logging.WARNING, + log_command_error_output=True, ).and_return([flexmock()]).ordered() flexmock(module).should_receive('log_error_records').with_args( 'bar: Error running actions for repository', OSError, levelno=logging.WARNING, + log_command_error_output=True, ).and_return([flexmock()]).ordered() foo_error_logs = [flexmock()] flexmock(module).should_receive('log_error_records').with_args( @@ -311,11 +314,13 @@ def test_run_configuration_retries_one_passes(): 'foo: Error running actions for repository', OSError, levelno=logging.WARNING, + log_command_error_output=True, ).and_return([flexmock()]).ordered() flexmock(module).should_receive('log_error_records').with_args( 'bar: Error running actions for repository', OSError, levelno=logging.WARNING, + log_command_error_output=True, ).and_return(flexmock()).ordered() error_logs = [flexmock()] flexmock(module).should_receive('log_error_records').with_args( @@ -339,6 +344,7 @@ def test_run_configuration_retry_wait(): 'foo: Error running actions for repository', OSError, levelno=logging.WARNING, + log_command_error_output=True, ).and_return([flexmock()]).ordered() flexmock(time).should_receive('sleep').with_args(10).and_return().ordered() @@ -346,6 +352,7 @@ def test_run_configuration_retry_wait(): 'foo: Error running actions for repository', OSError, levelno=logging.WARNING, + log_command_error_output=True, ).and_return([flexmock()]).ordered() flexmock(time).should_receive('sleep').with_args(20).and_return().ordered() @@ -353,6 +360,7 @@ def test_run_configuration_retry_wait(): 'foo: Error running actions for repository', OSError, levelno=logging.WARNING, + log_command_error_output=True, ).and_return([flexmock()]).ordered() flexmock(time).should_receive('sleep').with_args(30).and_return().ordered() @@ -381,11 +389,13 @@ def test_run_configuration_retries_timeout_multiple_repos(): 'foo: Error running actions for repository', OSError, levelno=logging.WARNING, + log_command_error_output=True, ).and_return([flexmock()]).ordered() flexmock(module).should_receive('log_error_records').with_args( 'bar: Error running actions for repository', OSError, levelno=logging.WARNING, + log_command_error_output=True, ).and_return([flexmock()]).ordered() # Sleep before retrying foo (and passing) @@ -816,6 +826,10 @@ def test_log_record_does_not_raise(): module.log_record(levelno=1, foo='bar', baz='quux') +def test_log_record_with_suppress_does_not_raise(): + module.log_record(levelno=1, foo='bar', baz='quux', suppress_log=True) + + def test_log_error_records_generates_output_logs_for_message_only(): flexmock(module).should_receive('log_record').replace_with(dict) @@ -824,7 +838,7 @@ def test_log_error_records_generates_output_logs_for_message_only(): assert {log['levelno'] for log in logs} == {logging.CRITICAL} -def test_log_error_records_generates_output_logs_for_called_process_error(): +def test_log_error_records_generates_output_logs_for_called_process_error_with_bytes_ouput(): flexmock(module).should_receive('log_record').replace_with(dict) flexmock(module.logger).should_receive('getEffectiveLevel').and_return(logging.WARNING) @@ -836,6 +850,18 @@ def test_log_error_records_generates_output_logs_for_called_process_error(): assert any(log for log in logs if 'error output' in str(log)) +def test_log_error_records_generates_output_logs_for_called_process_error_with_string_ouput(): + flexmock(module).should_receive('log_record').replace_with(dict) + flexmock(module.logger).should_receive('getEffectiveLevel').and_return(logging.WARNING) + + logs = tuple( + module.log_error_records('Error', subprocess.CalledProcessError(1, 'ls', 'error output')) + ) + + assert {log['levelno'] for log in logs} == {logging.CRITICAL} + assert any(log for log in logs if 'error output' in str(log)) + + def test_log_error_records_generates_logs_for_value_error(): flexmock(module).should_receive('log_record').replace_with(dict)