Log stdout, stderr and command on execute() error
It would help debugging considerably if a failure in execute() generated a message (at a client specified logging level). Such a message, generated by execute() would only occur if the user requested it by specifying a parameter (log_errors), and execute() were to throw an exception. As an example, this change would address the issue being addressed in bug 1340124 for the Trove project only. DocImpact: New parameter added to processutils.execute(). The possible values of the log_errors parameter are 'all' or 'final'. The default value of None implies no logging. If it is set to 'final', stdout and stderr are logged on the final failure. If it is set to 'all', stdout and stderr are logged on every failure. Originally-submitted-in: If8180e042e1a05374ef705f5873cc0981243619f Change-Id: Id9e94bd8d009b8f134f0b681da5dec5717d662ff DocImpact: Closes-Bug: #1342857 Suggested-By: Peter Stachowski <peter@tesora.com> Reported-By: Ionuț Arțăriși <iartarisi@suse.cz>
This commit is contained in:
parent
df6614936a
commit
0923ea1c23
@ -82,6 +82,10 @@ def _subprocess_setup():
|
|||||||
signal.signal(signal.SIGPIPE, signal.SIG_DFL)
|
signal.signal(signal.SIGPIPE, signal.SIG_DFL)
|
||||||
|
|
||||||
|
|
||||||
|
LOG_ALL_ERRORS = 1
|
||||||
|
LOG_FINAL_ERROR = 2
|
||||||
|
|
||||||
|
|
||||||
def execute(*cmd, **kwargs):
|
def execute(*cmd, **kwargs):
|
||||||
"""Helper method to shell out and execute a command through subprocess.
|
"""Helper method to shell out and execute a command through subprocess.
|
||||||
|
|
||||||
@ -116,10 +120,23 @@ def execute(*cmd, **kwargs):
|
|||||||
:type shell: boolean
|
:type shell: boolean
|
||||||
:param loglevel: log level for execute commands.
|
:param loglevel: log level for execute commands.
|
||||||
:type loglevel: int. (Should be logging.DEBUG or logging.INFO)
|
: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
|
:returns: (stdout, stderr) from process execution
|
||||||
:raises: :class:`UnknownArgumentError` on
|
:raises: :class:`UnknownArgumentError` on
|
||||||
receiving unknown arguments
|
receiving unknown arguments
|
||||||
:raises: :class:`ProcessExecutionError`
|
:raises: :class:`ProcessExecutionError`
|
||||||
|
|
||||||
"""
|
"""
|
||||||
|
|
||||||
process_input = kwargs.pop('process_input', None)
|
process_input = kwargs.pop('process_input', None)
|
||||||
@ -132,6 +149,7 @@ def execute(*cmd, **kwargs):
|
|||||||
root_helper = kwargs.pop('root_helper', '')
|
root_helper = kwargs.pop('root_helper', '')
|
||||||
shell = kwargs.pop('shell', False)
|
shell = kwargs.pop('shell', False)
|
||||||
loglevel = kwargs.pop('loglevel', logging.DEBUG)
|
loglevel = kwargs.pop('loglevel', logging.DEBUG)
|
||||||
|
log_errors = kwargs.pop('log_errors', None)
|
||||||
|
|
||||||
if isinstance(check_exit_code, bool):
|
if isinstance(check_exit_code, bool):
|
||||||
ignore_exit_code = not check_exit_code
|
ignore_exit_code = not check_exit_code
|
||||||
@ -142,6 +160,10 @@ def execute(*cmd, **kwargs):
|
|||||||
if kwargs:
|
if kwargs:
|
||||||
raise UnknownArgumentError(_('Got unknown keyword args: %r') % 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 run_as_root and hasattr(os, 'geteuid') and os.geteuid() != 0:
|
||||||
if not root_helper:
|
if not root_helper:
|
||||||
raise NoRootWrapSpecified(
|
raise NoRootWrapSpecified(
|
||||||
@ -199,11 +221,25 @@ def execute(*cmd, **kwargs):
|
|||||||
stderr=sanitized_stderr,
|
stderr=sanitized_stderr,
|
||||||
cmd=sanitized_cmd)
|
cmd=sanitized_cmd)
|
||||||
return result
|
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:
|
if not attempts:
|
||||||
|
LOG.log(loglevel, _('%r failed. Not Retrying.'), err.cmd)
|
||||||
raise
|
raise
|
||||||
else:
|
else:
|
||||||
LOG.log(loglevel, _('%r failed. Retrying.'), sanitized_cmd)
|
LOG.log(loglevel, _('%r failed. Retrying.'), err.cmd)
|
||||||
if delay_on_retry:
|
if delay_on_retry:
|
||||||
greenthread.sleep(random.randint(20, 200) / 100.0)
|
greenthread.sleep(random.randint(20, 200) / 100.0)
|
||||||
finally:
|
finally:
|
||||||
|
@ -16,17 +16,20 @@
|
|||||||
from __future__ import print_function
|
from __future__ import print_function
|
||||||
|
|
||||||
import errno
|
import errno
|
||||||
|
import logging
|
||||||
import multiprocessing
|
import multiprocessing
|
||||||
import os
|
import os
|
||||||
|
import stat
|
||||||
import tempfile
|
import tempfile
|
||||||
|
|
||||||
import fixtures
|
import fixtures
|
||||||
import mock
|
import mock
|
||||||
from oslotest import base as test_base
|
from oslotest import base as test_base
|
||||||
import six
|
import six
|
||||||
import stat
|
|
||||||
|
|
||||||
from oslo.concurrency import processutils
|
from oslo.concurrency import processutils
|
||||||
|
PROCESS_EXECUTION_ERROR_LOGGING_TEST = """#!/bin/bash
|
||||||
|
exit 41"""
|
||||||
|
|
||||||
TEST_EXCEPTION_AND_MASKING_SCRIPT = """#!/bin/bash
|
TEST_EXCEPTION_AND_MASKING_SCRIPT = """#!/bin/bash
|
||||||
# This is to test stdout and stderr
|
# This is to test stdout and stderr
|
||||||
@ -251,6 +254,65 @@ grep foo
|
|||||||
self.assertNotIn('secret', str(err))
|
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):
|
def fake_execute(*cmd, **kwargs):
|
||||||
return 'stdout', 'stderr'
|
return 'stdout', 'stderr'
|
||||||
|
|
||||||
|
Loading…
Reference in New Issue
Block a user