From 0406d18cfd048f93f455b9c3006326b2825f2d24 Mon Sep 17 00:00:00 2001 From: Dan Helfman Date: Wed, 12 Jun 2019 11:49:35 -0700 Subject: [PATCH] Log Borg --stats output as warning so it shows up at any verbosity level. --- borgmatic/borg/create.py | 2 +- borgmatic/borg/execute.py | 14 ++-- tests/unit/borg/test_create.py | 123 +++++++++++++++++++++++++------- tests/unit/borg/test_execute.py | 4 +- 4 files changed, 110 insertions(+), 33 deletions(-) diff --git a/borgmatic/borg/create.py b/borgmatic/borg/create.py index e4924c367..80665ca0b 100644 --- a/borgmatic/borg/create.py +++ b/borgmatic/borg/create.py @@ -162,4 +162,4 @@ def create_archive( + (('--json',) if json else ()) ) - return execute_command(full_command, capture_output=json) + return execute_command(full_command, capture_output=json, output_as_warning=stats and not json) diff --git a/borgmatic/borg/execute.py b/borgmatic/borg/execute.py index e9d255a0c..fb9319eae 100644 --- a/borgmatic/borg/execute.py +++ b/borgmatic/borg/execute.py @@ -5,24 +5,28 @@ from borgmatic.logger import get_logger logger = get_logger(__name__) -def execute_and_log_output(full_command): +def execute_and_log_output(full_command, output_as_warning=False): process = subprocess.Popen(full_command, stdout=None, stderr=subprocess.PIPE) while process.poll() is None: line = process.stderr.readline().rstrip().decode() if line.startswith('borg: error:'): logger.error(line) + elif output_as_warning: + logger.warning(line) else: logger.info(line) - logger.info(process.stderr.read().rstrip().decode()) - exit_code = process.poll() + remaining_output = process.stderr.read().rstrip().decode() + if remaining_output: + logger.info(remaining_output) + exit_code = process.poll() if exit_code != 0: raise subprocess.CalledProcessError(exit_code, full_command) -def execute_command(full_command, capture_output=False): +def execute_command(full_command, capture_output=False, output_as_warning=False): ''' Execute the given command (a sequence of command/argument strings). If capture output is True, then return the command's output as a string. @@ -33,4 +37,4 @@ def execute_command(full_command, capture_output=False): output = subprocess.check_output(full_command) return output.decode() if output is not None else None else: - execute_and_log_output(full_command) + execute_and_log_output(full_command, output_as_warning) diff --git a/tests/unit/borg/test_create.py b/tests/unit/borg/test_create.py index cf6cca659..bb13d75e3 100644 --- a/tests/unit/borg/test_create.py +++ b/tests/unit/borg/test_create.py @@ -166,7 +166,7 @@ def test_create_archive_calls_borg_with_parameters(): flexmock(module).should_receive('_make_pattern_flags').and_return(()) flexmock(module).should_receive('_make_exclude_flags').and_return(()) flexmock(module).should_receive('execute_command').with_args( - CREATE_COMMAND, capture_output=False + CREATE_COMMAND, capture_output=False, output_as_warning=False ) module.create_archive( @@ -191,7 +191,7 @@ def test_create_archive_with_patterns_calls_borg_with_patterns(): flexmock(module).should_receive('_make_pattern_flags').and_return(pattern_flags) flexmock(module).should_receive('_make_exclude_flags').and_return(()) flexmock(module).should_receive('execute_command').with_args( - CREATE_COMMAND + pattern_flags, capture_output=False + CREATE_COMMAND + pattern_flags, capture_output=False, output_as_warning=False ) module.create_archive( @@ -216,7 +216,7 @@ def test_create_archive_with_exclude_patterns_calls_borg_with_excludes(): flexmock(module).should_receive('_make_pattern_flags').and_return(()) flexmock(module).should_receive('_make_exclude_flags').and_return(exclude_flags) flexmock(module).should_receive('execute_command').with_args( - CREATE_COMMAND + exclude_flags, capture_output=False + CREATE_COMMAND + exclude_flags, capture_output=False, output_as_warning=False ) module.create_archive( @@ -239,7 +239,9 @@ def test_create_archive_with_log_info_calls_borg_with_info_parameter(): flexmock(module).should_receive('_make_pattern_flags').and_return(()) flexmock(module).should_receive('_make_exclude_flags').and_return(()) flexmock(module).should_receive('execute_command').with_args( - CREATE_COMMAND + ('--list', '--filter', 'AME-', '--info', '--stats'), capture_output=False + CREATE_COMMAND + ('--list', '--filter', 'AME-', '--info', '--stats'), + capture_output=False, + output_as_warning=False, ) insert_logging_mock(logging.INFO) @@ -263,7 +265,7 @@ def test_create_archive_with_log_info_and_json_suppresses_most_borg_output(): flexmock(module).should_receive('_make_pattern_flags').and_return(()) flexmock(module).should_receive('_make_exclude_flags').and_return(()) flexmock(module).should_receive('execute_command').with_args( - CREATE_COMMAND + ('--json',), capture_output=True + CREATE_COMMAND + ('--json',), capture_output=True, output_as_warning=False ) insert_logging_mock(logging.INFO) @@ -289,6 +291,7 @@ def test_create_archive_with_log_debug_calls_borg_with_debug_parameter(): flexmock(module).should_receive('execute_command').with_args( CREATE_COMMAND + ('--list', '--filter', 'AME-', '--stats', '--debug', '--show-rc'), capture_output=False, + output_as_warning=False, ) insert_logging_mock(logging.DEBUG) @@ -311,7 +314,7 @@ def test_create_archive_with_log_debug_and_json_suppresses_most_borg_output(): flexmock(module).should_receive('_make_pattern_flags').and_return(()) flexmock(module).should_receive('_make_exclude_flags').and_return(()) flexmock(module).should_receive('execute_command').with_args( - CREATE_COMMAND + ('--json',), capture_output=True + CREATE_COMMAND + ('--json',), capture_output=True, output_as_warning=False ) insert_logging_mock(logging.DEBUG) @@ -336,7 +339,7 @@ def test_create_archive_with_dry_run_calls_borg_with_dry_run_parameter(): flexmock(module).should_receive('_make_pattern_flags').and_return(()) flexmock(module).should_receive('_make_exclude_flags').and_return(()) flexmock(module).should_receive('execute_command').with_args( - CREATE_COMMAND + ('--dry-run',), capture_output=False + CREATE_COMMAND + ('--dry-run',), capture_output=False, output_as_warning=False ) module.create_archive( @@ -361,7 +364,9 @@ def test_create_archive_with_dry_run_and_log_info_calls_borg_without_stats_param flexmock(module).should_receive('_make_pattern_flags').and_return(()) flexmock(module).should_receive('_make_exclude_flags').and_return(()) flexmock(module).should_receive('execute_command').with_args( - CREATE_COMMAND + ('--list', '--filter', 'AME-', '--info', '--dry-run'), capture_output=False + CREATE_COMMAND + ('--list', '--filter', 'AME-', '--info', '--dry-run'), + capture_output=False, + output_as_warning=False, ) insert_logging_mock(logging.INFO) @@ -389,6 +394,7 @@ def test_create_archive_with_dry_run_and_log_debug_calls_borg_without_stats_para flexmock(module).should_receive('execute_command').with_args( CREATE_COMMAND + ('--list', '--filter', 'AME-', '--debug', '--show-rc', '--dry-run'), capture_output=False, + output_as_warning=False, ) insert_logging_mock(logging.DEBUG) @@ -411,7 +417,9 @@ def test_create_archive_with_checkpoint_interval_calls_borg_with_checkpoint_inte flexmock(module).should_receive('_make_pattern_flags').and_return(()) flexmock(module).should_receive('_make_exclude_flags').and_return(()) flexmock(module).should_receive('execute_command').with_args( - CREATE_COMMAND + ('--checkpoint-interval', '600'), capture_output=False + CREATE_COMMAND + ('--checkpoint-interval', '600'), + capture_output=False, + output_as_warning=False, ) module.create_archive( @@ -433,7 +441,9 @@ def test_create_archive_with_chunker_params_calls_borg_with_chunker_params_param flexmock(module).should_receive('_make_pattern_flags').and_return(()) flexmock(module).should_receive('_make_exclude_flags').and_return(()) flexmock(module).should_receive('execute_command').with_args( - CREATE_COMMAND + ('--chunker-params', '1,2,3,4'), capture_output=False + CREATE_COMMAND + ('--chunker-params', '1,2,3,4'), + capture_output=False, + output_as_warning=False, ) module.create_archive( @@ -455,7 +465,7 @@ def test_create_archive_with_compression_calls_borg_with_compression_parameters( flexmock(module).should_receive('_make_pattern_flags').and_return(()) flexmock(module).should_receive('_make_exclude_flags').and_return(()) flexmock(module).should_receive('execute_command').with_args( - CREATE_COMMAND + ('--compression', 'rle'), capture_output=False + CREATE_COMMAND + ('--compression', 'rle'), capture_output=False, output_as_warning=False ) module.create_archive( @@ -477,7 +487,9 @@ def test_create_archive_with_remote_rate_limit_calls_borg_with_remote_ratelimit_ flexmock(module).should_receive('_make_pattern_flags').and_return(()) flexmock(module).should_receive('_make_exclude_flags').and_return(()) flexmock(module).should_receive('execute_command').with_args( - CREATE_COMMAND + ('--remote-ratelimit', '100'), capture_output=False + CREATE_COMMAND + ('--remote-ratelimit', '100'), + capture_output=False, + output_as_warning=False, ) module.create_archive( @@ -499,7 +511,7 @@ def test_create_archive_with_one_file_system_calls_borg_with_one_file_system_par flexmock(module).should_receive('_make_pattern_flags').and_return(()) flexmock(module).should_receive('_make_exclude_flags').and_return(()) flexmock(module).should_receive('execute_command').with_args( - CREATE_COMMAND + ('--one-file-system',), capture_output=False + CREATE_COMMAND + ('--one-file-system',), capture_output=False, output_as_warning=False ) module.create_archive( @@ -522,7 +534,7 @@ def test_create_archive_with_numeric_owner_calls_borg_with_numeric_owner_paramet flexmock(module).should_receive('_make_pattern_flags').and_return(()) flexmock(module).should_receive('_make_exclude_flags').and_return(()) flexmock(module).should_receive('execute_command').with_args( - CREATE_COMMAND + ('--numeric-owner',), capture_output=False + CREATE_COMMAND + ('--numeric-owner',), capture_output=False, output_as_warning=False ) module.create_archive( @@ -545,7 +557,7 @@ def test_create_archive_with_read_special_calls_borg_with_read_special_parameter flexmock(module).should_receive('_make_pattern_flags').and_return(()) flexmock(module).should_receive('_make_exclude_flags').and_return(()) flexmock(module).should_receive('execute_command').with_args( - CREATE_COMMAND + ('--read-special',), capture_output=False + CREATE_COMMAND + ('--read-special',), capture_output=False, output_as_warning=False ) module.create_archive( @@ -568,7 +580,7 @@ def test_create_archive_with_bsd_flags_true_calls_borg_without_nobsdflags_parame flexmock(module).should_receive('_make_pattern_flags').and_return(()) flexmock(module).should_receive('_make_exclude_flags').and_return(()) flexmock(module).should_receive('execute_command').with_args( - CREATE_COMMAND, capture_output=False + CREATE_COMMAND, capture_output=False, output_as_warning=False ) module.create_archive( @@ -591,7 +603,7 @@ def test_create_archive_with_bsd_flags_false_calls_borg_with_nobsdflags_paramete flexmock(module).should_receive('_make_pattern_flags').and_return(()) flexmock(module).should_receive('_make_exclude_flags').and_return(()) flexmock(module).should_receive('execute_command').with_args( - CREATE_COMMAND + ('--nobsdflags',), capture_output=False + CREATE_COMMAND + ('--nobsdflags',), capture_output=False, output_as_warning=False ) module.create_archive( @@ -614,7 +626,9 @@ def test_create_archive_with_files_cache_calls_borg_with_files_cache_parameters( flexmock(module).should_receive('_make_pattern_flags').and_return(()) flexmock(module).should_receive('_make_exclude_flags').and_return(()) flexmock(module).should_receive('execute_command').with_args( - CREATE_COMMAND + ('--files-cache', 'ctime,size'), capture_output=False + CREATE_COMMAND + ('--files-cache', 'ctime,size'), + capture_output=False, + output_as_warning=False, ) module.create_archive( @@ -637,7 +651,7 @@ def test_create_archive_with_local_path_calls_borg_via_local_path(): flexmock(module).should_receive('_make_pattern_flags').and_return(()) flexmock(module).should_receive('_make_exclude_flags').and_return(()) flexmock(module).should_receive('execute_command').with_args( - ('borg1',) + CREATE_COMMAND[1:], capture_output=False + ('borg1',) + CREATE_COMMAND[1:], capture_output=False, output_as_warning=False ) module.create_archive( @@ -660,7 +674,7 @@ def test_create_archive_with_remote_path_calls_borg_with_remote_path_parameters( flexmock(module).should_receive('_make_pattern_flags').and_return(()) flexmock(module).should_receive('_make_exclude_flags').and_return(()) flexmock(module).should_receive('execute_command').with_args( - CREATE_COMMAND + ('--remote-path', 'borg1'), capture_output=False + CREATE_COMMAND + ('--remote-path', 'borg1'), capture_output=False, output_as_warning=False ) module.create_archive( @@ -683,7 +697,7 @@ def test_create_archive_with_umask_calls_borg_with_umask_parameters(): flexmock(module).should_receive('_make_pattern_flags').and_return(()) flexmock(module).should_receive('_make_exclude_flags').and_return(()) flexmock(module).should_receive('execute_command').with_args( - CREATE_COMMAND + ('--umask', '740'), capture_output=False + CREATE_COMMAND + ('--umask', '740'), capture_output=False, output_as_warning=False ) module.create_archive( @@ -705,7 +719,7 @@ def test_create_archive_with_lock_wait_calls_borg_with_lock_wait_parameters(): flexmock(module).should_receive('_make_pattern_flags').and_return(()) flexmock(module).should_receive('_make_exclude_flags').and_return(()) flexmock(module).should_receive('execute_command').with_args( - CREATE_COMMAND + ('--lock-wait', '5'), capture_output=False + CREATE_COMMAND + ('--lock-wait', '5'), capture_output=False, output_as_warning=False ) module.create_archive( @@ -720,6 +734,29 @@ def test_create_archive_with_lock_wait_calls_borg_with_lock_wait_parameters(): ) +def test_create_archive_with_stats_calls_borg_with_stats_parameter(): + flexmock(module).should_receive('_expand_directories').and_return(('foo', 'bar')) + flexmock(module).should_receive('_expand_home_directories').and_return(()) + flexmock(module).should_receive('_write_pattern_file').and_return(None) + flexmock(module).should_receive('_make_pattern_flags').and_return(()) + flexmock(module).should_receive('_make_exclude_flags').and_return(()) + flexmock(module).should_receive('execute_command').with_args( + CREATE_COMMAND + ('--stats',), capture_output=False, output_as_warning=True + ) + + module.create_archive( + dry_run=False, + repository='repo', + location_config={ + 'source_directories': ['foo', 'bar'], + 'repositories': ['repo'], + 'exclude_patterns': None, + }, + storage_config={}, + stats=True, + ) + + def test_create_archive_with_json_calls_borg_with_json_parameter(): flexmock(module).should_receive('_expand_directories').and_return(('foo', 'bar')) flexmock(module).should_receive('_expand_home_directories').and_return(()) @@ -727,7 +764,7 @@ def test_create_archive_with_json_calls_borg_with_json_parameter(): flexmock(module).should_receive('_make_pattern_flags').and_return(()) flexmock(module).should_receive('_make_exclude_flags').and_return(()) flexmock(module).should_receive('execute_command').with_args( - CREATE_COMMAND + ('--json',), capture_output=True + CREATE_COMMAND + ('--json',), capture_output=True, output_as_warning=False ).and_return('[]') json_output = module.create_archive( @@ -745,6 +782,32 @@ def test_create_archive_with_json_calls_borg_with_json_parameter(): assert json_output == '[]' +def test_create_archive_with_stats_and_json_calls_borg_without_stats_parameter(): + flexmock(module).should_receive('_expand_directories').and_return(('foo', 'bar')) + flexmock(module).should_receive('_expand_home_directories').and_return(()) + flexmock(module).should_receive('_write_pattern_file').and_return(None) + flexmock(module).should_receive('_make_pattern_flags').and_return(()) + flexmock(module).should_receive('_make_exclude_flags').and_return(()) + flexmock(module).should_receive('execute_command').with_args( + CREATE_COMMAND + ('--json',), capture_output=True, output_as_warning=False + ).and_return('[]') + + json_output = module.create_archive( + dry_run=False, + repository='repo', + location_config={ + 'source_directories': ['foo', 'bar'], + 'repositories': ['repo'], + 'exclude_patterns': None, + }, + storage_config={}, + json=True, + stats=True, + ) + + assert json_output == '[]' + + def test_create_archive_with_source_directories_glob_expands(): flexmock(module).should_receive('_expand_directories').and_return(('foo', 'food')) flexmock(module).should_receive('_expand_home_directories').and_return(()) @@ -754,6 +817,7 @@ def test_create_archive_with_source_directories_glob_expands(): flexmock(module).should_receive('execute_command').with_args( ('borg', 'create', 'repo::{}'.format(DEFAULT_ARCHIVE_NAME), 'foo', 'food'), capture_output=False, + output_as_warning=False, ) flexmock(module.glob).should_receive('glob').with_args('foo*').and_return(['foo', 'food']) @@ -776,7 +840,9 @@ def test_create_archive_with_non_matching_source_directories_glob_passes_through flexmock(module).should_receive('_make_pattern_flags').and_return(()) flexmock(module).should_receive('_make_exclude_flags').and_return(()) flexmock(module).should_receive('execute_command').with_args( - ('borg', 'create', 'repo::{}'.format(DEFAULT_ARCHIVE_NAME), 'foo*'), capture_output=False + ('borg', 'create', 'repo::{}'.format(DEFAULT_ARCHIVE_NAME), 'foo*'), + capture_output=False, + output_as_warning=False, ) flexmock(module.glob).should_receive('glob').with_args('foo*').and_return([]) @@ -801,6 +867,7 @@ def test_create_archive_with_glob_calls_borg_with_expanded_directories(): flexmock(module).should_receive('execute_command').with_args( ('borg', 'create', 'repo::{}'.format(DEFAULT_ARCHIVE_NAME), 'foo', 'food'), capture_output=False, + output_as_warning=False, ) module.create_archive( @@ -822,7 +889,9 @@ def test_create_archive_with_archive_name_format_calls_borg_with_archive_name(): flexmock(module).should_receive('_make_pattern_flags').and_return(()) flexmock(module).should_receive('_make_exclude_flags').and_return(()) flexmock(module).should_receive('execute_command').with_args( - ('borg', 'create', 'repo::ARCHIVE_NAME', 'foo', 'bar'), capture_output=False + ('borg', 'create', 'repo::ARCHIVE_NAME', 'foo', 'bar'), + capture_output=False, + output_as_warning=False, ) module.create_archive( @@ -844,7 +913,9 @@ def test_create_archive_with_archive_name_format_accepts_borg_placeholders(): flexmock(module).should_receive('_make_pattern_flags').and_return(()) flexmock(module).should_receive('_make_exclude_flags').and_return(()) flexmock(module).should_receive('execute_command').with_args( - ('borg', 'create', 'repo::Documents_{hostname}-{now}', 'foo', 'bar'), capture_output=False + ('borg', 'create', 'repo::Documents_{hostname}-{now}', 'foo', 'bar'), + capture_output=False, + output_as_warning=False, ) module.create_archive( diff --git a/tests/unit/borg/test_execute.py b/tests/unit/borg/test_execute.py index 571b18663..de9ae6626 100644 --- a/tests/unit/borg/test_execute.py +++ b/tests/unit/borg/test_execute.py @@ -5,7 +5,9 @@ from borgmatic.borg import execute as module def test_execute_command_calls_full_command(): full_command = ['foo', 'bar'] - flexmock(module).should_receive('execute_and_log_output').with_args(full_command).once() + flexmock(module).should_receive('execute_and_log_output').with_args( + full_command, output_as_warning=False + ).once() output = module.execute_command(full_command)