Can't get it to work

[simonihmig]

Hey, first thanks for working on this! Really looking forward to be able to write rules in modern JavaScript! 😁

Unfortunately I am struggling to get this to work. I tried first with how it is described in the Readme, but get this error with a simple test rule upon requiring ohj:

Error during evaluation of script 'file:/openhab/conf/automation/jsr223/javascript/personal/test.js': org.graalvm.polyglot.PolyglotException: Object: Module not found: log

Seems this is caused by

ohj/fluent/fluent.js

Line 1 in 6ccf04a

const log = require('log').Logger('fluent');

(which should be ../log)

I am able to require from other modules like lodash without any errors in the log. So at least the GraalVM integration seems to work.

I then realized the published version on npm is quite outdated, so I tried the current master branch (copying the repo into /conf/automation/lib/javascript/community/ohj and installing deps). But then I get this one:

Error during evaluation of script 'file:/openhab/conf/automation/jsr223/javascript/personal/test.js': org.graalvm.polyglot.PolyglotException: Object: Module not found: @runtime/osgi

Not really following how these special (non-existing) @runtime modules are supposed to work?

I am using the jar linked from the Readme, with Openhab 2.5.6.

[jpg0]

Thanks for giving it a try! The missing import you are seeing is because those modules are imported from the host jar, and I suspect the one you have is too old. Either you can build it yourself from https://github.com/jpg0/openhab-graaljs or I can do it and put it somewhere when I get a chance to?

[simonihmig]

Thanks for the quick feedback!

Either you can build it yourself from https://github.com/jpg0/openhab-graaljs or I can do it and put it somewhere when I get a chance to?

I can try it, though I am not a Java guy myself, so will probably need much longer than you. In case you have the time, a ready to use build would certainly be much appreciated! :)

Btw, the repo, is this the work that is supposed to eventually get merged into core, or are you following a different approach (user-land binding?) now? I saw that the PR was stuck for quite a while unfortunately...

[jpg0]

Ok, I've built a release - please give it a try!

Regarding merging to core; whilst I'm not an OH maintainer, they are keen for the Java part to become the primary JS engine used, as Nashorn is deprecated now. I do plan to get it merged in (either to core or the bundled plugins), but haven't had the time recently to create all the PRs.

As for the JS libs (this repo), this is less clear, although this is far ahead of anything else, so even if it were not directly this code I would expect it to be close. The JS libs that are available for Nashorn are pretty terrible.

[simonihmig]

Thanks a lot! I just did, but requirig modules seems to not work anymore (which worked before!):

0:49:14.267 [ERROR] [ab.automation.script.javascript.stack] - Failed to execute script:
org.graalvm.polyglot.PolyglotException: TypeError: Cannot load CommonJS module: 'lodash'
	at <js>.:program(test.js:4) ~[?:?]
	at org.graalvm.polyglot.Context.eval(Context.java:345) ~[?:?]
	at com.oracle.truffle.js.scriptengine.GraalJSScriptEngine.eval(GraalJSScriptEngine.java:379) ~[?:?]
	at com.oracle.truffle.js.scriptengine.GraalJSScriptEngine.eval(GraalJSScriptEngine.java:343) ~[?:?]
	at javax.script.AbstractScriptEngine.eval(AbstractScriptEngine.java:249) ~[?:1.8.0_252]
	at org.openhab.automation.module.script.graaljs.internal.commonjs.graaljs.GraalJSCommonJSScriptEngine.loadScript(GraalJSCommonJSScriptEngine.java:120) ~[?:?]
	at org.openhab.automation.module.script.graaljs.internal.commonjs.graaljs.GraalJSCommonJSScriptEngine.lambda$4(GraalJSCommonJSScriptEngine.java:103) ~[?:?]
	at com.sun.proxy.$Proxy877.invokeFunction(Unknown Source) ~[?:?]
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.8.0_252]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:1.8.0_252]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_252]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_252]
	at org.openhab.automation.module.script.graaljs.internal.DebuggingGraalScriptEngine.lambda$2(DebuggingGraalScriptEngine.java:78) ~[?:?]
	at org.openhab.automation.module.script.graaljs.internal.DebuggingGraalScriptEngine.withStackLogger(DebuggingGraalScriptEngine.java:102) ~[?:?]
	at org.openhab.automation.module.script.graaljs.internal.DebuggingGraalScriptEngine.lambda$0(DebuggingGraalScriptEngine.java:78) ~[?:?]
	at com.sun.proxy.$Proxy877.invokeFunction(Unknown Source) ~[?:?]
	at org.openhab.core.automation.module.script.internal.ScriptEngineManagerImpl.loadScript(ScriptEngineManagerImpl.java:161) ~[?:?]
	at org.openhab.core.automation.module.script.rulesupport.internal.loader.ScriptFileWatcher.importFile(ScriptFileWatcher.java:176) ~[?:?]
	at org.openhab.core.automation.module.script.rulesupport.internal.loader.ScriptFileWatcher.processWatchEvent(ScriptFileWatcher.java:143) ~[?:?]
	at org.eclipse.smarthome.core.service.WatchQueueReader.lambda$3(WatchQueueReader.java:323) ~[?:?]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_252]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_252]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [?:1.8.0_252]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [?:1.8.0_252]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_252]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_252]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_252]

I have ohj (in a seperate folder named ohj) and lodash (in node_modules) in /automation/lib/javascript/community, both don't work... 🤔

[jpg0]

I have an idea of what the problem is here: the changes in the build you are now using are quite major from the older one, the primary one being that I swapped out my own module loading with the one that comes with GraalJS. It works a little differently, and there is less flexibility on the paths that it will look in to find modules (it strictly follows the nodejs convention). I had to rearrange my JS folders to get it to work but I have all my code online, so you can see how I have laid things out: https://github.com/jpg0/oh-config

[simonihmig]

Thanks, that got me a little bit further. I did a npm i jpg0/ohj#master in /automation/lib/javascript/personal, which seems to allow me to require('ohj') in my /automation/jsr223/javascript/personal/test.js. At least I get no exception anymore in openhab's log.

Idk why, but now when I have same obvious syntax error, or just require() a non-existant module, I get this exception which is not very helpful in debugging:

java.lang.NullPointerException: null
	at com.oracle.truffle.polyglot.PolyglotImpl.guestToHostException(PolyglotImpl.java:475) ~[?:?]
	at com.oracle.truffle.polyglot.PolyglotContextImpl.eval(PolyglotContextImpl.java:867) ~[?:?]
	at org.graalvm.polyglot.Context.eval(Context.java:345) ~[?:?]
	at com.oracle.truffle.js.scriptengine.GraalJSScriptEngine.eval(GraalJSScriptEngine.java:379) ~[?:?]
	at com.oracle.truffle.js.scriptengine.GraalJSScriptEngine.eval(GraalJSScriptEngine.java:343) ~[?:?]
	at javax.script.AbstractScriptEngine.eval(AbstractScriptEngine.java:249) ~[?:1.8.0_252]
	at org.openhab.automation.module.script.graaljs.internal.commonjs.graaljs.GraalJSCommonJSScriptEngine.loadScript(GraalJSCommonJSScriptEngine.java:120) ~[?:?]
	at org.openhab.automation.module.script.graaljs.internal.commonjs.graaljs.GraalJSCommonJSScriptEngine.lambda$4(GraalJSCommonJSScriptEngine.java:103) ~[?:?]
	at com.sun.proxy.$Proxy868.invokeFunction(Unknown Source) ~[?:?]
	at sun.reflect.GeneratedMethodAccessor91.invoke(Unknown Source) ~[?:?]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_252]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_252]
	at org.openhab.automation.module.script.graaljs.internal.DebuggingGraalScriptEngine.lambda$2(DebuggingGraalScriptEngine.java:78) ~[?:?]
	at org.openhab.automation.module.script.graaljs.internal.DebuggingGraalScriptEngine.withStackLogger(DebuggingGraalScriptEngine.java:102) ~[?:?]
	at org.openhab.automation.module.script.graaljs.internal.DebuggingGraalScriptEngine.lambda$0(DebuggingGraalScriptEngine.java:78) ~[?:?]
	at com.sun.proxy.$Proxy868.invokeFunction(Unknown Source) ~[?:?]
	at org.openhab.core.automation.module.script.internal.ScriptEngineManagerImpl.loadScript(ScriptEngineManagerImpl.java:161) ~[?:?]
	at org.openhab.core.automation.module.script.rulesupport.internal.loader.ScriptFileWatcher.importFile(ScriptFileWatcher.java:176) ~[?:?]
	at org.openhab.core.automation.module.script.rulesupport.internal.loader.ScriptFileWatcher.processWatchEvent(ScriptFileWatcher.java:143) ~[?:?]
	at org.eclipse.smarthome.core.service.WatchQueueReader.lambda$3(WatchQueueReader.java:323) ~[?:?]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_252]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_252]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [?:1.8.0_252]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [?:1.8.0_252]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_252]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_252]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_252]

Apart from that, as I said I get no exception anymore when there is no obvious error anymore. But also I don't see anything happen. Even a simple attempt to log something does not show up. E.g. for this script, I would expect to see some logging, right?

const { rules, triggers, log } = require('ohj');
const logger = log('test');

logger.info('script started');

rules.JSRule({
    name: "test",
    description: "just a simple test",
    triggers: triggers.GenericCronTrigger("0 * * * * ?"),
    execute: triggerConfig => {
        logger.info('+++ JS Rule triggered! +++')
    }
});

I do see a message Added ScriptEngine for language 'js' with identifier: file:/openhab/conf/automation/jsr223/javascript/personal/test.js when saving the file, but nothing else...

[jpg0]

So I'm not sure why your code (or mine) is not working, but you can increase the logging by setting the following namespaces to debug:

org.openhab.automation.script.javascript.stack
script.js

(do this however you like, but I do it by going into the OH shell with openhab-cli console then log:set DEBUG <namespace>)

The first namespace should mean that any exceptions from JS code get stacks in the log. The second enables debug logging for the JS code. I'm not sure what the default is, but it may be WARN which would be why your script isn't logging anything.

Give it a go and let me know if you get any further.

[simonihmig]

I tried it with these logging settings, but did not get much further...

So under the org.openhab.automation.script.javascript.stack namespace I get to see only that NullPointerException I already posted above, whenever some error occurs (e.g. when I deliberately write faulty code). But not any kind of actual JS related error message that I would normally expect from a JS engine (e.g. Uncaught TypeError: ... is not a function)

However at least I found something: instantiating a logger already throws that exception, and it seems to be related to this log_appenders module (https://github.com/jpg0/ohj/blob/master/log.js#L208), which does not exist as an npm module. Idk what this is, something that's supposed to come out of the box from the JS engine?

So when I have this code, this already throws:

const ohj = require('ohj');
const logger = ohj.log('test');

But when I provide null for the appenderProvider argument like this:

const ohj = require('ohj');
const logger = ohj.log('test', null);

... then I at least don't see an exception anymore.

But I do get one when trying to actually log anything (logger.info('script started');).
Again, when I see only that obscure NullPointerException, it's hard to find anything out. So that's where I'm currently stuck at...

Are you using the same .jar as the one I am using? (from https://github.com/jpg0/openhab-graaljs/releases/tag/v1.0)
It seems strange that I am getting not even the simplest things working...

[jpg0]

TBH I have had some issues with the log.js module, but the ones I've seen have been related to parsing stack frames. It's something that I ported from elsewhere which really needs a rewrite.

The appenders thing was something that I added to allow consumers to insert log appenders in Javascript in case they want their log lines to get sent somewhere else in addition to the OH log. I use it to send any ERROR lines to Telegram so that I don't miss any errors. The way I came up with to do this was to depend on a module with a specific name (log_appenders) that included additional config, and if that was not found it should just ignore it and only log to OH. Saying this, since it was built I have switched over to the native GraalJS module loading, so possibly that cannot handle the missing module.

Anyway, let's figure out where the issue is. First, we should isolate the problem to either the host GraalJS bundle, or the ohj library. I'd advise doing this by logging something directly, without using ohj. You can do this with a script containing:

Java.type("org.slf4j.LoggerFactory").getLogger("test_logger").error("test error");

If this fails, then I believe the problem is with the bundle. If not, it is likely with ohj (and the log module).

Also, I am not using that exact jar (I built it after you asked), but have one that should reflect the same code that I built a long time ago (although didn't post it as I wasn't sure exactly how to extract it from OH). If it has problems though I'll switch to it to get it working. Since you've started trying to get it working, it's inspired me to find the time to make progress on reintegrating back in OH, which will mean that I need to make changes and rebuild + retest this bundle anyway openhab/openhab-addons#8441.

[simonihmig]

If this fails, then I believe the problem is with the bundle. If not, it is likely with ohj (and the log module).

It did not fail, I was able to see this in OH logs!

[simonihmig]

Investigated this a bit more, and finally got at least the logger working:

• replaced the getAppenderForLevel() call with null as a default. Not sure how this is meant to work, so filed Logger fails due to unknown log_appenders module #11
• logger was not able to match the stack line I was getting, so throws the Failed to parse stack line exception.
  Was able to see that when putting that direct Java call you posted into https://github.com/jpg0/ohj/blob/master/log.js#L156. Filed Logger is not able to match stackLine  #10
• instead of throwing, I changed the logger to just output without caller details. Created PR: Don't throw if logger is not able to parse caller details #9

[simonihmig]

Again, this was pretty hard to debug, as again I don't see anything but that NullPointerException if anything goes wrong. So debugging was like putting those direct logger calls in random places, commenting out random lines etc. until you somehow get a clue what's happening. I don't see "regular" openhab users eventually being able to debug their failed scripts if that is still the case! 🤔

[simonihmig]

After having figured out #12, I finally have a dummy rule getting triggered successfully! 🚀

Thanks so far for your assistance here! I'm going to close this, as the issue is kind-of solved, and we have the more specific ones to track the remaining issues!

[jpg0]

BTW, regarding the nightmare debugging - yes I completely agree. I explicitly included code in the bundle to log the JS stack, although there is some contention in OH core about whether this will even be allowed (!). They only want stack traces for errors in the core OH logic, and it's questionable whether scripts qualify for that. This is why I've logged it with a specially named (and by default disabled) appender of org.openhab.automation.script.javascript.stack as an attempted compromise. Still not sure why that one isn't working for you, but I'll get myself onto the same build as you and look into it then.