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!

README.md

@@ -2,7 +2,7 @@
 title: borgmatic
 permalink: index.html
 ---
-<a href="https://build.torsion.org/witten/borgmatic" alt="build status">![Build Status](https://build.torsion.org/api/badges/witten/borgmatic/status.svg)</a>
+<a href="https://build.torsion.org/witten/borgmatic" alt="build status">![Build Status](https://build.torsion.org/api/badges/witten/borgmatic/status.svg?ref=refs/heads/master)</a>
 
 ## Overview
 

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:'):
-            logger.error(line)
-        else:
-            logger.log(output_log_level, line)
+        # Keep the last few lines of output in case the command errors, and we need the output for
+        # the exception below.
+        last_lines.append(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):

docs/how-to/deal-with-very-large-backups.md

@@ -22,6 +22,9 @@ borgmatic create
 borgmatic check
 ```
 
+(No borgmatic `prune`, `create`, or `check` actions? Try the old-style
+`--prune`, `--create`, or `--check`. Or upgrade borgmatic!)
+
 You can run with only one of these flags provided, or you can mix and match
 any number of them in a single borgmatic run. This supports approaches like
 making backups with `create` on a frequent schedule, while only running

docs/how-to/inspect-your-backups.md

@@ -33,6 +33,9 @@ borgmatic list
 borgmatic info
 ```
 
+(No borgmatic `list` or `info` actions? Try the old-style `--list` or
+`--info`. Or upgrade borgmatic!)
+
 ## Logging
 
 By default, borgmatic logs to a local syslog-compatible daemon if one is

docs/how-to/restore-a-backup.md

@@ -11,6 +11,9 @@ to figure out which archive to restore. A good way to do that is to use the
 borgmatic list
 ```
 
+(No borgmatic `list` action? Try the old-style `--list`, or upgrade
+borgmatic!)
+
 That should yield output looking something like:
 
 ```text
@@ -25,6 +28,9 @@ and therefore the latest timestamp, run a command like:
 borgmatic extract --archive host-2019-01-02T04:06:07.080910
 ```
 
+(No borgmatic `extract` action? Try the old-style `--extract`, or upgrade
+borgmatic!)
+
 The `--archive` value is the name of the archive to restore. This extracts the
 entire contents of the archive to the current directory, so make sure you're
 in the right place before running the command.

docs/how-to/set-up-backups.md

@@ -124,6 +124,9 @@ a command like the following:
 borgmatic init --encryption repokey
 ```
 
+(No borgmatic `init` action? Try the old-style `--init` flag, or upgrade
+borgmatic!)
+
 This uses the borgmatic configuration file you created above to determine
 which local or remote repository to create, and encrypts it with the
 encryption passphrase specified there if one is provided. Read about [Borg

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():
-    flexmock(module.logger).should_receive('error').with_args('borg: error: oopsie').once()
+def test_execute_and_log_output_includes_borg_error_output_in_exception():
+    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(
-        ['echo', 'borg: error: oopsie'], output_log_level=logging.INFO, shell=False
-    )
+    assert error.value.returncode == 2
+    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']