diff --git a/NEWS b/NEWS index 3ba2ff30..d109b1ad 100644 --- a/NEWS +++ b/NEWS @@ -4,6 +4,9 @@ * #1286: Fix a regression in which running borgmatic with no arguments and no configuration files doesn't error as expected. * #1257: Fix for the Loki monitoring hook not respecting the monitoring verbosity. + * #1264: Improve performance of the "info" and "repo-list" actions by eliminating a second "borg + info" call that supports a "no matching archives" warning. The warning still occurs; it's just + done now without the extra "borg info" call. * When Borg exits with a warning exit code, show a description of it, so you don't have to lookup the code. * Split out borgmatic installation documentation to its own page, so it's easier to find. diff --git a/borgmatic/borg/flags.py b/borgmatic/borg/flags.py index f83c4939..49717e95 100644 --- a/borgmatic/borg/flags.py +++ b/borgmatic/borg/flags.py @@ -1,5 +1,4 @@ import itertools -import json import logging import re @@ -135,27 +134,18 @@ def make_match_archives_flags( # noqa: PLR0911 return ('--glob-archives', f'{derived_match_archives}') -def warn_for_aggressive_archive_flags(json_command, json_output): +def warn_for_aggressive_archive_flags(command, output_lines): ''' - Given a JSON archives command and the resulting JSON string output from running it, parse the - JSON and warn if the command used an archive flag but the output indicates zero archives were - found. + Given an archives command and the resulting output lines from running it, warn if the command + used an archive flag but the output indicates zero archives were found. ''' - archive_flags_used = {'--glob-archives', '--match-archives'}.intersection(set(json_command)) - - if not archive_flags_used: - return - - try: - if len(json.loads(json_output)['archives']) == 0: - logger.warning('An archive filter was applied, but no matching archives were found.') - logger.warning( - 'Try adding --match-archives "*" or adjusting archive_name_format/match_archives in configuration.', - ) - except json.JSONDecodeError as error: - logger.debug(f'Cannot parse JSON output from archive command: {error}') - except (TypeError, KeyError): - logger.debug('Cannot parse JSON output from archive command: No "archives" key found') + if {'--glob-archives', '--match-archives'}.intersection(set(command)) and len( + tuple(line for line in output_lines if not line.startswith('terminating with ')) + ) == 0: + logger.warning('An archive filter was applied, but no matching archives were found.') + logger.warning( + 'Try adding --match-archives "*" or adjusting archive_name_format/match_archives in configuration.', + ) def omit_flag(arguments, flag): diff --git a/borgmatic/borg/info.py b/borgmatic/borg/info.py index 00cc253d..134d2f9c 100644 --- a/borgmatic/borg/info.py +++ b/borgmatic/borg/info.py @@ -5,7 +5,7 @@ import shlex import borgmatic.config.paths import borgmatic.logger from borgmatic.borg import environment, feature, flags -from borgmatic.execute import execute_command, execute_command_and_capture_output +from borgmatic.execute import execute_command_and_capture_output logger = logging.getLogger(__name__) @@ -103,9 +103,21 @@ def display_archives_info( borg_exit_codes = config.get('borg_exit_codes') working_directory = borgmatic.config.paths.get_working_directory(config) - json_info = '\n'.join( + if info_arguments.json: + return '\n'.join( + execute_command_and_capture_output( + json_command, + environment=environment.make_environment(config), + working_directory=working_directory, + borg_local_path=local_path, + borg_exit_codes=borg_exit_codes, + ) + ) + + output_lines = tuple( execute_command_and_capture_output( - json_command, + main_command, + output_log_level=logging.ANSWER, environment=environment.make_environment(config), working_directory=working_directory, borg_local_path=local_path, @@ -113,18 +125,6 @@ def display_archives_info( ) ) - if info_arguments.json: - return json_info - - flags.warn_for_aggressive_archive_flags(json_command, json_info) - - execute_command( - main_command, - output_log_level=logging.ANSWER, - environment=environment.make_environment(config), - working_directory=working_directory, - borg_local_path=local_path, - borg_exit_codes=borg_exit_codes, - ) + flags.warn_for_aggressive_archive_flags(main_command, output_lines) return None diff --git a/borgmatic/borg/repo_list.py b/borgmatic/borg/repo_list.py index 446aacad..72f095a0 100644 --- a/borgmatic/borg/repo_list.py +++ b/borgmatic/borg/repo_list.py @@ -6,7 +6,7 @@ import shlex import borgmatic.config.paths import borgmatic.logger from borgmatic.borg import environment, feature, flags -from borgmatic.execute import execute_command, execute_command_and_capture_output +from borgmatic.execute import execute_command_and_capture_output logger = logging.getLogger(__name__) @@ -219,9 +219,21 @@ def list_repository( working_directory = borgmatic.config.paths.get_working_directory(config) borg_exit_codes = config.get('borg_exit_codes') - json_listing = '\n'.join( + if repo_list_arguments.json: + return '\n'.join( + execute_command_and_capture_output( + json_command, + environment=environment.make_environment(config), + working_directory=working_directory, + borg_local_path=local_path, + borg_exit_codes=borg_exit_codes, + ) + ) + + output_lines = tuple( execute_command_and_capture_output( - json_command, + main_command, + output_log_level=logging.ANSWER, environment=environment.make_environment(config), working_directory=working_directory, borg_local_path=local_path, @@ -229,18 +241,6 @@ def list_repository( ) ) - if repo_list_arguments.json: - return json_listing - - flags.warn_for_aggressive_archive_flags(json_command, json_listing) - - execute_command( - main_command, - output_log_level=logging.ANSWER, - environment=environment.make_environment(config), - working_directory=working_directory, - borg_local_path=local_path, - borg_exit_codes=borg_exit_codes, - ) + flags.warn_for_aggressive_archive_flags(main_command, output_lines) return None diff --git a/borgmatic/execute.py b/borgmatic/execute.py index c3905ad0..a06c0cd3 100644 --- a/borgmatic/execute.py +++ b/borgmatic/execute.py @@ -314,8 +314,9 @@ def log_buffer_lines( ''' Given a dict from buffer object to Buffer_reader, a dict from subprocess.Popen() instance to Process_metadata instance, a requested output log level for stdout, Borg's local path, and - whether to capture stderr, read and log any ready output lines from the buffers. Additionally, - if the log level is None for any log record, then yield those log messages for capture. + whether to capture stderr, read and log any ready output lines from the buffers. Additionally, + for any log records with a log level that meets or exceeds the output log level, yield those log + messages for capture. This function just does one "turn of the crank" of logging buffer output. It is intended to be called repeatedly to continue to process buffers. @@ -365,7 +366,9 @@ def log_buffer_lines( last_lines=process_metadatas[reader.process].last_lines, ) - if log_record.levelno is None and process_metadatas[reader.process].capture: + if ( + log_record.levelno is None or log_record.levelno >= output_log_level + ) and process_metadatas[reader.process].capture: yield log_record.getMessage() @@ -424,8 +427,8 @@ def log_remaining_buffer_lines( Given a dict from buffer object to Buffer_reader, a dict from subprocess.Popen() instance to Process_metadata instance, a requested output log level for stdout, Borg's local path, and whether to capture stderr, drain and log any remaining output lines from the buffers until - they're empty. Additionally, if the log level is None for any log record, then yield those log - messages for capture. + they're empty. Additionally, for any log records with a log level that meets or exceeds the + output log level, yield those log messages for capture. ''' for output_buffer, reader in buffer_readers.items(): if not reader.process: @@ -445,7 +448,9 @@ def log_remaining_buffer_lines( ), ) - if log_record.levelno is None and process_metadatas[reader.process].capture: + if ( + log_record.levelno is None or log_record.levelno >= output_log_level + ) and process_metadatas[reader.process].capture: yield log_record.getMessage() @@ -628,6 +633,7 @@ def execute_command( def execute_command_and_capture_output( full_command, + output_log_level=None, input_file=None, capture_stderr=False, shell=False, @@ -642,13 +648,15 @@ def execute_command_and_capture_output( output (stdout) as a generator that yields one line at a time. The generator must be consumed in order for the called command to execute. - If an input file descriptor is given, then pipe it to the command's stdin. If capture stderr is - True, then capture stderr in addition to stdout. If shell is True, execute the command within a - shell. If an environment variables dict is given, then pass it into the command. If a working - directory is given, use that as the present working directory when running the command. If a - Borg local path is given, and the command matches it (regardless of arguments), treat exit code - 1 as a warning instead of an error. But if Borg exit codes are given as a sequence of exit code - configuration dicts, then use that configuration to decide what's an error and what's a warning. + If an output log level is given, then instead of suppressing log output, also output the + captured lines at the given log level. If an input file descriptor is given, then pipe it to + the command's stdin. If capture stderr is True, then capture stderr in addition to stdout. If + shell is True, execute the command within a shell. If an environment variables dict is given, + then pass it into the command. If a working directory is given, use that as the present working + directory when running the command. If a Borg local path is given, and the command matches it + (regardless of arguments), treat exit code 1 as a warning instead of an error. But if Borg exit + codes are given as a sequence of exit code configuration dicts, then use that configuration to + decide what's an error and what's a warning. Raise subprocesses.CalledProcessError if an error occurs while running the command. ''' @@ -684,7 +692,7 @@ def execute_command_and_capture_output( yield from log_outputs( (process,), (input_file,), - None, + output_log_level, borg_local_path, borg_exit_codes, capture_stderr=capture_stderr, diff --git a/tests/integration/borg/test_commands.py b/tests/integration/borg/test_commands.py index 513ab680..6280790c 100644 --- a/tests/integration/borg/test_commands.py +++ b/tests/integration/borg/test_commands.py @@ -35,7 +35,7 @@ def assert_command_does_not_duplicate_flags(command, *args, **kwargs): if '--json' in command: return '{}' - return None + return '' def fuzz_argument(arguments, argument_name): @@ -159,10 +159,7 @@ def test_make_repo_list_command_does_not_duplicate_flags_or_raise(): def test_display_archives_info_command_does_not_duplicate_flags_or_raise(): arguments = borgmatic.commands.arguments.parse_arguments({}, 'info')['info'] flexmock(borgmatic.borg.info).should_receive('execute_command_and_capture_output').replace_with( - assert_command_does_not_duplicate_flags, - ) - flexmock(borgmatic.borg.info).should_receive('execute_command').replace_with( - assert_command_does_not_duplicate_flags, + lambda command, *args, **kwargs: iter((assert_command_does_not_duplicate_flags(command),)), ) for argument_name in dir(arguments): diff --git a/tests/integration/test_execute.py b/tests/integration/test_execute.py index cbf42f58..e14165e9 100644 --- a/tests/integration/test_execute.py +++ b/tests/integration/test_execute.py @@ -105,18 +105,15 @@ def test_log_outputs_logs_each_line_separately(): (), ).and_return((there_process.stdout,)) - assert ( - tuple( - module.log_outputs( - (hi_process, there_process), - exclude_stdouts=(), - output_log_level=logging.INFO, - borg_local_path='borg', - borg_exit_codes=None, - ) + assert tuple( + module.log_outputs( + (hi_process, there_process), + exclude_stdouts=(), + output_log_level=logging.INFO, + borg_local_path='borg', + borg_exit_codes=None, ) - == () - ) + ) == ('there',) def test_log_outputs_logs_stderr_as_error(): @@ -140,18 +137,15 @@ def test_log_outputs_logs_stderr_as_error(): (), ).and_return((echo_process.stdout, echo_process.stderr)) - assert ( - tuple( - module.log_outputs( - (echo_process,), - exclude_stdouts=(), - output_log_level=logging.INFO, - borg_local_path='borg', - borg_exit_codes=None, - ) + assert tuple( + module.log_outputs( + (echo_process,), + exclude_stdouts=(), + output_log_level=logging.INFO, + borg_local_path='borg', + borg_exit_codes=None, ) - == () - ) + ) == ('error',) def test_log_outputs_skips_logs_for_process_with_none_stdout(): @@ -180,18 +174,15 @@ def test_log_outputs_skips_logs_for_process_with_none_stdout(): (), ).and_return((there_process.stdout,)) - assert ( - tuple( - module.log_outputs( - (hi_process, there_process), - exclude_stdouts=(), - output_log_level=logging.INFO, - borg_local_path='borg', - borg_exit_codes=None, - ) + assert tuple( + module.log_outputs( + (hi_process, there_process), + exclude_stdouts=(), + output_log_level=logging.INFO, + borg_local_path='borg', + borg_exit_codes=None, ) - == () - ) + ) == ('there',) def test_log_outputs_returns_output_without_logging_for_output_log_level_none(): diff --git a/tests/unit/borg/test_flags.py b/tests/unit/borg/test_flags.py index c2130eb1..9d8e8da3 100644 --- a/tests/unit/borg/test_flags.py +++ b/tests/unit/borg/test_flags.py @@ -246,10 +246,10 @@ def test_make_match_archives_flags_accepts_default_archive_name_format(): ) -def test_warn_for_aggressive_archive_flags_without_archive_flags_bails(): +def test_warn_for_aggressive_archive_flags_without_archive_flags_does_not_warn(): flexmock(module.logger).should_receive('warning').never() - module.warn_for_aggressive_archive_flags(('borg', '--do-stuff'), '{}') + module.warn_for_aggressive_archive_flags(('borg', '--do-stuff'), ()) def test_warn_for_aggressive_archive_flags_with_glob_archives_and_zero_archives_warns(): @@ -257,7 +257,7 @@ def test_warn_for_aggressive_archive_flags_with_glob_archives_and_zero_archives_ module.warn_for_aggressive_archive_flags( ('borg', '--glob-archives', 'foo*'), - '{"archives": []}', + (), ) @@ -266,7 +266,16 @@ def test_warn_for_aggressive_archive_flags_with_match_archives_and_zero_archives module.warn_for_aggressive_archive_flags( ('borg', '--match-archives', 'foo*'), - '{"archives": []}', + (), + ) + + +def test_warn_for_aggressive_archive_flags_with_match_archives_and_just_exit_code_warns(): + flexmock(module.logger).should_receive('warning').twice() + + module.warn_for_aggressive_archive_flags( + ('borg', '--match-archives', 'foo*'), + ('terminating with success status, rc 0',), ) @@ -275,7 +284,7 @@ def test_warn_for_aggressive_archive_flags_with_glob_archives_and_one_archive_do module.warn_for_aggressive_archive_flags( ('borg', '--glob-archives', 'foo*'), - '{"archives": [{"name": "foo"]}', + ('this is an archive line',), ) @@ -284,22 +293,10 @@ def test_warn_for_aggressive_archive_flags_with_match_archives_and_one_archive_d module.warn_for_aggressive_archive_flags( ('borg', '--match-archives', 'foo*'), - '{"archives": [{"name": "foo"]}', + ('this is an archive line',), ) -def test_warn_for_aggressive_archive_flags_with_glob_archives_and_invalid_json_does_not_warn(): - flexmock(module.logger).should_receive('warning').never() - - module.warn_for_aggressive_archive_flags(('borg', '--glob-archives', 'foo*'), '{"archives": [}') - - -def test_warn_for_aggressive_archive_flags_with_glob_archives_and_json_missing_archives_does_not_warn(): - flexmock(module.logger).should_receive('warning').never() - - module.warn_for_aggressive_archive_flags(('borg', '--glob-archives', 'foo*'), '{}') - - def test_omit_flag_removes_flag_from_arguments(): assert module.omit_flag(('borg', 'create', '--flag', '--other'), '--flag') == ( 'borg', diff --git a/tests/unit/borg/test_info.py b/tests/unit/borg/test_info.py index ff11b472..eb34b6a3 100644 --- a/tests/unit/borg/test_info.py +++ b/tests/unit/borg/test_info.py @@ -565,15 +565,14 @@ def test_make_info_command_with_date_based_matching_passes_through_to_command(): ) -def test_display_archives_info_calls_two_commands(): +def test_display_archives_info_calls_borg_command(): flexmock(module.borgmatic.logger).should_receive('add_custom_log_levels') flexmock(module.logging).ANSWER = module.borgmatic.logger.ANSWER flexmock(module).should_receive('make_info_command') 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().once() + flexmock(module).should_receive('execute_command_and_capture_output').and_yield('').once() flexmock(module.flags).should_receive('warn_for_aggressive_archive_flags') - flexmock(module).should_receive('execute_command').once() module.display_archives_info( repository_path='repo', @@ -592,7 +591,6 @@ def test_display_archives_info_with_json_calls_json_command_only(): 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.flags).should_receive('warn_for_aggressive_archive_flags').never() - flexmock(module).should_receive('execute_command').never() assert ( module.display_archives_info( @@ -616,20 +614,13 @@ def test_display_archives_info_calls_borg_with_working_directory(): ) flexmock(module).should_receive('execute_command_and_capture_output').with_args( full_command=object, + output_log_level=int, environment=object, working_directory='/working/dir', borg_local_path=object, borg_exit_codes=object, - ).and_yield().once() + ).and_yield('').once() flexmock(module.flags).should_receive('warn_for_aggressive_archive_flags') - flexmock(module).should_receive('execute_command').with_args( - full_command=object, - output_log_level=object, - environment=object, - working_directory='/working/dir', - borg_local_path=object, - borg_exit_codes=object, - ).once() module.display_archives_info( repository_path='repo', diff --git a/tests/unit/borg/test_repo_list.py b/tests/unit/borg/test_repo_list.py index 6944a0b7..5da6aa18 100644 --- a/tests/unit/borg/test_repo_list.py +++ b/tests/unit/borg/test_repo_list.py @@ -1108,7 +1108,7 @@ def test_make_repo_list_command_with_match_archives_calls_borg_with_match_archiv assert command == ('borg', 'list', '--log-json', '--match-archives', 'foo-*', 'repo') -def test_list_repository_calls_two_commands(): +def test_list_repository_calls_borg_command(): flexmock(module.borgmatic.logger).should_receive('add_custom_log_levels') flexmock(module.logging).ANSWER = module.borgmatic.logger.ANSWER flexmock(module).should_receive('make_repo_list_command') @@ -1116,7 +1116,6 @@ def test_list_repository_calls_two_commands(): flexmock(module.borgmatic.config.paths).should_receive('get_working_directory').and_return(None) flexmock(module).should_receive('execute_command_and_capture_output').and_yield('').once() flexmock(module.flags).should_receive('warn_for_aggressive_archive_flags') - flexmock(module).should_receive('execute_command').once() module.list_repository( repository_path='repo', @@ -1127,14 +1126,13 @@ def test_list_repository_calls_two_commands(): ) -def test_list_repository_with_json_calls_json_command_only(): +def test_list_repository_with_json_calls_borg_json_command_only(): flexmock(module.borgmatic.logger).should_receive('add_custom_log_levels') flexmock(module).should_receive('make_repo_list_command') 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.flags).should_receive('warn_for_aggressive_archive_flags').never() - flexmock(module).should_receive('execute_command').never() assert ( module.list_repository( @@ -1206,20 +1204,13 @@ def test_list_repository_calls_borg_with_working_directory(): ) flexmock(module).should_receive('execute_command_and_capture_output').with_args( full_command=object, + output_log_level=int, environment=object, working_directory='/working/dir', borg_local_path=object, borg_exit_codes=object, ).and_yield('').once() flexmock(module.flags).should_receive('warn_for_aggressive_archive_flags') - flexmock(module).should_receive('execute_command').with_args( - full_command=object, - output_log_level=object, - environment=object, - working_directory='/working/dir', - borg_local_path=object, - borg_exit_codes=object, - ).once() module.list_repository( repository_path='repo', diff --git a/tests/unit/test_execute.py b/tests/unit/test_execute.py index af02aeb3..00436e8e 100644 --- a/tests/unit/test_execute.py +++ b/tests/unit/test_execute.py @@ -403,7 +403,7 @@ def test_log_buffer_lines_with_ready_buffer_and_running_process_handles_each_log module.log_buffer_lines( buffer_readers=buffer_readers, process_metadatas=process_metadatas, - output_log_level=flexmock(), + output_log_level=module.logging.INFO, borg_local_path=flexmock(), ) ) @@ -435,7 +435,7 @@ def test_log_buffer_lines_with_ready_buffer_and_capture_process_yields_each_line ) == ('message', 'message') -def test_log_buffer_lines_with_ready_buffer_and_log_level_and_capture_process_does_not_yield_each_line(): +def test_log_buffer_lines_with_ready_buffer_and_same_log_level_and_capture_process_yields_each_line(): process = flexmock(poll=lambda: None, stderr=flexmock(), args=flexmock()) buffer_readers = { flexmock(): module.Buffer_reader(lines=iter((('hi', 'there'),)), process=process) @@ -446,7 +446,31 @@ def test_log_buffer_lines_with_ready_buffer_and_log_level_and_capture_process_do ).and_return(list(buffer_readers.keys()), [], []) flexmock(module).should_receive('parse_log_line').and_return(flexmock()) flexmock(module).should_receive('handle_log_record').and_return( - flexmock(levelno=10, getMessage=lambda: 'message') + flexmock(levelno=module.logging.INFO, getMessage=lambda: 'message') + ).twice() + + assert tuple( + module.log_buffer_lines( + buffer_readers=buffer_readers, + process_metadatas=process_metadatas, + output_log_level=module.logging.INFO, + borg_local_path=flexmock(), + ) + ) == ('message', 'message') + + +def test_log_buffer_lines_with_ready_buffer_and_higher_log_level_and_capture_process_does_not_yield_each_line(): + process = flexmock(poll=lambda: None, stderr=flexmock(), args=flexmock()) + buffer_readers = { + flexmock(): module.Buffer_reader(lines=iter((('hi', 'there'),)), process=process) + } + process_metadatas = {process: module.Process_metadata(last_lines=[], capture=True)} + flexmock(module.select).should_receive('select').with_args( + buffer_readers.keys(), [], [] + ).and_return(list(buffer_readers.keys()), [], []) + flexmock(module).should_receive('parse_log_line').and_return(flexmock()) + flexmock(module).should_receive('handle_log_record').and_return( + flexmock(levelno=module.logging.DEBUG, getMessage=lambda: 'message') ).twice() assert ( @@ -454,7 +478,7 @@ def test_log_buffer_lines_with_ready_buffer_and_log_level_and_capture_process_do module.log_buffer_lines( buffer_readers=buffer_readers, process_metadatas=process_metadatas, - output_log_level=flexmock(), + output_log_level=module.logging.INFO, borg_local_path=flexmock(), ) ) @@ -462,6 +486,30 @@ def test_log_buffer_lines_with_ready_buffer_and_log_level_and_capture_process_do ) +def test_log_buffer_lines_with_ready_buffer_and_lower_log_level_and_capture_process_yields_each_line(): + process = flexmock(poll=lambda: None, stderr=flexmock(), args=flexmock()) + buffer_readers = { + flexmock(): module.Buffer_reader(lines=iter((('hi', 'there'),)), process=process) + } + process_metadatas = {process: module.Process_metadata(last_lines=[], capture=True)} + flexmock(module.select).should_receive('select').with_args( + buffer_readers.keys(), [], [] + ).and_return(list(buffer_readers.keys()), [], []) + flexmock(module).should_receive('parse_log_line').and_return(flexmock()) + flexmock(module).should_receive('handle_log_record').and_return( + flexmock(levelno=module.logging.ERROR, getMessage=lambda: 'message') + ).twice() + + assert tuple( + module.log_buffer_lines( + buffer_readers=buffer_readers, + process_metadatas=process_metadatas, + output_log_level=module.logging.INFO, + borg_local_path=flexmock(), + ) + ) == ('message', 'message') + + def test_log_buffer_lines_with_ready_buffer_and_finished_process_vents_other_processes(): process_stdout = flexmock() process = flexmock(poll=lambda: 0, stdout=process_stdout, stderr=flexmock(), args=flexmock()) @@ -485,7 +533,7 @@ def test_log_buffer_lines_with_ready_buffer_and_finished_process_vents_other_pro module.log_buffer_lines( buffer_readers=buffer_readers, process_metadatas=process_metadatas, - output_log_level=flexmock(), + output_log_level=module.logging.INFO, borg_local_path=flexmock(), ) ) @@ -522,7 +570,7 @@ def test_log_buffer_lines_with_ready_buffer_and_finished_process_does_not_vent_o module.log_buffer_lines( buffer_readers=buffer_readers, process_metadatas=process_metadatas, - output_log_level=flexmock(), + output_log_level=module.logging.INFO, borg_local_path=flexmock(), ) ) @@ -548,7 +596,7 @@ def test_log_buffer_lines_with_ready_eof_buffer_and_running_process_skips_it(): module.log_buffer_lines( buffer_readers=buffer_readers, process_metadatas=process_metadatas, - output_log_level=flexmock(), + output_log_level=module.logging.INFO, borg_local_path=flexmock(), ) ) @@ -571,7 +619,7 @@ def test_log_buffer_lines_with_ready_buffer_with_empty_line_skips_it(): module.log_buffer_lines( buffer_readers=buffer_readers, process_metadatas=process_metadatas, - output_log_level=flexmock(), + output_log_level=module.logging.INFO, borg_local_path=flexmock(), ) ) @@ -601,7 +649,7 @@ def test_log_buffer_lines_with_multiple_ready_buffers_and_running_processes_hand module.log_buffer_lines( buffer_readers=buffer_readers, process_metadatas=process_metadatas, - output_log_level=flexmock(), + output_log_level=module.logging.INFO, borg_local_path=flexmock(), ) ) @@ -629,7 +677,7 @@ def test_log_buffer_lines_with_multiple_ready_buffers_from_same_running_process_ module.log_buffer_lines( buffer_readers=buffer_readers, process_metadatas=process_metadatas, - output_log_level=flexmock(), + output_log_level=module.logging.INFO, borg_local_path=flexmock(), ) ) @@ -657,7 +705,7 @@ def test_log_buffer_lines_with_ready_stderr_buffer_and_running_process_elevates_ module.log_buffer_lines( buffer_readers=buffer_readers, process_metadatas=process_metadatas, - output_log_level=flexmock(), + output_log_level=module.logging.INFO, borg_local_path=flexmock(), ) ) @@ -685,7 +733,7 @@ def test_log_buffer_lines_with_ready_stdout_buffer_and_running_process_does_not_ module.log_buffer_lines( buffer_readers=buffer_readers, process_metadatas=process_metadatas, - output_log_level=flexmock(), + output_log_level=module.logging.INFO, borg_local_path=flexmock(), ) ) @@ -713,7 +761,7 @@ def test_log_buffer_lines_with_ready_stderr_buffer_and_capture_stderr_does_not_e module.log_buffer_lines( buffer_readers=buffer_readers, process_metadatas=process_metadatas, - output_log_level=flexmock(), + output_log_level=module.logging.INFO, borg_local_path=flexmock(), capture_stderr=True, ) @@ -993,7 +1041,7 @@ def test_log_remaining_buffer_lines_without_reader_process_bails(): module.log_remaining_buffer_lines( buffer_readers, process_metadatas, - output_log_level=flexmock(), + output_log_level=module.logging.INFO, borg_local_path=flexmock(), ) ) @@ -1020,7 +1068,7 @@ def test_log_remaining_buffer_lines_logs_each_line(): module.log_remaining_buffer_lines( buffer_readers, process_metadatas, - output_log_level=flexmock(), + output_log_level=module.logging.INFO, borg_local_path=flexmock(), ) ) @@ -1051,7 +1099,7 @@ def test_log_remaining_buffer_lines_with_multiple_buffers_logs_lines_from_each() module.log_remaining_buffer_lines( buffer_readers, process_metadatas, - output_log_level=flexmock(), + output_log_level=module.logging.INFO, borg_local_path=flexmock(), ) ) @@ -1086,7 +1134,7 @@ def test_log_remaining_buffer_lines_with_stderr_buffer_elevates_stderr(): module.log_remaining_buffer_lines( buffer_readers, process_metadatas, - output_log_level=flexmock(), + output_log_level=module.logging.INFO, borg_local_path=flexmock(), ) ) @@ -1118,7 +1166,7 @@ def test_log_remaining_buffer_lines_with_stderr_buffer_and_capture_stderr_does_n module.log_remaining_buffer_lines( buffer_readers, process_metadatas, - output_log_level=flexmock(), + output_log_level=module.logging.INFO, borg_local_path=flexmock(), capture_stderr=True, ) @@ -1147,13 +1195,13 @@ def test_log_remaining_buffer_lines_with_capture_process_yields_each_line(): module.log_remaining_buffer_lines( buffer_readers, process_metadatas, - output_log_level=flexmock(), + output_log_level=module.logging.INFO, borg_local_path=flexmock(), ) ) == ('message', 'message') -def test_log_remaining_buffer_lines_with_log_level_and_capture_process_does_not_yield_each_line(): +def test_log_remaining_buffer_lines_with_same_log_level_and_capture_process_yields_each_line(): process = flexmock(stderr=flexmock(), args=flexmock()) buffer_readers = { flexmock(): module.Buffer_reader( @@ -1166,7 +1214,33 @@ def test_log_remaining_buffer_lines_with_log_level_and_capture_process_does_not_ line=str, log_level=object, elevate_stderr=False, borg_local_path=object, command=object ).and_return(flexmock()).twice() flexmock(module).should_receive('handle_log_record').and_return( - flexmock(levelno=10, getMessage=lambda: 'message') + flexmock(levelno=module.logging.INFO, getMessage=lambda: 'message') + ).twice() + + assert tuple( + module.log_remaining_buffer_lines( + buffer_readers, + process_metadatas, + output_log_level=module.logging.INFO, + borg_local_path=flexmock(), + ) + ) == ('message', 'message') + + +def test_log_remaining_buffer_lines_with_higher_log_level_and_capture_process_does_not_yield_each_line(): + process = flexmock(stderr=flexmock(), args=flexmock()) + buffer_readers = { + flexmock(): module.Buffer_reader( + lines=(('hi', 'there'),), + process=process, + ) + } + process_metadatas = {process: module.Process_metadata(last_lines=[], capture=True)} + flexmock(module).should_receive('parse_log_line').with_args( + line=str, log_level=object, elevate_stderr=False, borg_local_path=object, command=object + ).and_return(flexmock()).twice() + flexmock(module).should_receive('handle_log_record').and_return( + flexmock(levelno=module.logging.DEBUG, getMessage=lambda: 'message') ).twice() assert ( @@ -1174,7 +1248,7 @@ def test_log_remaining_buffer_lines_with_log_level_and_capture_process_does_not_ module.log_remaining_buffer_lines( buffer_readers, process_metadatas, - output_log_level=flexmock(), + output_log_level=module.logging.INFO, borg_local_path=flexmock(), ) ) @@ -1182,6 +1256,32 @@ def test_log_remaining_buffer_lines_with_log_level_and_capture_process_does_not_ ) +def test_log_remaining_buffer_lines_with_lower_log_level_and_capture_process_does_yields_each_line(): + process = flexmock(stderr=flexmock(), args=flexmock()) + buffer_readers = { + flexmock(): module.Buffer_reader( + lines=(('hi', 'there'),), + process=process, + ) + } + process_metadatas = {process: module.Process_metadata(last_lines=[], capture=True)} + flexmock(module).should_receive('parse_log_line').with_args( + line=str, log_level=object, elevate_stderr=False, borg_local_path=object, command=object + ).and_return(flexmock()).twice() + flexmock(module).should_receive('handle_log_record').and_return( + flexmock(levelno=module.logging.ERROR, getMessage=lambda: 'message') + ).twice() + + assert tuple( + module.log_remaining_buffer_lines( + buffer_readers, + process_metadatas, + output_log_level=module.logging.INFO, + borg_local_path=flexmock(), + ) + ) == ('message', 'message') + + def test_mask_command_secrets_masks_password_flag_value(): assert module.mask_command_secrets(('cooldb', '--username', 'bob', '--password', 'pass')) == ( 'cooldb',