- Hi all,
I am currently on OH2.5.11 having recently updated from 2.5.9 where the code in my rule operated as desired.
My objective is easy enough I would like to verify that sonoff devices when requested to be turned off by Alexa actually turn off. The trigger works perfectly so I am leaving that out of this email. The issue is that when I check the voltage status of the sonoff some seconds later I am still seeing a voltage, therefore indicating it is still on, when in fact it is not and has actually switched off. As I said this code used to work in an earlier version, its as if OH is using a cached version of the state from when the rule executed not when the command was issued.
The part of the rule of interest is:
logInfo("sleep.rules", "Turn off water heating devices")
.
try DR_Urn.sendCommand(OFF) catch(Throwable t) logError("Sleep Check", "DR_Urn Error was caught: ", t)
.
.
.
logInfo("sleep.rules", "Check if Urn switched off correctly")
createTimer(now.plusSeconds(4), [|
if (DR_Urn_Voltage.state>5) {
LR_Echo_TTS.sendCommand('The urn did not switch off!')
logInfo("sleep.rules", "Urn did not switch off")
}
logInfo("sleep.rules", "Urn Voltage=" + DR_Urn_Voltage.state.toString)
])
The logs for these entries are:
2020-12-29 22:17:48.572 [INFO ] [e.smarthome.model.script.sleep.rules] - Turn off water heating devices
2020-12-29 22:17:48.602 [INFO ] [e.smarthome.model.script.sleep.rules] - Check if Urn switched off correctly
2020-12-29 22:17:48.621 [ome.event.ItemCommandEvent] - Item 'DR_Urn' received command OFF
.
.
.
2020-12-29 22:17:52.605 [INFO ] [e.smarthome.model.script.sleep.rules] - Urn did not switch off
2020-12-29 22:17:52.606 [INFO ] [e.smarthome.model.script.sleep.rules] - Urn Voltage=217
2020-12-29 22:17:52.607 [ome.event.ItemCommandEvent] - Item 'LR_Echo_TTS' received command The urn did not switch off!
2020-12-29 22:17:52.612 [nt.ItemStatePredictedEvent] - LR_Echo_TTS predicted to become The urn did not switch off!
2020-12-29 22:17:52.617 [vent.ItemStateChangedEvent] - LR_Echo_TTS changed from to The urn did not switch off!
2020-12-29 22:17:57.506 [vent.ItemStateChangedEvent] - LR_Echo_TTS changed from The urn did not switch off! to
2020-12-29 22:18:17.770 [vent.ItemStateChangedEvent] - DR_Urn_Voltage changed from 217 to 0
As ypu can see the state of the voltage drop is not being reported for about 30 seconds after the device was switched off. Is it possible that something changed in OH2 to slow down the event being registered? or am I barking up the wrong tree, and need to look at the sonoff sending the voltage off state faster?
I have noticed that sometimes the logs say an alexa command has been said and it happens around 30 seconds later, not sure if its a similar delay going on.
I have done some further research:
Here is my item definition for the retrieving the voltage
Number DR_Urn_Voltage "Voltage" (chartpersist, gPOWVoltage) { mqtt="<[MQTT:tasmota/DR_Urn/tele/SENSOR:state:JSONPATH($.ENERGY.Voltage)]" }
Using MQTT.fx I monitored the MQTT messages seen and the timings when you switch off a sonoff module, there are four messages in the sequence.
- cmnd/POWER OFF
- stat/RESULT
- stat/POWER
- tele/SENSOR {“Time”:“2020-12-30T12:09:21”,“ENERGY”:{“TotalStartTime”:“2019-03-30T18:45:44”,“Total”:731.415,“Yesterday”:0.001,“Today”:0.134,“Power”:0,“ApparentPower”:0,“ReactivePower”:0,“Factor”:0.00,“Voltage”:0,“Current”:0.000}}
The 4th SENSOR message is returned from the sonoff module around 2 seconds after the state is switched.
With that in mind I am now thinking as this is my bedtime routine and it switches off a load of MQTT items, that the initial SENSOR message with the new voltage state is getting lost in the noise. The reason the state changes is due most likely to the processing of a periodic SENSOR message sent by the sonoff device.
A couple of solutions come to mind, slow down the switch off routine to reduce the number of messages that are seen at this time, although to be honest this would require ongoing management so not my favoured workaround. The most elegant I can come up with is to look at the QOS options in MQTT and see if something better can be done there to ensure reliability. I suspect that will bring a new set of problems to the table 
I guess I also need to look at running the MQTT binding in debug mode to see if the drop is because it never received it or if it was unable to process it.
I will continue my investigation.
Regards
Paul