def newf(f, self, *args, **kw):
''' wrapper '''
errMsg = None
startTs = time.time() * 1000
try:
result = f(self, *args, **kw)
return result
except BaseException as excep:
errMsg = 'Error status (%s) - %s' % (excep, traceback.format_exc(2))
raise excep
finally:
#log
msg = []
corId = contextutils.getcontext(self, 'guid')
calTitle = contextutils.getcontext(self, 'caltitle')
calBody = contextutils.popcontext(self, 'calbody')
remoteAddr = contextutils.popcontext(self, 'remote_addr')
#construct message
msg.append('%s - %s' % ('correlationid', xstr(corId)))
msg.append('%s - %s' % ('request', xstr(calTitle)))
msg.append('%s - %s' % ('response', xstr(calBody)))
msg.append('%s - %s' % ('remoteAddr', xstr(remoteAddr)))
if errMsg:
msg.append('%s - %s' % ('errMsg', xstr(errMsg)))
apiTime = time.time() * 1000 - startTs
msg.append('API time: %.2fms' % apiTime)
if apiTime > 3000:
msg.append('Tags: LongAPI')
APILOG.info('\n' + ','.join(msg))
def newf(f, self, *args, **kw):
''' wrapper '''
errMsg = None
startTs = time.time() * 1000
try:
result = f(self, *args, **kw)
return result
except BaseException as excep:
errMsg = 'Error status (%s) - %s' % (excep,
traceback.format_exc(2))
raise excep
finally:
#log
msg = []
corId = contextutils.getcontext(self, 'guid')
calTitle = contextutils.getcontext(self, 'caltitle')
calBody = contextutils.popcontext(self, 'calbody')
remoteAddr = contextutils.popcontext(self, 'remote_addr')
#construct message
msg.append('%s - %s' % ('correlationid', xstr(corId)))
msg.append('%s - %s' % ('request', xstr(calTitle)))
msg.append('%s - %s' % ('response', xstr(calBody)))
msg.append('%s - %s' % ('remoteAddr', xstr(remoteAddr)))
if errMsg:
msg.append('%s - %s' % ('errMsg', xstr(errMsg)))
apiTime = time.time() * 1000 - startTs
msg.append('API time: %.2fms' % apiTime)
if apiTime > 3000:
msg.append('Tags: LongAPI')
APILOG.info('\n' + ','.join(msg))
def beforeRun(self):
""" set external timeout values if any """
# set timeout
if contextutils.existcontext(self, 'thread_timeout'):
self._timeout = contextutils.getcontext(self, 'thread_timeout', self._timeout)
if contextutils.existcontext(self, 'thread_progress_timeout'):
self._progressTimeout = contextutils.getcontext(self, 'thread_progress_timeout', self._progressTimeout)
def beforeRun(self):
""" set external timeout values if any """
# set timeout
if contextutils.existcontext(self, 'thread_timeout'):
self._timeout = contextutils.getcontext(self, 'thread_timeout', self._timeout)
if contextutils.existcontext(self, 'thread_progress_timeout'):
self._progressTimeout = contextutils.getcontext(self, 'thread_progress_timeout', self._progressTimeout)
def testContextUtils(self):
sc = SomeClass()
contextutils.injectcontext(sc, {'guid':'test-guid'})
assert contextutils.existcontext(sc, 'guid')
assert not contextutils.existcontext(sc, 'guid1')
assert contextutils.getcontext(sc, 'guid1', 'test-guid1') == 'test-guid1'
assert contextutils.getcontext(sc, 'guid') == 'test-guid'
contextutils.injectcontext(sc, {'guid':'new-guid'})
assert contextutils.getcontext(sc, 'guid') == 'new-guid'
assert contextutils.popcontext(sc, 'guid') == 'new-guid'
assert not contextutils.existcontext(sc, 'guid')
def testContextUtils(self):
sc = SomeClass()
contextutils.injectcontext(sc, {'guid': 'test-guid'})
assert contextutils.existcontext(sc, 'guid')
assert not contextutils.existcontext(sc, 'guid1')
assert contextutils.getcontext(sc, 'guid1',
'test-guid1') == 'test-guid1'
assert contextutils.getcontext(sc, 'guid') == 'test-guid'
contextutils.injectcontext(sc, {'guid': 'new-guid'})
assert contextutils.getcontext(sc, 'guid') == 'new-guid'
assert contextutils.popcontext(sc, 'guid') == 'new-guid'
assert not contextutils.existcontext(sc, 'guid')
def getServiceLogger(source, logger, servicename=None):
''' add a log handler for a specific __service to an existing logger, handler is cached
@param __service: __service name
@param logger: an existing logger to add handler to
'''
assert logger is not None
# only deal with Logger, not LogAdaptor
if not isinstance(logger, logging.Logger):
return logger
# __service name
service = servicename if servicename is not None else getcontext(source, '__service', None)
if 'agent' == service:
return logger
elif LOGHDLRS.has_key(service):
hdlr = LOGHDLRS.get(service)
elif service in getServices():
hdlr = __initServiceLogHandler(service)
else:
return logger
logger.addHandler(hdlr)
return logging.LoggerAdapter(logger, {'__service' : service})
def getServiceLogger(source, logger, servicename=None):
''' add a log handler for a specific __service to an existing logger, handler is cached
@param __service: __service name
@param logger: an existing logger to add handler to
'''
assert logger is not None
# only deal with Logger, not LogAdaptor
if not isinstance(logger, logging.Logger):
return logger
# __service name
service = servicename if servicename is not None else getcontext(source, '__service', None)
if 'agent' == service:
return logger
elif LOGHDLRS.has_key(service):
hdlr = LOGHDLRS.get(service)
elif service in getServices():
hdlr = __initServiceLogHandler(service)
else:
return logger
logger.addHandler(hdlr)
return logging.LoggerAdapter(logger, {'__service' : service})
def doRun(self):
""" run - exec the thread and parse the results """
display_cmd = ''
outputLogged = False
try:
serviceFromPath = manifestutil.serviceFromPath(self.__cmd, 'agent')
self.__service = contextutils.getcontext(self, 'service', serviceFromPath)
self.__LOG = manifestutil.getServiceLogger(self, logging.getLogger(__name__), self.__service)
self.log("Exec Thread running, cmd=%s" % self.__cmd)
closeFds = readall = True
# context injection via environment variables
if self.__injectctx:
cronusapp_home = str(manifestutil.servicePath(self.__service))
correlation_id = str(contextutils.getcontext(self, 'guid', ''))
authz_token = str(contextutils.getcontext(self, 'authztoken', ''))
env_variables = 'SERVICE_NAME=%s CRONUSAPP_HOME=%s CORRELATIONID=%s AUTHZTOKEN=%s' % (
self.__service, cronusapp_home, correlation_id, authz_token)
if self.__service:
lcmMetas = serviceutil.getLcmMetas(self.__service)
if lcmMetas:
for key, value in lcmMetas.items():
env_variables += (' %s=%s' % (key.upper(), value))
if isinstance(self.__cmd, basestring):
cmd_0 = str(self.__cmd)
if (cmd_0.find('sudo -u') >= 0): # as we have problem setting environment variables for sudo as root
cmd_0 = cmd_0.replace("sudo", ("sudo %s" % env_variables), 1)
self.__cmd = cmd_0
display_cmd = cmd_0.split(os.path.sep)[-1]
else:
cmd_0 = self.__cmd[0]
if (cmd_0 == 'sudo' and '-u' in self.__cmd): # as we have problem setting environment variables for sudo as root
for env_variable in env_variables.split(' ')[::-1]:
self.__cmd.insert(1, env_variable)
display_cmd = self.__cmd[-1].split(os.path.sep)[-1]
threadName = 'exec_thread(%s)' % display_cmd
# execute
self.__cmdProcess = subprocess.Popen(self.__cmd, stdout = subprocess.PIPE, stderr = subprocess.PIPE, close_fds = closeFds)
self.logExecOutput('%s uuid start ' % (self.getUuid()))
outputLogged = True
self.logExecOutput('cmd: %s' % (self.__cmd if isinstance(self.__cmd, basestring)
else (' '.join(self.__cmd))))
# in case we don't get any results
self.__response = {'progress': 0.0, 'result': None}
self.log('cmd(%s) output:' % display_cmd)
while True:
self._checkStop(threadName = threadName)
stopped = (self.__cmdProcess.poll() != None)
# read from stdout, if process completes, read all from stdout
lines = self.readStream(self.__cmdProcess.stdout, readall = readall)
if (not lines and stopped):
break
self.__outputlines.extend(lines)
for line in lines:
self.processExecResponse(line)
self.log(line)
if (not lines):
time.sleep(float(config['exec_thread_sleep_time']))
if self.__outputlines:
self.logExecOutput('\n'.join(self.__outputlines))
# maybe the script just closed stdout
# wait until the script finishes
while (self.__cmdProcess.poll() == None):
self._checkStop(threadName = threadName)
time.sleep(float(config['exec_thread_sleep_time']))
if self.__partial:
self.processExecResponse(self.__partial)
self.logExecOutput(self.__partial)
self.log(self.__partial)
self.log('cmd(%s) output done' % display_cmd)
returnCode = self.__cmdProcess.poll()
self.logExecOutput('exitcode: %s' % returnCode)
# the error condition
if (returnCode != 0):
self._updateStatus(httpStatus = 500)
# read from stderr and log
if self.__cmdProcess.stderr is not None:
lines = self.readStream(self.__cmdProcess.stderr)
for line in lines:
self.processExecResponse(line)
if lines:
self.logExecOutput('stderr: %s' % '\n'.join(lines))
self.log('cmd(%s) stderr: %s' % (display_cmd, '\n'.join(lines)))
self.__LOG.warning(self.__response)
errorCode = int(self.__response['error']) if 'error' in self.__response else returnCode
msg = 'Application script error (%s) error code (%d) error msg (%s)' % (self.__cmd, errorCode,
(self.__response['errorMsg'] if 'errorMsg' in self.__response else ''))
self.__LOG.warning(msg)
# now add 16000 to the error code to indicate this is a client error
clientErrorCode = Errors.CLIENT_SCRIPT_ERROR + abs(errorCode)
self._updateStatus(error = clientErrorCode, errorMsg = msg)
else:
self._updateStatus(httpStatus = 200)
if 'result' in self.__response:
self._updateStatus(result = self.__response['result'])
except SystemExit as excep:
# status already set in agent thread
msg = "System Exception for cmd %s - %s" % (self.__cmd, self.getStatus()['errorMsg'])
self.__LOG.warning("%s - %s" % (msg, str(excep)))
raise excep
except OSError as excep:
if self.__cmdProcess is None:
msg = 'Cannot create subprocess cmd(%s) %s - %s' % (self.__cmd, str(excep), traceback.format_exc(2))
else:
msg = 'Unknown OSError cmd(%s) %s - %s' % (self.__cmd, str(excep), traceback.format_exc(2))
self.__LOG.warning(msg)
self._updateStatus(httpStatus = 500, error = Errors.UNKNOWN_ERROR, errorMsg = msg)
except Exception as excep:
msg = 'Unknown error cmd(%s) %s - %s' % (self.__cmd, str(excep), traceback.format_exc(2))
self.__LOG.warning(msg)
self._updateStatus(httpStatus = 500, error = Errors.UNKNOWN_ERROR, errorMsg = msg)
finally:
self._updateStatus(progress = 100)
if self.__cmdProcess:
if (self.__cmdProcess.stdout != None):
self.__cmdProcess.stdout.close()
if (self.__cmdProcess.stdin != None):
self.__cmdProcess.stdin.close()
if (self.__cmdProcess.stderr != None):
self.__cmdProcess.stderr.close()
self.kill(self.__cmdProcess, self.__cmd)
if outputLogged:
self.logExecOutput('%s uuid end' % (self.getUuid()))
self.log("Exec Thread done, cmd=%s" % self.__cmd)
def doRun(self):
""" run - exec the thread and parse the results """
display_cmd = ''
try:
self.__LOG.debug("Exec Thread running %s" % self.__cmd)
closeFds = readall = True
service = manifestutil.serviceFromPath(self.__cmd)
cronusapp_home = ''
if (service != None and len(service) > 0):
cronusapp_home = str(manifestutil.servicePath(service))
elif (contextutils.existcontext(self, 'service')):
service = str(contextutils.getcontext(self, 'service'))
cronusapp_home = str(manifestutil.servicePath(service))
correlation_id = str(contextutils.getcontext(self, 'guid', ''))
env_variables = 'CRONUSAPP_HOME=%s LCM_CORRELATIONID=%s' % (cronusapp_home, correlation_id)
if isinstance(self.__cmd, basestring):
cmd_0 = str(self.__cmd)
if (cmd_0.find('sudo -u') >= 0): # as we have problem setting environment variables for sudo as root
cmd_0 = cmd_0.replace("sudo", ("sudo %s" % env_variables), 1)
self.__cmd = cmd_0
display_cmd = cmd_0.split(os.path.sep)[-1]
else:
cmd_0 = self.__cmd[0]
if (cmd_0 == 'sudo' and '-u' in self.__cmd): # as we have problem setting environment variables for sudo as root
for env_variable in env_variables.split(' ')[::-1]:
self.__cmd.insert(1, env_variable)
display_cmd = self.__cmd[-1].split(os.path.sep)[-1]
threadName = 'exec_thread(%s)' % display_cmd
self.__cmdProcess = subprocess.Popen(self.__cmd, stdout = subprocess.PIPE, stderr = subprocess.PIPE, close_fds = closeFds)
# in case we don't get any results
self.__response = {'progress': 100, 'result': None}
if 'info' == self.__logLevel:
self.__LOG.info("started Exec Thread..., cmd=%s" % self.__cmd)
outputlines = []
while True:
self._checkStop(threadName = threadName)
stopped = (self.__cmdProcess.poll() != None)
# read from stdout, if process completes, read all from stdout
lines = self.readStream(self.__cmdProcess.stdout, readall = readall)
if (not lines and stopped):
break
outputlines.extend(lines)
if 'info' == self.__logLevel and lines:
self.__LOG.info('cmd(%s) output:' % display_cmd)
for line in lines:
self.__LOG.info(line)
else:
self.__LOG.debug('cmd(%s) output:' % display_cmd)
for line in lines:
self.__LOG.debug(line)
for line in lines:
self.processExecResponse(line)
if (not lines):
time.sleep(float(config['exec_thread_sleep_time']))
if 'info' == self.__logLevel and outputlines:
OUTPUTLOG.info('%s output start %s %s output end' % (self.getUuid(), '\\n'.join(outputlines), self.getUuid()))
# maybe the script just closed stdout
# wait until the script finishes
while (self.__cmdProcess.poll() == None):
self._checkStop(threadName = threadName)
time.sleep(float(config['exec_thread_sleep_time']))
returnCode = self.__cmdProcess.poll()
# the error condition
if (returnCode != 0):
self._updateStatus(httpStatus = 500)
# read from stderr and log
if self.__cmdProcess.stderr is not None:
lines = self.readStream(self.__cmdProcess.stderr)
for line in lines:
self.processExecResponse(line)
self.__LOG.info('cmd(%s) stderr: %s' % (display_cmd, line))
self.__LOG.warning(self.__response)
errorCode = int(self.__response['error']) if 'error' in self.__response else returnCode
msg = 'Application script error (%s) error code (%d) error msg (%s)' % (self.__cmd, errorCode,
(self.__response['errorMsg'] if 'errorMsg' in self.__response else ''))
self.__LOG.warning(msg)
# now add 16000 to the error code to indicate this is a client error
clientErrorCode = Errors.CLIENT_SCRIPT_ERROR + abs(errorCode)
self._updateStatus(error = clientErrorCode, errorMsg = msg)
else:
self._updateStatus(httpStatus = 200)
if 'result' in self.__response:
self._updateStatus(result = self.__response['result'])
self._updateStatus(progress = 100)
except SystemExit as excep:
# status already set in agent thread
msg = "System Exception for cmd %s - %s" % (self.__cmd, self.getStatus()['errorMsg'])
self.__LOG.warning("%s - %s" % (msg, str(excep)))
raise excep
except OSError as excep:
if self.__cmdProcess is None:
msg = 'Cannot create subprocess cmd(%s) %s - %s' % (self.__cmd, str(excep), traceback.format_exc(2))
else:
msg = 'Unknown OSError cmd(%s) %s - %s' % (self.__cmd, str(excep), traceback.format_exc(2))
self.__LOG.warning(msg)
self._updateStatus(httpStatus = 500, error = Errors.UNKNOWN_ERROR, errorMsg = msg)
except Exception as excep:
msg = 'Unknown error cmd(%s) %s - %s' % (self.__cmd, str(excep), traceback.format_exc(2))
self.__LOG.warning(msg)
self._updateStatus(httpStatus = 500, error = Errors.UNKNOWN_ERROR, errorMsg = msg)
finally:
if self.__cmdProcess:
if (self.__cmdProcess.stdout != None):
self.__cmdProcess.stdout.close()
if (self.__cmdProcess.stdin != None):
self.__cmdProcess.stdin.close()
if (self.__cmdProcess.stderr != None):
self.__cmdProcess.stderr.close()
self.kill(self.__cmdProcess, self.__cmd)
self.__LOG.debug("Exec Thread %s done" % self.__cmd)
except Exception, excep:
LOG.error('Thread(%s / %s) Caught ThreadMgr Exception - exiting (%s) - %s' % (self.__name, self.__uuid, excep, traceback.format_exc(5)))
thread.exit()
finally:
# doesn't hurt set twice since this event is telling whether it's registered by threadMgr
self.threadMgrEvent.set()
# calculate execution time
executionMsec = time.time() * 1000 - self.__executionMsec
self.__status['executionMsec'] = int(executionMsec)
# log to uuid, only for user facing threads
if self.__cat is not None:
msg = json.dumps(self.status2msg())
thtype = self.__class__.__name__
guid = contextutils.getcontext(self, 'guid', 'na')
UUIDLOG.info('%s output start type=%s, status=%s, guid=%s %s output end' % (self.__uuid, thtype, msg, guid, self.__uuid))
def status2msg(self):
""" status to msg for logging """
res = {}
if (self.__status['executionMsec'] != None):
res['executionMsec'] = self.__status['executionMsec']
if (self.__status['result'] != None):
res['result'] = self.__status['result']
# check if the result is an error not not
if (self.__status['error'] == None):
res['progress'] = self.__status['progress']
