* 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@linux.vnet.ibm.com> --- src/wok/reqlogger.py | 175 ++++++++++++++++++++++++++++++++------------------- 1 file changed, 112 insertions(+), 63 deletions(-) diff --git a/src/wok/reqlogger.py b/src/wok/reqlogger.py index b675478..69ea22b 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 @@ -64,11 +65,38 @@ 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): + ''' + Add an entry to user request log + + @param settings + base Measurement base, accepts 2 or 10. defaults to 2. + unit The unit of the measurement, e.g., B, Bytes/s, bps, etc. + @param code message code (ending with L) for the request made by user + @param params templating parameters for the message referred by code + @param exception None if no exception, or a dict containing + code error message code (ending with E, I or W) + params templating parameters for the message referred by code + @param method the string corresponding to HTTP method (GET, PUT, POST, + DELETE) or the string 'TASK', meaning a log entry to track completion + of an asynchronous task. 'TASK' log entries are not visible to user. + @param status HTTP request status code + @param app the root URI of the mounted cherrypy application. Defaults to + cherrypy request application + @param user the logged in user that made the request. Defaults to cherrypy + request user + @param ip the IP address of the user that made the request. Defaults to + cherrypy request remote IP address + + @returns ID of log entry + ''' if app is None: - app = cherrypy.request.app.root.domain + app = cherrypy.request.app.script_name if user is None: user = cherrypy.session.get(USER_NAME, 'N/A') @@ -140,20 +168,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 - - msg = WokMessage(code, params, plugin) + def getTranslatedMessage(self, message, error, app_root): + code = message.get('code', '') + params = message.get('params', {}) + msg = WokMessage(code, params, app_root) 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, app_root) + text += ' (%s)' % msg.get_text(prepend_code=True, translate=True) return text @@ -163,8 +188,46 @@ 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) + uri = record['info']['app'] + text = self.getTranslatedMessage(message, error, uri) + record['info']['message'] = text + + # get user-friendly app name + app_name = 'wok' + app = cherrypy.tree.apps.get(uri) + if app: + app_name = app.root.domain + + record['info']['app'] = app_name + + 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 +240,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 +284,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 +318,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