[Kimchi-devel] [PATCH] [Wok 3/6] Update Request Logger to handle AsyncTask status

* Add ID to each entry * Change log entry format to one JSON per line * Modify getRecords() to apply AsyncTask entry status to original request entry * Use plugin_root to fix issue in plugin lookup Signed-off-by: Lucio Correia <luciojhc(a)linux.vnet.ibm.com&gt; --- src/wok/reqlogger.py | 142 +++++++++++++++++++++++++++++---------------------- 1 file changed, 80 insertions(+), 62 deletions(-) diff --git a/src/wok/reqlogger.py b/src/wok/reqlogger.py index b675478..2dcfd05 100644 --- a/src/wok/reqlogger.py +++ b/src/wok/reqlogger.py @@ -25,6 +25,7 @@ import logging import logging.handlers import os.path import time +import uuid from cherrypy.process.plugins import BackgroundTask from tempfile import NamedTemporaryFile @@ -34,7 +35,7 @@ from wok.config import config, get_log_download_path from wok.exception import InvalidParameter, OperationFailed from wok.message import WokMessage from wok.stringutils import ascii_dict -from wok.utils import remove_old_files +from wok.utils import plugin_root, remove_old_files # Log search setup @@ -64,6 +65,9 @@ UNSAFE_REQUEST_PARAMETERS = ['password', 'passwd'] REQUEST_LOG_FILE = "wok-req.log" WOK_REQUEST_LOGGER = "wok_request_logger" +# AsyncTask handling +ASYNCTASK_REQUEST_METHOD = 'TASK' + def log_request(code, params, exception, method, status, app=None, user=None, ip=None): @@ -140,20 +144,18 @@ class RequestParser(object): return LOG_DOWNLOAD_URI % os.path.basename(fd.name) - def getTranslatedMessage(self, record, params, detParams): - code = record.get('msgCode', '') - app = record.get('app', 'wok') - plugin = None - if app != 'wok': - plugin = "/plugins/%s" % app - + def getTranslatedMessage(self, message, error, app): + plugin = plugin_root.get(app, None) + code = message.get('code', '') + params = message.get('params', {}) msg = WokMessage(code, params, plugin) text = msg.get_text(prepend_code=False, translate=True) - detCode = record.get('detCode', '') - if detCode: - msg = WokMessage(detCode, detParams, plugin) - text += ' ' + msg.get_text(prepend_code=True, translate=True) + if error: + code = error.get('code', '') + params = error.get('params', {}) + msg = WokMessage(code, params, plugin) + text += ' (%s)' % msg.get_text(prepend_code=True, translate=True) return text @@ -163,8 +165,38 @@ class RequestParser(object): for filename in glob.glob(self.baseFile + "-*[!.gz]"): records.extend(self.getRecordsFromFile(filename)) - # Return ordered by latest events first - return sorted(records, key=lambda k: k['date'] + k['time'], + # normalize entries + normalized = {} + asynctask_updates = [] + for record in records: + # because async tasks run in another thread, their record entry + # may be recorded before original request record. Since we use + # them to just update original request record, do it afterwards + if record['info']['req'] == ASYNCTASK_REQUEST_METHOD: + asynctask_updates.append(record) + continue + + # initial request entry: generate translated message text + message = record.pop('message') + error = record.pop('error', None) + app = record['info']['app'] + text = self.getTranslatedMessage(message, error, app) + record['info']['message'] = text + + id = record.pop('id') + normalized[id] = record['info'] + + # time to update original records based on async task records + for record in asynctask_updates: + id = record.pop('id') + + # task id may not exist, since GET requests are not logged but + # may generate tasks (i.e. AsyncResource) + if id in normalized: + normalized[id]['status'] = record['info']['status'] + + # return results in chronological reverse order + return sorted(normalized.values(), key=lambda k: k['date'] + k['time'], reverse=True) def getRecordsFromFile(self, filename): @@ -177,34 +209,12 @@ class RequestParser(object): if not os.path.exists(filename): return [] - # read records from file try: with open(filename) as f: line = f.readline() while line != "": - data = line.split(">>>") - if len(data) > 1: - record = json.JSONDecoder().decode(data[0]) - - if len(data) > 2: - # new log format: translate message on the fly - params = json.JSONDecoder().decode(data[1]) - detParams = None - - # has original exception details - if len(data) > 3: - detParams = json.JSONDecoder().decode(data[2]) - - msg = self.getTranslatedMessage(record, params, - detParams) - else: - # make it compatible with v2.2 log files, which - # messages are already translated - msg = data[1].strip() - - record['message'] = msg - records.append(record) - + record = json.JSONDecoder().decode(line) + records.append(record) line = f.readline() f. close() @@ -243,20 +253,32 @@ class RequestParser(object): class RequestRecord(object): - def __init__(self, msgParams, details, **kwargs): - # log record data - self.logData = kwargs - self.details = details - + def __init__(self, message, error, id=None, **kwargs): # data for message translation - self.code = self.logData['msgCode'] - self.params = self.getSafeReqParams(msgParams) - - # register timestamp in local time + self.message = { + 'code': message['code'], + 'params': self.getSafeReqParams(message['params']), + } + + # data for error translation (WokException) + self.error = None + if error: + self.error = { + 'code': error.code, + 'params': error.params, + } + + # log entry info + self.id = id or str(uuid.uuid4()) + self.info = kwargs + + # generate timestamp timestamp = time.localtime() - self.logData['date'] = time.strftime(TS_DATE_FORMAT, timestamp) - self.logData['time'] = time.strftime(TS_TIME_FORMAT, timestamp) - self.logData['zone'] = time.strftime(TS_ZONE_FORMAT, timestamp) + self.info.update({ + 'date': time.strftime(TS_DATE_FORMAT, timestamp), + 'time': time.strftime(TS_TIME_FORMAT, timestamp), + 'zone': time.strftime(TS_ZONE_FORMAT, timestamp), + }) def getSafeReqParams(self, params): result = params.copy() @@ -265,20 +287,16 @@ class RequestRecord(object): return result def __str__(self): - # original exception details - details = '' - if self.details: - self.logData['detCode'] = self.details.code - details = ">>> %s" % json.JSONEncoder().encode(self.details.params) - - # request log message - msg = WokMessage(self.code, self.params) - msgText = msg.get_text(prepend_code=False, translate=False) - logData = json.JSONEncoder().encode(self.logData) - msgParams = json.JSONEncoder().encode(self.params) + entry = { + "id": self.id, + "message": self.message, + "error": self.error, + "info": self.info, + } - return '%s >>> %s %s >>> %s' % (logData, msgParams, details, msgText) + return json.JSONEncoder().encode(entry) def log(self): reqLogger = logging.getLogger(WOK_REQUEST_LOGGER) reqLogger.info(self) + return self.id -- 1.9.1