Merge log output functions into one.

This commit is contained in:
Dan Helfman 2020-05-11 10:55:50 -07:00
parent f7c93ea2e8
commit 695c764a01
3 changed files with 24 additions and 68 deletions

View file

@ -30,45 +30,6 @@ def process_command(process):
return process.args if isinstance(process.args, str) else ' '.join(process.args) 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): def output_buffer_for_process(process, exclude_stdouts):
''' '''
Given an instance of subprocess.Popen and a sequence of stdouts to exclude, return either the 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 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 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 process with the requested log level. Additionally, raise a CalledProcessError if a process
@ -213,12 +174,7 @@ def execute_command(
return None return None
log_output( log_outputs((process,), (input_file, output_file), output_log_level, error_on_warnings)
process,
process.stderr if output_file else process.stdout,
output_log_level,
error_on_warnings,
)
def execute_command_with_processes( def execute_command_with_processes(
@ -274,7 +230,7 @@ def execute_command_with_processes(
process.kill() process.kill()
raise raise
log_many_outputs( log_outputs(
tuple(processes) + (command_process,), tuple(processes) + (command_process,),
(input_file, output_file), (input_file, output_file),
output_log_level, output_log_level,

View file

@ -7,38 +7,38 @@ from flexmock import flexmock
from borgmatic import execute as module 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, 'hi').once()
flexmock(module.logger).should_receive('log').with_args(logging.INFO, 'there').once() flexmock(module.logger).should_receive('log').with_args(logging.INFO, 'there').once()
flexmock(module).should_receive('exit_code_indicates_error').and_return(False) flexmock(module).should_receive('exit_code_indicates_error').and_return(False)
hi_process = subprocess.Popen(['echo', 'hi'], stdout=subprocess.PIPE) hi_process = subprocess.Popen(['echo', 'hi'], stdout=subprocess.PIPE)
module.log_output( module.log_outputs(
hi_process, hi_process.stdout, output_log_level=logging.INFO, error_on_warnings=False (hi_process,), exclude_stdouts=(), output_log_level=logging.INFO, error_on_warnings=False
) )
there_process = subprocess.Popen(['echo', 'there'], stdout=subprocess.PIPE) there_process = subprocess.Popen(['echo', 'there'], stdout=subprocess.PIPE)
module.log_output( module.log_outputs(
there_process, there_process.stdout, output_log_level=logging.INFO, error_on_warnings=False (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.logger).should_receive('log')
flexmock(module).should_receive('exit_code_indicates_error').and_return(True) flexmock(module).should_receive('exit_code_indicates_error').and_return(True)
process = subprocess.Popen(['grep'], stdout=subprocess.PIPE, stderr=subprocess.STDOUT) process = subprocess.Popen(['grep'], stdout=subprocess.PIPE, stderr=subprocess.STDOUT)
with pytest.raises(subprocess.CalledProcessError) as error: with pytest.raises(subprocess.CalledProcessError) as error:
module.log_output( module.log_outputs(
process, process.stdout, output_log_level=logging.INFO, error_on_warnings=False (process,), exclude_stdouts=(), output_log_level=logging.INFO, error_on_warnings=False
) )
assert error.value.returncode == 2 assert error.value.returncode == 2
assert error.value.output 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).ERROR_OUTPUT_MAX_LINE_COUNT = 0
flexmock(module.logger).should_receive('log') flexmock(module.logger).should_receive('log')
flexmock(module).should_receive('exit_code_indicates_error').and_return(True) 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) process = subprocess.Popen(['grep'], stdout=subprocess.PIPE, stderr=subprocess.STDOUT)
with pytest.raises(subprocess.CalledProcessError) as error: with pytest.raises(subprocess.CalledProcessError) as error:
module.log_output( module.log_outputs(
process, process.stdout, output_log_level=logging.INFO, error_on_warnings=False (process,), exclude_stdouts=(), output_log_level=logging.INFO, error_on_warnings=False
) )
assert error.value.returncode == 2 assert error.value.returncode == 2
assert error.value.output.startswith('...') 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.logger).should_receive('log').never()
flexmock(module).should_receive('exit_code_indicates_error').and_return(False) flexmock(module).should_receive('exit_code_indicates_error').and_return(False)
process = subprocess.Popen(['true'], stdout=subprocess.PIPE, stderr=subprocess.STDOUT) process = subprocess.Popen(['true'], stdout=subprocess.PIPE, stderr=subprocess.STDOUT)
module.log_output( module.log_outputs(
process, process.stdout, output_log_level=logging.INFO, error_on_warnings=False (process,), exclude_stdouts=(), output_log_level=logging.INFO, error_on_warnings=False
) )

View file

@ -49,7 +49,7 @@ def test_execute_command_calls_full_command():
env=None, env=None,
cwd=None, cwd=None,
).and_return(flexmock(stdout=None)).once() ).and_return(flexmock(stdout=None)).once()
flexmock(module).should_receive('log_output') flexmock(module).should_receive('log_outputs')
output = module.execute_command(full_command) output = module.execute_command(full_command)
@ -69,7 +69,7 @@ def test_execute_command_calls_full_command_with_output_file():
env=None, env=None,
cwd=None, cwd=None,
).and_return(flexmock(stderr=None)).once() ).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) 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, env=None,
cwd=None, cwd=None,
).and_return(flexmock(stdout=None)).once() ).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) 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, env=None,
cwd=None, cwd=None,
).and_return(flexmock(stdout=None)).once() ).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) 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'}, env={'a': 'b', 'c': 'd'},
cwd=None, cwd=None,
).and_return(flexmock(stdout=None)).once() ).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'}) 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, env=None,
cwd='/working', cwd='/working',
).and_return(flexmock(stdout=None)).once() ).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') 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, env=None,
cwd=None, cwd=None,
).and_return(process).once() ).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 assert module.execute_command(full_command, run_to_completion=False) == process