Fix error handling to log command output as one record per line (#754).

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

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.
+            # 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[:MAX_CAPTURED_OUTPUT_LENGTH]
-                + ' ...' * (len(output) > MAX_CAPTURED_OUTPUT_LENGTH),
+                    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)

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