[PATCH] [Wok 0/7] #141 - Log async tasks status
IMPORTANT: This patchset requires its counterparts on all plugins to not break. Lucio Correia (7): Add get_plugin_from_uri() method to wok utils Move add_task to asynctask to avoid cyclic import Log AsyncTask start, success and failure Sort user log records by microsecond Put failure details into parenthesis Update UI to show TASK statuses and search for TASK entries Remove GET from advanced search form src/wok/asynctask.py | 74 ++++++++++++++++++++++++++++----- src/wok/i18n.py | 3 ++ src/wok/reqlogger.py | 27 ++++++++++-- src/wok/utils.py | 18 ++++---- ui/js/wok.user-log.js | 28 +++++++++---- ui/pages/tabs/settings-search.html.tmpl | 2 +- 6 files changed, 120 insertions(+), 32 deletions(-) -- 1.9.1
Signed-off-by: Lucio Correia <luciojhc@linux.vnet.ibm.com> --- src/wok/utils.py | 11 +++++++++++ 1 file changed, 11 insertions(+) diff --git a/src/wok/utils.py b/src/wok/utils.py index 4c132a1..3d61e66 100644 --- a/src/wok/utils.py +++ b/src/wok/utils.py @@ -137,6 +137,17 @@ def get_plugin_from_request(): return 'wok' +def get_plugin_from_uri(uri): + """ + Tries to deduce plugin name from URI. If no success, returns 'wok'. + """ + split = uri.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
Signed-off-by: Lucio Correia <luciojhc@linux.vnet.ibm.com> --- src/wok/asynctask.py | 7 +++++++ src/wok/utils.py | 7 ------- 2 files changed, 7 insertions(+), 7 deletions(-) diff --git a/src/wok/asynctask.py b/src/wok/asynctask.py index fb614a2..82a91ec 100644 --- a/src/wok/asynctask.py +++ b/src/wok/asynctask.py @@ -25,6 +25,13 @@ import traceback from wok.exception import OperationFailed +from wok.utils import get_next_task_id + + +def add_task(target_uri, fn, objstore, opaque=None): + id = get_next_task_id() + AsyncTask(id, target_uri, fn, objstore, opaque) + return id class AsyncTask(object): diff --git a/src/wok/utils.py b/src/wok/utils.py index 3d61e66..8caf4ee 100644 --- a/src/wok/utils.py +++ b/src/wok/utils.py @@ -39,7 +39,6 @@ from datetime import datetime, timedelta from multiprocessing import Process, Queue from threading import Timer -from wok.asynctask import AsyncTask from wok.config import paths, PluginPaths from wok.exception import InvalidParameter, TimeoutExpired from wok.stringutils import decode_value @@ -60,12 +59,6 @@ def get_task_id(): return task_id -def add_task(target_uri, fn, objstore, opaque=None): - id = get_next_task_id() - AsyncTask(id, target_uri, fn, objstore, opaque) - return id - - def is_digit(value): if isinstance(value, int): return True -- 1.9.1
* Change AsyncTask constructor to receive a dict task_info instead of adding more parameters * 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 | 71 ++++++++++++++++++++++++++++++++++++++++++---------- src/wok/i18n.py | 3 +++ src/wok/reqlogger.py | 20 +++++++++++++-- 3 files changed, 79 insertions(+), 15 deletions(-) diff --git a/src/wok/asynctask.py b/src/wok/asynctask.py index 82a91ec..5d32f5e 100644 --- a/src/wok/asynctask.py +++ b/src/wok/asynctask.py @@ -24,25 +24,45 @@ import threading import traceback -from wok.exception import OperationFailed -from wok.utils import get_next_task_id +from wok.exception import OperationFailed, WokException +from wok.reqlogger import RequestRecord +from wok.reqlogger import TASK_FAILED, TASK_STARTED, TASK_SUCCESS +from wok.utils import get_next_task_id, get_plugin_from_uri + + +METHOD_TASK = 'TASK' +MSG_FAILED = 'WOKASYNC0003L' +MSG_STARTED = 'WOKASYNC0001L' +MSG_SUCCESS = 'WOKASYNC0002L' def add_task(target_uri, fn, objstore, opaque=None): id = get_next_task_id() - AsyncTask(id, target_uri, fn, objstore, opaque) + task_info = { + 'id': id, + 'target_uri': target_uri, + 'fn': fn, + 'objstore': objstore, + 'plugin': get_plugin_from_uri(target_uri), + 'user': '', + 'ip': '', + } + AsyncTask(task_info, opaque) return id class AsyncTask(object): - def __init__(self, id, target_uri, fn, objstore, opaque=None): - if objstore is None: + def __init__(self, task_info, opaque=None): + if task_info['objstore'] is None: raise OperationFailed("WOKASYNC0001E") - self.id = str(id) - self.target_uri = target_uri - self.fn = fn - self.objstore = objstore + # task info + self.id = str(task_info['id']) + self.target_uri = task_info['target_uri'] + self.fn = task_info['fn'] + self.task_info = task_info + + # task context self.status = 'running' self.message = 'OK' self._save_helper() @@ -52,9 +72,29 @@ class AsyncTask(object): self.thread.setDaemon(True) self.thread.start() - def _status_cb(self, message, success=None): + # log async task start + self._log(MSG_STARTED, TASK_STARTED) + + def _log(self, msgCode, status, exception=None): + RequestRecord( + self.task_info, + exception, + app=self.task_info['plugin'], + msgCode=msgCode, + req=METHOD_TASK, + status=status, + user=self.task_info['user'], + ip=self.task_info['ip'] + ).log() + + def _status_cb(self, message, success=None, exception=None): if success is not None: - self.status = 'finished' if success else 'failed' + if success: + self.status = 'finished' + self._log(MSG_SUCCESS, TASK_SUCCESS) + else: + self.status = 'failed' + self._log(MSG_FAILED, TASK_FAILED, exception) if message.strip(): self.message = message @@ -65,7 +105,8 @@ class AsyncTask(object): for attr in ('id', 'target_uri', 'message', 'status'): obj[attr] = getattr(self, attr) try: - with self.objstore as session: + objstore = self.task_info['objstore'] + with objstore as session: session.store('task', self.id, obj) except Exception as e: raise OperationFailed('WOKASYNC0002E', {'err': e.message}) @@ -74,7 +115,11 @@ 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) diff --git a/src/wok/i18n.py b/src/wok/i18n.py index 33107ee..c271446 100644 --- a/src/wok/i18n.py +++ b/src/wok/i18n.py @@ -58,6 +58,9 @@ messages = { "WOKPROXY0001E": _("Unable to (re)start system's nginx.service. Details: '%(error)s'"), # These messages (ending with L) are for user log purposes + "WOKASYNC0001L": _("Started %(plugin)s task ID %(id)s: %(target_uri)s"), + "WOKASYNC0002L": _("Successfully completed %(plugin)s task ID %(id)s: %(target_uri)s"), + "WOKASYNC0003L": _("Failed to complete %(plugin)s task ID %(id)s: %(target_uri)s"), "WOKCOL0001L": _("Request made on collection"), "WOKRES0001L": _("Request made on resource"), "WOKROOT0001L": _("User '%(username)s' login"), diff --git a/src/wok/reqlogger.py b/src/wok/reqlogger.py index 9f1d2c8..c57b141 100644 --- a/src/wok/reqlogger.py +++ b/src/wok/reqlogger.py @@ -39,8 +39,8 @@ from wok.utils import remove_old_files FILTER_FIELDS = ['app', 'date', 'ip', 'req', 'status' 'user', 'time'] LOG_DOWNLOAD_URI = "/data/logs/%s" LOG_DOWNLOAD_TIMEOUT = 6 -LOG_FORMAT = "[%(date)s %(time)s %(zone)s] %(req)-6s %(status)s %(app)-11s " \ - "%(ip)-15s %(user)s: %(message)s\n" +LOG_FORMAT = "[%(date)s %(time)s %(zone)s] %(req)-6s %(status)-4s %(app)-11s" \ + " %(ip)-15s %(user)s: %(message)s\n" RECORD_TEMPLATE_DICT = { 'date': '', 'time': '', @@ -62,6 +62,16 @@ UNSAFE_REQUEST_PARAMETERS = ['password', 'passwd'] REQUEST_LOG_FILE = "wok-req.log" WOK_REQUEST_LOGGER = "wok_request_logger" +# Task logging +TASK_FAILED = 1002 +TASK_STARTED = 1000 +TASK_SUCCESS = 1001 +TASK_STATUSES = { + TASK_FAILED: 'FAIL', + TASK_STARTED: 'INIT', + TASK_SUCCESS: 'SUCC', +} + class RequestLogger(object): def __init__(self): @@ -106,6 +116,12 @@ class RequestParser(object): for record in sortedList: asciiRecord = RECORD_TEMPLATE_DICT asciiRecord.update(ascii_dict(record)) + + # log meaning of statuses 1000, 1001, 1002 for clarity + status = int(asciiRecord['status']) + if status in TASK_STATUSES.keys(): + asciiRecord['status'] = TASK_STATUSES[status] + fd.write(LOG_FORMAT % asciiRecord) fd.close() -- 1.9.1
With several requests occurring at the same second, we need further information to return user request entries in correct order. Signed-off-by: Lucio Correia <luciojhc@linux.vnet.ibm.com> --- src/wok/reqlogger.py | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/src/wok/reqlogger.py b/src/wok/reqlogger.py index c57b141..39d70e6 100644 --- a/src/wok/reqlogger.py +++ b/src/wok/reqlogger.py @@ -55,6 +55,7 @@ RECORD_TEMPLATE_DICT = { SECONDS_PER_HOUR = 360 TS_DATE_FORMAT = "%Y-%m-%d" TS_TIME_FORMAT = "%H:%M:%S" +TS_MS_FORMAT = "%f" TS_ZONE_FORMAT = "%Z" UNSAFE_REQUEST_PARAMETERS = ['password', 'passwd'] @@ -106,7 +107,8 @@ class RequestParser(object): """ try: # sort records chronologically - sortedList = sorted(records, key=lambda k: k['date'] + k['time']) + sortedList = sorted(records, key=lambda k: k['date'] + k['time'] + + k.get('ms', '')) # generate log file fd = NamedTemporaryFile(mode='w', dir=self.downloadDir, @@ -246,6 +248,7 @@ class RequestRecord(object): timestamp = time.localtime() self.logData['date'] = time.strftime(TS_DATE_FORMAT, timestamp) self.logData['time'] = time.strftime(TS_TIME_FORMAT, timestamp) + self.logData['ms'] = time.strftime(TS_MS_FORMAT, timestamp) self.logData['zone'] = time.strftime(TS_ZONE_FORMAT, timestamp) def getSafeReqParams(self, params): -- 1.9.1
Signed-off-by: Lucio Correia <luciojhc@linux.vnet.ibm.com> --- src/wok/reqlogger.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/wok/reqlogger.py b/src/wok/reqlogger.py index 39d70e6..884625b 100644 --- a/src/wok/reqlogger.py +++ b/src/wok/reqlogger.py @@ -145,7 +145,7 @@ class RequestParser(object): detCode = record.get('detCode', '') if detCode: msg = WokMessage(detCode, detParams, plugin) - text += ' ' + msg.get_text(prepend_code=True, translate=True) + text += ' (%s)' % msg.get_text(prepend_code=True, translate=True) return text -- 1.9.1
Signed-off-by: Lucio Correia <luciojhc@linux.vnet.ibm.com> --- ui/js/wok.user-log.js | 28 +++++++++++++++++++--------- ui/pages/tabs/settings-search.html.tmpl | 1 + 2 files changed, 20 insertions(+), 9 deletions(-) diff --git a/ui/js/wok.user-log.js b/ui/js/wok.user-log.js index bac5439..c54b037 100644 --- a/ui/js/wok.user-log.js +++ b/ui/js/wok.user-log.js @@ -135,17 +135,27 @@ wok.initUserLogConfigGridData = function() { var labelStyle = function(status) { var result = null; if (status != undefined) { - var firstNumberOfStatus = status.toString().charAt(0); result = { labelColor: "", - labelIcon: "" + labelIcon: "", + labelValue: status }; - switch(firstNumberOfStatus) { - case "1": - case "2": result.labelColor = 'label label-info'; result.labelIcon = 'fa fa-check fa-2'; break; - case "3": result.labelColor = 'label label-warning'; result.labelIcon = 'fa fa-times fa-2'; break; - case "4": - case "5": result.labelColor = 'label label-danger'; result.labelIcon = 'fa fa-times fa-2'; break; + if (status == 1000 || status == 1001) { + result.labelColor = 'label label-default'; result.labelIcon = 'fa fa-check fa-2'; + result.labelValue = '' + } + else if (status == 1002) { + result.labelColor = 'label label-danger'; result.labelIcon = 'fa fa-times fa-2'; + result.labelValue = '' + } + else if (status >= 400) { + result.labelColor = 'label label-danger'; result.labelIcon = 'fa fa-times fa-2'; + } + else if (status >= 300) { + result.labelColor = 'label label-warning'; result.labelIcon = 'fa fa-times fa-2'; + } + else { + result.labelColor = 'label label-info'; result.labelIcon = 'fa fa-check fa-2'; } } return result; @@ -155,7 +165,7 @@ wok.initUserLogConfigGridData = function() { $.each(result, function(index, log){ var statusLabel = labelStyle(log.status); if (statusLabel != null) { - log.status = "<span class='" + statusLabel.labelColor + "'><i class='" + statusLabel.labelIcon + "' aria-hidden='true'></i> " + log.status + "</span> "; + log.status = "<span class='" + statusLabel.labelColor + "'><i class='" + statusLabel.labelIcon + "' aria-hidden='true'></i> " + statusLabel.labelValue + "</span> "; } else { log.status = ""; } diff --git a/ui/pages/tabs/settings-search.html.tmpl b/ui/pages/tabs/settings-search.html.tmpl index 0bf664f..43eafd4 100644 --- a/ui/pages/tabs/settings-search.html.tmpl +++ b/ui/pages/tabs/settings-search.html.tmpl @@ -47,6 +47,7 @@ Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA <option value="GET">$_("GET")</option> <option value="PUT">$_("PUT")</option> <option value="DELETE">$_("DELETE")</option> + <option value="TASK">$_("TASK")</option> </select> </div> <div class="row clearfix"> -- 1.9.1
GET requests are not logged, causing search results using that field to be always empty. Signed-off-by: Lucio Correia <luciojhc@linux.vnet.ibm.com> --- ui/pages/tabs/settings-search.html.tmpl | 1 - 1 file changed, 1 deletion(-) diff --git a/ui/pages/tabs/settings-search.html.tmpl b/ui/pages/tabs/settings-search.html.tmpl index 43eafd4..dd7fdec 100644 --- a/ui/pages/tabs/settings-search.html.tmpl +++ b/ui/pages/tabs/settings-search.html.tmpl @@ -44,7 +44,6 @@ Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA <select class="form-control selectpicker" id="request-type" title="$_('Request Type')" name="req"> <option value="">$_("All Requests")</option> <option value="POST">$_("POST")</option> - <option value="GET">$_("GET")</option> <option value="PUT">$_("PUT")</option> <option value="DELETE">$_("DELETE")</option> <option value="TASK">$_("TASK")</option> -- 1.9.1
Hi Lucio, Sorry about that. But I have just replied to your RFC. On 08/19/2016 04:37 PM, Lucio Correia wrote:
IMPORTANT: This patchset requires its counterparts on all plugins to not break.
Lucio Correia (7): Add get_plugin_from_uri() method to wok utils Move add_task to asynctask to avoid cyclic import Log AsyncTask start, success and failure Sort user log records by microsecond Put failure details into parenthesis Update UI to show TASK statuses and search for TASK entries Remove GET from advanced search form
src/wok/asynctask.py | 74 ++++++++++++++++++++++++++++----- src/wok/i18n.py | 3 ++ src/wok/reqlogger.py | 27 ++++++++++-- src/wok/utils.py | 18 ++++---- ui/js/wok.user-log.js | 28 +++++++++---- ui/pages/tabs/settings-search.html.tmpl | 2 +- 6 files changed, 120 insertions(+), 32 deletions(-)
On 22-08-2016 13:55, Aline Manera wrote:
Hi Lucio,
Sorry about that. But I have just replied to your RFC.
On 08/19/2016 04:37 PM, Lucio Correia wrote:
IMPORTANT: This patchset requires its counterparts on all plugins to not break.
Lucio Correia (7): Add get_plugin_from_uri() method to wok utils Move add_task to asynctask to avoid cyclic import Log AsyncTask start, success and failure Sort user log records by microsecond Put failure details into parenthesis Update UI to show TASK statuses and search for TASK entries Remove GET from advanced search form
src/wok/asynctask.py | 74 ++++++++++++++++++++++++++++----- src/wok/i18n.py | 3 ++ src/wok/reqlogger.py | 27 ++++++++++-- src/wok/utils.py | 18 ++++---- ui/js/wok.user-log.js | 28 +++++++++---- ui/pages/tabs/settings-search.html.tmpl | 2 +- 6 files changed, 120 insertions(+), 32 deletions(-)
No problems Aline. I've answered the RFC. Let me know if you can reconsider these patches. Thanks, -- Lucio Correia Software Engineer IBM LTC Brazil
Ignore this patch. Will send V2. -- Lucio Correia Software Engineer IBM LTC Brazil
participants (2)
-
Aline Manera -
Lucio Correia