From bd9d592560213f0c4d6ab8cb30ffb7fc81660988 Mon Sep 17 00:00:00 2001 From: Dan Helfman Date: Mon, 10 Jul 2023 10:20:51 -0700 Subject: [PATCH] Truncate long command error output. --- NEWS | 2 ++ borgmatic/commands/borgmatic.py | 27 ++++++++++++--------------- tests/unit/commands/test_borgmatic.py | 16 +--------------- 3 files changed, 15 insertions(+), 30 deletions(-) diff --git a/NEWS b/NEWS index 2831f29..1638e08 100644 --- a/NEWS +++ b/NEWS @@ -20,6 +20,8 @@ * All deprecated configuration option values now generate warning logs. * Remove the deprecated (and non-functional) "--excludes" flag in favor of excludes within configuration. + * Fix an error when logging too-long command output during error handling. Now, long command output + is truncated before logging. 1.7.15 * #326: Add configuration options and command-line flags for backing up a database from one diff --git a/borgmatic/commands/borgmatic.py b/borgmatic/commands/borgmatic.py index a869594..af87ad6 100644 --- a/borgmatic/commands/borgmatic.py +++ b/borgmatic/commands/borgmatic.py @@ -141,7 +141,6 @@ 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( @@ -531,26 +530,24 @@ def load_configurations(config_filenames, overrides=None, resolve_env=True): return (configs, logs) -def log_record(suppress_log=False, **kwargs): +def log_record(**kwargs): ''' Create a log record based on the given makeLogRecord() arguments, one of which must be - named "levelno". Log the record (unless suppress log is set) and return it. + named "levelno". Log the record and return it. ''' record = logging.makeLogRecord(kwargs) - if suppress_log: - return record - logger.handle(record) + return record -def log_error_records( - message, error=None, levelno=logging.CRITICAL, log_command_error_output=False -): +MAX_CAPTURED_OUTPUT_LENGTH = 1000 + + +def log_error_records(message, error=None, levelno=logging.CRITICAL): ''' - 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. + 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. Note that because the logs are yielded as a generator, logs won't get logged unless you consume the generator output. @@ -566,12 +563,12 @@ def log_error_records( except CalledProcessError as error: yield log_record(levelno=levelno, levelname=level_name, msg=message) if error.output: - # Suppress these logs for now and save full error output for the log summary at the end. + output = error.output.decode('utf-8') yield log_record( levelno=levelno, levelname=level_name, - msg=error.output, - suppress_log=not log_command_error_output, + msg=output[:MAX_CAPTURED_OUTPUT_LENGTH] + + ' ...' * (len(output) > MAX_CAPTURED_OUTPUT_LENGTH), ) yield log_record(levelno=levelno, levelname=level_name, msg=error) except (ValueError, OSError) as error: diff --git a/tests/unit/commands/test_borgmatic.py b/tests/unit/commands/test_borgmatic.py index e94bdd8..2867a40 100644 --- a/tests/unit/commands/test_borgmatic.py +++ b/tests/unit/commands/test_borgmatic.py @@ -238,7 +238,6 @@ 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( @@ -278,13 +277,11 @@ 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( @@ -314,13 +311,11 @@ 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( @@ -344,7 +339,6 @@ 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() @@ -352,7 +346,6 @@ 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() @@ -360,7 +353,6 @@ 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() @@ -389,13 +381,11 @@ 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) @@ -826,10 +816,6 @@ 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) @@ -843,7 +829,7 @@ def test_log_error_records_generates_output_logs_for_called_process_error(): flexmock(module.logger).should_receive('getEffectiveLevel').and_return(logging.WARNING) logs = tuple( - module.log_error_records('Error', subprocess.CalledProcessError(1, 'ls', 'error output')) + module.log_error_records('Error', subprocess.CalledProcessError(1, 'ls', b'error output')) ) assert {log['levelno'] for log in logs} == {logging.CRITICAL}