CE-136 JSON export download logging #3178
There are no files selected for viewing
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -0,0 +1,86 @@ | ||
| define([], () => { | ||
| /** | ||
| * | ||
| * @param {string} code - executable Python code in a string | ||
| * @returns {Promise<string>} - 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 | ||
| }) | ||
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| Original file line number | Diff line number | Diff line change |
|---|---|---|
|
|
@@ -9,17 +9,22 @@ | |
|
|
||
| """ | ||
| import collections | ||
| import json | ||
| import logging | ||
| import os | ||
| import threading | ||
| import time | ||
| import uuid | ||
| from datetime import datetime, timezone | ||
| from logging import handlers | ||
|
|
||
| import biokbase | ||
|
|
||
| from . import log_proxy | ||
| from .log_common import format_event | ||
| from .narrative_logger import NarrativeLogger | ||
| # Local | ||
| from .util import kbase_env | ||
|
|
||
| __author__ = "Dan Gunter <[email protected]>" | ||
| __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): | ||
|
There was a problem hiding this comment. I think before going too far down this rabbit hole, we should talk to devops about what's the most reasonable logging format for their use. Though some local file logging would be good, too. Also, file handling / formatting should be a more global thing for all logging. There was a problem hiding this comment. Yeah, I just wanted to make sure that this prototyping work actually produced a JSON log in a minimal fashion with the simplest implementation -- a file in the same place we are currently logging (/tmp). And I agree it should be global. I figured, get it working in this case, then later switch over existing logging entry points to use it too. I'm sure on the table still is logging to a file in a mounted directory and having an external process grab those logs. I don't think that is a good solution for Narrative logging, but it should be considered, as it is a traditional logging technique. |
||
| # 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. | ||
|
Comment on lines
+303
to
+304
|
||
| "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 | ||
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
This seems reasonable. I think there's some other error catching / wait-until-kernel-is-alive code elsewhere that we can either repurpose or just make use of.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Ok, I'll hunt for that.