Fix logging to include the full traceback when Borg experiences an internal error (#553).

NEWS

@@ -1,3 +1,7 @@
+1.6.5.dev0
+ * #553: Fix logging to include the full traceback when Borg experiences an internal error, not just
+   the first few lines.
+
 1.6.4
  * #546, #382: Keep your repository passphrases and database passwords outside of borgmatic's
    configuration file with environment variable interpolation. See the documentation for more

borgmatic/execute.py

@@ -87,18 +87,19 @@ def log_outputs(processes, exclude_stdouts, output_log_level, borg_local_path):
                             # Add the process's output to output_buffers to ensure it'll get read.
                             output_buffers.append(other_process.stdout)
 
-                line = ready_buffer.readline().rstrip().decode()
-                if not line or not ready_process:
-                    continue
+                while True:
+                    line = ready_buffer.readline().rstrip().decode()
+                    if not line or not ready_process:
+                        break
 
-                # Keep the last few lines of output in case the process errors, and we need the output for
-                # the exception below.
-                last_lines = buffer_last_lines[ready_buffer]
-                last_lines.append(line)
-                if len(last_lines) > ERROR_OUTPUT_MAX_LINE_COUNT:
-                    last_lines.pop(0)
+                    # Keep the last few lines of output in case the process errors, and we need the output for
+                    # the exception below.
+                    last_lines = buffer_last_lines[ready_buffer]
+                    last_lines.append(line)
+                    if len(last_lines) > ERROR_OUTPUT_MAX_LINE_COUNT:
+                        last_lines.pop(0)
 
-                logger.log(output_log_level, line)
+                    logger.log(output_log_level, line)
 
         still_running = False
 
@@ -132,21 +133,6 @@ def log_outputs(processes, exclude_stdouts, output_log_level, borg_local_path):
         if not still_running:
             break
 
-    # Consume any remaining output that we missed (if any).
-    for process in processes:
-        output_buffer = output_buffer_for_process(process, exclude_stdouts)
-
-        if not output_buffer:
-            continue
-
-        while True:  # pragma: no cover
-            remaining_output = output_buffer.readline().rstrip().decode()
-
-            if not remaining_output:
-                break
-
-            logger.log(output_log_level, remaining_output)
-
 
 def log_command(full_command, input_file, output_file):
     '''

setup.py

@@ -1,6 +1,6 @@
 from setuptools import find_packages, setup
 
-VERSION = '1.6.4'
+VERSION = '1.6.5.dev0'
 
 
 setup(

tests/integration/test_execute.py

@@ -70,6 +70,27 @@ def test_log_outputs_includes_error_output_in_exception():
     assert error.value.output
 
 
+def test_log_outputs_logs_multiline_error_output():
+    '''
+    Make sure that all error output lines get logged, not just (for instance) the first few lines
+    of a process' traceback.
+    '''
+    flexmock(module.logger).should_receive('log')
+    flexmock(module).should_receive('exit_code_indicates_error').and_return(True)
+    flexmock(module).should_receive('command_for_process').and_return('grep')
+
+    process = subprocess.Popen(
+        ['python', '-c', 'foopydoo'], stdout=subprocess.PIPE, stderr=subprocess.STDOUT
+    )
+    flexmock(module).should_receive('output_buffer_for_process').and_return(process.stdout)
+    flexmock(module.logger).should_call('log').at_least().times(3)
+
+    with pytest.raises(subprocess.CalledProcessError):
+        module.log_outputs(
+            (process,), exclude_stdouts=(), output_log_level=logging.INFO, borg_local_path='borg'
+        )
+
+
 def test_log_outputs_skips_error_output_in_exception_for_process_with_none_stdout():
     flexmock(module.logger).should_receive('log')
     flexmock(module).should_receive('exit_code_indicates_error').and_return(True)