[jsscripting] Script dependency tracking will be disabled

[rkoshak]

Expected Behavior

To not see warning level log statements for things I can't change or correct. The fact they are at the warning level implies there is a potential problem.

Current Behavior

I've all of my rules in the UI. The first time these rules run, often I'll see the following warning in the logs.

2022-03-15 10:13:47.005 [WARN ] [.internal.OpenhabGraalJSScriptEngine] - Failed to retrieve script script dependency listener from engine bindings. Script dependency tracking will be disabled.

It doesn't say what rule. It doesn't say what script dependency. And it doesn't seem to impact the running of the rule in any apparent way. The rule still works as expected.

Possible Solution

Change the level of the log statement to INFO.

Steps to Reproduce (for Bugs)

1. Create a rule in the UI. The following is an example from my rules.

configuration: {}
triggers: []
conditions: []
actions:
  - inputs: {}
    id: "1"
    configuration:
      type: application/javascript;version=ECMAScript-2021
      script: >-
        var logger = log('Alarm');


        var hour = time.ZonedDateTime.now().hour();

        var currToD = items.getItem('TimeOfDay').state;


        logger.debug('Current ToD = {} Current Hour = {}', currToD, hour);

        if(currToD == 'NIGHT' || hour < 5) {
          logger.info("The alarm went off and it's night time, turning on the lights for ten minutes");
          items.getItem('TOD_Lights_ON_MORNING').sendCommand('ON');
          actions.ScriptExecution.createTimer(time.ZonedDateTime.now().plusMinutes(5), function() {
            items.getItem('TOD_Lights_ON_MORNING').sendCommand('OFF');
          });
        }

        else if(currToD == 'BED'){
          logger.info('Good morning!');
          items.getItem('TimeOfDay').sendCommand('MORNING');
        }

        else {
          logger.warn("The alarm went off but it's not BED or NIGHT")
        }
    type: script.ScriptAction

I'm not importing anything from my own libraries and depending on the automatic importation of openhab-js.

2. Save the rule to force it to be reloaded.
3. Manually run the rule.

Context

It's not a big impact but I worry about users becoming alarmed when they see this warning in their logs.

Your Environment

• Version used: 3.3.0.M2
• Environment name and version (e.g. Chrome 76, Java 8, Node.js 12.9, ...): latest official Docker Image
• Operating System and version (desktop or mobile, Windows 10, Raspbian Buster, ...): latest official Docker Image

runtimeInfo:
  version: 3.3.0.M2
  buildString: Milestone Build
locale: en-US
systemInfo:
  configFolder: /openhab/conf
  userdataFolder: /openhab/userdata
  logFolder: /openhab/userdata/logs
  javaVersion: 11.0.14
  javaVendor: Azul Systems, Inc.
  javaVendorVersion: Zulu11.54+23-CA
  osName: Linux
  osVersion: 5.4.0-104-generic
  osArchitecture: amd64
  availableProcessors: 4
  freeMemory: 132181136
  totalMemory: 465567744
  startLevel: 70
bindings:
  - astro
  - bluetooth
  - chromecast
  - ipcamera
  - mail
  - mqtt
  - network
  - networkupstools
  - openweathermap
  - roku
  - shelly
  - zigbee
  - zwave
timestamp: 2022-03-15T16:39:37.760Z

[J-N-K]

I believe this is a core issue. I have reports of similar issues with other JSR-223 languages that also relate to a missing ScriptDependencyListener in the engine bindings.

[ardanedh]

I believe this is a core issue. I have reports of similar issues with other JSR-223 languages that also relate to a missing ScriptDependencyListener in the engine bindings.

I can confirm, this happened in my system, running openHAB 3.2 with docker.

[goodfore]

Confirmed still happening in OH 3.3 with docker.

[frest-de]

Still happening in 3.4.0.M1 on a fresh openhabian installation. Happens with every ecma 11 rule.

[florian-h05]

@jpg0
How should we proceed here? You said that you think it’s a core problem. Is there an issue for it?
If we don’t come to a real fix, we should probably change the log level to INFO as @rkoshak pointed out.

[J-N-K]

After looking at the code again, I believe it might be an issue with the AbstractWatchService. For GraalJS it should never happen, because as far as I can see these scripts should always have a dependency tracker (it's created in the constructor of the watch service). My guess would be that the issue is that the same directory might be watched by the DefaultScriptFileWatcher and a call from somewhere else happens. If this is the case, it'll probably either happen more often (on every load) or disappear with openhab/openhab-core#3004.

In the mean time reducing it to INFO might help, but as the warning suggests, this might get you into trouble if you use dependencies.

[florian-h05]

Thanks for the explanation, I would propose to wait until your core PR is merged and see if that solves it.
This problem only occurs for UI scripts, for file based scripts the dependencies are properly watched.

In the mean time, I’ll reduce the log level to info and have a look if I can add some more information (script name).
The non-working dependency tracking for UI scrips shouldn’t read to real problems, the thing is, that you need to disable/enable or resave the script if you want to update it‘s dependencies.

[J-N-K]

I didn't read closely enough. If it's an UI only issue the WatchService can't be the problem. I'll check again.

Edit: After checking the code it is clear that there is no dependency listener for UI scripts but it is needed. This is a bug which I believe should be solved in core. Can you open an issue for that? Thanks.

[florian-h05]

Can you open an issue for that?

See openhab/openhab-core#3166.