From 7bb27e5366ebcfea85f648c04e449ca2579b581d Mon Sep 17 00:00:00 2001 From: Dan Helfman Date: Sun, 11 Jan 2026 09:51:50 -0800 Subject: [PATCH 1/9] Revert "Fix for incorrect use of "--log-json" when looking up latest archive (#1204)." This reverts commit 2c530cc1b9c503487df4c20eb92a768ff3d317ad. --- borgmatic/actions/check.py | 4 ++-- borgmatic/borg/repo_list.py | 1 + tests/unit/borg/test_repo_list.py | 26 ++++++++++++++------------ 3 files changed, 17 insertions(+), 14 deletions(-) diff --git a/borgmatic/actions/check.py b/borgmatic/actions/check.py index c25f7418..187a7cfa 100644 --- a/borgmatic/actions/check.py +++ b/borgmatic/actions/check.py @@ -602,6 +602,8 @@ def spot_check( disk to those stored in the latest archive. If any differences are beyond configured tolerances, then the check fails. ''' + logger.debug('Running spot check') + try: spot_check_config = next( check for check in config.get('checks', ()) if check.get('name') == 'spot' @@ -786,7 +788,6 @@ def run_check( write_check_time(make_check_time_path(config, repository_id, check, archives_check_id)) if 'extract' in checks: - logger.info('Running extract check') borgmatic.borg.extract.extract_last_archive_dry_run( config, local_borg_version, @@ -800,7 +801,6 @@ def run_check( if 'spot' in checks: with borgmatic.config.paths.Runtime_directory(config) as borgmatic_runtime_directory: - logger.info('Running spot check') spot_check( repository, config, diff --git a/borgmatic/borg/repo_list.py b/borgmatic/borg/repo_list.py index cbc28f58..446aacad 100644 --- a/borgmatic/borg/repo_list.py +++ b/borgmatic/borg/repo_list.py @@ -77,6 +77,7 @@ def get_latest_archive( ), *flags.make_flags('remote-path', remote_path), *flags.make_flags('umask', config.get('umask')), + *('--log-json',), *flags.make_flags('lock-wait', config.get('lock_wait')), *( flags.make_flags('consider-checkpoints', consider_checkpoints) diff --git a/tests/unit/borg/test_repo_list.py b/tests/unit/borg/test_repo_list.py index 0a5ea6d1..6944a0b7 100644 --- a/tests/unit/borg/test_repo_list.py +++ b/tests/unit/borg/test_repo_list.py @@ -119,7 +119,7 @@ def test_get_latest_archive_calls_borg_with_flags(): flexmock(module.environment).should_receive('make_environment') flexmock(module.borgmatic.config.paths).should_receive('get_working_directory').and_return(None) flexmock(module).should_receive('execute_command_and_capture_output').with_args( - ('borg', 'list', *BORG_LIST_LATEST_ARGUMENTS), + ('borg', 'list', '--log-json', *BORG_LIST_LATEST_ARGUMENTS), borg_local_path='borg', borg_exit_codes=None, environment=None, @@ -148,7 +148,7 @@ def test_get_latest_archive_with_log_info_calls_borg_without_info_flag(): flexmock(module.environment).should_receive('make_environment') flexmock(module.borgmatic.config.paths).should_receive('get_working_directory').and_return(None) flexmock(module).should_receive('execute_command_and_capture_output').with_args( - ('borg', 'list', *BORG_LIST_LATEST_ARGUMENTS), + ('borg', 'list', '--log-json', *BORG_LIST_LATEST_ARGUMENTS), environment=None, working_directory=None, borg_local_path='borg', @@ -178,7 +178,7 @@ def test_get_latest_archive_with_log_debug_calls_borg_without_debug_flag(): flexmock(module.environment).should_receive('make_environment') flexmock(module.borgmatic.config.paths).should_receive('get_working_directory').and_return(None) flexmock(module).should_receive('execute_command_and_capture_output').with_args( - ('borg', 'list', *BORG_LIST_LATEST_ARGUMENTS), + ('borg', 'list', '--log-json', *BORG_LIST_LATEST_ARGUMENTS), environment=None, working_directory=None, borg_local_path='borg', @@ -208,7 +208,7 @@ def test_get_latest_archive_with_local_path_calls_borg_via_local_path(): flexmock(module.environment).should_receive('make_environment') flexmock(module.borgmatic.config.paths).should_receive('get_working_directory').and_return(None) flexmock(module).should_receive('execute_command_and_capture_output').with_args( - ('borg1', 'list', *BORG_LIST_LATEST_ARGUMENTS), + ('borg1', 'list', '--log-json', *BORG_LIST_LATEST_ARGUMENTS), environment=None, working_directory=None, borg_local_path='borg1', @@ -239,7 +239,7 @@ def test_get_latest_archive_with_exit_codes_calls_borg_using_them(): flexmock(module.borgmatic.config.paths).should_receive('get_working_directory').and_return(None) borg_exit_codes = flexmock() flexmock(module).should_receive('execute_command_and_capture_output').with_args( - ('borg', 'list', *BORG_LIST_LATEST_ARGUMENTS), + ('borg', 'list', '--log-json', *BORG_LIST_LATEST_ARGUMENTS), environment=None, working_directory=None, borg_local_path='borg', @@ -271,7 +271,7 @@ def test_get_latest_archive_with_remote_path_calls_borg_with_remote_path_flags() flexmock(module.environment).should_receive('make_environment') flexmock(module.borgmatic.config.paths).should_receive('get_working_directory').and_return(None) flexmock(module).should_receive('execute_command_and_capture_output').with_args( - ('borg', 'list', '--remote-path', 'borg1', *BORG_LIST_LATEST_ARGUMENTS), + ('borg', 'list', '--remote-path', 'borg1', '--log-json', *BORG_LIST_LATEST_ARGUMENTS), environment=None, working_directory=None, borg_local_path='borg', @@ -304,7 +304,7 @@ def test_get_latest_archive_with_umask_calls_borg_with_umask_flags(): flexmock(module.environment).should_receive('make_environment') flexmock(module.borgmatic.config.paths).should_receive('get_working_directory').and_return(None) flexmock(module).should_receive('execute_command_and_capture_output').with_args( - ('borg', 'list', '--umask', '077', *BORG_LIST_LATEST_ARGUMENTS), + ('borg', 'list', '--umask', '077', '--log-json', *BORG_LIST_LATEST_ARGUMENTS), environment=None, working_directory=None, borg_local_path='borg', @@ -332,7 +332,7 @@ def test_get_latest_archive_without_archives_raises(): flexmock(module.flags).should_receive('make_repository_flags').and_return(('repo',)) flexmock(module.borgmatic.config.paths).should_receive('get_working_directory').and_return(None) flexmock(module).should_receive('execute_command_and_capture_output').with_args( - ('borg', 'list', *BORG_LIST_LATEST_ARGUMENTS), + ('borg', 'list', '--log-json', *BORG_LIST_LATEST_ARGUMENTS), environment=None, working_directory=None, borg_local_path='borg', @@ -362,7 +362,7 @@ def test_get_latest_archive_with_lock_wait_calls_borg_with_lock_wait_flags(): flexmock(module.environment).should_receive('make_environment') flexmock(module.borgmatic.config.paths).should_receive('get_working_directory').and_return(None) flexmock(module).should_receive('execute_command_and_capture_output').with_args( - ('borg', 'list', '--lock-wait', 'okay', *BORG_LIST_LATEST_ARGUMENTS), + ('borg', 'list', '--log-json', '--lock-wait', 'okay', *BORG_LIST_LATEST_ARGUMENTS), environment=None, working_directory=None, borg_local_path='borg', @@ -394,6 +394,7 @@ def test_get_latest_archive_calls_borg_with_list_extra_borg_options(): ( 'borg', 'list', + '--log-json', *BORG_LIST_LATEST_ARGUMENTS[:-1], '--extra', 'value with space', @@ -430,6 +431,7 @@ def test_get_latest_archive_with_feature_available_calls_borg_with_repo_list_ext ( 'borg', 'repo-list', + '--log-json', *BORG_LIST_LATEST_ARGUMENTS[:-1], '--extra', 'value with space', @@ -466,7 +468,7 @@ def test_get_latest_archive_with_consider_checkpoints_calls_borg_with_consider_c flexmock(module.environment).should_receive('make_environment') flexmock(module.borgmatic.config.paths).should_receive('get_working_directory').and_return(None) flexmock(module).should_receive('execute_command_and_capture_output').with_args( - ('borg', 'list', '--consider-checkpoints', *BORG_LIST_LATEST_ARGUMENTS), + ('borg', 'list', '--log-json', '--consider-checkpoints', *BORG_LIST_LATEST_ARGUMENTS), environment=None, working_directory=None, borg_local_path='borg', @@ -499,7 +501,7 @@ def test_get_latest_archive_with_consider_checkpoints_and_feature_available_call flexmock(module.environment).should_receive('make_environment') flexmock(module.borgmatic.config.paths).should_receive('get_working_directory').and_return(None) flexmock(module).should_receive('execute_command_and_capture_output').with_args( - ('borg', 'repo-list', *BORG_REPO_LIST_LATEST_ARGUMENTS), + ('borg', 'repo-list', '--log-json', *BORG_REPO_LIST_LATEST_ARGUMENTS), environment=None, working_directory=None, borg_local_path='borg', @@ -531,7 +533,7 @@ def test_get_latest_archive_calls_borg_with_working_directory(): '/working/dir', ) flexmock(module).should_receive('execute_command_and_capture_output').with_args( - ('borg', 'list', *BORG_LIST_LATEST_ARGUMENTS), + ('borg', 'list', '--log-json', *BORG_LIST_LATEST_ARGUMENTS), borg_local_path='borg', borg_exit_codes=None, environment=None, From 10f2d6bdfd7a2999ed6f155802885f5a248b567b Mon Sep 17 00:00:00 2001 From: Dan Helfman Date: Sun, 11 Jan 2026 10:00:08 -0800 Subject: [PATCH 2/9] Revert "Fix for stderr warnings from ssh dirtying Borg JSON output and breaking "check" (#485)." This reverts commit 7987a5ff1fcc51469ca65c963a6b1209f5236058. --- borgmatic/execute.py | 2 +- tests/unit/test_execute.py | 35 ++++++----------------------------- 2 files changed, 7 insertions(+), 30 deletions(-) diff --git a/borgmatic/execute.py b/borgmatic/execute.py index f533ed43..ea3ea467 100644 --- a/borgmatic/execute.py +++ b/borgmatic/execute.py @@ -471,7 +471,7 @@ def execute_command_and_capture_output( command, stdin=input_file, stdout=subprocess.PIPE, - stderr=subprocess.PIPE if capture_stderr else None, + stderr=subprocess.PIPE, shell=shell, env=environment, cwd=working_directory, diff --git a/tests/unit/test_execute.py b/tests/unit/test_execute.py index 94e89960..f0115894 100644 --- a/tests/unit/test_execute.py +++ b/tests/unit/test_execute.py @@ -497,7 +497,7 @@ def test_execute_command_and_capture_output_returns_stdout(): full_command, stdin=None, stdout=subprocess.PIPE, - stderr=None, + stderr=subprocess.PIPE, shell=False, env=None, cwd=None, @@ -534,29 +534,6 @@ def test_execute_command_and_capture_output_with_capture_stderr_returns_stderr() assert output_lines == ('out',) -def test_execute_command_and_capture_output_without_capture_stderr_omits_stderr(): - full_command = ['foo', 'bar'] - process = flexmock() - flexmock(module.subprocess).should_receive('Popen').with_args( - full_command, - stdin=None, - stdout=subprocess.PIPE, - stderr=None, - 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, capture_stderr=False) - ) - - 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'[]' @@ -565,7 +542,7 @@ def test_execute_command_and_capture_output_returns_output_when_process_error_is full_command, stdin=None, stdout=subprocess.PIPE, - stderr=None, + stderr=subprocess.PIPE, shell=False, env=None, cwd=None, @@ -587,7 +564,7 @@ def test_execute_command_and_capture_output_raises_when_command_errors(): full_command, stdin=None, stdout=subprocess.PIPE, - stderr=None, + stderr=subprocess.PIPE, shell=False, env=None, cwd=None, @@ -609,7 +586,7 @@ def test_execute_command_and_capture_output_with_shell_returns_output(): 'foo bar', stdin=None, stdout=subprocess.PIPE, - stderr=None, + stderr=subprocess.PIPE, shell=True, env=None, cwd=None, @@ -631,7 +608,7 @@ def test_execute_command_and_capture_output_with_enviroment_returns_output(): full_command, stdin=None, stdout=subprocess.PIPE, - stderr=None, + stderr=subprocess.PIPE, shell=False, env={'a': 'b'}, cwd=None, @@ -659,7 +636,7 @@ def test_execute_command_and_capture_output_returns_output_with_working_director full_command, stdin=None, stdout=subprocess.PIPE, - stderr=None, + stderr=subprocess.PIPE, shell=False, env=None, cwd='/working', From c4de1418991e11ab1730fc659206fe90fbdceeda Mon Sep 17 00:00:00 2001 From: Dan Helfman Date: Mon, 12 Jan 2026 15:26:50 -0800 Subject: [PATCH 3/9] Several related fixes and improvements in logging, output capturing, and command execution. --- borgmatic/actions/check.py | 53 ++++++++----- borgmatic/borg/list.py | 58 +++++++------- borgmatic/execute.py | 157 +++++++++++++++++++++++++++---------- 3 files changed, 176 insertions(+), 92 deletions(-) diff --git a/borgmatic/actions/check.py b/borgmatic/actions/check.py index 187a7cfa..026b98fd 100644 --- a/borgmatic/actions/check.py +++ b/borgmatic/actions/check.py @@ -448,24 +448,22 @@ def collect_spot_check_archive_paths( borgmatic_source_directory = borgmatic.config.paths.get_borgmatic_source_directory(config) return tuple( - path - for line in borgmatic.borg.list.capture_archive_listing( + entry['path'] + for entry in borgmatic.borg.list.capture_archive_listing( repository['path'], archive, config, local_borg_version, global_arguments, - path_format='{type} {path}{NUL}', local_path=local_path, remote_path=remote_path, ) - for (file_type, path) in (line.split(' ', 1),) - if file_type not in {BORG_DIRECTORY_FILE_TYPE, BORG_PIPE_FILE_TYPE} - if pathlib.Path('borgmatic') not in pathlib.Path(path).parents + if entry['type'] not in {BORG_DIRECTORY_FILE_TYPE, BORG_PIPE_FILE_TYPE} + if pathlib.Path('borgmatic') not in pathlib.Path(entry['path']).parents if pathlib.Path(borgmatic_source_directory.lstrip(os.path.sep)) - not in pathlib.Path(path).parents + not in pathlib.Path(entry['path']).parents if pathlib.Path(borgmatic_runtime_directory.lstrip(os.path.sep)) - not in pathlib.Path(path).parents + not in pathlib.Path(entry['path']).parents ) @@ -523,20 +521,33 @@ def compare_spot_check_hashes( if not source_sample_paths_subset: break + 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')) - ) - + tuple( - path for path in source_sample_paths_subset if path in hashable_source_sample_path - ), + ) + hash_paths, working_directory=working_directory, ) source_hashes.update( **dict( - (reversed(line.split(' ', 1)) for line in hash_lines), + zip( + # xxh64sum rewrites/escapes the paths that it returns alongside its hashes, for + # 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. @@ -550,21 +561,21 @@ def compare_spot_check_hashes( # Get the hash for each file in the archive. archive_hashes.update( - **dict( - reversed(line.split(' ', 1)) - for line in borgmatic.borg.list.capture_archive_listing( + **{ + entry['path']: entry['xxh64'] + for entry in borgmatic.borg.list.capture_archive_listing( repository['path'], archive, config, local_borg_version, global_arguments, list_paths=source_sample_paths_subset, - path_format='{xxh64} {path}{NUL}', + path_format='{xxh64}{path}', local_path=local_path, remote_path=remote_path, ) - if line - ), + if entry + }, ) # Compare the source hashes with the archive hashes to see how many match. @@ -602,8 +613,6 @@ def spot_check( disk to those stored in the latest archive. If any differences are beyond configured tolerances, then the check fails. ''' - logger.debug('Running spot check') - try: spot_check_config = next( check for check in config.get('checks', ()) if check.get('name') == 'spot' @@ -788,6 +797,7 @@ def run_check( write_check_time(make_check_time_path(config, repository_id, check, archives_check_id)) if 'extract' in checks: + logger.info('Running extract check') borgmatic.borg.extract.extract_last_archive_dry_run( config, local_borg_version, @@ -800,6 +810,7 @@ def run_check( write_check_time(make_check_time_path(config, repository_id, 'extract')) if 'spot' in checks: + logger.info('Running spot check') with borgmatic.config.paths.Runtime_directory(config) as borgmatic_runtime_directory: spot_check( repository, diff --git a/borgmatic/borg/list.py b/borgmatic/borg/list.py index 364074d3..22eccc76 100644 --- a/borgmatic/borg/list.py +++ b/borgmatic/borg/list.py @@ -1,5 +1,6 @@ import argparse import copy +import json import logging import re import shlex @@ -19,6 +20,7 @@ MAKE_FLAGS_EXCLUDES = ( 'paths', 'find_paths', 'format', + 'json', *ARCHIVE_FILTER_FLAGS_MOVED_TO_REPO_LIST, ) @@ -54,6 +56,7 @@ def make_list_command( + flags.make_flags('remote-path', remote_path) + flags.make_flags('umask', config.get('umask')) + ('--log-json',) + + (('--json-lines',) if list_arguments.json else ()) + flags.make_flags('lock-wait', config.get('lock_wait')) + flags.make_flags('format', list_arguments.format or config.get('file_list_format')) + flags.make_flags_from_arguments(list_arguments, excludes=MAKE_FLAGS_EXCLUDES) @@ -109,39 +112,36 @@ def capture_archive_listing( remote_path=None, ): ''' - Given a local or remote repository path, an archive name, a configuration - dict, the local Borg version, global arguments as an argparse.Namespace, - the archive paths (or Borg patterns) in which to list files, the Borg path - format to use for the output, and local and remote Borg paths, capture the - output of listing that archive and return it as a list of file paths. + Given a local or remote repository path, an archive name, a configuration dict, the local Borg + version, global arguments as an argparse.Namespace, the archive paths (or Borg patterns) in + which to list files, the Borg path format indicating keys to include in the output, and local + and remote Borg paths, capture the output of listing that archive and return it as a sequence of + dicts, one per path. ''' return tuple( - ''.join( - execute_command_and_capture_output( - make_list_command( - repository_path, - config, - local_borg_version, - argparse.Namespace( - repository=repository_path, - archive=archive, - paths=list(list_paths) if list_paths else None, - find_paths=None, - json=None, - format=path_format or '{path}{NUL}', - ), - global_arguments, - local_path, - remote_path, + json.loads(entry) + for entry in execute_command_and_capture_output( + make_list_command( + repository_path, + config, + local_borg_version, + argparse.Namespace( + repository=repository_path, + archive=archive, + paths=list(list_paths) if list_paths else None, + find_paths=None, + json=True, + format=path_format or None, ), - environment=environment.make_environment(config), - working_directory=borgmatic.config.paths.get_working_directory(config), - borg_local_path=local_path, - borg_exit_codes=config.get('borg_exit_codes'), - ) + global_arguments, + local_path, + remote_path, + ), + environment=environment.make_environment(config), + working_directory=borgmatic.config.paths.get_working_directory(config), + borg_local_path=local_path, + borg_exit_codes=config.get('borg_exit_codes'), ) - .strip('\0') - .split('\0'), ) diff --git a/borgmatic/execute.py b/borgmatic/execute.py index ea3ea467..aadd42d5 100644 --- a/borgmatic/execute.py +++ b/borgmatic/execute.py @@ -6,6 +6,7 @@ import logging import select import subprocess import textwrap +import time import borgmatic.logger @@ -101,28 +102,38 @@ def output_buffers_for_process(process, exclude_stdouts): ) -def borg_log_line_to_record(line, log_level): +def borg_json_log_line_to_record(line, log_level): ''' - Given a single Borg log entry and a log level, return the line converted to a logging.LogRecord - instance. - - If it can't be parsed, then fall back to making a record out of the raw line and the given 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. ''' with contextlib.suppress(json.JSONDecodeError, TypeError, KeyError, AttributeError): log_data = json.loads(line) + log_type = log_data.get('type') - return logging.makeLogRecord( - dict( - levelno=logging._nameToLevel.get(log_data.get('levelname')), - created=log_data.get('time'), - msg=log_data.get('message'), - levelname=log_data.get('levelname'), - name=log_data.get('name'), + if log_type == 'log_message': + return logging.makeLogRecord( + dict( + levelno=logging._nameToLevel.get(log_data.get('levelname')), + created=log_data.get('time'), + msg=log_data.get('message'), + levelname=log_data.get('levelname'), + name=log_data.get('name'), + ) ) - ) - return log_line_to_record(line, log_level) + if log_type == 'file_status': + return logging.makeLogRecord( + dict( + levelno=log_level, + created=time.time(), + msg=f'{log_data.get("status")} {log_data.get("path")}', + levelname=logging.getLevelName(log_level), + name='borg.file_status', + ) + ) + + return None def log_line_to_record(line, log_level): @@ -139,11 +150,11 @@ def log_line_to_record(line, log_level): ) -def parse_log_line(line, log_level, came_from_stderr, borg_local_path, command): +def parse_log_line(line, log_level, elevate_stderr, borg_local_path, command): ''' - Given a raw output line from an external program, whether this line came from stderr, the Borg - local path, and the command as a sequence, return a logging.LogRecord instance containing its - parsed data. + Given a raw output line from an external program, whether this line came from stderr and should + be elevated to error/warning, the Borg local path, and the command as a sequence, return a + logging.LogRecord instance containing its parsed data. If the command being run is Borg, and the log line is JSON-formatted log data, then grab the log level from it and log the parsed JSON to be consumed later by a Python logging.Formatter. @@ -153,9 +164,12 @@ def parse_log_line(line, log_level, came_from_stderr, borg_local_path, command): just elevate the log level to a WARN. ''' if borg_local_path and command[0] == borg_local_path: - return borg_log_line_to_record(line, log_level) + log_record = borg_json_log_line_to_record(line, log_level) - if came_from_stderr: + if log_record: + return log_record + + if elevate_stderr: return log_line_to_record( line, logging.WARNING if line.lower().startswith('warning:') else logging.ERROR ) @@ -182,7 +196,56 @@ def handle_log_record(log_record, last_lines): return log_record -def log_outputs(processes, exclude_stdouts, output_log_level, borg_local_path, borg_exit_codes): # noqa: PLR0912 +READ_CHUNK_SIZE = 4096 + + +def read_lines(buffer, process, line_separator='\n'): + ''' + Given a Python buffer (like stdout) ready for reading, its process, and a line separator, yield + each (decoded) line from the buffer until the process has exited. + + It is assumed that this function's generator is used in conjunction with an external select() + call to know when to read more lines. Otherwise, the generator will busywait if it's called in a + tight loop. + ''' + data = '' + + while True: + chunk = buffer.read(READ_CHUNK_SIZE).decode() + + if not chunk: # EOF + # The process is still running, so we keep running too. + if process.poll() is None: + continue + + break + + data += chunk + + while True: + separator_position = data.find(line_separator) + + if separator_position == -1: + break + + yield data[:separator_position].rstrip() + + data = data[separator_position + 1:] + + # Yield any leftover data from the end of the buffer. + if data: + yield data.rstrip() + + + +def log_outputs( + processes, + exclude_stdouts, + output_log_level, + borg_local_path, + borg_exit_codes, + capture_stderr=False, +): # noqa: PLR0912 ''' Given a sequence of subprocess.Popen() instances for multiple processes, log the outputs (stderr and stdout). Use the requested output log level for stdout, but always log stderr to the ERROR @@ -190,8 +253,8 @@ def log_outputs(processes, exclude_stdouts, output_log_level, borg_local_path, b warning for exit code 1, if that process does not match the Borg local path). If the output log level is None, then instead of logging, capture the output for the last - process given and yield it one line at a time. But if the output log level is not None, don't - yield anything. + process given and yield it one line at a time. This includes stderr if capture stderr is set. + But if the output log level is not None, don't yield anything. This yielding means that this function is a generator, and must be consumed in order to execute. @@ -208,6 +271,12 @@ def log_outputs(processes, exclude_stdouts, output_log_level, borg_local_path, b if process.stdout or process.stderr for buffer in output_buffers_for_process(process, exclude_stdouts) } + reader_for_output_buffer = { + buffer: read_lines(buffer, process) + for process in processes + if process.stdout or process.stderr + for buffer in output_buffers_for_process(process, exclude_stdouts) + } output_buffers = list(process_for_output_buffer.keys()) process_to_capture = processes[-1] still_running = True @@ -233,8 +302,7 @@ def log_outputs(processes, exclude_stdouts, output_log_level, borg_local_path, b # Add the process's output to output_buffers to ensure it'll get read. output_buffers.append(other_process.stdout) - while True: - line = ready_buffer.readline().rstrip().decode() + for line in reader_for_output_buffer[ready_buffer]: if not line or not ready_process: break @@ -250,7 +318,9 @@ def log_outputs(processes, exclude_stdouts, output_log_level, borg_local_path, b parse_log_line( line=line, log_level=output_log_level, - came_from_stderr=(ready_buffer == ready_process.stderr), + elevate_stderr=( + ready_buffer == ready_process.stderr and not capture_stderr + ), borg_local_path=borg_local_path, command=command, ), @@ -284,23 +354,25 @@ def log_outputs(processes, exclude_stdouts, output_log_level, borg_local_path, b for output_buffer in output_buffers_for_process(process, exclude_stdouts): # Collect any straggling output lines that came in since we last gathered output. while output_buffer: # pragma: no cover - line = output_buffer.readline().rstrip().decode() - if not line: - break + for line in reader_for_output_buffer[output_buffer]: + if not line: + break - log_record = handle_log_record( - parse_log_line( - line=line, - log_level=output_log_level, - came_from_stderr=(output_buffer == process.stderr), - borg_local_path=borg_local_path, - command=command, - ), - last_lines=last_lines, - ) + log_record = handle_log_record( + parse_log_line( + line=line, + log_level=output_log_level, + elevate_stderr=( + output_buffer == process.stderr and not capture_stderr + ), + borg_local_path=borg_local_path, + command=command, + ), + last_lines=last_lines, + ) - if log_record.levelno is None and process == process_to_capture: - yield log_record.getMessage() + if log_record.levelno is None and process == process_to_capture: + yield log_record.getMessage() if len(last_lines) == ERROR_OUTPUT_MAX_LINE_COUNT: last_lines.insert(0, '...') @@ -496,6 +568,7 @@ def execute_command_and_capture_output( None, borg_local_path, borg_exit_codes, + capture_stderr=capture_stderr, ) yield from captured_lines From 64e25144a88187b3e6feba74b137ecc598762c4e Mon Sep 17 00:00:00 2001 From: Dan Helfman Date: Tue, 13 Jan 2026 10:08:40 -0800 Subject: [PATCH 4/9] Going back to using readline() for reading lines from executed programs. --- borgmatic/execute.py | 83 ++++++++++---------------------------------- 1 file changed, 18 insertions(+), 65 deletions(-) diff --git a/borgmatic/execute.py b/borgmatic/execute.py index aadd42d5..af3a9709 100644 --- a/borgmatic/execute.py +++ b/borgmatic/execute.py @@ -196,48 +196,6 @@ def handle_log_record(log_record, last_lines): return log_record -READ_CHUNK_SIZE = 4096 - - -def read_lines(buffer, process, line_separator='\n'): - ''' - Given a Python buffer (like stdout) ready for reading, its process, and a line separator, yield - each (decoded) line from the buffer until the process has exited. - - It is assumed that this function's generator is used in conjunction with an external select() - call to know when to read more lines. Otherwise, the generator will busywait if it's called in a - tight loop. - ''' - data = '' - - while True: - chunk = buffer.read(READ_CHUNK_SIZE).decode() - - if not chunk: # EOF - # The process is still running, so we keep running too. - if process.poll() is None: - continue - - break - - data += chunk - - while True: - separator_position = data.find(line_separator) - - if separator_position == -1: - break - - yield data[:separator_position].rstrip() - - data = data[separator_position + 1:] - - # Yield any leftover data from the end of the buffer. - if data: - yield data.rstrip() - - - def log_outputs( processes, exclude_stdouts, @@ -271,12 +229,6 @@ def log_outputs( if process.stdout or process.stderr for buffer in output_buffers_for_process(process, exclude_stdouts) } - reader_for_output_buffer = { - buffer: read_lines(buffer, process) - for process in processes - if process.stdout or process.stderr - for buffer in output_buffers_for_process(process, exclude_stdouts) - } output_buffers = list(process_for_output_buffer.keys()) process_to_capture = processes[-1] still_running = True @@ -302,7 +254,8 @@ def log_outputs( # Add the process's output to output_buffers to ensure it'll get read. output_buffers.append(other_process.stdout) - for line in reader_for_output_buffer[ready_buffer]: + while True: + line = ready_buffer.readline().rstrip().decode() if not line or not ready_process: break @@ -354,25 +307,25 @@ def log_outputs( for output_buffer in output_buffers_for_process(process, exclude_stdouts): # Collect any straggling output lines that came in since we last gathered output. while output_buffer: # pragma: no cover - for line in reader_for_output_buffer[output_buffer]: - if not line: - break + line = ready_buffer.readline().rstrip().decode() + if not line or not ready_process: + break - log_record = handle_log_record( - parse_log_line( - line=line, - log_level=output_log_level, - elevate_stderr=( - output_buffer == process.stderr and not capture_stderr - ), - borg_local_path=borg_local_path, - command=command, + log_record = handle_log_record( + parse_log_line( + line=line, + log_level=output_log_level, + elevate_stderr=( + output_buffer == process.stderr and not capture_stderr ), - last_lines=last_lines, - ) + borg_local_path=borg_local_path, + command=command, + ), + last_lines=last_lines, + ) - if log_record.levelno is None and process == process_to_capture: - yield log_record.getMessage() + if log_record.levelno is None and process == process_to_capture: + yield log_record.getMessage() if len(last_lines) == ERROR_OUTPUT_MAX_LINE_COUNT: last_lines.insert(0, '...') From d354cf094282757b2f05dee3cf5a14b048b860ad Mon Sep 17 00:00:00 2001 From: Dan Helfman Date: Tue, 13 Jan 2026 16:02:02 -0800 Subject: [PATCH 5/9] Get unit/integration tests passing. --- NEWS | 1 + borgmatic/actions/check.py | 3 +- borgmatic/borg/list.py | 7 +-- borgmatic/execute.py | 4 +- tests/unit/actions/test_check.py | 85 +++++++++++++++++--------------- tests/unit/borg/test_list.py | 26 ++-------- tests/unit/test_execute.py | 62 +++++++++++++---------- 7 files changed, 90 insertions(+), 98 deletions(-) diff --git a/NEWS b/NEWS index 60fee340..2a3df2c2 100644 --- a/NEWS +++ b/NEWS @@ -39,6 +39,7 @@ * SECURITY: Prevent shell injection attacks via constant interpolation in command hooks. (This was already implemented for deprecated "before_*"/"after_*" command hooks.) * Fix for an error in the "key import" action when importing a key from stdin. + * Update the "list" action to support the "--json" flag when the "--archive" flag is also used. * Promote the ZFS, LVM, and Btrfs hooks from beta features to stable. 2.0.13 diff --git a/borgmatic/actions/check.py b/borgmatic/actions/check.py index 026b98fd..e6390598 100644 --- a/borgmatic/actions/check.py +++ b/borgmatic/actions/check.py @@ -528,7 +528,8 @@ def compare_spot_check_hashes( tuple( shlex.quote(part) for part in shlex.split(spot_check_config.get('xxh64sum_command', 'xxh64sum')) - ) + hash_paths, + ) + + hash_paths, working_directory=working_directory, ) diff --git a/borgmatic/borg/list.py b/borgmatic/borg/list.py index 22eccc76..308a6f31 100644 --- a/borgmatic/borg/list.py +++ b/borgmatic/borg/list.py @@ -56,7 +56,7 @@ def make_list_command( + flags.make_flags('remote-path', remote_path) + flags.make_flags('umask', config.get('umask')) + ('--log-json',) - + (('--json-lines',) if list_arguments.json else ()) + + flags.make_flags('json-lines', list_arguments.json) + flags.make_flags('lock-wait', config.get('lock_wait')) + flags.make_flags('format', list_arguments.format or config.get('file_list_format')) + flags.make_flags_from_arguments(list_arguments, excludes=MAKE_FLAGS_EXCLUDES) @@ -198,11 +198,6 @@ def list_archive( f"The --{name.replace('_', '-')} flag on the list action is ignored when using the --archive flag.", ) - if list_arguments.json: - raise ValueError( - 'The --json flag on the list action is not supported when using the --archive/--find flags.', - ) - borg_exit_codes = config.get('borg_exit_codes') # If there are any paths to find (and there's not a single archive already selected), start by diff --git a/borgmatic/execute.py b/borgmatic/execute.py index af3a9709..0e9d639b 100644 --- a/borgmatic/execute.py +++ b/borgmatic/execute.py @@ -196,14 +196,14 @@ def handle_log_record(log_record, last_lines): return log_record -def log_outputs( +def log_outputs( # noqa: PLR0912 processes, exclude_stdouts, output_log_level, borg_local_path, borg_exit_codes, capture_stderr=False, -): # noqa: PLR0912 +): ''' Given a sequence of subprocess.Popen() instances for multiple processes, log the outputs (stderr and stdout). Use the requested output log level for stdout, but always log stderr to the ERROR diff --git a/tests/unit/actions/test_check.py b/tests/unit/actions/test_check.py index 6e04158d..df6cfc03 100644 --- a/tests/unit/actions/test_check.py +++ b/tests/unit/actions/test_check.py @@ -850,13 +850,11 @@ def test_collect_spot_check_archive_paths_excludes_directories_and_pipes(): flexmock(module.borgmatic.config.paths).should_receive( 'get_borgmatic_source_directory', ).and_return('/home/user/.borgmatic') - flexmock(module.borgmatic.borg.list).should_receive('capture_archive_listing').and_return( - ( - 'f etc/path', - 'p var/pipe', - 'f etc/other', - 'd etc/dir', - ), + flexmock(module.borgmatic.borg.list).should_receive('capture_archive_listing').and_yield( + {'type': 'f', 'path': 'etc/path'}, + {'type': 'p', 'path': 'var/pipe'}, + {'type': 'f', 'path': 'etc/other'}, + {'type': 'd', 'path': 'etc/dir'}, ) assert module.collect_spot_check_archive_paths( @@ -875,11 +873,9 @@ def test_collect_spot_check_archive_paths_excludes_file_in_borgmatic_runtime_dir flexmock(module.borgmatic.config.paths).should_receive( 'get_borgmatic_source_directory', ).and_return('/root/.borgmatic') - flexmock(module.borgmatic.borg.list).should_receive('capture_archive_listing').and_return( - ( - 'f etc/path', - 'f borgmatic/some/thing', - ), + flexmock(module.borgmatic.borg.list).should_receive('capture_archive_listing').and_yield( + {'type': 'f', 'path': 'etc/path'}, + {'type': 'f', 'path': 'borgmatic/some/thing'}, ) assert module.collect_spot_check_archive_paths( @@ -898,11 +894,9 @@ def test_collect_spot_check_archive_paths_excludes_file_in_borgmatic_source_dire flexmock(module.borgmatic.config.paths).should_receive( 'get_borgmatic_source_directory', ).and_return('/root/.borgmatic') - flexmock(module.borgmatic.borg.list).should_receive('capture_archive_listing').and_return( - ( - 'f etc/path', - 'f root/.borgmatic/some/thing', - ), + flexmock(module.borgmatic.borg.list).should_receive('capture_archive_listing').and_yield( + {'type': 'f', 'path': 'etc/path'}, + {'type': 'f', 'path': 'root/.borgmatic/some/thing'}, ) assert module.collect_spot_check_archive_paths( @@ -921,11 +915,9 @@ def test_collect_spot_check_archive_paths_excludes_file_in_borgmatic_runtime_dir flexmock(module.borgmatic.config.paths).should_receive( 'get_borgmatic_source_directory', ).and_return('/root.borgmatic') - flexmock(module.borgmatic.borg.list).should_receive('capture_archive_listing').and_return( - ( - 'f etc/path', - 'f run/user/0/borgmatic/some/thing', - ), + flexmock(module.borgmatic.borg.list).should_receive('capture_archive_listing').and_yield( + {'type': 'f', 'path': 'etc/path'}, + {'type': 'f', 'path': 'run/user/0/borgmatic/some/thing'}, ) assert module.collect_spot_check_archive_paths( @@ -1009,8 +1001,9 @@ def test_compare_spot_check_hashes_returns_paths_having_failing_hashes(): 'hash1 /foo', 'hash2 /bar', ) - flexmock(module.borgmatic.borg.list).should_receive('capture_archive_listing').and_return( - ['hash1 foo', 'nothash2 bar'], + flexmock(module.borgmatic.borg.list).should_receive('capture_archive_listing').and_yield( + {'xxh64': 'hash1', 'path': 'foo'}, + {'xxh64': 'nothash2', 'path': 'bar'}, ) assert module.compare_spot_check_hashes( @@ -1051,8 +1044,9 @@ def test_compare_spot_check_hashes_returns_relative_paths_having_failing_hashes( 'hash1 foo', 'hash2 bar', ) - flexmock(module.borgmatic.borg.list).should_receive('capture_archive_listing').and_return( - ['hash1 foo', 'nothash2 bar'], + flexmock(module.borgmatic.borg.list).should_receive('capture_archive_listing').and_yield( + {'xxh64': 'hash1', 'path': 'foo'}, + {'xxh64': 'nothash2', 'path': 'bar'}, ) assert module.compare_spot_check_hashes( @@ -1093,8 +1087,9 @@ def test_compare_spot_check_hashes_handles_data_sample_percentage_above_100(): 'hash1 /foo', 'hash2 /bar', ) - flexmock(module.borgmatic.borg.list).should_receive('capture_archive_listing').and_return( - ['nothash1 foo', 'nothash2 bar'], + flexmock(module.borgmatic.borg.list).should_receive('capture_archive_listing').and_yield( + {'xxh64': 'nothash1', 'path': 'foo'}, + {'xxh64': 'nothash2', 'path': 'bar'}, ) assert module.compare_spot_check_hashes( @@ -1135,8 +1130,9 @@ def test_compare_spot_check_hashes_uses_xxh64sum_command_option(): ('/usr/local/bin/xxhsum', '-H64', '/foo', '/bar'), working_directory=None, ).and_yield('hash1 /foo', 'hash2 /bar') - flexmock(module.borgmatic.borg.list).should_receive('capture_archive_listing').and_return( - ['hash1 foo', 'nothash2 bar'], + flexmock(module.borgmatic.borg.list).should_receive('capture_archive_listing').and_yield( + {'xxh64': 'hash1', 'path': 'foo'}, + {'xxh64': 'nothash2', 'path': 'bar'}, ) assert module.compare_spot_check_hashes( @@ -1174,8 +1170,8 @@ def test_compare_spot_check_hashes_considers_path_missing_from_archive_as_not_ma 'hash1 /foo', 'hash2 /bar', ) - flexmock(module.borgmatic.borg.list).should_receive('capture_archive_listing').and_return( - ['hash1 foo'], + flexmock(module.borgmatic.borg.list).should_receive('capture_archive_listing').and_yield( + {'xxh64': 'hash1', 'path': 'foo'} ) assert module.compare_spot_check_hashes( @@ -1210,8 +1206,9 @@ def test_compare_spot_check_hashes_considers_symlink_path_as_not_matching(): flexmock(module.borgmatic.execute).should_receive( 'execute_command_and_capture_output', ).with_args(('xxh64sum', '/foo'), working_directory=None).and_yield('hash1 /foo') - flexmock(module.borgmatic.borg.list).should_receive('capture_archive_listing').and_return( - ['hash1 foo', 'hash2 bar'], + 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( @@ -1246,8 +1243,9 @@ def test_compare_spot_check_hashes_considers_non_existent_path_as_not_matching() flexmock(module.borgmatic.execute).should_receive( 'execute_command_and_capture_output', ).with_args(('xxh64sum', '/foo'), working_directory=None).and_yield('hash1 /foo') - flexmock(module.borgmatic.borg.list).should_receive('capture_archive_listing').and_return( - ['hash1 foo', 'hash2 bar'], + 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( @@ -1291,9 +1289,13 @@ def test_compare_spot_check_hashes_with_too_many_paths_feeds_them_to_commands_in 'hash3 /baz', 'hash4 /quux', ) - flexmock(module.borgmatic.borg.list).should_receive('capture_archive_listing').and_return( - ['hash1 foo', 'hash2 bar'], - ).and_return(['hash3 baz', 'nothash4 quux']) + flexmock(module.borgmatic.borg.list).should_receive('capture_archive_listing').and_yield( + {'xxh64': 'hash1', 'path': 'foo'}, + {'xxh64': 'hash2', 'path': 'bar'}, + ).and_yield( + {'xxh64': 'hash3', 'path': 'baz'}, + {'xxh64': 'nothash4', 'path': 'quux'}, + ) assert module.compare_spot_check_hashes( repository={'path': 'repo'}, @@ -1334,8 +1336,9 @@ def test_compare_spot_check_hashes_uses_working_directory_to_access_source_paths 'hash1 foo', 'hash2 bar', ) - flexmock(module.borgmatic.borg.list).should_receive('capture_archive_listing').and_return( - ['hash1 foo', 'nothash2 bar'], + flexmock(module.borgmatic.borg.list).should_receive('capture_archive_listing').and_yield( + {'xxh64': 'hash1', 'path': 'foo'}, + {'xxh64': 'nothash2', 'path': 'bar'}, ) assert module.compare_spot_check_hashes( diff --git a/tests/unit/borg/test_list.py b/tests/unit/borg/test_list.py index 0be0c4e1..fbb3a3a7 100644 --- a/tests/unit/borg/test_list.py +++ b/tests/unit/borg/test_list.py @@ -26,10 +26,10 @@ def test_make_list_command_includes_log_info(): assert command == ('borg', 'list', '--info', '--log-json', 'repo') -def test_make_list_command_includes_json_but_not_info(): +def test_make_list_command_includes_json_lines_but_not_info(): insert_logging_mock(logging.INFO) flexmock(module.flags).should_receive('make_flags').and_return(()) - flexmock(module.flags).should_receive('make_flags_from_arguments').and_return(('--json',)) + flexmock(module.flags).should_receive('make_flags_from_arguments').and_return(('--json-lines',)) flexmock(module.flags).should_receive('make_repository_flags').and_return(('repo',)) command = module.make_list_command( @@ -40,7 +40,7 @@ def test_make_list_command_includes_json_but_not_info(): global_arguments=flexmock(), ) - assert command == ('borg', 'list', '--log-json', '--json', 'repo') + assert command == ('borg', 'list', '--log-json', '--json-lines', 'repo') def test_make_list_command_includes_log_debug(): @@ -332,7 +332,7 @@ def test_make_find_paths_adds_globs_to_path_fragments(): def test_capture_archive_listing_does_not_raise(): flexmock(module.environment).should_receive('make_environment') flexmock(module.borgmatic.config.paths).should_receive('get_working_directory').and_return(None) - flexmock(module).should_receive('execute_command_and_capture_output').and_yield('') + flexmock(module).should_receive('execute_command_and_capture_output').and_yield('{}', '{}') flexmock(module).should_receive('make_list_command') module.capture_archive_listing( @@ -393,24 +393,6 @@ def test_list_archive_calls_borg_with_flags(): ) -def test_list_archive_with_archive_and_json_errors(): - flexmock(module.borgmatic.logger).should_receive('add_custom_log_levels') - flexmock(module.logging).ANSWER = module.borgmatic.logger.ANSWER - flexmock(module.logger).answer = lambda message: None - list_arguments = argparse.Namespace(archive='archive', paths=None, json=True, find_paths=None) - - flexmock(module.feature).should_receive('available').and_return(False) - - with pytest.raises(ValueError): - module.list_archive( - repository_path='repo', - config={}, - local_borg_version='1.2.3', - list_arguments=list_arguments, - global_arguments=flexmock(), - ) - - def test_list_archive_calls_borg_with_local_path(): flexmock(module.borgmatic.logger).should_receive('add_custom_log_levels') flexmock(module.logging).ANSWER = module.borgmatic.logger.ANSWER diff --git a/tests/unit/test_execute.py b/tests/unit/test_execute.py index f0115894..2b1b2b31 100644 --- a/tests/unit/test_execute.py +++ b/tests/unit/test_execute.py @@ -104,11 +104,10 @@ def test_output_buffers_for_process_returns_stderr_only_when_stdout_excluded(): ) -def test_borg_log_line_to_record_parses_line(): - flexmock(module).should_receive('log_line_to_record').never() - line = '{"levelname": "INFO", "time": 12345, "message": "All done", "name": "borg.something"}' +def test_borg_json_log_line_to_record_parses_log_message_line(): + line = '{"type": "log_message", "levelname": "INFO", "time": 12345, "message": "All done", "name": "borg.something"}' - record = module.borg_log_line_to_record(line, module.logging.INFO) + record = module.borg_json_log_line_to_record(line, module.logging.INFO) assert record.levelno == module.logging.INFO assert record.created == 12345 @@ -117,24 +116,35 @@ def test_borg_log_line_to_record_parses_line(): assert record.name == 'borg.something' -def test_borg_log_line_to_record_with_invalid_json_falls_back_to_raw_line(): - record = flexmock() +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"}' + + record = module.borg_json_log_line_to_record(line, module.logging.INFO) + + assert record.levelno == module.logging.INFO + assert record.created == 12345 + assert record.msg == '- /foo/bar' + assert record.levelname == 'INFO' + assert record.name == 'borg.file_status' + + +def test_borg_json_log_line_to_record_handles_invalid_json(): line = '{invalid' - flexmock(module).should_receive('log_line_to_record').with_args( - line, module.logging.INFO - ).and_return(record).once() - assert module.borg_log_line_to_record(line, module.logging.INFO) == record + assert module.borg_json_log_line_to_record(line, module.logging.INFO) is None -def test_borg_log_line_to_record_with_non_dict_json_falls_back_to_raw_line(): - record = flexmock() +def test_borg_json_log_line_to_record_handles_non_dict_json(): line = '[]' - flexmock(module).should_receive('log_line_to_record').with_args( - line, module.logging.INFO - ).and_return(record).once() - assert module.borg_log_line_to_record(line, module.logging.INFO) == record + assert module.borg_json_log_line_to_record(line, module.logging.INFO) is None + + +def test_borg_json_log_line_to_record_handles_json_dict_without_type(): + line = '{"status": "-", "path": "/foo/bar"}' + + assert module.borg_json_log_line_to_record(line, module.logging.INFO) is None def test_log_line_to_record_makes_log_record(): @@ -149,14 +159,14 @@ def test_log_line_to_record_makes_log_record(): def test_parse_log_line_with_borg_command_parses_borg_log_line(): record = flexmock() - flexmock(module).should_receive('borg_log_line_to_record').and_return(record).once() + flexmock(module).should_receive('borg_json_log_line_to_record').and_return(record).once() flexmock(module).should_receive('log_line_to_record').never() assert ( module.parse_log_line( 'All done', module.logging.INFO, - came_from_stderr=False, + elevate_stderr=False, borg_local_path='borg', command=['borg', 'do-stuff'], ) @@ -166,14 +176,14 @@ def test_parse_log_line_with_borg_command_parses_borg_log_line(): def test_parse_log_line_without_borg_command_parses_plain_log_line(): record = flexmock() - flexmock(module).should_receive('borg_log_line_to_record').never() + flexmock(module).should_receive('borg_json_log_line_to_record').never() flexmock(module).should_receive('log_line_to_record').and_return(record).once() assert ( module.parse_log_line( 'All done', module.logging.INFO, - came_from_stderr=False, + elevate_stderr=False, borg_local_path='borg', command=['totally-not-borg', 'do-stuff'], ) @@ -181,9 +191,9 @@ def test_parse_log_line_without_borg_command_parses_plain_log_line(): ) -def test_parse_log_line_with_came_from_stderr_makes_error_record(): +def test_parse_log_line_with_elevate_stderr_makes_error_record(): record = flexmock() - flexmock(module).should_receive('borg_log_line_to_record').never() + flexmock(module).should_receive('borg_json_log_line_to_record').never() flexmock(module).should_receive('log_line_to_record').with_args( 'All done', module.logging.ERROR ).and_return(record).once() @@ -192,7 +202,7 @@ def test_parse_log_line_with_came_from_stderr_makes_error_record(): module.parse_log_line( 'All done', module.logging.INFO, - came_from_stderr=True, + elevate_stderr=True, borg_local_path='borg', command=['totally-not-borg', 'do-stuff'], ) @@ -200,9 +210,9 @@ def test_parse_log_line_with_came_from_stderr_makes_error_record(): ) -def test_parse_log_line_with_came_from_stderr_and_warning_prefix_makes_warning_record(): +def test_parse_log_line_with_elevate_stderr_and_warning_prefix_makes_warning_record(): record = flexmock() - flexmock(module).should_receive('borg_log_line_to_record').never() + flexmock(module).should_receive('borg_json_log_line_to_record').never() flexmock(module).should_receive('log_line_to_record').with_args( 'warning: All done', module.logging.WARNING ).and_return(record).once() @@ -211,7 +221,7 @@ def test_parse_log_line_with_came_from_stderr_and_warning_prefix_makes_warning_r module.parse_log_line( 'warning: All done', module.logging.INFO, - came_from_stderr=True, + elevate_stderr=True, borg_local_path='borg', command=['totally-not-borg', 'do-stuff'], ) From 762beb46c2f678837756f1a129d545333c3491b0 Mon Sep 17 00:00:00 2001 From: Dan Helfman Date: Wed, 14 Jan 2026 12:54:36 -0800 Subject: [PATCH 6/9] Fix "restore" action and broken end-to-end tests. --- borgmatic/actions/restore.py | 14 ++-- borgmatic/borg/extract.py | 6 +- borgmatic/hooks/data_source/mariadb.py | 1 + borgmatic/hooks/data_source/mongodb.py | 1 + borgmatic/hooks/data_source/mysql.py | 1 + borgmatic/hooks/data_source/postgresql.py | 1 + borgmatic/hooks/data_source/sqlite.py | 2 + tests/unit/actions/test_restore.py | 72 +++++++++---------- tests/unit/borg/test_extract.py | 2 +- tests/unit/hooks/data_source/test_mariadb.py | 11 +++ tests/unit/hooks/data_source/test_mongodb.py | 10 +++ tests/unit/hooks/data_source/test_mysql.py | 11 +++ .../unit/hooks/data_source/test_postgresql.py | 11 +++ tests/unit/hooks/data_source/test_sqlite.py | 6 ++ 14 files changed, 101 insertions(+), 48 deletions(-) diff --git a/borgmatic/actions/restore.py b/borgmatic/actions/restore.py index 7aeaa533..1df39f7d 100644 --- a/borgmatic/actions/restore.py +++ b/borgmatic/actions/restore.py @@ -277,7 +277,7 @@ def collect_dumps_from_archive( dumps_from_archive = {} # Use a dict as an ordered set. # There is (at most) one dump metadata file per data source hook. Load each. - for dumps_metadata_path in borgmatic.borg.list.capture_archive_listing( + for dumps_metadata_entry in borgmatic.borg.list.capture_archive_listing( repository, archive, config, @@ -300,7 +300,7 @@ def collect_dumps_from_archive( local_path=local_path, remote_path=remote_path, ): - if not dumps_metadata_path: + if not dumps_metadata_entry.get('path'): continue for dump in borgmatic.hooks.data_source.dump.parse_data_source_dumps_metadata( @@ -308,7 +308,7 @@ def collect_dumps_from_archive( global_arguments.dry_run, repository, archive, - [dumps_metadata_path], + [dumps_metadata_entry['path']], config, local_borg_version, global_arguments, @@ -318,7 +318,7 @@ def collect_dumps_from_archive( ) .stdout.read() .decode(), - dumps_metadata_path, + dumps_metadata_entry['path'], ): dumps_from_archive[dump] = None @@ -338,7 +338,7 @@ def collect_dumps_from_archive( # Probe for the data source dumps in multiple locations, as the default location has moved to # the borgmatic runtime directory (which gets stored as just "/borgmatic" with Borg 1.4+). But # we still want to support reading dumps from previously created archives as well. - dump_paths = borgmatic.borg.list.capture_archive_listing( + dump_entries = borgmatic.borg.list.capture_archive_listing( repository, archive, config, @@ -360,7 +360,9 @@ def collect_dumps_from_archive( remote_path=remote_path, ) - for dump_path in dump_paths: + for dump_entry in dump_entries: + dump_path = dump_entry.get('path') + if not dump_path: continue diff --git a/borgmatic/borg/extract.py b/borgmatic/borg/extract.py index 6015747b..1765b744 100644 --- a/borgmatic/borg/extract.py +++ b/borgmatic/borg/extract.py @@ -135,11 +135,7 @@ def extract_archive( + (('--remote-path', remote_path) if remote_path else ()) + numeric_ids_flags + (('--umask', str(umask)) if umask else ()) - + ( - ('--log-json',) - if (config.get('log_json') or (not config.get('progress') and not extract_to_stdout)) - else () - ) + + (('--log-json',) if (config.get('log_json') or not config.get('progress')) else ()) + (('--lock-wait', str(lock_wait)) if lock_wait else ()) + (('--info',) if logger.getEffectiveLevel() == logging.INFO else ()) + (('--debug', '--list', '--show-rc') if logger.isEnabledFor(logging.DEBUG) else ()) diff --git a/borgmatic/hooks/data_source/mariadb.py b/borgmatic/hooks/data_source/mariadb.py index 84a0fd71..a6f744b9 100644 --- a/borgmatic/hooks/data_source/mariadb.py +++ b/borgmatic/hooks/data_source/mariadb.py @@ -524,5 +524,6 @@ def restore_data_source_dump( input_file=extract_process.stdout, environment=environment, working_directory=borgmatic.config.paths.get_working_directory(config), + borg_local_path=config.get('local_path', 'borg'), ) ) diff --git a/borgmatic/hooks/data_source/mongodb.py b/borgmatic/hooks/data_source/mongodb.py index 0ef03132..f95deb78 100644 --- a/borgmatic/hooks/data_source/mongodb.py +++ b/borgmatic/hooks/data_source/mongodb.py @@ -296,6 +296,7 @@ def restore_data_source_dump( output_log_level=logging.DEBUG, input_file=extract_process.stdout if extract_process else None, working_directory=borgmatic.config.paths.get_working_directory(config), + borg_local_path=config.get('local_path', 'borg'), ) ) diff --git a/borgmatic/hooks/data_source/mysql.py b/borgmatic/hooks/data_source/mysql.py index 9bed3683..c375cd18 100644 --- a/borgmatic/hooks/data_source/mysql.py +++ b/borgmatic/hooks/data_source/mysql.py @@ -461,5 +461,6 @@ def restore_data_source_dump( input_file=extract_process.stdout, environment=environment, working_directory=borgmatic.config.paths.get_working_directory(config), + borg_local_path=config.get('local_path', 'borg'), ) ) diff --git a/borgmatic/hooks/data_source/postgresql.py b/borgmatic/hooks/data_source/postgresql.py index b8397d0e..4b97b2e0 100644 --- a/borgmatic/hooks/data_source/postgresql.py +++ b/borgmatic/hooks/data_source/postgresql.py @@ -442,6 +442,7 @@ def restore_data_source_dump( input_file=extract_process.stdout if extract_process else None, environment=environment, working_directory=borgmatic.config.paths.get_working_directory(config), + borg_local_path=config.get('local_path', 'borg'), ) ) execute_command( diff --git a/borgmatic/hooks/data_source/sqlite.py b/borgmatic/hooks/data_source/sqlite.py index fcdcfcdb..09ec2016 100644 --- a/borgmatic/hooks/data_source/sqlite.py +++ b/borgmatic/hooks/data_source/sqlite.py @@ -215,6 +215,7 @@ def restore_data_source_dump( for part in shlex.split(data_source.get('sqlite_restore_command') or 'sqlite3') ) restore_command = (*sqlite_restore_command, '-bail', shlex.quote(database_path)) + # Don't give Borg local path so as to error on warnings, as "borg extract" only gives a warning # if the restore paths don't exist in the archive. tuple( @@ -224,5 +225,6 @@ def restore_data_source_dump( output_log_level=logging.DEBUG, input_file=extract_process.stdout, working_directory=borgmatic.config.paths.get_working_directory(config), + borg_local_path=config.get('local_path', 'borg'), ) ) diff --git a/tests/unit/actions/test_restore.py b/tests/unit/actions/test_restore.py index a6c8d2c1..8077a3c7 100644 --- a/tests/unit/actions/test_restore.py +++ b/tests/unit/actions/test_restore.py @@ -513,10 +513,10 @@ def test_collect_dumps_from_archive_with_dumps_metadata_parses_it(): 'make_runtime_directory_glob' ).and_return('') flexmock(module.borgmatic.borg.list).should_receive('capture_archive_listing').and_return( - [ - 'borgmatic/postgresql_databases/dumps.json', - 'borgmatic/mysql_databases/dumps.json', - ], + ( + {'path': 'borgmatic/postgresql_databases/dumps.json'}, + {'path': 'borgmatic/mysql_databases/dumps.json'}, + ), ) flexmock(module.borgmatic.borg.extract).should_receive('extract_archive').and_return( flexmock(stdout=flexmock(read=lambda: b'')) @@ -550,13 +550,13 @@ def test_collect_dumps_from_archive_with_empty_dumps_metadata_path_falls_back_to 'make_runtime_directory_glob' ).and_return('') flexmock(module.borgmatic.borg.list).should_receive('capture_archive_listing').and_return( - [''] + ({'path': ''},) ).and_return( - [ - 'borgmatic/postgresql_databases/localhost/foo', - 'borgmatic/postgresql_databases/host:1234/bar', - 'borgmatic/mysql_databases/localhost/quux', - ], + ( + {'path': 'borgmatic/postgresql_databases/localhost/foo'}, + {'path': 'borgmatic/postgresql_databases/host:1234/bar'}, + {'path': 'borgmatic/mysql_databases/localhost/quux'}, + ), ) flexmock(module.borgmatic.borg.extract).should_receive('extract_archive').never() flexmock(module.borgmatic.hooks.data_source.dump).should_receive( @@ -592,13 +592,13 @@ def test_collect_dumps_from_archive_without_dumps_metadata_falls_back_to_parsing 'make_runtime_directory_glob' ).and_return('') flexmock(module.borgmatic.borg.list).should_receive('capture_archive_listing').and_return( - [] + () ).and_return( - [ - 'borgmatic/postgresql_databases/localhost/foo', - 'borgmatic/postgresql_databases/host:1234/bar', - 'borgmatic/mysql_databases/localhost/quux', - ], + ( + {'path': 'borgmatic/postgresql_databases/localhost/foo'}, + {'path': 'borgmatic/postgresql_databases/host:1234/bar'}, + {'path': 'borgmatic/mysql_databases/localhost/quux'}, + ), ) flexmock(module.borgmatic.borg.extract).should_receive('extract_archive').never() flexmock(module.borgmatic.hooks.data_source.dump).should_receive( @@ -634,14 +634,14 @@ def test_collect_dumps_from_archive_parses_archive_paths_with_different_base_dir 'make_runtime_directory_glob' ).and_return('') flexmock(module.borgmatic.borg.list).should_receive('capture_archive_listing').and_return( - [] + () ).and_return( - [ - 'borgmatic/postgresql_databases/localhost/foo', - '.borgmatic/postgresql_databases/localhost/bar', - '/root/.borgmatic/postgresql_databases/localhost/baz', - '/var/run/0/borgmatic/mysql_databases/localhost/quux', - ], + ( + {'path': 'borgmatic/postgresql_databases/localhost/foo'}, + {'path': '.borgmatic/postgresql_databases/localhost/bar'}, + {'path': '/root/.borgmatic/postgresql_databases/localhost/baz'}, + {'path': '/var/run/0/borgmatic/mysql_databases/localhost/quux'}, + ), ) flexmock(module.borgmatic.borg.extract).should_receive('extract_archive').never() flexmock(module.borgmatic.hooks.data_source.dump).should_receive( @@ -678,12 +678,12 @@ def test_collect_dumps_from_archive_parses_directory_format_archive_paths(): 'make_runtime_directory_glob' ).and_return('') flexmock(module.borgmatic.borg.list).should_receive('capture_archive_listing').and_return( - [] + () ).and_return( - [ - 'borgmatic/postgresql_databases/localhost/foo/table1', - 'borgmatic/postgresql_databases/localhost/foo/table2', - ], + ( + {'path': 'borgmatic/postgresql_databases/localhost/foo/table1'}, + {'path': 'borgmatic/postgresql_databases/localhost/foo/table2'}, + ), ) flexmock(module.borgmatic.borg.extract).should_receive('extract_archive').never() flexmock(module.borgmatic.hooks.data_source.dump).should_receive( @@ -715,15 +715,15 @@ def test_collect_dumps_from_archive_skips_bad_archive_paths_or_bad_path_componen 'make_runtime_directory_glob' ).and_return('') flexmock(module.borgmatic.borg.list).should_receive('capture_archive_listing').and_return( - [] + () ).and_return( - [ - 'borgmatic/postgresql_databases/localhost/foo', - 'borgmatic/postgresql_databases/localhost:abcd/bar', - 'borgmatic/invalid', - 'invalid/as/well', - '', - ], + ( + {'path': 'borgmatic/postgresql_databases/localhost/foo'}, + {'path': 'borgmatic/postgresql_databases/localhost:abcd/bar'}, + {'path': 'borgmatic/invalid'}, + {'path': 'invalid/as/well'}, + {'path': ''}, + ) ) flexmock(module.borgmatic.borg.extract).should_receive('extract_archive').never() flexmock(module.borgmatic.hooks.data_source.dump).should_receive( diff --git a/tests/unit/borg/test_extract.py b/tests/unit/borg/test_extract.py index dc56e8ee..6983248d 100644 --- a/tests/unit/borg/test_extract.py +++ b/tests/unit/borg/test_extract.py @@ -715,7 +715,7 @@ def test_extract_archive_calls_borg_with_extract_to_stdout_returns_process(): flexmock(module.environment).should_receive('make_environment') flexmock(module.borgmatic.config.paths).should_receive('get_working_directory').and_return(None) flexmock(module).should_receive('execute_command').with_args( - ('borg', 'extract', '--stdout', 'repo::archive'), + ('borg', 'extract', '--log-json', '--stdout', 'repo::archive'), output_file=module.subprocess.PIPE, run_to_completion=False, environment=None, diff --git a/tests/unit/hooks/data_source/test_mariadb.py b/tests/unit/hooks/data_source/test_mariadb.py index d54536d5..3054006c 100644 --- a/tests/unit/hooks/data_source/test_mariadb.py +++ b/tests/unit/hooks/data_source/test_mariadb.py @@ -1353,6 +1353,7 @@ def test_restore_data_source_dump_runs_mariadb_to_restore(): input_file=extract_process.stdout, environment={'USER': 'root'}, working_directory=None, + borg_local_path='borg', ).and_yield().once() module.restore_data_source_dump( @@ -1394,6 +1395,7 @@ def test_restore_data_source_dump_runs_mariadb_with_options(): input_file=extract_process.stdout, environment={'USER': 'root'}, working_directory=None, + borg_local_path='borg', ).and_yield().once() module.restore_data_source_dump( @@ -1437,6 +1439,7 @@ def test_restore_data_source_dump_runs_non_default_mariadb_with_options(): input_file=extract_process.stdout, environment={'USER': 'root'}, working_directory=None, + borg_local_path='borg', ).and_yield().once() module.restore_data_source_dump( @@ -1489,6 +1492,7 @@ def test_restore_data_source_dump_runs_mariadb_with_hostname_and_port(): input_file=extract_process.stdout, environment={'USER': 'root'}, working_directory=None, + borg_local_path='borg', ).and_yield().once() module.restore_data_source_dump( @@ -1537,6 +1541,7 @@ def test_restore_data_source_dump_runs_mariadb_with_socket_path(): input_file=extract_process.stdout, environment={'USER': 'root'}, working_directory=None, + borg_local_path='borg', ).and_yield().once() module.restore_data_source_dump( @@ -1584,6 +1589,7 @@ def test_restore_data_source_dump_runs_mariadb_with_tls(): input_file=extract_process.stdout, environment={'USER': 'root'}, working_directory=None, + borg_local_path='borg', ).and_yield().once() module.restore_data_source_dump( @@ -1631,6 +1637,7 @@ def test_restore_data_source_dump_runs_mariadb_without_tls(): input_file=extract_process.stdout, environment={'USER': 'root'}, working_directory=None, + borg_local_path='borg', ).and_yield().once() module.restore_data_source_dump( @@ -1674,6 +1681,7 @@ def test_restore_data_source_dump_runs_mariadb_with_username_and_password(): input_file=extract_process.stdout, environment={'USER': 'root'}, working_directory=None, + borg_local_path='borg', ).and_yield().once() module.restore_data_source_dump( @@ -1722,6 +1730,7 @@ def test_restore_data_source_with_environment_password_transport_skips_defaults_ input_file=extract_process.stdout, environment={'USER': 'root', 'MYSQL_PWD': 'trustsome1'}, working_directory=None, + borg_local_path='borg', ).and_yield().once() module.restore_data_source_dump( @@ -1787,6 +1796,7 @@ def test_restore_data_source_dump_with_connection_params_uses_connection_params_ input_file=extract_process.stdout, environment={'USER': 'root'}, working_directory=None, + borg_local_path='borg', ).and_yield().once() module.restore_data_source_dump( @@ -1857,6 +1867,7 @@ def test_restore_data_source_dump_without_connection_params_uses_restore_params_ input_file=extract_process.stdout, environment={'USER': 'root'}, working_directory=None, + borg_local_path='borg', ).and_yield().once() module.restore_data_source_dump( diff --git a/tests/unit/hooks/data_source/test_mongodb.py b/tests/unit/hooks/data_source/test_mongodb.py index feaf59b5..19faa092 100644 --- a/tests/unit/hooks/data_source/test_mongodb.py +++ b/tests/unit/hooks/data_source/test_mongodb.py @@ -394,6 +394,7 @@ def test_restore_data_source_dump_runs_mongorestore(): output_log_level=logging.DEBUG, input_file=extract_process.stdout, working_directory=None, + borg_local_path='borg', ).and_yield().once() module.restore_data_source_dump( @@ -438,6 +439,7 @@ def test_restore_data_source_dump_runs_mongorestore_with_hostname_and_port(): output_log_level=logging.DEBUG, input_file=extract_process.stdout, working_directory=None, + borg_local_path='borg', ).and_yield().once() module.restore_data_source_dump( @@ -493,6 +495,7 @@ def test_restore_data_source_dump_runs_mongorestore_with_username_and_password() output_log_level=logging.DEBUG, input_file=extract_process.stdout, working_directory=None, + borg_local_path='borg', ).and_yield().once() module.restore_data_source_dump( @@ -556,6 +559,7 @@ def test_restore_data_source_dump_with_connection_params_uses_connection_params_ output_log_level=logging.DEBUG, input_file=extract_process.stdout, working_directory=None, + borg_local_path='borg', ).and_yield().once() module.restore_data_source_dump( @@ -619,6 +623,7 @@ def test_restore_data_source_dump_without_connection_params_uses_restore_params_ output_log_level=logging.DEBUG, input_file=extract_process.stdout, working_directory=None, + borg_local_path='borg', ).and_yield().once() module.restore_data_source_dump( @@ -653,6 +658,7 @@ def test_restore_data_source_dump_runs_mongorestore_with_options(): output_log_level=logging.DEBUG, input_file=extract_process.stdout, working_directory=None, + borg_local_path='borg', ).and_yield().once() module.restore_data_source_dump( @@ -695,6 +701,7 @@ def test_restore_databases_dump_runs_mongorestore_with_schemas(): output_log_level=logging.DEBUG, input_file=extract_process.stdout, working_directory=None, + borg_local_path='borg', ).and_yield().once() module.restore_data_source_dump( @@ -729,6 +736,7 @@ def test_restore_data_source_dump_runs_psql_for_all_database_dump(): output_log_level=logging.DEBUG, input_file=extract_process.stdout, working_directory=None, + borg_local_path='borg', ).and_yield().once() module.restore_data_source_dump( @@ -788,6 +796,7 @@ def test_restore_data_source_dump_without_extract_process_restores_from_disk(): output_log_level=logging.DEBUG, input_file=None, working_directory=None, + borg_local_path='borg', ).and_yield().once() module.restore_data_source_dump( @@ -901,6 +910,7 @@ def test_restore_data_source_dump_uses_custom_mongorestore_command(): output_log_level=logging.DEBUG, input_file=extract_process.stdout, working_directory=None, + borg_local_path='borg', ).and_yield().once() module.restore_data_source_dump( diff --git a/tests/unit/hooks/data_source/test_mysql.py b/tests/unit/hooks/data_source/test_mysql.py index a4e2a517..310ef3b2 100644 --- a/tests/unit/hooks/data_source/test_mysql.py +++ b/tests/unit/hooks/data_source/test_mysql.py @@ -1235,6 +1235,7 @@ def test_restore_data_source_dump_runs_mysql_to_restore(): input_file=extract_process.stdout, environment={'USER': 'root'}, working_directory=None, + borg_local_path='borg', ).and_yield().once() module.restore_data_source_dump( @@ -1276,6 +1277,7 @@ def test_restore_data_source_dump_runs_mysql_with_options(): input_file=extract_process.stdout, environment={'USER': 'root'}, working_directory=None, + borg_local_path='borg', ).and_yield().once() module.restore_data_source_dump( @@ -1317,6 +1319,7 @@ def test_restore_data_source_dump_runs_non_default_mysql_with_options(): input_file=extract_process.stdout, environment={'USER': 'root'}, working_directory=None, + borg_local_path='borg', ).and_yield().once() module.restore_data_source_dump( @@ -1369,6 +1372,7 @@ def test_restore_data_source_dump_runs_mysql_with_hostname_and_port(): input_file=extract_process.stdout, environment={'USER': 'root'}, working_directory=None, + borg_local_path='borg', ).and_yield().once() module.restore_data_source_dump( @@ -1421,6 +1425,7 @@ def test_restore_data_source_dump_runs_mysql_with_socket_path(): input_file=extract_process.stdout, environment={'USER': 'root'}, working_directory=None, + borg_local_path='borg', ).and_yield().once() module.restore_data_source_dump( @@ -1468,6 +1473,7 @@ def test_restore_data_source_dump_runs_mysql_with_tls(): input_file=extract_process.stdout, environment={'USER': 'root'}, working_directory=None, + borg_local_path='borg', ).and_yield().once() module.restore_data_source_dump( @@ -1515,6 +1521,7 @@ def test_restore_data_source_dump_runs_mysql_without_tls(): input_file=extract_process.stdout, environment={'USER': 'root'}, working_directory=None, + borg_local_path='borg', ).and_yield().once() module.restore_data_source_dump( @@ -1558,6 +1565,7 @@ def test_restore_data_source_dump_runs_mysql_with_username_and_password(): input_file=extract_process.stdout, environment={'USER': 'root'}, working_directory=None, + borg_local_path='borg', ).and_yield().once() module.restore_data_source_dump( @@ -1610,6 +1618,7 @@ def test_restore_data_source_with_environment_password_transport_skips_defaults_ input_file=extract_process.stdout, environment={'USER': 'root', 'MYSQL_PWD': 'trustsome1'}, working_directory=None, + borg_local_path='borg', ).and_yield().once() module.restore_data_source_dump( @@ -1677,6 +1686,7 @@ def test_restore_data_source_dump_with_connection_params_uses_connection_params_ input_file=extract_process.stdout, environment={'USER': 'root'}, working_directory=None, + borg_local_path='borg', ).and_yield().once() module.restore_data_source_dump( @@ -1749,6 +1759,7 @@ def test_restore_data_source_dump_without_connection_params_uses_restore_params_ input_file=extract_process.stdout, environment={'USER': 'root'}, working_directory=None, + borg_local_path='borg', ).and_yield().once() module.restore_data_source_dump( diff --git a/tests/unit/hooks/data_source/test_postgresql.py b/tests/unit/hooks/data_source/test_postgresql.py index 0b33d0c9..a07f1624 100644 --- a/tests/unit/hooks/data_source/test_postgresql.py +++ b/tests/unit/hooks/data_source/test_postgresql.py @@ -995,6 +995,7 @@ def test_restore_data_source_dump_runs_pg_restore(): input_file=extract_process.stdout, environment={'PGSSLMODE': 'disable'}, working_directory=None, + borg_local_path='borg', ).and_yield().once() flexmock(module).should_receive('execute_command').with_args( ( @@ -1059,6 +1060,7 @@ def test_restore_data_source_dump_runs_pg_restore_with_hostname_and_port(): input_file=extract_process.stdout, environment={'PGSSLMODE': 'disable'}, working_directory=None, + borg_local_path='borg', ).and_yield().once() flexmock(module).should_receive('execute_command').with_args( ( @@ -1127,6 +1129,7 @@ def test_restore_data_source_dump_runs_pg_restore_with_username_and_password(): input_file=extract_process.stdout, environment={'PGPASSWORD': 'trustsome1', 'PGSSLMODE': 'disable'}, working_directory=None, + borg_local_path='borg', ).and_yield().once() flexmock(module).should_receive('execute_command').with_args( ( @@ -1208,6 +1211,7 @@ def test_restore_data_source_dump_with_connection_params_uses_connection_params_ input_file=extract_process.stdout, environment={'PGPASSWORD': 'clipassword', 'PGSSLMODE': 'disable'}, working_directory=None, + borg_local_path='borg', ).and_yield().once() flexmock(module).should_receive('execute_command').with_args( ( @@ -1293,6 +1297,7 @@ def test_restore_data_source_dump_without_connection_params_uses_restore_params_ input_file=extract_process.stdout, environment={'PGPASSWORD': 'restorepassword', 'PGSSLMODE': 'disable'}, working_directory=None, + borg_local_path='borg', ).and_yield().once() flexmock(module).should_receive('execute_command').with_args( ( @@ -1365,6 +1370,7 @@ def test_restore_data_source_dump_runs_pg_restore_with_options(): input_file=extract_process.stdout, environment={'PGSSLMODE': 'disable'}, working_directory=None, + borg_local_path='borg', ).and_yield().once() flexmock(module).should_receive('execute_command').with_args( ( @@ -1420,6 +1426,7 @@ def test_restore_data_source_dump_runs_psql_for_all_database_dump(): input_file=extract_process.stdout, environment={'PGSSLMODE': 'disable'}, working_directory=None, + borg_local_path='borg', ).and_yield().once() flexmock(module).should_receive('execute_command').with_args( ('psql', '--no-password', '--no-psqlrc', '--quiet', '--command', 'ANALYZE'), @@ -1461,6 +1468,7 @@ def test_restore_data_source_dump_runs_psql_for_plain_database_dump(): input_file=extract_process.stdout, environment={'PGSSLMODE': 'disable'}, working_directory=None, + borg_local_path='borg', ).and_yield().once() flexmock(module).should_receive('execute_command').with_args( ( @@ -1531,6 +1539,7 @@ def test_restore_data_source_dump_runs_non_default_pg_restore_and_psql(): input_file=extract_process.stdout, environment={'PGSSLMODE': 'disable'}, working_directory=None, + borg_local_path='borg', ).and_yield().once() flexmock(module).should_receive('execute_command').with_args( ( @@ -1621,6 +1630,7 @@ def test_restore_data_source_dump_without_extract_process_restores_from_disk(): input_file=None, environment={'PGSSLMODE': 'disable'}, working_directory=None, + borg_local_path='borg', ).and_yield().once() flexmock(module).should_receive('execute_command').with_args( ( @@ -1683,6 +1693,7 @@ def test_restore_data_source_dump_with_schemas_restores_schemas(): input_file=None, environment={'PGSSLMODE': 'disable'}, working_directory=None, + borg_local_path='borg', ).and_yield().once() flexmock(module).should_receive('execute_command').with_args( ( diff --git a/tests/unit/hooks/data_source/test_sqlite.py b/tests/unit/hooks/data_source/test_sqlite.py index fb132884..763ccac9 100644 --- a/tests/unit/hooks/data_source/test_sqlite.py +++ b/tests/unit/hooks/data_source/test_sqlite.py @@ -341,6 +341,7 @@ def test_restore_data_source_dump_restores_database(): output_log_level=logging.DEBUG, input_file=extract_process.stdout, working_directory=None, + borg_local_path='borg', ).and_yield().once() flexmock(module.os).should_receive('remove').once() @@ -379,6 +380,7 @@ def test_restore_data_source_dump_runs_non_default_sqlite_restores_database(): output_log_level=logging.DEBUG, input_file=extract_process.stdout, working_directory=None, + borg_local_path='borg', ).and_yield().once() flexmock(module.os).should_receive('remove').once() @@ -415,6 +417,7 @@ def test_restore_data_source_dump_with_connection_params_uses_connection_params_ output_log_level=logging.DEBUG, input_file=extract_process.stdout, working_directory=None, + borg_local_path='borg', ).and_yield().once() flexmock(module.os).should_receive('remove').once() @@ -451,6 +454,7 @@ def test_restore_data_source_dump_runs_non_default_sqlite_with_connection_params output_log_level=logging.DEBUG, input_file=extract_process.stdout, working_directory=None, + borg_local_path='borg', ).and_yield().once() flexmock(module.os).should_receive('remove').once() @@ -489,6 +493,7 @@ def test_restore_data_source_dump_without_connection_params_uses_restore_params_ output_log_level=logging.DEBUG, input_file=extract_process.stdout, working_directory=None, + borg_local_path='borg', ).and_yield().once() flexmock(module.os).should_receive('remove').once() @@ -526,6 +531,7 @@ def test_restore_data_source_dump_runs_non_default_sqlite_without_connection_par output_log_level=logging.DEBUG, input_file=extract_process.stdout, working_directory=None, + borg_local_path='borg', ).and_yield().once() flexmock(module.os).should_receive('remove').once() From c301858cca60544d9d4814b0901d4fe05745b9c5 Mon Sep 17 00:00:00 2001 From: Dan Helfman Date: Wed, 14 Jan 2026 21:59:36 -0800 Subject: [PATCH 7/9] MOAR --log-json. --- borgmatic/borg/repo_info.py | 3 ++- borgmatic/borg/version.py | 1 + tests/unit/borg/test_repo_info.py | 7 ++++--- tests/unit/borg/test_version.py | 20 +++++++++++++------- 4 files changed, 20 insertions(+), 11 deletions(-) diff --git a/borgmatic/borg/repo_info.py b/borgmatic/borg/repo_info.py index 42f3c466..ab66d99c 100644 --- a/borgmatic/borg/repo_info.py +++ b/borgmatic/borg/repo_info.py @@ -50,7 +50,8 @@ def display_repository_info( + flags.make_flags('remote-path', remote_path) + flags.make_flags('umask', config.get('umask')) + flags.make_flags('lock-wait', lock_wait) - + (('--json',) if repo_info_arguments.json else ('--log-json',)) + + ('--log-json',) + + (('--json',) if repo_info_arguments.json else ()) + (tuple(shlex.split(extra_borg_options)) if extra_borg_options else ()) + flags.make_repository_flags(repository_path, local_borg_version) ) diff --git a/borgmatic/borg/version.py b/borgmatic/borg/version.py index 67f7b002..6cd467f3 100644 --- a/borgmatic/borg/version.py +++ b/borgmatic/borg/version.py @@ -16,6 +16,7 @@ def local_borg_version(config, local_path='borg'): ''' full_command = ( (local_path, '--version') + + ('--log-json',) + (('--info',) if logger.getEffectiveLevel() == logging.INFO else ()) + (('--debug', '--show-rc') if logger.isEnabledFor(logging.DEBUG) else ()) ) diff --git a/tests/unit/borg/test_repo_info.py b/tests/unit/borg/test_repo_info.py index f542d456..09b5e1d0 100644 --- a/tests/unit/borg/test_repo_info.py +++ b/tests/unit/borg/test_repo_info.py @@ -141,7 +141,7 @@ def test_display_repository_info_with_log_info_and_json_suppresses_most_borg_out flexmock(module.environment).should_receive('make_environment') flexmock(module.borgmatic.config.paths).should_receive('get_working_directory').and_return(None) flexmock(module).should_receive('execute_command_and_capture_output').with_args( - ('borg', 'repo-info', '--json', '--repo', 'repo'), + ('borg', 'repo-info', '--log-json', '--json', '--repo', 'repo'), environment=None, working_directory=None, borg_local_path='borg', @@ -219,7 +219,7 @@ def test_display_repository_info_with_log_debug_and_json_suppresses_most_borg_ou flexmock(module.environment).should_receive('make_environment') flexmock(module.borgmatic.config.paths).should_receive('get_working_directory').and_return(None) flexmock(module).should_receive('execute_command_and_capture_output').with_args( - ('borg', 'repo-info', '--json', '--repo', 'repo'), + ('borg', 'repo-info', '--log-json', '--json', '--repo', 'repo'), environment=None, working_directory=None, borg_local_path='borg', @@ -255,7 +255,7 @@ def test_display_repository_info_with_json_calls_borg_with_json_flag(): flexmock(module.environment).should_receive('make_environment') flexmock(module.borgmatic.config.paths).should_receive('get_working_directory').and_return(None) flexmock(module).should_receive('execute_command_and_capture_output').with_args( - ('borg', 'repo-info', '--json', '--repo', 'repo'), + ('borg', 'repo-info', '--log-json', '--json', '--repo', 'repo'), environment=None, working_directory=None, borg_local_path='borg', @@ -542,6 +542,7 @@ def test_display_repository_info_with_feature_available_calls_borg_with_repo_inf '--log-json', '--extra', 'value with space', + '--log-json', '--json', '--repo', 'repo', diff --git a/tests/unit/borg/test_version.py b/tests/unit/borg/test_version.py index 7a1be8fa..f38d0592 100644 --- a/tests/unit/borg/test_version.py +++ b/tests/unit/borg/test_version.py @@ -31,14 +31,14 @@ def insert_execute_command_and_capture_output_mock( def test_local_borg_version_calls_borg_with_required_parameters(): - insert_execute_command_and_capture_output_mock(('borg', '--version')) + insert_execute_command_and_capture_output_mock(('borg', '--version', '--log-json')) flexmock(module.environment).should_receive('make_environment') assert module.local_borg_version({}) == VERSION def test_local_borg_version_with_log_info_calls_borg_with_info_parameter(): - insert_execute_command_and_capture_output_mock(('borg', '--version', '--info')) + insert_execute_command_and_capture_output_mock(('borg', '--version', '--log-json', '--info')) insert_logging_mock(logging.INFO) flexmock(module.environment).should_receive('make_environment') @@ -46,7 +46,9 @@ def test_local_borg_version_with_log_info_calls_borg_with_info_parameter(): def test_local_borg_version_with_log_debug_calls_borg_with_debug_parameters(): - insert_execute_command_and_capture_output_mock(('borg', '--version', '--debug', '--show-rc')) + insert_execute_command_and_capture_output_mock( + ('borg', '--version', '--log-json', '--debug', '--show-rc') + ) insert_logging_mock(logging.DEBUG) flexmock(module.environment).should_receive('make_environment') @@ -54,7 +56,9 @@ def test_local_borg_version_with_log_debug_calls_borg_with_debug_parameters(): def test_local_borg_version_with_local_borg_path_calls_borg_with_it(): - insert_execute_command_and_capture_output_mock(('borg1', '--version'), borg_local_path='borg1') + insert_execute_command_and_capture_output_mock( + ('borg1', '--version', '--log-json'), borg_local_path='borg1' + ) flexmock(module.environment).should_receive('make_environment') assert module.local_borg_version({}, 'borg1') == VERSION @@ -63,7 +67,7 @@ def test_local_borg_version_with_local_borg_path_calls_borg_with_it(): def test_local_borg_version_with_borg_exit_codes_calls_using_with_them(): borg_exit_codes = flexmock() insert_execute_command_and_capture_output_mock( - ('borg', '--version'), + ('borg', '--version', '--log-json'), borg_exit_codes=borg_exit_codes, ) flexmock(module.environment).should_receive('make_environment') @@ -72,7 +76,9 @@ def test_local_borg_version_with_borg_exit_codes_calls_using_with_them(): def test_local_borg_version_with_invalid_version_raises(): - insert_execute_command_and_capture_output_mock(('borg', '--version'), version_output='wtf') + insert_execute_command_and_capture_output_mock( + ('borg', '--version', '--log-json'), version_output='wtf' + ) flexmock(module.environment).should_receive('make_environment') with pytest.raises(ValueError): @@ -81,7 +87,7 @@ def test_local_borg_version_with_invalid_version_raises(): def test_local_borg_version_calls_borg_with_working_directory(): insert_execute_command_and_capture_output_mock( - ('borg', '--version'), + ('borg', '--version', '--log-json'), working_directory='/working/dir', ) flexmock(module.environment).should_receive('make_environment') From e39c503fb7bc9b2e1f0b5616094fe87342439e8b Mon Sep 17 00:00:00 2001 From: Dan Helfman Date: Wed, 14 Jan 2026 22:18:19 -0800 Subject: [PATCH 8/9] Add missing test coverage and fix log_outputs() variable use. --- borgmatic/execute.py | 4 +- tests/unit/actions/test_check.py | 86 ++++++++++++++++++++++++++++++++ 2 files changed, 88 insertions(+), 2 deletions(-) diff --git a/borgmatic/execute.py b/borgmatic/execute.py index 0e9d639b..34fdebbe 100644 --- a/borgmatic/execute.py +++ b/borgmatic/execute.py @@ -307,8 +307,8 @@ def log_outputs( # noqa: PLR0912 for output_buffer in output_buffers_for_process(process, exclude_stdouts): # Collect any straggling output lines that came in since we last gathered output. while output_buffer: # pragma: no cover - line = ready_buffer.readline().rstrip().decode() - if not line or not ready_process: + line = output_buffer.readline().rstrip().decode() + if not line: break log_record = handle_log_record( diff --git a/tests/unit/actions/test_check.py b/tests/unit/actions/test_check.py index df6cfc03..84111ac8 100644 --- a/tests/unit/actions/test_check.py +++ b/tests/unit/actions/test_check.py @@ -1029,6 +1029,92 @@ def test_compare_spot_check_hashes_returns_paths_having_failing_hashes(): ) == ('/bar',) +def test_compare_spot_check_hashes_handles_weird_backslashed_hashes_from_xxh64sum(): + 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_yield( + '\\hash1 /foo', + '\\hash2 /bar', + ) + flexmock(module.borgmatic.borg.list).should_receive('capture_archive_listing').and_yield( + {'xxh64': 'hash1', 'path': 'foo'}, + {'xxh64': 'nothash2', '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'), + ) == ('/bar',) + + +def test_compare_spot_check_hashes_handles_incorrect_path_names_from_xxh64sum(): + 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_yield( + 'hash1 /foo/wrong/path', + 'hash2 /bar/wrong/path', + ) + flexmock(module.borgmatic.borg.list).should_receive('capture_archive_listing').and_yield( + {'xxh64': 'hash1', 'path': 'foo'}, + {'xxh64': 'nothash2', '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'), + ) == ('/bar',) + + 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]), From 7e4a894cc47146091d8e8c5cca3ac5285643d1cc Mon Sep 17 00:00:00 2001 From: Dan Helfman Date: Wed, 14 Jan 2026 22:38:09 -0800 Subject: [PATCH 9/9] Prevent Borg error-level log about repo not existing when "borgmatic repo-create" probes for repo existence. --- borgmatic/borg/repo_info.py | 1 + tests/unit/borg/test_repo_info.py | 6 +++--- 2 files changed, 4 insertions(+), 3 deletions(-) diff --git a/borgmatic/borg/repo_info.py b/borgmatic/borg/repo_info.py index ab66d99c..9924aa8d 100644 --- a/borgmatic/borg/repo_info.py +++ b/borgmatic/borg/repo_info.py @@ -37,6 +37,7 @@ def display_repository_info( if feature.available(feature.Feature.REPO_INFO, local_borg_version) else ('info',) ) + + (('--critical',) if repo_info_arguments.json else ()) + ( ('--info',) if logger.getEffectiveLevel() == logging.INFO and not repo_info_arguments.json diff --git a/tests/unit/borg/test_repo_info.py b/tests/unit/borg/test_repo_info.py index 09b5e1d0..a85837ff 100644 --- a/tests/unit/borg/test_repo_info.py +++ b/tests/unit/borg/test_repo_info.py @@ -141,7 +141,7 @@ def test_display_repository_info_with_log_info_and_json_suppresses_most_borg_out flexmock(module.environment).should_receive('make_environment') flexmock(module.borgmatic.config.paths).should_receive('get_working_directory').and_return(None) flexmock(module).should_receive('execute_command_and_capture_output').with_args( - ('borg', 'repo-info', '--log-json', '--json', '--repo', 'repo'), + ('borg', 'repo-info', '--critical', '--log-json', '--json', '--repo', 'repo'), environment=None, working_directory=None, borg_local_path='borg', @@ -219,7 +219,7 @@ def test_display_repository_info_with_log_debug_and_json_suppresses_most_borg_ou flexmock(module.environment).should_receive('make_environment') flexmock(module.borgmatic.config.paths).should_receive('get_working_directory').and_return(None) flexmock(module).should_receive('execute_command_and_capture_output').with_args( - ('borg', 'repo-info', '--log-json', '--json', '--repo', 'repo'), + ('borg', 'repo-info', '--critical', '--log-json', '--json', '--repo', 'repo'), environment=None, working_directory=None, borg_local_path='borg', @@ -255,7 +255,7 @@ def test_display_repository_info_with_json_calls_borg_with_json_flag(): flexmock(module.environment).should_receive('make_environment') flexmock(module.borgmatic.config.paths).should_receive('get_working_directory').and_return(None) flexmock(module).should_receive('execute_command_and_capture_output').with_args( - ('borg', 'repo-info', '--log-json', '--json', '--repo', 'repo'), + ('borg', 'repo-info', '--critical', '--log-json', '--json', '--repo', 'repo'), environment=None, working_directory=None, borg_local_path='borg',