When a database command errors, display and log the error message instead of swallowing it (#396).

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.

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, '...')
 

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,
     )
 
 

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'
         )
 

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()

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'})