I’ve hit a situation where boost turns on the heat and then just leaves it on indefinitely and I’m having trouble with debugging the issue.
Background
I’m using the 1.2 dev image. My setup is that I have a cron job on the pi which sets the heating set point to 16C every night and then back up to 20.2 every morning. This part works fine.
Because we have a problem with our heating pipes freezing (which, as ironic is it, I can assure you it’s no laughing matter), I have an additional cron job that effectively pushes the heating boost button every hour.
When it was boosting for the default amount of time (10 minutes), this seemed to work fine. I have a temperature sensor near one of the heating pipes and I can see the heat come on, heat up the pipe and then it slowly starts cooling down. At this point, it’s working exactly as expected. Terrific!
A challenger problem arises
After looking at the heat graphs, we decided that we didn’t need to use so much energy overnight and that just boosting for 5 minutes, every two hours would be fine. It was after I manually set the boost time to 5 minutes that the problems started to arise.
One night, OpenHAB seemed to lock up. The temperature reading was clearly incorrect, and IIRC the web interface didn’t response. I was able to SSH in and restart OpenHAB. I also restarted my reverse proxy (nginx), but it didn’t fix the issue. So I rebooted the entire system. For some uninexplicable reason when I reboot from the command line, I get different results than when I reboot from the web UI (even when calling ~pi/scripts/reboot.sh)… but that’s not the problem I’m trying to solve right now. Point being, after a few reboots, it was up and running just fine again.
Last night instead of failing to heat when it should, it got stuck in boost mode and heated up the house far too much. I manually changed it from “Boost” to “Auto” at 02:55, and at 04:00, the boost kicked in (which is desirable), but then never stopped (undesirable). Once again, I manually changed the mode back to “Auto”.
The Investigation
Now I’m trying to track down what’s going wrong, and this is where I could use some help. After looking at the code, I eventually found out that logDebug() apparently winds up in /var/log/openhab2/openhab.log.
2021-12-18 00:00:02.641 [INFO ] [.eclipse.smarthome.model.script.mode] - Heating mode changed from ON to Boost
2021-12-18 00:00:09.504 [INFO ] [eclipse.smarthome.model.script.boost] - Starting Heating boost
2021-12-18 00:00:09.836 [INFO ] [marthome.model.script.heatingcooling] - TURN ON Heating: heating delta is -3.299999237060547 cooling delta is -1.4000015258789062 hysteresis is 1
2021-12-18 00:00:10.282 [INFO ] [lipse.smarthome.model.script.heating] - Turning ON the heater: curr temp = 19.3 setpoint = 16 mode = Boost
2021-12-18 00:00:10.416 [INFO ] [eclipse.smarthome.model.script.boost] - 5 minutes remaining on boost for Heating
2021-12-18 00:00:11.535 [INFO ] [.eclipse.smarthome.model.script.mode] - Fan mode changed from OFF to AUTO
2021-12-18 00:00:20.793 [INFO ] [.eclipse.smarthome.model.script.pins] - Commanding Pin12 to ON for HeatingPin
2021-12-18 00:18:40.002 [INFO ] [marthome.model.script.heatingcooling] - TURN ON Heating: heating delta is -3.799999237060547 cooling delta is -0.9000015258789062 hysteresis is 1
2021-12-18 00:25:51.740 [WARN ] [me.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.eclipse.smarthome.core.internal.items.ItemUpdater@1513b36' takes more than 5000ms.
2021-12-18 00:29:01.874 [INFO ] [marthome.model.script.heatingcooling] - TURN ON Heating: heating delta is -4 cooling delta is -0.7000007629394531 hysteresis is 1
2021-12-18 00:53:24.248 [INFO ] [marthome.model.script.heatingcooling] - TURN ON Heating: heating delta is -4.299999237060547 cooling delta is -0.40000152587890625 hysteresis is 1
2021-12-18 01:14:48.844 [INFO ] [marthome.model.script.heatingcooling] - TURN ON Heating: heating delta is -4.5 cooling delta is -0.20000076293945312 hysteresis is 1
2021-12-18 01:56:39.763 [INFO ] [marthome.model.script.heatingcooling] - TURN ON Heating: heating delta is -4.799999237060547 cooling delta is 0.09999847412109375 hysteresis is 1
2021-12-18 02:20:05.417 [INFO ] [marthome.model.script.heatingcooling] - TURN ON Heating: heating delta is -5 cooling delta is 0.2999992370605469 hysteresis is 1
2021-12-18 02:55:17.439 [INFO ] [.eclipse.smarthome.model.script.mode] - Heating mode changed from Boost to ON
2021-12-18 02:55:17.653 [INFO ] [.eclipse.smarthome.model.script.mode] - Cancelling boost mode
2021-12-18 02:55:18.912 [INFO ] [marthome.model.script.heatingcooling] - TURN OFF Heating: heating delta is -4.899999618530273 cooling delta is 0.1999988555908203 hysteresis is 1
2021-12-18 02:55:21.254 [INFO ] [lipse.smarthome.model.script.heating] - Turning OFF the heater: curr temp = 20.9 setpoint = 16 mode = ON
2021-12-18 02:55:24.672 [INFO ] [.eclipse.smarthome.model.script.pins] - Commanding Pin12 to OFF for HeatingPin
2021-12-18 02:55:32.604 [INFO ] [.eclipse.smarthome.model.script.mode] - Fan mode changed from AUTO to OFF
2021-12-18 02:55:33.515 [INFO ] [g.eclipse.smarthome.model.script.fan] - Turning OFF the fan: fan mode = OFF
2021-12-18 03:01:52.099 [INFO ] [marthome.model.script.heatingcooling] - TURN OFF Heating: heating delta is -4.700000762939453 cooling delta is 0 hysteresis is 1
2021-12-18 03:11:30.809 [INFO ] [marthome.model.script.heatingcooling] - TURN OFF Heating: heating delta is -4.5 cooling delta is -0.20000076293945312 hysteresis is 1
2021-12-18 03:26:44.538 [INFO ] [marthome.model.script.heatingcooling] - TURN OFF Heating: heating delta is -4.200000762939453 cooling delta is -0.5 hysteresis is 1
2021-12-18 03:45:30.753 [INFO ] [marthome.model.script.heatingcooling] - TURN OFF Heating: heating delta is -4 cooling delta is -0.7000007629394531 hysteresis is 1
2021-12-18 04:00:02.091 [INFO ] [.eclipse.smarthome.model.script.mode] - Heating mode changed from ON to Boost
2021-12-18 04:00:04.753 [INFO ] [eclipse.smarthome.model.script.boost] - Starting Heating boost
2021-12-18 04:00:05.029 [INFO ] [marthome.model.script.heatingcooling] - TURN ON Heating: heating delta is -3.8999996185302734 cooling delta is -0.8000011444091797 hysteresis is 1
2021-12-18 04:00:05.198 [INFO ] [lipse.smarthome.model.script.heating] - Turning ON the heater: curr temp = 19.9 setpoint = 16 mode = Boost
2021-12-18 04:00:06.014 [INFO ] [eclipse.smarthome.model.script.boost] - 5 minutes remaining on boost for Heating
2021-12-18 04:00:06.529 [INFO ] [.eclipse.smarthome.model.script.mode] - Fan mode changed from OFF to AUTO
2021-12-18 04:00:16.347 [INFO ] [.eclipse.smarthome.model.script.pins] - Commanding Pin12 to ON for HeatingPin
2021-12-18 04:22:07.537 [INFO ] [marthome.model.script.heatingcooling] - TURN ON Heating: heating delta is -4.299999237060547 cooling delta is -0.40000152587890625 hysteresis is 1
2021-12-18 04:51:41.205 [INFO ] [marthome.model.script.heatingcooling] - TURN ON Heating: heating delta is -4.5 cooling delta is -0.20000076293945312 hysteresis is 1
2021-12-18 05:54:53.161 [INFO ] [marthome.model.script.heatingcooling] - TURN ON Heating: heating delta is -4.799999237060547 cooling delta is 0.09999847412109375 hysteresis is 1
2021-12-18 06:50:00.053 [INFO ] [marthome.model.script.heatingcooling] - TURN ON Heating: heating delta is -5 cooling delta is 0.2999992370605469 hysteresis is 1
2021-12-18 08:00:04.037 [INFO ] [marthome.model.script.heatingcooling] - TURN ON Heating: heating delta is -1 cooling delta is 0.5 hysteresis is 1
2021-12-18 08:06:56.431 [INFO ] [marthome.model.script.heatingcooling] - TURN ON Heating: heating delta is -1.0999984741210938 cooling delta is 0.5999984741210938 hysteresis is 1
2021-12-18 08:30:25.061 [INFO ] [marthome.model.script.heatingcooling] - TURN ON Heating: heating delta is -2.0999984741210938 cooling delta is 0.5999984741210938 hysteresis is 1
2021-12-18 09:02:58.441 [INFO ] [marthome.model.script.heatingcooling] - TURN ON Heating: heating delta is -2.299999237060547 cooling delta is 0.7999992370605469 hysteresis is 1
2021-12-18 09:09:33.283 [INFO ] [.eclipse.smarthome.model.script.mode] - Heating mode changed from Boost to ON
2021-12-18 09:09:33.495 [INFO ] [.eclipse.smarthome.model.script.mode] - Cancelling boost mode
2021-12-18 09:09:34.631 [INFO ] [marthome.model.script.heatingcooling] - TURN OFF Heating: heating delta is -2.3999996185302734 cooling delta is 0.8999996185302734 hysteresis is 1
2021-12-18 09:09:34.992 [INFO ] [lipse.smarthome.model.script.heating] - Turning OFF the heater: curr temp = 21.6 setpoint = 19.2 mode = ON
2021-12-18 09:09:36.175 [INFO ] [.eclipse.smarthome.model.script.pins] - Commanding Pin12 to OFF for HeatingPin
2021-12-18 09:09:45.754 [INFO ] [.eclipse.smarthome.model.script.mode] - Fan mode changed from AUTO to OFF
2021-12-18 09:09:46.049 [INFO ] [g.eclipse.smarthome.model.script.fan] - Turning OFF the fan: fan mode = OFF
2021-12-18 09:11:08.208 [INFO ] [marthome.model.script.heatingcooling] - TURN OFF Heating: heating delta is -2.5999984741210938 cooling delta is 1.0999984741210938 hysteresis is 1
2021-12-18 09:14:10.893 [INFO ] [marthome.model.script.heatingcooling] - TURN OFF Heating: heating delta is -2.799999237060547 cooling delta is 1.2999992370605469 hysteresis is 1
From the log, we can see the expected boost at midnight. It takes 20 seconds to turn on the heating pin, seems kinda slow to me, but it’s good enough. Then then next thing we see, just a bit over 18 minutes later, is the heating being turned on again. From there, we see the delta continue to grow as it gets further and further above our set point.
Expected Behavior
So, what do the logs look like when it is behaving as expected? I went back a few days in the logs and was able to find an example.
2021-12-15 00:00:06.243 [INFO ] [.eclipse.smarthome.model.script.mode] - Heating mode changed from ON to Boost
2021-12-15 00:00:12.461 [INFO ] [eclipse.smarthome.model.script.boost] - Starting Heating boost
2021-12-15 00:00:13.413 [INFO ] [eclipse.smarthome.model.script.boost] - 10 minutes remaining on boost for Heating
2021-12-15 00:00:26.365 [INFO ] [marthome.model.script.heatingcooling] - TURN ON Heating: heating delta is -4.200000762939453 cooling delta is -5.299999237060547 hysteresis is 1
2021-12-15 00:00:27.882 [INFO ] [lipse.smarthome.model.script.heating] - Turning ON the heater: curr temp = 20.2 setpoint = 16 mode = Boost
2021-12-15 00:00:33.717 [WARN ] [me.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.eclipse.smarthome.core.thing.internal.CommunicationManager@511f75' takes more than 5000ms.
2021-12-15 00:00:34.876 [INFO ] [.eclipse.smarthome.model.script.mode] - Fan mode changed from OFF to AUTO
2021-12-15 00:00:41.771 [INFO ] [.eclipse.smarthome.model.script.pins] - Commanding Pin12 to ON for HeatingPin
2021-12-15 00:01:14.765 [INFO ] [eclipse.smarthome.model.script.boost] - 9 minutes remaining on boost for Heating
2021-12-15 00:02:22.514 [INFO ] [eclipse.smarthome.model.script.boost] - 8 minutes remaining on boost for Heating
2021-12-15 00:03:05.813 [WARN ] [me.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.openhab.core.events.internal.EventBridge@1c78a8b' takes more than 5000ms.
2021-12-15 00:03:23.528 [INFO ] [eclipse.smarthome.model.script.boost] - 7 minutes remaining on boost for Heating
2021-12-15 00:04:24.401 [INFO ] [eclipse.smarthome.model.script.boost] - 6 minutes remaining on boost for Heating
2021-12-15 00:05:25.085 [INFO ] [eclipse.smarthome.model.script.boost] - 5 minutes remaining on boost for Heating
2021-12-15 00:06:25.780 [INFO ] [eclipse.smarthome.model.script.boost] - 4 minutes remaining on boost for Heating
2021-12-15 00:07:26.659 [INFO ] [eclipse.smarthome.model.script.boost] - 3 minutes remaining on boost for Heating
2021-12-15 00:08:27.411 [INFO ] [eclipse.smarthome.model.script.boost] - 2 minutes remaining on boost for Heating
2021-12-15 00:09:30.087 [INFO ] [eclipse.smarthome.model.script.boost] - 1 minutes remaining on boost for Heating
2021-12-15 00:10:30.871 [INFO ] [eclipse.smarthome.model.script.boost] - Boost for Heating has ended, restoring to ON
2021-12-15 00:10:40.577 [INFO ] [.eclipse.smarthome.model.script.mode] - Heating mode changed from Boost to ON
2021-12-15 00:10:40.856 [INFO ] [.eclipse.smarthome.model.script.mode] - Cancelling boost mode
2021-12-15 00:10:55.293 [INFO ] [marthome.model.script.heatingcooling] - TURN OFF Heating: heating delta is -4.299999237060547 cooling delta is -5.200000762939453 hysteresis is 1
2021-12-15 00:10:57.359 [INFO ] [lipse.smarthome.model.script.heating] - Turning OFF the heater: curr temp = 20.3 setpoint = 16 mode = ON
2021-12-15 00:11:06.614 [INFO ] [.eclipse.smarthome.model.script.pins] - Commanding Pin12 to OFF for HeatingPin
2021-12-15 00:11:09.720 [INFO ] [.eclipse.smarthome.model.script.mode] - Fan mode changed from AUTO to OFF
2021-12-15 00:11:12.094 [INFO ] [g.eclipse.smarthome.model.script.fan] - Turning OFF the fan: fan mode = OFF
Importantly, we see those logDebug messages counting down each minute ( 9, 8, 7, 6... 1 minutes remaining on boost for Heating). After which, it ends boost mode and returns us to “ON”.
Where to go from here?
This means that the code in the “Boost time control” rule either isn’t being run at all, or it’s being run, but newState.intValue() is <= 0 and items[mode+“Mode”] != “Boost”. Since I saw that the mode was boost when I manually corrected the problem (and this is confirmed in the logs), I expect that it’s that this rule isn’t being run.
Now, I’m still very new to OpenHAB, but in the PaperUI, I see the rule fires when… {Heating,Cooling,HotWater,Humidity}RemBoostTime changes. Based on the code in the “then…” clause, it looks like this value should change every 60 seconds (on account of createTimerSecs(60, runme);).
This is where I could use your help. Why is this not running as expected?
I’ve set the boost time back to 10 minutes to see if this restores me to a functional state, but I won’t be able to see if that works until tonight. I’ll report back, but any tips on how to better debug this issue would be very much appreciated.