From 9a5e7a3abb8503477bf1631acef0ff6348e41300 Mon Sep 17 00:00:00 2001 From: Dan Helfman Date: Tue, 11 Jun 2019 16:42:04 -0700 Subject: [PATCH] Successfully convert Borg output to Python logging entries. --- NEWS | 3 ++- borgmatic/borg/create.py | 12 ++++++++---- borgmatic/borg/execute.py | 19 ++++++++++++++++++- borgmatic/borg/info.py | 4 ++-- borgmatic/borg/list.py | 4 ++-- borgmatic/commands/borgmatic.py | 2 +- borgmatic/logger.py | 20 ++++++++++++++------ docs/how-to/inspect-your-backups.md | 22 ++++++++++++++++++++++ tests/unit/borg/test_execute.py | 6 ++---- 9 files changed, 71 insertions(+), 21 deletions(-) diff --git a/NEWS b/NEWS index 9df2b6f3..c37adee2 100644 --- a/NEWS +++ b/NEWS @@ -1,5 +1,6 @@ 1.3.6.dev0 - * #53: Log to syslog in addition to existing standard out logging. + * #53: Log to syslog in addition to existing console logging. Add --syslog-verbosity flag to + customize the log level. * #178: Look for .yml configuration file extension in addition to .yaml. * Remove Python cache files before each Tox run. * Add #borgmatic Freenode IRC channel to documentation. diff --git a/borgmatic/borg/create.py b/borgmatic/borg/create.py index 3cb88597..e4924c36 100644 --- a/borgmatic/borg/create.py +++ b/borgmatic/borg/create.py @@ -149,10 +149,14 @@ def create_archive( + (('--remote-path', remote_path) if remote_path else ()) + (('--umask', str(umask)) if umask else ()) + (('--lock-wait', str(lock_wait)) if lock_wait else ()) - + (('--list', '--filter', 'AME-') if logger.isEnabledFor(logging.INFO) else ()) - + (('--info',) if logger.getEffectiveLevel() == logging.INFO else ()) - + (('--stats',) if not dry_run and (logger.isEnabledFor(logging.INFO) or stats) else ()) - + (('--debug', '--show-rc') if logger.isEnabledFor(logging.DEBUG) else ()) + + (('--list', '--filter', 'AME-') if logger.isEnabledFor(logging.INFO) and not json else ()) + + (('--info',) if logger.getEffectiveLevel() == logging.INFO and not json else ()) + + ( + ('--stats',) + if not dry_run and (logger.isEnabledFor(logging.INFO) or stats) and not json + else () + ) + + (('--debug', '--show-rc') if logger.isEnabledFor(logging.DEBUG) and not json else ()) + (('--dry-run',) if dry_run else ()) + (('--progress',) if progress else ()) + (('--json',) if json else ()) diff --git a/borgmatic/borg/execute.py b/borgmatic/borg/execute.py index 80040bee..e9d255a0 100644 --- a/borgmatic/borg/execute.py +++ b/borgmatic/borg/execute.py @@ -5,6 +5,23 @@ from borgmatic.logger import get_logger logger = get_logger(__name__) +def execute_and_log_output(full_command): + process = subprocess.Popen(full_command, stdout=None, stderr=subprocess.PIPE) + + while process.poll() is None: + line = process.stderr.readline().rstrip().decode() + if line.startswith('borg: error:'): + logger.error(line) + else: + logger.info(line) + + logger.info(process.stderr.read().rstrip().decode()) + exit_code = process.poll() + + if exit_code != 0: + raise subprocess.CalledProcessError(exit_code, full_command) + + def execute_command(full_command, capture_output=False): ''' Execute the given command (a sequence of command/argument strings). If capture output is True, @@ -16,4 +33,4 @@ def execute_command(full_command, capture_output=False): output = subprocess.check_output(full_command) return output.decode() if output is not None else None else: - subprocess.check_call(full_command) + execute_and_log_output(full_command) diff --git a/borgmatic/borg/info.py b/borgmatic/borg/info.py index 6b6df426..87193911 100644 --- a/borgmatic/borg/info.py +++ b/borgmatic/borg/info.py @@ -19,8 +19,8 @@ def display_archives_info( (local_path, 'info', repository) + (('--remote-path', remote_path) if remote_path else ()) + (('--lock-wait', str(lock_wait)) if lock_wait else ()) - + (('--info',) if logger.getEffectiveLevel() == logging.INFO else ()) - + (('--debug', '--show-rc') if logger.isEnabledFor(logging.DEBUG) else ()) + + (('--info',) if logger.getEffectiveLevel() == logging.INFO and not json else ()) + + (('--debug', '--show-rc') if logger.isEnabledFor(logging.DEBUG) and not json else ()) + (('--json',) if json else ()) ) diff --git a/borgmatic/borg/list.py b/borgmatic/borg/list.py index cc66a5b9..4f35f1c0 100644 --- a/borgmatic/borg/list.py +++ b/borgmatic/borg/list.py @@ -20,8 +20,8 @@ def list_archives( (local_path, 'list', '::'.join((repository, archive)) if archive else repository) + (('--remote-path', remote_path) if remote_path else ()) + (('--lock-wait', str(lock_wait)) if lock_wait else ()) - + (('--info',) if logger.getEffectiveLevel() == logging.INFO else ()) - + (('--debug', '--show-rc') if logger.isEnabledFor(logging.DEBUG) else ()) + + (('--info',) if logger.getEffectiveLevel() == logging.INFO and not json else ()) + + (('--debug', '--show-rc') if logger.isEnabledFor(logging.DEBUG) and not json else ()) + (('--json',) if json else ()) ) diff --git a/borgmatic/commands/borgmatic.py b/borgmatic/commands/borgmatic.py index 179ff2b9..c04dbac5 100644 --- a/borgmatic/commands/borgmatic.py +++ b/borgmatic/commands/borgmatic.py @@ -182,7 +182,7 @@ def parse_arguments(*arguments): '--syslog-verbosity', type=int, choices=range(0, 3), - default=2, + default=1, help='Display verbose progress to syslog (from none to lots: 0, 1, or 2)', ) common_group.add_argument( diff --git a/borgmatic/logger.py b/borgmatic/logger.py index 00d6c7ee..334930c4 100644 --- a/borgmatic/logger.py +++ b/borgmatic/logger.py @@ -114,10 +114,18 @@ def configure_logging(console_log_level, syslog_log_level=None): console_handler.setFormatter(logging.Formatter('%(message)s')) console_handler.setLevel(console_log_level) - syslog_handler = logging.handlers.SysLogHandler(address='/dev/log') - syslog_handler.setFormatter(logging.Formatter('borgmatic: %(levelname)s %(message)s')) - syslog_handler.setLevel(syslog_log_level) + syslog_path = None + if os.path.exists('/dev/log'): + syslog_path = '/dev/log' + elif os.path.exists('/var/run/syslog'): + syslog_path = '/var/run/syslog' - logging.basicConfig( - level=min(console_log_level, syslog_log_level), handlers=(console_handler, syslog_handler) - ) + if syslog_path: + syslog_handler = logging.handlers.SysLogHandler(address=syslog_path) + syslog_handler.setFormatter(logging.Formatter('borgmatic: %(levelname)s \ufeff%(message)s')) + syslog_handler.setLevel(syslog_log_level) + handlers = (console_handler, syslog_handler) + else: + handlers = (console_handler,) + + logging.basicConfig(level=min(console_log_level, syslog_log_level), handlers=handlers) diff --git a/docs/how-to/inspect-your-backups.md b/docs/how-to/inspect-your-backups.md index 5e50fc55..956443c1 100644 --- a/docs/how-to/inspect-your-backups.md +++ b/docs/how-to/inspect-your-backups.md @@ -33,12 +33,34 @@ borgmatic --list borgmatic --info ``` +## Logging + +By default, borgmatic logs to a local syslog-compatible daemon if one is +present. You can customize the log level used for syslog logging with the +`--syslog-verbosity` flag, and this is independent from the console logging +`--verbosity` flag described above. For instance, to disable syslog logging +except for errors: + +```bash +borgmatic --syslog-verbosity 0 +``` + +Or to increase syslog logging to include debug spew: + +```bash +borgmatic --syslog-verbosity 2 +``` + ## Scripting borgmatic To consume the output of borgmatic in other software, you can include an optional `--json` flag with `--create`, `--list`, or `--info` to get the output formatted as JSON. +Note that when you specify the `--json` flag, Borg's other non-JSON output is +suppressed so as not to interfere with the captured JSON. Also note that JSON +output only shows up at the console, and not in syslog. + ## Related documentation diff --git a/tests/unit/borg/test_execute.py b/tests/unit/borg/test_execute.py index a7bc45b5..571b1866 100644 --- a/tests/unit/borg/test_execute.py +++ b/tests/unit/borg/test_execute.py @@ -5,8 +5,7 @@ from borgmatic.borg import execute as module def test_execute_command_calls_full_command(): full_command = ['foo', 'bar'] - subprocess = flexmock(module.subprocess) - subprocess.should_receive('check_call').with_args(full_command).once() + flexmock(module).should_receive('execute_and_log_output').with_args(full_command).once() output = module.execute_command(full_command) @@ -16,8 +15,7 @@ def test_execute_command_calls_full_command(): def test_execute_command_captures_output(): full_command = ['foo', 'bar'] expected_output = '[]' - subprocess = flexmock(module.subprocess) - subprocess.should_receive('check_output').with_args(full_command).and_return( + flexmock(module.subprocess).should_receive('check_output').with_args(full_command).and_return( flexmock(decode=lambda: expected_output) ).once()