Fix "borgmatic create --progress" output so that it updates on the console in real-time (#221).

NEWS

@@ -1,3 +1,8 @@
+1.3.20
+ * #205: More robust sample systemd service: boot delay, network dependency, lowered CPU/IO
+   priority, etc.
+ * #221: Fix "borgmatic create --progress" output so that it updates on the console in real-time.
+
 1.3.19
  * #219: Fix visibility of "borgmatic prune --stats" output.
 

borgmatic/borg/create.py

@@ -4,7 +4,7 @@ import logging
 import os
 import tempfile
 
-from borgmatic.execute import execute_command
+from borgmatic.execute import execute_command, execute_command_without_capture
 
 logger = logging.getLogger(__name__)
 
@@ -163,6 +163,12 @@ def create_archive(
         + sources
     )
 
+    # The progress output isn't compatible with captured and logged output, as progress messes with
+    # the terminal directly.
+    if progress:
+        execute_command_without_capture(full_command)
+        return
+
     if json:
         output_log_level = None
     elif stats:

borgmatic/borg/extract.py

@@ -1,6 +1,6 @@
 import logging
 
-from borgmatic.execute import execute_command
+from borgmatic.execute import execute_command, execute_command_without_capture
 
 logger = logging.getLogger(__name__)
 
@@ -83,4 +83,10 @@ def extract_archive(
         + (tuple(restore_paths) if restore_paths else ())
     )
 
+    # The progress output isn't compatible with captured and logged output, as progress messes with
+    # the terminal directly.
+    if progress:
+        execute_command_without_capture(full_command)
+        return
+
     execute_command(full_command)

borgmatic/borg/init.py

@@ -1,7 +1,7 @@
 import logging
 import subprocess
 
-from borgmatic.execute import BORG_ERROR_EXIT_CODE, execute_command
+from borgmatic.execute import execute_command, execute_command_without_capture
 
 logger = logging.getLogger(__name__)
 
@@ -45,8 +45,4 @@ def initialize_repository(
     )
 
     # Don't use execute_command() here because it doesn't support interactive prompts.
-    try:
-        subprocess.check_call(init_command)
-    except subprocess.CalledProcessError as error:
-        if error.returncode >= BORG_ERROR_EXIT_CODE:
-            raise
+    execute_command_without_capture(init_command)

borgmatic/execute.py

@@ -61,3 +61,18 @@ def execute_command(full_command, output_log_level=logging.INFO, shell=False):
         return output.decode() if output is not None else None
     else:
         execute_and_log_output(full_command, output_log_level, shell=shell)
+
+
+def execute_command_without_capture(full_command):
+    '''
+    Execute the given command (a sequence of command/argument strings), but don't capture or log its
+    output in any way. This is necessary for commands that monkey with the terminal (e.g. progress
+    display) or provide interactive prompts.
+    '''
+    logger.debug(' '.join(full_command))
+
+    try:
+        subprocess.check_call(full_command)
+    except subprocess.CalledProcessError as error:
+        if error.returncode >= BORG_ERROR_EXIT_CODE:
+            raise

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

@@ -20,6 +20,16 @@ Or, for even more progress and debug spew:
 borgmatic --verbosity 2
 ```
 
+## Backup summary
+
+If you're less concerned with progress during a backup, and you just want to
+see the summary of archive statistics at the end, you can use the stats
+option:
+
+```bash
+borgmatic --stats
+```
+
 ## Existing backups
 
 Borgmatic provides convenient flags for Borg's

sample/cron-alpine/borgmatic

@@ -1,3 +0,0 @@
-# You can drop this file into /etc/cron.d/ to run borgmatic nightly.
-
-0 3 * * * PATH=$PATH:/usr/bin /root/.local/bin/borgmatic

sample/cron/borgmatic

@@ -1,3 +1,3 @@
 # You can drop this file into /etc/cron.d/ to run borgmatic nightly.
 
-0 3 * * * root PATH=$PATH:/usr/local/bin /root/.local/bin/borgmatic
+0 3 * * * root PATH=$PATH:/usr/bin:/usr/local/bin /root/.local/bin/borgmatic --syslog-verbosity 1

sample/systemd/borgmatic.service

@@ -1,7 +1,22 @@
 [Unit]
 Description=borgmatic backup
+Wants=network-online.target
+After=network-online.target
+ConditionACPower=true
 
 [Service]
 Type=oneshot
-ExecStart=/root/.local/bin/borgmatic
+
+# Lower CPU and I/O priority.
+Nice=19
+CPUSchedulingPolicy=batch
+IOSchedulingClass=best-effort
+IOSchedulingPriority=7
+IOWeight=100
+
+Restart=no
 LogRateLimitIntervalSec=0
+
+# Delay start to prevent backups running during boot.
+ExecStartPre=sleep 1m
+ExecStart=systemd-inhibit --who="borgmatic" --why="Prevent interrupting scheduled backup" /root/.local/bin/borgmatic --syslog-verbosity 1

setup.py

@@ -1,6 +1,6 @@
 from setuptools import find_packages, setup
 
-VERSION = '1.3.19'
+VERSION = '1.3.20'
 
 
 setup(

tests/unit/borg/test_create.py

@@ -758,6 +758,29 @@ def test_create_archive_with_stats_calls_borg_with_stats_parameter():
     )
 
 
+def test_create_archive_with_progress_calls_borg_with_progress_parameter():
+    flexmock(module).should_receive('_expand_directories').and_return(('foo', 'bar'))
+    flexmock(module).should_receive('_expand_home_directories').and_return(())
+    flexmock(module).should_receive('_write_pattern_file').and_return(None)
+    flexmock(module).should_receive('_make_pattern_flags').and_return(())
+    flexmock(module).should_receive('_make_exclude_flags').and_return(())
+    flexmock(module).should_receive('execute_command_without_capture').with_args(
+        ('borg', 'create', '--progress') + ARCHIVE_WITH_PATHS
+    )
+
+    module.create_archive(
+        dry_run=False,
+        repository='repo',
+        location_config={
+            'source_directories': ['foo', 'bar'],
+            'repositories': ['repo'],
+            'exclude_patterns': None,
+        },
+        storage_config={},
+        progress=True,
+    )
+
+
 def test_create_archive_with_json_calls_borg_with_json_parameter():
     flexmock(module).should_receive('_expand_directories').and_return(('foo', 'bar'))
     flexmock(module).should_receive('_expand_home_directories').and_return(())

tests/unit/borg/test_extract.py

@@ -195,7 +195,9 @@ def test_extract_archive_calls_borg_with_dry_run_parameter():
 
 
 def test_extract_archive_calls_borg_with_progress_parameter():
-    insert_execute_command_mock(('borg', 'extract', '--progress', 'repo::archive'))
+    flexmock(module).should_receive('execute_command_without_capture').with_args(
+        ('borg', 'extract', '--progress', 'repo::archive')
+    ).once()
 
     module.extract_archive(
         dry_run=False,

tests/unit/borg/test_init.py

@@ -23,8 +23,8 @@ def insert_info_command_not_found_mock():
 
 
 def insert_init_command_mock(init_command, **kwargs):
-    flexmock(module.subprocess).should_receive('check_call').with_args(
-        init_command, **kwargs
+    flexmock(module).should_receive('execute_command_without_capture').with_args(
+        init_command
     ).once()
 
 
@@ -35,18 +35,9 @@ def test_initialize_repository_calls_borg_with_parameters():
     module.initialize_repository(repository='repo', encryption_mode='repokey')
 
 
-def test_initialize_repository_does_not_raise_for_borg_init_warning():
-    insert_info_command_not_found_mock()
-    flexmock(module.subprocess).should_receive('check_call').and_raise(
-        module.subprocess.CalledProcessError(1, 'borg init')
-    )
-
-    module.initialize_repository(repository='repo', encryption_mode='repokey')
-
-
 def test_initialize_repository_raises_for_borg_init_error():
     insert_info_command_not_found_mock()
-    flexmock(module.subprocess).should_receive('check_call').and_raise(
+    flexmock(module).should_receive('execute_command_without_capture').and_raise(
         module.subprocess.CalledProcessError(2, 'borg init')
     )
 
@@ -56,7 +47,7 @@ def test_initialize_repository_raises_for_borg_init_error():
 
 def test_initialize_repository_skips_initialization_when_repository_already_exists():
     insert_info_command_found_mock()
-    flexmock(module.subprocess).should_receive('check_call').never()
+    flexmock(module).should_receive('execute_command_without_capture').never()
 
     module.initialize_repository(repository='repo', encryption_mode='repokey')
 

tests/unit/test_execute.py

@@ -1,5 +1,6 @@
 import logging
 
+import pytest
 from flexmock import flexmock
 
 from borgmatic import execute as module
@@ -49,3 +50,28 @@ def test_execute_command_captures_output_with_shell():
     output = module.execute_command(full_command, output_log_level=None, shell=True)
 
     assert output == expected_output
+
+
+def test_execute_command_without_capture_does_not_raise_on_success():
+    flexmock(module.subprocess).should_receive('check_call').and_raise(
+        module.subprocess.CalledProcessError(0, 'borg init')
+    )
+
+    module.execute_command_without_capture(('borg', 'init'))
+
+
+def test_execute_command_without_capture_does_not_raise_on_warning():
+    flexmock(module.subprocess).should_receive('check_call').and_raise(
+        module.subprocess.CalledProcessError(1, 'borg init')
+    )
+
+    module.execute_command_without_capture(('borg', 'init'))
+
+
+def test_execute_command_without_capture_raises_on_error():
+    flexmock(module.subprocess).should_receive('check_call').and_raise(
+        module.subprocess.CalledProcessError(2, 'borg init')
+    )
+
+    with pytest.raises(module.subprocess.CalledProcessError):
+        module.execute_command_without_capture(('borg', 'init'))