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

.drone.yml

@@ -1,30 +1,30 @@
 ---
 kind: pipeline
-name: python-3-5-alpine-3-9
+name: python-3-5-alpine-3-10
 
 steps:
 - name: build
-  image: python:3.5-alpine3.9
+  image: python:3.5-alpine3.10
   pull: always
   commands:
     - scripts/run-tests
 ---
 kind: pipeline
-name: python-3-6-alpine-3-9
+name: python-3-6-alpine-3-10
 
 steps:
 - name: build
-  image: python:3.6-alpine3.9
+  image: python:3.6-alpine3.10
   pull: always
   commands:
     - scripts/run-tests
 ---
 kind: pipeline
-name: python-3-7-alpine-3-9
+name: python-3-7-alpine-3-10
 
 steps:
 - name: build
-  image: python:3.7-alpine3.9
+  image: python:3.7-alpine3.10
   pull: always
   commands:
     - scripts/run-tests

MANIFEST.in

@@ -1 +1,2 @@
 include borgmatic/config/schema.yaml
+graft sample/systemd

NEWS

@@ -1,3 +1,14 @@
+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.
+
+1.3.18
+ * #220: Fix regression of argument parsing for default actions.
+
 1.3.17
  * #217: Fix error with "borgmatic check --only" command-line flag with "extract" consistency check.
 

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/borg/prune.py

@@ -64,4 +64,4 @@ def prune_archives(
         + (repository,)
     )
 
-    execute_command(full_command)
+    execute_command(full_command, output_log_level=logging.WARNING if stats else logging.INFO)

borgmatic/commands/arguments.py

@@ -80,6 +80,16 @@ def parse_global_arguments(unparsed_arguments, top_level_parser, subparsers):
         present_subparser_names.add(subparser_name)
         unused_parsed, remaining_arguments = subparser.parse_known_args(remaining_arguments)
 
+    # If no actions are explicitly requested, assume defaults: prune, create, and check.
+    if (
+        not present_subparser_names
+        and '--help' not in unparsed_arguments
+        and '-h' not in unparsed_arguments
+    ):
+        for subparser_name in ('prune', 'create', 'check'):
+            subparser = subparsers.choices[subparser_name]
+            unused_parsed, remaining_arguments = subparser.parse_known_args(remaining_arguments)
+
     # Remove the subparser names themselves.
     for subparser_name in present_subparser_names:
         if subparser_name in remaining_arguments:

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.17'
+VERSION = '1.3.20'
 
 
 setup(

tests/integration/commands/test_arguments.py

@@ -78,6 +78,18 @@ def test_parse_arguments_with_no_actions_defaults_to_all_actions_enabled():
     assert 'check' in arguments
 
 
+def test_parse_arguments_with_no_actions_passes_argument_to_relevant_actions():
+    flexmock(module.collect).should_receive('get_default_config_paths').and_return(['default'])
+
+    arguments = module.parse_arguments('--stats')
+
+    assert 'prune' in arguments
+    assert arguments['prune'].stats
+    assert 'create' in arguments
+    assert arguments['create'].stats
+    assert 'check' in arguments
+
+
 def test_parse_arguments_with_help_and_no_actions_shows_global_help(capsys):
     flexmock(module.collect).should_receive('get_default_config_paths').and_return(['default'])
 

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/borg/test_prune.py

@@ -8,8 +8,10 @@ from borgmatic.borg import prune as module
 from ..test_verbosity import insert_logging_mock
 
 
-def insert_execute_command_mock(prune_command, **kwargs):
-    flexmock(module).should_receive('execute_command').with_args(prune_command).once()
+def insert_execute_command_mock(prune_command, output_log_level):
+    flexmock(module).should_receive('execute_command').with_args(
+        prune_command, output_log_level=output_log_level
+    ).once()
 
 
 BASE_PRUNE_FLAGS = (('--keep-daily', '1'), ('--keep-weekly', '2'), ('--keep-monthly', '3'))
@@ -61,7 +63,7 @@ def test_prune_archives_calls_borg_with_parameters():
     flexmock(module).should_receive('_make_prune_flags').with_args(retention_config).and_return(
         BASE_PRUNE_FLAGS
     )
-    insert_execute_command_mock(PRUNE_COMMAND + ('repo',))
+    insert_execute_command_mock(PRUNE_COMMAND + ('repo',), logging.INFO)
 
     module.prune_archives(
         dry_run=False, repository='repo', storage_config={}, retention_config=retention_config
@@ -73,7 +75,7 @@ def test_prune_archives_with_log_info_calls_borg_with_info_parameter():
     flexmock(module).should_receive('_make_prune_flags').with_args(retention_config).and_return(
         BASE_PRUNE_FLAGS
     )
-    insert_execute_command_mock(PRUNE_COMMAND + ('--stats', '--info', 'repo'))
+    insert_execute_command_mock(PRUNE_COMMAND + ('--stats', '--info', 'repo'), logging.INFO)
     insert_logging_mock(logging.INFO)
 
     module.prune_archives(
@@ -87,7 +89,7 @@ def test_prune_archives_with_log_debug_calls_borg_with_debug_parameter():
         BASE_PRUNE_FLAGS
     )
     insert_execute_command_mock(
-        PRUNE_COMMAND + ('--stats', '--debug', '--list', '--show-rc', 'repo')
+        PRUNE_COMMAND + ('--stats', '--debug', '--list', '--show-rc', 'repo'), logging.INFO
     )
     insert_logging_mock(logging.DEBUG)
 
@@ -101,7 +103,7 @@ def test_prune_archives_with_dry_run_calls_borg_with_dry_run_parameter():
     flexmock(module).should_receive('_make_prune_flags').with_args(retention_config).and_return(
         BASE_PRUNE_FLAGS
     )
-    insert_execute_command_mock(PRUNE_COMMAND + ('--dry-run', 'repo'))
+    insert_execute_command_mock(PRUNE_COMMAND + ('--dry-run', 'repo'), logging.INFO)
 
     module.prune_archives(
         repository='repo', storage_config={}, dry_run=True, retention_config=retention_config
@@ -113,7 +115,7 @@ def test_prune_archives_with_local_path_calls_borg_via_local_path():
     flexmock(module).should_receive('_make_prune_flags').with_args(retention_config).and_return(
         BASE_PRUNE_FLAGS
     )
-    insert_execute_command_mock(('borg1',) + PRUNE_COMMAND[1:] + ('repo',))
+    insert_execute_command_mock(('borg1',) + PRUNE_COMMAND[1:] + ('repo',), logging.INFO)
 
     module.prune_archives(
         dry_run=False,
@@ -129,7 +131,7 @@ def test_prune_archives_with_remote_path_calls_borg_with_remote_path_parameters(
     flexmock(module).should_receive('_make_prune_flags').with_args(retention_config).and_return(
         BASE_PRUNE_FLAGS
     )
-    insert_execute_command_mock(PRUNE_COMMAND + ('--remote-path', 'borg1', 'repo'))
+    insert_execute_command_mock(PRUNE_COMMAND + ('--remote-path', 'borg1', 'repo'), logging.INFO)
 
     module.prune_archives(
         dry_run=False,
@@ -140,13 +142,29 @@ def test_prune_archives_with_remote_path_calls_borg_with_remote_path_parameters(
     )
 
 
+def test_prune_archives_with_stats_calls_borg_with_stats_parameter():
+    retention_config = flexmock()
+    flexmock(module).should_receive('_make_prune_flags').with_args(retention_config).and_return(
+        BASE_PRUNE_FLAGS
+    )
+    insert_execute_command_mock(PRUNE_COMMAND + ('--stats', 'repo'), logging.WARNING)
+
+    module.prune_archives(
+        dry_run=False,
+        repository='repo',
+        storage_config={},
+        retention_config=retention_config,
+        stats=True,
+    )
+
+
 def test_prune_archives_with_umask_calls_borg_with_umask_parameters():
     storage_config = {'umask': '077'}
     retention_config = flexmock()
     flexmock(module).should_receive('_make_prune_flags').with_args(retention_config).and_return(
         BASE_PRUNE_FLAGS
     )
-    insert_execute_command_mock(PRUNE_COMMAND + ('--umask', '077', 'repo'))
+    insert_execute_command_mock(PRUNE_COMMAND + ('--umask', '077', 'repo'), logging.INFO)
 
     module.prune_archives(
         dry_run=False,
@@ -162,7 +180,7 @@ def test_prune_archives_with_lock_wait_calls_borg_with_lock_wait_parameters():
     flexmock(module).should_receive('_make_prune_flags').with_args(retention_config).and_return(
         BASE_PRUNE_FLAGS
     )
-    insert_execute_command_mock(PRUNE_COMMAND + ('--lock-wait', '5', 'repo'))
+    insert_execute_command_mock(PRUNE_COMMAND + ('--lock-wait', '5', 'repo'), logging.INFO)
 
     module.prune_archives(
         dry_run=False,

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