Truncate long command error output.

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

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:

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}