diff --git a/kbase-extension/static/kbase/js/util/Logging.js b/kbase-extension/static/kbase/js/util/Logging.js new file mode 100644 index 0000000000..7e8c7e6cc9 --- /dev/null +++ b/kbase-extension/static/kbase/js/util/Logging.js @@ -0,0 +1,86 @@ +define([], () => { + /** + * + * @param {string} code - executable Python code in a string + * @returns {Promise} - A promise which will result in a string the value + * of which was that returned by the last statement + * in the Python code. + */ + async function executePython(code) { + return new Promise((resolve, reject) => { + Jupyter.notebook.kernel.execute(code, { + iopub: { + output: (msg) => { + if ('content' in msg) { + if ('data' in msg.content) { + if ('text/plain' in msg.content.data) { + resolve(msg.content.data['text/plain']); + } else { + reject(new Error('Cannot locate "text/plain" response in "content.data" of output message')); + } + } else if ('ename' in msg.content) { + reject(new Error(`Error executing logging kernel command: ${msg.content.ename}, ${msg.content.evalue}`)) + } else { + reject(new Error('Cannot locate "data" or "ename" in output message "content"')) + } + } else { + reject(new Error('Cannot locate "content" in output message')); + } + } + } + }, { + store_history: false, + silent: false + }); + }); + } + class Logging { + async execBackendLogging(event, data, level) { + // Is it really possible to go to this code if the nodebook + // and kernel have not been initialized? + if (!Jupyter || !Jupyter.notebook || !Jupyter.notebook.kernel) { + console.warn('Jupyter not fully set up, cannot log'); + return; + } + + if (!Jupyter.notebook.kernel.is_connected()) { + console.warn('Jupyter kernel not connected, cannot log'); + return + } + + const code = ` + from biokbase.narrative.common.kblogging import log_ui_event + log_ui_event("${event}", ${JSON.stringify(data)}, "${level}") + ` + + // Wrap in try/catch to be resilient to logging failures. + try { + return await executePython(code); + } catch (ex) { + console.error('Error executing logging code', ex); + } + } + log(event, data, level) { + return this.execBackendLogging(event, data, level); + } + // One method per logging level. These are the methods + // that should be used for logging. + debug(event, data) { + return this.log(event, data, 'debug'); + } + info(event, data) { + return this.log(event, data, 'info'); + } + warning(event, data) { + return this.log(event, data, 'warning'); + } + error(event, data) { + return this.log(event, data, 'error'); + } + critical(event, data) { + return this.log(event, data, 'critical'); + } + } + + return Logging +}) \ No newline at end of file diff --git a/kbase-extension/static/kbase/js/widgets/narrative_core/kbaseNarrativeDownloadPanel.js b/kbase-extension/static/kbase/js/widgets/narrative_core/kbaseNarrativeDownloadPanel.js index bafbb46e55..30b3c81e41 100644 --- a/kbase-extension/static/kbase/js/widgets/narrative_core/kbaseNarrativeDownloadPanel.js +++ b/kbase-extension/static/kbase/js/widgets/narrative_core/kbaseNarrativeDownloadPanel.js @@ -11,10 +11,13 @@ define([ 'kbase-client-api', 'kbase-generic-client-api', 'base/js/namespace', -], (Promise, KBWidget, $, Config, kbase_client_api, GenericClient, Jupyter) => { + 'kbaseAuthenticatedWidget', + 'util/Logging' +], (Promise, KBWidget, $, Config, kbase_client_api, GenericClient, Jupyter, kbaseAuthenticatedWidget, Logging) => { 'use strict'; return KBWidget({ name: 'kbaseNarrativeDownloadPanel', + parent: kbaseAuthenticatedWidget, version: '1.0.0', options: { token: null, @@ -126,16 +129,8 @@ define([ .addClass('kb-data-list-btn') .append('JSON') .click(() => { - const urlSuffix = - '/download?' + - 'ref=' + - encodeURIComponent(self.ref) + - '&url=' + - encodeURIComponent(self.wsUrl) + - '&wszip=1' + - '&name=' + - encodeURIComponent(self.objName + '.JSON.zip'); - self.downloadFile(urlSuffix); + + self.downloadObject() }) ); $btnTd.append( @@ -153,6 +148,22 @@ define([ self.$statusDiv.append(self.$statusDivContent); downloadPanel.append(self.$statusDiv.hide()); }, + + downloadObject: async function () { + // First start the download + const name = `${this.objName}.JSON.zip`; + + const params = { + ref: this.ref, url: this.wsUrl, wszip: 1, name + } + this.downloadFile2(params); + + // Then log the download. This is asynchronous as the logger waits for the kernel to respond with the + // result, which should be a log id (uuid). + const data = {ref: this.ref, format: "json"} + const result = await new Logging().info('download-object', data); + console.log(`Logged download ${result}`); + }, prepareDownloaders: function (type) { const ret = []; @@ -330,31 +341,19 @@ define([ }, downloadFile: function (urlSuffix) { - const self = this; - if (self.useDynamicDownloadSupport) { - const genericClient = new GenericClient( - self.srvWizURL, - { token: self.token }, - null, - false - ); - genericClient.sync_call( - 'ServiceWizard.get_service_status', - [{ module_name: 'NarrativeDownloadSupport', version: 'dev' }], - (data) => { - const urlPrefix = data[0]['url']; - self.downloadFileInner(urlPrefix + urlSuffix); - }, - (error) => { - console.error(error); - self.showError(error); - } - ); - } else { - self.downloadFileInner(self.exportURL + urlSuffix); + this.downloadFileInner(this.exportURL + urlSuffix); + }, + + downloadFile2: function (params) { + const url = new URL(`${this.exportURL}/download`); + for (const [key, value] of Object.entries(params)) { + url.searchParams.set(key, value); } + + this.downloadFileInner(url.toString()); }, + downloadFileInner: function (url) { console.log('Downloading url=' + url); const hiddenIFrameID = 'hiddenDownloader'; diff --git a/src/biokbase/narrative/common/kblogging.py b/src/biokbase/narrative/common/kblogging.py index 9387a3bf6c..1f0ecce0e9 100644 --- a/src/biokbase/narrative/common/kblogging.py +++ b/src/biokbase/narrative/common/kblogging.py @@ -9,17 +9,22 @@ """ import collections +import json import logging -from logging import handlers import os import threading import time +import uuid +from datetime import datetime, timezone +from logging import handlers + +import biokbase -# Local -from .util import kbase_env from . import log_proxy from .log_common import format_event from .narrative_logger import NarrativeLogger +# Local +from .util import kbase_env __author__ = "Dan Gunter " __date__ = "2014-07-31" @@ -29,6 +34,8 @@ KBASE_TMP_DIR = "/tmp" KBASE_TMP_LOGFILE = os.path.join(KBASE_TMP_DIR, "kbase-narrative.log") +KBASE_UI_LOGFILE = os.path.join(KBASE_TMP_DIR, "kbase-narrative-ui.json") + # env var with location of proxy config file KBASE_PROXY_ENV = "KBASE_PROXY_CONFIG" @@ -200,6 +207,7 @@ def init_handlers(): if not _has_handler_type(g_log, logging.FileHandler): hndlr = logging.FileHandler(KBASE_TMP_LOGFILE) + # hndlr = logging.StreamHandler(sys.stdout) fmtr = logging.Formatter("%(levelname)s %(asctime)s %(name)s %(message)s") hndlr.setFormatter(fmtr) g_log.addHandler(hndlr) @@ -252,3 +260,97 @@ def __init__(self, is_fatal, where="unknown location", what="unknown condition") msg = format_event("ui.error", info) log_method = (self.ui_log.error, self.ui_log.critical)[is_fatal] log_method(msg) + +def epoch_time_millis(): + epoch_time = datetime.now(tz=timezone.utc).timestamp() + return int(epoch_time * 1000) + +def get_username(): + token = biokbase.auth.get_auth_token() + if token is None: + return None + try: + user_info = biokbase.auth.get_user_info(token) + return user_info.get("user", None) + except BaseException: + return None + +def log_ui_event(event: str, data: dict, level: str): + # We use a separate logger, configured to save the + # entire message as a simple string ... and that string + # is a JSON-encoded message object. + # The resulting log file, then, is y it is a JSON stream format, since it + # contains multiple objects in sequence. + ui_log = get_logger("narrative_ui_json") + log_id = str(uuid.uuid4()) + if not _has_handler_type(ui_log, logging.FileHandler): + # Here we may change the logging handler to something like HTTP, syslog, io stream, + # see https://docs.python.org/3/library/logging.handlers.html + handler = logging.FileHandler(KBASE_UI_LOGFILE) + formatter = logging.Formatter("%(message)s") + handler.setFormatter(formatter) + ui_log.addHandler(handler) + + + # + # The logging message is simply what, when, who, where, and ... data + # There could be other interesting information such as + # + [_, workspace_id, _, object_id] = kbase_env.narrative.split(".") + + + message = json.dumps({ + # If logs are combined, we need to tie log entries to + # a specific version of a service in a specific environment. + "service": "narrative", + "version": biokbase.narrative.version(), + "environment": kbase_env.env, + # General log entry; information that any log entry + # will need. + # id helps create a unique reference to a log entry; perhaps + # should be uuid, service + uuid, or omitted and only created + # by a logging repository service. + "id": log_id, + "timestamp": epoch_time_millis(), + # The actual, specific event. The event name is a simple + # string, the data is a dict or serializable class whose + # definition is implied by the event name. + "event": { + "name": event, + # the event context captures information common to instances + # of this kind of event. As a narrative ui event, part of the context + # is the narrative object, the current user, and the current user's + # browser. Clearly more could be captured here, e.g. the browser model, + # narrative session id, etc. + "context": { + # I tried to update kbase_env to reflect the current narrative ref, + # but no no avail so far. The kbase_env here is not the same as the + # one used when saving a narrative and getting the new version, so it does + # not reflect an updated narrative object version. + # If that isn't possible, we can store the ws and object id instead. + "narrative_ref": kbase_env.narrative_ref, + # Log entries for authenticated contexts should identify the user + "username": kbase_env.user, + # Log entries resulting from a network call can/should identify + # the ip address of the caller + "client_ip": kbase_env.client_ip + # could be more context, like the jupyter / ipython / etc. versions + }, + # This is the specific data sent in this logging event + "data": data + } + }) + + if level == 'debug': + ui_log.debug(message) + elif level == 'info': + ui_log.info(message) + elif level == 'warning': + ui_log.warning(message) + elif level == 'error': + ui_log.error(message) + elif level == 'critical': + ui_log.critical(message) + else: + raise ValueError(f"log level must be one of debug, info, warning, error, or critical; it is '{level}'") + return log_id diff --git a/src/biokbase/narrative/common/util.py b/src/biokbase/narrative/common/util.py index 0cf30a690b..89991cb6a1 100644 --- a/src/biokbase/narrative/common/util.py +++ b/src/biokbase/narrative/common/util.py @@ -6,11 +6,9 @@ import os import re -import requests +import uuid + from setuptools import Command -from .kvp import KVP_EXPR, parse_kvp -from biokbase.workspace.client import Workspace as WS2 -from biokbase.workspace.baseclient import ServerError def kbase_debug_mode(): @@ -35,6 +33,7 @@ class _KBaseEnv(object): env_workspace = "KB_WORKSPACE_ID" env_user = "KB_USER_ID" env_env = "KB_ENVIRONMENT" + env_narrative_ref = "KB_NARRATIVE_REF" _defaults = { "auth_token": "none", @@ -44,6 +43,7 @@ class _KBaseEnv(object): "user": "anonymous", "workspace": "none", "env": "none", + "narrative_ref": "none" } def __getattr__(self, name): diff --git a/src/biokbase/narrative/contents/kbasewsmanager.py b/src/biokbase/narrative/contents/kbasewsmanager.py index 520a3d63a7..ca4e3806d9 100644 --- a/src/biokbase/narrative/contents/kbasewsmanager.py +++ b/src/biokbase/narrative/contents/kbasewsmanager.py @@ -243,6 +243,7 @@ def get(self, path, content=True, type=None, format=None): util.kbase_env.narrative = "ws.{}.obj.{}".format( ref.wsid, ref.objid ) + util.kbase_env.narrative_ref = f"{ref.wsid}/{ref.objid}/{nar_obj['info'][4]}" util.kbase_env.workspace = model["content"].metadata.ws_name self.narrative_logger.narrative_open( "{}/{}".format(ref.wsid, ref.objid), nar_obj["info"][4] @@ -289,12 +290,13 @@ def save(self, model, path): try: ref = self._parse_path(path) - result = self.write_narrative(ref, nb, self.get_userid()) + nb, workspace_id, object_id, object_version = self.write_narrative(ref, nb, self.get_userid()) - new_id = "ws.%s.obj.%s" % (result[1], result[2]) + new_id = "ws.%s.obj.%s" % (workspace_id, object_id) util.kbase_env.narrative = new_id + new_ref = f"{workspace_id}/{object_id}/{object_version}" + util.kbase_env.narrative_ref = new_ref - nb = result[0] self.validate_notebook_model(model) validation_message = model.get("message", None) @@ -302,7 +304,7 @@ def save(self, model, path): if validation_message: model["message"] = validation_message self.narrative_logger.narrative_save( - "{}/{}".format(result[1], result[2]), result[3] + "{}/{}".format(workspace_id, object_id), object_version ) return model except WorkspaceError as err: