From 5912769273d360c2996c6f33a04878299aec2506 Mon Sep 17 00:00:00 2001 From: Dan Helfman Date: Thu, 14 Sep 2023 21:10:52 -0700 Subject: [PATCH] Fix error handling to log command output as one record per line (#754). --- NEWS | 2 ++ borgmatic/commands/borgmatic.py | 23 ++++++++++++----------- tests/unit/commands/test_borgmatic.py | 26 ++++++++++++++++++++------ 3 files changed, 34 insertions(+), 17 deletions(-) diff --git a/NEWS b/NEWS index 3c89e46..8e24ca9 100644 --- a/NEWS +++ b/NEWS @@ -4,6 +4,8 @@ https://torsion.org/borgmatic/docs/how-to/monitor-your-backups/#loki-hook * #753: When "archive_name_format" is not set, filter archives using the default archive name format. + * #754: Fix error handling to log command output as one record per line instead of truncating + too-long output and swallowing the end of some Borg error messages. * Update documentation to recommend installing/upgrading borgmatic with pipx instead of pip. See the documentation for more information: https://torsion.org/borgmatic/docs/how-to/set-up-backups/#installation diff --git a/borgmatic/commands/borgmatic.py b/borgmatic/commands/borgmatic.py index 40584be..ba80d2c 100644 --- a/borgmatic/commands/borgmatic.py +++ b/borgmatic/commands/borgmatic.py @@ -555,9 +555,6 @@ def log_record(suppress_log=False, **kwargs): return record -MAX_CAPTURED_OUTPUT_LENGTH = 1000 - - def log_error_records( message, error=None, levelno=logging.CRITICAL, log_command_error_output=False ): @@ -579,20 +576,24 @@ def log_error_records( raise error except CalledProcessError as error: yield log_record(levelno=levelno, levelname=level_name, msg=message) + if error.output: 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, - ) + # Suppress these logs for now and save the error output for the log summary at the end. + # Log a separate record per line, as some errors can be really verbose and overflow the + # per-record size limits imposed by some logging backends. + for output_line in output.splitlines(): + yield log_record( + levelno=levelno, + levelname=level_name, + msg=output_line, + suppress_log=True, + ) + yield log_record(levelno=levelno, levelname=level_name, msg=error) except (ValueError, OSError) as error: yield log_record(levelno=levelno, levelname=level_name, msg=message) diff --git a/tests/unit/commands/test_borgmatic.py b/tests/unit/commands/test_borgmatic.py index abed9cd..26321c3 100644 --- a/tests/unit/commands/test_borgmatic.py +++ b/tests/unit/commands/test_borgmatic.py @@ -849,7 +849,7 @@ def test_log_record_with_suppress_does_not_raise(): def test_log_error_records_generates_output_logs_for_message_only(): - flexmock(module).should_receive('log_record').replace_with(dict) + flexmock(module).should_receive('log_record').replace_with(dict).once() logs = tuple(module.log_error_records('Error')) @@ -857,7 +857,7 @@ def test_log_error_records_generates_output_logs_for_message_only(): 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).should_receive('log_record').replace_with(dict).times(3) flexmock(module.logger).should_receive('getEffectiveLevel').and_return(logging.WARNING) logs = tuple( @@ -869,7 +869,7 @@ def test_log_error_records_generates_output_logs_for_called_process_error_with_b 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).should_receive('log_record').replace_with(dict).times(3) flexmock(module.logger).should_receive('getEffectiveLevel').and_return(logging.WARNING) logs = tuple( @@ -880,8 +880,22 @@ def test_log_error_records_generates_output_logs_for_called_process_error_with_s assert any(log for log in logs if 'error output' in str(log)) +def test_log_error_records_splits_called_process_error_with_multiline_ouput_into_multiple_logs(): + flexmock(module).should_receive('log_record').replace_with(dict).times(4) + flexmock(module.logger).should_receive('getEffectiveLevel').and_return(logging.WARNING) + + logs = tuple( + module.log_error_records( + 'Error', subprocess.CalledProcessError(1, 'ls', 'error output\nanother line') + ) + ) + + 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) + flexmock(module).should_receive('log_record').replace_with(dict).twice() logs = tuple(module.log_error_records('Error', ValueError())) @@ -889,7 +903,7 @@ def test_log_error_records_generates_logs_for_value_error(): def test_log_error_records_generates_logs_for_os_error(): - flexmock(module).should_receive('log_record').replace_with(dict) + flexmock(module).should_receive('log_record').replace_with(dict).twice() logs = tuple(module.log_error_records('Error', OSError())) @@ -897,7 +911,7 @@ def test_log_error_records_generates_logs_for_os_error(): def test_log_error_records_generates_nothing_for_other_error(): - flexmock(module).should_receive('log_record').replace_with(dict) + flexmock(module).should_receive('log_record').never() logs = tuple(module.log_error_records('Error', KeyError()))