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