diff --git a/oslo/concurrency/processutils.py b/oslo/concurrency/processutils.py index ad49566..43108d7 100644 --- a/oslo/concurrency/processutils.py +++ b/oslo/concurrency/processutils.py @@ -82,6 +82,10 @@ def _subprocess_setup(): signal.signal(signal.SIGPIPE, signal.SIG_DFL) +LOG_ALL_ERRORS = 1 +LOG_FINAL_ERROR = 2 + + def execute(*cmd, **kwargs): """Helper method to shell out and execute a command through subprocess. @@ -116,10 +120,23 @@ def execute(*cmd, **kwargs): :type shell: boolean :param loglevel: log level for execute commands. :type loglevel: int. (Should be logging.DEBUG or logging.INFO) + :param log_errors: Should stdout and stderr be logged on error? + Possible values are None=default, + LOG_FINAL_ERROR, or LOG_ALL_ERRORS. None + implies no logging on errors. The values + LOG_FINAL_ERROR and LOG_ALL_ERRORS are + relevant when multiple attempts of command + execution are requested using the + 'attempts' parameter. If LOG_FINAL_ERROR + is specified then only log an error on the + last attempt, and LOG_ALL_ERRORS requires + logging on each occurence of an error. + :type log_errors: integer. :returns: (stdout, stderr) from process execution :raises: :class:`UnknownArgumentError` on receiving unknown arguments :raises: :class:`ProcessExecutionError` + """ process_input = kwargs.pop('process_input', None) @@ -132,6 +149,7 @@ def execute(*cmd, **kwargs): root_helper = kwargs.pop('root_helper', '') shell = kwargs.pop('shell', False) loglevel = kwargs.pop('loglevel', logging.DEBUG) + log_errors = kwargs.pop('log_errors', None) if isinstance(check_exit_code, bool): ignore_exit_code = not check_exit_code @@ -142,6 +160,10 @@ def execute(*cmd, **kwargs): if kwargs: raise UnknownArgumentError(_('Got unknown keyword args: %r') % kwargs) + if log_errors not in [None, LOG_ALL_ERRORS, LOG_FINAL_ERROR]: + raise InvalidArgumentError(_('Got invalid arg log_errors: %r') % + log_errors) + if run_as_root and hasattr(os, 'geteuid') and os.geteuid() != 0: if not root_helper: raise NoRootWrapSpecified( @@ -199,11 +221,25 @@ def execute(*cmd, **kwargs): stderr=sanitized_stderr, cmd=sanitized_cmd) return result - except ProcessExecutionError: + except ProcessExecutionError as err: + # if we want to always log the errors or if this is + # the final attempt that failed and we want to log that. + if log_errors == LOG_ALL_ERRORS or ( + log_errors == LOG_FINAL_ERROR and not attempts): + format = _('%(desc)r\ncommand: %(cmd)r\n' + 'exit code: %(code)r\nstdout: %(stdout)r\n' + 'stderr: %(stderr)r') + LOG.log(loglevel, format, {"desc": err.description, + "cmd": err.cmd, + "code": err.exit_code, + "stdout": err.stdout, + "stderr": err.stderr}) + if not attempts: + LOG.log(loglevel, _('%r failed. Not Retrying.'), err.cmd) raise else: - LOG.log(loglevel, _('%r failed. Retrying.'), sanitized_cmd) + LOG.log(loglevel, _('%r failed. Retrying.'), err.cmd) if delay_on_retry: greenthread.sleep(random.randint(20, 200) / 100.0) finally: diff --git a/tests/unit/test_processutils.py b/tests/unit/test_processutils.py index 829807b..2bdd525 100644 --- a/tests/unit/test_processutils.py +++ b/tests/unit/test_processutils.py @@ -19,15 +19,17 @@ import errno import logging import multiprocessing import os +import stat import tempfile import fixtures import mock from oslotest import base as test_base import six -import stat from oslo.concurrency import processutils +PROCESS_EXECUTION_ERROR_LOGGING_TEST = """#!/bin/bash +exit 41""" TEST_EXCEPTION_AND_MASKING_SCRIPT = """#!/bin/bash # This is to test stdout and stderr @@ -252,6 +254,65 @@ grep foo self.assertNotIn('secret', str(err)) +class ProcessExecutionErrorLoggingTest(test_base.BaseTestCase): + def setUp(self): + super(ProcessExecutionErrorLoggingTest, self).setUp() + self.tmpfilename = self.create_tempfiles( + [["process_execution_error_logging_test", + PROCESS_EXECUTION_ERROR_LOGGING_TEST]], + ext='bash')[0] + + os.chmod(self.tmpfilename, (stat.S_IRWXU | stat.S_IRGRP | + stat.S_IXGRP | stat.S_IROTH | + stat.S_IXOTH)) + + def _test_and_check(self, log_errors=None, attempts=None): + fixture = self.useFixture(fixtures.FakeLogger(level=logging.DEBUG)) + kwargs = {} + + if log_errors: + kwargs.update({"log_errors": log_errors}) + + if attempts: + kwargs.update({"attempts": attempts}) + + err = self.assertRaises(processutils.ProcessExecutionError, + processutils.execute, + self.tmpfilename, + **kwargs) + + self.assertEqual(41, err.exit_code) + self.assertIn(self.tmpfilename, fixture.output) + + def test_with_invalid_log_errors(self): + self.assertRaises(processutils.InvalidArgumentError, + processutils.execute, + self.tmpfilename, + log_errors='invalid') + + def test_with_log_errors_NONE(self): + self._test_and_check(log_errors=None, attempts=None) + + def test_with_log_errors_final(self): + self._test_and_check(log_errors=processutils.LOG_FINAL_ERROR, + attempts=None) + + def test_with_log_errors_all(self): + self._test_and_check(log_errors=processutils.LOG_ALL_ERRORS, + attempts=None) + + def test_multiattempt_with_log_errors_NONE(self): + self._test_and_check(log_errors=None, attempts=3) + + def test_multiattempt_with_log_errors_final(self): + self._test_and_check(log_errors=processutils.LOG_FINAL_ERROR, + attempts=3) + + def test_multiattempt_with_log_errors_all(self): + self._test_and_check(log_errors=processutils.LOG_ALL_ERRORS, + attempts=3) + + def fake_execute(*cmd, **kwargs): return 'stdout', 'stderr'