Successfully convert Borg output to Python logging entries.

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.

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 ())

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)

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 ())
     )
 

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 ())
     )
 

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(

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)
-
-    logging.basicConfig(
-        level=min(console_log_level, syslog_log_level), handlers=(console_handler, syslog_handler)
-    )
+    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'
+
+    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)

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
 

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()