Fix for Borg create error output not showing up at borgmatic verbosity level zero (#198).

NEWS

@@ -1,3 +1,6 @@
+1.3.10
+ * #198: Fix for Borg create error output not showing up at borgmatic verbosity level zero.
+
 1.3.9
  * #195: Switch to command-line actions as more traditional sub-commands, e.g. "borgmatic create",
    "borgmatic prune", etc. However, the classic dashed options like "--create" still work!

borgmatic/commands/borgmatic.py

@@ -265,7 +265,21 @@ def collect_configuration_run_summary_logs(configs, arguments):
                     msg='{}: Successfully ran configuration file'.format(config_filename),
                 )
             )
-        except (ValueError, OSError, CalledProcessError) as error:
+        except CalledProcessError as error:
+            yield logging.makeLogRecord(
+                dict(
+                    levelno=logging.CRITICAL,
+                    levelname='CRITICAL',
+                    msg='{}: Error running configuration file'.format(config_filename),
+                )
+            )
+            yield logging.makeLogRecord(
+                dict(levelno=logging.CRITICAL, levelname='CRITICAL', msg=error.output)
+            )
+            yield logging.makeLogRecord(
+                dict(levelno=logging.CRITICAL, levelname='CRITICAL', msg=error)
+            )
+        except (ValueError, OSError) as error:
             yield logging.makeLogRecord(
                 dict(
                     levelno=logging.CRITICAL,

borgmatic/execute.py

@@ -4,7 +4,11 @@ import subprocess
 logger = logging.getLogger(__name__)
 
 
+ERROR_OUTPUT_MAX_LINE_COUNT = 25
+
+
 def execute_and_log_output(full_command, output_log_level, shell):
+    last_lines = []
     process = subprocess.Popen(
         full_command, stdout=subprocess.PIPE, stderr=subprocess.STDOUT, shell=shell
     )
@@ -14,10 +18,13 @@ def execute_and_log_output(full_command, output_log_level, shell):
         if not line:
             continue
 
-        if line.startswith('borg: error:'):
+        # Keep the last few lines of output in case the command errors, and we need the output for
-            logger.error(line)
+        # the exception below.
-        else:
+        last_lines.append(line)
-            logger.log(output_log_level, line)
+        if len(last_lines) > ERROR_OUTPUT_MAX_LINE_COUNT:
+            last_lines.pop(0)
+
+        logger.log(output_log_level, line)
 
     remaining_output = process.stdout.read().rstrip().decode()
     if remaining_output:  # pragma: no cover
@@ -25,7 +32,14 @@ def execute_and_log_output(full_command, output_log_level, shell):
 
     exit_code = process.poll()
     if exit_code != 0:
-        raise subprocess.CalledProcessError(exit_code, full_command)
+        # 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, ' '.join(full_command), '\n'.join(last_lines)
+        )
 
 
 def execute_command(full_command, output_log_level=logging.INFO, shell=False):

setup.py

@@ -1,6 +1,6 @@
 from setuptools import find_packages, setup
 
-VERSION = '1.3.9'
+VERSION = '1.3.10'
 
 
 setup(

tests/integration/test_execute.py

@@ -15,12 +15,22 @@ def test_execute_and_log_output_logs_each_line_separately():
     module.execute_and_log_output(['echo', 'there'], output_log_level=logging.INFO, shell=False)
 
 
-def test_execute_and_log_output_logs_borg_error_as_error():
+def test_execute_and_log_output_includes_borg_error_output_in_exception():
-    flexmock(module.logger).should_receive('error').with_args('borg: error: oopsie').once()
+    with pytest.raises(subprocess.CalledProcessError) as error:
+        module.execute_and_log_output(['grep'], output_log_level=logging.INFO, shell=False)
 
-    module.execute_and_log_output(
+    assert error.value.returncode == 2
-        ['echo', 'borg: error: oopsie'], output_log_level=logging.INFO, shell=False
+    assert error.value.output
-    )
+
+
+def test_execute_and_log_output_truncates_long_borg_error_output():
+    flexmock(module).ERROR_OUTPUT_MAX_LINE_COUNT = 0
+
+    with pytest.raises(subprocess.CalledProcessError) as error:
+        module.execute_and_log_output(['grep'], output_log_level=logging.INFO, shell=False)
+
+    assert error.value.returncode == 2
+    assert error.value.output.startswith('...')
 
 
 def test_execute_and_log_output_with_no_output_logs_nothing():

tests/unit/commands/test_borgmatic.py

@@ -1,3 +1,5 @@
+import subprocess
+
 from flexmock import flexmock
 
 from borgmatic.commands import borgmatic as module
@@ -85,7 +87,7 @@ def test_collect_configuration_run_summary_logs_info_for_success_with_list():
     assert all(log for log in logs if log.levelno == module.logging.INFO)
 
 
-def test_collect_configuration_run_summary_logs_critical_for_run_error():
+def test_collect_configuration_run_summary_logs_critical_for_run_value_error():
     flexmock(module.validate).should_receive('guard_configuration_contains_repository')
     flexmock(module).should_receive('run_configuration').and_raise(ValueError)
     arguments = {}
@@ -97,6 +99,21 @@ def test_collect_configuration_run_summary_logs_critical_for_run_error():
     assert any(log for log in logs if log.levelno == module.logging.CRITICAL)
 
 
+def test_collect_configuration_run_summary_logs_critical_including_output_for_run_process_error():
+    flexmock(module.validate).should_receive('guard_configuration_contains_repository')
+    flexmock(module).should_receive('run_configuration').and_raise(
+        subprocess.CalledProcessError(1, 'command', 'error output')
+    )
+    arguments = {}
+
+    logs = tuple(
+        module.collect_configuration_run_summary_logs({'test.yaml': {}}, arguments=arguments)
+    )
+
+    assert any(log for log in logs if log.levelno == module.logging.CRITICAL)
+    assert any(log for log in logs if 'error output' in str(log))
+
+
 def test_collect_configuration_run_summary_logs_outputs_merged_json_results():
     flexmock(module).should_receive('run_configuration').and_return(['foo', 'bar']).and_return(
         ['baz']