Bump version for release.

Reviewed-on: https://projects.torsion.org/borgmatic-collective/borgmatic/pulls/1259
Reviewed-by: Dan Helfman <witten@torsion.org>

NEWS

@@ -1,3 +1,17 @@
+2.1.2
+ * #1231: If a source file is deleted during a "spot" check, consider the file as non-matching
+   and move on instead of immediately failing the entire check.
+ * #1250: Fix a regression in which the "--stats" flag hides statistics at default verbosity.
+ * #1251: Fix a regression in the ntfy monitoring hook in which borgmatic sends tags incorrectly,
+   resulting in "400 Bad Request" from ntfy.
+ * #1258: Fix a "codec can't decode byte" error when running commands that output multi-byte unicode
+   characters.
+ * #1260: Fix for SSH warnings from Borg showing up as JSON logs even without the "--log-json" flag.
+ * #1252: Work around Borg returning a warning exit code when a repository/archive check fails. Now,
+   borgmatic interprets such failures as errors.
+ * Deduplicate overlapping source directories and patterns so they don't throw off "spot" check file
+   counts and cause spurious check failures.
+
 2.1.1
  * #1241: For the "recreate" action, actually pass the "--dry-run" flag through to Borg instead of
    just skipping the Borg call.

borgmatic/actions/check.py

@@ -9,6 +9,7 @@ import pathlib
 import random
 import shlex
 import shutil
+import subprocess
 import textwrap
 
 import borgmatic.actions.config.bootstrap
@@ -418,7 +419,13 @@ def collect_spot_check_source_paths(
     )
 
     return tuple(
-        path for path in paths if os.path.isfile(os.path.join(working_directory or '', path))
+        # Use dict.fromkeys() to deduplicate file paths, which are present in Borg's dry run output
+        # when there are overlapping source patterns. For instance, if both "/foo" and
+        # "/foo/file.txt" are in configured patterns, then "/foo/file.txt" will show up in Borg's
+        # dry run output twice.
+        dict.fromkeys(
+            path for path in paths if os.path.isfile(os.path.join(working_directory or '', path))
+        )
     )
 
 
@@ -524,41 +531,70 @@ def compare_spot_check_hashes(
         hash_paths = tuple(
             path for path in source_sample_paths_subset if path in hashable_source_sample_path
         )
-        hash_lines = borgmatic.execute.execute_command_and_capture_output(
-            tuple(
-                shlex.quote(part)
-                for part in shlex.split(spot_check_config.get('xxh64sum_command', 'xxh64sum'))
-            )
-            + hash_paths,
-            working_directory=working_directory,
-        )
 
-        source_hashes.update(
+        try:
-            **dict(
+            hash_lines = borgmatic.execute.execute_command_and_capture_output(
-                zip(
+                tuple(
-                    # xxh64sum rewrites/escapes the paths that it returns alongside its hashes, for
+                    shlex.quote(part)
-                    # instance if they contain special characters. When that happens, they don't
+                    for part in shlex.split(spot_check_config.get('xxh64sum_command', 'xxh64sum'))
-                    # match the original source paths and therefore hash lookups fail. So when
+                )
-                    # building this lookup dict, use the original unaltered paths we provided as
+                + hash_paths,
-                    # input to xxh64sum.
+                working_directory=working_directory,
-                    hash_paths,
+            )
-                    (
+            source_hashes.update(
-                        # For some reason, xxh64sum prefixes the hash with a backslash if the path
+                **dict(
-                        # contains a newline. Work around that.
+                    zip(
-                        line.split('  ', 1)[0].lstrip('\\')
+                        # xxh64sum rewrites/escapes the paths that it returns alongside its hashes, for
-                        for line in hash_lines
+                        # instance if they contain special characters. When that happens, they don't
+                        # match the original source paths and therefore hash lookups fail. So when
+                        # building this lookup dict, use the original unaltered paths we provided as
+                        # input to xxh64sum.
+                        hash_paths,
+                        (
+                            # For some reason, xxh64sum prefixes the hash with a backslash if the path
+                            # contains a newline. Work around that.
+                            line.split('  ', 1)[0].lstrip('\\')
+                            for line in hash_lines
+                        ),
                     ),
+                    # Represent non-existent files as having empty hashes so the comparison below still
+                    # works. Same thing for filesystem links, since Borg produces empty archive hashes
+                    # for them.
+                    **{
+                        path: ''
+                        for path in source_sample_paths_subset
+                        if path not in hashable_source_sample_path
+                    },
                 ),
-                # Represent non-existent files as having empty hashes so the comparison below still
+            )
-                # works. Same thing for filesystem links, since Borg produces empty archive hashes
+        except subprocess.CalledProcessError:
-                # for them.
+            # This can happen if a file we planned to hash gets deleted right before we try to hash
-                **{
+            # it. Falling back to individual file hashing allows us to find and mark just the
-                    path: ''
+            # file(s) with problems instead of failing the whole batch.
-                    for path in source_sample_paths_subset
+            logger.warning(
-                    if path not in hashable_source_sample_path
+                'Bulk source path hashing failed for this batch; falling back to individual file hashing'
-                },
+            )
-            ),
+
-        )
+            for hash_path in hash_paths:
+                try:
+                    hash_lines = borgmatic.execute.execute_command_and_capture_output(
+                        (
+                            *(
+                                shlex.quote(part)
+                                for part in shlex.split(
+                                    spot_check_config.get('xxh64sum_command', 'xxh64sum')
+                                )
+                            ),
+                            hash_path,
+                        ),
+                        working_directory=working_directory,
+                    )
+                    source_hashes[hash_path] = next(hash_lines).split('  ', 1)[0].lstrip('\\')
+                except (subprocess.CalledProcessError, StopIteration):  # noqa: PERF203
+                    logger.warning(
+                        f'Source path hashing failed for {hash_path}; treating as missing'
+                    )
+                    source_hashes[hash_path] = ''
 
         # Get the hash for each file in the archive.
         archive_hashes.update(

borgmatic/borg/check.py

@@ -149,8 +149,10 @@ def check_archives(
 
     max_duration = check_arguments.max_duration or repository_check_config.get('max_duration')
 
+    # If not configured, elevate Borg's exit code 1 (an ostensible warning) to error, because Borg
+    # returns exit code 1 for repository check errors!
+    borg_exit_codes = [*config.get('borg_exit_codes', []), *[{'code': 1, 'treat_as': 'error'}]]
     umask = config.get('umask')
-    borg_exit_codes = config.get('borg_exit_codes')
     working_directory = borgmatic.config.paths.get_working_directory(config)
 
     if 'data' in checks:

borgmatic/execute.py

@@ -29,6 +29,19 @@ class Exit_status(enum.Enum):
     ERROR = 4
 
 
+def command_is_borg(command, borg_local_path):
+    '''
+    Given a command as a sequence and the Borg local path, return whether that command is a call to
+    Borg.
+    '''
+    parsed_command = command.split(' ', 1) if isinstance(command, str) else command
+
+    if not parsed_command:
+        return False
+
+    return bool(borg_local_path and parsed_command[0] == borg_local_path)
+
+
 def interpret_exit_code(command, exit_code, borg_local_path=None, borg_exit_codes=None):  # noqa: PLR0911
     '''
     Return an Exit_status value (e.g. SUCCESS, ERROR, or WARNING) based on interpreting the given
@@ -42,9 +55,7 @@ def interpret_exit_code(command, exit_code, borg_local_path=None, borg_exit_code
     if exit_code == 0:
         return Exit_status.SUCCESS
 
-    parsed_command = command.split(' ', 1) if isinstance(command, str) else command
+    if command_is_borg(command, borg_local_path):
-
-    if borg_local_path and parsed_command[0] == borg_local_path:
         # First try looking for the exit code in the borg_exit_codes configuration.
         for entry in borg_exit_codes or ():
             if entry.get('code') == exit_code:
@@ -105,19 +116,41 @@ def output_buffers_for_process(process, exclude_stdouts):
     )
 
 
+BORG_LOG_LEVEL_ELEVATION_THRESHOLD = 10
+
+
 def borg_json_log_line_to_record(line, log_level):
     '''
     Given a single Borg "--log-json"-style log line and a log level, return the line converted to a
     logging.LogRecord instance. Return None if the line can't be parsed as JSON.
+
+    If Borg provides a log level in its JSON, prefer logging at that level. But if Borg doesn't
+    provide a log level—or the log level given to this function is just a little bit higher than
+    Borg's—elevate to that level. This supports use cases like elevating Borg's INFO level logs to
+    borgmatic's custom ANSWER level so that requested data shows up even at the default verbosity.
     '''
     with contextlib.suppress(json.JSONDecodeError, TypeError, KeyError, AttributeError):
         log_data = json.loads(line)
         log_type = log_data.get('type')
 
         if log_type == 'log_message':
+            borg_log_level = logging._nameToLevel.get(log_data.get('levelname'))
+            log_level_delta = 0 if log_level is None else log_level - borg_log_level
+
+            if log_level_delta > 0 and log_level_delta < BORG_LOG_LEVEL_ELEVATION_THRESHOLD:
+                return logging.makeLogRecord(
+                    dict(
+                        levelno=log_level,
+                        created=log_data.get('time'),
+                        msg=log_data.get('message'),
+                        levelname=logging.getLevelName(log_level),
+                        name=log_data.get('name'),
+                    )
+                )
+
             return logging.makeLogRecord(
                 dict(
-                    levelno=logging._nameToLevel.get(log_data.get('levelname')),
+                    levelno=borg_log_level,
                     created=log_data.get('time'),
                     msg=log_data.get('message'),
                     levelname=log_data.get('levelname'),
@@ -166,9 +199,7 @@ def parse_log_line(line, log_level, elevate_stderr, borg_local_path, command):
     came from stderr and the string "warning:" appears at the start of the log line. In that case,
     just elevate the log level to a WARN.
     '''
-    parsed_command = command.split(' ', 1) if isinstance(command, str) else command
+    if command_is_borg(command, borg_local_path):
-
-    if borg_local_path and parsed_command[0] == borg_local_path:
         log_record = borg_json_log_line_to_record(line, log_level)
 
         if log_record:
@@ -215,10 +246,12 @@ def read_lines(buffer, process, line_separator='\n'):
     call to know when to read more lines. Otherwise, the generator will busywait if it's called in a
     tight loop.
     '''
-    data = ''
+    data = b''
+    encoded_separator = line_separator.encode()
+    separator_size = len(encoded_separator)
 
     while True:
-        chunk = os.read(buffer.fileno(), READ_CHUNK_SIZE).decode()
+        chunk = os.read(buffer.fileno(), READ_CHUNK_SIZE)
 
         if not chunk:  # EOF
             # The process is still running, so we keep running too.
@@ -233,19 +266,19 @@ def read_lines(buffer, process, line_separator='\n'):
         # Split the data into lines, holding back anything leftover that might
         # be a partial line.
         while True:
-            separator_position = data.find(line_separator)
+            separator_position = data.find(encoded_separator)
 
             if separator_position == -1:
                 break
 
-            lines.append(data[:separator_position].rstrip())
+            lines.append(data[:separator_position].decode())
-            data = data[separator_position + 1 :]
+            data = data[separator_position + separator_size :]
 
         yield tuple(lines)
 
     # Yield any leftover data from the end of the buffer.
     if data:
-        yield (data.rstrip(),)
+        yield (data.decode().rstrip(),)
 
 
 Buffer_reader = collections.namedtuple(
@@ -612,7 +645,9 @@ def execute_command_and_capture_output(
             command,
             stdin=input_file,
             stdout=subprocess.PIPE,
-            stderr=subprocess.PIPE if capture_stderr else None,
+            stderr=subprocess.PIPE
+            if capture_stderr or command_is_borg(command, borg_local_path)
+            else None,
             shell=shell,
             env=environment,
             cwd=working_directory,

borgmatic/hooks/monitoring/ntfy.py

@@ -22,6 +22,19 @@ def initialize_monitor(
     '''
 
 
+def convert_string_to_array(value):
+    value = '' if value is None else str(value)
+    items = []
+
+    for item in value.split(','):
+        stripped = item.strip()
+
+        if stripped:
+            items.append(stripped)
+
+    return items
+
+
 PRIORITY_NAME_TO_ID = {
     'max': 5,
     'urgent': 5,
@@ -66,7 +79,7 @@ def ping_monitor(hook_config, config, config_filename, state, monitoring_log_lev
             'title': state_config.get('title'),
             'message': state_config.get('message'),
             'priority': PRIORITY_NAME_TO_ID.get(state_config.get('priority'), default_priority),
-            'tags': state_config.get('tags'),
+            'tags': convert_string_to_array(state_config.get('tags')),
         }
 
         try:

docs/how-to/backup-to-a-removable-drive-or-an-intermittent-server.md

@@ -82,7 +82,7 @@ before_actions:
 option in the `hooks:` section of your configuration.
 
 <span class="minilink minilink-addedin">Prior to version 1.7.0</span> Use
-`before_create` or similar instead of `before_actions`, which was introduced in
+`before_backup` or similar instead of `before_actions`, which was introduced in
 borgmatic 1.7.0.
 
 What this does is check if the `findmnt` command errors when probing for a

docs/reference/configuration/command-hooks.md

@@ -12,11 +12,15 @@ list of `commands:` in your borgmatic configuration file. For example:
 ```yaml
 commands:
     - before: action
-      when: [create]
+      when: [check]  # This is an inline YAML sequence.
       run:
           - echo "Before create!"
+    - before: action
+      when: [create, prune]  # Also an inline YAML sequence.
+      run:
+          - echo "Before create or prune!"
     - after: action
-      when:
+      when:  # Multi-line YAML sequence, equivalent to "[create, prune]".
           - create
           - prune
       run:
@@ -29,7 +33,7 @@ commands:
 Each command in the `commands:` list has the following options:
 
  * `before` or `after`: Name for the point in borgmatic's execution that the commands should be run before or after, one of:
-    * `action` runs before or after each action for each repository. This replaces the deprecated `before_create`, `after_prune`, etc.
+    * `action` runs before or after each action for each repository. This replaces the deprecated `before_backup`, `after_prune`, etc.
     * `repository` runs before or after all actions for each repository. This replaces the deprecated `before_actions` and `after_actions`.
     * `configuration` runs before or after all actions and repositories in the current configuration file.
     * `everything` runs before or after all configuration files. Errors here do not trigger `error` hooks or the `fail` state in monitoring hooks. This replaces the deprecated `before_everything` and `after_everything`.

pyproject.toml

@@ -1,6 +1,6 @@
 [project]
 name = "borgmatic"
-version = "2.1.1"
+version = "2.1.2"
 authors = [
   { name="Dan Helfman", email="witten@torsion.org" },
 ]

tests/integration/test_execute.py

@@ -26,6 +26,19 @@ def test_read_lines_yields_single_line_longer_than_chunk_size():
     )
 
 
+def test_read_lines_yields_single_line_with_multibyte_unicode_character_spanning_chunk_boundary():
+    # In case it's not clear, "ñ" is a multi-byte UTF-8 character. The "a" shifts it over one byte
+    # so it straddles the chunk boundary.
+    process = subprocess.Popen(['echo', 'aññññññññññññññññññññññññññññññ'], stdout=subprocess.PIPE)
+
+    assert tuple(flexmock(module, READ_CHUNK_SIZE=16).read_lines(process.stdout, process)) == (
+        (),
+        (),
+        (),
+        ('aññññññññññññññññññññññññññññññ',),
+    )
+
+
 def test_read_lines_yields_multiple_lines():
     process = subprocess.Popen(['echo', 'hi\nthere'], stdout=subprocess.PIPE)
 

tests/unit/actions/test_check.py

@@ -986,6 +986,65 @@ def test_collect_spot_check_source_paths_uses_working_directory():
     ) == ('foo', 'bar')
 
 
+def test_collect_spot_check_source_paths_deduplicates_borg_output_paths():
+    flexmock(module.borgmatic.hooks.dispatch).should_receive('call_hooks').and_return(
+        {'hook1': False, 'hook2': True},
+    )
+    flexmock(module.borgmatic.config.paths).should_receive('get_working_directory').and_return(
+        flexmock(),
+    )
+    flexmock(module.borgmatic.actions.pattern).should_receive('collect_patterns').and_return(
+        (Pattern('collected'),),
+    )
+    flexmock(module.borgmatic.actions.pattern).should_receive('process_patterns').with_args(
+        (
+            Pattern('collected', source=module.borgmatic.borg.pattern.Pattern_source.HOOK),
+            Pattern('extra.yaml', source=module.borgmatic.borg.pattern.Pattern_source.INTERNAL),
+        ),
+        config=object,
+        working_directory=None,
+    ).and_return(
+        [Pattern('foo'), Pattern('bar')],
+    )
+    flexmock(module.borgmatic.borg.create).should_receive('make_base_create_command').with_args(
+        dry_run=True,
+        repository_path='repo',
+        config=object,
+        patterns=[Pattern('foo'), Pattern('bar')],
+        local_borg_version=object,
+        global_arguments=object,
+        borgmatic_runtime_directory='/run/borgmatic',
+        local_path=object,
+        remote_path=object,
+        stream_processes=True,
+    ).and_return((('borg', 'create'), ('repo::archive',), flexmock()))
+    flexmock(module.borgmatic.borg.environment).should_receive('make_environment').and_return(
+        flexmock(),
+    )
+    flexmock(module.borgmatic.config.paths).should_receive('get_working_directory').and_return(None)
+    flexmock(module.borgmatic.execute).should_receive(
+        'execute_command_and_capture_output',
+    ).and_yield(
+        'warning: stuff',
+        '- /etc/path',
+        '+ /etc/other',
+        '? /nope',
+        '- /etc/path',
+    )
+    flexmock(module.os.path).should_receive('isfile').and_return(True)
+
+    assert module.collect_spot_check_source_paths(
+        repository={'path': 'repo'},
+        config={'working_directory': '/'},
+        local_borg_version=flexmock(),
+        global_arguments=flexmock(),
+        local_path=flexmock(),
+        remote_path=flexmock(),
+        borgmatic_runtime_directory='/run/borgmatic',
+        bootstrap_config_paths=('extra.yaml',),
+    ) == ('/etc/path', '/etc/other')
+
+
 def test_compare_spot_check_hashes_returns_paths_having_failing_hashes():
     flexmock(module.random).should_receive('SystemRandom').and_return(
         flexmock(sample=lambda population, count: population[:count]),
@@ -1115,6 +1174,59 @@ def test_compare_spot_check_hashes_handles_incorrect_path_names_from_xxh64sum():
     ) == ('/bar',)
 
 
+def test_compare_spot_check_hashes_with_xxh64sum_failure_falls_back_to_individual_file_hashing():
+    flexmock(module.random).should_receive('SystemRandom').and_return(
+        flexmock(sample=lambda population, count: population[:count]),
+    )
+    flexmock(module.borgmatic.config.paths).should_receive('get_working_directory').and_return(
+        None,
+    )
+    flexmock(module.os.path).should_receive('exists').and_return(True)
+    flexmock(module.os.path).should_receive('islink').and_return(False)
+    flexmock(module.borgmatic.execute).should_receive(
+        'execute_command_and_capture_output',
+    ).with_args(('xxh64sum', '/foo', '/bar'), working_directory=None).and_raise(
+        module.subprocess.CalledProcessError(1, 'wtf')
+    )
+    flexmock(module.borgmatic.execute).should_receive(
+        'execute_command_and_capture_output',
+    ).with_args(('xxh64sum', '/foo'), working_directory=None).and_raise(
+        module.subprocess.CalledProcessError(1, 'wtf')
+    ).once()
+    flexmock(module.borgmatic.execute).should_receive(
+        'execute_command_and_capture_output',
+    ).with_args(('xxh64sum', '/bar'), working_directory=None).and_yield(
+        'hash2  /bar',
+    ).once()
+
+    flexmock(module.borgmatic.borg.list).should_receive('capture_archive_listing').and_yield(
+        {'xxh64': 'hash1', 'path': 'foo'},
+        {'xxh64': 'hash2', 'path': 'bar'},
+    )
+
+    assert module.compare_spot_check_hashes(
+        repository={'path': 'repo'},
+        archive='archive',
+        config={
+            'checks': [
+                {
+                    'name': 'archives',
+                    'frequency': '2 weeks',
+                },
+                {
+                    'name': 'spot',
+                    'data_sample_percentage': 50,
+                },
+            ],
+        },
+        local_borg_version=flexmock(),
+        global_arguments=flexmock(),
+        local_path=flexmock(),
+        remote_path=flexmock(),
+        source_paths=('/foo', '/bar', '/baz', '/quux'),
+    ) == ('/foo',)
+
+
 def test_compare_spot_check_hashes_returns_relative_paths_having_failing_hashes():
     flexmock(module.random).should_receive('SystemRandom').and_return(
         flexmock(sample=lambda population, count: population[:count]),

tests/unit/borg/test_check.py

@@ -24,7 +24,7 @@ def insert_execute_command_mock(
         environment=None,
         working_directory=working_directory,
         borg_local_path=command[0],
-        borg_exit_codes=borg_exit_codes,
+        borg_exit_codes=(borg_exit_codes or []) + [{'code': 1, 'treat_as': 'error'}],
     ).once()
 
 
@@ -335,7 +335,7 @@ def test_check_archives_with_progress_passes_through_to_borg():
         environment=None,
         working_directory=None,
         borg_local_path='borg',
-        borg_exit_codes=None,
+        borg_exit_codes=[{'code': 1, 'treat_as': 'error'}],
     ).once()
 
     module.check_archives(
@@ -371,7 +371,7 @@ def test_check_archives_with_log_json_and_progress_passes_through_both_to_borg()
         environment=None,
         working_directory=None,
         borg_local_path='borg',
-        borg_exit_codes=None,
+        borg_exit_codes=[{'code': 1, 'treat_as': 'error'}],
     ).once()
 
     module.check_archives(
@@ -407,7 +407,7 @@ def test_check_archives_with_repair_passes_through_to_borg():
         environment=None,
         working_directory=None,
         borg_local_path='borg',
-        borg_exit_codes=None,
+        borg_exit_codes=[{'code': 1, 'treat_as': 'error'}],
     ).once()
 
     module.check_archives(
@@ -443,7 +443,7 @@ def test_check_archives_with_log_json_and_repair_passes_through_both_to_borg():
         environment=None,
         working_directory=None,
         borg_local_path='borg',
-        borg_exit_codes=None,
+        borg_exit_codes=[{'code': 1, 'treat_as': 'error'}],
     ).once()
 
     module.check_archives(
@@ -479,7 +479,7 @@ def test_check_archives_with_max_duration_flag_passes_through_to_borg():
         environment=None,
         working_directory=None,
         borg_local_path='borg',
-        borg_exit_codes=None,
+        borg_exit_codes=[{'code': 1, 'treat_as': 'error'}],
     ).once()
 
     module.check_archives(
@@ -515,7 +515,7 @@ def test_check_archives_with_max_duration_option_passes_through_to_borg():
         environment=None,
         working_directory=None,
         borg_local_path='borg',
-        borg_exit_codes=None,
+        borg_exit_codes=[{'code': 1, 'treat_as': 'error'}],
     ).once()
 
     module.check_archives(
@@ -689,7 +689,7 @@ def test_check_archives_with_max_duration_flag_overrides_max_duration_option():
         environment=None,
         working_directory=None,
         borg_local_path='borg',
-        borg_exit_codes=None,
+        borg_exit_codes=[{'code': 1, 'treat_as': 'error'}],
     ).once()
 
     module.check_archives(
@@ -854,7 +854,7 @@ def test_check_archives_with_local_path_calls_borg_via_local_path():
 
 def test_check_archives_with_exit_codes_calls_borg_using_them():
     checks = {'repository'}
-    borg_exit_codes = flexmock()
+    borg_exit_codes = [{'code': 101, 'treat_as': 'error'}]
     config = {'borg_exit_codes': borg_exit_codes}
     flexmock(module).should_receive('make_check_name_flags').with_args(checks, ()).and_return(())
     flexmock(module.flags).should_receive('make_repository_flags').and_return(('repo',))
@@ -1026,7 +1026,7 @@ def test_check_archives_with_match_archives_passes_through_to_borg():
         environment=None,
         working_directory=None,
         borg_local_path='borg',
-        borg_exit_codes=None,
+        borg_exit_codes=[{'code': 1, 'treat_as': 'error'}],
     ).once()
 
     module.check_archives(

tests/unit/hooks/monitoring/test_ntfy.py

@@ -1,10 +1,26 @@
 from enum import Enum
 
+import pytest
 from flexmock import flexmock
 
 import borgmatic.hooks.monitoring.monitor
 from borgmatic.hooks.monitoring import ntfy as module
 
+
+@pytest.mark.parametrize(
+    'tags_input,expected_tags_output',
+    (
+        (None, []),
+        ('', []),
+        ('foo', ['foo']),
+        (' foo ,  bar ,baz ', ['foo', 'bar', 'baz']),
+        ('foo,,bar,', ['foo', 'bar']),
+    ),
+)
+def test_convert_string_to_array(tags_input, expected_tags_output):
+    assert module.convert_string_to_array(tags_input) == expected_tags_output
+
+
 DEFAULT_BASE_URL = 'https://ntfy.sh'
 CUSTOM_BASE_URL = 'https://ntfy.example.com'
 TOPIC = 'borgmatic-unit-testing'
@@ -25,7 +41,7 @@ CUSTOM_MESSAGE_PAYLOAD = {
     'title': CUSTOM_MESSAGE_CONFIG['title'],
     'message': CUSTOM_MESSAGE_CONFIG['message'],
     'priority': 1,
-    'tags': CUSTOM_MESSAGE_CONFIG['tags'],
+    'tags': [CUSTOM_MESSAGE_CONFIG['tags']],
 }
 
 
@@ -35,12 +51,15 @@ def default_message_payload(state=Enum):
         'title': f'A borgmatic {state.name} event happened',
         'message': f'A borgmatic {state.name} event happened',
         'priority': 3,
-        'tags': 'borgmatic',
+        'tags': ['borgmatic'],
     }
 
 
 def test_ping_monitor_minimal_config_hits_hosted_ntfy_on_fail():
     hook_config = {'topic': TOPIC}
+    flexmock(module).should_receive('convert_string_to_array').with_args('borgmatic').and_return(
+        ['borgmatic']
+    )
     flexmock(module.borgmatic.hooks.credential.parse).should_receive(
         'resolve_credential',
     ).replace_with(lambda value, config: value)
@@ -67,6 +86,9 @@ def test_ping_monitor_with_access_token_hits_hosted_ntfy_on_fail():
         'topic': TOPIC,
         'access_token': 'abc123',
     }
+    flexmock(module).should_receive('convert_string_to_array').with_args('borgmatic').and_return(
+        ['borgmatic']
+    )
     flexmock(module.borgmatic.hooks.credential.parse).should_receive(
         'resolve_credential',
     ).replace_with(lambda value, config: value)
@@ -95,6 +117,9 @@ def test_ping_monitor_with_username_password_and_access_token_ignores_username_p
         'password': 'fakepassword',
         'access_token': 'abc123',
     }
+    flexmock(module).should_receive('convert_string_to_array').with_args('borgmatic').and_return(
+        ['borgmatic']
+    )
     flexmock(module.borgmatic.hooks.credential.parse).should_receive(
         'resolve_credential',
     ).replace_with(lambda value, config: value)
@@ -123,6 +148,9 @@ def test_ping_monitor_with_username_password_hits_hosted_ntfy_on_fail():
         'username': 'testuser',
         'password': 'fakepassword',
     }
+    flexmock(module).should_receive('convert_string_to_array').with_args('borgmatic').and_return(
+        ['borgmatic']
+    )
     flexmock(module.borgmatic.hooks.credential.parse).should_receive(
         'resolve_credential',
     ).replace_with(lambda value, config: value)
@@ -146,6 +174,9 @@ def test_ping_monitor_with_username_password_hits_hosted_ntfy_on_fail():
 
 def test_ping_monitor_with_password_but_no_username_warns():
     hook_config = {'topic': TOPIC, 'password': 'fakepassword'}
+    flexmock(module).should_receive('convert_string_to_array').with_args('borgmatic').and_return(
+        ['borgmatic']
+    )
     flexmock(module.borgmatic.hooks.credential.parse).should_receive(
         'resolve_credential',
     ).replace_with(lambda value, config: value)
@@ -170,6 +201,9 @@ def test_ping_monitor_with_password_but_no_username_warns():
 
 def test_ping_monitor_with_username_but_no_password_warns():
     hook_config = {'topic': TOPIC, 'username': 'testuser'}
+    flexmock(module).should_receive('convert_string_to_array').with_args('borgmatic').and_return(
+        ['borgmatic']
+    )
     flexmock(module.borgmatic.hooks.credential.parse).should_receive(
         'resolve_credential',
     ).replace_with(lambda value, config: value)
@@ -194,6 +228,9 @@ def test_ping_monitor_with_username_but_no_password_warns():
 
 def test_ping_monitor_minimal_config_does_not_hit_hosted_ntfy_on_start():
     hook_config = {'topic': TOPIC}
+    flexmock(module).should_receive('convert_string_to_array').with_args('borgmatic').and_return(
+        ['borgmatic']
+    )
     flexmock(module.borgmatic.hooks.credential.parse).should_receive(
         'resolve_credential',
     ).replace_with(lambda value, config: value)
@@ -211,6 +248,9 @@ def test_ping_monitor_minimal_config_does_not_hit_hosted_ntfy_on_start():
 
 def test_ping_monitor_minimal_config_does_not_hit_hosted_ntfy_on_finish():
     hook_config = {'topic': TOPIC}
+    flexmock(module).should_receive('convert_string_to_array').with_args('borgmatic').and_return(
+        ['borgmatic']
+    )
     flexmock(module.borgmatic.hooks.credential.parse).should_receive(
         'resolve_credential',
     ).replace_with(lambda value, config: value)
@@ -228,6 +268,9 @@ def test_ping_monitor_minimal_config_does_not_hit_hosted_ntfy_on_finish():
 
 def test_ping_monitor_minimal_config_hits_selfhosted_ntfy_on_fail():
     hook_config = {'topic': TOPIC, 'server': CUSTOM_BASE_URL}
+    flexmock(module).should_receive('convert_string_to_array').with_args('borgmatic').and_return(
+        ['borgmatic']
+    )
     flexmock(module.borgmatic.hooks.credential.parse).should_receive(
         'resolve_credential',
     ).replace_with(lambda value, config: value)
@@ -251,6 +294,9 @@ def test_ping_monitor_minimal_config_hits_selfhosted_ntfy_on_fail():
 
 def test_ping_monitor_minimal_config_does_not_hit_hosted_ntfy_on_fail_dry_run():
     hook_config = {'topic': TOPIC}
+    flexmock(module).should_receive('convert_string_to_array').with_args('borgmatic').and_return(
+        ['borgmatic']
+    )
     flexmock(module.borgmatic.hooks.credential.parse).should_receive(
         'resolve_credential',
     ).replace_with(lambda value, config: value)
@@ -268,6 +314,7 @@ def test_ping_monitor_minimal_config_does_not_hit_hosted_ntfy_on_fail_dry_run():
 
 def test_ping_monitor_custom_message_hits_hosted_ntfy_on_fail():
     hook_config = {'topic': TOPIC, 'fail': CUSTOM_MESSAGE_CONFIG}
+    flexmock(module).should_receive('convert_string_to_array').with_args('+1').and_return(['+1'])
     flexmock(module.borgmatic.hooks.credential.parse).should_receive(
         'resolve_credential',
     ).replace_with(lambda value, config: value)
@@ -291,6 +338,9 @@ def test_ping_monitor_custom_message_hits_hosted_ntfy_on_fail():
 
 def test_ping_monitor_custom_state_hits_hosted_ntfy_on_start():
     hook_config = {'topic': TOPIC, 'states': ['start', 'fail']}
+    flexmock(module).should_receive('convert_string_to_array').with_args('borgmatic').and_return(
+        ['borgmatic']
+    )
     flexmock(module.borgmatic.hooks.credential.parse).should_receive(
         'resolve_credential',
     ).replace_with(lambda value, config: value)
@@ -314,6 +364,9 @@ def test_ping_monitor_custom_state_hits_hosted_ntfy_on_start():
 
 def test_ping_monitor_with_connection_error_logs_warning():
     hook_config = {'topic': TOPIC}
+    flexmock(module).should_receive('convert_string_to_array').with_args('borgmatic').and_return(
+        ['borgmatic']
+    )
     flexmock(module.borgmatic.hooks.credential.parse).should_receive(
         'resolve_credential',
     ).replace_with(lambda value, config: value)
@@ -338,6 +391,9 @@ def test_ping_monitor_with_connection_error_logs_warning():
 
 def test_ping_monitor_with_credential_error_logs_warning():
     hook_config = {'topic': TOPIC}
+    flexmock(module).should_receive('convert_string_to_array').with_args('borgmatic').and_return(
+        ['borgmatic']
+    )
     flexmock(module.borgmatic.hooks.credential.parse).should_receive(
         'resolve_credential',
     ).and_raise(ValueError)
@@ -356,6 +412,9 @@ def test_ping_monitor_with_credential_error_logs_warning():
 
 def test_ping_monitor_with_other_error_logs_warning():
     hook_config = {'topic': TOPIC}
+    flexmock(module).should_receive('convert_string_to_array').with_args('borgmatic').and_return(
+        ['borgmatic']
+    )
     flexmock(module.borgmatic.hooks.credential.parse).should_receive(
         'resolve_credential',
     ).replace_with(lambda value, config: value)

tests/unit/test_execute.py

@@ -7,72 +7,80 @@ from borgmatic import execute as module
 
 
 @pytest.mark.parametrize(
-    'command,exit_code,borg_local_path,borg_exit_codes,expected_result',
+    'command,borg_local_path,expected_result',
     (
-        (['grep'], 2, None, None, module.Exit_status.ERROR),
+        (['foo', 'bar'], 'borg', False),
-        (['grep'], 2, 'borg', None, module.Exit_status.ERROR),
+        (['borg', 'list'], 'borg', True),
-        (['borg'], 2, 'borg', None, module.Exit_status.ERROR),
+        (['borg1', 'list'], 'borg', False),
-        (['borg1'], 2, 'borg1', None, module.Exit_status.ERROR),
+        (['borg', 'list'], 'borg1', False),
-        (['grep'], 1, None, None, module.Exit_status.ERROR),
+        ([], 'borg', False),
-        (['grep'], 1, 'borg', None, module.Exit_status.ERROR),
+        ('foo bar', 'borg', False),
-        (['borg'], 1, 'borg', None, module.Exit_status.WARNING),
+        ('borg list', 'borg', True),
-        (['borg1'], 1, 'borg1', None, module.Exit_status.WARNING),
+        ('', 'borg', False),
-        (['grep'], 100, None, None, module.Exit_status.ERROR),
+    ),
-        (['grep'], 100, 'borg', None, module.Exit_status.ERROR),
+)
-        ('grep', 2, None, None, module.Exit_status.ERROR),
+def test_command_is_borg_matches_local_path_to_command(command, borg_local_path, expected_result):
-        ('borg', 2, 'borg', None, module.Exit_status.ERROR),
+    assert module.command_is_borg(command, borg_local_path) == expected_result
-        (['borg'], 100, 'borg', None, module.Exit_status.WARNING),
+
-        (['borg1'], 100, 'borg1', None, module.Exit_status.WARNING),
+
-        ('borg', 100, 'borg', None, module.Exit_status.WARNING),
+@pytest.mark.parametrize(
-        ('borg1', 100, 'borg1', None, module.Exit_status.WARNING),
+    'command_is_borg,exit_code,borg_exit_codes,expected_result',
-        (['grep'], 0, None, None, module.Exit_status.SUCCESS),
+    (
-        (['grep'], 0, 'borg', None, module.Exit_status.SUCCESS),
+        (False, 2, None, module.Exit_status.ERROR),
-        (['borg'], 0, 'borg', None, module.Exit_status.SUCCESS),
+        (True, 2, None, module.Exit_status.ERROR),
-        (['borg1'], 0, 'borg1', None, module.Exit_status.SUCCESS),
+        (False, 1, None, module.Exit_status.ERROR),
-        ('grep', 0, None, None, module.Exit_status.SUCCESS),
+        (True, 1, None, module.Exit_status.WARNING),
-        ('grep', 0, 'borg', None, module.Exit_status.SUCCESS),
+        (False, 100, None, module.Exit_status.ERROR),
+        (False, 2, None, module.Exit_status.ERROR),
+        (True, 2, None, module.Exit_status.ERROR),
+        (True, 100, None, module.Exit_status.WARNING),
+        (False, 0, None, module.Exit_status.SUCCESS),
+        (True, 0, None, module.Exit_status.SUCCESS),
         # -9 exit code occurs when child process get SIGKILLed.
-        (['grep'], -9, None, None, module.Exit_status.ERROR),
+        (False, -9, None, module.Exit_status.ERROR),
-        (['grep'], -9, 'borg', None, module.Exit_status.ERROR),
+        (True, -9, None, module.Exit_status.ERROR),
-        (['borg'], -9, 'borg', None, module.Exit_status.ERROR),
+        (True, None, None, module.Exit_status.STILL_RUNNING),
-        (['borg1'], -9, 'borg1', None, module.Exit_status.ERROR),
+        (True, 1, [], module.Exit_status.WARNING),
-        (['borg'], None, None, None, module.Exit_status.STILL_RUNNING),
+        (True, 1, [{'code': 1}], module.Exit_status.WARNING),
-        (['borg'], 1, 'borg', [], module.Exit_status.WARNING),
+        (False, 1, [{'code': 100, 'treat_as': 'error'}], module.Exit_status.ERROR),
-        (['borg'], 1, 'borg', [{}], module.Exit_status.WARNING),
+        (True, 1, [{'code': 100, 'treat_as': 'error'}], module.Exit_status.WARNING),
-        (['borg'], 1, 'borg', [{'code': 1}], module.Exit_status.WARNING),
+        (True, 1, [{'code': 1, 'treat_as': 'error'}], module.Exit_status.ERROR),
-        (['grep'], 1, 'borg', [{'code': 100, 'treat_as': 'error'}], module.Exit_status.ERROR),
+        (True, 2, [{'code': 99, 'treat_as': 'warning'}], module.Exit_status.ERROR),
-        (['borg'], 1, 'borg', [{'code': 100, 'treat_as': 'error'}], module.Exit_status.WARNING),
+        (True, 2, [{'code': 2, 'treat_as': 'warning'}], module.Exit_status.WARNING),
-        (['borg'], 1, 'borg', [{'code': 1, 'treat_as': 'error'}], module.Exit_status.ERROR),
+        (True, 100, [{'code': 1, 'treat_as': 'error'}], module.Exit_status.WARNING),
-        (['borg'], 2, 'borg', [{'code': 99, 'treat_as': 'warning'}], module.Exit_status.ERROR),
+        (True, 100, [], module.Exit_status.WARNING),
-        (['borg'], 2, 'borg', [{'code': 2, 'treat_as': 'warning'}], module.Exit_status.WARNING),
+        (True, 100, [{'code': 100, 'treat_as': 'error'}], module.Exit_status.ERROR),
-        (['borg'], 100, 'borg', [{'code': 1, 'treat_as': 'error'}], module.Exit_status.WARNING),
+        (True, 101, [], module.Exit_status.ERROR),
-        (['borg'], 100, 'borg', [], module.Exit_status.WARNING),
+        (True, 101, [{'code': 101, 'treat_as': 'warning'}], module.Exit_status.WARNING),
-        (['borg'], 100, 'borg', [{'code': 100, 'treat_as': 'error'}], module.Exit_status.ERROR),
+        (True, 102, [], module.Exit_status.ERROR),
-        (['borg'], 101, 'borg', [], module.Exit_status.ERROR),
+        (True, 102, [{'code': 102, 'treat_as': 'warning'}], module.Exit_status.WARNING),
-        (['borg'], 101, 'borg', [{'code': 101, 'treat_as': 'warning'}], module.Exit_status.WARNING),
+        (True, 103, [], module.Exit_status.WARNING),
-        (['borg'], 102, 'borg', [], module.Exit_status.ERROR),
+        (True, 103, [{'code': 103, 'treat_as': 'error'}], module.Exit_status.ERROR),
-        (['borg'], 102, 'borg', [{'code': 102, 'treat_as': 'warning'}], module.Exit_status.WARNING),
+        (True, 104, [], module.Exit_status.ERROR),
-        (['borg'], 103, 'borg', [], module.Exit_status.WARNING),
+        (True, 104, [{'code': 104, 'treat_as': 'warning'}], module.Exit_status.WARNING),
-        (['borg'], 103, 'borg', [{'code': 103, 'treat_as': 'error'}], module.Exit_status.ERROR),
+        (True, 105, [], module.Exit_status.ERROR),
-        (['borg'], 104, 'borg', [], module.Exit_status.ERROR),
+        (True, 105, [{'code': 105, 'treat_as': 'warning'}], module.Exit_status.WARNING),
-        (['borg'], 104, 'borg', [{'code': 104, 'treat_as': 'warning'}], module.Exit_status.WARNING),
+        (True, 106, [], module.Exit_status.ERROR),
-        (['borg'], 105, 'borg', [], module.Exit_status.ERROR),
+        (True, 106, [{'code': 106, 'treat_as': 'warning'}], module.Exit_status.WARNING),
-        (['borg'], 105, 'borg', [{'code': 105, 'treat_as': 'warning'}], module.Exit_status.WARNING),
+        (True, 107, [], module.Exit_status.ERROR),
-        (['borg'], 106, 'borg', [], module.Exit_status.ERROR),
+        (True, 107, [{'code': 107, 'treat_as': 'warning'}], module.Exit_status.WARNING),
-        (['borg'], 106, 'borg', [{'code': 106, 'treat_as': 'warning'}], module.Exit_status.WARNING),
-        (['borg'], 107, 'borg', [], module.Exit_status.ERROR),
-        (['borg'], 107, 'borg', [{'code': 107, 'treat_as': 'warning'}], module.Exit_status.WARNING),
     ),
 )
 def test_interpret_exit_code_respects_exit_code_and_borg_local_path(
-    command,
+    command_is_borg,
     exit_code,
-    borg_local_path,
     borg_exit_codes,
     expected_result,
 ):
+    flexmock(module).should_receive('command_is_borg').and_return(command_is_borg)
+
     assert (
-        module.interpret_exit_code(command, exit_code, borg_local_path, borg_exit_codes)
+        module.interpret_exit_code(
+            command=flexmock(),
+            exit_code=exit_code,
+            borg_local_path=flexmock(),
+            borg_exit_codes=borg_exit_codes,
+        )
         is expected_result
     )
 
@@ -122,6 +130,42 @@ def test_borg_json_log_line_to_record_parses_log_message_line():
     assert record.name == 'borg.something'
 
 
+def test_borg_json_log_line_to_record_elevates_log_message_info_level_to_small_jump_in_log_level():
+    line = '{"type": "log_message", "levelname": "INFO", "time": 12345, "message": "All done", "name": "borg.something"}'
+
+    record = module.borg_json_log_line_to_record(line, 25)
+
+    assert record.levelno == 25
+    assert record.created == 12345
+    assert record.msg == 'All done'
+    assert record.levelname in {'ANSWER', 'Level 25'}
+    assert record.name == 'borg.something'
+
+
+def test_borg_json_log_line_to_record_does_not_elevate_log_message_info_level_to_big_jump_in_log_level():
+    line = '{"type": "log_message", "levelname": "INFO", "time": 12345, "message": "All done", "name": "borg.something"}'
+
+    record = module.borg_json_log_line_to_record(line, 40)
+
+    assert record.levelno == module.logging.INFO
+    assert record.created == 12345
+    assert record.msg == 'All done'
+    assert record.levelname == 'INFO'
+    assert record.name == 'borg.something'
+
+
+def test_borg_json_log_line_with_none_log_level_parses_log_message_line():
+    line = '{"type": "log_message", "levelname": "INFO", "time": 12345, "message": "All done", "name": "borg.something"}'
+
+    record = module.borg_json_log_line_to_record(line, None)
+
+    assert record.levelno == module.logging.INFO
+    assert record.created == 12345
+    assert record.msg == 'All done'
+    assert record.levelname == 'INFO'
+    assert record.name == 'borg.something'
+
+
 def test_borg_json_log_line_to_record_parses_file_status_line():
     flexmock(module.time).should_receive('time').and_return(12345)
     line = '{"type": "file_status", "status": "-", "path": "/foo/bar"}'
@@ -1380,6 +1424,7 @@ def test_execute_command_without_run_to_completion_returns_process():
 def test_execute_command_and_capture_output_returns_stdout():
     full_command = ['foo', 'bar']
     flexmock(module).should_receive('log_command')
+    flexmock(module).should_receive('command_is_borg').and_return(False)
     process = flexmock()
     flexmock(module.subprocess).should_receive('Popen').with_args(
         full_command,
@@ -1399,8 +1444,10 @@ def test_execute_command_and_capture_output_returns_stdout():
     assert output_lines == ('out',)
 
 
-def test_execute_command_and_capture_output_with_capture_stderr_returns_stderr():
+def test_execute_command_and_capture_output_with_capture_stderr_popens_stderr():
     full_command = ['foo', 'bar']
+    flexmock(module).should_receive('log_command')
+    flexmock(module).should_receive('command_is_borg').and_return(False)
     process = flexmock()
     flexmock(module.subprocess).should_receive('Popen').with_args(
         full_command,
@@ -1422,10 +1469,34 @@ def test_execute_command_and_capture_output_with_capture_stderr_returns_stderr()
     assert output_lines == ('out',)
 
 
+def test_execute_command_and_capture_output_with_borg_command_popens_stderr():
+    full_command = ['borg', 'list']
+    flexmock(module).should_receive('log_command')
+    flexmock(module).should_receive('command_is_borg').and_return(True)
+    process = flexmock()
+    flexmock(module.subprocess).should_receive('Popen').with_args(
+        full_command,
+        stdin=None,
+        stdout=subprocess.PIPE,
+        stderr=subprocess.PIPE,
+        shell=False,
+        env=None,
+        cwd=None,
+        close_fds=False,
+    ).and_return(process).once()
+    flexmock(module.borgmatic.logger).should_receive('Log_prefix').and_return(flexmock())
+    flexmock(module).should_receive('log_outputs').and_yield('out')
+
+    output_lines = tuple(module.execute_command_and_capture_output(full_command))
+
+    assert output_lines == ('out',)
+
+
 def test_execute_command_and_capture_output_returns_output_when_process_error_is_not_considered_an_error():
     full_command = ['foo', 'bar']
     err_output = b'[]'
     flexmock(module).should_receive('log_command')
+    flexmock(module).should_receive('command_is_borg').and_return(False)
     flexmock(module.subprocess).should_receive('Popen').with_args(
         full_command,
         stdin=None,
@@ -1448,6 +1519,7 @@ def test_execute_command_and_capture_output_returns_output_when_process_error_is
 def test_execute_command_and_capture_output_raises_when_command_errors():
     full_command = ['foo', 'bar']
     flexmock(module).should_receive('log_command')
+    flexmock(module).should_receive('command_is_borg').and_return(False)
     flexmock(module.subprocess).should_receive('Popen').with_args(
         full_command,
         stdin=None,
@@ -1469,6 +1541,7 @@ def test_execute_command_and_capture_output_raises_when_command_errors():
 def test_execute_command_and_capture_output_with_shell_returns_output():
     full_command = ['foo', 'bar']
     flexmock(module).should_receive('log_command')
+    flexmock(module).should_receive('command_is_borg').and_return(False)
     process = flexmock()
     flexmock(module.subprocess).should_receive('Popen').with_args(
         'foo bar',
@@ -1491,6 +1564,7 @@ def test_execute_command_and_capture_output_with_shell_returns_output():
 def test_execute_command_and_capture_output_with_enviroment_returns_output():
     full_command = ['foo', 'bar']
     flexmock(module).should_receive('log_command')
+    flexmock(module).should_receive('command_is_borg').and_return(False)
     process = flexmock()
     flexmock(module.subprocess).should_receive('Popen').with_args(
         full_command,
@@ -1519,6 +1593,7 @@ def test_execute_command_and_capture_output_with_enviroment_returns_output():
 def test_execute_command_and_capture_output_returns_output_with_working_directory():
     full_command = ['foo', 'bar']
     flexmock(module).should_receive('log_command')
+    flexmock(module).should_receive('command_is_borg').and_return(False)
     process = flexmock()
     flexmock(module.subprocess).should_receive('Popen').with_args(
         full_command,