[Solved] Cascading timer irrigation (weird behaviour)

[rPi3B, Stretch Lite, Zulu Java (zulu8.31.1.122-jdk1.8.0_181-linux_aarch32hf)
OH2.4.0-1 (apt-get), mosquitto, samba]

My irrigation rules are built on Rich’s pattern of cascading timers, which I installed on a OHv1 system in March 2018. It worked ever since (however, I cannot say, whether the problem I found three days ago existed back then). I migrated from OH1 to OH2 on Jan 1st, 2019.

Three days ago, my wife noticed that valve 3 of one of the irrigation systems ran twice in a row.
I checked over the weekend; it ran fine on Saturday; today it ran valve 2 twice. Hover, tracking MQTT messages sent by the OH rules say that valve 1 was sent an ON command twice.

The valve commands are strings with 4 characters (built by rules and published via MQTT), the first two for the valve 00-99, the second pair for the time in minutes or 00 = OFF; e.g. 0320 = valve 3 for 20 minutes; 0300 valve 3 off.

My suspicion is an item update timing issue; why there is the odd Threat::sleep in the rules (aiming to prevent that).

Only investigating OH2.4.0 running since Jan 1:

Irrigation days .....: 120
Faulty days..........: 7
Max. valve triggers..: 17

7 days showed more than the 8 valve triggers; 4 valves with two commands (ON|OFF) = 8 commands (triggers).
1 day had 17 triggers.

No changes were made to the irrigation rules post migration from OH1 to OH2 in on Jan 1st.

What comes next are:

  1. the MQTT tracking for today
  2. the OH log file for today (Please note: “turning OFF all valves regardless of state” was added yesterday to make sure valves are OFF before another one comes on)
  3. the rules (Please note: Irrigation valve 2…4 OFF is the same as for valve 1, except for the identifier)
mosquitto_sub -v -t ArgyleCourt/Property/PumpStation1/Valve | xargs -d$'\n' -L1 sh -c 'date "+%D %T.%3N $0"'
05/04/19 20:53:36.387 ArgyleCourt/Property/PumpStation1/Valve 0000
05/05/19 10:00:15.209 ArgyleCourt/Property/PumpStation1/Valve 0115
05/05/19 10:15:15.251 ArgyleCourt/Property/PumpStation1/Valve 0100
05/05/19 10:15:16.265 ArgyleCourt/Property/PumpStation1/Valve 0000
05/05/19 10:15:30.421 ArgyleCourt/Property/PumpStation1/Valve 0115
05/05/19 10:30:30.439 ArgyleCourt/Property/PumpStation1/Valve 0100
05/05/19 10:30:31.456 ArgyleCourt/Property/PumpStation1/Valve 0000
05/05/19 10:30:45.565 ArgyleCourt/Property/PumpStation1/Valve 0215
05/05/19 10:45:45.576 ArgyleCourt/Property/PumpStation1/Valve 0200
05/05/19 10:45:46.591 ArgyleCourt/Property/PumpStation1/Valve 0000
05/05/19 10:46:00.721 ArgyleCourt/Property/PumpStation1/Valve 0325
05/05/19 11:11:00.737 ArgyleCourt/Property/PumpStation1/Valve 0300
05/05/19 11:11:01.752 ArgyleCourt/Property/PumpStation1/Valve 0000
05/05/19 11:11:15.886 ArgyleCourt/Property/PumpStation1/Valve 0420
05/05/19 11:31:15.913 ArgyleCourt/Property/PumpStation1/Valve 0400
05/05/19 11:31:16.933 ArgyleCourt/Property/PumpStation1/Valve 0000

2019-05-05 10:00:00.043 [INFO ] [arthome.model.script.Irrigation1.11a] - ... PumpStation1_LastSessionTotal set to 919
2019-05-05 10:00:05.059 [INFO ] [arthome.model.script.Irrigation1.11b] - ... PumpStation1_LastSessionTotal set to 841
2019-05-05 10:00:10.070 [INFO ] [arthome.model.script.Irrigation1.11e] - ... PumpStation1_LastSessionMemory -> to 0
2019-05-05 10:00:15.092 [INFO ] [marthome.model.script.Irrigation1.14] - ... station1 VolumeSession ... -> set to 0; is it? -> 0
2019-05-05 10:00:15.101 [INFO ] [marthome.model.script.Irrigation1.15] - ..> turning Irrigation1_1 ON
2019-05-05 10:00:15.132 [INFO ] [marthome.model.script.Irrigation1.21] - ... currValveSwitch...: ON
2019-05-05 10:00:15.152 [INFO ] [rthome.model.script.Irrigation1.23.1] - ... currValveMins.dec.: 15.0
2019-05-05 10:00:15.158 [INFO ] [rthome.model.script.Irrigation1.23.2] - ... currValveMinsInt..: 15
2019-05-05 10:00:15.178 [INFO ] [marthome.model.script.Irrigation1.24] - ... VolumePrevious (meter 1) . -> 0
2019-05-05 10:15:15.210 [INFO ] [ome.model.script.Irrigation1.timer.1] - ..< turning Irrigation1_1 OFF
2019-05-05 10:15:15.250 [INFO ] [home.model.script.Irrigation1_1.off1] - ... valve flow rate .......... -> 9
2019-05-05 10:15:15.272 [INFO ] [home.model.script.Irrigation1_1.off2] - ... current meter reading .... -> 193
2019-05-05 10:15:15.282 [INFO ] [home.model.script.Irrigation1_1.off3] - ... valveVolume (calculated) . -> 193
2019-05-05 10:15:16.255 [INFO ] [marthome.model.script.Irrigation1.1b] - ..! turning OFF all valves regardless of state
2019-05-05 10:15:30.269 [INFO ] [ome.model.script.Irrigation1.timer.2] - ..> turning Irrigation1_2 ON
2019-05-05 10:15:30.333 [INFO ] [marthome.model.script.Irrigation1.21] - ... currValveSwitch...: OFF
2019-05-05 10:15:30.363 [INFO ] [rthome.model.script.Irrigation1.23.1] - ... currValveMins.dec.: 15.0
2019-05-05 10:15:30.377 [INFO ] [rthome.model.script.Irrigation1.23.2] - ... currValveMinsInt..: 15
2019-05-05 10:15:30.397 [INFO ] [marthome.model.script.Irrigation1.24] - ... VolumePrevious (meter 1) . -> 194
2019-05-05 10:30:30.421 [INFO ] [ome.model.script.Irrigation1.timer.1] - ..< turning Irrigation1_1 OFF
2019-05-05 10:30:30.444 [INFO ] [home.model.script.Irrigation1_1.off1] - ... valve flow rate .......... -> 9
2019-05-05 10:30:30.453 [INFO ] [home.model.script.Irrigation1_1.off2] - ... current meter reading .... -> 331
2019-05-05 10:30:30.458 [INFO ] [home.model.script.Irrigation1_1.off3] - ... valveVolume (calculated) . -> 137
2019-05-05 10:30:31.441 [INFO ] [marthome.model.script.Irrigation1.1b] - ..! turning OFF all valves regardless of state
2019-05-05 10:30:45.462 [INFO ] [ome.model.script.Irrigation1.timer.2] - ..> turning Irrigation1_2 ON
2019-05-05 10:30:45.493 [INFO ] [marthome.model.script.Irrigation1.21] - ... currValveSwitch...: ON
2019-05-05 10:30:45.512 [INFO ] [rthome.model.script.Irrigation1.23.1] - ... currValveMins.dec.: 15.0
2019-05-05 10:30:45.518 [INFO ] [rthome.model.script.Irrigation1.23.2] - ... currValveMinsInt..: 15
2019-05-05 10:30:45.537 [INFO ] [marthome.model.script.Irrigation1.24] - ... VolumePrevious (meter 1) . -> 333
2019-05-05 10:45:45.564 [INFO ] [ome.model.script.Irrigation1.timer.1] - ..< turning Irrigation1_2 OFF
2019-05-05 10:45:45.592 [INFO ] [home.model.script.Irrigation1_2.off1] - ... valve flow rate .......... -> 5
2019-05-05 10:45:45.604 [INFO ] [home.model.script.Irrigation1_2.off2] - ... current meter reading .... -> 441
2019-05-05 10:45:45.611 [INFO ] [home.model.script.Irrigation1_2.off3] - ... valveVolume (calculated) . -> 108
2019-05-05 10:45:46.577 [INFO ] [marthome.model.script.Irrigation1.1b] - ..! turning OFF all valves regardless of state
2019-05-05 10:46:00.590 [INFO ] [ome.model.script.Irrigation1.timer.2] - ..> turning Irrigation1_3 ON
2019-05-05 10:46:00.631 [INFO ] [marthome.model.script.Irrigation1.21] - ... currValveSwitch...: ON
2019-05-05 10:46:00.654 [INFO ] [rthome.model.script.Irrigation1.23.1] - ... currValveMins.dec.: 25.0
2019-05-05 10:46:00.660 [INFO ] [rthome.model.script.Irrigation1.23.2] - ... currValveMinsInt..: 25
2019-05-05 10:46:00.684 [INFO ] [marthome.model.script.Irrigation1.24] - ... VolumePrevious (meter 1) . -> 442
2019-05-05 11:11:00.720 [INFO ] [ome.model.script.Irrigation1.timer.1] - ..< turning Irrigation1_3 OFF
2019-05-05 11:11:00.749 [INFO ] [home.model.script.Irrigation1_3.off1] - ... valve flow rate .......... -> 11
2019-05-05 11:11:00.758 [INFO ] [home.model.script.Irrigation1_3.off2] - ... current meter reading .... -> 754
2019-05-05 11:11:00.764 [INFO ] [home.model.script.Irrigation1_3.off3] - ... valveVolume (calculated) . -> 312
2019-05-05 11:11:01.738 [INFO ] [marthome.model.script.Irrigation1.1b] - ..! turning OFF all valves regardless of state
2019-05-05 11:11:15.751 [INFO ] [ome.model.script.Irrigation1.timer.2] - ..> turning Irrigation1_4 ON
2019-05-05 11:11:15.799 [INFO ] [marthome.model.script.Irrigation1.21] - ... currValveSwitch...: ON
2019-05-05 11:11:15.826 [INFO ] [rthome.model.script.Irrigation1.23.1] - ... currValveMins.dec.: 20.0
2019-05-05 11:11:15.832 [INFO ] [rthome.model.script.Irrigation1.23.2] - ... currValveMinsInt..: 20
2019-05-05 11:11:15.856 [INFO ] [marthome.model.script.Irrigation1.24] - ... VolumePrevious (meter 1) . -> 757
2019-05-05 11:31:15.886 [INFO ] [ome.model.script.Irrigation1.timer.1] - ..< turning Irrigation1_4 OFF
2019-05-05 11:31:15.944 [INFO ] [home.model.script.Irrigation1_4.off1] - ... valve flow rate .......... -> 10
2019-05-05 11:31:15.954 [INFO ] [home.model.script.Irrigation1_4.off2] - ... current meter reading .... -> 981
2019-05-05 11:31:15.964 [INFO ] [home.model.script.Irrigation1_4.off3] - ... valveVolume (calculated) . -> 224
2019-05-05 11:31:16.918 [INFO ] [marthome.model.script.Irrigation1.1b] - ..! turning OFF all valves regardless of state
2019-05-05 11:31:30.931 [INFO ] [e.smarthome.model.script.Irrigation1] - Irrigation group 1 finished.
2019-05-05 11:31:30.964 [INFO ] [marthome.model.script.Irrigation1.41] - Irrigation1 -> reset Auto Switch
// When either auto or manual switch is flicked ON, the whole sequence kicks off
// one valve after the other, as per set durations
rule "Start Irrigation1"
  when
    // triggers to start this group; either auto (by cron) or manual
    Item Irrigation1_Auto changed to ON or
    Item Irrigation1_Now  changed to ON
  then
    // only irrigate if allowed is ON
    if (Irrigation1_Allowed.state == ON) {

      // start up valve 1 of 4
      logInfo("Irrigation1.10", "Irrigation1 started...")

      // capture current meter (from last session) and store it in last session total
      logInfo("Irrigation1.11a", "... PumpStation1_LastSessionTotal set to {}", PumpStation1_LastSessionTotal.state)
      PumpStation1_LastSessionTotal.postUpdate(PumpStation1_LastSessionMemory.state)
      Thread::sleep(5000)
      logInfo("Irrigation1.11b", "... PumpStation1_LastSessionTotal set to {}", PumpStation1_LastSessionTotal.state)

      // zero the last session memory and start at zero for this session
      //logInfo("Irrigation1.11c", "... PumpStation1_LastSessionMemory -> to {}", PumpStation1_LastSessionMemory.state)
      PumpStation1_LastSessionMemory.postUpdate(0)
      //logInfo("Irrigation1.11d", "... PumpStation1_LastSessionMemory -> to {}", PumpStation1_LastSessionMemory.state)
      Thread::sleep(5000)
      logInfo("Irrigation1.11e", "... PumpStation1_LastSessionMemory -> to {}", PumpStation1_LastSessionMemory.state)

      // ----- reset meter to 0 for good...
      // reset the controller's meter to 0
      publish("mymosquitto", "ArgyleCourt/Property/PumpStation1/Command", "resetMeter")
      //logInfo("Irrigation1.11f", "... MQTT: pump station 1 meter -> set to 0")

      // also publish the reset to 0 to the item 'PumpStation1_Meter' item, because
      //   the controller does not publish (force) this value
      publish("mymosquitto", "ArgyleCourt/Property/PumpStation1/Meter", "0")
      //logInfo("Irrigation1.12", "... MQTT: PumpStation1_Meter .. -> set to 0")

      // we now have to update this value as well, because the controller does
      //   not publish back the forced change to 0
      PumpStation1_Meter.postUpdate(0)
      //logInfo("Irrigation1.13a", "... PumpStation1_Meter ....... -> set to 0 -> {}", PumpStation1_Meter.state)

      // reset the session volume counter to zero
      // sleep for 5 seconds to let the meter settle
      Thread::sleep(5000)
      //logInfo("Irrigation1.13b", "... PumpStation1_Meter ....... -> set to 0 -> {}", PumpStation1_Meter.state)
      //logInfo("Irrigation1.14a", "... station1 VolumeSession ... -> set to {}", PumpStation1_MemoriseMeterRead)

      PumpStation1_MemoriseMeterRead = (PumpStation1_Meter.state as Number).intValue
      //logInfo("Irrigation1.14b", "... station1 VolumeSession ... -> set to {}", PumpStation1_MemoriseMeterRead)
      // was
      //PumpStation1_MemoriseMeterRead = 0
      //logInfo("Irrigation1.14", "... station1 VolumeSession ... -> set to 0")
      logInfo("Irrigation1.14", "... PumpStation1 VolumeSession ... -> set to 0; is it? -> {}", PumpStation1_MemoriseMeterRead)

      // update 'curr'ent valve name; which is #1
      Irrigation1_Curr.sendCommand(Irrigation1_1.name)

      // now switch valve 1 ON
      Irrigation1_1.sendCommand(ON)
      logInfo("Irrigation1.15", "..> turning {} ON ", Irrigation1_Curr.state)

    } else {

      logInfo("Irrigation1.16", "Irrigation1 not started -> not allowed!")
      Irrigation1_Reset.postUpdate(ON)
    }
end


// This is the domino rule, to trigger the next valve ON
// 1. It starts with 1 from the previous rule
// 2...4 one after the other
rule "Irrigation1 valve cascade ON"
  when
    Item Irrigation1_1 received command ON or
    Item Irrigation1_2 received command ON or
    Item Irrigation1_3 received command ON or
    Item Irrigation1_4 received command ON
  then
    // Get the currently running valve's name: e.g. Irrigation1_1
    val currValveName = Irrigation1_Curr.state.toString
    //logInfo("Irrigation1.20", "... currValveName.....: {}", currValveName)

    // get the part 'Irrigation1'
    val currValveSwitch = gIrrigation1.members.filter[i | i.name == currValveName].head
    logInfo("Irrigation1.21", "... currValveSwitch...: {}", currValveSwitch.state)

    // e.g. Irrigation1_1 -> split at _ and get array item 0 and 1,
    // with array item 0 being the irrigation1 part, and
    // with array item 1 being the number of the valve having been triggered
    val currValveNum = Integer::parseInt(currValveName.split("_").get(1))
    //logInfo("Irrigation1.22", "... currValveNum......: {}", currValveNum)

    // the valve time comes from an item named e.g. Irrigation1_1_Time
    val currValveMins = gIrrigation1Time.members.filter[t | t.name == currValveName + "_Time"].head.state as DecimalType
    // current duration for display on sitemap; decimal value
    logInfo("Irrigation1.23.1", "... currValveMins.dec.: {}", currValveMins)

    // 181231 MaxG: make it integer permanently
    val currValveMinsInt = currValveMins.intValue

    // current duration for display on sitemap; cast to integer
    Irrigation1_CurrTimer.postUpdate(currValveMinsInt)
    logInfo("Irrigation1.23.2", "... currValveMinsInt..: {}", currValveMinsInt)

    // Get the next running valve in the sequence
    val nextValveName = "Irrigation1_" + (currValveNum + 1)

    // will be null if not found
    val nextValveSwitch = gIrrigation1.members.filter[i|i.name == nextValveName].head


    // global: memorise current total volume
    PumpStation1_MemoriseMeterRead = (PumpStation1_Meter.state as Number).intValue
    logInfo("Irrigation1.24", "... VolumePrevious (meter 1) . -> {}", PumpStation1_MemoriseMeterRead)

    // ----- build MQTT message for valve OFF
    var String valveMessageOff = ""

    // add leading zero to send 2-digit number as string
    if (currValveNum < 10) {
      valveMessageOff = "0" + currValveNum.toString
    } else {
      valveMessageOff = currValveNum.toString
    }

    // prefix with double zero for OFF (Arduino OFF = 00)
    valveMessageOff = valveMessageOff + "00"

    // assign var to val; has to be due to use in lambda, which requires a constant (val)
    val finalValveMessageOff = valveMessageOff

    // ----- build MQTT message for valve ON
    var String valveMessageOn = ""

    // add leading zero to send 2-digit number as string
    if (currValveNum < 10) {
      valveMessageOn = "0" + currValveNum.toString
    } else {
      valveMessageOn = currValveNum.toString
    }

    // ----- add minutes to MQTT message
    // add leading zero to send 2-digit number as string
    if (currValveMinsInt < 10) {
      valveMessageOn = valveMessageOn + "0" + currValveMinsInt.toString
    } else {
      valveMessageOn = valveMessageOn + currValveMinsInt.toString
    }

    // send MQTT command to switch valve xx ON for yy minutes, received by controller
    publish("mymosquitto", "ArgyleCourt/Property/PumpStation1/Valve", valveMessageOn)


    // ----- timer: runs when its time has expired
    // Create a timer to turn off curr and change state to on for next next valve
    // while this timer is created here, it only executes its contents on expire
    irrigation1Timer = createTimer(now.plusMinutes(currValveMinsInt), [|

      // turn OFF current valve
      logInfo("Irrigation1.timer.1", "..< turning {} OFF ", currValveName)
      currValveSwitch.sendCommand(OFF)

      // send valve OFF via MQTT to pump station controller
      publish("mymosquitto", "ArgyleCourt/Property/PumpStation1/Valve", finalValveMessageOff)

      //  190503 added; fail safe; had OH sent switch valve 2 OFF twice, instead of OFF 2 then OFF 3
      Thread::sleep(1000)
      logInfo("Irrigation1.1b", "..! turning OFF all valves regardless of state")
      publish("mymosquitto", "ArgyleCourt/Property/PumpStation1/Valve", "0000")

      // without the sleep commands OFF and ON the next may follow too quickly
      // here: sleep 14 seconds
      Thread::sleep(14000)

      if (nextValveSwitch !== null) {
        logInfo("Irrigation1.timer.2", "..> turning {} ON ", nextValveName)
        Irrigation1_Curr.sendCommand(nextValveName)
        nextValveSwitch.sendCommand(ON)

      } else {
        logInfo("Irrigation1", "Irrigation group 1 finished.")
        Irrigation1_Curr.sendCommand("None")

        // switch OFF Now and Auto
        Irrigation1_Reset.postUpdate(ON)

        // update last run time
        Irrigation1_LastOn.postUpdate(new DateTimeType())
      }

      irrigation1Timer = null
    ])
end


rule "Irrigation1 valve 1 OFF"
  when
    Item Irrigation1_1 received command OFF
  then
    // ----- water volume calculations

    // ----- flow calculations
    // get current flow rate from controller update via MQTT;
    //   should be reflective of mean at end of valve duration
    var int valveFlow = (PumpStation1_Flow.state as Number).intValue
    logInfo("Irrigation1_1.off1", "... valve flow rate .......... -> {}", valveFlow)

    // send flow rate to site map item for this session
    publish("mymosquitto", "ArgyleCourt/Property/PumpStation1/Flow1", valveFlow.toString)

    // ----- calculate valve volume
    // get current meter reading
    var int valveVolume = (PumpStation1_Meter.state as Number).intValue
    logInfo("Irrigation1_1.off2", "... current meter reading .... -> {}", valveVolume)

    // subtract the memorised meter (valve start value) for this valve from the current valve meter reading
    valveVolume = valveVolume - PumpStation1_MemoriseMeterRead
    logInfo("Irrigation1_1.off3", "... valveVolume (calculated) . -> {}", valveVolume)

    // send valve volume to valve volume item for site map display
    publish("mymosquitto", "ArgyleCourt/Property/PumpStation1/Volume1", valveVolume.toString)

    // add volume to build SessionMemory
    val int tmpVolume = (PumpStation1_LastSessionMemory.state as Number).intValue
    PumpStation1_LastSessionMemory.postUpdate(tmpVolume + valveVolume)
    // alternative:
    //PumpStation1_LastSessionMemory.postUpdate((PumpStation1_LastSessionMemory.state as Number).intValue + valveVolume)
end

I do not know if this is related to what you observe, but I will use it to illustrate.
When you command an Item, this does not immediately change its state. In fact, it may never change the Items state.
Example - sending a rollerblind command UP may result in a state 50% … followed shortly by 60% … 70% … etc.
The idealized openHAB model of an Item linked to real device is that you may send it a command e.g. ON. Some time later, an actual device responds with a new status of ON and the binding now upates the Item state to ON.

Because real devices may be very slow to respond, or may never give an actual status at all, openHAB includes an autoupdate feature.
This is like a psuedo-binding, it listens out for commands, then makes an informed guess about the likely results, and then posts an update to the Item, ultimately setting the Item state.
This feature is enabled by default on each Item, but can be disabled as required (like when your actual device responds promptly).

People using “virtual” Items - no binding to a real device - often rely on autupdate to reflect commands in the Item state. That’s fine.

But important - there’s an unpredictable time delay between command and new state. Autoupdate listens for the command, does some processing, posts an update, openHAB hears the update, finally changes Item state.

Meantime, any rules also listening for commands will have triggered and be executing. If those same rules examine the Item state - it’s indeterminate, it may be the old or new value. It may change as the rule chunters along.

The bit of rule I’ve picked out above is a classic example of the problem. Irrigation1_Curr was given a command in the other rule, followed by Irrigation1_1 getting a command to trigger this rule. Irrigation1_Curr state is indeterminate.

Rules of thumb;
It’s okay to trigger from command, but use receivedCommand implicit variable to find out what it was. Don’t rely on state.
Alternatively;
If you want to use state, that’s fine - but trigger the rule from state updated or change, not command.

1 Like

I’m not sure what the actual fix is in your case, by the by :crazy_face:
Complicated sequence of events - piles of long delays are definitely a bad idea.

I’d be looking to refactor so that event X toggles event Y toggles event Z.
Is this Irrigation1_Curr command always accompanied by command to Irrigation1_1?

Perhaps more simpler rules.

.// some rule
      Irrigation1_Curr.sendCommand(XX)
...

//new rule
when
   Irrigation1_Curr updated
then
   Irrigation1_1.sendCommand(ZZ)
...

// rule that does the work
when 
    Irrigation1_1 received command
then
...

Thanks for the explanation… it demonstrates to me that I never understood openHAB… hence. the constant problems I am facing with it.

I saw your post elsewhere:

… and read: https://www.openhab.org/docs/configuration/rules-dsl.html

It does my head in… :slight_smile:

I always thought OH has an event bus, with items that have a state; the state changes rule-based or event-based, and if that happens the state changes to reflect that state.

Now I learn, it may or may not change its state, and more conditions when it may or may not do so. Why on earth is it designed that way? Is there even logic in this basically unpredictable behaviour?

The sleeps are in the code, because I noticed that the state is not updated in a timely fashion, hoping the sleep() would fix this issue.

The sprinkler code basically works by starting with valve 1 setting a few variables, and then cascades through the other valves incrementally. It “fails” only some 5% of the time (another inconsistency of that state business), and I may leave everything as it is.

My general issue is, I can get the hang of a programming language and then not use it for a few years, and forget all about it. E.g. I programmed a website (content system) in ASP in 2004; rewrote it in PHP in 2011; had to change to PHP7 in 2016, was forced to make at least the minimum change from mysql() to msqli() to make the site work again. I can’t remember a thing about ASP, forgot all about PHP in 2016, and today… because I do not use it in between. so with OH; OH1 worked, installed a new OH2, moved the rules; fixed what needed fixing and forgot about it. Four month later I find this problem, and literally start from scratch… and yes, I am on old fart (over 60 yo).

In essence, I am after programming principles that always work, and not this works here and this works there (insert condition here). If I say change state, I want this reflected to reuse it elsewhere; I am happy to understand what I need to do to achieve this (and never worry about options again). Am I too naive | demanding?

Or is it as simple as, replace all .state with .receivedCommand?

[later edit:] further thinking about this… so if I use receivedCommand() and change the items or rule file this would be a ‘system start’, the item has not yet received a command, hence receivedCommand() may return null, yet its state is ON. Or do I need persistence, which as I understand it only saves its state, not the last command??

Because it had to be this way. How else can it handle:

  • technologies that report a devices state change back to OH
  • technologies that do not report a device state change back to OH
  • Items that can be commanded with something that *is not a State the Item holds (e.g. sending UP to a roller shutter or ON to a Dimmer)
  • the ability to trigger a Rule based on a command and to get in that Rule the actual command, even if the command does not match the State of the Item.

In order for OH to work as you describe we could not handle most of these cases which would greatly cripple OH’s utility. But if you want it to work like you describe, never use received command Rule triggers. Then your Rules will only trigger when the actual Item has changed State or received an update. Of course this eliminated some important use cases like Expire Binding based Timers.

There is definitely a TOCTU (time of check, time of use) bug in the code. I can’t really look at it until I get to a computer, probably tomorrow. The sleeps might address the problem, I don’t know yet until I can study there coffee and the logs more.

This was likely a problem even in OH 1 but you were just lucky that the timing worked out. The behavior described had always been the way OH works.

I can offer nothing to help with dealing with the advances in languages and technologies. Your only choice is to either never change anything ever, which isn’t really feasible most of the time. Or enter a state of constant learning which is what most of us do I think.

There is no such thing. Only programming principles that work now.

But in this particular case, the programming principles have not changed. It’s always worked like this.

This doesn’t make much sense so I think there is still some confusion. You have the following Item triggers:

  • changed: triggers the rule when that Item changes it’s state. Unless the Item changes state again really fast, you can rely on MyItem.state matching the state that the Item changed to. There will be a variable named previousState that holds the state the Item was in prior to the change.

  • received update: triggers the rule when that Item receives an update regardless of whether the update results in a change to the Item’s state.

  • received command: triggers the rule when that Item is commanded. Not that a command is completely independent of update or change. The Item may receive an update in response to the command and it may change state. But it also may not. So in order to know what the command received was you should use the variable receivedCommand which holds the command that was sent to the Item. The command may not be of the same type as MyItem.state (e.g. sending command ON to a Dimmer). By default, OH assumes that what ever device the command is being sent to will not post an update back to the Item so OH had a feature that guesses what the state will be as a result of the command and post an update/change based on that guess (e.g. sending ON to a Dimmer may result in OH updating the Dimmer to 100%). You can turn this guessing off in cases where you do have technologies that report state changes by seeing autoupdate=false. Then the Item will not change state or recurve an update until the device actually reports back that it has changed state as a response to the command. All of this, whether OH is guessing or the device reports back takes some time. So on a received command triggered Rule, you can’t rely on on the state of the Item that received the command. It may not have reached that state yet. And if you do need to really on the state, you need to use a changed or received update trigger instead because you really care about the state change, not the command. A command is a signal of anintention to change the state of a device but does not reflect the actual change to the Item.

A quick reply on my current thinking (which I may well change after reading (and more so understanding) your post and documentation, making an effort to understand the underlying principles), hence, no need to reply to what I am saying here; (it may serve as knowledge gap identifier):

  1. putting the colour item aside (on, off, dim, colour compositions, etc.) a switch is either on or off… I have no issue with whatever process changes it, the state should still be what the last state was no matter who updates it (even if it is a different format, like HSB).
  2. this is my case. I had individual timers with no connection to OH; they died, I quickly replaced them with solenoid valves and an Arduino receiving ON|OFF commands from OH; what I have now. This works! Other than my state enquiry :slight_smile:
  3. yes, sort of get it and have to think about it | understand the impact. No matter what I sent to a colour item, it comes back as HSB, which I get, as any of these states can be translated to a HSB value set.
  4. this is what I do not seem to grasp yet. Why? Don’t worry, have to do more reading.

Aside from all of this: thank you kindly for your support…

I will come back once I have an updated rule set that works.

That is correct. Note hat commands are something different - they also propogate on the bus, and affect only bindings or rules listening for them. Commands are not states. Commands may or may not, depending on the configuration, trigger some state changes somewhere. Which then make their own way onto the bus.

1 Like

I think the key takeaway is that a command is not a state change. Think of a command as a request for a state change. The Item may or may not change to that state and it may take some time to change to that state. So in a received command Rule, you can’t rely on the MyItem.state because received command isn’t an Item state event, it’s an event indicating that we have asked the Item to change state. Actions are afoot but not necessarily complete.

For 4, perhaps an example would prove illuminating.

Imagine I have a proxy Item and I’m using a Rollershutter Item. I want to do have a Rule trigger when that Rollershutter Item receives an UP, DOWN, or STOP command.

A Rollershutter’s state is a PercentType (integer between 0 and 100).

If I trigger a Rule using changed, I can perhaps infer whether there was an UP or DOWN command at some point prior by comparing the current state with the previous state. But I’d never get a trigger for STOP because the Item will stop changing.

Similarly with a received update, I can only infer whether there was an UP or DOWN command, onyl it’s even more difficult because I don’t have the previousState implicit variable. And again, STOP will not trigger the Rule because that command results in the Item no longer changing state.

This is because changed and received update are Item state change events.

In this case, I don’t care about the state changes though, I only care about the actual command that was sent. So we use received command.

Let’s assume that when you send a command to an Item it immediately changes to that same state, as you suggest. Once I’m in the Rule, as with the received update Rule, I can only infer what the actual command was because MyRollershutterProxy.state can only be UNDEF, NULL, or PercentType. It can’t be UpDownType.

I can’t use if(MyRollershutterProxy.state == UP). UP isn’t a state that is valid for this Item type. And again, what about STOP? In short, I really can’t reliably discover whether the command was UP, DOWN, or STOP, which is what I really care about.

Now, let’s go back to the idea that a command is not a state event. In that case our Rule triggers and we get a receivedCommand implicit variable telling us what the command was. But because this is a command and not a state change, we know that we can’t rely on the state of the Item that was commanded. It may not have changed yet. It may never change. We may not care whether it changes. In this Rule we certainly don’t care whether the Item changed. If we did, we should have used a changed trigger instead. We only care about the command. So we shouldn’t even try to check the state of the Item and only use receivedCommand.


Looking at the code. The five second sleeps are not a good idea and far far longer than needed. Although we talk about Item state changed taking some time in the case of commands, these are all updates and even with commands, the changes rarely take more than half a second except in cases where there is a poor network connection and the device takes some time to either receive the command or respond that it has acted on the command.

In your first Rule, remove all the Thread::sleeps and add one of no more than 500 milliseconds immediately before sending the command to Irrigation1_Curr. Though I don’t think it is needed even there.

Based on the behavior you are describing is sounds like it’s the second Rule that is triggering too fast and probably running before Irrigation1_Curr is updated or changed. That is the most likely explanation for why the same zone might run more than once but only rarely.

The quick and easy fix for that would be to add a little sleep (no more than 500 msec) between the postUpdate to Irrigation1_Curr and the command to nextValveSwitch. This will ensure that Curr is updated before the Rule triggers again.

The probably more correct solution would be to trigger the Rule when Irrigation1_Curr changes instead of the commands on the Irrigation Items. I’m going to update the DP to use Curr instead of commands to the Items.

I’m uncomfortable with the really really long sleeps. Creating another Timer would be more appropriate, assuming that these sleeps are actually better. It isn’t actually clear to me what problem you are solving with that 14 second sleep.

NOTE: I’ve updated the Cascading Timers DP to be driven by commands send to Irrigation_Curr so you can see how to do that.

1 Like

Firstly, thank you very much for looking into this; I followed your advice and removed the sleep() yesterday; today saw the cascade running w/o any hick-ups.
The initial reason for the sleep() was that I did not see the numeric updates to the items occurring fast enough, and weird calculations took place. The sleeps fixed these issues at the time (never looked back). It is also the only rule set where I used sleeps.

Secondly, as for your explanation: I need the some quiet time over the weekend to digest your and other’s comments, as well as reading the docs on it.

I understand that state may never change for some items (where I used the colour item with HSB as an example); however, I was nevertheless expecting for any change/command to take place ASAP.

Oh it does. It’s just that ASAP may not be fast enough.