If you have an extra micro SD card, you can flash that with this testing image and then just swap SD cards. Give the new one a try and then swap back yo your main system. This is the safest way to test it out.
If you have a GitHub account and can submit this chsnge as a merge request from the HestiaPi/hestia-touch-openhab repo, I can just rebuild the image and it’ll have this feature.
If not, I can submit your patch at some point. I’m just not sure when I’ll get to it.
I can confirm that the countdown starts showing the, say, 10 min, and stays there. No countdown, no triggered action after the time has elapsed (even though the minutes never go down).
Committed just now.
This call is to determine the public IP of HestiaPi to help you setup external access without using OpenHAB’s (free) cloud service. It is then shown on the LCD on the information screen (i icon top right). Ideally it should be easily enabled/disabled from UI with disabled as the default. In terms of privacy/security I doubt it adds any risk.
Downloading… I expect the LCD to behave the same…
I need to check that a little bit more as I don’t think humidity is often expressed with decimals. It sure adds accuracy but also may clutter the UI. Looking around many commercial UIs, I only see decimals in Celsius which are much larger units (20C is 68F while 21C is ~70F) and need more precision. Humidity on the other hand has always been shown as integers. I’d rather leave it as it is unless others need it too.
Yes I have a git hub account. I will look at the source java files and submit a request.
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
Rich @rlkoshak do you have any clues as to where to look at? Boost (rule Boost Looping Timer) works fine on HVAC mode but not on Generic (EU) and stays on the initial time indefinitely.
Will try and troubleshoot a bit more on this but till we actually manufacture/sell devices, users will buy “whatever” they can source locally/from China and minor tweaks like these will always be needed, so I’m not sure if this will end up being only 2 options like it is now or we will simply suggest a method (like the calibration tool) for users to find their needed settings. Also CPU is a little high and I don’t know if this would affect anything…
So far the latest image, is looking good apart from my previous issues 1 & 3 mentioned.
I have added enough debug statements to see in the logs that in some rules, the ScriptExecution and ExecUtil classes are getting loaded just fine when in EU mode. I believe it is the Process Sensor Changes rule that is firing frequently which is outputting these log messages, but whatever rule it is, it’s clear that it’s working properly.
I believe part of my issue in troubleshooting is that the context in which rule execution happens makes a difference. Pressing the “run” button is not the same as an event being triggered by something in the “When…” clause.
To be clear: I’m saying that it is possible that the ClassNotFound issue only occurs when attempting to manually run the test. If so, that’s incredibly annoying, but it is not the cause of the boost timer not working.
My debugging continues, just wanted to post an update so nobody goes down rabbit holes on account of the fuzzy picture of what’s going on that I painted in my previous post.
Note, it’s easier to read stack traces and logs when code fences are used.
```
code goes here
```
That will preserve the spacing and keep the text contained.
Just to confirm, this is still running on OH 2, correct? If it’s OH 3 than this is another breaking change that I forgot about when listing the breaking changes previously. One of the primary drivers of OH 3 in the first place was the fact that Eclipse Smarthome was essentially closed down and all that stuff was brought back over to be part of openHAB core. That means everywhere where you see “org.eclipse.smarthome” in a rule it needs to be replaced with “org.openhab”. Beyond that everything else is the same. So org.eclipse.smarthome.model.script.actions.ScriptExecution becomes org.openhab.model.script.actions.ScriptExecution
If this is OH 2 still (which seems to be the case since you mentioned PaperUI) I can’t imagine what would cause these to fail loading sometimes but not all the time. Those Java.type lines of code are basically importing Java Classes from openHAB itself and they are definitely in the org.eclipse.smarthome package for OH 2. The fact that OH is up and running at all means those Classes exist and there shouldn’t be anything preventing their import. There doesn’t appear to be a typo on the imports.
This isn’t surprising really. IIRC the “Process Sensor Changes” is mainly a traffic cop, deciding what to do based on the change and the current state. It’s the “Control” rules that actually take action.
I can’t remember why I used ExecUtil instead of the executeCommandLine Action. there had to be a good reason but it’s been years. But what ever is going on it’s the same reason ScriptExecution is failing.
Yes, everything moved to the org.openhab but only for OH 3. In OH 2 it’s still in the org.eclipse.smarthome packages. But ExecUtil is sort of an internal class so it may have moved or changed between OH 2 and OH 3 beyond just moving packages. That code should probably be changed to use executeCommandLine instead.
OH 2.5 is approaching 2.5 years old at this point so a lot of things it depends upon will be no longer maintained. However, the installation package comes with all the libraries it depends on so that shouldn’t matter. But the root problem is that for some reason the rules engine simply cannot find classes that are part of OH itself which is weird in the extreme.
I’m not sure if dpkg looks inside .kar files. That’s where you’d find it, inside openhab.kar.
Indeed that’s the question. It’s the same code for the most part. I don’t recall any reports of a problem like this reported on the OH forum and I never experienced it myself. Later today I will try some tests and see if I can reproduce but it’s looking like something outside of our control buried deep in OH code which means upgrading is going to be the only way to fix it.
Note that manually running a rule does indeed work differently. Many of the rules require information from the Item that triggered it. So it’s not always possible to trigger a rule manually in any meaningful way. It differs on a rule by rule basis.
But that should not cause those Java.type lines to fail. Those should work no matter how the rule is executed.
Yeah, this is still OpenHAB 2.
Good news: It’s possible to fix this issue. I have done so on my test system.
Bad news: I’m not sure what I changed to make it work, and now I can’t reproduce the issue. 
I was keeping notes here, which I’ll post below so I (or others) can pick up where I’m leaving off in case we are able to reproduce this again later. The short version, is that I did a lot of debugging and I was understanding how all these rules work when I uncommented the code for the Boost Looping Timer rule and it started working. So flashed the latest buster image (Job #4861 in pipeline #1524), set up wifi, switched it to Generic mode, and the boost timer works just fine. I don’t see any errors in the logs either.
If anyone can repro this issue with the latest image, if you can check /var/log/openhab2/openhab.log to see what’s going on and post all the output from the time you press the boost button, it could be helpful in allowing me to get to the bottom of this.
Debugging notes
The Boost Looping Timer rule only fires when one of the following items changes: Heating/Cooling/Hot Water/Humidity boost time remaining.
The Boost rule will update the previous mode, turn on the check, and set the boost time. For example, when boosting the heat, the HeatingPrevMode is set without triggering any other rules. HeatingCheck is set to “ON” (triggering any updates that are set to happen when the heat is turned on). And the HeatingRemBoostTime item is updated to items[“HeatingBoostTime”], which is 10 (minutes).
Updating HeatingCheck should cause the Heating/Cooling Check rule to fire, which it does. This rule correctly determines that we’re in boost mode and sets HeatingCtl to “ON”.
The Heat Control rule then fires on account of the HeatingCtl command being sent. It turns the main switch on if it wasn’t already on. This is where the functionality differs in the US mode versus the EU mode. In the EU mode, it turns the heat on (HeatingPin = ON), but in US mode it turns the Fan off and then ten seconds later it’ll turn on the heat (HeatingPin = ON) and set the fan to auto. Finally, in either case, it sets HeatingMode to “Boost” (with a comment that this updates the LCD screen).
Turning the heat on will trigger the Map Pin to GPIO rule, which uses the SystemType (US or EU) to get the pin mapping. This ends up turning ON Pin23. I can’t find the code that executes when “Pin23” is sent the command of “ON”, but as far as I understand the heat is turning on, so I am not diving deeper into this.
Updating HeatingRemBoostTime, which is the last thing the Boost rule does, should trigger “Boost Loop Timer”.
The BoostLoopTimer rule should create a timer that fire in 60 seconds. The action to occur when the timer fires is to decrement the boost time by 1. This is the part that is not happening when in EU mode.
Debugging rules
Here are some snippets of JS that can be put into the rules to better understand what’s happening at runtime. These should be entered in the Paper UI → Rules → Click the rule to edit → Click the gear under the “then…” clause → read the code and replace only the appropriate parts (these are not the entire script, just snippets).
Boost Looping Timer:
var OPENHAB_CONF = Java.type('java.lang.System').getenv('OPENHAB_CONF');
// BEGIN debugging info
var LOG_ROOT = "";
var logger = Java.type("org.slf4j.LoggerFactory").getLogger(LOG_ROOT+"boost");
logger.info("Executing the boost loop timer now");
// END debugging info
load(OPENHAB_CONF + '/automation/lib/hestia/utils.js');
// BEGIN debugging info
logger.info("Loaded utils.js");
// END debugging info
var logName = "boost";
var mode = event.itemName.replace("RemBoostTime", "");
It’s “Map Pin to GPIO” which takes the name of the Item that triggered the rule and sends a command to the Item linked to the GPIO pin through the GPIO binding.
I just had a chance to look at the rules a little. My goodness I forgot how far we’ve come in OH 3 when it comes to UI rules and the helper functions.
Which part? The rule isn’t triggering at all? The timer isn’t being created, or the boost time isn’t being decremented?
Or is that still to be determined?
Looking at the code for Boost Looping Timer, it doesn’t even know whether it’s in US or EU mode so it’s weird that that makes a difference. The only thing I can think of is if perhaps in EU mode, the items[mode+"BoostTimer"] Item (e.g. HeatingBoostTimer) isn’t being commanded to ON so the timer isn’t created, or maybe it’s already ON because of a restoreOnStartup or something?
But this is the same rule that commands the BoostTimer Item in the first place, but it’s something to check. What’s the state of the BoostTimer Item when the BoostLoopTimer Rule triggers the first time in EU mode? If it’s already ON before the rule gets called the first time, it will never set the looping timer and will never return to OFF, breaking the looping timer entirely.
If that’s the case, the quick and easy fix is to simply update the BoostTimer Item to OFF. The long term fix is going to be complicated to capture this error case and frankly, when/if we move to OH 3 I’ll volunteer to rewrite the rules and hopefully simplify them significantly. There is a lot of code here that is only here to avoid duplicating a lot of code and to deal with limitations in OH 2 and ECMAScript 5.1 which do not exist in OH 3 and ECMAScript 2021 with the helper library.
I’ve switched back and forth between US and EU with this latest build (pipeline 1524), and I can’t reproduce the issue now.
Thinking it may be some silent, intermittent failure in the build process, I flashed the previous buster testing image (pipeline 1520) onto another card, but I was also unable to reproduce the issue there either.
I think the loop rule was being triggered once, and only once, that being why the timer was set to 10 minutes (first run of the rule) but never decremented (because the rule wasn’t repeating, for reasons unknown).
The only thing that comes to mind with an intermittent failure like this is that it’s happening when there is memory pressure, hitting I/O limits, CPU load causing interrupts not to fire properly, or something along these lines. But I can’t even reproduce the issue immediately after boot, which is when the system is under the heaviest load (initialization routines running, caches having not been filled, etc.).
If I can just get it to happen again, I understand the rules well enough now to do much better troubleshooting.
Same here… issue is “gone” 
I hate these…
I found a bug in 1.2-dev that I wanted to bring up so it does not get into future builds.
If you issue a sudu reboot either from the UI or the CLI openHAB will freeze after it loads the paper UI. You then have to issue a shutdown -h now then hard reset and it will boot back up. After that it will sometimes restore the last setting. It also does this on a power failure as we just had one.
If you do a shutdown -h now on a working system then a reset it always comes back up.
I wasn’t sure a sudo reboot causes any issues as I’ve done this many times. Make sure you close all browser tabs before the Pi reboots.
In the case of a power failure sometimes I need to manually run from the Paper UI the rule Initialization.
Please check again and report back
Rebooting / power outages
- I normally reboot with
sudo shutdown -r nowwhich has always worked fine on all of the images. - I tried
sudo rebootand the thermostat worked and I could load the Paper UI without trouble - When I’ve had power outages with the official 1.2-dev image, sometimes it requires a proper reboot and other times it comes up and functions just fine.
- I pretty much always just cut power to the images I’ve been testing and haven’t seen any problems with that either, but I’m not sure I’d notice if the temperature set points got reset. I haven’t seen the heat get to 0 C, which is nice because 32 clicks is a lot to get to 16C!
LCD touch screen
I just re-tried the X11 settings that worked for @HestiaPi (InvertX, InvertY, etc.) and can confirm it renders my LCD unusable.
Boost
Boost mode is still working for me, for better or worse.
Rebooting / power outages
- I normally reboot with
sudo shutdown -r nowwhich has always worked fine on all of the images. - I tried
sudo rebootand the thermostat worked and I could load the Paper UI without trouble - When I’ve had power outages with the official 1.2-dev image, sometimes it requires a proper reboot and other times it comes up and functions just fine.
- I pretty much always just cut power to the images I’ve been testing and haven’t seen any problems with that either, but I’m not sure I’d notice if the temperature set points got reset. I haven’t seen the heat get to 0 C, which is nice because 32 clicks is a lot to get to 16C!
LCD touch screen
I just re-tried the X11 settings that worked for @HestiaPi (InvertX, InvertY, etc.) and can confirm it renders my LCD unusable.
Wrapping up
What needs to happen to make the buster build the new official image? I believe the only issue that can still be reproduced is with @HestiaPi’s touchscreen.
I suppose a new version would be in order. I’d like to propose 1.21-dev. This makes it clear that there may still be issues, distinguishes it from 1.2-dev, and since there aren’t any new features, I feel like only a very small version change is in order.
With the OS change I think it should be 1.3-dev and then when released make it 1.3.0. When going to openHAB 3 might want to go to 2.0.
With the OS change I think it should be 1.3-dev and then when released make it 1.3.0. When going to openHAB 3 might want to go to 2.0.
I’m also fine with this scheme. When we get this settled, I’ll need to look into how to update the version number on the Maintenance screen in the OpenHAB Basic UI. Right now it says 1.1, which is obviously wrong.
Boost mode bug
I’ve finally made some progress in reproducing a bug with boost mode (hopefully the bug with boost mode, but I’m not sure about that). I can reproduce it reliably in EU mode, sometimes also in US mode, and I confirmed that it happens on the 1.2-dev image too (at least, in EU mode). The bug I am able to reproduce is completely independent of any issues with loading Java classes. Let’s call this bug “concurrent boosting” to distinguish it from any other boosting bugs that may also exist.
The punchline is that if the user attempts to boost system B while system A is boosting, system A will boost forever and the timer will cease to continue count down. This is 100% reproducible in EU mode.
In US mode, the only two systems that can be attempted to be boosted at the same time are Heating and Cooling. There’s logic in the Boost rule (in the “but only if…” clause) to make sure the thermostat refuses to allow the heating and cooling systems to battle each other. This protection seems to avoid this bug sometimes, but not other times. This may be some kind of race condition.
I don’t fully understand why, but it seems like any existing timers are cancelled (or perhaps replaced?) if the Boost rule is triggered. This seems to get that system wedged into a state that I have only been able to get out of by rebooting the entire system.
Edit 1: I see there’s a code path in the implementation of ScriptExecution that will delete an old timer, but that should not happen in our test case. That would require pressing both boost buttons within at least the same second, as the DateTime is used as part of the key. Everything in the Java code looks like it supports multiple, concurrent timers. The Boost Loop Timer rule does not currently save a reference to the timer that gets created, so there’s no way for any of the JavaScript code to cancel the timer. I still don’t see how timers are getting lost, but it seems pretty clear from the logs that’s what’s going on here.
Edit 2: The first boost timer gets converted to count down the timer on the second system. For example, if I boost Heating then boost Humidity, the Humidity counter will go from 10 to 0 in 5 minutes. See logs immediately below. I can’t explain why this is happening, only that it is happening.
Log showing double counting (note the timestamps for the "x minutes remaining" lines)
2023-03-27 18:25:38.037 [INFO ] [.eclipse.smarthome.model.script.pins] - Commanding Pin23 to ON for HeatingPin
2023-03-27 18:26:23.019 [INFO ] [eclipse.smarthome.model.script.boost] - 9 minutes remaining on boost for Heating
2023-03-27 18:26:28.858 [INFO ] [.eclipse.smarthome.model.script.mode] - Humidity mode changed from OFF to Boost
2023-03-27 18:26:29.175 [INFO ] [eclipse.smarthome.model.script.boost] - Starting Humidity boost
2023-03-27 18:26:30.686 [INFO ] [eclipse.smarthome.model.script.boost] - 10 minutes remaining on boost for Humidity
2023-03-27 18:26:31.765 [INFO ] [ipse.smarthome.model.script.humidity] - Turning ON the Dehumidify: curr humidity = 52.9 setpoint = 50 mode = Boost
2023-03-27 18:26:32.931 [INFO ] [.eclipse.smarthome.model.script.pins] - Commanding Pin18 to ON for HumidityPin
2023-03-27 18:27:23.798 [INFO ] [eclipse.smarthome.model.script.boost] - 9 minutes remaining on boost for Humidity
2023-03-27 18:27:31.494 [INFO ] [eclipse.smarthome.model.script.boost] - 8 minutes remaining on boost for Humidity
2023-03-27 18:28:24.534 [INFO ] [eclipse.smarthome.model.script.boost] - 7 minutes remaining on boost for Humidity
2023-03-27 18:28:32.282 [INFO ] [eclipse.smarthome.model.script.boost] - 6 minutes remaining on boost for Humidity
2023-03-27 18:29:25.540 [INFO ] [eclipse.smarthome.model.script.boost] - 5 minutes remaining on boost for Humidity
2023-03-27 18:29:32.963 [INFO ] [eclipse.smarthome.model.script.boost] - 4 minutes remaining on boost for Humidity
2023-03-27 18:30:26.320 [INFO ] [eclipse.smarthome.model.script.boost] - 3 minutes remaining on boost for Humidity
2023-03-27 18:30:33.828 [INFO ] [eclipse.smarthome.model.script.boost] - 2 minutes remaining on boost for Humidity
2023-03-27 18:31:11.710 [INFO ] [marthome.model.script.heatingcooling] - TURN ON Heating: heating delta is 10 cooling delta is -14 hysteresis is 1
2023-03-27 18:31:27.308 [INFO ] [eclipse.smarthome.model.script.boost] - 1 minutes remaining on boost for Humidity
2023-03-27 18:31:34.700 [INFO ] [eclipse.smarthome.model.script.boost] - Boost for Humidity has ended, restoring to OFF
2023-03-27 18:31:35.756 [INFO ] [.eclipse.smarthome.model.script.mode] - Humidity mode changed from Boost to OFF
2023-03-27 18:31:36.015 [INFO ] [.eclipse.smarthome.model.script.mode] - Cancelling boost mode
2023-03-27 18:31:36.792 [INFO ] [ipse.smarthome.model.script.humidity] - Turning OFF the Dehumidify: curr humidity = 52.8 setpoint = 50 mode = OFF
2023-03-27 18:31:38.502 [INFO ] [.eclipse.smarthome.model.script.pins] - Commanding Pin18 to OFF for HumidityPin
2023-03-27 18:31:40.385 [INFO ] [marthome.model.script.heatingcooling] - TURN ON Heating: heating delta is 11 cooling delta is -15 hysteresis is 1
This even happened to me once with the “when” condition of the Boost rule was met, even if the rule never executes on account of the “but only when” clause. However, I’ve not been able to reliable reproduce that, so we should probably focus on the EU mode for now.
The rest of this post will be going over the details of how I discovered this bug, the logs that show what’s happening when I exercise it, and so forth. The only other relevant things to note for those who don’t want all the gory details are:
- I do not have a fix for this yet (but I have some ideas)
- The workaround is to not try to boost multiple things concurrently
- There may be additional bugs related to boosting and I’m not sure if fixing the bug described here, and if so, fixing this bug may fix them… or maybe not.
- There are concise instructions on how to reproduce this issue on the 1.2-dev image at the end of this post
Finding the Concurrent Boosting bug
I have three HestiaPi boxes running three different versions of the firmware (build 1520 of 1.3-dev, build 1524 of 1.3-dev, and the official 1.2-dev image). This is because it takes a long time to reproduce the issue and to reboot if I get things into a messed up state.
I was able to get the boost timers to not count down properly on Saturday on the 1524 build (latest candidate to be 1.3-dev) in EU mode. This happened when I boosted everything at once. Then I tried to debug, but my system was in some wonky state so that didn’t go very well. I’ve saved a bunch of notes, but I’m not going to post them here because I fear it’ll cause more confusing than it would solve.
I switch to my other Buster test system (build 1520) to try to reproduce the issue. This was in US mode and since rebooting was going to take 15 minutes, I decided to try to reproduce it in US mode first and switch to EU mode if I couldn’t trigger it in US mode.
I boosted the cooling, which started working fine. When it got down to 6 minutes, I attempted to boost the heat, expecting it to reject my request. It did reject my request (switching the heat from Boost back to Off), but then it broke the cooling boost timer.
the gory details
Full logs:
2023-03-26 02:26:09.875 [INFO ] [.model.script.initialization.kickoff] - OH is loaded, kicking off initialization, Initialized == NULL
2023-03-26 02:26:09.926 [INFO ] [.model.script.initialization.kickoff] - Commanding Initialization Rule to start
2023-03-26 02:26:14.718 [INFO ] [marthome.model.script.initialization] - Initializing settings...
2023-03-26 02:26:18.902 [INFO ] [marthome.model.script.initialization] - MaxTempSetpoint is 2, initializing to 74
2023-03-26 02:26:19.270 [INFO ] [marthome.model.script.initialization] - MaxTempSetpointF is 2, initializing to 74
2023-03-26 02:26:20.133 [INFO ] [marthome.model.script.initialization] - Comfort_Mode is COMFORT, Default value is 1
2023-03-26 02:26:20.254 [INFO ] [marthome.model.script.initialization] - Comfort_Value is 1, initializing to 1
2023-03-26 02:26:24.018 [INFO ] [marthome.model.script.initialization] - System is ready to operate, kicking off restored behaviors
2023-03-26 02:26:26.461 [ERROR] [e.automation.internal.RuleEngineImpl] - Failed to execute rule '32223121-5acf-423f-a9f5-1dffbe665927': Fail to execute action: 2
2023-03-26 18:07:46.396 [INFO ] [.eclipse.smarthome.model.script.mode] - Cooling mode changed from OFF to Boost
2023-03-26 18:07:51.502 [INFO ] [eclipse.smarthome.model.script.boost] - Starting Cooling boost
2023-03-26 18:07:53.748 [INFO ] [eclipse.smarthome.model.script.boost] - 10 minutes remaining on boost for Cooling
2023-03-26 18:07:59.163 [INFO ] [marthome.model.script.heatingcooling] - TURN ON Cooling: heating delta is 1 cooling delta is -5 hysteresis is 1
2023-03-26 18:08:03.048 [INFO ] [lipse.smarthome.model.script.cooling] - Turning ON the cooling: curr temp = 69 setpoint = 74 mode = Boost
2023-03-26 18:08:10.842 [INFO ] [marthome.model.script.heatingcooling] - TURN ON Cooling: heating delta is 1 cooling delta is -5 hysteresis is 1
2023-03-26 18:08:11.059 [INFO ] [lipse.smarthome.model.script.cooling] - Turning ON the cooling: curr temp = 69 setpoint = 74 mode = Boost
2023-03-26 18:08:14.990 [INFO ] [.eclipse.smarthome.model.script.mode] - Fan mode changed from OFF to AUTO
2023-03-26 18:08:18.211 [INFO ] [g.eclipse.smarthome.model.script.fan] - FanMode is AUTO
2023-03-26 18:08:21.678 [INFO ] [g.eclipse.smarthome.model.script.fan] - Turning ON the fan: fan mode = AUTO
2023-03-26 18:08:23.318 [INFO ] [.eclipse.smarthome.model.script.pins] - Commanding Pin23 to ON for CoolingPin
2023-03-26 18:08:23.721 [INFO ] [.eclipse.smarthome.model.script.pins] - FanPin commanded to ON
2023-03-26 18:08:24.033 [INFO ] [.eclipse.smarthome.model.script.pins] - Commanding Pin18 to ON for FanPin
2023-03-26 18:08:56.340 [INFO ] [eclipse.smarthome.model.script.boost] - 9 minutes remaining on boost for Cooling
2023-03-26 18:09:57.264 [INFO ] [eclipse.smarthome.model.script.boost] - 8 minutes remaining on boost for Cooling
2023-03-26 18:10:57.827 [INFO ] [eclipse.smarthome.model.script.boost] - 7 minutes remaining on boost for Cooling
2023-03-26 18:11:58.370 [INFO ] [eclipse.smarthome.model.script.boost] - 6 minutes remaining on boost for Cooling
2023-03-26 18:12:19.641 [INFO ] [.eclipse.smarthome.model.script.mode] - Heating mode changed from OFF to Boost
2023-03-26 18:12:20.032 [ERROR] [eclipse.smarthome.model.script.boost] - Cooling is already ON, cannot activate Boost for Heating
2023-03-26 18:12:20.329 [INFO ] [.eclipse.smarthome.model.script.mode] - Heating mode changed from Boost to OFF
2023-03-26 18:12:20.529 [INFO ] [.eclipse.smarthome.model.script.mode] - Cancelling boost mode
2023-03-26 18:12:24.771 [INFO ] [lipse.smarthome.model.script.heating] - Turning OFF the heater: curr temp = 69 setpoint = 70 mode = OFF
2023-03-26 18:12:26.134 [INFO ] [.eclipse.smarthome.model.script.pins] - Commanding Pin12 to OFF for HeatingPin
2023-03-26 18:12:35.672 [INFO ] [.eclipse.smarthome.model.script.mode] - Fan mode changed from AUTO to OFF
2023-03-26 18:12:36.023 [INFO ] [g.eclipse.smarthome.model.script.fan] - Turning OFF the fan: fan mode = OFF
2023-03-26 18:12:36.568 [INFO ] [.eclipse.smarthome.model.script.pins] - FanPin commanded to OFF
2023-03-26 18:12:36.761 [WARN ] [.eclipse.smarthome.model.script.pins] - Cannot turn off the fan when heating or cooling in US system type! Restoring fan states!
2023-03-26 18:12:37.356 [INFO ] [.eclipse.smarthome.model.script.mode] - Fan mode changed from OFF to AUTO
2023-03-26 18:12:37.886 [INFO ] [.eclipse.smarthome.model.script.pins] - FanPin commanded to ON
2023-03-26 18:12:38.022 [INFO ] [.eclipse.smarthome.model.script.pins] - Commanding Pin18 to ON for FanPin
2023-03-26 18:12:38.175 [INFO ] [g.eclipse.smarthome.model.script.fan] - FanMode is AUTO
2023-03-26 18:12:38.463 [INFO ] [g.eclipse.smarthome.model.script.fan] - Turning ON the fan: fan mode = AUTO
2023-03-26 18:21:30.073 [INFO ] [marthome.model.script.heatingcooling] - TURN ON Cooling: heating delta is 2 cooling delta is -6 hysteresis is 1
2023-03-26 22:34:30.255 [INFO ] [marthome.model.script.heatingcooling] - TURN ON Cooling: heating delta is 1 cooling delta is -5 hysteresis is 1
2023-03-26 22:34:52.681 [INFO ] [marthome.model.script.heatingcooling] - TURN ON Cooling: heating delta is 2 cooling delta is -6 hysteresis is 1
2023-03-26 22:36:24.359 [INFO ] [marthome.model.script.heatingcooling] - TURN ON Cooling: heating delta is 1 cooling delta is -5 hysteresis is 1
2023-03-26 22:37:55.914 [INFO ] [marthome.model.script.heatingcooling] - TURN ON Cooling: heating delta is 2 cooling delta is -6 hysteresis is 1
2023-03-26 22:39:58.557 [INFO ] [marthome.model.script.heatingcooling] - TURN ON Cooling: heating delta is 1 cooling delta is -5 hysteresis is 1
2023-03-26 22:41:00.038 [INFO ] [marthome.model.script.heatingcooling] - TURN ON Cooling: heating delta is 2 cooling delta is -6 hysteresis is 1
2023-03-26 22:41:30.273 [INFO ] [marthome.model.script.heatingcooling] - TURN ON Cooling: heating delta is 1 cooling delta is -5 hysteresis is 1
2023-03-26 23:52:26.234 [INFO ] [marthome.model.script.heatingcooling] - TURN ON Cooling: heating delta is 2 cooling delta is -6 hysteresis is 1
2023-03-26 23:52:56.819 [INFO ] [marthome.model.script.heatingcooling] - TURN ON Cooling: heating delta is 3 cooling delta is -7 hysteresis is 1
2023-03-26 23:53:27.420 [INFO ] [marthome.model.script.heatingcooling] - TURN ON Cooling: heating delta is 4 cooling delta is -8 hysteresis is 1
2023-03-26 23:53:58.787 [INFO ] [marthome.model.script.heatingcooling] - TURN ON Cooling: heating delta is 5 cooling delta is -9 hysteresis is 1
2023-03-26 23:54:59.711 [INFO ] [marthome.model.script.heatingcooling] - TURN ON Cooling: heating delta is 6 cooling delta is -10 hysteresis is 1
2023-03-26 23:55:21.163 [INFO ] [.eclipse.smarthome.model.script.mode] - Cooling mode changed from Boost to OFF
2023-03-26 23:55:21.560 [INFO ] [.eclipse.smarthome.model.script.mode] - Cancelling boost mode
2023-03-26 23:55:24.282 [INFO ] [lipse.smarthome.model.script.cooling] - Turning OFF the cooling: curr temp = 64 setpoint = 74 mode = OFF
2023-03-26 23:55:27.960 [INFO ] [.eclipse.smarthome.model.script.pins] - Commanding Pin23 to OFF for CoolingPin
2023-03-26 23:55:35.327 [INFO ] [.eclipse.smarthome.model.script.mode] - Fan mode changed from AUTO to OFF
2023-03-26 23:55:35.868 [INFO ] [g.eclipse.smarthome.model.script.fan] - Turning OFF the fan: fan mode = OFF
2023-03-26 23:55:36.381 [INFO ] [.eclipse.smarthome.model.script.pins] - FanPin commanded to OFF
2023-03-26 23:55:36.488 [INFO ] [.eclipse.smarthome.model.script.pins] - Commanding Pin18 to OFF for FanPin
2023-03-26 23:55:39.466 [INFO ] [.eclipse.smarthome.model.script.mode] - Cooling mode changed from OFF to Boost
2023-03-26 23:55:40.758 [INFO ] [eclipse.smarthome.model.script.boost] - Starting Cooling boost
2023-03-26 23:55:41.002 [INFO ] [marthome.model.script.heatingcooling] - TURN ON Cooling: heating delta is 6 cooling delta is -10 hysteresis is 1
2023-03-26 23:55:41.247 [INFO ] [lipse.smarthome.model.script.cooling] - Turning ON the cooling: curr temp = 64 setpoint = 74 mode = Boost
2023-03-26 23:55:41.571 [INFO ] [eclipse.smarthome.model.script.boost] - 10 minutes remaining on boost for Cooling
2023-03-26 23:55:51.794 [INFO ] [.eclipse.smarthome.model.script.pins] - Commanding Pin23 to ON for CoolingPin
2023-03-26 23:55:52.213 [INFO ] [.eclipse.smarthome.model.script.mode] - Fan mode changed from OFF to AUTO
2023-03-26 23:55:52.699 [INFO ] [g.eclipse.smarthome.model.script.fan] - FanMode is AUTO
2023-03-26 23:55:52.878 [INFO ] [g.eclipse.smarthome.model.script.fan] - Turning ON the fan: fan mode = AUTO
2023-03-26 23:55:53.479 [INFO ] [.eclipse.smarthome.model.script.pins] - FanPin commanded to ON
2023-03-26 23:55:53.650 [INFO ] [.eclipse.smarthome.model.script.pins] - Commanding Pin18 to ON for FanPin
2023-03-27 00:55:27.038 [INFO ] [.eclipse.smarthome.model.script.mode] - Cooling mode changed from Boost to OFF
2023-03-27 00:55:27.275 [INFO ] [.eclipse.smarthome.model.script.mode] - Cancelling boost mode
2023-03-27 00:55:27.776 [INFO ] [lipse.smarthome.model.script.cooling] - Turning OFF the cooling: curr temp = 64 setpoint = 74 mode = OFF
2023-03-27 00:55:29.402 [INFO ] [.eclipse.smarthome.model.script.pins] - Commanding Pin23 to OFF for CoolingPin
2023-03-27 00:55:38.369 [INFO ] [.eclipse.smarthome.model.script.mode] - Fan mode changed from AUTO to OFF
2023-03-27 00:55:38.650 [INFO ] [g.eclipse.smarthome.model.script.fan] - Turning OFF the fan: fan mode = OFF
2023-03-27 00:55:39.305 [INFO ] [.eclipse.smarthome.model.script.pins] - FanPin commanded to OFF
2023-03-27 00:55:39.428 [INFO ] [.eclipse.smarthome.model.script.pins] - Commanding Pin18 to OFF for FanPin
2023-03-27 01:08:29.736 [INFO ] [.eclipse.smarthome.model.script.mode] - Heating mode changed from OFF to Boost
2023-03-27 01:08:30.427 [INFO ] [eclipse.smarthome.model.script.boost] - Starting Heating boost
2023-03-27 01:08:30.793 [INFO ] [marthome.model.script.heatingcooling] - TURN ON Heating: heating delta is 5 cooling delta is -9 hysteresis is 1
2023-03-27 01:08:31.069 [INFO ] [eclipse.smarthome.model.script.boost] - 10 minutes remaining on boost for Heating
2023-03-27 01:08:32.268 [INFO ] [lipse.smarthome.model.script.heating] - Turning ON the heater: curr temp = 65 setpoint = 70 mode = Boost
2023-03-27 01:08:43.231 [INFO ] [.eclipse.smarthome.model.script.pins] - Commanding Pin12 to ON for HeatingPin
2023-03-27 01:08:43.631 [INFO ] [.eclipse.smarthome.model.script.mode] - Fan mode changed from OFF to AUTO
2023-03-27 01:08:43.863 [INFO ] [g.eclipse.smarthome.model.script.fan] - FanMode is AUTO
2023-03-27 01:08:44.118 [INFO ] [g.eclipse.smarthome.model.script.fan] - Turning ON the fan: fan mode = AUTO
2023-03-27 01:08:44.801 [INFO ] [.eclipse.smarthome.model.script.pins] - FanPin commanded to ON
2023-03-27 01:08:44.911 [INFO ] [.eclipse.smarthome.model.script.pins] - Commanding Pin18 to ON for FanPin
2023-03-27 01:09:31.645 [INFO ] [eclipse.smarthome.model.script.boost] - 9 minutes remaining on boost for Heating
2023-03-27 01:10:32.390 [INFO ] [eclipse.smarthome.model.script.boost] - 8 minutes remaining on boost for Heating
2023-03-27 01:11:33.067 [INFO ] [eclipse.smarthome.model.script.boost] - 7 minutes remaining on boost for Heating
2023-03-27 01:12:33.890 [INFO ] [eclipse.smarthome.model.script.boost] - 6 minutes remaining on boost for Heating
2023-03-27 01:13:34.590 [INFO ] [eclipse.smarthome.model.script.boost] - 5 minutes remaining on boost for Heating
2023-03-27 01:14:35.245 [INFO ] [eclipse.smarthome.model.script.boost] - 4 minutes remaining on boost for Heating
2023-03-27 01:15:35.879 [INFO ] [eclipse.smarthome.model.script.boost] - 3 minutes remaining on boost for Heating
2023-03-27 01:16:36.485 [INFO ] [eclipse.smarthome.model.script.boost] - 2 minutes remaining on boost for Heating
2023-03-27 01:17:37.109 [INFO ] [eclipse.smarthome.model.script.boost] - 1 minutes remaining on boost for Heating
2023-03-27 01:18:38.488 [INFO ] [eclipse.smarthome.model.script.boost] - Boost for Heating has ended, restoring to OFF
2023-03-27 01:18:39.150 [INFO ] [.eclipse.smarthome.model.script.mode] - Heating mode changed from Boost to OFF
2023-03-27 01:18:39.283 [INFO ] [.eclipse.smarthome.model.script.mode] - Cancelling boost mode
2023-03-27 01:18:40.538 [INFO ] [lipse.smarthome.model.script.heating] - Turning OFF the heater: curr temp = 65 setpoint = 70 mode = OFF
2023-03-27 01:18:41.331 [INFO ] [.eclipse.smarthome.model.script.pins] - Commanding Pin12 to OFF for HeatingPin
2023-03-27 01:18:51.099 [INFO ] [.eclipse.smarthome.model.script.mode] - Fan mode changed from AUTO to OFF
2023-03-27 01:18:51.337 [INFO ] [g.eclipse.smarthome.model.script.fan] - Turning OFF the fan: fan mode = OFF
2023-03-27 01:18:51.807 [INFO ] [.eclipse.smarthome.model.script.pins] - FanPin commanded to OFF
2023-03-27 01:18:51.868 [INFO ] [.eclipse.smarthome.model.script.pins] - Commanding Pin18 to OFF for FanPin
2023-03-27 01:24:52.924 [INFO ] [.eclipse.smarthome.model.script.mode] - Cooling mode changed from OFF to Boost
2023-03-27 01:24:52.977 [INFO ] [eclipse.smarthome.model.script.boost] - Starting Cooling boost
2023-03-27 01:24:53.467 [INFO ] [marthome.model.script.heatingcooling] - TURN ON Cooling: heating delta is 5 cooling delta is -9 hysteresis is 1
2023-03-27 01:24:53.902 [INFO ] [eclipse.smarthome.model.script.boost] - 10 minutes remaining on boost for Cooling
2023-03-27 01:24:53.862 [INFO ] [lipse.smarthome.model.script.cooling] - Turning ON the cooling: curr temp = 65 setpoint = 74 mode = Boost
2023-03-27 01:25:04.386 [INFO ] [.eclipse.smarthome.model.script.pins] - Commanding Pin23 to ON for CoolingPin
2023-03-27 01:25:04.721 [INFO ] [.eclipse.smarthome.model.script.mode] - Fan mode changed from OFF to AUTO
2023-03-27 01:25:04.909 [INFO ] [g.eclipse.smarthome.model.script.fan] - FanMode is AUTO
2023-03-27 01:25:05.049 [INFO ] [g.eclipse.smarthome.model.script.fan] - Turning ON the fan: fan mode = AUTO
2023-03-27 01:25:05.665 [INFO ] [.eclipse.smarthome.model.script.pins] - FanPin commanded to ON
2023-03-27 01:25:05.797 [INFO ] [.eclipse.smarthome.model.script.pins] - Commanding Pin18 to ON for FanPin
2023-03-27 01:36:10.459 [INFO ] [.eclipse.smarthome.model.script.mode] - Cooling mode changed from Boost to OFF
2023-03-27 01:36:10.548 [INFO ] [.eclipse.smarthome.model.script.mode] - Cancelling boost mode
2023-03-27 01:36:11.000 [INFO ] [lipse.smarthome.model.script.cooling] - Turning OFF the cooling: curr temp = 65 setpoint = 74 mode = OFF
2023-03-27 01:36:11.829 [INFO ] [.eclipse.smarthome.model.script.pins] - Commanding Pin23 to OFF for CoolingPin
2023-03-27 01:36:21.582 [INFO ] [.eclipse.smarthome.model.script.mode] - Fan mode changed from AUTO to OFF
2023-03-27 01:36:21.770 [INFO ] [g.eclipse.smarthome.model.script.fan] - Turning OFF the fan: fan mode = OFF
2023-03-27 01:36:22.268 [INFO ] [.eclipse.smarthome.model.script.pins] - FanPin commanded to OFF
2023-03-27 01:36:22.338 [INFO ] [.eclipse.smarthome.model.script.pins] - Commanding Pin18 to OFF for FanPin
Here are the noteworthy events:
-
2023-03-26 18:07:51.502Press boost cooling button -
2023-03-26 18:12:19.641Attempt to boost the heat while the cooling is already being boosted- At this point the heating went back from “boost” to “off” (as expected)
- Cooling remained in “Boost” but the timer stopped counting down (it stayed at 6 minutes remaining)
- I didn’t notice that it was still boosting until I came back quite a few hours later
-
2023-03-26 23:55:21.163I turn cooling from Boost to Off -
2023-03-26 23:55:39.466I attempt to boost the cooling again- The timer shows 6 minutes remaining on boost
- The timer does not count down
-
2023-03-27 00:55:27.038I turn cooling from Boost to Off again -
2023-03-27 01:08:29.736I try boosting the heat to see if that works. It worked exactly as expected -
2023-03-27 01:24:52.924I attempt to boost the cooling again- Cooling goes into boost mode, activating the cooling and fan relays
- Display shows “Cooling boost mode 10 min remaining”
- Timer never counts down
-
2023-03-27 01:36:10.459I turn cooling from Boost to Off again
Reproducibility on Buster
After this, I rebooted the HestiaPi and attempted to boost the cooling again. It worked just fine. I boosted the heating. It worked fine. Cooling again, fine.
Heating, wait a minute, then attempt to boost the cooling. Cooling switches itself back to “off” and heating countdown continues. So in other words, I am unable to reproduce the issue now in US mode.
So I switched to EU mode and tried concurrent boosting (exact steps are in the “Reproducing on the official 1.2-dev image” section below) and was able to reproduce the issue. So it seems like this can be reliably reproduced in EU mode.
Fixing the concurrent boost issue
I’m not clear on the details of what’s going on with this timer, so I’m not sure I can suggest an optimal solution, however here’s my best stab at it.
- Instead of putting the boost protection in the “but only if…” clause, move it to the “Then…” clause.
- Instead of rejecting the second boost, accept it and cancel any other boosts
This should be feasible from a technical perspective. If there’s some way to make sure boosting one system doesn’t mess up the timer of another system, I’d expect that to be a preferred solution. This would allow EU users to do things like boost both heat and humidity, which seems like a reasonable use case.
In either case, the fix should be made to the rules, and committed to the hestia-touch-openhab repo. After that fix is in, I can rebuild a fresh candidate to become 1.3-dev and we can do another round of testing.
Reproducing on the offical 1.2-dev image
I then tried to reproduce this on the official 1.2-dev image. For whatever reason, I decided to attempt to do this in EU mode instead of US mode.
Test procedure:
- Boost heat, wait until there are 9 minutes remaining
- Boost hot water, wait until there are 6 minutes remaining on the hot water boost
- Boost humidity, allow boost timer to run its full course
Results:
- Heat boosts forever, timer is stuck at 9 minutes
- Hot water boosts forever, timer is stuck at 6 minutes
- Humidity boosts as expected (stops boosting when the timer hits 0 minutes)
Waiting to 6 minutes in particular isn’t necessary, but I wanted to wait longer than one minute to see if I could get things stuck at different places.
Logs for test case
2023-03-27 00:10:28.246 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'default.rules'
2023-03-27 00:10:38.499 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Error during the execution of startup rule 'Kick off initialization': Could not access fie
ld: DefaultRules.Initialized on instance: null
2023-03-27 00:10:39.253 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'default.rules'
2023-03-27 00:10:47.491 [INFO ] [.model.script.initialization.kickoff] - OH is loaded, kicking off initialization, Initialized == NULL
2023-03-27 00:10:47.555 [INFO ] [.model.script.initialization.kickoff] - Commanding Initialization Rule to start
2023-03-27 00:10:55.751 [INFO ] [marthome.model.script.initialization] - Initializing settings...
2023-03-27 00:10:59.736 [INFO ] [marthome.model.script.initialization] - MinTempSetpoint is 0, initializing to 70
2023-03-27 00:10:59.951 [INFO ] [marthome.model.script.initialization] - MinTempSetpointF is 0, initializing to 70
2023-03-27 00:11:00.103 [INFO ] [marthome.model.script.initialization] - MaxTempSetpoint is 1, initializing to 74
2023-03-27 00:11:00.258 [INFO ] [marthome.model.script.initialization] - MaxTempSetpointF is 1, initializing to 74
2023-03-27 00:11:00.913 [INFO ] [marthome.model.script.initialization] - Comfort_Mode is COMFORT, Default value is 1
2023-03-27 00:11:00.976 [INFO ] [marthome.model.script.initialization] - Comfort_Value is 1, initializing to 1
2023-03-27 00:11:05.133 [INFO ] [marthome.model.script.initialization] - System is ready to operate, kicking off restored behaviors
2023-03-27 00:41:01.139 [INFO ] [.eclipse.smarthome.model.script.mode] - Heating mode changed from OFF to Boost
2023-03-27 00:41:03.793 [INFO ] [eclipse.smarthome.model.script.boost] - Starting Heating boost
2023-03-27 00:41:06.099 [INFO ] [eclipse.smarthome.model.script.boost] - 10.0 minutes remaining on boost for Heating
2023-03-27 00:41:12.505 [INFO ] [marthome.model.script.heatingcooling] - TURN ON Heating: heating delta is 8 cooling delta is -12 hysteresis is 1
2023-03-27 00:41:18.078 [INFO ] [lipse.smarthome.model.script.heating] - Turning ON the heater: curr temp = 62 setpoint = 70 mode = Boost
2023-03-27 00:41:26.095 [INFO ] [.eclipse.smarthome.model.script.pins] - Commanding Pin23 to ON for HeatingPin
2023-03-27 00:42:07.459 [INFO ] [eclipse.smarthome.model.script.boost] - 9 minutes remaining on boost for Heating
2023-03-27 00:42:13.899 [INFO ] [.eclipse.smarthome.model.script.mode] - HotWater mode changed from OFF to Boost
2023-03-27 00:42:14.099 [INFO ] [eclipse.smarthome.model.script.boost] - Starting HotWater boost
2023-03-27 00:42:14.896 [INFO ] [eclipse.smarthome.model.script.boost] - 10 minutes remaining on boost for HotWater
2023-03-27 00:42:19.186 [INFO ] [ipse.smarthome.model.script.hotwater] - Turning ON the hot water: mode = Boost
2023-03-27 00:43:08.078 [INFO ] [eclipse.smarthome.model.script.boost] - 9 minutes remaining on boost for HotWater
2023-03-27 00:43:15.438 [INFO ] [eclipse.smarthome.model.script.boost] - 8 minutes remaining on boost for HotWater
2023-03-27 00:44:08.682 [INFO ] [eclipse.smarthome.model.script.boost] - 7 minutes remaining on boost for HotWater
2023-03-27 00:44:16.014 [INFO ] [eclipse.smarthome.model.script.boost] - 6 minutes remaining on boost for HotWater
2023-03-27 00:44:18.337 [INFO ] [.eclipse.smarthome.model.script.mode] - Humidity mode changed from OFF to Boost
2023-03-27 00:44:18.688 [INFO ] [eclipse.smarthome.model.script.boost] - Starting Humidity boost
2023-03-27 00:44:19.600 [INFO ] [eclipse.smarthome.model.script.boost] - 10 minutes remaining on boost for Humidity
2023-03-27 00:44:24.527 [INFO ] [ipse.smarthome.model.script.humidity] - Turning ON the Dehumidify: curr humidity = 54.6 setpoint = 50 mode = Boost
2023-03-27 00:44:26.178 [INFO ] [.eclipse.smarthome.model.script.pins] - Commanding Pin18 to ON for HumidityPin
2023-03-27 00:45:09.236 [INFO ] [eclipse.smarthome.model.script.boost] - 9 minutes remaining on boost for Humidity
2023-03-27 00:45:16.705 [INFO ] [eclipse.smarthome.model.script.boost] - 8 minutes remaining on boost for Humidity
2023-03-27 00:45:20.204 [INFO ] [eclipse.smarthome.model.script.boost] - 7 minutes remaining on boost for Humidity
2023-03-27 00:46:09.863 [INFO ] [eclipse.smarthome.model.script.boost] - 6 minutes remaining on boost for Humidity
2023-03-27 00:46:17.270 [INFO ] [eclipse.smarthome.model.script.boost] - 5 minutes remaining on boost for Humidity
2023-03-27 00:46:21.392 [INFO ] [eclipse.smarthome.model.script.boost] - 4 minutes remaining on boost for Humidity
2023-03-27 00:47:10.434 [INFO ] [eclipse.smarthome.model.script.boost] - 3 minutes remaining on boost for Humidity
2023-03-27 00:47:17.831 [INFO ] [eclipse.smarthome.model.script.boost] - 2 minutes remaining on boost for Humidity
2023-03-27 00:47:22.173 [INFO ] [eclipse.smarthome.model.script.boost] - 1 minutes remaining on boost for Humidity
2023-03-27 00:48:11.910 [INFO ] [eclipse.smarthome.model.script.boost] - Boost for Humidity has ended, restoring to OFF
2023-03-27 00:48:12.599 [INFO ] [.eclipse.smarthome.model.script.mode] - Humidity mode changed from Boost to OFF
2023-03-27 00:48:13.037 [INFO ] [.eclipse.smarthome.model.script.mode] - Cancelling boost mode
2023-03-27 00:48:14.084 [INFO ] [ipse.smarthome.model.script.humidity] - Turning OFF the Dehumidify: curr humidity = 54.5 setpoint = 50 mode = OFF
2023-03-27 00:48:15.536 [INFO ] [.eclipse.smarthome.model.script.pins] - Commanding Pin18 to OFF for HumidityPin