OH3: if() in rule occasionally not executing

[Max_G]

• openHABian 3.3.0 on rPi4 with 4GB

I am pondering over an issue I cannot explain.

I have a ‘universal timer’ (ut) in form of an Arduino with a relay output where I can set the on time and off time via MQTT.
At present the relay is ON for 3 minutes and OFF for 5 min,

I have three items in OH. which get updated by the Arduino sending ON, OFF and a heartbeat message via MQTT to OH.

The three notifications are processed by almost identical rules, which differ in action.

Such a rule looks like this:

        if (ut_notification.state.toString == "ON")
        {
            ut_last_on.postUpdate(new DateTimeType())
            ut_alarm_too_long_on.postUpdate(OFF)
            // blue
            Shed_KDL_Colour.sendCommand("220,100,30")
        }

These rules work.

The relevant items are:

… each of which have an expire timer of 9 minutes for ON|OFF and 11 minutes for the heartbeat (which occurs every 10 min).

The expire functions (if not triggered) will send an ON command, which triggers a rule, like the following

rule "UT Alarm: ON state duration exceeded"
    when
        Item ut_alarm_too_long_on changed to ON
    then
        // red
        Shed_KDL_Colour.sendCommand("10,100,30")
        logInfo(LOG_PREFIX + "02.01", "Alarm red triggered by ut_alarm_too_long_on")
end

The MQTT log shows precise ON and OFF events, as well as the heartbeat,

2023-01-31 18:18:18.611 UniversalTimer|INFO|DHCP OK
2023-01-31 18:18:19.235 ON
2023-01-31 18:21:19.309 OFF
2023-01-31 18:26:19.431 ON
2023-01-31 18:28:18.856 UniversalTimer|INFO|DHCP OK
2023-01-31 18:29:19.505 OFF
2023-01-31 18:34:19.627 ON
2023-01-31 18:37:19.702 OFF
2023-01-31 18:38:19.099 UniversalTimer|INFO|DHCP OK
2023-01-31 18:42:19.822 ON
2023-01-31 18:45:19.897 OFF
2023-01-31 18:48:19.341 UniversalTimer|INFO|DHCP OK
2023-01-31 18:50:20.019 ON
2023-01-31 18:53:20.095 OFF
2023-01-31 18:58:19.588 UniversalTimer|INFO|DHCP OK
2023-01-31 18:58:20.217 ON
2023-01-31 19:01:20.293 OFF
2023-01-31 19:06:20.414 ON
2023-01-31 19:08:19.832 UniversalTimer|INFO|DHCP OK

So far so good; all working as designed

The problem is, OH, every now and then, issues an alert, despite the events occurring within the expire time setting.

Here the OH log:

2023-01-31 18:29:18.684 [INFO ] [re.model.script.UniversalTimer.04.01] - Alarm red triggered by ut_alarm_no_heartbeat
2023-01-31 18:37:19.861 [INFO ] [re.model.script.UniversalTimer.02.01] - Alarm red triggered by ut_alarm_too_long_on

And for convenience, the logs together in sequence:

2023-01-31 18:18:18.611 UniversalTimer|INFO|DHCP OK
2023-01-31 18:18:19.235 ON
2023-01-31 18:21:19.309 OFF
2023-01-31 18:26:19.431 ON
2023-01-31 18:28:18.856 UniversalTimer|INFO|DHCP OK
2023-01-31 18:29:18.684 [INFO ] [re.model.script.UniversalTimer.04.01] - Alarm red triggered by ut_alarm_no_heartbeat
2023-01-31 18:29:19.505 OFF
2023-01-31 18:34:19.627 ON
2023-01-31 18:37:19.702 OFF
2023-01-31 18:37:19.861 [INFO ] [re.model.script.UniversalTimer.02.01] - Alarm red triggered by ut_alarm_too_long_on
2023-01-31 18:38:19.099 UniversalTimer|INFO|DHCP OK
2023-01-31 18:42:19.822 ON
2023-01-31 18:45:19.897 OFF
2023-01-31 18:48:19.341 UniversalTimer|INFO|DHCP OK
2023-01-31 18:50:20.019 ON
2023-01-31 18:53:20.095 OFF
2023-01-31 18:58:19.588 UniversalTimer|INFO|DHCP OK
2023-01-31 18:58:20.217 ON
2023-01-31 19:01:20.293 OFF
2023-01-31 19:06:20.414 ON
2023-01-31 19:08:19.832 UniversalTimer|INFO|DHCP OK

I have no idea how to fix this?
Nor have I found this to be a known issue with the expire function.

Any hints appreciated.

[rlkoshak (Rich Koshak)]

@Max_G

I have three items in OH. which get updated by the Arduino sending ON, OFF and a heartbeat message via MQTT to OH.

You probably don’t need the heartbeat message. MQTT has its own built in heartbeat when a client connects to the broker and registers a LWT topic and message. The typical usage is the client will publish ONLINE or some such to the LWT topic and register OFFLINE as the LWT message on the broker (both messages are retained). When the heartbeat between the client and the broker fail, the broker will publish OFFLINE to the LWT topic and because the messages are retained, it’s always possible to know the online status of the client by looking at that one topic.

@Max_G

ut_last_on.postUpdate(new DateTimeType())

Assuming that the timestamp also gets set for OFF, this part can be handled by the timestamp profile. Link this Item to the same Channel as ut_notification and use the timestamp profile. Any change published by the Channel will update the DateTime Item to now.

I only bring these up because you have the option to sidestep these problems entirely and eliminate what sounds like could be a number of rules, resulting in a simpler and more responsive design over all.

As to your problem, I don’t see where ut_alarm_no_heartbeat is updated.

@Max_G

The MQTT log shows precise ON and OFF events, as well as the heartbeat,

The relevant events.log would be more informative. None of the code you’ve shown has the log statements that produce these logs so it’s impossible to tell what we are looking at. What’s turning ON and OFF? What’s UniveralTimer... mean?

@Max_G

Nor have I found this to be a known issue with the expire function.

Expire has options whether to treat updates to the same state the Item currently is in as a reason to reset the timer or not. That might be something to look at. Beyond that, there’s not enough information presented here to say. We see some logs but not the log statements that generate them. We are not seeing the actual events on the Items themselves which is what actually drives expire.

[Max_G]

Thank you for your detailed reply.
… more so how this whole set-up can be improved.

@rlkoshak

Assuming that the timestamp also gets set for OFF, this part can be handled by the timestamp profile.

OFF was in the first rule segment, adding here the lot:

rule "UT: Last Reboot"
    when
        Item ut_notification received update
    then
        // various `if then` here ... (but irrelevant)3

        if (ut_notification.state.toString == "ON")
        {
            ut_last_on.postUpdate(new DateTimeType())
            // blue
            ut_alarm_too_long_on.postUpdate(OFF)
            Shed_KDL_Colour.sendCommand("220,100,30")
        }
end

So, if ON received set the ut_alarm_too_long_on to OFF; expire on ut_alarm_too_long_on after 9 minutes sets it to 11 min. This triggers this rule:

rule "UT Alarm: ON state duration exceeded"
    when
        Item ut_alarm_too_long_on changed to ON
    then
        // red
        Shed_KDL_Colour.sendCommand("10,100,30")
        logInfo(LOG_PREFIX + "02.01", "Alarm red triggered by ut_alarm_too_long_on")
end

All this with two other items in a similar fashion.

The reason for the 9 minutes is; ON = 3 min, OFF = 5 min added together = 8 min, before either ON|OFF is being received. Add another minute = 9 just to give it enough time for expire to receive a reset.

@rlkoshak

The relevant events.log would be more informative.

Here the even’ts.log part:

2023-01-31 18:29:18.679 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'ut_alarm_no_heartbeat' received command ON
2023-01-31 18:29:18.683 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_alarm_no_heartbeat' changed from OFF to ON
2023-01-31 18:37:19.843 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'ut_alarm_too_long_on' received command ON
2023-01-31 18:37:19.859 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_alarm_too_long_on' changed from OFF to ON
2023-01-31 18:38:19.121 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_alarm_no_heartbeat' changed from ON to OFF
2023-01-31 18:42:19.878 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_alarm_too_long_on' changed from ON to OFF

And here the chronological mix of event.log, openhab.log and MQTT.log

2023-01-31 18:18:18.611 UniversalTimer|INFO|DHCP OK
2023-01-31 18:18:19.235 ON
2023-01-31 18:21:19.309 OFF
2023-01-31 18:26:19.431 ON
2023-01-31 18:28:18.856 UniversalTimer|INFO|DHCP OK
2023-01-31 18:29:18.679 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'ut_alarm_no_heartbeat' received command ON
2023-01-31 18:29:18.683 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_alarm_no_heartbeat' changed from OFF to ON
2023-01-31 18:29:18.684 [INFO ] [re.model.script.UniversalTimer.04.01] - Alarm red triggered by ut_alarm_no_heartbeat
2023-01-31 18:29:19.505 OFF
2023-01-31 18:34:19.627 ON
2023-01-31 18:37:19.702 OFF
2023-01-31 18:37:19.843 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'ut_alarm_too_long_on' received command ON
2023-01-31 18:37:19.859 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_alarm_too_long_on' changed from OFF to ON
2023-01-31 18:37:19.861 [INFO ] [re.model.script.UniversalTimer.02.01] - Alarm red triggered by ut_alarm_too_long_on
2023-01-31 18:38:19.099 UniversalTimer|INFO|DHCP OK
2023-01-31 18:38:19.121 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_alarm_no_heartbeat' changed from ON to OFF
2023-01-31 18:42:19.822 ON
2023-01-31 18:42:19.878 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_alarm_too_long_on' changed from ON to OFF
2023-01-31 18:45:19.897 OFF
2023-01-31 18:48:19.341 UniversalTimer|INFO|DHCP OK
2023-01-31 18:50:20.019 ON
2023-01-31 18:53:20.095 OFF
2023-01-31 18:58:19.588 UniversalTimer|INFO|DHCP OK

@rlkoshak

What’s UniveralTimer... mean?

UniversalTimer is an Arduino UNO controlling a sump pump.
It switches the pump on given intervals; here, 3 min ON, and 5 min OFF.
It will post what it does via MQTT, which I use in OH to add the ALARM functions in case the pump or controller don’t stick to the set intervals.

---

This set-up is an emergency set-up I put together from 23:00 to 02:00 on Saturday night, after I put my wormfarm tank (grey and black water) back into the ground. However, what used to be a “dry” hole, still reaches a water level of 1m, which could rip the tank out again. So I put a sump pump in which lets the water rise for 5 min and then pumps it out for 3 min. My float switch got damaged when the tank popped out after 800mm of rain over three days, hence, I timed the water rise, programmed the Arduino for this purposes, and set the Arduino UniversalTimer accordingly.

Once I have a float switch on the pump, I do not need this setup. However, I always wanted such a UniversalTimer, which I have many uses for.

The OH alarm part is something I wanted to do for year, but this event triggered the ‘must have now’ priority.

I have currently my iPhone in my bed to check when I wake if the pump is running properly. with the currently ‘unreliable’ alarm, I cannot put a buzzer on this to wake us at night in case of a failure.

[rlkoshak (Rich Koshak)]

So ultimately, what you are trying to accomplish here is to get an alert when the Arduino doesn’t report that it’s changed state for too long of a period, meaning something went wrong, correct?

It might be easier to use the Open Door Reminder rule template: Open Reminder [3.3.0;3.4.9). It will be a tiny bit awkward but it would save you a whole lot of coding.

1. I assume you have the JS Scripting add-on installed, IIRC you’ve been experimenting with that.

2. From the /etc/openhab/automation/js folder run npm install openhab_rules_tools.

3. Create a Rule that will be called with the name of the Item that has been ON/OFF for too long as alertItem. You can generate your alert there. Note, this can be a file based Rules DSL or any other valid rule. Theoretically it doesn’t have to be a UI rule using JS Scripting, though I admit I’ve never tested that. I do know that it works with Blockly UI rules for sure if you don’t want to use JS Scripting.

4. Install the Open Door Reminder rule template from the marketplace.

5. Instantiate one instance of the rule to handle the ON case. Initially choose any old Group as the triggering Group (we’ll change that in the next step). Choose “ON” for the “Alert State” and toggle “Invert”. Set the timeout to “PT6M” for six minutes (it probably could be less, it just needs to be longer than 3 minutes). Select the rule you created in 3 as the “Alert Rule”. Set any of the other properties as you see fit.

6. Edit the trigger for the rule and change it to “Item changed” with your ON/OFF Item.

7. Instantiate another instance of the rule to handle the OFF case. This time use “OFF” for the “Alert State”. “PT10M” for ten minutes and all the same settings you made in 5. Update the trigger as you did in step 6.

Notice how all you actually have to code yourself is the alert.

Now the rule you created in step 3 will be called if the Item remains ON for more than 6 minutes or OFF for more than 10 minutes (you could probably get away with less so long as it’s more than 5). You don’t need any timestamps (though it could be handy to capture the last time the Item updated in a DateTime Item), Expire, extra “too_long” Items, or to mess with any complicated logic. All you have to worry about is what to do (e.g. send the alert).

Rule templates; we code them so you don have to! ™

It sounds complicated but step 1 is probably already done, step 2 is available from openhabian-config if you are using openHABian (and it includes lots of timer management libraries you might find useful anyway) and the rest is no more complicated than configuring a Thing or a custom widget.

Anyway, looking at these logs I’m confused. Did you perhaps cut out more logs than you should? I do not see any events on ut_alarm_too_long_on. Without seeing when it changes to OFF and then to ON and correlating it with the “Alarm red triggered” log statement and the events on the ut_notification Item it’s impossible to thread together everything that’s happening and when.

@Max_G

Here the even’ts.log part:

Looking at these events:

• At 18:29 the heatbeat changed to ON.
• Eight minutes later at 18:37, the too_long_on changes to ON, but we don’t know when it was last set to OFF so
• At 18:38 the hearbeat changed to OFF
• Four minutes later at 18:42, the too_long_on changes to OFF. That’s weird as it implies there is some other timer involved here that is driving the setting of this Item to OFF. You don’t show the rules (if any) nor provide any information about what drives the state of ut_notification which, based on these rules, is the actual Item that drives too_long_on.

I really know no more now than I did before.

[Max_G]

I apologise for not providing enough information…

Here the events.log for the 18th hour:

2023-01-31 18:02:18.864 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from UniversalTimer|INFO|DHCP OK to ON
2023-01-31 18:02:18.867 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_on' changed from 2023-01-31T17:54:18.667100+1000 to 2023-01-31T18:02:18.861207+1000
2023-01-31 18:05:18.939 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from ON to OFF
2023-01-31 18:05:18.943 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_off' changed from 2023-01-31T17:57:18.746197+1000 to 2023-01-31T18:05:18.936876+1000
2023-01-31 18:08:18.394 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from OFF to UniversalTimer|INFO|DHCP OK
2023-01-31 18:10:19.061 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from UniversalTimer|INFO|DHCP OK to ON
2023-01-31 18:10:19.073 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_on' changed from 2023-01-31T18:02:18.861207+1000 to 2023-01-31T18:10:19.063247+1000
2023-01-31 18:13:19.137 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from ON to OFF
2023-01-31 18:13:19.150 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_off' changed from 2023-01-31T18:05:18.936876+1000 to 2023-01-31T18:13:19.140350+1000
2023-01-31 18:18:18.639 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from OFF to UniversalTimer|INFO|DHCP OK
2023-01-31 18:18:19.257 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from UniversalTimer|INFO|DHCP OK to ON
2023-01-31 18:18:19.264 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_on' changed from 2023-01-31T18:10:19.063247+1000 to 2023-01-31T18:18:19.258689+1000
2023-01-31 18:21:19.333 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from ON to OFF
2023-01-31 18:21:19.341 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_off' changed from 2023-01-31T18:13:19.140350+1000 to 2023-01-31T18:21:19.333752+1000
2023-01-31 18:26:19.450 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from OFF to ON
2023-01-31 18:26:19.469 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_on' changed from 2023-01-31T18:18:19.258689+1000 to 2023-01-31T18:26:19.451917+1000
2023-01-31 18:28:18.884 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from ON to UniversalTimer|INFO|DHCP OK
2023-01-31 18:28:18.885 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_on' changed from 2023-01-31T18:26:19.451917+1000 to 2023-01-31T18:28:18.872871+1000
2023-01-31 18:29:18.679 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'ut_alarm_no_heartbeat' received command ON
2023-01-31 18:29:18.683 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_alarm_no_heartbeat' changed from OFF to ON
2023-01-31 18:29:19.521 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from UniversalTimer|INFO|DHCP OK to OFF
2023-01-31 18:29:19.525 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_off' changed from 2023-01-31T18:21:19.333752+1000 to 2023-01-31T18:29:19.522419+1000
2023-01-31 18:34:19.657 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from OFF to ON
2023-01-31 18:34:19.659 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_off' changed from 2023-01-31T18:29:19.522419+1000 to 2023-01-31T18:34:19.643863+1000
2023-01-31 18:37:19.719 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from ON to OFF
2023-01-31 18:37:19.728 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_off' changed from 2023-01-31T18:34:19.643863+1000 to 2023-01-31T18:37:19.719183+1000
2023-01-31 18:37:19.843 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'ut_alarm_too_long_on' received command ON
2023-01-31 18:37:19.859 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_alarm_too_long_on' changed from OFF to ON
2023-01-31 18:38:19.119 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from OFF to UniversalTimer|INFO|DHCP OK
2023-01-31 18:38:19.121 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_alarm_no_heartbeat' changed from ON to OFF
2023-01-31 18:42:19.838 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from UniversalTimer|INFO|DHCP OK to ON
2023-01-31 18:42:19.876 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_on' changed from 2023-01-31T18:28:18.872871+1000 to 2023-01-31T18:42:19.840286+1000
2023-01-31 18:42:19.878 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_alarm_too_long_on' changed from ON to OFF
2023-01-31 18:45:19.914 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from ON to OFF
2023-01-31 18:45:19.927 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_off' changed from 2023-01-31T18:37:19.719183+1000 to 2023-01-31T18:45:19.914796+1000
2023-01-31 18:48:19.354 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from OFF to UniversalTimer|INFO|DHCP OK
2023-01-31 18:50:20.034 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from UniversalTimer|INFO|DHCP OK to ON
2023-01-31 18:50:20.045 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_on' changed from 2023-01-31T18:42:19.840286+1000 to 2023-01-31T18:50:20.035196+1000
2023-01-31 18:53:20.110 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from ON to OFF
2023-01-31 18:53:20.111 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_off' changed from 2023-01-31T18:45:19.914796+1000 to 2023-01-31T18:53:20.105606+1000
2023-01-31 18:58:19.598 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from OFF to UniversalTimer|INFO|DHCP OK
2023-01-31 18:58:20.228 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from UniversalTimer|INFO|DHCP OK to ON
2023-01-31 18:58:20.238 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_on' changed from 2023-01-31T18:50:20.035196+1000 to 2023-01-31T18:58:20.227772+1000

The thing:

The MQTT channel:

UID: mqtt:topic:universal_timer
label: MQTT Universal Timer
thingTypeUID: mqtt:topic
configuration: {}
bridgeUID: mqtt:broker:mosquitto
channels:
  - id: ut_notification
    channelTypeUID: mqtt:string
    label: Universal timer notification
    description: ""
    configuration:
      stateTopic: ArgyleCourt/Property/UniversalTimer/Notification

Here the complete rule file related to this universal timer business:

// 20230129 MaxG created

val String LOG_PREFIX = "UniversalTimer."
val mqttTopicRoot = "ArgyleCourt/Property/UniversalTimer/Command/"

rule "UT: Last Reboot"
    when
        Item ut_notification received update
    then
        if (ut_notification.state.toString == "UniversalTimer|INFO|has rebooted")
        {
            logInfo(LOG_PREFIX + "01.01", "--> Universal timer has rebooted :(")
            ut_last_reboot.postUpdate(new DateTimeType())

            // logging controller reboots
            val String ERROR_MESSAGE = LocalDateTime.now().toString + " " + ut_notification.state.toString.replace('|', '_')
            val String CLI_RETURN_CODE = executeCommandLine(Duration.ofSeconds(3), "/bin/sh", "-c", "echo " + ERROR_MESSAGE + " >> /etc/openhab/html/universal_timer.txt; echo -n $?")
            logInfo(LOG_PREFIX + "01.02","Universal Timer message logged to file")

            if (Integer::parseInt(CLI_RETURN_CODE) != 0)
            {
                logInfo(LOG_PREFIX + "01.03","Return code: {}", CLI_RETURN_CODE)
            }

            // red
            Shed_KDL_Colour.sendCommand("10,100,30")

            val mqttActions = getActions("mqtt","mqtt:broker:mosquitto")
            mqttActions.publishMQTT(mqttTopicRoot + "Time_On", "3")

        }

        if (ut_notification.state.toString.contains("|ERROR|"))
        {
            val String ERROR_MESSAGE = LocalDateTime.now().toString + " " + ut_notification.state.toString.replace('|', '_')
            val String CLI_RETURN_CODE = executeCommandLine(Duration.ofSeconds(3), "/bin/sh", "-c", "echo " + ERROR_MESSAGE + " >> /etc/openhab/html/universal_timer.txt; echo -n $?")

            if (Integer::parseInt(CLI_RETURN_CODE) != 0)
            {
                logInfo(LOG_PREFIX + "01.05","Return code: {}", CLI_RETURN_CODE)
            }
        }

        if (ut_notification.state.toString == "UniversalTimer|INFO|DHCP OK")
        {
            ut_alarm_no_heartbeat.postUpdate(OFF)
        }

        if (ut_notification.state.toString == "ON")
        {
            ut_last_on.postUpdate(new DateTimeType())
            // blue
            ut_alarm_too_long_on.postUpdate(OFF)
            Shed_KDL_Colour.sendCommand("220,100,30")
        }

        if (ut_notification.state.toString == "OFF")
        {
            ut_last_off.postUpdate(new DateTimeType())
            ut_alarm_too_long_off.postUpdate(OFF)
            // green
            Shed_KDL_Colour.sendCommand("120,100,30")
        }
end

/*
    Timer status:
    on = working: blue
    off = pausing, but OK: green
    no Ethernet update: red

    ON too long: red
    OFF too long: red

    HSL stands for hue, saturation, and lightness.
    Hue is a degree on the color wheel from 0 to 360. 0 is red, 120 is green, 240 is blue.
    Saturation is a percentage value; 0% means a shade of gray and 100% is the full color.
    Lightness is also a percentage; 0% is black, 100% is white.

    red: 10, 100, 50
    grn: 120, 100, 50
    blu: 220, 100, 50
*/

rule "UT Alarm: ON state duration exceeded"
    when
        Item ut_alarm_too_long_on changed to ON
    then
        // red
        Shed_KDL_Colour.sendCommand("10,100,30")
        logInfo(LOG_PREFIX + "02.01", "Alarm red triggered by ut_alarm_too_long_on")
end


rule "UT Alarm: OFF state duration exceeded"
    when
        Item ut_alarm_too_long_off changed to ON
    then
        // red
        Shed_KDL_Colour.sendCommand("10,100,30")
        logInfo(LOG_PREFIX + "03.01", "Alarm red triggered by ut_alarm_too_long_off")
end


rule "UT Alarm: no heartbeat received"
    when
        Item ut_alarm_no_heartbeat changed to ON
    then
        // red
        Shed_KDL_Colour.sendCommand("10,100,30")
        logInfo(LOG_PREFIX + "04.01", "Alarm red triggered by ut_alarm_no_heartbeat")
end

/* end of file */

And the items:

(That’s all I have)…

[edit 1] Have removed irrelevant log entries from other devices (1st above) and added the merged log (below)

2023-01-31 18:02:18.841 ON
2023-01-31 18:02:18.864 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from UniversalTimer|INFO|DHCP OK to ON
2023-01-31 18:02:18.867 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_on' changed from 2023-01-31T17:54:18.667100+1000 to 2023-01-31T18:02:18.861207+1000
2023-01-31 18:05:18.917 OFF
2023-01-31 18:05:18.939 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from ON to OFF
2023-01-31 18:05:18.943 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_off' changed from 2023-01-31T17:57:18.746197+1000 to 2023-01-31T18:05:18.936876+1000
2023-01-31 18:08:18.367 UniversalTimer|INFO|DHCP OK
2023-01-31 18:08:18.394 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from OFF to UniversalTimer|INFO|DHCP OK
2023-01-31 18:10:19.039 ON
2023-01-31 18:10:19.061 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from UniversalTimer|INFO|DHCP OK to ON
2023-01-31 18:10:19.073 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_on' changed from 2023-01-31T18:02:18.861207+1000 to 2023-01-31T18:10:19.063247+1000
2023-01-31 18:13:19.114 OFF
2023-01-31 18:13:19.137 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from ON to OFF
2023-01-31 18:13:19.150 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_off' changed from 2023-01-31T18:05:18.936876+1000 to 2023-01-31T18:13:19.140350+1000
2023-01-31 18:18:18.611 UniversalTimer|INFO|DHCP OK
2023-01-31 18:18:18.639 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from OFF to UniversalTimer|INFO|DHCP OK
2023-01-31 18:18:19.235 ON
2023-01-31 18:18:19.257 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from UniversalTimer|INFO|DHCP OK to ON
2023-01-31 18:18:19.264 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_on' changed from 2023-01-31T18:10:19.063247+1000 to 2023-01-31T18:18:19.258689+1000
2023-01-31 18:21:19.309 OFF
2023-01-31 18:21:19.333 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from ON to OFF
2023-01-31 18:21:19.341 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_off' changed from 2023-01-31T18:13:19.140350+1000 to 2023-01-31T18:21:19.333752+1000
2023-01-31 18:26:19.431 ON
2023-01-31 18:26:19.450 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from OFF to ON
2023-01-31 18:26:19.469 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_on' changed from 2023-01-31T18:18:19.258689+1000 to 2023-01-31T18:26:19.451917+1000
2023-01-31 18:28:18.856 UniversalTimer|INFO|DHCP OK
2023-01-31 18:28:18.884 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from ON to UniversalTimer|INFO|DHCP OK
2023-01-31 18:28:18.885 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_on' changed from 2023-01-31T18:26:19.451917+1000 to 2023-01-31T18:28:18.872871+1000
2023-01-31 18:29:18.679 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'ut_alarm_no_heartbeat' received command ON
2023-01-31 18:29:18.683 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_alarm_no_heartbeat' changed from OFF to ON
2023-01-31 18:29:18.684 [INFO ] [re.model.script.UniversalTimer.04.01] - Alarm red triggered by ut_alarm_no_heartbeat
2023-01-31 18:29:19.505 OFF
2023-01-31 18:29:19.521 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from UniversalTimer|INFO|DHCP OK to OFF
2023-01-31 18:29:19.525 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_off' changed from 2023-01-31T18:21:19.333752+1000 to 2023-01-31T18:29:19.522419+1000
2023-01-31 18:34:19.627 ON
2023-01-31 18:34:19.657 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from OFF to ON
2023-01-31 18:34:19.659 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_off' changed from 2023-01-31T18:29:19.522419+1000 to 2023-01-31T18:34:19.643863+1000
2023-01-31 18:37:19.702 OFF
2023-01-31 18:37:19.719 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from ON to OFF
2023-01-31 18:37:19.728 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_off' changed from 2023-01-31T18:34:19.643863+1000 to 2023-01-31T18:37:19.719183+1000
2023-01-31 18:37:19.843 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'ut_alarm_too_long_on' received command ON
2023-01-31 18:37:19.859 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_alarm_too_long_on' changed from OFF to ON
2023-01-31 18:37:19.861 [INFO ] [re.model.script.UniversalTimer.02.01] - Alarm red triggered by ut_alarm_too_long_on
2023-01-31 18:38:19.099 UniversalTimer|INFO|DHCP OK
2023-01-31 18:38:19.119 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from OFF to UniversalTimer|INFO|DHCP OK
2023-01-31 18:38:19.121 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_alarm_no_heartbeat' changed from ON to OFF
2023-01-31 18:42:19.822 ON
2023-01-31 18:42:19.838 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from UniversalTimer|INFO|DHCP OK to ON
2023-01-31 18:42:19.876 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_on' changed from 2023-01-31T18:28:18.872871+1000 to 2023-01-31T18:42:19.840286+1000
2023-01-31 18:42:19.878 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_alarm_too_long_on' changed from ON to OFF
2023-01-31 18:45:19.897 OFF
2023-01-31 18:45:19.914 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from ON to OFF
2023-01-31 18:45:19.927 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_off' changed from 2023-01-31T18:37:19.719183+1000 to 2023-01-31T18:45:19.914796+1000
2023-01-31 18:48:19.341 UniversalTimer|INFO|DHCP OK
2023-01-31 18:48:19.354 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from OFF to UniversalTimer|INFO|DHCP OK
2023-01-31 18:50:20.019 ON
2023-01-31 18:50:20.034 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from UniversalTimer|INFO|DHCP OK to ON
2023-01-31 18:50:20.045 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_on' changed from 2023-01-31T18:42:19.840286+1000 to 2023-01-31T18:50:20.035196+1000
2023-01-31 18:53:20.095 OFF
2023-01-31 18:53:20.110 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from ON to OFF
2023-01-31 18:53:20.111 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_off' changed from 2023-01-31T18:45:19.914796+1000 to 2023-01-31T18:53:20.105606+1000
2023-01-31 18:58:19.588 UniversalTimer|INFO|DHCP OK
2023-01-31 18:58:19.598 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from OFF to UniversalTimer|INFO|DHCP OK
2023-01-31 18:58:20.217 ON
2023-01-31 18:58:20.228 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from UniversalTimer|INFO|DHCP OK to ON
2023-01-31 18:58:20.238 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_on' changed from 2023-01-31T18:50:20.035196+1000 to 2023-01-31T18:58:20.227772+1000

[Max_G]

@rlkoshak

Looking at these events:

1. At 18:29 the heatbeat changed to ON.
2. Eight minutes later at 18:37, the too_long_on changes to ON, but we don’t know when it was last set to OFF so
3. At 18:38 the hearbeat changed to OFF
4. Four minutes later at 18:42, the too_long_on changes to OFF. That’s weird as it implies there is some other timer involved here that is driving the setting of this Item to OFF. You don’t show the rules (if any) nor provide any information about what drives the state of ut_notification which, based on these rules, is the actual Item that drives too_long_on.

1. yes
2. yes; and it was set to OFF at:
   2023-01-31 17:30:18.086 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_alarm_too_long_on' changed from ON to OFF Every ut_last_on resets the expiry timer on ut_alarm_too_long_on (which is set to 9 min)
3. yes…
4. yes; 18:37:19.859 changed it to ON, and as there was a MQTT OFF received for ut_last_off

---

Let’s simplify this problem [even better, I figured what went wrong, see bold sentence all the way down and skip this for the time being.]

1. a controller sends ON and OFF commands related to a pump (let’s forget the heartbeat and OFF messages, as their setup is the same as ON)
2. OH receives these in channel, which is linked to the item ut_notification.
3. A rule has an if

        if (ut_notification.state.toString == "ON")
        {
            ut_last_on.postUpdate(new DateTimeType())
            // blue
            ut_alarm_too_long_on.postUpdate(OFF)
            Shed_KDL_Colour.sendCommand("220,100,30")
        }

assigning a timestamp to ut_last_on (not relevant to the problem)
4. and updating ut_alarm_too_long_on with OFF; which resets its associated expiry timer.
5. ut_alarm_too_long_on has an expiry timer of 9 min (I thought I had shown this somewhere, but didn’t)
6. if ut_alarm_too_long_on does not receive an update from the rule above, then expiry sends a 'command=ONto theut_alarm_too_long_on`
7. which triggers a colour bulb to show red (also not relevant to the problem)

What is the problem?

The ut_alarm_too_long_on expires after 9 minutes and triggers the alarm, despite having received an ON via ut_last_on see point 3.

I have now added a log from 17:00 to 19:00 for information, and added an empty line for better readability.

2023-01-31 17:01:17.340 OFF
2023-01-31 17:01:17.352 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from ON to OFF
2023-01-31 17:01:17.360 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_off' changed from 2023-01-31T16:53:17.158594+1000 to 2023-01-31T17:01:17.354497+1000

2023-01-31 17:06:17.461 ON
2023-01-31 17:06:17.474 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from OFF to ON
2023-01-31 17:06:17.479 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_on' changed from 2023-01-31T16:58:17.279173+1000 to 2023-01-31T17:06:17.474353+1000

2023-01-31 17:08:16.898 UniversalTimer|INFO|DHCP OK
2023-01-31 17:08:16.912 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from ON to UniversalTimer|INFO|DHCP OK

2023-01-31 17:09:17.535 OFF
2023-01-31 17:09:17.549 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from UniversalTimer|INFO|DHCP OK to OFF
2023-01-31 17:09:17.554 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_off' changed from 2023-01-31T17:01:17.354497+1000 to 2023-01-31T17:09:17.549675+1000

2023-01-31 17:14:17.657 ON
2023-01-31 17:14:17.672 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from OFF to ON
2023-01-31 17:14:17.681 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_on' changed from 2023-01-31T17:06:17.474353+1000 to 2023-01-31T17:14:17.676770+1000

2023-01-31 17:17:17.732 OFF
2023-01-31 17:17:17.747 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from ON to OFF
2023-01-31 17:17:17.778 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_off' changed from 2023-01-31T17:09:17.549675+1000 to 2023-01-31T17:17:17.751455+1000

2023-01-31 17:18:17.195 UniversalTimer|INFO|DHCP renew OK
2023-01-31 17:18:17.216 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from OFF to UniversalTimer|INFO|DHCP renew OK
2023-01-31 17:19:17.189 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'ut_alarm_no_heartbeat' received command ON
2023-01-31 17:19:17.192 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_alarm_no_heartbeat' changed from OFF to ON
2023-01-31 17:19:17.194 [INFO ] [re.model.script.UniversalTimer.04.01] - Alarm red triggered by ut_alarm_no_heartbeat

2023-01-31 17:22:17.853 ON
2023-01-31 17:22:17.870 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from UniversalTimer|INFO|DHCP renew OK to ON
2023-01-31 17:23:18.272 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'ut_alarm_too_long_on' received command ON
2023-01-31 17:23:18.278 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_alarm_too_long_on' changed from OFF to ON
2023-01-31 17:23:18.280 [INFO ] [re.model.script.UniversalTimer.02.01] - Alarm red triggered by ut_alarm_too_long_on

2023-01-31 17:25:17.928 OFF
2023-01-31 17:25:17.946 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from ON to OFF
2023-01-31 17:25:17.958 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_off' changed from 2023-01-31T17:17:17.751455+1000 to 2023-01-31T17:25:17.949663+1000

2023-01-31 17:28:17.384 UniversalTimer|INFO|DHCP OK
2023-01-31 17:28:17.405 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from OFF to UniversalTimer|INFO|DHCP OK
2023-01-31 17:28:17.408 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_alarm_no_heartbeat' changed from ON to OFF

2023-01-31 17:30:18.049 ON
2023-01-31 17:30:18.069 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from UniversalTimer|INFO|DHCP OK to ON
2023-01-31 17:30:18.083 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_on' changed from 2023-01-31T17:14:17.676770+1000 to 2023-01-31T17:30:18.071026+1000
2023-01-31 17:30:18.086 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_alarm_too_long_on' changed from ON to OFF

2023-01-31 17:33:18.125 OFF
2023-01-31 17:33:18.145 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from ON to OFF
2023-01-31 17:33:18.149 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_off' changed from 2023-01-31T17:25:17.949663+1000 to 2023-01-31T17:33:18.143477+1000

2023-01-31 17:38:17.628 UniversalTimer|INFO|DHCP OK
2023-01-31 17:38:17.647 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from OFF to UniversalTimer|INFO|DHCP OK

2023-01-31 17:38:18.246 ON
2023-01-31 17:38:18.265 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from UniversalTimer|INFO|DHCP OK to ON
2023-01-31 17:38:18.276 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_on' changed from 2023-01-31T17:30:18.071026+1000 to 2023-01-31T17:38:18.268007+1000

2023-01-31 17:41:18.324 OFF
2023-01-31 17:41:18.345 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from ON to OFF
2023-01-31 17:41:18.357 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_off' changed from 2023-01-31T17:33:18.143477+1000 to 2023-01-31T17:41:18.344432+1000

2023-01-31 17:46:18.447 ON
2023-01-31 17:46:18.475 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from OFF to ON
2023-01-31 17:46:18.477 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_on' changed from 2023-01-31T17:38:18.268007+1000 to 2023-01-31T17:46:18.465678+1000

2023-01-31 17:48:17.877 UniversalTimer|INFO|DHCP OK
2023-01-31 17:48:17.897 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from ON to UniversalTimer|INFO|DHCP OK

2023-01-31 17:49:18.523 OFF
2023-01-31 17:49:18.541 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from UniversalTimer|INFO|DHCP OK to OFF
2023-01-31 17:49:18.555 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_off' changed from 2023-01-31T17:41:18.344432+1000 to 2023-01-31T17:49:18.545037+1000

2023-01-31 17:54:18.645 ON
2023-01-31 17:54:18.663 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from OFF to ON
2023-01-31 17:54:18.687 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_on' changed from 2023-01-31T17:46:18.465678+1000 to 2023-01-31T17:54:18.667100+1000

2023-01-31 17:57:18.721 OFF
2023-01-31 17:57:18.743 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from ON to OFF
2023-01-31 17:57:18.759 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_off' changed from 2023-01-31T17:49:18.545037+1000 to 2023-01-31T17:57:18.746197+1000

2023-01-31 17:58:18.124 UniversalTimer|INFO|DHCP OK
2023-01-31 17:58:18.144 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from OFF to UniversalTimer|INFO|DHCP OK

2023-01-31 18:02:18.841 ON
2023-01-31 18:02:18.864 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from UniversalTimer|INFO|DHCP OK to ON
2023-01-31 18:02:18.867 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_on' changed from 2023-01-31T17:54:18.667100+1000 to 2023-01-31T18:02:18.861207+1000

2023-01-31 18:05:18.917 OFF
2023-01-31 18:05:18.939 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from ON to OFF
2023-01-31 18:05:18.943 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_off' changed from 2023-01-31T17:57:18.746197+1000 to 2023-01-31T18:05:18.936876+1000

2023-01-31 18:08:18.367 UniversalTimer|INFO|DHCP OK
2023-01-31 18:08:18.394 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from OFF to UniversalTimer|INFO|DHCP OK

2023-01-31 18:10:19.039 ON
2023-01-31 18:10:19.061 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from UniversalTimer|INFO|DHCP OK to ON
2023-01-31 18:10:19.073 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_on' changed from 2023-01-31T18:02:18.861207+1000 to 2023-01-31T18:10:19.063247+1000

2023-01-31 18:13:19.114 OFF
2023-01-31 18:13:19.137 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from ON to OFF
2023-01-31 18:13:19.150 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_off' changed from 2023-01-31T18:05:18.936876+1000 to 2023-01-31T18:13:19.140350+1000

2023-01-31 18:18:18.611 UniversalTimer|INFO|DHCP OK
2023-01-31 18:18:18.639 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from OFF to UniversalTimer|INFO|DHCP OK

2023-01-31 18:18:19.235 ON
2023-01-31 18:18:19.257 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from UniversalTimer|INFO|DHCP OK to ON
2023-01-31 18:18:19.264 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_on' changed from 2023-01-31T18:10:19.063247+1000 to 2023-01-31T18:18:19.258689+1000

2023-01-31 18:21:19.309 OFF
2023-01-31 18:21:19.333 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from ON to OFF
2023-01-31 18:21:19.341 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_off' changed from 2023-01-31T18:13:19.140350+1000 to 2023-01-31T18:21:19.333752+1000

2023-01-31 18:26:19.431 ON
2023-01-31 18:26:19.450 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from OFF to ON
2023-01-31 18:26:19.469 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_on' changed from 2023-01-31T18:18:19.258689+1000 to 2023-01-31T18:26:19.451917+1000

2023-01-31 18:28:18.856 UniversalTimer|INFO|DHCP OK
2023-01-31 18:28:18.884 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from ON to UniversalTimer|INFO|DHCP OK
2023-01-31 18:28:18.885 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_on' changed from 2023-01-31T18:26:19.451917+1000 to 2023-01-31T18:28:18.872871+1000
2023-01-31 18:29:18.679 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'ut_alarm_no_heartbeat' received command ON
2023-01-31 18:29:18.683 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_alarm_no_heartbeat' changed from OFF to ON
2023-01-31 18:29:18.684 [INFO ] [re.model.script.UniversalTimer.04.01] - Alarm red triggered by ut_alarm_no_heartbeat

2023-01-31 18:29:19.505 OFF
2023-01-31 18:29:19.521 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from UniversalTimer|INFO|DHCP OK to OFF
2023-01-31 18:29:19.525 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_off' changed from 2023-01-31T18:21:19.333752+1000 to 2023-01-31T18:29:19.522419+1000

2023-01-31 18:34:19.627 ON
2023-01-31 18:34:19.657 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from OFF to ON
2023-01-31 18:34:19.659 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_off' changed from 2023-01-31T18:29:19.522419+1000 to 2023-01-31T18:34:19.643863+1000

2023-01-31 18:37:19.702 OFF
2023-01-31 18:37:19.719 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from ON to OFF
2023-01-31 18:37:19.728 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_off' changed from 2023-01-31T18:34:19.643863+1000 to 2023-01-31T18:37:19.719183+1000
2023-01-31 18:37:19.843 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'ut_alarm_too_long_on' received command ON
2023-01-31 18:37:19.859 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_alarm_too_long_on' changed from OFF to ON
2023-01-31 18:37:19.861 [INFO ] [re.model.script.UniversalTimer.02.01] - Alarm red triggered by ut_alarm_too_long_on

2023-01-31 18:38:19.099 UniversalTimer|INFO|DHCP OK
2023-01-31 18:38:19.119 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from OFF to UniversalTimer|INFO|DHCP OK
2023-01-31 18:38:19.121 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_alarm_no_heartbeat' changed from ON to OFF

2023-01-31 18:42:19.822 ON
2023-01-31 18:42:19.838 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from UniversalTimer|INFO|DHCP OK to ON
2023-01-31 18:42:19.876 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_on' changed from 2023-01-31T18:28:18.872871+1000 to 2023-01-31T18:42:19.840286+1000
2023-01-31 18:42:19.878 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_alarm_too_long_on' changed from ON to OFF

2023-01-31 18:45:19.897 OFF
2023-01-31 18:45:19.914 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from ON to OFF
2023-01-31 18:45:19.927 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_off' changed from 2023-01-31T18:37:19.719183+1000 to 2023-01-31T18:45:19.914796+1000

2023-01-31 18:48:19.341 UniversalTimer|INFO|DHCP OK
2023-01-31 18:48:19.354 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from OFF to UniversalTimer|INFO|DHCP OK

2023-01-31 18:50:20.019 ON
2023-01-31 18:50:20.034 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from UniversalTimer|INFO|DHCP OK to ON
2023-01-31 18:50:20.045 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_on' changed from 2023-01-31T18:42:19.840286+1000 to 2023-01-31T18:50:20.035196+1000

2023-01-31 18:53:20.095 OFF
2023-01-31 18:53:20.110 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from ON to OFF
2023-01-31 18:53:20.111 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_off' changed from 2023-01-31T18:45:19.914796+1000 to 2023-01-31T18:53:20.105606+1000

2023-01-31 18:58:19.588 UniversalTimer|INFO|DHCP OK
2023-01-31 18:58:19.598 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from OFF to UniversalTimer|INFO|DHCP OK

2023-01-31 18:58:20.217 ON
2023-01-31 18:58:20.228 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from UniversalTimer|INFO|DHCP OK to ON
2023-01-31 18:58:20.238 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_on' changed from 2023-01-31T18:50:20.035196+1000 to 2023-01-31T18:58:20.227772+1000

2023-01-31 19:01:20.293 OFF
2023-01-31 19:01:20.303 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from ON to OFF
2023-01-31 19:01:20.311 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_off' changed from 2023-01-31T18:53:20.105606+1000 to 2023-01-31T19:01:20.302221+1000

2023-01-31 19:06:20.414 ON
2023-01-31 19:06:20.423 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from OFF to ON
2023-01-31 19:06:20.429 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_on' changed from 2023-01-31T18:58:20.227772+1000 to 2023-01-31T19:06:20.423708+1000

2023-01-31 19:08:19.832 UniversalTimer|INFO|DHCP OK
2023-01-31 19:08:19.860 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from ON to UniversalTimer|INFO|DHCP OK

2023-01-31 19:09:20.488 OFF
2023-01-31 19:09:20.499 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from UniversalTimer|INFO|DHCP OK to OFF
2023-01-31 19:09:20.504 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_off' changed from 2023-01-31T19:01:20.302221+1000 to 2023-01-31T19:09:20.498453+1000

2023-01-31 19:14:20.609 ON
2023-01-31 19:14:20.619 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from OFF to ON
2023-01-31 19:14:20.626 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_on' changed from 2023-01-31T19:06:20.423708+1000 to 2023-01-31T19:14:20.619092+1000

2023-01-31 19:17:20.684 OFF
2023-01-31 19:17:20.692 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from ON to OFF
2023-01-31 19:17:20.713 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_off' changed from 2023-01-31T19:09:20.498453+1000 to 2023-01-31T19:17:20.693390+1000

2023-01-31 19:18:20.076 UniversalTimer|INFO|DHCP OK
2023-01-31 19:18:20.085 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from OFF to UniversalTimer|INFO|DHCP OK

2023-01-31 19:22:20.804 ON
2023-01-31 19:22:20.811 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from UniversalTimer|INFO|DHCP OK to ON
2023-01-31 19:22:20.819 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_on' changed from 2023-01-31T19:14:20.619092+1000 to 2023-01-31T19:22:20.813603+1000

2023-01-31 19:25:20.878 OFF
2023-01-31 19:25:20.886 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from ON to OFF
2023-01-31 19:25:20.893 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_off' changed from 2023-01-31T19:17:20.693390+1000 to 2023-01-31T19:25:20.888398+1000

2023-01-31 19:28:20.314 UniversalTimer|INFO|DHCP OK
2023-01-31 19:28:20.327 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from OFF to UniversalTimer|INFO|DHCP OK

2023-01-31 19:30:20.998 ON
2023-01-31 19:30:21.015 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from UniversalTimer|INFO|DHCP OK to ON
2023-01-31 19:30:21.028 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_on' changed from 2023-01-31T19:22:20.813603+1000 to 2023-01-31T19:30:21.010509+1000

2023-01-31 19:33:21.071 OFF
2023-01-31 19:33:21.083 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from ON to OFF
2023-01-31 19:33:21.088 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_off' changed from 2023-01-31T19:25:20.888398+1000 to 2023-01-31T19:33:21.084116+1000

2023-01-31 19:38:20.555 UniversalTimer|INFO|DHCP OK
2023-01-31 19:38:20.568 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from OFF to UniversalTimer|INFO|DHCP OK

2023-01-31 19:38:21.192 ON
2023-01-31 19:38:21.208 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from UniversalTimer|INFO|DHCP OK to ON
2023-01-31 19:38:21.219 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_on' changed from 2023-01-31T19:30:21.010509+1000 to 2023-01-31T19:38:21.206709+1000

2023-01-31 19:41:21.265 OFF
2023-01-31 19:41:21.280 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from ON to OFF
2023-01-31 19:41:21.292 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_off' changed from 2023-01-31T19:33:21.084116+1000 to 2023-01-31T19:41:21.282523+1000

2023-01-31 19:46:21.385 ON
2023-01-31 19:46:21.400 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from OFF to ON
2023-01-31 19:46:21.411 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_on' changed from 2023-01-31T19:38:21.206709+1000 to 2023-01-31T19:46:21.402496+1000

2023-01-31 19:48:20.796 UniversalTimer|INFO|DHCP OK
2023-01-31 19:48:20.810 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from ON to UniversalTimer|INFO|DHCP OK

2023-01-31 19:49:21.459 OFF
2023-01-31 19:49:21.473 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from UniversalTimer|INFO|DHCP OK to OFF
2023-01-31 19:49:21.481 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_off' changed from 2023-01-31T19:41:21.282523+1000 to 2023-01-31T19:49:21.475703+1000

2023-01-31 19:54:21.579 ON
2023-01-31 19:54:21.594 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from OFF to ON
2023-01-31 19:54:21.605 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_on' changed from 2023-01-31T19:46:21.402496+1000 to 2023-01-31T19:54:21.596255+1000

2023-01-31 19:57:21.653 OFF
2023-01-31 19:57:21.668 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from ON to OFF
2023-01-31 19:57:21.680 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_last_off' changed from 2023-01-31T19:49:21.475703+1000 to 2023-01-31T19:57:21.671397+1000
2
023-01-31 19:58:21.038 UniversalTimer|INFO|DHCP OK
2023-01-31 19:58:21.054 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ut_notification' changed from OFF to UniversalTimer|INFO|DHCP OK

---

When I look at the log, MQTT messages are reliably sent as per schedule (3 min ON, 5 min OFF)

Given the extra bit of log file, we see an alternating change of ut_last_on and ut_last_off

17:23 gets weird. We receive an ON, and the 'ut_alarm_on_too_long` is set to ON 400ms later. Why? The 9 min have not lapsed yet for the expiry timer to trigger.

And by explaining it all and gazing at the log I figured that ut_last_off did not happen!

Why? It is in the rule… it should have appeared as the last thing at 17:22:17.

And because this did not happen, the alarm went off a minute later (as designed).

So why does the if in the rule not trigger? While it usually does… is this an OH code issue?

[rlkoshak (Rich Koshak)]

@Max_G

So why does the if in the rule not trigger? While it usually does… is this an OH code issue?

I assume the if you are referring to is

@Max_G

if (ut_notification.state.toString == "ON")

In that case, for some reason, ut_notification.state.toString == "ON" is false at that point.

But there are lots of if statements in that rule. Perhaps the state is something you are not expecting here. Perhaps the state changed after the rule triggered (you can avoid that problem using newState which is the state that caused the Item to trigger the rule instead of what the Item happens to be now).

One easy way to catch something like this is to make these if/else if statements instead of a series of if statements, or even a switch statement. Then you can define an else or default in cases where none of the conditions match.

[Max_G]

Well, I have changed the controller code to have a separate state topic (as in ON|OFF) separate from the notification topic… and updated the OH channels accordingly.
This seems to have solved the problem (need longer testing as is can take a day to show the initially identified behaviour.

Thank you for pointers and support… which I greatly appreciate.

Yes, I was looking at trying to use ECMAscript, but haven’t done so yet.