[Kimchi-devel] [PATCH] [Wok 3/7] Update Request Logger to handle AsyncTask status
Lucio Correia
luciojhc at linux.vnet.ibm.com
Thu Sep 1 17:27:18 UTC 2016
On 01-09-2016 13:48, Aline Manera wrote:
>
>
> On 09/01/2016 01:31 PM, Lucio Correia wrote:
>> 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 at linux.vnet.ibm.com>
>>>>>> ---
>>>>>> 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.
>>
>
> I'd say to do not mix things. A parameter related to HTTP methods should
> not handle any other information.
> Why do not use the status code? Wouldn't be the status code used by UI
> to update the information to user?
The TASK type log entries are not in the final log - UI does not see
them. They are filtered by backend before, exactly what this code is
doing here.
In the task log entry, I use status=200 or status=400 (see async task
_log() usage) to mean success or failure, and here I use that value to
update the original request log entry (which contains 202 until task
finishes).
>
>>
>>>
>>>>>
>>>>>> + # 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
>>>>>
>>>>
>>>>
>>>
>>
>>
>
--
Lucio Correia
Software Engineer
IBM LTC Brazil
More information about the Kimchi-devel
mailing list