Improve performance of the "info" and "repo-list" actions by eliminating a second "borg info" call that supports a "no matching archives" warning (#1264).

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

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():

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

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

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

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