Signed-off-by: Lucio Correia <luciojhc(a)linux.vnet.ibm.com&gt; --- src/wok/control/base.py | 37 +++++-------------------------------- src/wok/control/utils.py | 1 - src/wok/reqlogger.py | 26 ++++++++++++++++++++++++++ src/wok/root.py | 40 ++++------------------------------------ 4 files changed, 35 insertions(+), 69 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 '{}' -- 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(a)linux.vnet.ibm.com&gt; --- src/wok/reqlogger.py | 142 +++++++++++++++++++++++++++++---------------------- 1 file changed, 80 insertions(+), 62 deletions(-) diff --git a/src/wok/reqlogger.py b/src/wok/reqlogger.py index b675478..2dcfd05 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 @@ -34,7 +35,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 @@ -64,6 +65,9 @@ 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): @@ -140,20 +144,18 @@ 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, None) + 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) - text += ' ' + msg.get_text(prepend_code=True, translate=True) + if error: + code = error.get('code', '') + params = error.get('params', {}) + msg = WokMessage(code, params, plugin) + text += ' (%s)' % msg.get_text(prepend_code=True, translate=True) return text @@ -163,8 +165,38 @@ 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) + app = record['info']['app'] + text = self.getTranslatedMessage(message, error, app) + record['info']['message'] = text + + 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 +209,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 +253,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 +287,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(a)linux.vnet.ibm.com&gt; --- src/wok/asynctask.py | 50 ++++++++++++++++++++++++++++++++++++++++++++------ src/wok/i18n.py | 2 ++ 2 files changed, 46 insertions(+), 6 deletions(-) diff --git a/src/wok/asynctask.py b/src/wok/asynctask.py index 021b76c..ff9ac3c 100644 --- a/src/wok/asynctask.py +++ b/src/wok/asynctask.py @@ -25,10 +25,13 @@ import time import traceback import uuid - -from wok.exception import InvalidOperation, OperationFailed +from wok.auth import USER_NAME +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 +46,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 = 'wok' + if cherrypy.request.app: + self.app = cherrypy.request.app.root.domain + + # 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 +106,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

That log file is not intended anymore to be a log file itself. Signed-off-by: Lucio Correia <luciojhc(a)linux.vnet.ibm.com&gt; --- 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 2dcfd05..1ccf1c3 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 @@ -95,7 +95,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