Hi, I’m seeing some strange behavior in my system, and have a question regarding “latest” system state vs what I see in my IDE event logs.
I have a contact that exhibits bounce on a garage door, and I am seeing the wrong state be reported to my smartapps (triggering incorrect notifications). When I look at the IDE event log, the “order” of reported state is wrong, although the timestamps seem to be correct. To clarify (look @ log example below), when the door closed the last IDE log’s “close” timestamp 5:56:19.498 is shown BEFORE the “open” timestamp 5:56:19.493 – i.e. out of order. Also the current state of the contact in IDE is shown as “open”, which is wrong.
So I’m guessing that events “close” together (100’s of ms) may be incorrectly handled by the ST system? Can anyone confirm this or give me suggestions on a workaround (other than getting a different physical device)? If it matters, I’m using the Xiaomi Door/Window Sensor as DTH. Maybe I can customize it somehow to add a debounce feature internal to the DTH?
the cloud-logging process itself can report in unexpected sequence, sometimes with extreme latency. After several years of casual observation, I think but do not know, that multiple hosts are logging separate events, that get compiled in a single reporting list, out of order by seconds, minutes and perhaps hours+days on extreme occasions.
So are you still certain that you see contact bounce?
And yes it does appear that smartthings can then act on the out-of-sequence events as-is, which can (for example) leave the lights on.
Workaround is to have a cleanup routine, or otherwise implement fault-tolerance.
My history suggests that other common cause of bad current state is, bad mesh, repair it, add repeaters, etc.
I am assuming that the state change from this contact within a few 100msec (close/close/open in this log example) is due to contact bounce, but don’t know that for sure… but can’t think of what else it could be.
Cleanup routine… could you elaborate? Within the DTH or as some separate thing. I’m not sure how to “force” the state of the contact to the correct value.
The nature of asynchronous messaging, particularly when messages are processed in the cloud, is that occasionally messages can arrive or be processed out of order.
In some cases, if you know certain details about the messaging pattern and don’t mind adding latency to the event processing, you might be able to buffer and sort messages before applying them to avoid out of order processing, but usually it is not worth the effort. For devices that support refresh, you maybe able to mitigate the problem by scheduling a refresh periodically (or in some cases if/when you detect that events were applied out of order).
There’s no guaranteed forced sequencing with a mesh topology. It’s not common, but it happens, and most often with contact sensors where a door is quickly opened and then closed.
The first message, the open, starts out along the route. But say the second repeater along that route is busy or fails to send a message for whatever reason.
Meanwhile, the second message, the closed, has to take a different route because the first one was busy with the opening. As it happens, that one has no delays along the route and so it arrives at the hub first.
Think of it like two bicycle messengers leaving from the same office to go to the same destination . The first one to leave takes route A but runs into a detour or holdup along the path. The second one to leave takes route B and ends up arriving at the destination first.
So it can happen. Especially if you’re trying to send two messages from the same device in less than 30 seconds.
A lot of devices do have a Debounce built into their processing where they throw away the second input if it occurs too quickly. But that occurs in the firmware of the device itself, not on the hub or the cloud.
And of course the cloud layer adds another whole level of potential problems.
I’m not saying any of that is what’s going on here, I’m just saying that it can happen.
What is the source of the timestamp values that are shown in the IDE log? Are they inserted by the device or its DTH, my hub or somewhere up in the ST cloud?
I’m wondering if some form of debounce added to the DTH would fix things (not that I know how to code that yet).
Maybe I just need to spend a few bucks on a new garage door sensor, but was hoping the spare contact sensor I had lying around could suit my needs… but the false readings are too annoying for that.
