diff --git a/NEWS b/NEWS index 7bbc24d6..8c2dc6e2 100644 --- a/NEWS +++ b/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 diff --git a/borgmatic/execute.py b/borgmatic/execute.py index a6741c90..8760703e 100644 --- a/borgmatic/execute.py +++ b/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): ''' diff --git a/setup.py b/setup.py index dc585bac..393a9cb0 100644 --- a/setup.py +++ b/setup.py @@ -1,6 +1,6 @@ from setuptools import find_packages, setup -VERSION = '1.6.4' +VERSION = '1.6.5.dev0' setup( diff --git a/tests/integration/test_execute.py b/tests/integration/test_execute.py index 51aa5f43..1647a9e0 100644 --- a/tests/integration/test_execute.py +++ b/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)