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

On 01-09-2016 13:19, Aline Manera wrote: > > > On 09/01/2016 12:56 PM, Lucio Correia wrote: >> On 01-09-2016 10:35, Aline Manera wrote: >>> >>> >>> On 08/31/2016 06:06 PM, Lucio Correia wrote: >>>> * 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 >>>> >>>> Signed-off-by: Lucio Correia <luciojhc(a)linux.vnet.ibm.com&gt; >>>> --- >>>> src/wok/message.py | 2 +- >>>> src/wok/reqlogger.py | 142 >>>> +++++++++++++++++++++++++++++---------------------- >>>> 2 files changed, 82 insertions(+), 62 deletions(-) >>>> >>>> diff --git a/src/wok/message.py b/src/wok/message.py >>>> index ff4cbc9..28462b7 100644 >>>> --- a/src/wok/message.py >>>> +++ b/src/wok/message.py >>>> @@ -51,7 +51,7 @@ class WokMessage(object): >>>> wok_app = cherrypy.tree.apps.get('', None) >>>> >>>> # get app from plugin path if specified >>> >>>> - if self.plugin: >>>> + if self.plugin and self.plugin != 'wok': >>> >>> Why is that needed? Why wok is different from the rest of the >>> application? >> >> This is consequence of returning 'wok' as default instead of None in >> get_plugin_from_request. I will rethink it in case I can return None >> there. >> >>> >>>> app = cherrypy.tree.apps.get(self.plugin, None) >>>> # if on request, try to get app from it >>>> elif cherrypy.request.app: >>>> diff --git a/src/wok/reqlogger.py b/src/wok/reqlogger.py >>>> index 9f1d2c8..2923d7c 100644 >>>> --- a/src/wok/reqlogger.py >>>> +++ b/src/wok/reqlogger.py >>>> @@ -24,6 +24,7 @@ import logging >>>> import logging.handlers >>>> import os.path >>>> import time >>>> +import uuid >>>> >>>> from cherrypy.process.plugins import BackgroundTask >>>> from tempfile import NamedTemporaryFile >>>> @@ -32,7 +33,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 >>>> @@ -62,6 +63,9 @@ UNSAFE_REQUEST_PARAMETERS = ['password', 'passwd'] >>>> REQUEST_LOG_FILE = "wok-req.log" >>>> WOK_REQUEST_LOGGER = "wok_request_logger" >>> >>> >>>> +# AsyncTask handling >>>> +ASYNCTASK_REQUEST_METHOD = 'TASK' >>>> + >>> >>> I am curious to see how this constant is used. >>> >>>> class RequestLogger(object): >>>> def __init__(self): >>>> @@ -114,19 +118,17 @@ 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, 'wok') >>> >>> Do not set 'wok' as plugin name. It is not true as wok is not a >>> plugin. >> >> The var is named plugin but it means app.. wok or any plugin. I may >> change the variable name. >> >>> >>>> + 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) >>>> + if error: >>>> + code = error.get('code', '') >>>> + params = error.get('params', {}) >>>> + msg = WokMessage(code, params, plugin) >>>> text += ' ' + msg.get_text(prepend_code=True, >>>> translate=True) >>>> >>>> return text >>>> @@ -137,8 +139,40 @@ 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'], >>>> + # sort records chronologically >>>> + sort = sorted(records, key=lambda k: k['info']['date'] + >>>> + k['info']['time']) >>>> + >>> >>>> + # normalize entries >>>> + normalized = {} >>>> + asynctask_updates = [] >>>> + for record in sort: >>> >>>> + # async task entries are left to the end >>> >>> Why? >> >> Because they are just updates to the original request log entry. And >> the task log entry may be written before the task finishes since runs >> in separate thread. >> > > Ok. Please, add more comments related to that so it is easy to > understand the code proposal. OK > >>> >>>> + if record['info']['req'] == ASYNCTASK_REQUEST_METHOD: >>>> + asynctask_updates.append(record) >>>> + continue >>>> + >>> >>> Could you explain why do we need to add an specific 'req' information >>> for task? >> >> I use it to differentiate task finish log entries from regular request >> log entries. >> >> > > You can use the status parameter for that. We don't need an extra > parameter. I'm not creating a new parameter, I'm using method (request type) instead of status. So instead of POST, PUT, it will be TASK. It's the same right? Or there is a reason to not use request type? This is not showed to the user.

> >>> >>>> + # initial request entry: generate message text >>>> + message = record.pop('message') >>>> + error = record.pop('error', None) >>>> + plugin = record['info']['app'] >>>> + text = self.getTranslatedMessage(message, error, plugin) >>>> + record['info']['message'] = text >>>> + >>>> + id = record.pop('id') >>>> + normalized[id] = record['info'] >>>> + >>>> + # async task entries: update only status >>>> + 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): >>>> @@ -151,34 +185,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() >>>> @@ -217,20 +229,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() >>>> @@ -239,20 +263,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 >>> >> >> >