borgmatic/tests/integration/test_execute.py

206 lines
8.1 KiB
Python
Raw Normal View History

2019-06-13 19:48:21 +02:00
import logging
import subprocess
import sys
2019-06-13 19:48:21 +02:00
import pytest
from flexmock import flexmock
from borgmatic import execute as module
2020-05-11 19:55:50 +02:00
def test_log_outputs_logs_each_line_separately():
2019-06-13 19:48:21 +02:00
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)
2019-06-13 19:48:21 +02:00
hi_process = subprocess.Popen(['echo', 'hi'], stdout=subprocess.PIPE)
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)
2020-05-11 19:55:50 +02:00
module.log_outputs(
(hi_process, there_process),
exclude_stdouts=(),
output_log_level=logging.INFO,
borg_local_path='borg',
)
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)
2020-05-11 19:55:50 +02:00
module.log_outputs(
(hi_process, there_process),
exclude_stdouts=(),
output_log_level=logging.INFO,
borg_local_path='borg',
)
2020-05-11 19:55:50 +02:00
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)
flexmock(module).should_receive('command_for_process').and_return('grep')
process = subprocess.Popen(['grep'], stdout=subprocess.PIPE, stderr=subprocess.STDOUT)
flexmock(module).should_receive('output_buffer_for_process').and_return(process.stdout)
with pytest.raises(subprocess.CalledProcessError) as error:
2020-05-11 19:55:50 +02:00
module.log_outputs(
(process,), exclude_stdouts=(), output_log_level=logging.INFO, borg_local_path='borg'
)
2019-06-13 19:48:21 +02:00
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, borg_local_path='borg'
)
assert error.value.returncode == 2
assert not error.value.output
2020-05-15 08:21:43 +02:00
def test_log_outputs_kills_other_processes_when_one_errors():
flexmock(module.logger).should_receive('log')
flexmock(module).should_receive('command_for_process').and_return('grep')
process = subprocess.Popen(['grep'], stdout=subprocess.PIPE, stderr=subprocess.STDOUT)
2020-11-26 02:46:57 +01:00
flexmock(module).should_receive('exit_code_indicates_error').with_args(
process, None, 'borg'
).and_return(False)
flexmock(module).should_receive('exit_code_indicates_error').with_args(
process, 2, 'borg'
).and_return(True)
2020-05-15 08:21:43 +02:00
other_process = subprocess.Popen(
['sleep', '2'], stdout=subprocess.PIPE, stderr=subprocess.STDOUT
2020-05-15 08:21:43 +02:00
)
2020-11-26 02:46:57 +01:00
flexmock(module).should_receive('exit_code_indicates_error').with_args(
other_process, None, 'borg'
).and_return(False)
2020-05-15 08:21:43 +02:00
flexmock(module).should_receive('output_buffer_for_process').with_args(process, ()).and_return(
process.stdout
)
flexmock(module).should_receive('output_buffer_for_process').with_args(
other_process, ()
).and_return(other_process.stdout)
flexmock(other_process).should_receive('kill').once()
with pytest.raises(subprocess.CalledProcessError) as error:
module.log_outputs(
(process, other_process),
exclude_stdouts=(),
output_log_level=logging.INFO,
borg_local_path='borg',
)
assert error.value.returncode == 2
assert error.value.output
def test_log_outputs_vents_other_processes_when_one_exits():
'''
Execute a command to generate a longish random string and pipe it into another command that
exits quickly. The test is basically to ensure we don't hang forever waiting for the exited
process to read the pipe, and that the string-generating process eventually gets vented and
exits.
'''
flexmock(module.logger).should_receive('log')
flexmock(module).should_receive('command_for_process').and_return('grep')
process = subprocess.Popen(
[sys.executable, '-c', "import random, string; print(''.join(random.choice(string.ascii_letters) for _ in range(40000)))"],
stdout=subprocess.PIPE, stderr=subprocess.PIPE
)
other_process = subprocess.Popen(
['true'], stdin=process.stdout, stdout=subprocess.PIPE, stderr=subprocess.STDOUT
)
flexmock(module).should_receive('output_buffer_for_process').with_args(
process, (process.stdout,)
).and_return(process.stderr)
flexmock(module).should_receive('output_buffer_for_process').with_args(
other_process, (process.stdout,)
).and_return(other_process.stdout)
flexmock(process.stdout).should_call('readline').at_least().once()
module.log_outputs(
(process, other_process),
exclude_stdouts=(process.stdout,),
output_log_level=logging.INFO,
borg_local_path='borg',
)
2020-05-11 19:55:50 +02:00
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('command_for_process').and_return('grep')
process = subprocess.Popen(['grep'], stdout=subprocess.PIPE, stderr=subprocess.STDOUT)
flexmock(module).should_receive('exit_code_indicates_error').with_args(
process, None, 'borg'
).and_return(False)
flexmock(module).should_receive('exit_code_indicates_error').with_args(
process, 2, 'borg'
).and_return(True)
flexmock(module).should_receive('output_buffer_for_process').and_return(process.stdout)
with pytest.raises(subprocess.CalledProcessError) as error:
2020-05-11 19:55:50 +02:00
module.log_outputs(
(process,), exclude_stdouts=(), output_log_level=logging.INFO, borg_local_path='borg'
)
assert error.value.returncode == 2
assert error.value.output.startswith('...')
2019-06-13 19:48:21 +02:00
2020-05-11 19:55:50 +02:00
def test_log_outputs_with_no_output_logs_nothing():
2019-06-13 19:48:21 +02:00
flexmock(module.logger).should_receive('log').never()
flexmock(module).should_receive('exit_code_indicates_error').and_return(False)
2019-06-13 19:48:21 +02:00
process = subprocess.Popen(['true'], stdout=subprocess.PIPE, stderr=subprocess.STDOUT)
flexmock(module).should_receive('output_buffer_for_process').and_return(process.stdout)
2020-05-11 19:55:50 +02:00
module.log_outputs(
(process,), exclude_stdouts=(), output_log_level=logging.INFO, borg_local_path='borg'
)
2020-07-08 07:31:17 +02:00
def test_log_outputs_with_unfinished_process_re_polls():
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)
flexmock(process).should_receive('poll').and_return(None).and_return(0).twice()
flexmock(module).should_receive('output_buffer_for_process').and_return(process.stdout)
module.log_outputs(
(process,), exclude_stdouts=(), output_log_level=logging.INFO, borg_local_path='borg'
)