HestiaPi Touch stops heating

helgew · January 23, 2022, 4:53pm

Hi all,

I have been running my HestiaPi Touch successfully for a couple of months now with no problems other than a couple of system freezes (those were easily resolved with a reboot). However, over the past few days the thermostat has now twice stopped to turn on the heating when the temperature falls below the set point. There are no log messages to indicate any problems and neither restarting openHAB nor a full reboot have helped. What ultimately brings the system fully back online is a cleaning of the cache and a resetting of the permissions using the openhab-cli utility.

Any idea what might be going on?

HestiaPi · January 24, 2022, 5:45am

Hi @helgew and welcome to the club.
When you say that a reboot doesn’t help do you mean that HestiaPi never turns heating on?
Is it only the heating or all the actions are not working (depending on your US/EU model fan, ac or humidity/water)?
Do you have any custom rules you added or other modifications?
Run openhab-cli showlogs and copy back here messages from idle till 20sec after you press heating to start.
Also you could try from PaperUI>Rules>Initialization and maybe from the phone app to change the temperature unit twice (so it is back to your preference) waiting a few minutes in between (or until the openhab-cli showlogs shows it completed any required step each time). We have seen above steps to fix some times glitches but this is not a common issue reported.

helgew · January 24, 2022, 1:56pm

Thanks and thank you for the reply.

I only use the heating function (pretty common scenario in Southern California) and have gone through most of what you describe. Right now, the thermostat is working again, so I cannot test it directly. That said, the logs in each case were silent… no errors, no info messages. I think I even tried switching system type from US to EU and back and it didn’t change anything. I do not have any custom rules.

HestiaPi · January 26, 2022, 12:17pm

These are my logs from openhab-cli showlogs with 1.2-dev image in EU mode:

Starting heating boost

pi@raspberrypi:~ $ openhab-cli showlogs
...
2022-01-26 14:06:30.223 [INFO ] [.eclipse.smarthome.model.script.mode] - Heating mode changed from OFF to Boost
2022-01-26 14:06:31.117 [INFO ] [eclipse.smarthome.model.script.boost] - Starting Heating boost
2022-01-26 14:06:32.357 [INFO ] [eclipse.smarthome.model.script.boost] - 10.0 minutes remaining on boost for Heating
2022-01-26 14:06:36.690 [INFO ] [marthome.model.script.heatingcooling] - TURN ON Heating: heating delta is 3.700000762939453 cooling delta is -7.700000762939453 hysteresis is 0.5
2022-01-26 14:06:38.042 [INFO ] [lipse.smarthome.model.script.heating] - Turning ON the heater: curr temp = 18.3 setpoint = 22.0 mode = Boost
2022-01-26 14:06:41.092 [INFO ] [.eclipse.smarthome.model.script.pins] - Commanding Pin23 to ON for HeatingPin

Stoping heating boost

2022-01-26 14:06:55.589 [INFO ] [.eclipse.smarthome.model.script.mode] - Heating mode changed from Boost to OFF
2022-01-26 14:06:56.021 [INFO ] [.eclipse.smarthome.model.script.mode] - Cancelling boost mode
2022-01-26 14:06:56.637 [INFO ] [lipse.smarthome.model.script.heating] - Turning OFF the heater: curr temp = 18.3 setpoint = 22.0 mode = OFF
2022-01-26 14:06:57.366 [INFO ] [.eclipse.smarthome.model.script.pins] - Commanding Pin23 to OFF for HeatingPin

Starting heating AUTO

2022-01-26 14:07:04.043 [INFO ] [.eclipse.smarthome.model.script.mode] - Heating mode changed from OFF to ON
2022-01-26 14:07:04.524 [INFO ] [marthome.model.script.heatingcooling] - TURN ON Heating: heating delta is 3.700000762939453 cooling delta is -7.700000762939453 hysteresis is 0.5
2022-01-26 14:07:04.599 [INFO ] [lipse.smarthome.model.script.heating] - Turning ON the heater: curr temp = 18.3 setpoint = 22.0 mode = ON
2022-01-26 14:07:05.292 [INFO ] [.eclipse.smarthome.model.script.pins] - Commanding Pin23 to ON for HeatingPin

Stoping heating AUTO

2022-01-26 14:07:12.961 [INFO ] [.eclipse.smarthome.model.script.mode] - Heating mode changed from ON to OFF
2022-01-26 14:07:13.423 [INFO ] [lipse.smarthome.model.script.heating] - Turning OFF the heater: curr temp = 18.3 setpoint = 22.0 mode = OFF
2022-01-26 14:07:14.610 [INFO ] [.eclipse.smarthome.model.script.pins] - Commanding Pin23 to OFF for HeatingPin

Something strange is happening in your setup and when strange things happen it usually is the SD card or file(s) corrupted. If it happens again I would advise you to scan the SD for any hardware issues. If it is not an SD provided by us, I would recommend replacing it with a branded high class/speed card. To save you time and hassle, I would prepare one and have it ready or swap it when it is convenient for you.

helgew · January 26, 2022, 5:24pm

TL;DR: Updated openHAB to the latest 2.x version, installed the latest addons locally, configured it for local access to addons, completely removed all persisted objects and states, and restarted OH with no default.rules before moving them into place.

SD card failure is always a possibility, but aside from openHAB, everything else seems to be working fine.

That said, I think I am going to be cautiously optimistic and mark this as solved. Although I have no hard evidence, I suspect this to have been an incompatibility issue with some components in openHAB that somehow were updated or changed by themselves. While that sounds far fetched, updating openHAB to the latest version, installing the latest addons locally, and setting remote to false in /var/lib/openhab2/config/org/openhab/addons.config along with a “thorough” cleaning of the OH cache and a “proper” restart of it seems to have done the trick (see below for a description of what I did).

Here are the log messages at or around the last time the thermostat worked properly:

2022-01-16 12:21:28.818 [INFO ] [.eclipse.smarthome.model.script.mode] - Heating mode changed from ON to OFF
2022-01-16 12:21:29.365 [INFO ] [lipse.smarthome.model.script.heating] - Turning OFF the heater: curr temp = 69 setpoint = 70 mode = OFF
2022-01-16 12:21:30.035 [INFO ] [.eclipse.smarthome.model.script.pins] - Commanding Pin23 to OFF for HeatingPin
2022-01-17 18:26:38.053 [WARN ] [me.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.eclipse.smarthome.core.thing.internal.CommunicationManager@7cd3cb' takes more than 5000ms.
2022-01-17 18:26:48.458 [INFO ] [.reconnect.PeriodicReconnectStrategy] - Try to restore connection to 'localhost'. Next attempt in 60000ms
2022-01-17 18:26:48.691 [INFO ] [.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to 'localhost' with clientid mosquitto
2022-01-19 06:40:36.596 [WARN ] [me.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.eclipse.smarthome.core.thing.internal.CommunicationManager@7cd3cb' takes more than 5000ms.

I had initially dismissed the event subscriber error because it had occurred sporadically before and then again when the thermostat was seemingly working again. However, aside from an occasional INFO level message, those errors were it in the log until a bunch of MQTT-related messages started:

2022-01-19 09:47:04.193 [WARN ] [me.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.eclipse.smarthome.core.thing.internal.CommunicationManager@7cd3cb' takes more than 5000ms.
2022-01-19 09:46:48.569 [WARN ] [.transport.mqtt.MqttBrokerConnection] - Failed subscribing to topic hestia/local/stat/fanmode
java.util.concurrent.CompletionException: com.hivemq.client.mqtt.exceptions.MqttSessionExpiredException: Session expired as connection was closed.
        at java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:292) ~[?:1.8.0_222]
        at java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:308) ~[?:1.8.0_222]
        at java.util.concurrent.CompletableFuture.uniApply(CompletableFuture.java:593) ~[?:1.8.0_222]
        at java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:577) ~[?:1.8.0_222]
        at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:474) ~[?:1.8.0_222]
        at java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:1977) ~[?:1.8.0_222]
        at com.hivemq.client.internal.mqtt.mqtt3.Mqtt3AsyncClientView.lambda$handleSubAck$0(Mqtt3AsyncClientView.java:64) ~[?:?]
        at java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:760) [?:1.8.0_222]
        at java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:736) [?:1.8.0_222]
        at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:474) [?:1.8.0_222]
        at java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:1977) [?:1.8.0_222]
        at com.hivemq.client.rx.FlowableWithSingle$SingleFutureSubscriber.onError(FlowableWithSingle.java:395) [bundleFile:?]
        at com.hivemq.client.internal.rx.operators.FlowableWithSingleCombine$SplitSubscriber.onError(FlowableWithSingleCombine.java:178) [bundleFile:?]
        at io.reactivex.internal.operators.flowable.FlowableObserveOn$BaseObserveOnSubscriber.checkTerminated(FlowableObserveOn.java:197) [bundleFile:?]
        at io.reactivex.internal.operators.flowable.FlowableObserveOn$ObserveOnConditionalSubscriber.runAsync(FlowableObserveOn.java:641) [bundleFile:?]
        at io.reactivex.internal.operators.flowable.FlowableObserveOn$BaseObserveOnSubscriber.run(FlowableObserveOn.java:176) [bundleFile:?]
        at io.reactivex.internal.schedulers.ScheduledRunnable.run(ScheduledRunnable.java:66) [bundleFile:?]
        at io.reactivex.internal.schedulers.ScheduledRunnable.call(ScheduledRunnable.java:57) [bundleFile:?]
        at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_222]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [?:1.8.0_222]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [?:1.8.0_222]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_222]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_222]
        at java.lang.Thread.run(Thread.java:748) [?:1.8.0_222]
Caused by: com.hivemq.client.mqtt.exceptions.MqttSessionExpiredException: Session expired as connection was closed.
Caused by: com.hivemq.client.mqtt.exceptions.ConnectionClosedException: java.io.IOException: Broken pipe
Caused by: java.io.IOException: Broken pipe
        at sun.nio.ch.FileDispatcherImpl.write0(Native Method) ~[?:1.8.0_222]
        at sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:47) ~[?:1.8.0_222]
        at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:93) ~[?:1.8.0_222]
        at sun.nio.ch.IOUtil.write(IOUtil.java:51) ~[?:1.8.0_222]
        at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:471) ~[?:1.8.0_222]
        at io.netty.channel.socket.nio.NioSocketChannel.doWrite(NioSocketChannel.java:405) ~[?:?]
        at io.netty.channel.AbstractChannel$AbstractUnsafe.flush0(AbstractChannel.java:931) ~[?:?]
        at io.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.flush0(AbstractNioChannel.java:354) ~[?:?]
        at io.netty.channel.AbstractChannel$AbstractUnsafe.flush(AbstractChannel.java:898) ~[?:?]
        at io.netty.channel.DefaultChannelPipeline$HeadContext.flush(DefaultChannelPipeline.java:1384) ~[?:?]
        at io.netty.channel.AbstractChannelHandlerContext.invokeFlush0(AbstractChannelHandlerContext.java:749) ~[?:?]
        at io.netty.channel.AbstractChannelHandlerContext.invokeFlush(AbstractChannelHandlerContext.java:741) ~[?:?]
        at io.netty.channel.AbstractChannelHandlerContext.flush(AbstractChannelHandlerContext.java:727) ~[?:?]
        at com.hivemq.client.internal.mqtt.handler.ping.MqttPingHandler.flush(MqttPingHandler.java:73) ~[?:?]
        at io.netty.channel.AbstractChannelHandlerContext.invokeFlush0(AbstractChannelHandlerContext.java:749) ~[?:?]
        at io.netty.channel.AbstractChannelHandlerContext.invokeWriteAndFlush(AbstractChannelHandlerContext.java:764) ~[?:?]
        at io.netty.channel.AbstractChannelHandlerContext.write(AbstractChannelHandlerContext.java:789) ~[?:?]
        at io.netty.channel.AbstractChannelHandlerContext.writeAndFlush(AbstractChannelHandlerContext.java:757) ~[?:?]
        at com.hivemq.client.internal.mqtt.handler.subscribe.MqttSubscriptionHandler.writeSubscribe(MqttSubscriptionHandler.java:223) ~[?:?]
        at com.hivemq.client.internal.mqtt.handler.subscribe.MqttSubscriptionHandler.writeSubscribeOrUnsubscribe(MqttSubscriptionHandler.java:187) ~[?:?]
        at com.hivemq.client.internal.mqtt.handler.subscribe.MqttSubscriptionHandler.run(MqttSubscriptionHandler.java:161) ~[?:?]
        at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:163) ~[?:?]
        at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:510) ~[?:?]
        at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:518) ~[?:?]
        at io.netty.util.concurrent.SingleThreadEventExecutor$6.run(SingleThreadEventExecutor.java:1044) ~[?:?]
        at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) ~[?:?]
        at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) ~[?:?]
        ... 1 more

Here was my first attempt at a restart of openHAB. I am not sure if I rebooted the RPi or just restarted openHAB:

2022-01-20 05:48:10.856 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'default.items'
2022-01-20 05:48:15.754 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'mapdb.persist'
2022-01-20 05:48:24.393 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'default.sitemap'
2022-01-20 05:49:16.068 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'default.rules'
2022-01-20 05:49:18.064 [INFO ] [thome.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
2022-01-20 05:49:32.492 [INFO ] [.model.script.initialization.kickoff] - OH is loaded, kicking off initialization, Initialized == NULL
2022-01-20 05:49:32.559 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Error during the execution of startup rule 'Kick off initialization': null
2022-01-20 05:49:50.332 [INFO ] [.model.script.initialization.kickoff] - OH is loaded, kicking off initialization, Initialized == NULL
2022-01-20 05:49:50.718 [INFO ] [.model.script.initialization.kickoff] - Commanding Initialization Rule to start
2022-01-20 05:49:57.504 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at http://10.0.3.16:8080
2022-01-20 05:49:57.544 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at https://10.0.3.16:8443
2022-01-20 05:50:12.158 [INFO ] [.model.script.initialization.kickoff] - OH is loaded, kicking off initialization, Initialized == NULL
2022-01-20 05:50:12.384 [INFO ] [.model.script.initialization.kickoff] - Commanding Initialization Rule to start
2022-01-20 05:51:14.642 [WARN ] [core.thing.internal.ThingManagerImpl] - Initializing handler for thing 'mqtt:broker:mosquitto' takes more than 5000ms.
2022-01-20 05:51:44.507 [INFO ] [.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to 'localhost' with clientid mosquitto
2022-01-20 05:52:20.063 [INFO ] [openhab.ui.paper.internal.PaperUIApp] - Started Paper UI at /paperui

For 2 hours, it sat there and didn’t do anything much. Some messages came through via MQTT but notably, no temperature reading. After you posted your log messages, I came to realize that openHAB in all my attempts never really completely initialized (System is ready to operate, kicking off restored behaviors didn’t show up in the log). While I ignorantly rebooted/restarted again (with or without calling openhab-cli clear-cache and openhab-cli reset-ownership first) and started fiddling with running some rules from the PaperUI, these errors would show up:

2022-01-20 07:19:56.765 [WARN ] [e.automation.internal.RuleEngineImpl] - Fail to execute action: 3
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$35$\^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$37$34A$utils.L:3(/etc/openhab2/automation/lib/hestia/utils.js:31) ~[?:?]
        at jdk.nashorn.internal.scripts.Script$36$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

Clearly, something was rotten in the state of Denmark! At this point, I was ready to chuck openHAB and go with my own control scripts since for my needs (heating only), OH was decidedly overkill. Still, I decided to give it one last chance by upgrading it, which involved a bit of sleuthing since jessie is no longer supported and openHAB had moved their own repos as well.

/etc/apt/sources.list.d/openhab2.list was changed to:

deb https://openhab.jfrog.io/artifactory/openhab-linuxpkg stable main

Not relevant, but I changed /etc/apt/sources.list to:

deb http://legacy.raspbian.org/raspbian/ jessie main contrib non-free rpi

sudo apt update
sudo apt upgrade openhab2

And, since the maven repositories used by OH for their add-ons have also changed (I would get errors like Failed installing 'openhab-persistence-mapdb, openhab-ui-restdocs, openhab-binding-exec, openhab-binding-mqtt, openhab-transformation-map, openhab-ui-basic, openhab-misc-ruleengine, openhab-transformation-regex, openhab-ui-paper, openhab-binding-gpio1': Error: Error downloading mvn:org.openhab.addons.bundles/org.openhab.transform.map/[2.5.0,2.6)), I followed the instructions I found on an OH forum:

cd /usr/share/openhab2/addons
sudo wget https://openhab.jfrog.io/artifactory/libs-release-local/org/openhab/distro/openhab-addons/2.5.12/openhab-addons-2.5.12.kar
sudo vi /var/lib/openhab2/config/org/openhab/addons.config # changed remote to "false"

For good measure, after cleaning cache and restoring ownerships again, I removed /var/lib/openhab2/persistence/mapdb/storage.mapdb* and moved /etc/openhab2/rules/default.rules out of the way (I think the latter should probably be mentioned in the docs somewhere!). After letting OH come up (much more quickly now!!), these messages showed in the log:

2022-01-25 17:31:34.394 [INFO ] [.dashboard.internal.DashboardService] - Stopped Dashboard
2022-01-25 17:35:44.297 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'default.items'
2022-01-25 17:35:49.325 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'mapdb.persist'
2022-01-25 17:35:57.755 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'default.sitemap'
2022-01-25 17:36:31.542 [INFO ] [thome.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
2022-01-25 17:36:54.758 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at http://10.0.3.16:8080
2022-01-25 17:36:54.783 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at https://10.0.3.16:8443
2022-01-25 17:38:03.281 [WARN ] [core.thing.internal.ThingManagerImpl] - Initializing handler for thing 'mqtt:broker:mosquitto' takes more than 5000ms.
2022-01-25 17:38:23.940 [INFO ] [.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to 'localhost' with clientid mosquitto
2022-01-25 17:38:36.929 [INFO ] [openhab.ui.paper.internal.PaperUIApp] - Started Paper UI at /paperui
2022-01-25 17:39:01.700 [ERROR] [internal.handler.ScriptActionHandler] - Script execution failed: TypeError: items["Previous" + device + "Reading"].floatValue is not a function in <eval> at line number 14

The last error was expected and has been discussed elsewhere. It repeated a few times before I restored the default.rules from the /home/pi/scripts folder. Afterward, it was smooth sailing:

2022-01-25 18:08:15.449 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'default.rules'
2022-01-25 18:08:25.756 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Error during the execution of startup rule 'Kick off initialization': null
2022-01-25 18:08:26.743 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'default.rules'
2022-01-25 18:08:36.482 [INFO ] [.model.script.initialization.kickoff] - OH is loaded, kicking off initialization, Initialized == NULL
2022-01-25 18:08:36.572 [INFO ] [.model.script.initialization.kickoff] - Commanding Initialization Rule to start
2022-01-25 18:08:44.461 [INFO ] [marthome.model.script.initialization] - Initializing settings...
2022-01-25 18:08:44.598 [ERROR] [internal.handler.ScriptActionHandler] - Script execution failed: TypeError: items["Previous" + device + "Reading"].floatValue is not a function in <eval> at line number 14
2022-01-25 18:08:46.464 [INFO ] [marthome.model.script.initialization] - FanMode is undefined, initializing to OFF
2022-01-25 18:08:46.695 [INFO ] [marthome.model.script.initialization] - MainSwitch is undefined, initializing to OFF
2022-01-25 18:08:46.766 [INFO ] [marthome.model.script.initialization] - HeatingMode is undefined, initializing to OFF
2022-01-25 18:08:46.827 [INFO ] [marthome.model.script.initialization] - CoolingMode is undefined, initializing to OFF
2022-01-25 18:08:46.876 [INFO ] [marthome.model.script.initialization] - HotWaterMode is undefined, initializing to OFF
2022-01-25 18:08:46.939 [INFO ] [marthome.model.script.initialization] - HumidityMode is undefined, initializing to OFF
2022-01-25 18:08:47.005 [INFO ] [marthome.model.script.initialization] - Heating2 is undefined, initializing to OFF
2022-01-25 18:08:47.058 [INFO ] [marthome.model.script.initialization] - Comfort_Mode is undefined, initializing to COMFORT
2022-01-25 18:08:49.113 [INFO ] [marthome.model.script.initialization] - MinTempSetpoint is NULL, initializing to 70
2022-01-25 18:08:49.332 [INFO ] [marthome.model.script.initialization] - MinTempSetpointF is NULL, initializing to 70
2022-01-25 18:08:49.476 [INFO ] [marthome.model.script.initialization] - MaxTempSetpoint is NULL, initializing to 74
2022-01-25 18:08:49.801 [INFO ] [marthome.model.script.initialization] - MaxTempSetpointF is NULL, initializing to 74
2022-01-25 18:08:50.555 [WARN ] [marthome.model.script.initialization] - Waiting for Comfort_Mode to update
2022-01-25 18:08:56.425 [WARN ] [marthome.model.script.initialization] - Comfort_Mode finally updated to COMFORT
2022-01-25 18:08:57.047 [INFO ] [marthome.model.script.initialization] - Comfort_Mode is COMFORT, Default value is 2
2022-01-25 18:08:57.212 [INFO ] [marthome.model.script.initialization] - Comfort_Value is NULL, initializing to 2
2022-01-25 18:08:59.776 [INFO ] [marthome.model.script.initialization] - HumiSetpoint is NULL, initializing to 50
2022-01-25 18:09:00.403 [INFO ] [marthome.model.script.initialization] - HeatingBoostTime is undefined, initializing to 10
2022-01-25 18:09:00.648 [INFO ] [marthome.model.script.initialization] - HotWaterBoostTime is undefined, initializing to 10
2022-01-25 18:09:01.019 [INFO ] [marthome.model.script.initialization] - HumidityBoostTime is undefined, initializing to 10
2022-01-25 18:09:01.247 [INFO ] [marthome.model.script.initialization] - CoolingBoostTime is undefined, initializing to 10
2022-01-25 18:09:02.216 [INFO ] [marthome.model.script.initialization] - PreviousTempReading is undefined, initializing to 0
2022-01-25 18:09:02.390 [INFO ] [marthome.model.script.initialization] - PreviousHumiReading is undefined, initializing to 0
2022-01-25 18:09:02.461 [INFO ] [marthome.model.script.initialization] - PreviousPressureReading is undefined, initializing to 0
2022-01-25 18:09:02.735 [INFO ] [marthome.model.script.initialization] - Heating2Time is undefined, initializing to 0
2022-01-25 18:09:03.009 [INFO ] [marthome.model.script.initialization] - Heating2Delta is undefined, initializing to 0
2022-01-25 18:09:03.129 [INFO ] [marthome.model.script.initialization] - FanCtrl is undefined, initializing to ON
2022-01-25 18:09:03.465 [INFO ] [marthome.model.script.initialization] - System is ready to operate, kicking off restored behaviors
2022-01-25 18:09:56.266 [INFO ] [.eclipse.smarthome.model.script.mode] - Heating mode changed from OFF to ON
2022-01-25 18:10:01.507 [INFO ] [marthome.model.script.heatingcooling] - TURN OFF Heating: heating delta is 0 cooling delta is -4 hysteresis is 2
2022-01-25 18:10:06.486 [INFO ] [lipse.smarthome.model.script.heating] - Turning OFF the heater: curr temp = 70 setpoint = 70 mode = ON
2022-01-25 18:10:11.107 [INFO ] [.eclipse.smarthome.model.script.pins] - Commanding Pin23 to OFF for HeatingPin
2

This morning, I changed my mind about the comfort level hysteresis and set it back to the default 1 °F and triggered the initialization rule from the PaperUI:

2022-01-26 06:40:20.220 [INFO ] [marthome.model.script.initialization] - Initializing settings...
2022-01-26 06:40:22.691 [INFO ] [marthome.model.script.initialization] - Comfort_Mode is COMFORT, Default value is 1
2022-01-26 06:40:22.946 [INFO ] [marthome.model.script.initialization] - Comfort_Value is 1, initializing to 1
2022-01-26 06:40:25.301 [INFO ] [marthome.model.script.initialization] - System is ready to operate, kicking off restored behaviors

HestiaPi · January 26, 2022, 5:42pm

Great work! Please move the TL;DR: to the top

helgew · January 26, 2022, 5:48pm

done!

Thanks for your help!!

system · April 27, 2022, 11:49pm

This topic was automatically closed 91 days after the last reply. New replies are no longer allowed.