[PATCH V4] [Wok 0/5] Issue #141 - Handle AsyncTasks in request log
V4: review comments (use app uri in log entry and document req='TASK' usage) V3: review comments V2: rebase with master to fix conflict Lucio Correia (5): Create log_request() method for code simplification Update Request Logger to handle AsyncTask status Log AsyncTask success or failure Save log entry IDs for requests that generate tasks Change location of User Requests Log src/wok/asynctask.py | 49 +++++++++-- src/wok/control/base.py | 63 +++++++-------- src/wok/control/utils.py | 1 - src/wok/i18n.py | 2 + src/wok/reqlogger.py | 205 ++++++++++++++++++++++++++++++++--------------- src/wok/root.py | 40 +-------- src/wok/utils.py | 12 --- 7 files changed, 218 insertions(+), 154 deletions(-) -- 1.9.1
Drop get_plugin_from_request() method Signed-off-by: Lucio Correia <luciojhc@linux.vnet.ibm.com> --- src/wok/control/base.py | 37 +++++-------------------------------- src/wok/control/utils.py | 1 - src/wok/reqlogger.py | 26 ++++++++++++++++++++++++++ src/wok/root.py | 40 ++++------------------------------------ src/wok/utils.py | 12 ------------ 5 files changed, 35 insertions(+), 81 deletions(-) diff --git a/src/wok/control/base.py b/src/wok/control/base.py index 04cf2cb..686a1aa 100644 --- a/src/wok/control/base.py +++ b/src/wok/control/base.py @@ -31,9 +31,9 @@ from wok.control.utils import get_class_name, internal_redirect, model_fn from wok.control.utils import parse_request, validate_method from wok.control.utils import validate_params from wok.exception import InvalidOperation, UnauthorizedError, WokException -from wok.reqlogger import RequestRecord +from wok.reqlogger import log_request from wok.stringutils import encode_value, utf8_dict -from wok.utils import get_plugin_from_request, wok_log +from wok.utils import wok_log # Default request log messages @@ -157,16 +157,7 @@ class Resource(object): # log request code = self.getRequestMessage(method, action_name) reqParams = utf8_dict(self.log_args, request) - RequestRecord( - reqParams, - details, - app=get_plugin_from_request(), - msgCode=code, - req=method, - status=status, - user=cherrypy.session.get(USER_NAME, 'N/A'), - ip=cherrypy.request.remote.ip - ).log() + log_request(code, reqParams, details, method, status) wrapper.__name__ = action_name wrapper.exposed = True @@ -220,16 +211,7 @@ class Resource(object): # log request if method not in LOG_DISABLED_METHODS: code = self.getRequestMessage(method) - RequestRecord( - self.log_args, - details, - app=get_plugin_from_request(), - msgCode=code, - req=method, - status=status, - user=cherrypy.session.get(USER_NAME, 'N/A'), - ip=cherrypy.request.remote.ip - ).log() + log_request(code, self.log_args, details, method, status) return result @@ -462,16 +444,7 @@ class Collection(object): # log request code = self.getRequestMessage(method) reqParams = utf8_dict(self.log_args, params) - RequestRecord( - reqParams, - details, - app=get_plugin_from_request(), - msgCode=code, - req=method, - status=status, - user=cherrypy.session.get(USER_NAME, 'N/A'), - ip=cherrypy.request.remote.ip - ).log() + log_request(code, reqParams, details, method, status) class AsyncCollection(Collection): diff --git a/src/wok/control/utils.py b/src/wok/control/utils.py index 059c187..987dd00 100644 --- a/src/wok/control/utils.py +++ b/src/wok/control/utils.py @@ -24,7 +24,6 @@ import cherrypy import json from jsonschema import Draft3Validator, ValidationError, FormatChecker - from wok.auth import USER_ROLES from wok.exception import InvalidParameter, OperationFailed from wok.utils import import_module, listPathModules diff --git a/src/wok/reqlogger.py b/src/wok/reqlogger.py index 9f1d2c8..b675478 100644 --- a/src/wok/reqlogger.py +++ b/src/wok/reqlogger.py @@ -18,6 +18,7 @@ # Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA # +import cherrypy import glob import json import logging @@ -28,6 +29,7 @@ import time from cherrypy.process.plugins import BackgroundTask from tempfile import NamedTemporaryFile +from wok.auth import USER_NAME from wok.config import config, get_log_download_path from wok.exception import InvalidParameter, OperationFailed from wok.message import WokMessage @@ -63,6 +65,30 @@ REQUEST_LOG_FILE = "wok-req.log" WOK_REQUEST_LOGGER = "wok_request_logger" +def log_request(code, params, exception, method, status, app=None, user=None, + ip=None): + if app is None: + app = cherrypy.request.app.root.domain + + if user is None: + user = cherrypy.session.get(USER_NAME, 'N/A') + + if ip is None: + ip = cherrypy.request.remote.ip + + log_id = RequestRecord( + {'code': code, 'params': params}, + exception, + app=app, + req=method, + status=status, + user=user, + ip=ip + ).log() + + return log_id + + class RequestLogger(object): def __init__(self): log = os.path.join(config.get("logging", "log_dir"), REQUEST_LOG_FILE) diff --git a/src/wok/root.py b/src/wok/root.py index e54bf38..080b7f0 100644 --- a/src/wok/root.py +++ b/src/wok/root.py @@ -32,7 +32,7 @@ from wok.control import sub_nodes from wok.control.base import Resource from wok.control.utils import parse_request from wok.exception import MissingParameter -from wok.reqlogger import RequestRecord +from wok.reqlogger import log_request ROOT_REQUESTS = { @@ -156,8 +156,6 @@ class WokRoot(Root): details = None method = 'POST' code = self.getRequestMessage(method, 'login') - app = 'wok' - ip = cherrypy.request.remote.ip try: params = parse_request() @@ -165,18 +163,7 @@ class WokRoot(Root): password = params['password'] except KeyError, item: details = e = MissingParameter('WOKAUTH0003E', {'item': str(item)}) - - RequestRecord( - params, - details, - app=app, - msgCode=code, - req=method, - status=400, - user='N/A', - ip=ip - ).log() - + log_request(code, params, details, method, 400) raise cherrypy.HTTPError(400, e.message) try: @@ -186,16 +173,7 @@ class WokRoot(Root): status = e.status raise finally: - RequestRecord( - params, - details, - app=app, - msgCode=code, - req=method, - status=status, - user='N/A', - ip=ip - ).log() + log_request(code, params, details, method, status) return json.dumps(user_info) @@ -204,19 +182,9 @@ class WokRoot(Root): method = 'POST' code = self.getRequestMessage(method, 'logout') params = {'username': cherrypy.session.get(auth.USER_NAME, 'N/A')} - ip = cherrypy.request.remote.ip auth.logout() - RequestRecord( - params, - None, - app='wok', - msgCode=code, - req=method, - status=200, - user=params['username'], - ip=ip - ).log() + log_request(code, params, None, method, 200, user=params['username']) return '{}' diff --git a/src/wok/utils.py b/src/wok/utils.py index 7599e85..1cdc025 100644 --- a/src/wok/utils.py +++ b/src/wok/utils.py @@ -106,18 +106,6 @@ def get_all_tabs(): return tabs -def get_plugin_from_request(): - """ - Returns name of plugin being requested. If no plugin, returns 'wok'. - """ - script_name = cherrypy.request.script_name - split = script_name.split('/') - if len(split) > 2 and split[1] == 'plugins': - return split[2] - - return 'wok' - - def import_class(class_path): module_name, class_name = class_path.rsplit('.', 1) try: -- 1.9.1
* 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
* Add plugin and log_id attributes to AsyncTask * Create auxiliary method to save log entry ID for a task * Handle WokException separately in order to add it in translatable form to user log Signed-off-by: Lucio Correia <luciojhc@linux.vnet.ibm.com> --- src/wok/asynctask.py | 49 +++++++++++++++++++++++++++++++++++++++++++------ src/wok/i18n.py | 2 ++ 2 files changed, 45 insertions(+), 6 deletions(-) diff --git a/src/wok/asynctask.py b/src/wok/asynctask.py index 021b76c..6097acb 100644 --- a/src/wok/asynctask.py +++ b/src/wok/asynctask.py @@ -25,10 +25,12 @@ import time import traceback import uuid - -from wok.exception import InvalidOperation, OperationFailed +from wok.exception import InvalidOperation, OperationFailed, WokException +from wok.reqlogger import ASYNCTASK_REQUEST_METHOD, log_request +MSG_FAILED = 'WOKASYNC0002L' +MSG_SUCCESS = 'WOKASYNC0001L' tasks_queue = {} @@ -43,27 +45,58 @@ def clean_old_tasks(): task.remove() +def save_request_log_id(log_id, task_id): + tasks_queue[task_id].log_id = log_id + + class AsyncTask(object): def __init__(self, target_uri, fn, opaque=None, kill_cb=None): + # task info self.id = str(uuid.uuid1()) self.target_uri = target_uri self.fn = fn self.kill_cb = kill_cb + self.log_id = None + self.timestamp = time.time() + + # log info - save info to log on task finish + self.app = '' + if cherrypy.request.app: + self.app = cherrypy.request.app.script_name + + # task context self.status = 'running' self.message = 'The request is being processing.' - self.timestamp = time.time() self._cp_request = cherrypy.serving.request self.thread = threading.Thread(target=self._run_helper, args=(opaque, self._status_cb)) self.thread.setDaemon(True) self.thread.start() + # let's prevent memory leak in tasks_queue clean_old_tasks() tasks_queue[self.id] = self - def _status_cb(self, message, success=None): + def _log(self, code, status, exception=None): + log_request( + code, + {'target_uri': self.target_uri}, + exception, + ASYNCTASK_REQUEST_METHOD, + status, + app=self.app, + user='', + ip='' + ) + + def _status_cb(self, message, success=None, exception=None): if success is not None: - self.status = 'finished' if success else 'failed' + if success: + self._log(MSG_SUCCESS, 200) + self.status = 'finished' + else: + self._log(MSG_FAILED, 400, exception) + self.status = 'failed' if message.strip(): self.message = message @@ -72,10 +105,14 @@ class AsyncTask(object): cherrypy.serving.request = self._cp_request try: self.fn(cb, opaque) + except WokException, e: + cherrypy.log.error_log.error("Error in async_task %s " % self.id) + cherrypy.log.error_log.error(traceback.format_exc()) + cb(e.message, success=False, exception=e) except Exception, e: cherrypy.log.error_log.error("Error in async_task %s " % self.id) cherrypy.log.error_log.error(traceback.format_exc()) - cb(e.message, False) + cb(e.message, success=False) def remove(self): try: diff --git a/src/wok/i18n.py b/src/wok/i18n.py index 7ba7c24..4893be7 100644 --- a/src/wok/i18n.py +++ b/src/wok/i18n.py @@ -59,6 +59,8 @@ messages = { "WOKPROXY0001E": _("Unable to (re)start system's nginx.service. Details: '%(error)s'"), # These messages (ending with L) are for user log purposes + "WOKASYNC0001L": _("Successfully completed task '%(target_uri)s'"), + "WOKASYNC0002L": _("Failed to complete task '%(target_uri)s'"), "WOKCOL0001L": _("Request made on collection"), "WOKRES0001L": _("Request made on resource"), "WOKROOT0001L": _("User '%(username)s' login"), -- 1.9.1
Signed-off-by: Lucio Correia <luciojhc@linux.vnet.ibm.com> --- src/wok/control/base.py | 28 +++++++++++++++++++++++++--- 1 file changed, 25 insertions(+), 3 deletions(-) diff --git a/src/wok/control/base.py b/src/wok/control/base.py index 686a1aa..786ecb7 100644 --- a/src/wok/control/base.py +++ b/src/wok/control/base.py @@ -26,6 +26,7 @@ import urllib2 import wok.template +from wok.asynctask import save_request_log_id from wok.auth import USER_GROUPS, USER_NAME, USER_ROLES from wok.control.utils import get_class_name, internal_redirect, model_fn from wok.control.utils import parse_request, validate_method @@ -148,6 +149,7 @@ class Resource(object): self.info['persistent'] is True): result = render_fn(self, action_result) status = cherrypy.response.status + return result except WokException, e: details = e @@ -157,7 +159,9 @@ class Resource(object): # log request code = self.getRequestMessage(method, action_name) reqParams = utf8_dict(self.log_args, request) - log_request(code, reqParams, details, method, status) + log_id = log_request(code, reqParams, details, method, status) + if status == 202: + save_request_log_id(log_id, action_result['id']) wrapper.__name__ = action_name wrapper.exposed = True @@ -209,7 +213,7 @@ class Resource(object): raise finally: # log request - if method not in LOG_DISABLED_METHODS: + if method not in LOG_DISABLED_METHODS and status != 202: code = self.getRequestMessage(method) log_request(code, self.log_args, details, method, status) @@ -293,6 +297,15 @@ class AsyncResource(Resource): raise cherrypy.HTTPError(405, e.message) cherrypy.response.status = 202 + + # log request + method = 'DELETE' + code = self.getRequestMessage(method) + reqParams = utf8_dict(self.log_args) + log_id = log_request(code, reqParams, None, method, + cherrypy.response.status) + save_request_log_id(log_id, task['id']) + return wok.template.render("Task", task) @@ -440,7 +453,7 @@ class Collection(object): status = e.status raise finally: - if method not in LOG_DISABLED_METHODS: + if method not in LOG_DISABLED_METHODS and status != 202: # log request code = self.getRequestMessage(method) reqParams = utf8_dict(self.log_args, params) @@ -466,6 +479,15 @@ class AsyncCollection(Collection): args = self.model_args + [params] task = create(*args) cherrypy.response.status = 202 + + # log request + method = 'POST' + code = self.getRequestMessage(method) + reqParams = utf8_dict(self.log_args, params) + log_id = log_request(code, reqParams, None, method, + cherrypy.response.status) + save_request_log_id(log_id, task['id']) + return wok.template.render("Task", task) -- 1.9.1
That log file is not intended anymore to be a log file itself. Signed-off-by: Lucio Correia <luciojhc@linux.vnet.ibm.com> --- src/wok/reqlogger.py | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/src/wok/reqlogger.py b/src/wok/reqlogger.py index 69ea22b..7449f95 100644 --- a/src/wok/reqlogger.py +++ b/src/wok/reqlogger.py @@ -31,7 +31,7 @@ from cherrypy.process.plugins import BackgroundTask from tempfile import NamedTemporaryFile from wok.auth import USER_NAME -from wok.config import config, get_log_download_path +from wok.config import get_log_download_path, paths from wok.exception import InvalidParameter, OperationFailed from wok.message import WokMessage from wok.stringutils import ascii_dict @@ -62,7 +62,7 @@ TS_ZONE_FORMAT = "%Z" UNSAFE_REQUEST_PARAMETERS = ['password', 'passwd'] # Log handler setup -REQUEST_LOG_FILE = "wok-req.log" +REQUEST_LOG_FILE = "user-requests.data" WOK_REQUEST_LOGGER = "wok_request_logger" # AsyncTask handling @@ -119,7 +119,7 @@ def log_request(code, params, exception, method, status, app=None, user=None, class RequestLogger(object): def __init__(self): - log = os.path.join(config.get("logging", "log_dir"), REQUEST_LOG_FILE) + log = os.path.join(paths.state_dir, REQUEST_LOG_FILE) h = logging.handlers.WatchedFileHandler(log, 'a') h.setFormatter(logging.Formatter('%(message)s')) self.handler = h -- 1.9.1
participants (2)
-
Aline Manera -
Lucio Correia