OH3: HomeMatic: light turns on when sending "OFF" after a communications failure

Setup, Configuration and Use Scripts & Rules
1

Maybe I’m getting it all wrong since I’m not the most experienced OH user. Certainly the scripts doc, especially the part about postUpdate vs. sendCommand is super confusing to me.

So here it goes: I have a OH3 installation with the HomeMatic binding, speaking to a CCU3. A motion event turns on a certain light via a rule:

2021-02-03 17:39:42.074 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Et_Bewegungsmelder_1_Motion' changed from OFF to ON
2021-02-03 17:39:42.088 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'Et_Licht_1_State' received command ON
2021-02-03 17:39:42.094 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'Et_Licht_1_State' predicted to become ON
2021-02-03 17:39:42.099 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Et_Licht_1_State' changed from OFF to ON

And the light turns on. Well, this time, a few seconds later a communication error about the light device was logged and the item “restarted”:

2021-02-03 17:39:46.118 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'homematic:HM-LC-Sw1PBU-FM:3014F711A0001F9A49922BFF:NEQ0275927' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR)
2021-02-03 17:39:46.133 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'homematic:HM-LC-Sw1PBU-FM:3014F711A0001F9A49922BFF:NEQ0275927' changed from OFFLINE (COMMUNICATION_ERROR) to ONLINE
2021-02-03 17:39:46.146 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Et_Licht_1_State' changed from ON to OFF

See, the Light state was reset to OFF, although it was still burning!

Then, after 5 minutes, when the light was supposed to be turned off via a rule, this happened:

2021-02-03 17:44:42.091 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'Et_Licht_1_State' received command OFF
2021-02-03 17:44:42.094 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'Et_Licht_1_State' predicted to become OFF
2021-02-03 17:44:42.279 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Et_Licht_1_State' changed from OFF to ON

The rule definitely set the light to off via sendCommand(OFF), but instead it turned on, so it stayed on! That’s not the desired result…

This is the whole rule:

var Timer ETLichtTimer = null
var String TAG = "et_bewegungslicht"

// Schaltet das Licht neben der Eingangstür für 300 Sekunden ein.
rule "Eingangstuer Licht an bei Bewegung"
when
    Item Et_Bewegungsmelder_1_Motion changed to ON
then
    if(ETLichtTimer !== null)
        ETLichtTimer.cancel()

    var String sun_state = LocalSun_Phase_SunPhaseName.state
    if(sun_state != "DAYLIGHT" && sun_state != "SUN_RISE" && sun_state != "SUN_SET")
    {
    	Et_Licht_1_State.sendCommand(ON)
        ETLichtTimer = createTimer(now.plusSeconds(300), [ |
            Et_Licht_1_State.sendCommand(OFF)
        ])
    }
end

If I understand it correctly, this is what happened: the connection error reset the internal state of the light to OFF although the light was still on (physically). And the subsequent sendCommand(OFF) for some reason translated into a ON command, perhaps because some internal state comparison went foul.

What can I do about it? Is this a bug? Is it expected behaviour?

2

As far as I know from the binding code, it should not change the device state after a reconnect. After the connection to the CCU has restored the binding queries the CCU for all item states.

Can you enable the TRACE logging for org.openhab.binding.homematic and try to reproduce the problem? After that please attach the relevant part of openhab.log here. I would also recommend to add some log output to your rule. Then you can see when it is fired and what it does.

3

The rule did command OFF, as hoped.
( the prediction logged is a follow-on from the command, not very relevant here.)
200mS later, presumably in response to being prodded by the command, the CCU reports that is in fact (still) ON.
The time delay suggests the misinformation has come from the CCU not the binding, but we’ll see what your TRACE logs says.

4

Thank you, I’ve enabled TRACE now on the Homematic binding. As soon as it happens again I’ll post the logs.

Meanwhile I’m thinking about how to trigger this condition manually, to reproduce the situation.