From fa293828dfba5d5ce63ff56357e0bdb1ba79fddf Mon Sep 17 00:00:00 2001 From: Dan Helfman Date: Wed, 12 Jun 2019 13:09:04 -0700 Subject: [PATCH] Run hooks such that their output goes to syslog as well as console. --- borgmatic/commands/hook.py | 7 ++- borgmatic/execute.py | 19 ++++--- .../run-preparation-steps-before-backups.md | 7 +++ tests/unit/borg/test_execute.py | 28 ---------- tests/unit/commands/test_hook.py | 19 ++++--- tests/unit/test_execute.py | 51 +++++++++++++++++++ 6 files changed, 84 insertions(+), 47 deletions(-) delete mode 100644 tests/unit/borg/test_execute.py create mode 100644 tests/unit/test_execute.py diff --git a/borgmatic/commands/hook.py b/borgmatic/commands/hook.py index 3e2844116..79970b2e6 100644 --- a/borgmatic/commands/hook.py +++ b/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) diff --git a/borgmatic/execute.py b/borgmatic/execute.py index 3ca9f6007..c80473575 100644 --- a/borgmatic/execute.py +++ b/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) diff --git a/docs/how-to/run-preparation-steps-before-backups.md b/docs/how-to/run-preparation-steps-before-backups.md index 1944fd901..76757fb3c 100644 --- a/docs/how-to/run-preparation-steps-before-backups.md +++ b/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 inspecting +your backups. ## 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) diff --git a/tests/unit/borg/test_execute.py b/tests/unit/borg/test_execute.py deleted file mode 100644 index f1bb00af0..000000000 --- a/tests/unit/borg/test_execute.py +++ /dev/null @@ -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 diff --git a/tests/unit/commands/test_hook.py b/tests/unit/commands/test_hook.py index d54c078e1..6ad94f3f7 100644 --- a/tests/unit/commands/test_hook.py +++ b/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) diff --git a/tests/unit/test_execute.py b/tests/unit/test_execute.py new file mode 100644 index 000000000..ec2ebe957 --- /dev/null +++ b/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