From d0d3a398332b89966e57c3617a6acaa71add85bc Mon Sep 17 00:00:00 2001 From: Dan Helfman Date: Mon, 27 Mar 2023 10:36:39 -0700 Subject: [PATCH] When a database command errors, display and log the error message instead of swallowing it (#396). --- NEWS | 1 + borgmatic/execute.py | 44 ++++++++++++++++++++++++------- borgmatic/hooks/mysql.py | 6 ++--- tests/integration/test_execute.py | 3 +-- tests/unit/hooks/test_mysql.py | 32 +++++++++++++++------- tests/unit/test_execute.py | 35 ++++++++++++++++++++++++ 6 files changed, 95 insertions(+), 26 deletions(-) diff --git a/NEWS b/NEWS index 7d02c0e..472eef4 100644 --- a/NEWS +++ b/NEWS @@ -1,4 +1,5 @@ 1.7.10.dev0 + * #396: When a database command errors, display and log the error message instead of swallowing it. * #501: Optionally error if a source directory does not exist via "source_directories_must_exist" option in borgmatic's location configuration. * #576: Add support for "file://" paths within "repositories" option. diff --git a/borgmatic/execute.py b/borgmatic/execute.py index 46dd04f..0afa5cc 100644 --- a/borgmatic/execute.py +++ b/borgmatic/execute.py @@ -43,6 +43,23 @@ def output_buffer_for_process(process, exclude_stdouts): return process.stderr if process.stdout in exclude_stdouts else process.stdout +def append_last_lines(last_lines, captured_output, line, output_log_level): + ''' + Given a rolling list of last lines, a list of captured output, a line to append, and an output + log level, append the line to the last lines and (if necessary) the captured output. Then log + the line at the requested output log level. + ''' + last_lines.append(line) + + if len(last_lines) > ERROR_OUTPUT_MAX_LINE_COUNT: + last_lines.pop(0) + + if output_log_level is None: + captured_output.append(line) + else: + logger.log(output_log_level, line) + + def log_outputs(processes, exclude_stdouts, output_log_level, borg_local_path): ''' Given a sequence of subprocess.Popen() instances for multiple processes, log the output for each @@ -98,15 +115,12 @@ def log_outputs(processes, exclude_stdouts, output_log_level, borg_local_path): # 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) - - if output_log_level is None: - captured_outputs[ready_process].append(line) - else: - logger.log(output_log_level, line) + append_last_lines( + buffer_last_lines[ready_buffer], + captured_outputs[ready_process], + line, + output_log_level, + ) if not still_running: break @@ -125,8 +139,18 @@ def log_outputs(processes, exclude_stdouts, output_log_level, borg_local_path): # If an error occurs, include its output in the raised exception so that we don't # inadvertently hide error output. output_buffer = output_buffer_for_process(process, exclude_stdouts) - last_lines = buffer_last_lines[output_buffer] if output_buffer else [] + + # Collect any straggling output lines that came in since we last gathered output. + while output_buffer: # pragma: no cover + line = output_buffer.readline().rstrip().decode() + if not line: + break + + append_last_lines( + last_lines, captured_outputs[process], line, output_log_level=logging.ERROR + ) + if len(last_lines) == ERROR_OUTPUT_MAX_LINE_COUNT: last_lines.insert(0, '...') diff --git a/borgmatic/hooks/mysql.py b/borgmatic/hooks/mysql.py index 0bf9774..aeeeee5 100644 --- a/borgmatic/hooks/mysql.py +++ b/borgmatic/hooks/mysql.py @@ -88,9 +88,7 @@ def execute_dump_command( + (('--user', database['username']) if 'username' in database else ()) + ('--databases',) + database_names - # Use shell redirection rather than execute_command(output_file=open(...)) to prevent - # the open() call on a named pipe from hanging the main borgmatic process. - + ('>', dump_filename) + + ('--result-file', dump_filename) ) logger.debug( @@ -102,7 +100,7 @@ def execute_dump_command( dump.create_named_pipe_for_dump(dump_filename) return execute_command( - dump_command, shell=True, extra_environment=extra_environment, run_to_completion=False, + dump_command, extra_environment=extra_environment, run_to_completion=False, ) diff --git a/tests/integration/test_execute.py b/tests/integration/test_execute.py index 2a9b61d..09e9093 100644 --- a/tests/integration/test_execute.py +++ b/tests/integration/test_execute.py @@ -239,7 +239,6 @@ def test_log_outputs_does_not_error_when_one_process_exits(): 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') @@ -253,7 +252,7 @@ def test_log_outputs_truncates_long_error_output(): flexmock(module).should_receive('output_buffer_for_process').and_return(process.stdout) with pytest.raises(subprocess.CalledProcessError) as error: - module.log_outputs( + flexmock(module, ERROR_OUTPUT_MAX_LINE_COUNT=0).log_outputs( (process,), exclude_stdouts=(), output_log_level=logging.INFO, borg_local_path='borg' ) diff --git a/tests/unit/hooks/test_mysql.py b/tests/unit/hooks/test_mysql.py index 1e8df69..137a88a 100644 --- a/tests/unit/hooks/test_mysql.py +++ b/tests/unit/hooks/test_mysql.py @@ -149,8 +149,7 @@ def test_execute_dump_command_runs_mysqldump(): flexmock(module.dump).should_receive('create_named_pipe_for_dump') flexmock(module).should_receive('execute_command').with_args( - ('mysqldump', '--add-drop-database', '--databases', 'foo', '>', 'dump',), - shell=True, + ('mysqldump', '--add-drop-database', '--databases', 'foo', '--result-file', 'dump',), extra_environment=None, run_to_completion=False, ).and_return(process).once() @@ -176,8 +175,7 @@ def test_execute_dump_command_runs_mysqldump_without_add_drop_database(): flexmock(module.dump).should_receive('create_named_pipe_for_dump') flexmock(module).should_receive('execute_command').with_args( - ('mysqldump', '--databases', 'foo', '>', 'dump',), - shell=True, + ('mysqldump', '--databases', 'foo', '--result-file', 'dump',), extra_environment=None, run_to_completion=False, ).and_return(process).once() @@ -214,10 +212,9 @@ def test_execute_dump_command_runs_mysqldump_with_hostname_and_port(): 'tcp', '--databases', 'foo', - '>', + '--result-file', 'dump', ), - shell=True, extra_environment=None, run_to_completion=False, ).and_return(process).once() @@ -243,8 +240,16 @@ def test_execute_dump_command_runs_mysqldump_with_username_and_password(): flexmock(module.dump).should_receive('create_named_pipe_for_dump') flexmock(module).should_receive('execute_command').with_args( - ('mysqldump', '--add-drop-database', '--user', 'root', '--databases', 'foo', '>', 'dump',), - shell=True, + ( + 'mysqldump', + '--add-drop-database', + '--user', + 'root', + '--databases', + 'foo', + '--result-file', + 'dump', + ), extra_environment={'MYSQL_PWD': 'trustsome1'}, run_to_completion=False, ).and_return(process).once() @@ -270,8 +275,15 @@ def test_execute_dump_command_runs_mysqldump_with_options(): flexmock(module.dump).should_receive('create_named_pipe_for_dump') flexmock(module).should_receive('execute_command').with_args( - ('mysqldump', '--stuff=such', '--add-drop-database', '--databases', 'foo', '>', 'dump',), - shell=True, + ( + 'mysqldump', + '--stuff=such', + '--add-drop-database', + '--databases', + 'foo', + '--result-file', + 'dump', + ), extra_environment=None, run_to_completion=False, ).and_return(process).once() diff --git a/tests/unit/test_execute.py b/tests/unit/test_execute.py index badcb8f..1492407 100644 --- a/tests/unit/test_execute.py +++ b/tests/unit/test_execute.py @@ -65,6 +65,41 @@ def test_output_buffer_for_process_returns_stdout_when_not_excluded(): ) +def test_append_last_lines_under_max_line_count_appends(): + last_lines = ['last'] + flexmock(module.logger).should_receive('log').once() + + module.append_last_lines( + last_lines, captured_output=flexmock(), line='line', output_log_level=flexmock() + ) + + assert last_lines == ['last', 'line'] + + +def test_append_last_lines_over_max_line_count_trims_and_appends(): + original_last_lines = [str(number) for number in range(0, module.ERROR_OUTPUT_MAX_LINE_COUNT)] + last_lines = list(original_last_lines) + flexmock(module.logger).should_receive('log').once() + + module.append_last_lines( + last_lines, captured_output=flexmock(), line='line', output_log_level=flexmock() + ) + + assert last_lines == original_last_lines[1:] + ['line'] + + +def test_append_last_lines_with_output_log_level_none_appends_captured_output(): + last_lines = ['last'] + captured_output = ['captured'] + flexmock(module.logger).should_receive('log').never() + + module.append_last_lines( + last_lines, captured_output=captured_output, line='line', output_log_level=None + ) + + assert captured_output == ['captured', 'line'] + + def test_execute_command_calls_full_command(): full_command = ['foo', 'bar'] flexmock(module.os, environ={'a': 'b'})