Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Initial contribution core/log.js #268

Open
wants to merge 7 commits into
base: master
Choose a base branch
from
Open

Initial contribution core/log.js #268

Show file tree
Hide file tree
Changes from 2 commits
Commits
Show all changes
7 commits
Select commit Hold shift + click to select a range
995c762
initial contribution core/log.js
Martin-Stangl Oct 18, 2019
f25bf61
log string added, fixed parameterization for notifications, legacy co…
Martin-Stangl Oct 19, 2019
91a89a0
Revert master back to upstream state.
Martin-Stangl Oct 19, 2019
067dac6
Fix: Wrong check for Error object
Martin-Stangl Oct 22, 2019
45ea7e4
Merge branch 'master' of https://github.com/openhab-scripters/openhab…
Martin-Stangl Oct 22, 2019
7d5ea41
Merge branch 'master' into feature-logger
Martin-Stangl Oct 22, 2019
53cc387
Change to message format and logger name prefix
Martin-Stangl Oct 23, 2019
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
199 changes: 199 additions & 0 deletions Core/automation/lib/javascript/core/log.js
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -0,0 +1,199 @@
/**
* Logging functions and variables
*
* Copyright (c) 2019 Contributors to the openHAB Scripters project
*
* @author Martin Stangl - initial contribution
Martin-Stangl marked this conversation as resolved.
Show resolved Hide resolved
*/
'use strict';

(function context (context) {
'use strict';

load(__DIR__+'/actions.js');

context.NOTIFY_OFF = 0;
context.NOTIFY_ERROR = 200;
context.NOTIFY_WARN = 300;
context.NOTIFY_INFO = 400;
context.NOTIFY_DEBUG = 500;

context.Logger = function Logger (name, notificationLevel, config) {
if (name === undefined) {
name = Error().stack.split('\n')[2].split('/').slice(-2).join('.').split(':')[0];
name = name.slice(-3) == ".js" ? name.slice(0,-3) : null;
}
var _logger = Java.type("org.slf4j.LoggerFactory").getLogger(name === null ? "jsr223.javascript" : "jsr223.javascript." + name.toString().toLowerCase());
var _messageFormatter = Java.type("org.slf4j.helpers.MessageFormatter");

try {
// Set default config for config params not provided.
if (config === undefined) config = {};
if (config.ERROR === undefined) config.ERROR = {};
if (config.WARN === undefined) config.WARN = {};
if (config.INFO === undefined) config.INFO = {};
if (config.DEBUG === undefined) config.DEBUG = {};
if (config.ERROR.prefix === undefined) config.ERROR.prefix = "short";
if (config.WARN.prefix === undefined) config.WARN.prefix = "none";
if (config.INFO.prefix === undefined) config.INFO.prefix = "none";
if (config.DEBUG.prefix === undefined) config.DEBUG.prefix = "short";

return Object.create(Object.prototype, {
_notificationLevel: { value: (notificationLevel === undefined || notificationLevel === null) ? context.NOTIFY_OFF : notificationLevel },
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

You are using an underscore prefix for private vars. @openhab-5iver is this a coding style that we should be using in general?

Also note that these vars are still accessible; if you want to actually make them inaccessible, I'd suggest that you move the definition of these vars from the object block into the containing function body.

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yes, I am aware of that and even did it this way originally. But then I got worried if this would not cause an issue when I instantiate multiple Loggers as I got confused by all these JS context mechanism. So I just moved it into the returned object, well aware that I loose the privacy.
Maybe I should have just taken the time and test it out. I will do actually do this and move them into the function body, if it works.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@openhab-5iver is this a coding style that we should be using in general?

That would be my preference. That's how we do it in Python, so it fit in perfectly IMO!

Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

As long as the vars are defined in the function, they should map 1:1 to the object being returned so you should be fine.

@openhab-5iver I can certainly see the bias for Python here! I agree that striving for alignment is good. I would only caution that there are likely to be areas requiring divergence if you want the JS support to be idiomatic to JS, not Python (although I don't think this is one of them!).

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Truly, it is not bias. I'm attempting to keep some consistency in place to ease the future migration to a Scripting API, which will absorb pretty much all of the helper library functionality. That will take some time though, and development is continuing. I'm hopeful that, with the new development efforts on the JS libs, there will be some collaboration on how to move forward with bringing their functionality to the level of the Python libs.

I have done plenty of development, but my background is from the management side of things. I'm currently the only active maintainer in this repo, and I am very open to collaboration on its technical direction, especially with the JS libs!

_config: { value: config },
_name: { value: name },

error: { value: function error (msg) {
try {
if (_logger.isErrorEnabled()) {
_logger.error(this._getLogMessage(msg), [].slice.call(arguments).slice(1));
}
if (this._notificationLevel >= context.NOTIFY_ERROR) {
this._sendNotification(_messageFormatter.arrayFormat(this._getLogMessage(msg, this._config.ERROR.prefix, "ERROR"), [].slice.call(arguments).slice(1)).getMessage(), "fire", "ERROR");
}
} catch (err) {
_logger.error(this._getLogMessage(err));
}
}},

warn: { value: function warn (msg) {
try {
if (_logger.isWarnEnabled()) {
_logger.warn(this._getLogMessage(msg), [].slice.call(arguments).slice(1));
}
if (this._notificationLevel >= context.NOTIFY_WARN) {
this._sendNotification(_messageFormatter.arrayFormat(this._getLogMessage(msg, this._config.WARN.prefix, "WARN"), [].slice.call(arguments).slice(1)).getMessage(), "error", "WARN");
}
} catch (err) {
_logger.error(this._getLogMessage(err));
}
}},

info: { value: function info (msg) {
try {
if (_logger.isInfoEnabled()) {
_logger.info(this._getLogMessage(msg), [].slice.call(arguments).slice(1));
}
if (this._notificationLevel >= context.NOTIFY_INFO) {
this._sendNotification(_messageFormatter.arrayFormat(this._getLogMessage(msg, this._config.INFO.prefix, "INFO"), [].slice.call(arguments).slice(1)).getMessage(), "lightbulb", "INFO");
}
} catch (err) {
_logger.error(this._getLogMessage(err));
}
}},

debug: { value: function debug (msg) {
try {
if (_logger.isDebugEnabled()) {
_logger.debug(this._getLogMessage(msg), [].slice.call(arguments).slice(1));
}
if (this._notificationLevel >= context.NOTIFY_DEBUG) {
this._sendNotification(_messageFormatter.arrayFormat(this._getLogMessage(msg, this._config.DEBUG.prefix, "DEBUG"), [].slice.call(arguments).slice(1)).getMessage(), "text", "DEBUG");
}
} catch (err) {
_logger.error(this._getLogMessage(err));
}
}},

trace: { value: function trace (msg) {
try {
if (_logger.isTraceEnabled()) {
_logger.trace(this._getLogMessage(msg), [].slice.call(arguments).slice(1));
}
} catch (err) {
_logger.error(this._getLogMessage(err));
}
}},

_getCallerDetails: { value: function _getCallerDetails (msg) {
var matches = msg.stack.split('\n\tat ')[3].match(/(.+?) \((.+):(\d+?)\)/);
msg.caller = matches[1];
msg.fileName = matches[2]
msg.lineNumber = matches[3]
return msg;
}},

_getLogMessage: { value: function _getLogMessage (msg, prefix, levelString) {
if ((typeof msg) !== "object") {
msg = Error(msg);
msg = this._getCallerDetails(msg);
} else {
msg.caller = msg.stack.split('\n\tat ')[1].split(' (')[0]
}
msg = this._legacyLoggerCorrection(msg);

if (prefix === undefined) prefix = "log";

if (prefix == "none") {
return msg.message;
}

var level = "";
var name = "";
if (prefix != "log") {
level = "[" + levelString + "] ";
name = this._name === null ? "" : this._name;
}

if (prefix == "level") {
return (level + msg);
}

var callerText;
if (msg.caller.substr(0,1) == "<") {
callerText = ", in " + msg.caller;
} else {
callerText = ", function " + msg.caller;
}

var message = msg.message == "" ? "" : "] " + msg.message;

if (prefix == "short") {
return (level + "[" + (name != "" ? name + ", " : "") + msg.fileName.split('/').pop() + ":" + msg.lineNumber + callerText + message);
}
return (level + "[" + (name != "" ? name + ": " : "") + "source " + msg.fileName + ", line " + msg.lineNumber + callerText + message);
}},

_legacyLoggerCorrection: { value: function _legacyLoggerCorrection (msg) {
if (msg.fileName.search(/automation\/lib\/javascript\/core\/utils\.js$/) !== -1) {
switch (msg.caller) {
case "logError":
case "logWarn":
case "logInfo":
case "logDebug":
case "logTrace":
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm concerned about the use of the LogAction method names and potential conflicts. The utils.js lib did the same. My guess is that this was to provide a familiar name for people who had used the rules DSL. Now that actions.js is available and LogAction is easily accessible, this should be removed. This library should provide similar functionality to the Python core.log and provide a bridge between the native JS logging (console.log) and slf4j. Although, I have questioned the bridging to slf4j and have considered swapping it with LogAction.

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This part was done specifically for support backwards compability support. If we get rid of logError, logWarn, ... in utils.log, this part goes away as well.

The new log functions are used like this:

load(__DIR__+'/log.js');
var log = Logger();
log.error("Message");
log.warn("Message");
log.info("Message");
log.debug("Message");
log.trace("Message");

utils.js does actually already provide this bridge between console.log and slf4j. I can move this part to log.js by simply instantiating a logger instance called console. var console = Logger();
Just need to add a few methods like log() and methods to change the logger name, log level and notification feature configuration, which currently can only be set at initialization.

But I also want to check, if we can so easily pretend to be console.log. Console.log also has a few tricks up it´s sleeve and I am not sure, if we can emulate all of that. But most I can remember is about color and font styles, which we just have to ignore / do not need to support.

I could convert log.js to use LogAction pretty easily instead of using slf4j directly, as LogAction does nothing else than wrap slf4j.
This means loosing the level trace, which is no big issue. But it would make log.js slower. All the compilation of data about the log call position is very slow (a few milliseconds - forever for a logger). Therefore I check using slf4j's isErrorEnabled() and the likes, if it even makes sense to do all of this. Unfortunately LogAction does not expose these methods. (Actually, I am guilty of the same and should expose these in log.js.)

If we just want to look and behave like we are using LogAction under the hood, we could simply call our logger "org.eclipse.smarthome.model.script.jsr223.javascript" and get rid of the level trace.
Not sure, if LogAction adds some fancy formatting, which we would need to emulate.

I keep you posted on the console.log front.
Give me your thoughts on LogAction. Maybe we should try a pull request there to get the isEnabled() methods.

Copy link
Member

@5iver 5iver Oct 22, 2019 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

But I also want to check, if we can so easily pretend to be console.log. Console.log also has a few tricks up it´s sleeve and I am not sure, if we can emulate all of that.

The big question is if there is any benefit to using this over LogAction 😄. If concole.log has some cool stuff in it, then that may be what tips the scale. I think it is great to equalize the functionality between the JS and Jython libraries, but I really question if we need this (or the Jython) library at all.

'use strict';
var OPENHAB_CONF = Java.type("java.lang.System").getenv("OPENHAB_CONF");
load(OPENHAB_CONF + '/automation/lib/javascript/core/actions.js');
LogAction.logWarn("Rules", "Test")

The Jython core.log provides a helpful decorator for getting a traceback, and it sends a notification too, but LogAction can do everything else.

A big benefit to slf4j is the parameterized logging and only calculating the value to log if the log entry fits the logger. It's nice to have some performance heavy logging in place that doesn't slow things down when not in use. I haven't found a way to make use of this in Jython. Is this the isErrorEnabled() (I'll need to look that up)? A PR for LogAction to enable this would be really nice!

Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

As I mentioned elsewhere, I believe that there is benefit to having a console.log defined (so that existing JS code works), but what that forwards the actual log messages to I have no opinion on, and it could be either slf4j or LogAction with no impact to consumers.

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I had a look at console. Browser and node.js implementation.
The node.js is probably, the one we would like to emulate, as we are also a backend implementation.
But looking at the node.js documetation at https://nodejs.org/api/console.html, I would say console is a different, much bigger beast. Already the message formatting syntax is completely different and then there are quite some methods to be implemented.

Therefore I do not think that what I built should pretend to be console. At least the formatting syntax would need to be supported, then it would be just about features not available, but not differences in functionality.

We could make quick progress when we canibalize the node.js implementation, but I am not sure, if I am up for that right now. Maybe.

case "error":
case "warn":
case "info":
case "debug":
case "log":
var stackArray = msg.stack.split('\n\tat ');
stackArray.splice(3,1);
msg.stack = stackArray.join('\n\tat ');
msg = this._getCallerDetails(msg);
}
}
return msg;
}},

_sendNotification: { value: function _sendNotification (message, icon, levelString) {
if (this._config[levelString].recipients !== undefined) {
this._config[levelString].recipients.forEach(function(mail){
NotificationAction.sendNotification(mail, message, icon, levelString);
})
if (this._config[levelString].recipients.length > 0) {
this.trace(Error("Notification sent to " + this._config[levelString].recipients.join(", ") + ". Message: \"" + message + "\""));
}
} else {
NotificationAction.sendBroadcastNotification(message, icon, levelString);
this.trace(Error("Broadcast notification sent. Message: \"" + message + "\""));
}
}}

})
} catch (err) {
_logger.error(err.fileName + ", line " + err.lineNumber + ": " + err.message);
}
}

})(this);
Martin-Stangl marked this conversation as resolved.
Show resolved Hide resolved
35 changes: 23 additions & 12 deletions Core/automation/lib/javascript/core/utils.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -11,7 +11,10 @@
var automationPath = OPENHAB_CONF+'/automation/';
var mainPath = automationPath + 'lib/javascript/core/';
//https://wiki.shibboleth.net/confluence/display/IDP30/ScriptedAttributeDefinition
var logger = Java.type("org.slf4j.LoggerFactory").getLogger("jsr223.javascript");

load(__DIR__+'/log.js');
var logger = Logger(null);
var loggerConsole = Logger("console");
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

All of the logging functionality should be stripped out of utils.js. The utils.js library will end up being used to hold helper functions for use in scripts and libs. This is a breaking change, but these should be expected... https://github.com/openhab-scripters/openhab-helper-libraries/blob/master/README.md#-under-construction-.

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

OK. I will the go ahead and remove this from utils.js.
But this means I have to rework all log calls all exiting core libraries.

So I first want to resolve, if we will emulate console.log (most likely yes).

Also it might be better that @jpg0 gets his CommonJS stuff done and merged into the master, before I start also changing all libraries.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

But this means I have to rework all log calls all exiting core libraries.

I'm missing something... I did not think there was much effort to pull logging out of utils.js. But yes... if the core libs need reworked for logging, then it should wait for CommonJS, if that is the direction we're going... haven't dug into that one yet!

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Well, I could just take the log methods as they are in utils.js and move them to log.js. But if we completely forego backwards compatibility and get rid of logError, logWarn, ..., I do not see much value in that. Better to leave them in utils.js, until we actually get rid of them and not pollute the new library with it.
And logError, logWarn, ...are used by the core libraries, So this needs to be changed to get rid of these methods.


try {
var RuleBuilder = Java.type("org.openhab.core.automation.util.RuleBuilder");
Expand Down Expand Up @@ -87,31 +90,39 @@

context.uuid = uuid;

context.logInfo = function(type , value) {
context.logInfo = function (type , value) {
logger.info(args(arguments));
};
context.logWarn = function(type , value) {
context.logWarn = function (type , value) {
logger.warn(args(arguments));
};
context.logDebug = function(type , value) {
context.logDebug = function (type , value) {
logger.debug(args(arguments));
};
context.logError = function(type , value) {
context.logError = function (type , value) {
logger.error(args(arguments));
};
context.logTrace = function(type , value) {
context.logTrace = function (type , value) {
logger.trace(args(arguments));
};


context.console = {};
context.console.info = context.logInfo;
context.console.warn = context.logWarn;
context.console.debug = context.logDebug;
context.console.error = context.logError;
context.console.info = function (type , value) {
loggerConsole.info(args(arguments));
};
context.console.warn = function (type , value) {
loggerConsole.warn(args(arguments));
};
context.console.debug = function (type , value) {
loggerConsole.debug(args(arguments));
};
context.console.error = function (type , value) {
loggerConsole.error(args(arguments));
};

context.console.log = function(value) {
logger.info("console.log", value);
context.console.log = function (value) {
loggerConsole.info(value.toString());
};

context.isUndefined = function(item) {
Expand Down