Automated build process (buster)

hestia_hacker · March 25, 2023, 1:36am

Rebooting / power outages

I normally reboot with sudo shutdown -r now which has always worked fine on all of the images.
I tried sudo reboot and 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.

hestia_hacker · March 25, 2023, 8:44pm

Rebooting / power outages

I normally reboot with sudo shutdown -r now which has always worked fine on all of the images.
I tried sudo reboot and 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.

jrtaylor71 · March 26, 2023, 1:36pm

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.

hestia_hacker · March 27, 2023, 2:36am

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.502 Press boost cooling button
2023-03-26 18:12:19.641 Attempt 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.163 I turn cooling from Boost to Off
2023-03-26 23:55:39.466 I 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.038 I turn cooling from Boost to Off again
2023-03-27 01:08:29.736 I try boosting the heat to see if that works. It worked exactly as expected
2023-03-27 01:24:52.924 I 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.459 I 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

jrtaylor71 · March 27, 2023, 4:00am

The versions in the basic UI are controlled with 2 script files and a text file with the installed version.

/home/pi/scripts/getgitinstalledversion.sh
/home/pi/scripts/getgitlatestversion.sh
/home/pi/scripts/gitinstalledversion

pi@raspberrypi:~ $ /home/pi/scripts/getgitinstalledversion.sh
v1.1
pi@raspberrypi:~ $ /home/pi/scripts/getgitlatestversion.sh
v1.1
pi@raspberrypi:~ $ cat /home/pi/scripts/gitinstalledversion
v1.1
pi@raspberrypi:~ $ 
pi@raspberrypi:~ $ nano /home/pi/scripts/gitinstalledversion
pi@raspberrypi:~ $ cat /home/pi/scripts/gitinstalledversion
v1.3-dev

The gitinstalledversion file is updated by the /home/pi/scripts/updateone.sh script. Probably should be creating branches and tags for each version.

HestiaPi · April 4, 2023, 5:39am

I’m happy to release 1.3-dev in GitHub but I’m not sure how this should be reflected on the repo as I believe it is now the result of your scripts, pulling a clean image, pulling the HestiaPi repo and producing an image file. Maybe only the instructions on the wiki are to be replaced before releasing the 1.3-dev.
What do you guys think?

hestia_hacker · April 5, 2023, 4:05am

I updated the scripts to call my build 1.3-dev and there’s a fresh image available.

The version numbering is tricky here because there’s more that goes into the disk image than just the openhab configs from the repo which contains the version number. It’s largely the same process now as previously, just more automated. I think it’d be reasonable to bump the github version number to 1.3-dev based on the other fixes that were done (hot water rule and jumping away from the wifi setup screen early).

The instructions on the wiki could just point to the ansible script to transform a Raspberry Pi into a HestiaPi. There is kinda a lot going on there, specifically in terms of different versions on different distros. I did not remove support for building on old versions of Debian and it’s going to get more complex if we extend it to support both 32-bit and 64-bit platforms. We could describe it in prose on the wiki, but that seems unnecessary if it’s already described in yaml. Users interested in building their own could just run and/or read the yaml files to roll their own image.

HestiaPi · April 5, 2023, 6:05am

Can you update the filename to 1.3-dev? I’ll try over the next 2 weeks (holidays) to update the version file on github and publish the 1.3-dev image file under the releases with a brief change on the wiki for info/instructions.

hestia_hacker · April 6, 2023, 5:22am

Yes. https://gitlab.hax0rbana.org/hax0rbana_public/raspberrypi-automation/-/jobs/4922/artifacts/file/hestia-pi-ONE-v1.3-dev-buster-4922.img.xz

jrtaylor71 · April 7, 2023, 3:26am

Network time sync: Is it disabled for a reason or did it just get missed?

systemd-timesyncd is disabled in 1.3-dev. I enabled it and here is what I found that makes it work.

First off the config file does not work and what I found at forums.raspberrypi.com was just to delete it and use the compiled defaults. This is the file that is on the 1.3-dev image.

pi@raspberrypi:~ $ cat /etc/systemd/timesyncd.conf 
#  This file is part of systemd.
#
#  systemd is free software; you can redistribute it and/or modify it
#  under the terms of the GNU Lesser General Public License as published by
#  the Free Software Foundation; either version 2.1 of the License, or
#  (at your option) any later version.
#
# Entries in this file show the compile time defaults.
# You can change settings by editing this file.
# Defaults can be restored by simply deleting this file.
#
# See timesyncd.conf(5) for details.

[Time]
#NTP=
NTP=ben.hax0rbana.org
#RootDistanceMaxSec=5
#PollIntervalMinSec=32
#PollIntervalMaxSec=2048

Enable systemd.timesyncd

pi@raspberrypi:~ $ sudo timedatectl set-timezone America/Chicago
pi@raspberrypi:~ $ sudo timedatectl set-ntp true
pi@raspberrypi:~ $ sudo rm /etc/systemd/timesyncd.conf
pi@raspberrypi:~ $ sudo systemctl enable systemd-timesyncd
pi@raspberrypi:~ $ sudo systemctl start systemd-timesyncd
pi@raspberrypi:~ $ sudo systemctl status systemd-timesyncd
● systemd-timesyncd.service - Network Time Synchronization
   Loaded: loaded (/lib/systemd/system/systemd-timesyncd.service; enabled; vendor preset: enabled)
  Drop-In: /lib/systemd/system/systemd-timesyncd.service.d
           └─disable-with-time-daemon.conf
   Active: active (running) since Thu 2023-04-06 22:03:58 CDT; 6s ago
     Docs: man:systemd-timesyncd.service(8)
 Main PID: 7608 (systemd-timesyn)
   Status: "Synchronized to time server for the first time 104.131.155.175:123 (0.debian.pool.ntp.org)."
    Tasks: 2 (limit: 877)
   CGroup: /system.slice/systemd-timesyncd.service
           └─7608 /lib/systemd/systemd-timesyncd

Apr 06 22:03:57 raspberrypi systemd[1]: Starting Network Time Synchronization...
Apr 06 22:03:58 raspberrypi systemd[1]: Started Network Time Synchronization.
Apr 06 22:03:58 raspberrypi systemd-timesyncd[7608]: Synchronized to time server for the first time 104.131.155.175:123 (0.debian.pool.ntp.org).
pi@raspberrypi:~ $ timedatectl show-timesync
FallbackNTPServers=0.debian.pool.ntp.org 1.debian.pool.ntp.org 2.debian.pool.ntp.org 3.debian.pool.ntp.org
ServerName=0.debian.pool.ntp.org
ServerAddress=104.131.155.175
RootDistanceMaxUSec=5s
PollIntervalMinUSec=32s
PollIntervalMaxUSec=34min 8s
PollIntervalUSec=2min 8s
NTPMessage={ Leap=0, Version=4, Mode=4, Stratum=2, Precision=-30, RootDelay=3.112ms, RootDispersion=5.661ms, Reference=408E7A25, OriginateTimestamp=Thu 2023-04-06 22:05:02 CDT, ReceiveTimestamp=Thu 2023-04-06 22:05:02 CDT, TransmitTimestamp=Thu 2023-04-06 22:05:02 CDT, DestinationTimestamp=Thu 2023-04-06 22:05:02 CDT, Ignored=no PacketCount=2, Jitter=3.911ms }
Frequency=-6318359
pi@raspberrypi:~ $ sudo timedatectl status
               Local time: Thu 2023-04-06 22:07:24 CDT
           Universal time: Fri 2023-04-07 03:07:24 UTC
                 RTC time: n/a
                Time zone: America/Chicago (CDT, -0500)
System clock synchronized: yes
              NTP service: active
          RTC in local TZ: no

hestia_hacker · April 7, 2023, 6:27pm

Having a non-public time server in /etc/systemd/timesyncd.conf is an error that occurred because of the build environment. Sorry about that, my automation project has had to move git hosts a few times now … In any case, I’ve updated the build scripts to remove this file so it won’t be in the next image.

I’m not disabling the timesync service, but it’s not going to sync the time with that config file either. I think all that is required is to delete the config file and then restart the service or reboot. That worked for me. Once the automated build system completes, I’ll verify the timesyncd service works out of the box and report back.

Thanks for the additional testing and feedback. The new image keeps getting better because of it.

hestia_hacker · April 8, 2023, 4:22am

I tested the updated image (build 4838) can con confirm that it fixes the time sync issue.

hestia_hacker · April 15, 2023, 8:43pm

@jrtaylor71 Did you have a chance to confirm that build 4838 fixes the NTP issue on your network?

All: are we ready to make the 1.3-dev image official?

jrtaylor71 · April 16, 2023, 12:42am

No I didn’t, I was working US HVAC customization for temperature and humidity with one decimal and a .5 step. I will check it out in a day or so.

jrtaylor71 · April 17, 2023, 7:30pm

Yes that fixed the problem with date and time syncing.

hestia_hacker · April 28, 2023, 6:44pm

@HestiaPi, do you think this build (4838) is ready to be promoted to be 1.3-dev on Download – HestiaPi?

HestiaPi · May 5, 2023, 6:07am

Absolutely… I have already uploaded the 4938 file to GDrive since April but haven’t got the chance to actually publish it… Trying now…

HestiaPi · May 5, 2023, 6:34am

Have a look and please add a few lines in the release notes.
Apologies for the delay on my behalf

system · August 4, 2023, 12:34pm

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