[Kimchi-devel] [PATCH] [Wok 3/7] Update Request Logger to handle AsyncTask status
Lucio Correia
luciojhc at linux.vnet.ibm.com
Thu Sep 1 16:31:50 UTC 2016
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.
>
>>>
>>>> + # 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