Flesh out missing test coverage for execute.py.

borgmatic/execute.py

@@ -47,6 +47,9 @@ def log_outputs(processes, exclude_stdouts, output_log_level, error_on_warnings)
 
     For simplicity, it's assumed that the output buffer for each process is its stdout. But if any
     stdouts are given to exclude, then for any matching processes, log from their stderr instead.
+
+    Note that stdout for a process can be None if output is intentionally not captured. In which
+    case it won't be logged.
     '''
     # Map from output buffer to sequence of last lines.
     buffer_last_lines = collections.defaultdict(list)
@@ -56,7 +59,11 @@ def log_outputs(processes, exclude_stdouts, output_log_level, error_on_warnings)
         if process.stdout or process.stderr
     ]
 
+    # Log output for each process until they all exit.
     while True:
+        if not output_buffers:
+            break
+
         (ready_buffers, _, _) = select.select(output_buffers, [], [])
 
         for ready_buffer in ready_buffers:
@@ -76,6 +83,7 @@ def log_outputs(processes, exclude_stdouts, output_log_level, error_on_warnings)
         if all(process.poll() is not None for process in processes):
             break
 
+    # Consume any remaining output that we missed (if any).
     for process in processes:
         output_buffer = output_buffer_for_process(process, exclude_stdouts)
 
@@ -87,8 +95,9 @@ def log_outputs(processes, exclude_stdouts, output_log_level, error_on_warnings)
         if remaining_output:  # pragma: no cover
             logger.log(output_log_level, remaining_output)
 
+    # If any process errored, then raise accordingly.
     for process in processes:
-        exit_code = process.poll()
+        exit_code = process.wait()
 
         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
@@ -116,6 +125,9 @@ def log_command(full_command, input_file, output_file):
     )
 
 
+# An sentinel passed as an output file to execute_command() to indicate that the command's output
+# should be allowed to flow through to stdout without being captured for logging. Useful for
+# commands with interactive prompts or those that mess directly with the console.
 DO_NOT_CAPTURE = object()
 
 
@@ -147,15 +159,16 @@ def execute_command(
     log_command(full_command, input_file, output_file)
     environment = {**os.environ, **extra_environment} if extra_environment else None
     do_not_capture = bool(output_file is DO_NOT_CAPTURE)
+    command = ' '.join(full_command) if shell else full_command
 
     if output_log_level is None:
         output = subprocess.check_output(
-            full_command, shell=shell, env=environment, cwd=working_directory
+            command, shell=shell, env=environment, cwd=working_directory
         )
         return output.decode() if output is not None else None
 
     process = subprocess.Popen(
-        ' '.join(full_command) if shell else full_command,
+        command,
         stdin=input_file,
         stdout=None if do_not_capture else (output_file or subprocess.PIPE),
         stderr=None if do_not_capture else (subprocess.PIPE if output_file else subprocess.STDOUT),
@@ -166,14 +179,6 @@ def execute_command(
     if not run_to_completion:
         return process
 
-    if do_not_capture:
-        exit_code = process.wait()
-
-        if exit_code_indicates_error(exit_code, error_on_warnings):
-            raise subprocess.CalledProcessError(exit_code, command_for_process(process))
-
-        return None
-
     log_outputs((process,), (input_file, output_file), output_log_level, error_on_warnings)
 
 
@@ -208,10 +213,11 @@ def execute_command_with_processes(
     log_command(full_command, input_file, output_file)
     environment = {**os.environ, **extra_environment} if extra_environment else None
     do_not_capture = bool(output_file is DO_NOT_CAPTURE)
+    command = ' '.join(full_command) if shell else full_command
 
     try:
         command_process = subprocess.Popen(
-            full_command,
+            command,
             stdin=input_file,
             stdout=None if do_not_capture else (output_file or subprocess.PIPE),
             stderr=None

tests/integration/test_execute.py

@@ -17,17 +17,39 @@ def test_log_outputs_logs_each_line_separately():
         hi_process, ()
     ).and_return(hi_process.stdout)
 
+    there_process = subprocess.Popen(['echo', 'there'], stdout=subprocess.PIPE)
+    flexmock(module).should_receive('output_buffer_for_process').with_args(
+        there_process, ()
+    ).and_return(there_process.stdout)
+
     module.log_outputs(
-        (hi_process,), exclude_stdouts=(), output_log_level=logging.INFO, error_on_warnings=False
+        (hi_process, there_process),
+        exclude_stdouts=(),
+        output_log_level=logging.INFO,
+        error_on_warnings=False,
     )
 
+
+def test_log_outputs_skips_logs_for_process_with_none_stdout():
+    flexmock(module.logger).should_receive('log').with_args(logging.INFO, 'hi').never()
+    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=None)
+    flexmock(module).should_receive('output_buffer_for_process').with_args(
+        hi_process, ()
+    ).and_return(hi_process.stdout)
+
     there_process = subprocess.Popen(['echo', 'there'], stdout=subprocess.PIPE)
     flexmock(module).should_receive('output_buffer_for_process').with_args(
         there_process, ()
     ).and_return(there_process.stdout)
 
     module.log_outputs(
-        (there_process,), exclude_stdouts=(), output_log_level=logging.INFO, error_on_warnings=False
+        (hi_process, there_process),
+        exclude_stdouts=(),
+        output_log_level=logging.INFO,
+        error_on_warnings=False,
     )
 
 
@@ -48,6 +70,23 @@ def test_log_outputs_includes_error_output_in_exception():
     assert error.value.output
 
 
+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)
+    flexmock(module).should_receive('command_for_process').and_return('grep')
+
+    process = subprocess.Popen(['grep'], stdout=None)
+    flexmock(module).should_receive('output_buffer_for_process').and_return(process.stdout)
+
+    with pytest.raises(subprocess.CalledProcessError) as error:
+        module.log_outputs(
+            (process,), exclude_stdouts=(), output_log_level=logging.INFO, error_on_warnings=False
+        )
+
+    assert error.value.returncode == 2
+    assert not error.value.output
+
+
 def test_log_outputs_truncates_long_error_output():
     flexmock(module).ERROR_OUTPUT_MAX_LINE_COUNT = 0
     flexmock(module.logger).should_receive('log')

tests/unit/test_execute.py

@@ -1,3 +1,5 @@
+import subprocess
+
 import pytest
 from flexmock import flexmock
 
@@ -24,17 +26,34 @@ def test_exit_code_indicates_error_respects_exit_code_and_error_on_warnings(
     )
 
 
-def output_buffer_for_process_returns_stderr_when_stdout_excluded():
+def test_command_for_process_converts_sequence_command_to_string():
+    process = flexmock(args=['foo', 'bar', 'baz'])
+
+    assert module.command_for_process(process) == 'foo bar baz'
+
+
+def test_command_for_process_passes_through_string_command():
+    process = flexmock(args='foo bar baz')
+
+    assert module.command_for_process(process) == 'foo bar baz'
+
+
+def test_output_buffer_for_process_returns_stderr_when_stdout_excluded():
+    stdout = flexmock()
+    stderr = flexmock()
+    process = flexmock(stdout=stdout, stderr=stderr)
+
+    assert module.output_buffer_for_process(process, exclude_stdouts=[flexmock(), stdout]) == stderr
+
+
+def test_output_buffer_for_process_returns_stdout_when_not_excluded():
     stdout = flexmock()
     process = flexmock(stdout=stdout)
 
-    module.output_buffer_for_process(process, excluded_stdouts=[flexmock(), stdout])
+    assert (
-
+        module.output_buffer_for_process(process, exclude_stdouts=[flexmock(), flexmock()])
-
+        == stdout
-def output_buffer_for_process_returns_stdout_when_not_excluded():
+    )
-    process = flexmock(stdout=flexmock())
-
-    module.output_buffer_for_process(process, excluded_stdouts=[flexmock(), flexmock()])
 
 
 def test_execute_command_calls_full_command():
@@ -76,6 +95,20 @@ def test_execute_command_calls_full_command_with_output_file():
     assert output is None
 
 
+def test_execute_command_calls_full_command_without_capturing_output():
+    full_command = ['foo', 'bar']
+    flexmock(module.os, environ={'a': 'b'})
+    flexmock(module.subprocess).should_receive('Popen').with_args(
+        full_command, stdin=None, stdout=None, stderr=None, shell=False, env=None, cwd=None
+    ).and_return(flexmock(wait=lambda: 0)).once()
+    flexmock(module).should_receive('exit_code_indicates_error').and_return(False)
+    flexmock(module).should_receive('log_outputs')
+
+    output = module.execute_command(full_command, output_file=module.DO_NOT_CAPTURE)
+
+    assert output is None
+
+
 def test_execute_command_calls_full_command_with_input_file():
     full_command = ['foo', 'bar']
     input_file = flexmock(name='test')
@@ -189,7 +222,7 @@ def test_execute_command_captures_output_with_shell():
     expected_output = '[]'
     flexmock(module.os, environ={'a': 'b'})
     flexmock(module.subprocess).should_receive('check_output').with_args(
-        full_command, shell=True, env=None, cwd=None
+        'foo bar', shell=True, env=None, cwd=None
     ).and_return(flexmock(decode=lambda: expected_output)).once()
 
     output = module.execute_command(full_command, output_log_level=None, shell=True)
@@ -225,3 +258,168 @@ def test_execute_command_captures_output_with_working_directory():
     )
 
     assert output == expected_output
+
+
+def test_execute_command_with_processes_calls_full_command():
+    full_command = ['foo', 'bar']
+    processes = (flexmock(),)
+    flexmock(module.os, environ={'a': 'b'})
+    flexmock(module.subprocess).should_receive('Popen').with_args(
+        full_command,
+        stdin=None,
+        stdout=module.subprocess.PIPE,
+        stderr=module.subprocess.STDOUT,
+        shell=False,
+        env=None,
+        cwd=None,
+    ).and_return(flexmock(stdout=None)).once()
+    flexmock(module).should_receive('log_outputs')
+
+    output = module.execute_command_with_processes(full_command, processes)
+
+    assert output is None
+
+
+def test_execute_command_with_processes_calls_full_command_with_output_file():
+    full_command = ['foo', 'bar']
+    processes = (flexmock(),)
+    output_file = flexmock(name='test')
+    flexmock(module.os, environ={'a': 'b'})
+    flexmock(module.subprocess).should_receive('Popen').with_args(
+        full_command,
+        stdin=None,
+        stdout=output_file,
+        stderr=module.subprocess.PIPE,
+        shell=False,
+        env=None,
+        cwd=None,
+    ).and_return(flexmock(stderr=None)).once()
+    flexmock(module).should_receive('log_outputs')
+
+    output = module.execute_command_with_processes(full_command, processes, output_file=output_file)
+
+    assert output is None
+
+
+def test_execute_command_with_processes_calls_full_command_without_capturing_output():
+    full_command = ['foo', 'bar']
+    processes = (flexmock(),)
+    flexmock(module.os, environ={'a': 'b'})
+    flexmock(module.subprocess).should_receive('Popen').with_args(
+        full_command, stdin=None, stdout=None, stderr=None, shell=False, env=None, cwd=None
+    ).and_return(flexmock(wait=lambda: 0)).once()
+    flexmock(module).should_receive('exit_code_indicates_error').and_return(False)
+    flexmock(module).should_receive('log_outputs')
+
+    output = module.execute_command_with_processes(
+        full_command, processes, output_file=module.DO_NOT_CAPTURE
+    )
+
+    assert output is None
+
+
+def test_execute_command_with_processes_calls_full_command_with_input_file():
+    full_command = ['foo', 'bar']
+    processes = (flexmock(),)
+    input_file = flexmock(name='test')
+    flexmock(module.os, environ={'a': 'b'})
+    flexmock(module.subprocess).should_receive('Popen').with_args(
+        full_command,
+        stdin=input_file,
+        stdout=module.subprocess.PIPE,
+        stderr=module.subprocess.STDOUT,
+        shell=False,
+        env=None,
+        cwd=None,
+    ).and_return(flexmock(stdout=None)).once()
+    flexmock(module).should_receive('log_outputs')
+
+    output = module.execute_command_with_processes(full_command, processes, input_file=input_file)
+
+    assert output is None
+
+
+def test_execute_command_with_processes_calls_full_command_with_shell():
+    full_command = ['foo', 'bar']
+    processes = (flexmock(),)
+    flexmock(module.os, environ={'a': 'b'})
+    flexmock(module.subprocess).should_receive('Popen').with_args(
+        ' '.join(full_command),
+        stdin=None,
+        stdout=module.subprocess.PIPE,
+        stderr=module.subprocess.STDOUT,
+        shell=True,
+        env=None,
+        cwd=None,
+    ).and_return(flexmock(stdout=None)).once()
+    flexmock(module).should_receive('log_outputs')
+
+    output = module.execute_command_with_processes(full_command, processes, shell=True)
+
+    assert output is None
+
+
+def test_execute_command_with_processes_calls_full_command_with_extra_environment():
+    full_command = ['foo', 'bar']
+    processes = (flexmock(),)
+    flexmock(module.os, environ={'a': 'b'})
+    flexmock(module.subprocess).should_receive('Popen').with_args(
+        full_command,
+        stdin=None,
+        stdout=module.subprocess.PIPE,
+        stderr=module.subprocess.STDOUT,
+        shell=False,
+        env={'a': 'b', 'c': 'd'},
+        cwd=None,
+    ).and_return(flexmock(stdout=None)).once()
+    flexmock(module).should_receive('log_outputs')
+
+    output = module.execute_command_with_processes(
+        full_command, processes, extra_environment={'c': 'd'}
+    )
+
+    assert output is None
+
+
+def test_execute_command_with_processes_calls_full_command_with_working_directory():
+    full_command = ['foo', 'bar']
+    processes = (flexmock(),)
+    flexmock(module.os, environ={'a': 'b'})
+    flexmock(module.subprocess).should_receive('Popen').with_args(
+        full_command,
+        stdin=None,
+        stdout=module.subprocess.PIPE,
+        stderr=module.subprocess.STDOUT,
+        shell=False,
+        env=None,
+        cwd='/working',
+    ).and_return(flexmock(stdout=None)).once()
+    flexmock(module).should_receive('log_outputs')
+
+    output = module.execute_command_with_processes(
+        full_command, processes, working_directory='/working'
+    )
+
+    assert output is None
+
+
+def test_execute_command_with_processes_kills_processes_on_error():
+    full_command = ['foo', 'bar']
+    process = flexmock(stdout=flexmock(read=lambda count: None))
+    process.should_receive('poll')
+    process.should_receive('kill').once()
+    processes = (process,)
+    flexmock(module.os, environ={'a': 'b'})
+    flexmock(module.subprocess).should_receive('Popen').with_args(
+        full_command,
+        stdin=None,
+        stdout=module.subprocess.PIPE,
+        stderr=module.subprocess.STDOUT,
+        shell=False,
+        env=None,
+        cwd=None,
+    ).and_raise(subprocess.CalledProcessError(1, full_command, 'error')).once()
+    flexmock(module).should_receive('log_outputs').never()
+
+    with pytest.raises(subprocess.CalledProcessError):
+        module.execute_command_with_processes(full_command, processes)