From 695c764a010f4bc1378d13854399d661217d1f67 Mon Sep 17 00:00:00 2001 From: Dan Helfman Date: Mon, 11 May 2020 10:55:50 -0700 Subject: [PATCH] Merge log output functions into one. --- borgmatic/execute.py | 50 ++----------------------------- tests/integration/test_execute.py | 28 ++++++++--------- tests/unit/test_execute.py | 14 ++++----- 3 files changed, 24 insertions(+), 68 deletions(-) diff --git a/borgmatic/execute.py b/borgmatic/execute.py index b8bb91a..86caa49 100644 --- a/borgmatic/execute.py +++ b/borgmatic/execute.py @@ -30,45 +30,6 @@ def process_command(process): return process.args if isinstance(process.args, str) else ' '.join(process.args) -def log_output(process, output_buffer, output_log_level, error_on_warnings): - ''' - Given an executed command's process opened by subprocess.Popen(), and the process' relevant - output buffer (stderr or stdout), log its output with the requested log level. Additionally, - raise a CalledProcessError if the process exits with an error (or a warning, if error on - warnings is True). - ''' - last_lines = [] - - while process.poll() is None: - line = output_buffer.readline().rstrip().decode() - if not line: - continue - - # Keep the last few lines of output in case the command errors, and we need the output for - # the exception below. - last_lines.append(line) - if len(last_lines) > ERROR_OUTPUT_MAX_LINE_COUNT: - last_lines.pop(0) - - logger.log(output_log_level, line) - - remaining_output = output_buffer.read().rstrip().decode() - if remaining_output: # pragma: no cover - logger.log(output_log_level, remaining_output) - - exit_code = process.poll() - - if exit_code_indicates_error(exit_code, error_on_warnings): - # If an error occurs, include its output in the raised exception so that we don't - # inadvertently hide error output. - if len(last_lines) == ERROR_OUTPUT_MAX_LINE_COUNT: - last_lines.insert(0, '...') - - raise subprocess.CalledProcessError( - exit_code, process_command(process), '\n'.join(last_lines) - ) - - def output_buffer_for_process(process, exclude_stdouts): ''' Given an instance of subprocess.Popen and a sequence of stdouts to exclude, return either the @@ -78,7 +39,7 @@ def output_buffer_for_process(process, exclude_stdouts): return process.stderr if process.stdout in exclude_stdouts else process.stdout -def log_many_outputs(processes, exclude_stdouts, output_log_level, error_on_warnings): +def log_outputs(processes, exclude_stdouts, output_log_level, error_on_warnings): ''' Given a sequence of subprocess.Popen() instances for multiple processes, log the output for each process with the requested log level. Additionally, raise a CalledProcessError if a process @@ -213,12 +174,7 @@ def execute_command( return None - log_output( - process, - process.stderr if output_file else process.stdout, - output_log_level, - error_on_warnings, - ) + log_outputs((process,), (input_file, output_file), output_log_level, error_on_warnings) def execute_command_with_processes( @@ -274,7 +230,7 @@ def execute_command_with_processes( process.kill() raise - log_many_outputs( + log_outputs( tuple(processes) + (command_process,), (input_file, output_file), output_log_level, diff --git a/tests/integration/test_execute.py b/tests/integration/test_execute.py index 1792fb4..fb3b3a9 100644 --- a/tests/integration/test_execute.py +++ b/tests/integration/test_execute.py @@ -7,38 +7,38 @@ from flexmock import flexmock from borgmatic import execute as module -def test_log_output_logs_each_line_separately(): +def test_log_outputs_logs_each_line_separately(): flexmock(module.logger).should_receive('log').with_args(logging.INFO, 'hi').once() flexmock(module.logger).should_receive('log').with_args(logging.INFO, 'there').once() flexmock(module).should_receive('exit_code_indicates_error').and_return(False) hi_process = subprocess.Popen(['echo', 'hi'], stdout=subprocess.PIPE) - module.log_output( - hi_process, hi_process.stdout, output_log_level=logging.INFO, error_on_warnings=False + module.log_outputs( + (hi_process,), exclude_stdouts=(), output_log_level=logging.INFO, error_on_warnings=False ) there_process = subprocess.Popen(['echo', 'there'], stdout=subprocess.PIPE) - module.log_output( - there_process, there_process.stdout, output_log_level=logging.INFO, error_on_warnings=False + module.log_outputs( + (there_process,), exclude_stdouts=(), output_log_level=logging.INFO, error_on_warnings=False ) -def test_log_output_includes_error_output_in_exception(): +def test_log_outputs_includes_error_output_in_exception(): flexmock(module.logger).should_receive('log') flexmock(module).should_receive('exit_code_indicates_error').and_return(True) process = subprocess.Popen(['grep'], stdout=subprocess.PIPE, stderr=subprocess.STDOUT) with pytest.raises(subprocess.CalledProcessError) as error: - module.log_output( - process, process.stdout, output_log_level=logging.INFO, error_on_warnings=False + module.log_outputs( + (process,), exclude_stdouts=(), output_log_level=logging.INFO, error_on_warnings=False ) assert error.value.returncode == 2 assert error.value.output -def test_log_output_truncates_long_error_output(): +def test_log_outputs_truncates_long_error_output(): flexmock(module).ERROR_OUTPUT_MAX_LINE_COUNT = 0 flexmock(module.logger).should_receive('log') flexmock(module).should_receive('exit_code_indicates_error').and_return(True) @@ -46,19 +46,19 @@ def test_log_output_truncates_long_error_output(): process = subprocess.Popen(['grep'], stdout=subprocess.PIPE, stderr=subprocess.STDOUT) with pytest.raises(subprocess.CalledProcessError) as error: - module.log_output( - process, process.stdout, output_log_level=logging.INFO, error_on_warnings=False + module.log_outputs( + (process,), exclude_stdouts=(), output_log_level=logging.INFO, error_on_warnings=False ) assert error.value.returncode == 2 assert error.value.output.startswith('...') -def test_log_output_with_no_output_logs_nothing(): +def test_log_outputs_with_no_output_logs_nothing(): flexmock(module.logger).should_receive('log').never() flexmock(module).should_receive('exit_code_indicates_error').and_return(False) process = subprocess.Popen(['true'], stdout=subprocess.PIPE, stderr=subprocess.STDOUT) - module.log_output( - process, process.stdout, output_log_level=logging.INFO, error_on_warnings=False + module.log_outputs( + (process,), exclude_stdouts=(), output_log_level=logging.INFO, error_on_warnings=False ) diff --git a/tests/unit/test_execute.py b/tests/unit/test_execute.py index dd18a80..7e37dbd 100644 --- a/tests/unit/test_execute.py +++ b/tests/unit/test_execute.py @@ -49,7 +49,7 @@ def test_execute_command_calls_full_command(): env=None, cwd=None, ).and_return(flexmock(stdout=None)).once() - flexmock(module).should_receive('log_output') + flexmock(module).should_receive('log_outputs') output = module.execute_command(full_command) @@ -69,7 +69,7 @@ def test_execute_command_calls_full_command_with_output_file(): env=None, cwd=None, ).and_return(flexmock(stderr=None)).once() - flexmock(module).should_receive('log_output') + flexmock(module).should_receive('log_outputs') output = module.execute_command(full_command, output_file=output_file) @@ -89,7 +89,7 @@ def test_execute_command_calls_full_command_with_input_file(): env=None, cwd=None, ).and_return(flexmock(stdout=None)).once() - flexmock(module).should_receive('log_output') + flexmock(module).should_receive('log_outputs') output = module.execute_command(full_command, input_file=input_file) @@ -108,7 +108,7 @@ def test_execute_command_calls_full_command_with_shell(): env=None, cwd=None, ).and_return(flexmock(stdout=None)).once() - flexmock(module).should_receive('log_output') + flexmock(module).should_receive('log_outputs') output = module.execute_command(full_command, shell=True) @@ -127,7 +127,7 @@ def test_execute_command_calls_full_command_with_extra_environment(): env={'a': 'b', 'c': 'd'}, cwd=None, ).and_return(flexmock(stdout=None)).once() - flexmock(module).should_receive('log_output') + flexmock(module).should_receive('log_outputs') output = module.execute_command(full_command, extra_environment={'c': 'd'}) @@ -146,7 +146,7 @@ def test_execute_command_calls_full_command_with_working_directory(): env=None, cwd='/working', ).and_return(flexmock(stdout=None)).once() - flexmock(module).should_receive('log_output') + flexmock(module).should_receive('log_outputs') output = module.execute_command(full_command, working_directory='/working') @@ -166,7 +166,7 @@ def test_execute_command_without_run_to_completion_returns_process(): env=None, cwd=None, ).and_return(process).once() - flexmock(module).should_receive('log_output') + flexmock(module).should_receive('log_outputs') assert module.execute_command(full_command, run_to_completion=False) == process