Merge "Replace 'print' with 'logger.info()' in command executors"

This commit is contained in:
Jenkins 2017-02-06 16:21:32 +00:00 committed by Gerrit Code Review
commit 41bcf73586
4 changed files with 148 additions and 220 deletions

View File

@ -12,7 +12,6 @@
# License for the specific language governing permissions and limitations
# under the License.
from __future__ import print_function
from __future__ import unicode_literals
import base64
@ -630,17 +629,11 @@ class SSHClient(six.with_metaclass(_MemorizedSSH, object)):
if ret['exit_code'] not in expected:
message = (
"{append}Command '{cmd!r}' returned exit code {code!s} while "
"expected {expected!s}\n"
"\tSTDOUT:\n"
"{stdout}"
"\n\tSTDERR:\n"
"{stderr}".format(
"expected {expected!s}\n".format(
append=error_info + '\n' if error_info else '',
cmd=command,
code=ret['exit_code'],
expected=expected,
stdout=ret['stdout_str'],
stderr=ret['stderr_str']
))
logger.error(message)
if raise_on_err:
@ -672,16 +665,10 @@ class SSHClient(six.with_metaclass(_MemorizedSSH, object)):
if ret['stderr']:
message = (
"{append}Command '{cmd!r}' STDERR while not expected\n"
"\texit code: {code!s}\n"
"\tSTDOUT:\n"
"{stdout}"
"\n\tSTDERR:\n"
"{stderr}".format(
"\texit code: {code!s}\n".format(
append=error_info + '\n' if error_info else '',
cmd=command,
code=ret['exit_code'],
stdout=ret['stdout_str'],
stderr=ret['stderr_str']
))
logger.error(message)
if raise_on_err:
@ -732,24 +719,29 @@ class SSHClient(six.with_metaclass(_MemorizedSSH, object)):
:rtype: ExecResult
:raises: TimeoutError
"""
def poll_stream(src, verbose):
def poll_stream(src, verb_logger=None):
dst = []
try:
for line in src:
dst.append(line)
if verbose:
print(
line.decode('utf-8', errors='backslashreplace'),
end="")
if verb_logger is not None:
verb_logger(
line.decode('utf-8',
errors='backslashreplace').rstrip()
)
except IOError:
pass
return dst
def poll_streams(result, channel, stdout, stderr, verbose):
if channel.recv_ready():
result.stdout += poll_stream(src=stdout, verbose=verbose)
result.stdout += poll_stream(
src=stdout,
verb_logger=logger.info if verbose else logger.debug)
if channel.recv_stderr_ready():
result.stderr += poll_stream(src=stderr, verbose=verbose)
result.stderr += poll_stream(
src=stderr,
verb_logger=logger.error if verbose else logger.debug)
@decorators.threaded(started=True)
def poll_pipes(stdout, stderr, result, stop, channel):
@ -775,8 +767,12 @@ class SSHClient(six.with_metaclass(_MemorizedSSH, object)):
if channel.status_event.is_set():
result.exit_code = result.exit_code = channel.exit_status
result.stdout += poll_stream(src=stdout, verbose=verbose)
result.stderr += poll_stream(src=stderr, verbose=verbose)
result.stdout += poll_stream(
src=stdout,
verb_logger=logger.info if verbose else logger.debug)
result.stderr += poll_stream(
src=stderr,
verb_logger=logger.error if verbose else logger.debug)
stop.set()
@ -784,7 +780,9 @@ class SSHClient(six.with_metaclass(_MemorizedSSH, object)):
result = exec_result.ExecResult(cmd=command)
stop_event = threading.Event()
if verbose:
print("\nExecuting command: {!r}".format(command.rstrip()))
logger.info("\nExecuting command: {!r}".format(command.rstrip()))
else:
logger.debug("\nExecuting command: {!r}".format(command.rstrip()))
poll_pipes(
stdout=stdout,
stderr=stderr,
@ -804,25 +802,15 @@ class SSHClient(six.with_metaclass(_MemorizedSSH, object)):
stop_event.set()
channel.close()
status_tmpl = (
'Wait for {0!r} during {1}s: no return code!\n'
'\tSTDOUT:\n'
'{2}\n'
'\tSTDERR"\n'
'{3}')
logger.debug(
status_tmpl.format(
command, timeout,
result.stdout,
result.stderr
)
)
raise error.TimeoutError(
status_tmpl.format(
command, timeout,
result.stdout_brief,
result.stderr_brief
))
wait_err_msg = ('Wait for {0!r} during {1}s: no return code!\n'
.format(command, timeout))
output_brief_msg = ('\tSTDOUT:\n'
'{0}\n'
'\tSTDERR"\n'
'{1}'.format(result.stdout_brief,
result.stderr_brief))
logger.debug(wait_err_msg)
raise error.TimeoutError(wait_err_msg + output_brief_msg)
def execute(self, command, verbose=False, timeout=None, **kwargs):
"""Execute command and wait for return code
@ -840,39 +828,15 @@ class SSHClient(six.with_metaclass(_MemorizedSSH, object)):
verbose=verbose
)
message = (
'\n{cmd!r} execution results: Exit code: {code!s}'.format(
cmd=command,
code=result.exit_code
))
if verbose:
print(
'\n{cmd!r} execution results: Exit code: {code!s}'.format(
cmd=command,
code=result.exit_code
)
)
logger.debug(
'{cmd!r} execution results:\n'
'Exit code: {code!s}\n'
'STDOUT:\n'
'{stdout}\n'
'STDERR:\n'
'{stderr}'.format(
cmd=command,
code=result.exit_code,
stdout=result.stdout_str,
stderr=result.stderr_str
))
logger.info(message)
else:
logger.debug(
'{cmd!r} execution results:\n'
'Exit code: {code!s}\n'
'BRIEF STDOUT:\n'
'{stdout}\n'
'BRIEF STDERR:\n'
'{stderr}'.format(
cmd=command,
code=result.exit_code,
stdout=result.stdout_brief,
stderr=result.stderr_brief
))
logger.debug(message)
return result
def execute_async(self, command, get_pty=False):

View File

@ -12,7 +12,6 @@
# License for the specific language governing permissions and limitations
# under the License.
from __future__ import print_function
from __future__ import unicode_literals
import fcntl
@ -53,17 +52,16 @@ class Subprocess(six.with_metaclass(metaclasses.SingletonMeta, object)):
:type timeout: int
:rtype: ExecResult
"""
def poll_stream(src, verbose):
def poll_stream(src, verb_logger=None):
dst = []
try:
for line in src:
dst.append(line)
if verbose:
print(
line.decode(
'utf-8',
errors='backslashreplace'),
end="")
if verb_logger is not None:
verb_logger(
line.decode('utf-8',
errors='backslashreplace').rstrip()
)
except IOError:
pass
return dst
@ -75,9 +73,13 @@ class Subprocess(six.with_metaclass(metaclasses.SingletonMeta, object)):
[])
if rlist:
if stdout in rlist:
result.stdout += poll_stream(src=stdout, verbose=verbose)
result.stdout += poll_stream(
src=stdout,
verb_logger=logger.info if verbose else logger.debug)
if stderr in rlist:
result.stderr += poll_stream(src=stderr, verbose=verbose)
result.stderr += poll_stream(
src=stderr,
verb_logger=logger.error if verbose else logger.debug)
@decorators.threaded(started=True)
def poll_pipes(proc, result, stop):
@ -112,10 +114,10 @@ class Subprocess(six.with_metaclass(metaclasses.SingletonMeta, object)):
result.exit_code = proc.returncode
result.stdout += poll_stream(
src=proc.stdout,
verbose=verbose)
verb_logger=logger.info if verbose else logger.debug)
result.stderr += poll_stream(
src=proc.stderr,
verbose=verbose)
verb_logger=logger.error if verbose else logger.debug)
stop.set()
@ -125,8 +127,11 @@ class Subprocess(six.with_metaclass(metaclasses.SingletonMeta, object)):
stop_event = threading.Event()
if verbose:
print("\nExecuting command: {!r}".format(command.rstrip()))
logger.info("\nExecuting command: {!r}"
.format(command.rstrip()))
else:
logger.debug("\nExecuting command: {!r}"
.format(command.rstrip()))
# Run
process = subprocess.Popen(
args=[command],
@ -157,25 +162,15 @@ class Subprocess(six.with_metaclass(metaclasses.SingletonMeta, object)):
"{!r} has been completed just after timeout: "
"please validate timeout.".format(command))
status_tmpl = (
'Wait for {0!r} during {1}s: no return code!\n'
'\tSTDOUT:\n'
'{2}\n'
'\tSTDERR"\n'
'{3}')
logger.debug(
status_tmpl.format(
command, timeout,
result.stdout,
result.stderr
)
)
raise error.TimeoutError(
status_tmpl.format(
command, timeout,
result.stdout_brief,
result.stderr_brief
))
wait_err_msg = ('Wait for {0!r} during {1}s: no return code!\n'
.format(command, timeout))
output_brief_msg = ('\tSTDOUT:\n'
'{0}\n'
'\tSTDERR"\n'
'{1}'.format(result.stdout_brief,
result.stderr_brief))
logger.debug(wait_err_msg)
raise error.TimeoutError(wait_err_msg + output_brief_msg)
@classmethod
def execute(cls, command, verbose=False, timeout=None, **kwargs):
@ -189,41 +184,17 @@ class Subprocess(six.with_metaclass(metaclasses.SingletonMeta, object)):
:rtype: ExecResult
:raises: TimeoutError
"""
logger.debug("Executing command: {!r}".format(command.rstrip()))
result = cls.__exec_command(command=command, timeout=timeout,
verbose=verbose, **kwargs)
message = (
'\n{cmd!r} execution results: Exit code: {code!s}'.format(
cmd=command,
code=result.exit_code
))
if verbose:
print(
'\n{cmd!r} execution results: Exit code: {code!s}'.format(
cmd=command,
code=result.exit_code
)
)
logger.debug(
'{cmd!r} execution results:\n'
'Exit code: {code!s}\n'
'STDOUT:\n'
'{stdout}\n'
'STDERR:\n'
'{stderr}'.format(
cmd=command,
code=result.exit_code,
stdout=result.stdout_str,
stderr=result.stderr_str
))
logger.info(message)
else:
logger.debug(
'{cmd!r} execution results:\n'
'Exit code: {code!s}\n'
'BRIEF STDOUT:\n'
'{stdout}\n'
'BRIEF STDERR:\n'
'{stderr}'.format(
cmd=command,
code=result.exit_code,
stdout=result.stdout_brief,
stderr=result.stderr_brief
))
logger.debug(message)
return result
@ -262,17 +233,11 @@ class Subprocess(six.with_metaclass(metaclasses.SingletonMeta, object)):
if ret['exit_code'] not in expected:
message = (
"{append}Command '{cmd!r}' returned exit code {code!s} while "
"expected {expected!s}\n"
"\tSTDOUT:\n"
"{stdout}"
"\n\tSTDERR:\n"
"{stderr}".format(
"expected {expected!s}\n".format(
append=error_info + '\n' if error_info else '',
cmd=command,
code=ret['exit_code'],
expected=expected,
stdout=ret['stdout_str'],
stderr=ret['stderr_str']
expected=expected
))
logger.error(message)
if raise_on_err:
@ -307,16 +272,10 @@ class Subprocess(six.with_metaclass(metaclasses.SingletonMeta, object)):
if ret['stderr']:
message = (
"{append}Command '{cmd!r}' STDERR while not expected\n"
"\texit code: {code!s}\n"
"\tSTDOUT:\n"
"{stdout}"
"\n\tSTDERR:\n"
"{stderr}".format(
"\texit code: {code!s}\n".format(
append=error_info + '\n' if error_info else '',
cmd=command,
code=ret['exit_code'],
stdout=ret['stdout_str'],
stderr=ret['stderr_str']
code=ret['exit_code']
))
logger.error(message)
if raise_on_err:

View File

@ -63,6 +63,8 @@ username = 'user'
password = 'pass'
private_keys = []
command = 'ls ~ '
stdout_list = [b' \n', b'2\n', b'3\n', b' \n']
stderr_list = [b' \n', b'0\n', b'1\n', b' \n']
encoded_cmd = base64.b64encode(
"{}\n".format(command).encode('utf-8')
).decode('utf-8')
@ -1162,7 +1164,7 @@ class TestExecute(unittest.TestCase):
)
@staticmethod
def get_patched_execute_async_retval(ec=0, stderr_val=True):
def get_patched_execute_async_retval(ec=0, stderr_val=None):
"""get patched execute_async retval
:rtype:
@ -1173,8 +1175,8 @@ class TestExecute(unittest.TestCase):
FakeStream,
FakeStream)
"""
out = [b' \n', b'2\n', b'3\n', b' \n']
err = [b' \n', b'0\n', b'1\n', b' \n'] if stderr_val is None else []
out = stdout_list
err = stderr_list if stderr_val is None else []
stdout = FakeStream(*out)
stderr = FakeStream(*err)
@ -1227,20 +1229,23 @@ class TestExecute(unittest.TestCase):
)
execute_async.assert_called_once_with(command)
chan.assert_has_calls((mock.call.status_event.is_set(), ))
logger.assert_has_calls((
logger.assert_has_calls([
mock.call.debug(
'{cmd!r} execution results:\n'
'Exit code: {code!s}\n'
'BRIEF STDOUT:\n'
'{stdout}\n'
'BRIEF STDERR:\n'
'{stderr}'.format(
cmd=exp_result.cmd,
code=exp_result.exit_code,
stdout=exp_result.stdout_brief,
stderr=exp_result.stderr_brief
"\nExecuting command: {!r}".format(command.rstrip())),
] + [
mock.call.debug(str(x.rstrip().decode('utf-8')))
for x in stdout_list
] + [
mock.call.debug(str(x.rstrip().decode('utf-8')))
for x in stderr_list
] + [
mock.call.debug(
'\n{cmd!r} execution results: '
'Exit code: {code!s}'.format(
cmd=command,
code=result.exit_code,
)),
))
])
@mock.patch(
'devops.helpers.ssh_client.SSHClient.execute_async')
@ -1269,20 +1274,24 @@ class TestExecute(unittest.TestCase):
)
execute_async.assert_called_once_with(command)
chan.assert_has_calls((mock.call.status_event.is_set(), ))
logger.assert_has_calls((
mock.call.debug(
'{cmd!r} execution results:\n'
'Exit code: {code!s}\n'
'STDOUT:\n'
'{stdout}\n'
'STDERR:\n'
'{stderr}'.format(
logger.assert_has_calls([
mock.call.info(
"\nExecuting command: {!r}".format(command.rstrip())),
] + [
mock.call.info(str(x.rstrip().decode('utf-8')))
for x in stdout_list
] + [
mock.call.error(str(x.rstrip().decode('utf-8')))
for x in stderr_list
] + [
mock.call.info(
'\n{cmd!r} execution results: '
'Exit code: {code!s}'.format(
cmd=command,
code=result['exit_code'],
stdout=result['stdout_str'],
stderr=result['stderr_str']
code=result.exit_code,
)),
))
])
@mock.patch('time.sleep', autospec=True)
@mock.patch(
@ -1314,16 +1323,10 @@ class TestExecute(unittest.TestCase):
chan.assert_has_calls((mock.call.status_event.is_set(), ))
logger.assert_has_calls((
mock.call.debug(
'{cmd!r} execution results:\n'
'Exit code: {code!s}\n'
'BRIEF STDOUT:\n'
'{stdout}\n'
'BRIEF STDERR:\n'
'{stderr}'.format(
'\n{cmd!r} execution results: '
'Exit code: {code!s}'.format(
cmd=exp_result.cmd,
code=exp_result.exit_code,
stdout=exp_result.stdout_brief,
stderr=exp_result.stderr_brief
code=exp_result.exit_code
)),
))

View File

@ -24,6 +24,8 @@ from devops.helpers import exec_result
from devops.helpers import subprocess_runner
command = 'ls ~ '
stdout_list = [b' \n', b'2\n', b'3\n', b' \n']
stderr_list = [b' \n', b'0\n', b'1\n', b' \n']
class FakeFileStream(object):
@ -48,10 +50,8 @@ class FakeFileStream(object):
class TestSubprocessRunner(unittest.TestCase):
@staticmethod
def prepare_close(popen, stderr_val=None, ec=0):
stdout_lines = [b' \n', b'2\n', b'3\n', b' \n']
stderr_lines = (
[b' \n', b'0\n', b'1\n', b' \n'] if stderr_val is None else []
)
stdout_lines = stdout_list
stderr_lines = stderr_list if stderr_val is None else []
stdout = FakeFileStream(*stdout_lines)
stderr = FakeFileStream(*stderr_lines)
@ -96,22 +96,23 @@ class TestSubprocessRunner(unittest.TestCase):
stdout=subprocess.PIPE,
universal_newlines=False),
))
logger.assert_has_calls((
logger.assert_has_calls([
mock.call.debug(
"Executing command: {!r}".format(command.rstrip())),
"\nExecuting command: {!r}".format(command.rstrip())),
] + [
mock.call.debug(str(x.rstrip().decode('utf-8')))
for x in stdout_list
] + [
mock.call.debug(str(x.rstrip().decode('utf-8')))
for x in stderr_list
] + [
mock.call.debug(
'{cmd!r} execution results:\n'
'Exit code: {code!s}\n'
'BRIEF STDOUT:\n'
'{stdout}\n'
'BRIEF STDERR:\n'
'{stderr}'.format(
'\n{cmd!r} execution results: '
'Exit code: {code!s}'.format(
cmd=command,
code=result.exit_code,
stdout=result.stdout_brief,
stderr=result.stderr_brief
code=result.exit_code
)),
))
])
self.assertIn(
mock.call.poll(), popen_obj.mock_calls
)
@ -125,22 +126,23 @@ class TestSubprocessRunner(unittest.TestCase):
# noinspection PyTypeChecker
result = runner.execute(command, verbose=True)
logger.assert_has_calls((
mock.call.debug(
"Executing command: {!r}".format(command.rstrip())),
mock.call.debug(
'{cmd!r} execution results:\n'
'Exit code: {code!s}\n'
'STDOUT:\n'
'{stdout}\n'
'STDERR:\n'
'{stderr}'.format(
logger.assert_has_calls([
mock.call.info(
"\nExecuting command: {!r}".format(command.rstrip())),
] + [
mock.call.info(str(x.rstrip().decode('utf-8')))
for x in stdout_list
] + [
mock.call.error(str(x.rstrip().decode('utf-8')))
for x in stderr_list
] + [
mock.call.info(
'\n{cmd!r} execution results: '
'Exit code: {code!s}'.format(
cmd=command,
code=result.exit_code,
stdout=result.stdout_str,
stderr=result.stderr_str
)),
))
])
@mock.patch('devops.helpers.subprocess_runner.logger', autospec=True)