psw/borgmatic
1
0
Fork 0
Code Issues Pull requests Projects Releases Packages Wiki Activity Actions

Truncate long command output without assuming an encoded byte string.

Browse source
This commit is contained in:
Dan Helfman 2023-07-10 11:16:18 -07:00
parent bd9d592560
commit e8dbca9d68
15 changed files with 85 additions and 12 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

2
borgmatic/borg/create.py
View file

@ -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(

1
borgmatic/borg/info.py
View file

@ -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(

2
borgmatic/borg/list.py
View file

@ -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')

1
borgmatic/borg/rinfo.py
View file

@ -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(

5
borgmatic/borg/rlist.py
View file

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

1
borgmatic/borg/version.py
View file

@ -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:

26
borgmatic/commands/borgmatic.py
View file

@ -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:

7
borgmatic/execute.py
View file

@ -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

7
tests/unit/borg/test_create.py
View file

@ -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(

3
tests/unit/borg/test_info.py
View file

@ -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(

2
tests/unit/borg/test_list.py
View file

@ -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(

3
tests/unit/borg/test_rinfo.py
View file

@ -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(

8
tests/unit/borg/test_rlist.py
View file

@ -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 (

1
tests/unit/borg/test_version.py
View file

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

28
tests/unit/commands/test_borgmatic.py
View file

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