I am able to reproduce the issue with the boost being stuck at 10 minutes. It doesn’t happen when the system is set to HVAC, only when it is set to “Generic”. To troubleshoot, I watched openhab.log as I clicked the boost button. This displayed an error message:
2023-03-21 10:23:23.727 [ERROR] [e.automation.internal.RuleEngineImpl] - Failed to execute rule '5635a61b-859b-48d5-82f4-a53f6e1c34d1': Fail to execute action: 2
I went into the PaperUI → Rules and clicked the run icon next to “Boost Looping Timer” and I saw a more detailed error message:
Details of the java.lang.ClassNotFoundException error
2023-03-21 10:24:01.331 [WARN ] [e.automation.internal.RuleEngineImpl] - Fail to execute action: 2
java.lang.RuntimeException: java.lang.ClassNotFoundException: org.eclipse.smarthome.model.script.actions.ScriptExecution cannot be found by com.eclipsesource.jaxrs.publisher_5.3.1.201602281253
at jdk.nashorn.internal.runtime.ScriptRuntime.apply(ScriptRuntime.java:397) ~[nashorn.jar:?]
at jdk.nashorn.internal.runtime.Context.evaluateSource(Context.java:1222) ~[nashorn.jar:?]
at jdk.nashorn.internal.runtime.Context.load(Context.java:839) ~[nashorn.jar:?]
at jdk.nashorn.internal.objects.Global.load(Global.java:1546) ~[nashorn.jar:?]
at jdk.nashorn.internal.scripts.Script$125$\^eval\_.:program(<eval>:2) ~[?:?]
at jdk.nashorn.internal.runtime.ScriptFunctionData.invoke(ScriptFunctionData.java:637) ~[nashorn.jar:?]
at jdk.nashorn.internal.runtime.ScriptFunction.invoke(ScriptFunction.java:494) ~[nashorn.jar:?]
at jdk.nashorn.internal.runtime.ScriptRuntime.apply(ScriptRuntime.java:393) ~[nashorn.jar:?]
at jdk.nashorn.api.scripting.NashornScriptEngine.evalImpl(NashornScriptEngine.java:449) ~[nashorn.jar:?]
at jdk.nashorn.api.scripting.NashornScriptEngine.evalImpl(NashornScriptEngine.java:406) ~[nashorn.jar:?]
at jdk.nashorn.api.scripting.NashornScriptEngine.evalImpl(NashornScriptEngine.java:402) ~[nashorn.jar:?]
at jdk.nashorn.api.scripting.NashornScriptEngine.eval(NashornScriptEngine.java:155) ~[nashorn.jar:?]
at javax.script.AbstractScriptEngine.eval(AbstractScriptEngine.java:264) ~[?:1.8.0_222]
at org.openhab.core.automation.module.script.internal.handler.ScriptActionHandler.lambda$0(ScriptActionHandler.java:62) ~[?:?]
at java.util.Optional.ifPresent(Optional.java:159) ~[?:1.8.0_222]
at org.openhab.core.automation.module.script.internal.handler.ScriptActionHandler.execute(ScriptActionHandler.java:59) ~[?:?]
at org.openhab.core.automation.internal.RuleEngineImpl.executeActions(RuleEngineImpl.java:1189) [bundleFile:?]
at org.openhab.core.automation.internal.RuleEngineImpl.runNow(RuleEngineImpl.java:1037) [bundleFile:?]
at org.openhab.core.automation.internal.RuleEngineImpl.runNow(RuleEngineImpl.java:1053) [bundleFile:?]
at org.openhab.core.automation.rest.internal.RuleResource.runNow(RuleResource.java:288) [bundleFile:?]
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.8.0_222]
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:1.8.0_222]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_222]
at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_222]
at org.glassfish.jersey.server.model.internal.ResourceMethodInvocationHandlerFactory$1.invoke(ResourceMethodInvocationHandlerFactory.java:81) [bundleFile:?]
at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher$1.run(AbstractJavaResourceMethodDispatcher.java:144) [bundleFile:?]
at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.invoke(AbstractJavaResourceMethodDispatcher.java:161) [bundleFile:?]
at org.glassfish.jersey.server.model.internal.JavaResourceMethodDispatcherProvider$ResponseOutInvoker.doDispatch(JavaResourceMethodDispatcherProvider.java:160) [bundleFile:?]
at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.dispatch(AbstractJavaResourceMethodDispatcher.java:99) [bundleFile:?]
at org.glassfish.jersey.server.model.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:389) [bundleFile:?]
at org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:347) [bundleFile:?]
at org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:102) [bundleFile:?]
at org.glassfish.jersey.server.ServerRuntime$2.run(ServerRuntime.java:326) [bundleFile:?]
at org.glassfish.jersey.internal.Errors$1.call(Errors.java:271) [bundleFile:?]
at org.glassfish.jersey.internal.Errors$1.call(Errors.java:267) [bundleFile:?]
at org.glassfish.jersey.internal.Errors.process(Errors.java:315) [bundleFile:?]
at org.glassfish.jersey.internal.Errors.process(Errors.java:297) [bundleFile:?]
at org.glassfish.jersey.internal.Errors.process(Errors.java:267) [bundleFile:?]
at org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:317) [bundleFile:?]
at org.glassfish.jersey.server.ServerRuntime.process(ServerRuntime.java:305) [bundleFile:?]
at org.glassfish.jersey.server.ApplicationHandler.handle(ApplicationHandler.java:1154) [bundleFile:?]
at org.glassfish.jersey.servlet.WebComponent.serviceImpl(WebComponent.java:473) [bundleFile:?]
at org.glassfish.jersey.servlet.WebComponent.service(WebComponent.java:427) [bundleFile:?]
at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:388) [bundleFile:?]
at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:341) [bundleFile:?]
at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:228) [bundleFile:?]
at com.eclipsesource.jaxrs.publisher.internal.ServletContainerBridge.service(ServletContainerBridge.java:76) [bundleFile:?]
at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:852) [bundleFile:9.4.20.v20190813]
at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:544) [bundleFile:9.4.20.v20190813]
at org.ops4j.pax.web.service.jetty.internal.HttpServiceServletHandler.doHandle(HttpServiceServletHandler.java:71) [bundleFile:?]
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143) [bundleFile:9.4.20.v20190813]
at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:536) [bundleFile:9.4.20.v20190813]
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) [bundleFile:9.4.20.v20190813]
at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235) [bundleFile:9.4.20.v20190813]
at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1581) [bundleFile:9.4.20.v20190813]
at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233) [bundleFile:9.4.20.v20190813]
at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1307) [bundleFile:9.4.20.v20190813]
at org.ops4j.pax.web.service.jetty.internal.HttpServiceContext.doHandle(HttpServiceContext.java:293) [bundleFile:?]
at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188) [bundleFile:9.4.20.v20190813]
at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:482) [bundleFile:9.4.20.v20190813]
at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1549) [bundleFile:9.4.20.v20190813]
at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186) [bundleFile:9.4.20.v20190813]
at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1204) [bundleFile:9.4.20.v20190813]
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) [bundleFile:9.4.20.v20190813]
at org.ops4j.pax.web.service.jetty.internal.JettyServerHandlerCollection.handle(JettyServerHandlerCollection.java:80) [bundleFile:?]
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) [bundleFile:9.4.20.v20190813]
at org.eclipse.jetty.server.Server.handle(Server.java:494) [bundleFile:9.4.20.v20190813]
at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:374) [bundleFile:9.4.20.v20190813]
at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:268) [bundleFile:9.4.20.v20190813]
at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311) [bundleFile:9.4.20.v20190813]
at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103) [bundleFile:9.4.20.v20190813]
at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:117) [bundleFile:9.4.20.v20190813]
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:336) [bundleFile:9.4.20.v20190813]
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:313) [bundleFile:9.4.20.v20190813]
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171) [bundleFile:9.4.20.v20190813]
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:129) [bundleFile:9.4.20.v20190813]
at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:367) [bundleFile:9.4.20.v20190813]
at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:782) [bundleFile:9.4.20.v20190813]
at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:918) [bundleFile:9.4.20.v20190813]
at java.lang.Thread.run(Thread.java:748) [?:1.8.0_222]
Caused by: java.lang.ClassNotFoundException: org.eclipse.smarthome.model.script.actions.ScriptExecution cannot be found by com.eclipsesource.jaxrs.publisher_5.3.1.201602281253
at org.eclipse.osgi.internal.loader.BundleLoader.findClassInternal(BundleLoader.java:484) ~[org.eclipse.osgi-3.12.100.jar:?]
at org.eclipse.osgi.internal.loader.BundleLoader.findClass(BundleLoader.java:395) ~[org.eclipse.osgi-3.12.100.jar:?]
at org.eclipse.osgi.internal.loader.BundleLoader.findClass(BundleLoader.java:387) ~[org.eclipse.osgi-3.12.100.jar:?]
at org.eclipse.osgi.internal.loader.ModuleClassLoader.loadClass(ModuleClassLoader.java:150) ~[org.eclipse.osgi-3.12.100.jar:?]
at java.lang.ClassLoader.loadClass(ClassLoader.java:357) ~[?:1.8.0_222]
at org.eclipse.osgi.internal.framework.EquinoxBundle.loadClass(EquinoxBundle.java:564) ~[org.eclipse.osgi-3.12.100.jar:?]
at org.ops4j.pax.swissbox.core.BundleClassLoader.findClass(BundleClassLoader.java:176) ~[bundleFile:?]
at java.lang.ClassLoader.loadClass(ClassLoader.java:424) ~[?:1.8.0_222]
at org.ops4j.pax.swissbox.core.BundleClassLoader.loadClass(BundleClassLoader.java:192) ~[bundleFile:?]
at java.lang.ClassLoader.loadClass(ClassLoader.java:357) ~[?:1.8.0_222]
at java.lang.Class.forName0(Native Method) ~[?:1.8.0_222]
at java.lang.Class.forName(Class.java:348) ~[?:1.8.0_222]
at jdk.nashorn.internal.runtime.Context.findClass(Context.java:1051) ~[nashorn.jar:?]
at jdk.nashorn.internal.objects.NativeJava.simpleType(NativeJava.java:498) ~[nashorn.jar:?]
at jdk.nashorn.internal.objects.NativeJava.type(NativeJava.java:322) ~[nashorn.jar:?]
at jdk.nashorn.internal.objects.NativeJava.type(NativeJava.java:314) ~[nashorn.jar:?]
at jdk.nashorn.internal.objects.NativeJava.type(NativeJava.java:310) ~[nashorn.jar:?]
at jdk.nashorn.internal.scripts.Script$Recompilation$127$34A$utils.L:3(/etc/openhab2/automation/lib/hestia/utils.js:31) ~[?:?]
at jdk.nashorn.internal.scripts.Script$126$utils.:program(/etc/openhab2/automation/lib/hestia/utils.js:3) ~[?:?]
at jdk.nashorn.internal.runtime.ScriptFunctionData.invoke(ScriptFunctionData.java:637) ~[nashorn.jar:?]
at jdk.nashorn.internal.runtime.ScriptFunction.invoke(ScriptFunction.java:494) ~[nashorn.jar:?]
at jdk.nashorn.internal.runtime.ScriptRuntime.apply(ScriptRuntime.java:393) ~[nashorn.jar:?]
... 79 more
This looks like it might be a bigger issue than just the boost not working as expected. It’s also worth noting that this is the same problem as the Can’t stop boosting thread which was experienced on the official 1.2-dev image. We never really got to a root cause or resolved that one, but rather just worked around it. I just restored the stock 1.2-dev image, which does not have this issue. I’ll try to get to the bottom of this issue this time around.
Before going any further, I switched back into HVAC mode to run these same tests and see if the error message and stacktrace also appears when the timer is working properly. If so, then they can likely be ignored. It turned out, the error & stracktrace did not appear.
Logs when boost is working properly
2023-03-21 10:47:00.544 [INFO ] [.eclipse.smarthome.model.script.mode] - Heating mode changed from OFF to Boost
2023-03-21 10:47:02.439 [INFO ] [eclipse.smarthome.model.script.boost] - Starting Heating boost
2023-03-21 10:47:03.699 [INFO ] [eclipse.smarthome.model.script.boost] - 10 minutes remaining on boost for Heating
2023-03-21 10:47:10.849 [INFO ] [marthome.model.script.heatingcooling] - TURN ON Heating: heating delta is 14 cooling delta is -18 hysteresis is 1
2023-03-21 10:47:14.353 [INFO ] [lipse.smarthome.model.script.heating] - Turning ON the heater: curr temp = 56 setpoint = 70 mode = Boost
2023-03-21 10:47:25.839 [INFO ] [.eclipse.smarthome.model.script.mode] - Fan mode changed from OFF to AUTO
2023-03-21 10:47:28.890 [INFO ] [g.eclipse.smarthome.model.script.fan] - FanMode is AUTO
2023-03-21 10:47:31.938 [INFO ] [g.eclipse.smarthome.model.script.fan] - Turning ON the fan: fan mode = AUTO
2023-03-21 10:47:33.563 [INFO ] [.eclipse.smarthome.model.script.pins] - Commanding Pin12 to ON for HeatingPin
2023-03-21 10:47:33.899 [INFO ] [.eclipse.smarthome.model.script.pins] - FanPin commanded to ON
2023-03-21 10:47:34.270 [INFO ] [.eclipse.smarthome.model.script.pins] - Commanding Pin18 to ON for FanPin
2023-03-21 10:48:04.858 [INFO ] [eclipse.smarthome.model.script.boost] - 9 minutes remaining on boost for Heating
I switched back into Generic mode and did a few hours worth of debugging. I didn’t solve this one, but here’s a summary of what I learned:
- “Hot Water Control” and “TempUnit changed” rules had this same stacktrace when run, but “Process Sensor Changes” did not. I didn’t see any pattern in which rules raised an exception and which ones did not
- I found that if I load util.js in the Boost Looping Timer rule, I get the exception and if I don’t load utils.js, I don’t. Digging further, the two lines that will cause this exception are
Java.type("org.eclipse.smarthome.model.script.actions.ScriptExecution")andJava.type("org.eclipse.smarthome.io.net.exec.ExecUtil"). However,Java.type("org.slf4j.LoggerFactory")did not cause any exception. - I found two ScriptExecution classes online. The one our code is trying to load is in the (now archived) smarthome project. The other is in OpenHAB. They look similar, but they are not the same. Calling
Java.type("org.openhab.core.io.net.exec.ExecUtil")also raised a ClassDefNotFound exception. - I noticed that jaxrs seems to be the thing trying to load ExecUtil (from the error:
org.eclipse.smarthome.io.net.exec.ExecUtil cannot be found by com.eclipsesource.jaxrs.publisher_5.3.1.201602281253). I found the Maven page about this version of this library. Going to the project HomePage shows us this project is also archived and no longer maintained. - Running
dpkg -L openhab2shows some config related to “smarthome”, but no jar file. The jaxrs v5.3.1 jar file does appear in this list./usr/share/openhab2/runtime/system/com/eclipsesource/jaxrs/publisher/5.3.1/publisher-5.3.1.jar. I don’t see any jar files that look like they would have the Eclipse of version ofExecUtil, but I did find/usr/share/openhab2/runtime/system/org/openhab/core/bundles/org.openhab.core.io.net/2.5.0/org.openhab.core.io.net-2.5.0.jarwhich I would expect to contain the OpenHAB version ofExecUtil.
The glaring questions remain: why can the Boost Looping Timer rule find this Class in the US mode (HVAC), but not in the EU mode (Generic)? and why don’t all rules have this issue in EU mode?
I’ll keep plugging away and see if I can make any progress at answering these.
As for the LCD screen, I’m perplexed. Our screens look identical as far as I can tell. It doesn’t make any sense why they are behaving differently. Since we currently have two people reporting that it’s working as expected, I think what is in the image now should be the default, but we should have a single command that anyone having issues can run to swap over to the alternative configuration.
Maybe call it something like ./fix_LCD.sh, put it in the scripts directory and make the content something like the following?
echo 'Section "InputClass"
Identifier "calibration"
MatchProduct "ADS7846 Touchscreen"
Option "Calibration" "254 3910 3716 1476"
Option "SwapAxes" "1"
Option "InvertX" "1"
Option "InvertY" "1"
EndSection' | sudo tee /etc/X11/xorg.conf.d/99-calibration.conf > /dev/null
sudo shutdown -r now