From 1676a98c51faf33d0c231c672bdd853a3c79611d Mon Sep 17 00:00:00 2001 From: Dan Helfman Date: Mon, 24 Jun 2019 09:55:41 -0700 Subject: [PATCH] Fix for Borg create error output not showing up at borgmatic verbosity level zero (#198). --- NEWS | 3 +++ borgmatic/commands/borgmatic.py | 16 +++++++++++++++- borgmatic/execute.py | 24 +++++++++++++++++++----- setup.py | 2 +- tests/integration/test_execute.py | 20 +++++++++++++++----- tests/unit/commands/test_borgmatic.py | 19 ++++++++++++++++++- 6 files changed, 71 insertions(+), 13 deletions(-) diff --git a/NEWS b/NEWS index 2e13863a7..c82aefc1c 100644 --- a/NEWS +++ b/NEWS @@ -1,3 +1,6 @@ +1.3.10 + * #198: Fix for Borg create error output not showing up at borgmatic verbosity level zero. + 1.3.9 * #195: Switch to command-line actions as more traditional sub-commands, e.g. "borgmatic create", "borgmatic prune", etc. However, the classic dashed options like "--create" still work! diff --git a/borgmatic/commands/borgmatic.py b/borgmatic/commands/borgmatic.py index 9b87ed197..95f8cb6f9 100644 --- a/borgmatic/commands/borgmatic.py +++ b/borgmatic/commands/borgmatic.py @@ -265,7 +265,21 @@ def collect_configuration_run_summary_logs(configs, arguments): msg='{}: Successfully ran configuration file'.format(config_filename), ) ) - except (ValueError, OSError, CalledProcessError) as error: + except CalledProcessError as error: + yield logging.makeLogRecord( + dict( + levelno=logging.CRITICAL, + levelname='CRITICAL', + msg='{}: Error running configuration file'.format(config_filename), + ) + ) + yield logging.makeLogRecord( + dict(levelno=logging.CRITICAL, levelname='CRITICAL', msg=error.output) + ) + yield logging.makeLogRecord( + dict(levelno=logging.CRITICAL, levelname='CRITICAL', msg=error) + ) + except (ValueError, OSError) as error: yield logging.makeLogRecord( dict( levelno=logging.CRITICAL, diff --git a/borgmatic/execute.py b/borgmatic/execute.py index 1458247ce..261e0e4a5 100644 --- a/borgmatic/execute.py +++ b/borgmatic/execute.py @@ -4,7 +4,11 @@ import subprocess logger = logging.getLogger(__name__) +ERROR_OUTPUT_MAX_LINE_COUNT = 25 + + def execute_and_log_output(full_command, output_log_level, shell): + last_lines = [] process = subprocess.Popen( full_command, stdout=subprocess.PIPE, stderr=subprocess.STDOUT, shell=shell ) @@ -14,10 +18,13 @@ def execute_and_log_output(full_command, output_log_level, shell): if not line: continue - if line.startswith('borg: error:'): - logger.error(line) - else: - logger.log(output_log_level, line) + # Keep the last few lines of output in case the command errors, and we need the output for + # the exception below. + last_lines.append(line) + if len(last_lines) > ERROR_OUTPUT_MAX_LINE_COUNT: + last_lines.pop(0) + + logger.log(output_log_level, line) remaining_output = process.stdout.read().rstrip().decode() if remaining_output: # pragma: no cover @@ -25,7 +32,14 @@ def execute_and_log_output(full_command, output_log_level, shell): exit_code = process.poll() if exit_code != 0: - raise subprocess.CalledProcessError(exit_code, full_command) + # If an error occurs, include its output in the raised exception so that we don't + # inadvertently hide error output. + if len(last_lines) == ERROR_OUTPUT_MAX_LINE_COUNT: + last_lines.insert(0, '...') + + raise subprocess.CalledProcessError( + exit_code, ' '.join(full_command), '\n'.join(last_lines) + ) def execute_command(full_command, output_log_level=logging.INFO, shell=False): diff --git a/setup.py b/setup.py index e3a6c7c88..acff92751 100644 --- a/setup.py +++ b/setup.py @@ -1,6 +1,6 @@ from setuptools import find_packages, setup -VERSION = '1.3.9' +VERSION = '1.3.10' setup( diff --git a/tests/integration/test_execute.py b/tests/integration/test_execute.py index 2270765f8..5807fcd90 100644 --- a/tests/integration/test_execute.py +++ b/tests/integration/test_execute.py @@ -15,12 +15,22 @@ def test_execute_and_log_output_logs_each_line_separately(): module.execute_and_log_output(['echo', 'there'], output_log_level=logging.INFO, shell=False) -def test_execute_and_log_output_logs_borg_error_as_error(): - flexmock(module.logger).should_receive('error').with_args('borg: error: oopsie').once() +def test_execute_and_log_output_includes_borg_error_output_in_exception(): + with pytest.raises(subprocess.CalledProcessError) as error: + module.execute_and_log_output(['grep'], output_log_level=logging.INFO, shell=False) - module.execute_and_log_output( - ['echo', 'borg: error: oopsie'], output_log_level=logging.INFO, shell=False - ) + assert error.value.returncode == 2 + assert error.value.output + + +def test_execute_and_log_output_truncates_long_borg_error_output(): + flexmock(module).ERROR_OUTPUT_MAX_LINE_COUNT = 0 + + with pytest.raises(subprocess.CalledProcessError) as error: + module.execute_and_log_output(['grep'], output_log_level=logging.INFO, shell=False) + + assert error.value.returncode == 2 + assert error.value.output.startswith('...') def test_execute_and_log_output_with_no_output_logs_nothing(): diff --git a/tests/unit/commands/test_borgmatic.py b/tests/unit/commands/test_borgmatic.py index caca645d0..0b7704a1a 100644 --- a/tests/unit/commands/test_borgmatic.py +++ b/tests/unit/commands/test_borgmatic.py @@ -1,3 +1,5 @@ +import subprocess + from flexmock import flexmock from borgmatic.commands import borgmatic as module @@ -85,7 +87,7 @@ def test_collect_configuration_run_summary_logs_info_for_success_with_list(): assert all(log for log in logs if log.levelno == module.logging.INFO) -def test_collect_configuration_run_summary_logs_critical_for_run_error(): +def test_collect_configuration_run_summary_logs_critical_for_run_value_error(): flexmock(module.validate).should_receive('guard_configuration_contains_repository') flexmock(module).should_receive('run_configuration').and_raise(ValueError) arguments = {} @@ -97,6 +99,21 @@ def test_collect_configuration_run_summary_logs_critical_for_run_error(): assert any(log for log in logs if log.levelno == module.logging.CRITICAL) +def test_collect_configuration_run_summary_logs_critical_including_output_for_run_process_error(): + flexmock(module.validate).should_receive('guard_configuration_contains_repository') + flexmock(module).should_receive('run_configuration').and_raise( + subprocess.CalledProcessError(1, 'command', 'error output') + ) + arguments = {} + + logs = tuple( + module.collect_configuration_run_summary_logs({'test.yaml': {}}, arguments=arguments) + ) + + assert any(log for log in logs if log.levelno == module.logging.CRITICAL) + assert any(log for log in logs if 'error output' in str(log)) + + def test_collect_configuration_run_summary_logs_outputs_merged_json_results(): flexmock(module).should_receive('run_configuration').and_return(['foo', 'bar']).and_return( ['baz']