Run hooks such that their output goes to syslog as well as console.

borgmatic/commands/hook.py

@@ -1,5 +1,6 @@
-import subprocess
+import logging
 
+from borgmatic import execute
 from borgmatic.logger import get_logger
 
 logger = get_logger(__name__)
@@ -7,7 +8,6 @@ logger = get_logger(__name__)
 
 def execute_hook(commands, config_filename, description, dry_run):
     '''
-
     Given a list of hook commands to execute, a config filename, a hook description, and whether
     this is a dry run, run the given commands. Or, don't run them if this is a dry run.
     '''
@@ -29,6 +29,5 @@ def execute_hook(commands, config_filename, description, dry_run):
         )
 
     for command in commands:
-        logger.debug('{}: Hook command: {}'.format(config_filename, command))
         if not dry_run:
-            subprocess.check_call(command, shell=True)
+            execute.execute_command([command], output_log_level=logging.WARNING, shell=True)

borgmatic/execute.py

@@ -6,17 +6,19 @@ from borgmatic.logger import get_logger
 logger = get_logger(__name__)
 
 
-def execute_and_log_output(full_command, output_log_level):
-    process = subprocess.Popen(full_command, stdout=None, stderr=subprocess.PIPE)
+def execute_and_log_output(full_command, output_log_level, shell):
+    process = subprocess.Popen(
+        full_command, stdout=subprocess.PIPE, stderr=subprocess.STDOUT, shell=shell
+    )
 
     while process.poll() is None:
-        line = process.stderr.readline().rstrip().decode()
+        line = process.stdout.readline().rstrip().decode()
         if line.startswith('borg: error:'):
             logger.error(line)
         else:
             logger.log(output_log_level, line)
 
-    remaining_output = process.stderr.read().rstrip().decode()
+    remaining_output = process.stdout.read().rstrip().decode()
     if remaining_output:
         logger.info(remaining_output)
 
@@ -25,15 +27,16 @@ def execute_and_log_output(full_command, output_log_level):
         raise subprocess.CalledProcessError(exit_code, full_command)
 
 
-def execute_command(full_command, output_log_level=logging.INFO):
+def execute_command(full_command, output_log_level=logging.INFO, shell=False):
     '''
     Execute the given command (a sequence of command/argument strings) and log its output at the
-    given log level. If output log level is None, instead capture and return the output.
+    given log level. If output log level is None, instead capture and return the output. If
+    shell is True, execute the command within a shell.
     '''
     logger.debug(' '.join(full_command))
 
     if output_log_level is None:
-        output = subprocess.check_output(full_command)
+        output = subprocess.check_output(full_command, shell=shell)
         return output.decode() if output is not None else None
     else:
-        execute_and_log_output(full_command, output_log_level)
+        execute_and_log_output(full_command, output_log_level, shell=shell)

docs/how-to/run-preparation-steps-before-backups.md

@@ -36,6 +36,12 @@ hooks:
         - echo "Error while creating a backup."
 ```
 
+## Hook output
+
+Any output produced by your hooks shows up both at the console and in syslog.
+For more information, read about <a
+href="https://torsion.org/borgmatic/docs/how-to/inspect-your-backups.md">inspecting
+your backups</a>.
 
 ## Security
 
@@ -49,3 +55,4 @@ injection or privilege escalation, do not forget to set secure permissions
 
  * [Set up backups with borgmatic](https://torsion.org/borgmatic/docs/how-to/set-up-backups.md)
  * [Make per-application backups](https://torsion.org/borgmatic/docs/how-to/make-per-application-backups.md)
+ * [Inspect your backups](https://torsion.org/borgmatic/docs/how-to/inspect-your-backups.md)

tests/unit/borg/test_execute.py

@@ -1,28 +0,0 @@
-import logging
-
-from flexmock import flexmock
-
-from borgmatic import execute as module
-
-
-def test_execute_command_calls_full_command():
-    full_command = ['foo', 'bar']
-    flexmock(module).should_receive('execute_and_log_output').with_args(
-        full_command, output_log_level=logging.INFO
-    ).once()
-
-    output = module.execute_command(full_command)
-
-    assert output is None
-
-
-def test_execute_command_captures_output():
-    full_command = ['foo', 'bar']
-    expected_output = '[]'
-    flexmock(module.subprocess).should_receive('check_output').with_args(full_command).and_return(
-        flexmock(decode=lambda: expected_output)
-    ).once()
-
-    output = module.execute_command(full_command, output_log_level=None)
-
-    assert output == expected_output

tests/unit/commands/test_hook.py

@@ -1,26 +1,31 @@
+import logging
+
 from flexmock import flexmock
 
 from borgmatic.commands import hook as module
 
 
 def test_execute_hook_invokes_each_command():
-    subprocess = flexmock(module.subprocess)
-    subprocess.should_receive('check_call').with_args(':', shell=True).once()
+    flexmock(module.execute).should_receive('execute_command').with_args(
+        [':'], output_log_level=logging.WARNING, shell=True
+    ).once()
 
     module.execute_hook([':'], 'config.yaml', 'pre-backup', dry_run=False)
 
 
 def test_execute_hook_with_multiple_commands_invokes_each_command():
-    subprocess = flexmock(module.subprocess)
-    subprocess.should_receive('check_call').with_args(':', shell=True).once()
-    subprocess.should_receive('check_call').with_args('true', shell=True).once()
+    flexmock(module.execute).should_receive('execute_command').with_args(
+        [':'], output_log_level=logging.WARNING, shell=True
+    ).once()
+    flexmock(module.execute).should_receive('execute_command').with_args(
+        ['true'], output_log_level=logging.WARNING, shell=True
+    ).once()
 
     module.execute_hook([':', 'true'], 'config.yaml', 'pre-backup', dry_run=False)
 
 
 def test_execute_hook_with_dry_run_skips_commands():
-    subprocess = flexmock(module.subprocess)
-    subprocess.should_receive('check_call').never()
+    flexmock(module.execute).should_receive('execute_command').never()
 
     module.execute_hook([':', 'true'], 'config.yaml', 'pre-backup', dry_run=True)
 

tests/unit/test_execute.py

@@ -0,0 +1,51 @@
+import logging
+
+from flexmock import flexmock
+
+from borgmatic import execute as module
+
+
+def test_execute_command_calls_full_command():
+    full_command = ['foo', 'bar']
+    flexmock(module).should_receive('execute_and_log_output').with_args(
+        full_command, output_log_level=logging.INFO, shell=False
+    ).once()
+
+    output = module.execute_command(full_command)
+
+    assert output is None
+
+
+def test_execute_command_calls_full_command_with_shell():
+    full_command = ['foo', 'bar']
+    flexmock(module).should_receive('execute_and_log_output').with_args(
+        full_command, output_log_level=logging.INFO, shell=True
+    ).once()
+
+    output = module.execute_command(full_command, shell=True)
+
+    assert output is None
+
+
+def test_execute_command_captures_output():
+    full_command = ['foo', 'bar']
+    expected_output = '[]'
+    flexmock(module.subprocess).should_receive('check_output').with_args(
+        full_command, shell=False
+    ).and_return(flexmock(decode=lambda: expected_output)).once()
+
+    output = module.execute_command(full_command, output_log_level=None)
+
+    assert output == expected_output
+
+
+def test_execute_command_captures_output_with_shell():
+    full_command = ['foo', 'bar']
+    expected_output = '[]'
+    flexmock(module.subprocess).should_receive('check_output').with_args(
+        full_command, shell=True
+    ).and_return(flexmock(decode=lambda: expected_output)).once()
+
+    output = module.execute_command(full_command, output_log_level=None, shell=True)
+
+    assert output == expected_output