Add end-to-end tests for the systemd credential hook (#966).

NEWS

@@ -10,6 +10,8 @@
    refused to run checks in this situation.
  * #989: Fix the log message code to avoid using Python 3.10+ logging features. Now borgmatic will
    work with Python 3.9 again.
+ * Capture and delay any log records produced before logging is fully configured, so early log
+   records don't get lost.
  * Add support for Python 3.13.
 
 1.9.9

borgmatic/config/credential.py

@@ -1,7 +1,10 @@
 import borgmatic.hooks.dispatch
 
 
-def resolve_credentials(config, item=None):
+UNSPECIFIED = object()
+
+
+def resolve_credentials(config, item=UNSPECIFIED):
     '''
     Resolves values like "!credential hookname credentialname" from the given configuration by
     calling relevant hooks to get the actual credential values. The item parameter is used to
@@ -10,7 +13,7 @@ def resolve_credentials(config, item=None):
 
     Raise ValueError if the config could not be parsed or the credential could not be loaded.
     '''
-    if not item:
+    if item is UNSPECIFIED:
         item = config
 
     if isinstance(item, str):

borgmatic/hooks/credential/systemd.py

@@ -1,11 +1,7 @@
-import functools
 import logging
 import os
 import re
 
-import borgmatic.config.paths
-import borgmatic.execute
-
 logger = logging.getLogger(__name__)
 
 
@@ -15,7 +11,7 @@ CREDENTIAL_NAME_PATTERN = re.compile(r'^\w+$')
 def load_credential(hook_config, config, credential_name):
     '''
     Given the hook configuration dict, the configuration dict, and a credential name to load, read
-    the credential from the corresonding systemd credential file and return it.
+    the credential from the corresponding systemd credential file and return it.
 
     Raise ValueError if the systemd CREDENTIALS_DIRECTORY environment variable is not set, the
     credential name is invalid, or the credential file cannot be read.

borgmatic/logger.py

@@ -269,6 +269,10 @@ class Delayed_logging_handler(logging.handlers.BufferingHandler):
     target handlers are actually set). It's useful for holding onto messages logged before logging
     is configured, ensuring those records eventually make their way to the relevant logging
     handlers.
+
+    When flushing, don't forward log records to a target handler if the record's log level is below
+    that of the handler. This recreates the standard logging behavior of, say, logging.DEBUG records
+    getting suppressed if a handler's level is only set to logging.INFO.
     '''
 
     def __init__(self):
@@ -288,7 +292,8 @@ class Delayed_logging_handler(logging.handlers.BufferingHandler):
 
             for record in self.buffer:
                 for target in self.targets:
-                    target.handle(record)
+                    if record.levelno >= target.level:
+                        target.handle(record)
 
             self.buffer.clear()
         finally:

docs/how-to/provide-your-passwords.md

@@ -129,6 +129,12 @@ encryption_passcommand: cat ${CREDENTIALS_DIRECTORY}/borgmatic_backupserver1
 Adjust `borgmatic_backupserver1` according to the name of the credential and the
 directory set in the service file.
 
+Be aware that when using this systemd `!credential` feature, you can no longer
+run borgmatic outside of its systemd service, as the credentials are only
+available from within the context of that service. The one exception is
+`borgmatic config validate`, which doesn't actually load any credentials and
+should continue working anywhere.
+
 
 ### Environment variable interpolation
 

tests/end-to-end/hooks/credential/test_systemd.py

@@ -0,0 +1,71 @@
+import json
+import os
+import shutil
+import subprocess
+import sys
+import tempfile
+
+
+def generate_configuration(config_path, repository_path):
+    '''
+    Generate borgmatic configuration into a file at the config path, and update the defaults so as
+    to work for testing, including updating the source directories, injecting the given repository
+    path, and tacking on an encryption passphrase loaded from systemd.
+    '''
+    subprocess.check_call(f'borgmatic config generate --destination {config_path}'.split(' '))
+    config = (
+        open(config_path)
+        .read()
+        .replace('ssh://user@backupserver/./sourcehostname.borg', repository_path)
+        .replace('- path: /mnt/backup', '')
+        .replace('label: local', '')
+        .replace('- /home/user/path with spaces', '')
+        .replace('- /home', f'- {config_path}')
+        .replace('- /etc', '')
+        .replace('- /var/log/syslog*', '')
+        + '\nencryption_passphrase: !credential systemd mycredential'
+    )
+    config_file = open(config_path, 'w')
+    config_file.write(config)
+    config_file.close()
+
+
+def test_borgmatic_command():
+    # Create a Borg repository.
+    temporary_directory = tempfile.mkdtemp()
+    repository_path = os.path.join(temporary_directory, 'test.borg')
+    extract_path = os.path.join(temporary_directory, 'extract')
+
+    original_working_directory = os.getcwd()
+    os.mkdir(extract_path)
+    os.chdir(extract_path)
+
+    try:
+        config_path = os.path.join(temporary_directory, 'test.yaml')
+        generate_configuration(config_path, repository_path)
+
+        credential_path = os.path.join(temporary_directory, 'mycredential')
+        with open(credential_path, 'w') as credential_file:
+            credential_file.write('test')
+
+        subprocess.check_call(
+            f'borgmatic -v 2 --config {config_path} repo-create --encryption repokey'.split(' '),
+            env=dict(os.environ, **{'CREDENTIALS_DIRECTORY': temporary_directory}),
+        )
+
+        # Run borgmatic to generate a backup archive, and then list it to make sure it exists.
+        subprocess.check_call(
+            f'borgmatic --config {config_path}'.split(' '),
+            env=dict(os.environ, **{'CREDENTIALS_DIRECTORY': temporary_directory}),
+        )
+        output = subprocess.check_output(
+            f'borgmatic --config {config_path} list --json'.split(' '),
+            env=dict(os.environ, **{'CREDENTIALS_DIRECTORY': temporary_directory}),
+        ).decode(sys.stdout.encoding)
+        parsed_output = json.loads(output)
+
+        assert len(parsed_output) == 1
+        assert len(parsed_output[0]['archives']) == 1
+    finally:
+        os.chdir(original_working_directory)
+        shutil.rmtree(temporary_directory)

tests/unit/config/test_credential.py

@@ -1,14 +1,22 @@
 import pytest
 from flexmock import flexmock
 
-
 from borgmatic.config import credential as module
 
 
-def test_resolve_credentials_ignores_string_without_credential_tag():
+def test_resolve_credentials_passes_through_string_without_credential_tag():
+    flexmock(module.borgmatic.hooks.dispatch).should_receive('call_hook').never()
+
+    assert (
+        module.resolve_credentials(config=flexmock(), item='!no credentials here')
+        == '!no credentials here'
+    )
+
+
+def test_resolve_credentials_passes_through_none():
     flexmock(module.borgmatic.hooks.dispatch).should_receive('call_hook').never()
 
-    module.resolve_credentials(config=flexmock(), item='!no credentials here')
+    assert module.resolve_credentials(config=flexmock(), item=None) == None
 
 
 def test_resolve_credentials_with_invalid_credential_tag_raises():

tests/unit/hooks/credential/test_systemd.py

@@ -1,8 +1,8 @@
 import io
 import sys
 
-from flexmock import flexmock
 import pytest
+from flexmock import flexmock
 
 from borgmatic.hooks.credential import systemd as module
 

tests/unit/test_logger.py

@@ -382,8 +382,8 @@ def test_delayed_logging_handler_flush_forwards_each_record_to_each_target():
     handler = module.Delayed_logging_handler()
     flexmock(handler).should_receive('acquire')
     flexmock(handler).should_receive('release')
-    handler.targets = [flexmock(), flexmock()]
-    handler.buffer = [flexmock(), flexmock()]
+    handler.targets = [flexmock(level=logging.DEBUG), flexmock(level=logging.DEBUG)]
+    handler.buffer = [flexmock(levelno=logging.DEBUG), flexmock(levelno=logging.DEBUG)]
     handler.targets[0].should_receive('handle').with_args(handler.buffer[0]).once()
     handler.targets[1].should_receive('handle').with_args(handler.buffer[0]).once()
     handler.targets[0].should_receive('handle').with_args(handler.buffer[1]).once()
@@ -394,6 +394,22 @@ def test_delayed_logging_handler_flush_forwards_each_record_to_each_target():
     assert handler.buffer == []
 
 
+def test_delayed_logging_handler_flush_skips_forwarding_when_log_record_is_too_low_for_target():
+    handler = module.Delayed_logging_handler()
+    flexmock(handler).should_receive('acquire')
+    flexmock(handler).should_receive('release')
+    handler.targets = [flexmock(level=logging.INFO), flexmock(level=logging.DEBUG)]
+    handler.buffer = [flexmock(levelno=logging.DEBUG), flexmock(levelno=logging.INFO)]
+    handler.targets[0].should_receive('handle').with_args(handler.buffer[0]).never()
+    handler.targets[1].should_receive('handle').with_args(handler.buffer[0]).once()
+    handler.targets[0].should_receive('handle').with_args(handler.buffer[1]).once()
+    handler.targets[1].should_receive('handle').with_args(handler.buffer[1]).once()
+
+    handler.flush()
+
+    assert handler.buffer == []
+
+
 def test_flush_delayed_logging_without_handlers_does_not_raise():
     root_logger = flexmock(handlers=[])
     root_logger.should_receive('removeHandler')