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.

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

[jsscripting] Fix multi-threading issues in UI-based scripts #17510

Merged
merged 5 commits into from
Oct 24, 2024

Conversation

florian-h05
Copy link
Contributor

@florian-h05 florian-h05 commented Oct 5, 2024

This fixes illegal multi-thread access requests to the GraalJS context for UI-based rules.

Those have two causes:

  1. The execution of pre-compiled scripts (refs [rules] Add support for pre-compilation of conditions and actions openhab-core#4289) is not synchronized for JS Scripting.
  2. If the script is currently executed and a timer is already waiting to acquire the lock, illegal multi-thread access is requested even though the locking mechanism is in place. I cannot really explain that behaviour, but it seems to be a timing issue in the milliseconds range ... When adding logging, the logger tells me that the timer acquires the lock before its released by the script execution. And when attaching a debugger to verify the correct functionality of the locking mechanism, the issue is gone, which IMO again speaks for a timing issue ...

This is fixed through the following:

  1. Add support for synchronized execution of pre-compiled scripts in [automation] Add support for synchronized execution of compiled scripts openhab-core#4402 and implement the Lock interface in the ScriptEngine that gets passed to openHAB Core.
  2. Add a Thread.sleep of 1/100 second to the Lock unlocking logic inside the add-on.

The issue can be reproduced by pasting the following script into a script inside the UI and running it:

console.log('Sleeping...')
setTimeout(() => {
  console.log('Timer ran.')
}, 1000)
setTimeout(() => {
  console.log('Timer ran.')
}, 2000)
setTimeout(() => {
  console.log('Timer ran.')
}, 3000)
java.lang.Thread.sleep(10000)

Signed-off-by: Florian Hotze <florianh_dev@icloud.com>
Signed-off-by: Florian Hotze <florianh_dev@icloud.com>
… Core can lock and unlock when executing the pre-compiled script

Signed-off-by: Florian Hotze <florianh_dev@icloud.com>
Signed-off-by: Florian Hotze <florianh_dev@icloud.com>
…-threading issues with UI-based scripts

Signed-off-by: Florian Hotze <florianh_dev@icloud.com>
@florian-h05 florian-h05 added bug An unexpected problem or unintended behavior of an add-on awaiting other PR Depends on another PR labels Oct 5, 2024
@florian-h05 florian-h05 requested review from lsiepel and jlaur October 5, 2024 10:00
@J-N-K J-N-K removed the awaiting other PR Depends on another PR label Oct 6, 2024
@@ -230,7 +229,10 @@ public Path toRealPath(Path path, LinkOption... linkOptions) throws IOException
protected void beforeInvocation() {
Copy link
Member

Choose a reason for hiding this comment

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

When is this method called (when executing a script)?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

It is called everytime before the engine executes code, there is only one exception: When a compiled script is executed, this won't be called (it has been called when the script was compiled, so the setup already happened).

See https://github.com/openhab/openhab-addons/blob/main/bundles/org.openhab.automation.jsscripting/src/main/java/org/openhab/automation/jsscripting/internal/scriptengine/InvocationInterceptingScriptEngineWithInvocableAndCompilableAndAutoCloseable.java, there is beforeInvocation called.

@florian-h05
Copy link
Contributor Author

Any feedback on this PR?

Copy link
Member

@kaikreuzer kaikreuzer left a comment

Choose a reason for hiding this comment

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

As nobody has a better idea - let's merge this. Thanks @florian-h05!

@kaikreuzer kaikreuzer merged commit e6056d3 into openhab:main Oct 24, 2024
5 checks passed
@kaikreuzer kaikreuzer added this to the 4.3 milestone Oct 24, 2024
@florian-h05 florian-h05 deleted the jsscripting branch October 24, 2024 17:05
@florian-h05
Copy link
Contributor Author

Just confirmed this fix works on my

  • production system Linux smarthomevm 6.1.0-26-amd64 #1 SMP PREEMPT_DYNAMIC Debian 6.1.112-1 (2024-09-30) x86_64 GNU/Linux with openjdk version "17.0.13" 2024-10-15
  • development system Linux pc-fh211 6.11.3-200.fc40.x86_64 #1 SMP PREEMPT_DYNAMIC Thu Oct 10 22:31:19 UTC 2024 x86_64 GNU/Linux with openjdk version "21.0.5" 2024-10-15

@SkyLined
Copy link
Contributor

SkyLined commented Oct 26, 2024

I cannot really explain that behaviour, but it seems to be a timing issue in the milliseconds range
<snip>
This is fixed through the following:
<snip>
Add a Thread.sleep of 1/100 second to the Lock unlocking logic inside the add-on.

Not to be overly critical but that doesn't sound like a fix for a specific issue as mush as a mitigation against an unknown issue. There is no guarantee that 1/100 seconds is enough given that we do not know the root cause; it may simply happen less often with this mitigation. Having said that, this is an improvement and I cannot judge if it's worth investigating deeper right now or focusing on other things. I don't know what the policy is for using the bug tracker to track things, but personally, I'd leave an issue open as a reminder to come back to remove the Thread.sleep, try to find the root cause, and write a proper fix at some point in the future.

florian-h05 added a commit to florian-h05/openhab-core that referenced this pull request Oct 26, 2024
…implements Lock

This moves the locking mechanism added in openhab#4402 to the inheritors of AbstractScriptModuleHandler
to synchronize execution context access as well.

This fixes the problem thathttps://github.com/openhab/openhab-addons/pull/17510 worked around by using Thread.sleep.

Signed-off-by: Florian Hotze <dev@florianhotze.com>
@florian-h05
Copy link
Contributor Author

I was not satisfied with this solution so I started some futher investigation once I had the time to do so, and after checking the core code again, I found the root cause and created a fix: openhab/openhab-core#4426
After this has been merged, the Thread.sleep can be removed here.

kaikreuzer pushed a commit to openhab/openhab-core that referenced this pull request Oct 26, 2024
…implements Lock (#4426)

This moves the locking mechanism added in #4402 to the inheritors of AbstractScriptModuleHandler
to synchronize execution context access as well.

This fixes the problem thathttps://github.com/openhab/openhab-addons/pull/17510 worked around by using Thread.sleep.

Signed-off-by: Florian Hotze <dev@florianhotze.com>
@kaikreuzer kaikreuzer removed the bug An unexpected problem or unintended behavior of an add-on label Oct 26, 2024
KaaNee pushed a commit to KaaNee/openhab-addons that referenced this pull request Nov 8, 2024
…#17510)

* [jsscripting] Make logger non-static
* [jsscripting] Log lock acquisition and release
* [jsscripting] Implement Lock in DebuggingGraalScriptEngine so openHAB Core can lock and unlock when executing the pre-compiled script
* [jsscripting] Improve comments in ThreadsafeTimers
* [jsscripting] Add a short sleep after unlocking the lock to fix multi-threading issues with UI-based scripts

Signed-off-by: Florian Hotze <florianh_dev@icloud.com>
@kaikreuzer kaikreuzer added the bug An unexpected problem or unintended behavior of an add-on label Nov 14, 2024
matchews pushed a commit to matchews/openhab-addons that referenced this pull request Dec 16, 2024
…#17510)

* [jsscripting] Make logger non-static
* [jsscripting] Log lock acquisition and release
* [jsscripting] Implement Lock in DebuggingGraalScriptEngine so openHAB Core can lock and unlock when executing the pre-compiled script
* [jsscripting] Improve comments in ThreadsafeTimers
* [jsscripting] Add a short sleep after unlocking the lock to fix multi-threading issues with UI-based scripts

Signed-off-by: Florian Hotze <florianh_dev@icloud.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug An unexpected problem or unintended behavior of an add-on
Projects
None yet
Development

Successfully merging this pull request may close these issues.

4 participants