Commandline client environment variable setting and logging updates.
* Adds update_environment_variables() to update internal os_env_var dictionary after instantiation. * Adds run_async_command() method to run a command and immediately return a process object instead of waiting for the process output. * Modifies run_command to use run_async_command(). * For each request, logs the intersection of all environment variables that are present in the environment and that have been set in the environment by the client. * Cleans up log line formatting. Change-Id: I845bfaf9de096fbfe523722e5a21c1b6dde76363
This commit is contained in:
Jose Idar
@@ -22,6 +22,10 @@ from collections import OrderedDict
|
||||
log = logging.getLogger('RunnerLog')
|
||||
|
||||
|
||||
def logsafe_str(data):
|
||||
return "{0}".format(data).decode('utf-8', 'replace')
|
||||
|
||||
|
||||
def get_object_namespace(obj):
|
||||
'''Attempts to return a dotted string name representation of the general
|
||||
form 'package.module.class.obj' for an object that has an __mro__ attribute
|
||||
@@ -194,9 +198,10 @@ def init_root_log_handler():
|
||||
|
||||
|
||||
def log_info_block(
|
||||
log, info, separator=None, heading=None, log_level=logging.INFO):
|
||||
log, info, separator=None, heading=None, log_level=logging.INFO,
|
||||
one_line=False):
|
||||
"""Expects info to be a list of tuples or an OrderedDict
|
||||
Logs info as individual lines in blocks surrounded by a separator:
|
||||
Logs info in blocks surrounded by a separator:
|
||||
====================================================================
|
||||
A heading will print here, with another separator below it.
|
||||
====================================================================
|
||||
@@ -207,28 +212,36 @@ def log_info_block(
|
||||
Lower lines will still line up correctly.................: Info
|
||||
The longest line dictates the dot length for all lines...: Like this
|
||||
====================================================================
|
||||
if one_line is true, info block will be logged as a single line, formatted
|
||||
using newlines. Otherwise, each line of the info block will be logged
|
||||
as seperate log lines (with seperate timestamps, etc.)
|
||||
"""
|
||||
output = []
|
||||
try:
|
||||
info = info if isinstance(info, OrderedDict) else OrderedDict(info)
|
||||
except:
|
||||
#Something went wrong, log what can be logged
|
||||
log.log(log_level, str(info))
|
||||
output.append(str(info))
|
||||
return
|
||||
|
||||
separator = str(separator or "{0}".format('=' * 56))
|
||||
max_length = len(max([k for k in info.keys() if info.get(k)], key=len))+3
|
||||
|
||||
log.log(log_level, separator)
|
||||
output.append(separator)
|
||||
if heading:
|
||||
log.info(heading)
|
||||
log.log(log_level, separator)
|
||||
output.append(heading)
|
||||
output.append(separator)
|
||||
|
||||
for k in info:
|
||||
value = str(info.get(k, None))
|
||||
if value:
|
||||
log.log(log_level, "{0}{1}: {2}".format(
|
||||
k, "." * (max_length-len(k)), value))
|
||||
output.append(
|
||||
"{0}{1}: {2}".format(k, "." * (max_length-len(k)), value))
|
||||
else:
|
||||
log.log(log_level, "{0}".format(k))
|
||||
output.append("{0}".format(k))
|
||||
output.append(separator)
|
||||
|
||||
log.log(log_level, separator)
|
||||
if one_line:
|
||||
log.log(log_level, "\n{0}".format("\n".join(output)))
|
||||
else:
|
||||
[log.log(log_level, line) for line in output]
|
||||
|
||||
@@ -20,10 +20,12 @@ limitations under the License.
|
||||
'''
|
||||
import os
|
||||
import sys
|
||||
import subprocess
|
||||
from subprocess import Popen, PIPE, CalledProcessError
|
||||
|
||||
from cafe.engine.models.commandline_response import CommandLineResponse
|
||||
from cafe.common.reporting.cclogging import log_info_block, logsafe_str
|
||||
from logging import DEBUG
|
||||
from cafe.engine.clients.base import BaseClient
|
||||
from cafe.engine.models.commandline_response import CommandLineResponse
|
||||
|
||||
|
||||
class BaseCommandLineClient(BaseClient):
|
||||
@@ -46,9 +48,17 @@ class BaseCommandLineClient(BaseClient):
|
||||
|
||||
def set_environment_variables(self, env_var_dict=None):
|
||||
'''Sets all os environment variables provided in env_var_dict'''
|
||||
for key, value in env_var_dict.items():
|
||||
self.env_var_dict = env_var_dict
|
||||
for key, value in self.env_var_dict.items():
|
||||
self._log.debug('setting {0}={1}'.format(key, value))
|
||||
os.putenv(str(key), str(value))
|
||||
os.environ[str(key)] = str(value)
|
||||
|
||||
def update_environment_variables(self, env_var_dict=None):
|
||||
'''Sets all os environment variables provided in env_var_dict'''
|
||||
self.env_var_dict = self.env_var_dict.update(env_var_dict or {})
|
||||
for key, value in self.env_var_dict.items():
|
||||
self._log.debug('setting {0}={1}'.format(key, value))
|
||||
os.environ[str(key)] = str(value)
|
||||
|
||||
def unset_environment_variables(self, env_var_list=None):
|
||||
'''Unsets all os environment variables provided in env_var_dict
|
||||
@@ -60,6 +70,48 @@ class BaseCommandLineClient(BaseClient):
|
||||
self._log.debug('unsetting {0}'.format(key))
|
||||
os.unsetenv(str(key))
|
||||
|
||||
def _build_command(self, cmd, *args):
|
||||
#Process command we received
|
||||
command = "{0} {1}".format(
|
||||
self.base_command, cmd) if self.base_command else cmd
|
||||
if args and args[0]:
|
||||
for arg in args[0]:
|
||||
command += "{0} {1}".format(command, arg)
|
||||
|
||||
keys = set(os.environ).intersection(self.env_var_dict)
|
||||
set_env_vars = dict([(k, os.environ[k]) for k in keys])
|
||||
|
||||
info = [
|
||||
("command", logsafe_str(command)),
|
||||
("args", logsafe_str(args)),
|
||||
("set env vars", logsafe_str(set_env_vars))]
|
||||
|
||||
log_info_block(
|
||||
self._log, info, heading='COMMAND LINE REQUEST',
|
||||
log_level=DEBUG, one_line=True)
|
||||
|
||||
return command
|
||||
|
||||
def _execute_command(self, command):
|
||||
#Run the command
|
||||
process = None
|
||||
try:
|
||||
process = Popen(command, stdout=PIPE, stderr=PIPE, shell=True)
|
||||
except CalledProcessError as exception:
|
||||
self._log.exception(
|
||||
"Exception running commandline command {0}\n{1}".format(
|
||||
str(command), str(exception)))
|
||||
return process
|
||||
|
||||
def run_command_async(self, cmd, *args):
|
||||
"""Running a command asynchronously returns a CommandLineResponse
|
||||
objecct with a running subprocess.Process object in it. This process
|
||||
needs to be closed or killed manually after execution."""
|
||||
os_response = CommandLineResponse()
|
||||
os_response.command = self._build_command(cmd, *args)
|
||||
os_response.process = self._execute_command(os_response.command)
|
||||
return os_response
|
||||
|
||||
def run_command(self, cmd, *args):
|
||||
'''Sends a command directly to this instance's command line
|
||||
@param cmd: Command to sent to command line
|
||||
@@ -71,89 +123,30 @@ class BaseCommandLineClient(BaseClient):
|
||||
@rtype: L{CommandLineResponse}
|
||||
@note: PRIVATE. Can be over-ridden in a child class
|
||||
'''
|
||||
os_process = None
|
||||
os_response = CommandLineResponse()
|
||||
|
||||
#Process command we received
|
||||
os_response.command = "{0} {1}".format(
|
||||
self.base_command, cmd) if self.base_command else cmd
|
||||
if args and args[0]:
|
||||
for arg in args[0]:
|
||||
os_response.command += "{0} {1}".format(
|
||||
os_response.command, arg)
|
||||
|
||||
"""@TODO: Turn this into a decorator like the rest client"""
|
||||
try:
|
||||
logline = ''.join([
|
||||
'\n{0}\nCOMMAND LINE REQUEST\n{0}\n'.format('-' * 4),
|
||||
"args..........: {0}".format(args),
|
||||
"command.......: {0}".format(os_response.command)])
|
||||
except Exception as exception:
|
||||
self._log.exception(exception)
|
||||
|
||||
try:
|
||||
self._log.debug(logline.decode('utf-8', 'replace'))
|
||||
except Exception as exception:
|
||||
#Ignore all exceptions that happen in logging, then log them
|
||||
self._log.debug('\n{0}\nCOMMAND LINE REQUEST INFO\n{0}\n'.format(
|
||||
'-' * 12))
|
||||
self._log.exception(exception)
|
||||
|
||||
#Run the command
|
||||
try:
|
||||
os_process = subprocess.Popen(os_response.command,
|
||||
stdout=subprocess.PIPE,
|
||||
stderr=subprocess.PIPE,
|
||||
shell=True)
|
||||
except subprocess.CalledProcessError() as cpe:
|
||||
self._log.exception(
|
||||
"Exception running commandline command {0}\n{1}".format(
|
||||
str(os_response.command), str(cpe)))
|
||||
|
||||
#Wait for the process to complete and then read the lines.
|
||||
#for some reason if you read each line as the process is running
|
||||
#and use os_process.Poll() you don't always get all output
|
||||
std_out, std_err = os_process.communicate()
|
||||
os_response.return_code = os_process.returncode
|
||||
|
||||
#Pass the full output of the process_command back. It is important to
|
||||
#not parse, strip or otherwise massage this output in the private send
|
||||
#since a child class could override and contain actual command
|
||||
#processing logic.
|
||||
#Wait for the process to complete and then read the output
|
||||
os_response = self.run_command_async(cmd, *args)
|
||||
std_out, std_err = os_response.process.communicate()
|
||||
os_response.standard_out = str(std_out).splitlines()
|
||||
if std_err is not None:
|
||||
os_response.standard_error = str(std_err).splitlines()
|
||||
os_response.standard_error = str(std_err).splitlines()
|
||||
os_response.return_code = os_response.process.returncode
|
||||
|
||||
"""@TODO: Turn this into a decorator like in the rest client"""
|
||||
try:
|
||||
logline = ''.join([
|
||||
'\n{0}\nCOMMAND LINE RESPONSE\n{0}\n'.format('-' * 4),
|
||||
"standard out...: {0}".format(os_response.standard_out),
|
||||
"standard error.: {0}".format(os_response.standard_error),
|
||||
"return code....: {0}".format(os_response.return_code)])
|
||||
except Exception as exception:
|
||||
self._log.exception(exception)
|
||||
|
||||
try:
|
||||
self._log.debug(logline.decode('utf-8', 'replace'))
|
||||
except Exception as exception:
|
||||
#Ignore all exceptions that happen in logging, then log them
|
||||
self._log.debug('\n{0}\nCOMMAND LINE RESPONSE INFO\n{0}\n'.format(
|
||||
'-' * 12))
|
||||
self._log.exception(exception)
|
||||
info = [
|
||||
("return code", logsafe_str(os_response.return_code)),
|
||||
("standard out", logsafe_str("\n{0}".format(
|
||||
"\n".join(os_response.standard_out)))),
|
||||
("standard error", logsafe_str("\n{0}".format(
|
||||
"\n".join(os_response.standard_error))))]
|
||||
log_info_block(
|
||||
self._log, info, heading='COMMAND LINE RESPONSE',
|
||||
log_level=DEBUG, one_line=True)
|
||||
|
||||
#Clean up the process to avoid any leakage/wonkiness with stdout/stderr
|
||||
try:
|
||||
os_process.kill()
|
||||
os_response.process.kill()
|
||||
except OSError:
|
||||
#An OS Error is valid if the process has exited. We only
|
||||
#need to be concerned about other exceptions
|
||||
sys.exc_clear()
|
||||
except Exception, kill_exception:
|
||||
raise Exception(
|
||||
"Exception forcing %s Process to close: {0}".format(
|
||||
self.base_command, kill_exception))
|
||||
finally:
|
||||
del os_process
|
||||
|
||||
os_response.process = None
|
||||
return os_response
|
||||
|
||||
@@ -37,3 +37,4 @@ class CommandLineResponse(BaseModel):
|
||||
self.standard_out = []
|
||||
self.standard_error = []
|
||||
self.return_code = None
|
||||
self.process = None
|
||||
|
||||
Reference in New Issue
Block a user