Rules not firing - thread stall or something wrong my end?

PaulL1 · February 15, 2021, 8:51am

Platform information:
- Hardware: Pi4
- OS: PiOS
- Java Runtime Environment: 1.8.0_161
- openHAB version: 2.5.11-1

I have a set of rules that run my boiler, heating valves and overall heating system. Late last winter I migrated my valves to homegear, and so I also installed the homematic binding. In general that works excellently. I was however having some issues with rules occassionally not running, which I normally resolved with a restart. Winter ended and it was no longer a problem, so I’ve spent no more time on the problem.

Even though it’s summer, it was a little colder today, and my mother-in-law is visiting, so I turned the heating on. And it didn’t run. And I have pretty good line of sight that the rule didn’t trigger from the event, as when I was last looking at this I turned on all debug logging, and haven’t turned it off.

This looks like some sort of thread stall or failure to fire events to me, as the problem corrects when I reboot with no code change, and the code itself never seems to get to the first debug statement, which is the first statement in the rule - so I think the rule isn’t triggering at all sometimes.

My questions are:

Has anyone seen anything like this before - is there some obvious thing I’m missing before I spend time chasing?
Could it be the Homematic binding causing it? I have no real reason to think that other than it was the last major change I made, but thought I’d ask. I can’t really remove the binding without things stopping working, and of course removing the binding requires a reboot, which usually fixes the problem anyway, so difficult to diagnose that way

On to the detail.

I have some items defined as so:

Group:Number:SUM DeviceValves (All)
Switch swMasterHeating "Heating Master" (InternalFlags, Switches, InitSwitchesOn, RestoreGroup)
Number BootValve "Boot Room Valve [%d %%]" (valveBoot, DeviceValves) { channel="homematic:HG-BC-RT-TRX-CyG-3:ABDD5864-8959-5743-FE7A-8ADC71DCD01D:MEQ1344264:1#VALVE_STATE" }
Number MasterValve "Master Valve [%d %%]" (valveMaster, DeviceValves) { channel="homematic:HG-BC-RT-TRX-CyG-3:4BCAAC30-44F5-BBDE-DF54-27D1B87DCE09:LEQ1133856:1#VALVE_STATE" }
# (a number of other valves)

Then a particular rule that should fire:

rule "Adjust heating state and timers whenever the amount of valve opening changes"
when
  Item DeviceValves changed or 
  Item swMasterHeating changed
then
  logDebug( 'boiler', 'Valve opening changed, deciding what to do, valve opening is ' + DeviceValves)

  if ( swInitialisationDone.state == NULL || swInitialisationDone.state != ON ){
    logInfo( 'boiler', 'Not running heating state rule - initialisation not done')
  } else {
    // count how many valves are at 100%
    var Number numberValves100 = 0
    DeviceValves.members.forEach(  valve | {
      if( valve.state as Number == 100 ){
        numberValves100 = numberValves100 + 1
      }
    })
# - quite a bit of code in here, but ultimately we're not getting to the debug statement, and it compiles, so it's not probably relevant

In my event log I have both a valve change, and a change to swMasterHeating, but I never get the debug message from the rule firing. After rebooting, I do get the debug message, and the rule runs fine. So I believe that the rule itself works, the logic works, and the event usually fires (i.e. this can’t be a syntax problem, if it was a syntax problem it would never run).

That’s leaving me to think it’s some sort of thread stall or other event handling problem that stops the event being fired. Is that a thing that can/does happen in Openhab?

Event log:

2021-02-15 12:01:54.751 [vent.ItemStateChangedEvent] - numberFridgesEnergyUsage changed from 34.972 to 34.973
2021-02-15 12:02:01.099 [ome.event.ItemCommandEvent] - Item 'numberHeatingReturnTemp' received command 23
2021-02-15 12:02:01.105 [vent.ItemStateChangedEvent] - numberHeatingReturnTemp changed from 22.9 to 23
2021-02-15 12:02:24.926 [vent.ItemStateChangedEvent] - numberFridgesPower changed from 200.443 to 201.485
2021-02-15 12:02:24.934 [vent.ItemStateChangedEvent] - numberFridgesEnergyUsage changed from 34.973 to 34.975
2021-02-15 12:02:31.131 [ome.event.ItemCommandEvent] - Item 'BootValve' received command 10
2021-02-15 12:02:31.187 [nt.ItemStatePredictedEvent] - BootValve predicted to become 10
2021-02-15 12:02:31.219 [vent.ItemStateChangedEvent] - BootValve changed from 0 to 10
2021-02-15 12:02:31.228 [GroupItemStateChangedEvent] - DeviceValves changed from 236 to 246 through BootValve
2021-02-15 12:02:31.738 [ome.event.ItemCommandEvent] - Item 'numberDHWUpperCylinderTemp' received command 43.5
2021-02-15 12:02:31.749 [vent.ItemStateChangedEvent] - numberDHWUpperCylinderTemp changed from 43.6 to 43.5
2021-02-15 12:02:32.777 [ome.event.ItemCommandEvent] - Item 'numberHeatingReturnTemp' received command 22.9
2021-02-15 12:02:32.789 [vent.ItemStateChangedEvent] - numberHeatingReturnTemp changed from 23 to 22.9
2021-02-15 12:02:45.536 [ome.event.ItemCommandEvent] - Item 'BootValve' received command 0
2021-02-15 12:02:45.581 [nt.ItemStatePredictedEvent] - BootValve predicted to become 0
2021-02-15 12:02:45.627 [GroupItemStateChangedEvent] - DeviceValves changed from 246 to 236 through BootValve
2021-02-15 12:02:45.629 [vent.ItemStateChangedEvent] - BootValve changed from 10 to 0
2021-02-15 12:02:48.156 [ome.event.ItemCommandEvent] - Item 'numberHeatingReturnTemp' received command 23
2021-02-15 12:02:48.172 [vent.ItemStateChangedEvent] - numberHeatingReturnTemp changed from 22.9 to 23
2021-02-15 12:02:55.163 [vent.ItemStateChangedEvent] - numberFridgesPower changed from 201.485 to 201.216
2021-02-15 12:02:55.166 [vent.ItemStateChangedEvent] - numberFridgesEnergyUsage changed from 34.975 to 34.977
2021-02-15 12:03:15.276 [ome.event.ItemCommandEvent] - Item 'numberDHWLowerCylinderTemp' received command 28
2021-02-15 12:03:15.298 [vent.ItemStateChangedEvent] - numberDHWLowerCylinderTemp changed from 28.1 to 28
2021-02-15 12:03:22.398 [ome.event.ItemCommandEvent] - Item 'numberDHWUpperCylinderTemp' received command 44
2021-02-15 12:03:22.423 [vent.ItemStateChangedEvent] - numberDHWUpperCylinderTemp changed from 43.5 to 44
2021-02-15 12:03:25.360 [vent.ItemStateChangedEvent] - numberFridgesPower changed from 201.216 to 201.246
2021-02-15 12:03:25.371 [vent.ItemStateChangedEvent] - numberFridgesEnergyUsage changed from 34.977 to 34.979
2021-02-15 12:03:37.036 [ome.event.ItemCommandEvent] - Item 'numberDHWUpperCylinderTemp' received command 44.3
2021-02-15 12:03:37.049 [vent.ItemStateChangedEvent] - numberDHWUpperCylinderTemp changed from 44 to 44.3
.....
2021-02-15 12:07:16.717 [ome.event.ItemCommandEvent] - Item 'numberDHWLowerCylinderTemp' received command 27.9
2021-02-15 12:07:16.733 [vent.ItemStateChangedEvent] - numberDHWLowerCylinderTemp changed from 28 to 27.9
2021-02-15 12:07:18.557 [ome.event.ItemCommandEvent] - Item 'numberHeatingReturnTemp' received command 23.1
2021-02-15 12:07:18.571 [vent.ItemStateChangedEvent] - numberHeatingReturnTemp changed from 23 to 23.1
2021-02-15 12:07:25.391 [ome.event.ItemCommandEvent] - Item 'swMasterHeating' received command OFF
2021-02-15 12:07:25.406 [vent.ItemStateChangedEvent] - swMasterHeating changed from ON to OFF
2021-02-15 12:07:26.943 [vent.ItemStateChangedEvent] - numberFridgesPower changed from 201.077 to 200.87
2021-02-15 12:07:26.946 [vent.ItemStateChangedEvent] - numberFridgesEnergyUsage changed from 34.991 to 34.992
2021-02-15 12:07:33.036 [ome.event.ItemCommandEvent] - Item 'numberDHWUpperCylinderTemp' received command 44.3
2021-02-15 12:07:33.050 [vent.ItemStateChangedEvent] - numberDHWUpperCylinderTemp changed from 44.5 to 44.3
2021-02-15 12:07:38.848 [ome.event.ItemCommandEvent] - Item 'swMasterHeating' received command ON
2021-02-15 12:07:38.865 [vent.ItemStateChangedEvent] - swMasterHeating changed from OFF to ON
2021-02-15 12:07:49.276 [ome.event.ItemCommandEvent] - Item 'numberHeatingReturnTemp' received command 23
2021-02-15 12:07:49.290 [vent.ItemStateChangedEvent] - numberHeatingReturnTemp changed from 23.1 to 23
2021-02-15 12:07:57.130 [vent.ItemStateChangedEvent] - numberFridgesPower changed from 200.87 to 200.377
2021-02-15 12:07:57.133 [vent.ItemStateChangedEvent] - numberFridgesEnergyUsage changed from 34.992 to 34.994

Openhab.log around that time period (there’s lots of debug logging, so quite a bit going on, but nothing that looks like this rule):

2021-02-15 12:01:47.461 [DEBUG] [eclipse.smarthome.model.script.zones] - Set to summer, use summerSetpoint
2021-02-15 12:01:47.478 [DEBUG] [eclipse.smarthome.model.script.zones] - Calculating setpoint for zoneLoggia at time 1201
2021-02-15 12:01:47.491 [DEBUG] [eclipse.smarthome.model.script.zones] - Checking time 600 against currentTime 1201
2021-02-15 12:01:47.495 [DEBUG] [eclipse.smarthome.model.script.zones] - Was less than or equal
2021-02-15 12:01:47.499 [DEBUG] [eclipse.smarthome.model.script.zones] - Checking time 900 against currentTime 1201
2021-02-15 12:01:47.504 [DEBUG] [eclipse.smarthome.model.script.zones] - Was less than or equal
2021-02-15 12:01:47.508 [DEBUG] [eclipse.smarthome.model.script.zones] - Checking time 1800 against currentTime 1201
2021-02-15 12:01:47.513 [DEBUG] [eclipse.smarthome.model.script.zones] - Checking time 2130 against currentTime 1201
2021-02-15 12:01:47.541 [DEBUG] [eclipse.smarthome.model.script.zones] - Calculated setpoint for zone zoneLoggia is setpointNumber 2 with value of 18.5, including adjustor of -0.5, 
old setpoint was setCurrentLoggia (Type=NumberItem, State=14, Label=Loggia Zone Current Setpoint, Category=temperature, Groups=[zoneSettingsLoggia, InitCurrentSetpoints, ZoneSetpoin
ts])
2021-02-15 12:01:47.552 [DEBUG] [eclipse.smarthome.model.script.zones] - Set to summer, use summerSetpoint
2021-02-15 12:02:31.226 [WARN ] [ommunicator.AbstractHomematicGateway] - Datapoint is readOnly, it is not published to the gateway with id 'ABDD5864-8959-5743-FE7A-8ADC71DCD01D': 'M
EQ1344264:1#VALVE_STATE'
2021-02-15 12:02:45.598 [WARN ] [ommunicator.AbstractHomematicGateway] - Datapoint is readOnly, it is not published to the gateway with id 'ABDD5864-8959-5743-FE7A-8ADC71DCD01D': 'M
EQ1344264:1#VALVE_STATE'
2021-02-15 12:06:47.032 [DEBUG] [eclipse.smarthome.model.script.zones] - Running zone settings
2021-02-15 12:06:47.055 [DEBUG] [eclipse.smarthome.model.script.zones] - Calculating setpoint for zoneBoot at time 1206
2021-02-15 12:06:47.102 [DEBUG] [eclipse.smarthome.model.script.zones] - Checking time 600 against currentTime 1206
2021-02-15 12:06:47.111 [DEBUG] [eclipse.smarthome.model.script.zones] - Was less than or equal
2021-02-15 12:06:47.121 [DEBUG] [eclipse.smarthome.model.script.zones] - Checking time 900 against currentTime 1206
2021-02-15 12:06:47.130 [DEBUG] [eclipse.smarthome.model.script.zones] - Was less than or equal
2021-02-15 12:06:47.140 [DEBUG] [eclipse.smarthome.model.script.zones] - Checking time 1800 against currentTime 1206
2021-02-15 12:06:47.151 [DEBUG] [eclipse.smarthome.model.script.zones] - Checking time 2130 against currentTime 1206
2021-02-15 12:06:47.362 [DEBUG] [eclipse.smarthome.model.script.zones] - Calculating setpoint for zoneGuest at time 1206
2021-02-15 12:06:47.389 [DEBUG] [eclipse.smarthome.model.script.zones] - Checking time 600 against currentTime 1206
2021-02-15 12:06:47.394 [DEBUG] [eclipse.smarthome.model.script.zones] - Was less than or equal
2021-02-15 12:06:47.401 [DEBUG] [eclipse.smarthome.model.script.zones] - Checking time 900 against currentTime 1206
2021-02-15 12:06:47.407 [DEBUG] [eclipse.smarthome.model.script.zones] - Was less than or equal
2021-02-15 12:06:47.412 [DEBUG] [eclipse.smarthome.model.script.zones] - Checking time 1800 against currentTime 1206
2021-02-15 12:06:47.420 [DEBUG] [eclipse.smarthome.model.script.zones] - Checking time 2130 against currentTime 1206
2021-02-15 12:06:47.460 [DEBUG] [eclipse.smarthome.model.script.zones] - Calculated setpoint for zone zoneGuest is setpointNumber 2 with value of 18.5, including adjustor of -0.5, old setpoint was setCurrentGuest (Type=NumberItem, State=10, Label=Guest Zone Current Setpoint, Category=temperature, Groups=[zoneSettingsGuest, InitCurrentSetpoints, ZoneSetpoints])
2021-02-15 12:06:47.471 [DEBUG] [eclipse.smarthome.model.script.zones] - Zone zoneGuest is switched off, setting setpoint to away setpoint
2021-02-15 12:06:47.483 [DEBUG] [eclipse.smarthome.model.script.zones] - Calculating setpoint for zoneLiving at time 1206
2021-02-15 12:06:47.500 [DEBUG] [eclipse.smarthome.model.script.zones] - Checking time 600 against currentTime 1206
2021-02-15 12:06:47.504 [DEBUG] [eclipse.smarthome.model.script.zones] - Was less than or equal
2021-02-15 12:06:47.508 [DEBUG] [eclipse.smarthome.model.script.zones] - Checking time 900 against currentTime 1206
2021-02-15 12:06:47.513 [DEBUG] [eclipse.smarthome.model.script.zones] - Was less than or equal
2021-02-15 12:06:47.517 [DEBUG] [eclipse.smarthome.model.script.zones] - Checking time 1800 against currentTime 1206
2021-02-15 12:06:47.522 [DEBUG] [eclipse.smarthome.model.script.zones] - Checking time 2130 against currentTime 1206
2021-02-15 12:06:47.551 [DEBUG] [eclipse.smarthome.model.script.zones] - Calculated setpoint for zone zoneLiving is setpointNumber 2 with value of 18.5, including adjustor of -0.5, old setpoint was setCurrentLiving (Type=NumberItem, State=14, Label=Living Zone Current Setpoint, Category=temperature, Groups=[zoneSettingsLiving, InitCurrentSetpoints, ZoneSetpoints])
2021-02-15 12:06:47.567 [DEBUG] [eclipse.smarthome.model.script.zones] - Set to summer, use summerSetpoint
2021-02-15 12:06:47.577 [DEBUG] [eclipse.smarthome.model.script.zones] - Calculating setpoint for zoneLoggia at time 1206
2021-02-15 12:06:47.592 [DEBUG] [eclipse.smarthome.model.script.zones] - Checking time 600 against currentTime 1206
2021-02-15 12:06:47.597 [DEBUG] [eclipse.smarthome.model.script.zones] - Was less than or equal
2021-02-15 12:06:47.601 [DEBUG] [eclipse.smarthome.model.script.zones] - Checking time 900 against currentTime 1206
2021-02-15 12:06:47.605 [DEBUG] [eclipse.smarthome.model.script.zones] - Was less than or equal
2021-02-15 12:06:47.609 [DEBUG] [eclipse.smarthome.model.script.zones] - Checking time 1800 against currentTime 1206
2021-02-15 12:06:47.614 [DEBUG] [eclipse.smarthome.model.script.zones] - Checking time 2130 against currentTime 1206
2021-02-15 12:06:47.640 [DEBUG] [eclipse.smarthome.model.script.zones] - Calculated setpoint for zone zoneLoggia is setpointNumber 2 with value of 18.5, including adjustor of -0.5, old setpoint was setCurrentLoggia (Type=NumberItem, State=14, Label=Loggia Zone Current Setpoint, Category=temperature, Groups=[zoneSettingsLoggia, InitCurrentSetpoints, ZoneSetpoints])
2021-02-15 12:06:47.650 [DEBUG] [eclipse.smarthome.model.script.zones] - Set to summer, use summerSetpoint
2021-02-15 12:11:47.032 [DEBUG] [eclipse.smarthome.model.script.zones] - Running zone settings
2021-02-15 12:11:47.053 [DEBUG] [eclipse.smarthome.model.script.zones] - Calculating setpoint for zoneBoot at time 1211
2021-02-15 12:11:47.088 [DEBUG] [eclipse.smarthome.model.script.zones] - Checking time 600 against currentTime 1211
2021-02-15 12:11:47.097 [DEBUG] [eclipse.smarthome.model.script.zones] - Was less than or equal
2021-02-15 12:11:47.107 [DEBUG] [eclipse.smarthome.model.script.zones] - Checking time 900 against currentTime 1211
2021-02-15 12:11:47.113 [DEBUG] [eclipse.smarthome.model.script.zones] - Was less than or equal
2021-02-15 12:11:47.118 [DEBUG] [eclipse.smarthome.model.script.zones] - Checking time 1800 against currentTime 1211
2021-02-15 12:11:47.124 [DEBUG] [eclipse.smarthome.model.script.zones] - Checking time 2130 against currentTime 1211
2021-02-15 12:11:47.157 [DEBUG] [eclipse.smarthome.model.script.zones] - Calculated setpoint for zone zoneBoot is setpointNumber 2 with value of 18.5, including adjustor of -0.5, old setpoint was setCurrentBoot (Type=NumberItem, State=14, Label=Boot Zone Current Setpoint, Category=temperature, Groups=[zoneSettingsBoot, InitCurrentSetpoints, ZoneSetpoints])
2021-02-15 12:11:47.170 [DEBUG] [eclipse.smarthome.model.script.zones] - Set to summer, use summerSetpoint
2021-02-15 12:11:47.180 [DEBUG] [eclipse.smarthome.model.script.zones] - Calculating setpoint for zoneBed at time 1211

So there are other rules and timers firing, but not these particular events, which seems unusual.

Finally, a log from after the reboot, where it’s working properly.


2021-02-15 19:09:59.855 [DEBUG] [lipse.smarthome.model.script.devices] - A valve changed value: Kitchen
2021-02-15 19:09:59.921 [DEBUG] [lipse.smarthome.model.script.devices] - Releasing lock
2021-02-15 19:09:59.927 [DEBUG] [clipse.smarthome.model.script.boiler] - Valve opening changed, deciding what to do, valve opening is DeviceValves (Type=GroupItem, BaseType=NumberIt
em, Members=12, State=76, Label=null, Category=null, Groups=[All])
2021-02-15 19:09:59.964 [DEBUG] [clipse.smarthome.model.script.boiler] - Already running, valves have changed so need to adjust run timer
2021-02-15 19:09:59.969 [DEBUG] [clipse.smarthome.model.script.boiler] - setRunTimer with type of update
2021-02-15 19:09:59.979 [DEBUG] [clipse.smarthome.model.script.boiler] - Heating run timer calculated as 1990.00000000 based on numberHeatingRunBaseMinutes (Type=NumberItem, State=3
0, Label=Base Run Minutes, Category=clock, Groups=[InternalFlags, RestoreGroup])DeviceValves (Type=GroupItem, BaseType=NumberItem, Members=12, State=76, Label=null, Category=null, G
roups=[All])numberHeatingRunFactor (Type=NumberItem, State=250, Label=Run Factor, Category=waterpump, Groups=[InternalFlags, RestoreGroup])
2021-02-15 19:09:59.983 [DEBUG] [clipse.smarthome.model.script.boiler] - Timer was present, cancelled it
2021-02-15 19:09:59.999 [DEBUG] [clipse.smarthome.model.script.boiler] - Valves changed, creating a new run timer, timer will end at dtTimerEnd (Type=DateTimeItem, State=2021-02-15T
19:26:59.227+1300, Label=Current Timer End, Category=clock, Groups=[InternalFlags, RestoreGroup])
2021-02-15 19:10:00.008 [DEBUG] [model.script.actions.ScriptExecution] - Scheduled code for execution at 2021-02-15T19:26:59.227+13:00
2021-02-15 19:10:00.015 [DEBUG] [clipse.smarthome.model.script.boiler] - Run timer is org.eclipse.smarthome.model.script.internal.actions.TimerImpl@b06bf6
2021-02-15 19:10:00.022 [DEBUG] [lipse.smarthome.model.script.devices] - Timer called: ValveTimerSet (Type=StringItem, State=Kitchen, Label=Valve Timer, Category=null)
2021-02-15 19:10:00.063 [DEBUG] [lipse.smarthome.model.script.devices] - Cancelling existing timer for Kitchen
2021-02-15 19:10:00.079 [DEBUG] [lipse.smarthome.model.script.devices] - Timer called: ValveTimerSet (Type=StringItem, State=, Label=Valve Timer, Category=null)
2021-02-15 19:10:00.082 [DEBUG] [lipse.smarthome.model.script.devices] - Timer called, string is empty meaning its an unset not a set
2021

Any information or ideas gratefully received.

rlkoshak · February 15, 2021, 8:25pm

Check (OH 1.x and OH 2.x Rules DSL only] Why have my Rules stopped running? Why Thread::sleep is a bad idea and see if any of that applies to you. A big sign that this is happening would be if you see those two triggering Items changing in events.log but no sign that the rule is running. I can see them changing in the logs you posted and I can see at least one case where the first line of the rule logged out something in openhab.log. But your events.log is from 12:11 and openhab.log is from 19:09 so there is nothing one can conclude from this.

NOTE: this is not a problem in OH 3.

Without way more information there is no way to tell. You’d have to correlate the events in events.log with when you issued the command and try to trace it through the full path from clicking on the sitemap through the binding. You’d probably want to put the binding into trace logging mode.

rossko57 · February 15, 2021, 11:23pm

Long shot, make sure you only have only one rule with given “name” across all rules files. The rules parser will replace a rule upon a second load attempt of same rule “name”. People have got in knots when copy-paste rules for template use, the apparent symptom is “my rule doesn’t trigger sometimes” (depending on who got edited last).

PaulL1 · February 16, 2021, 12:28am

Thanks for the link to “Why have my Rules stopped running” - I’ll take a look at that. I don’t in general use thread::sleep, other than as a timing thing on the programming of the watering system where it needs 90ms between toggles - but I presume we’re concerned about long sleeps in the order of minutes or more, not short pauses like that.

I’m also interested that other rules are still running, but just not this one - so there are still triggers firing. I presume if thread:sleep was the culprit then no rules would fire. Locks could be a problem, I think I have one area that I use locks, which I wrote a long time ago. I need to go back and see if that’s actually needed, and whether it could possibly be blocking. I think I always write a debug before the lock, so I should see the locked threads if that was happening.

In terms of the logs - the log at 19:09 is a log of it working properly (demonstrating that it does sometimes work - in this case after a reboot). There is an openhab.log that correlates to the time period where the switch and/or valve changed (the valve at 12:02:45, the switch at 12:07:25), and in neither of those cases did the debug statement at the start of the rule appear in the log (refer the gap between 12:01 and 12:06 in the log, where no rules ran). The next set of logging is a timed even at 12:06:47.

That’s ultimately my question - what could cause a rule that does sometimes work to sometimes not work, when the only thing I can see is an event trigger then a debug statement. I’m trying to work out what I could do that would cause a rule/event to not fire like that. It sounds like the number of rule threads could be the cause (or, more correctly, exhaustion of the number of rule threads), and you’ve given some good pointers towards where I can look for causes.

Thanks,

rlkoshak · February 16, 2021, 1:45am

If you have lock look at that first. If not I’m not sure what else to look at. a off it’s just this rule that isn’t firing then it’s probably not the thread pool that’s the problem.

It works be unusual for the rule to crash without anything in the log but I’ve seen that happen before.

PaulL1 · February 18, 2021, 1:27am

Reviewing all my locks was quite interesting. I had about 40 lines of code doing some complex work to determine if any of my valves were stuck (occasionally they stop communicating, so you end up with a valve that the heating thinks is open, but actually isn’t, so the boiler keeps cycling).

I thought hard about it, and rewrote the whole thing much more elegantly using one of your design patterns. It had an ugly timer, and then that timer had to be recursively called if the valve didn’t unstick, and it had a synch point so we didn’t do multiple valves at the same time. All of that because I wasn’t using the persistence history, I was trying to remember the state at a point in time and check it again in 40 minutes (I didn’t have a sleep though, I at least was using a timer). New code looks like this:

import org.joda.time.DateTime

rule "Check if valves have changed every 30 minutes"
when 
  Time cron "47 0/30 * * * ?" 
then
  if ( swInitialisationDone.state == NULL || swInitialisationDone.state != ON ){
    logInfo( 'devices', 'Not running valve stuck check - initialisation not done')
  } else {
    logDebug( 'devices', "Checking if any valves are stuck" )

    DeviceValves.members.forEach[ valve | 
      if( valve.state > 0 && !( valve.changedSince(now.minusMinutes(32)) ) ){
        logDebug( 'devices', "Valve " + valve + " appears stuck, hasn't changed for 32 minutes.  Resending setpoint")
        val NumberItem setpoint = Device.Setpoints.members.filter( m | m.name.startsWith( valve.name.substring( 0, valve.name.length() -  5 ) )).last as NumberItem  
        setpoint.sendCommand(setpoint.state as Number)
      }
    ]
  }
end

Just wanted to say thanks for all you do for the community - those patterns were excellent.

No info yet on whether this fixes things, but the code is definitely way better. It surely cannot hurt.