Initial contribution core/log.js

[Martin-Stangl]

Integration of my logger as a core library.

Fully backwards compatible: Logging functions in core/utils.js have been kept but were adjusted to use the new core/log.js.

Documentation is not done yet. The sun is already rising and I want some sleep :-). I will add it, once the implementation is considered good to merge. But it works pretty much as described here: https://github.com/Martin-Stangl/openHAB-javascript-rule-libraries/blob/master/README.md. The relevant differences are:

• Log line formats changed slightly.
• Notification levels are now NOTIFY_OFF, NOTIFY_ERROR, NOTIFY_WARN, NOTIFY_INFO and NOTIFY_DEBUG. (I was worried to create a conflict if I throw a variable called OFF into the global context. Not an issue anymore, when we adopt a module architecture.)
• Support for parameterized logging added: logger.debug("The new entry is {}. It replaces {}.", entry, oldEntry);

Let me know if this needs any major changes or if I can go ahead an prepare the documentation. Thanks.

[Martin-Stangl]

After getting a little bit of sleep, I think I want to make the compatibility functionality, which was the last thing I added in, the default behavior. This means getting rid of the need to wrap the message in an Error object.

Also I noticed that the console.log function in utils.js just creates an INFO log entry with the text „console.log“. I initially kept the behavior in the rewrite, but it would make more sense to fix it.So I will do that.

[Martin-Stangl]

I completed the changes:

• It is now possible to log an Error object or a string: log.error("Test") and log.error(Error("Test")) produce the same result.
• Parameterized notifications fixed. I basically forgot to implement it initially, when I did it for the logging part.
• context.console.log fixed and console logs now log to [jsr223.javascript.console]
• Minor changes to the "short" log format.

This should be it (except for the missing documentation).

PS: Next step would then be probably to replace all core logging calls to use log.js. It is not mandatory, as the utils.js log functions work as before (output format is slightly different), but I saw that a lot of error logging uses LINE to specify the error position instead of err.lineNumber. This makes the error messages point to the line where the error is logged instead of the actual line, where the error occurs, which is not ideal.

[5iver]

All of the logging in the JS libraries should go through this new lib. The other logging functions should be removed. I will review as soon as I can find some time. Hopefully @lewie will go through this too!

@jpg0, you had a library for logging in your test commit. Does the functionality in this PR align with yours? Do you have any suggestions or improvements?

The JS libraries are still under construction, so do what you can, but don't get blocked if you can't keep backwards compatibility.

[Martin-Stangl]

Another remark: One thing utils.js does right now is to override console.log and the other console.* logging functions. I did not move this to log.js, as I am not sure it is needed, but kept in in utils.js instead.

My thought also is that at some point the backwards compatibility support could be dropped by just cleaning up utils.js. Or we could meanwhile collect these things in a separate compatibility library, so we can also clean up utils.js earlier.

[jpg0]

Just got this from your library: 2019-10-22 20:18:44.503 [ERROR] [jsr223.javascript.schedules ] - [source /etc/openhab2/automation/lib/javascript/personal/log.js, line 121, function _getLogMessage] Cannot read property "split" from undefined

I expect that I fed it a bad (error) object to log or something, but that error message is pretty cryptic and looks like it hit an edge-case. (The error I fed it was: java.lang.ClassCastException: Cannot cast jdk.nashorn.internal.runtime.Undefined to java.util.Collection)

[Martin-Stangl]

Just got this from your library: 2019-10-22 20:18:44.503 [ERROR] [jsr223.javascript.schedules ] - [source /etc/openhab2/automation/lib/javascript/personal/log.js, line 121, function _getLogMessage] Cannot read property "split" from undefined

I expect that I fed it a bad (error) object to log or something, but that error message is pretty cryptic and looks like it hit an edge-case. (The error I fed it was: java.lang.ClassCastException: Cannot cast jdk.nashorn.internal.runtime.Undefined to java.util.Collection)

Yes, this is caused by providing an object, which is not an Error object. I wanted to check, if I got an Error object or a child object of Error object, but knew this will be tricky. So I just made a "cheaper" implementation first but then forgot to revisit it. I think it is not an even an edge-case, but something many people might do: Just temporary log out an object for debugging purposes, to figure out what is going on. I will provide a fix.

[Martin-Stangl]

Just got this from your library: 2019-10-22 20:18:44.503 [ERROR] [jsr223.javascript.schedules ] - [source /etc/openhab2/automation/lib/javascript/personal/log.js, line 121, function _getLogMessage] Cannot read property "split" from undefined I expect that I fed it a bad (error) object to log or something, but that error message is pretty cryptic and looks like it hit an edge-case. (The error I fed it was: java.lang.ClassCastException: Cannot cast jdk.nashorn.internal.runtime.Undefined to java.util.Collection)

Yes, this is caused by providing an object, which is not an Error object. I wanted to check, if I got an Error object or a child object of Error object, but knew this will be tricky. So I just made a "cheaper" implementation first but then forgot to revisit it. I think it is not an even an edge-case, but something many people might do: Just temporary log out an object for debugging purposes, to figure out what is going on. I will provide a fix.

Fixed this. Was easy, I was just thinking too complicated at the time.

[jpg0]

@openhab-5iver sorry I never responded to your original questions:

@jpg0, you had a library for logging in your test commit. Does the functionality in this PR align with yours? Do you have any suggestions or improvements?

The logging library that I had was actually just some handy utilities that I was using, but wasn't really a logging library. The only function that it had over this was the ability to pass in the level in case it needed to be dynamic: log.atLevel('warn', 'message'), but I'm not concerned if this isn't present as it's a rare use-case and it's easy to wrap this library if needed.

Looking at this contribution, I think most of the things that I thought about are already being covered. The only other one is the whole notification functionality. I'm undecided about that. I do think that it's useful to be able to notify of errors, however this seems like a weird place to put it. Typically you wouldn't do it like this as it's pretty high coupling and at a high level in the stack, but would instead expect something like:

• use a chain of responsibility pattern to allow adding notifications if required
• use an event-based system to reduce coupling further, allowing notifications to subscribe to applicable log events to also send them as notifications (possibly async events here)
• just do notifications as a log Appender and stick it into the log system so that all of OH gets this functionality But TBH I'm not too concerned; given that this doesn't affect the API for scripts its something which can be changed or moved at a later date.

Also, as for the compatibility with a move to CommonJS, this works fine and I've already switched over to using it. I agree that we should remove all the logInfo etc, functions, and need to think about what we will do with console.log (I do like that it's defined as it will allow existing 3rd party nodeJS code to work).

[5iver]

The only other one is the whole notification functionality. I'm undecided about that. I do think that it's useful to be able to notify of errors, however this seems like a weird place to put it.

I agree. I put it into Jython core.log to test and almost forgot it was there, but was reminded by a random error that showed up on my phone. It's caught several that I probably would have missed. I'm sure there is a better way, but I've been glad that I put it in.

[jpg0]

After using this library for quite a bit, I wanted to raise a UX issue: the prepending of location can be a positive, but can also be a big drawback when log statements start in differing columns. The current OH logging includes namespace, but truncates (or pads) them to ensure that log messages always begin at the same column. This is not the case with this library and I'm having a really hard time reading debug logs because I cannot scan down the messages because they begin at different places on the screen. I would suggest two options:

• (hard) use a fixed size string to include location information, just like OH does
• (easy) provide a global toggle to override location information on and off - similar to how the npm debug package works.

[Martin-Stangl]

I agree to the UX issue. I myself noticed that it sometime is difficult to quickly see the actual message as there so much stuff is going on before it. I will try something else first: I will will shorten the filename and put the location details at the end instead.

[Martin-Stangl]

The only other one is the whole notification functionality. I'm undecided about that. I do think that it's useful to be able to notify of errors, however this seems like a weird place to put it. Typically you wouldn't do it like this as it's pretty high coupling and at a high level in the stack, but would instead expect something like:

• use a chain of responsibility pattern to allow adding notifications if required
• use an event-based system to reduce coupling further, allowing notifications to subscribe to applicable log events to also send them as notifications (possibly async events here)
• just do notifications as a log Appender and stick it into the log system so that all of OH gets this functionality

I agree, this should be decoupled. This tight coupling resulted from this initially being just a helper function for me. Simple and easy to use. It got already a bit more sophisticated, when I decided to make it public and meanwhile it is reaching a point where having logging and notification combined is making things a little messy.

Right now I am thinking in the following direction: Create a console.js, (similar to what node.js has), but instead of it logging directly, log.js and notification.js can subscribe to console.js. The two things I have still to figure out:

• One instance of Console should be initialized by default, ideally with no load/require needed at all (as node.js does), so console.log() just works out of the box. A Logger with default config will be initialized with this Console instance and subscribe to all Console log events of Console to get the messages into the log by default.
• Some clever subscription management: I personally would use my own instances of Console instead of the default one and suggest this for each core library as well. Simply to have different logger names, so log levels can be controlled per library. But I guess this would require features like "subscribe to error messages of any Console instance" and "have the default Logger automatically subscribe to my new Console instance.

[5iver]

After using this library for quite a bit, I wanted to raise a UX issue: the prepending of location can be a positive, but can also be a big drawback when log statements start in differing columns.

@jpg0, could you please include an image of what you mean? I have commented out the "Common pattern layout for appenders" section at the top of the org.ops4j.pax.logging.cfg file, so my logging looks different than stock...

[jpg0]

Sure; here's a sample:

Often I'm looking for a specific log statement about what I'm working on. When the statements don't start at the same horizontal location it's very hard to scan down to find the statement that you're after.

[Martin-Stangl]

@jpg0 please let me know how you like the new format, once you had a chance to try it out. Thanks.

[jpg0]

@Martin-Stangl aplologies for the delay; been busy this week. Anyway, yes I much prefer this.

I did add a couple of comments regarding stack parsing, which make this code fail on Graal (I've managed to get this working; I'll submit a PR once I'm happy with it all). Additionally the fileName property on an error is not present in Graal. Up to you if you want to attempt to handle these at this point.

Also, one other question: why did you do this as an object with Object.create, rather than just a closure with error/warn/etc as methods in the returned object? Was it to try to allow polymorphism in the future? I ask because this style I find much more complex (and that's even with me coming from Java and initially attempting to OO all my JS).

[Martin-Stangl]

Additionally the fileName property on an error is not present in Graal. Up to you if you want to attempt to handle these at this point. fileName, lineNumber and stack are all not part of the ECMAScript standard. So ideally I should not use any of it, but that leaves me with nothing. I guess I will integrate a fallback to pull it out of stack and maybe another fallback if even stack is not available?

Also, one other question: why did you do this as an object with Object.create, rather than just a closure with error/warn/etc as methods in the returned object? For once, because we only have ES5 :-P I wanted to have private methods and variables and initially could not find another way to do it or at least I also understood. So meanwhile, all my stuff is built like that. I did not went so far to need polymorphism (although I think I have a first proper use case at hand: lights - some are HSBtypes, some On/Off), but I make use of the possibility to define which variables are writable and which not.

[jpg0]

I noticed that while Graal doesn't have the fileName property (although it does have stack), you can get the filename from the stack. For example, here is a stack trace:

org.graalvm.polyglot.PolyglotException: TypeError: Cannot read property 'split' of undefined
        at <js>._getLogMessage(log.js:55) ~[?:?]
        at <js>.info(log.js:178) ~[?:?]
        at <js>.context.JSRule(rules.js:110) ~[?:?]
        at <js>.:anonymous(<eval>:35) ~[?:?]
        at <js>.:program(<eval>:4) ~[?:?]
        at org.graalvm.polyglot.Context.eval(Context.java:344) ~[?:?]
        at com.oracle.truffle.js.scriptengine.GraalJSScriptEngine.eval(GraalJSScriptEngine.java:346) ~[?:?]

Not sure if that is useful! I do think at a minimum being defensive over the property not being present would be worthwhile (at least for me right now!).

[jpg0]

Regarding the class construction stuff, what I meant was instead of:

<in Logger function>
var _privateFunction = ...
...
return Object.create(Object.prototype, {
                publicProperty: {value: "foo"},
                ...
                publicFunction: { value: function publicFunction (param) {
                   //impl
                }},
                ...
}

to use a closure, like the other existing files (by lewie I gather) use:

<in Logger function>
var _privateFunction = ...
...
return {
                publicProperty: "foo",
                ...
                publicFunction: function (param) {
                   //impl
                },
                ...
}

(Not sure what your dev background is, but I had primarily Java experience before I started with JS, but was quickly shown to stop trying to make everything OO and embrace closures and functional style, and only use classes for specific cases.)

[Martin-Stangl]

Thanks, I must have totally failed to see this approach in lewie's code. I actually tried to copy lewie's style before doing something else, but back then my JS knowledge did not allow me to understand it all too well. (Not that I became an expert in the past 2 weeks...)

Yes, this would get rid of Object.create(Object.prototype.

I think the other stuff is the exact same thing: It should be possible to use publicProperty: "foo" instead of publicProperty: {value: "foo"}, also in Object.create. I actually considered to change this, once I figured out that all my functions where called value in the stack trace due to that notation if I do not name them, but have the proper name when using your shorter notation. I wonder if there is also a different notation, if want to make a variable writable, which is easier to read. I am sure there is a way to do it differently, but have to see, if it has better readability.

So I am wondering, if it is an advantage to keep Object.create around as the rest should be adjustable to your suggested style. At the moment I have no arguments for or against it.

(I guess my dev background has not much to do with the choice. I already coded in 25+ languages but programming stopped being my main business over a decade ago. And back than I mostly worked in SAP ABAP, before it knew about any OO concepts - and old ABAP does not translate to JS very well. So in the rare occasions when it happens that I find time to do some programming, I basically have to start from scratch and google for every command how it is named an how it is used. And in this case I only knew I wanted something that I could best describe as an object and ended up with Object.create after some googling. Mostly because the blog explaining it was probably the best to explain it to me.)

[jpg0]

The only benefit I know of explicitly using Object.create is that it allows you to develop an object hierarchy if you want polymorphism. I don't think it's necessary here though so I'd drop it.

I wonder if there is also a different notation, if want to make a variable writable, which is easier to read.

I don't understand this? All the variables here are writable AFAIK? var will mean that it's writable, you need to use const (which won't work with Nashorn, but will with Graal) to make it readonly. Object properties are typically always writable.

[Martin-Stangl]

Sorry, my wording was not precise: I am referring to the object properties. For e.g. if I do this:

var log = Logger("MyLoggerName");
log.name = "MyNewLoggerName";

It will throw the following error: 16:33:35.231 [ERROR] [ript.internal.ScriptEngineManagerImpl] - Error during evaluation of script 'file:/C:/WORKSP~1/Projects/openHAB/openhab/conf/automation/jsr223/javascript/personal/test.js': TypeError: "name" is not a writable property of [object Object] in <eval> at line number 17

The reason is that all object properties are write protected by default and I did not specify anything changing this:

            return Object.create(Object.prototype, {
                name: { value: _name },

If I would want name to be writable, I would need to change it to:

            return Object.create(Object.prototype, {
                name: { value: _name, writable: true },

I really like this, as I can make some information available without additional effort, but still be ensured that nobody changes my variables unexpectedly. Otherwise I would need to make these properties private and write getters. There are also a few other parameters, but I did not make use of them yet. See Object.defineProperty()

[jpg0]

Ah, I wasn't aware that you were trying to expose readonly properties. TBH I have never really used these as I've not really seen them used much in APIs so haven't used them myself. If you want to retain them, then yes you'd need to keep this style (or alternatively Object.freeze the object before you return it).

Also: another question as I'm regularly butchering the code to ensure it works as a module: Do you anticipate that Logger is the only top-level function that you will expose? Because if so I'll make it the default export so that you can create loggers like this:

const log = require('log')('myscript');
log.info(...);

Much nicer than require('log').Logger('myscript'); IMO.

[Martin-Stangl]

I tried to simplify the style based on your example but with Object.create, but it did not work. So my assumption above was wrong and I guess it has to stay as it is. Object.freeze or Object.defineProperty would be an option, but it means freezing every object in my returned object separately. Although, if I do not care about the functions, it would not come up that often.

Yes, I intend to keep it the only one exposed function.

[Martin-Stangl]

@openhab-5iver: I really like your idea of creating a console log functionality. But right now I have to focus on actually doing my rule implementations and then a different project. So I will not come around to it soon.

But I could wrap up the current state by replacing the core library logging with this logger in a way that it would be compatible to a future actual console implementation. This means

• call the log object console
• only use console.error, console.warn, console.info and console.debug
• no use of {} replacement
• no use of the notification functionality

For documentation I could document the full feature set or only the console compatible usage for now. It would even be an option to rip out any functionality, which does not conform with console and provide it as console.js, or at least wrap the logger in a core console object. I like the idea more and more as I type this out.

The other approach would be to be logAction compatible, what we basically are, if we ignore the log.trace and notification functionality.

What do you think?

Question is also on what to do with the community stuff. This all would probably break. Should we update this too or leave it to the creators?

[jpg0]

@Martin-Stangl re: Object.freeze, I think you only need to change your code to:

return Object.freeze(Object.create(Object.prototype(...

ps. now I'm using ES6, all the class-based stuff is far nicer!

[jpg0]

@Martin-Stangl I've just ported this to ES6 as it kept failing on Graal stacktraces; in case you're interested it's here: https://gist.github.com/jpg0/5c991b486255b015221a04056548a74b (I removed notifications in favour of providing a callback which could process them).

[Martin-Stangl]

@Martin-Stangl re: Object.freeze, I think you only need to change your code to:

return Object.freeze(Object.create(Object.prototype(...

ps. now I'm using ES6, all the class-based stuff is far nicer!

It would almost work. Object.freeze does not freeze objects in the object, so config would remain writable. The problem is described here and they also show a simple deepFreeze() function to handle this. And not relevant for log.js, but I use the same pattern in all my "classes" in my rules, so I have cases, where I keep some properties writable. So I would also need to consider a feature to specify which properties to freeze and which not. This could definitely be put into a freezer function. I would not be surprised, if someone out there already made it.

[jpg0]

That's true, but I was just trying to emulate what you've already done - right now making the config a readonly property still allows consumers to mess with what's inside it. My personal view on this is that it's not worth exposing at this point, as the use-cases for getting something that you've just set are pretty slim for a logger. For simplicity, I wouldn't expose anything that is passed in until (a) it's really needed or (b) it becomes much easier with ES6.

[jpg0]

Thought that I'd leave a comment here as I finally got around to adding custom appender support to my logging module, for another approach on how it could be done. I decided that the simplest way to do it was to have the log library search for a predefined module of appenders when it loads. The code is here and can be used by dropping in a 'log_appenders.js' file with content such as:

module.exports = {
    forLevel: level => {
        switch(level){
            case "error":
                return {
                    logAt: (level, msg) => sendLogErrorLineSomewhere(msg)
                }
            default:
                return null;
        }
    }
};

I think it strikes a good balance between not hardcoding any specific appenders (for mine I have error messages going to a telegram group for example), performance (very little code in the logging hot path) and simplicity.