"Debounce a Contact Sensor" in RM

📐 Rule Machine®
21

@bravenel -- So I tried this "busy" approach to fix a problem I'm having with my Driveway lights flashing on/off when a rule fires twice. Didn't work. The rule is firing SO QUICKLY in succession, that I'm seeing this in the log:

app:361 2019-09-19 09:11:40.460 info Action: Set Busy to true
app:361 2019-09-19 09:11:40.455 info Action: IF (Variable Busy(false) = true FALSE) Exit Rule (skipped)
app:361 2019-09-19 09:11:40.454 info Action: Set Busy to true
app:361 2019-09-19 09:11:40.448 info Action: IF (Variable Busy(false) = true FALSE) Exit Rule (skipped)

It is setting the variable to true at 9:11:40:454, then checking and finding it false at 9:11:40:455.

BTW -- the "motion active" that triggered this rule fired twice with a difference of 12ms. So I'm not quite getting "atomic" behavior for this variable. I'm on 2.1.4.121 BTW.

22

No time in 12 ms to do anything, so you are getting two instances of the rule running. Has nothing to do with atomic.

What device and what driver is causing this? This is a driver issue that needs to be addressed.

23

I've got two very different situations going on here, both firing rules more than once.

1 - "Arrive via Garage": I have two contact sensors on my garage doors (they are old Aeon door sensors using the Generic Zwave contact sensor driver). If either opens, and my interior lights are off, they trigger a 5 minute "wait for the laundry door to open" (same sensor here). If the door opens, the kitchen lights come on. I have the "busy" variable deboucing in there. This rule just triggered 2 times, and the "wait for the door to open" fired 4 times! The sensors here are on my upstairs hub, and the rule and light are on my downstairs hub (the HubConnect server, using Event sockets). The log for this rule firing is included below. Note: on the client hub, the logs show the Laundry door opening twice at that time, 1ms apart.

2 - Driveway motion (and a similar porch motion rule). These use EcoLink motion sensors using the Generic Z-wave motion sensor driver. They are fed into the Zone Motion Controller app, which turns the lights on or off with motion change. I have 2 sensors (garage, porch). They are fed into 2 separate Zones: both -> garage, porch -> porch (so the porch sensor is in both). When there is motion near the garage, the garage lights should come on. If there is motion at the porch, both garage and porch lights come on. The garage motion sensor and garage light are on my upstairs hub, the porch motion sensor and porch light are on the downstairs hub. The garage light rule runs on the upstairs hub (but references the porch motion sensor shared from the server -- that isn't being used in my tests). The porch light rule runs on the downstairs hub, referencing the garage light which is shared from the client.

I can remove the Zone stuff with the trade off of making the rules a bit more complex. But the kitchen light only uses contact sensors, and is having issues. The garage and porch lights only use motion, and are having issues also.

I'm happy to send you anything that might be helpful in terms of logs, config dumps, whatever. If you want to take this off the board you can email me directly.

I need to get this fixed because these are pretty much all my automations, they aren't working, and it is getting very frustrating.

Here are a couple of log snippets:

dev:1322019-09-19 10:34:25.826 infoKitchen - Pendant Lights switch is on
app:1702019-09-19 10:34:25.290 infoAction: Set Busy to false --> delayed: 0:00:02
app:1702019-09-19 10:34:25.284 infoAction: END-IF
app:1702019-09-19 10:34:25.270 infoAction: Set Busy to false --> delayed: 0:00:02
app:1702019-09-19 10:34:25.266 infoAction: Set Busy to false --> delayed: 0:00:02
app:1702019-09-19 10:34:25.261 infoAction: END-IF
app:1702019-09-19 10:34:25.249 infoAction: Set Busy to false --> delayed: 0:00:02
app:1702019-09-19 10:34:25.246 infoAction: END-IF
app:1702019-09-19 10:34:25.245 infoAction: END-IF
app:1702019-09-19 10:34:25.122 infoAction: IF (Laundry door open TRUE) On: Kitchen - Pendant Lights
app:1702019-09-19 10:34:25.117 infoAction: IF (Laundry door open TRUE) On: Kitchen - Pendant Lights
app:1702019-09-19 10:34:25.099 infoAction: IF (Laundry door open TRUE) On: Kitchen - Pendant Lights
app:1702019-09-19 10:34:25.086 infoAction: IF (Laundry door open TRUE) On: Kitchen - Pendant Lights
app:1702019-09-19 10:34:24.998 infoWait over: Laundry door contact open
app:1702019-09-19 10:34:24.905 infoWait over: Laundry door contact open
app:1702019-09-19 10:34:24.861 infoWait over: Laundry door contact open
app:1702019-09-19 10:34:24.859 infoWait over: Laundry door contact open
app:1702019-09-19 10:34:19.440 infoAction: Wait for events: Laundry door open --> timeout: 0:05:00
app:1702019-09-19 10:34:19.440 infoAction: Wait for events: Laundry door open --> timeout: 0:05:00
app:1702019-09-19 10:34:19.410 infoAction: IF (Kitchen Lights(off) is off(T) AND
Laundry door closed(T) [TRUE]) THEN
app:1702019-09-19 10:34:19.410 infoAction: IF (Kitchen Lights(off) is off(T) AND
Laundry door closed(T) [TRUE]) THEN
app:1702019-09-19 10:34:19.306 infoAction: Set Busy to true
app:1702019-09-19 10:34:19.301 infoAction: IF (Variable Busy(false) = true FALSE) Exit Rule (skipped)
app:1702019-09-19 10:34:19.290 infoAction: Set Busy to true
app:1702019-09-19 10:34:19.284 infoAction: IF (Variable Busy(false) = true FALSE) Exit Rule (skipped)
app:1702019-09-19 10:34:19.201 infoArrive via Garage Triggered
app:1702019-09-19 10:34:19.182 infoArrive via Garage: Garage door 1 contact open
app:1702019-09-19 10:34:19.173 infoArrive via Garage Triggered
app:1702019-09-19 10:34:19.161 infoArrive via Garage: Garage door 1 contact open

Could RM have a truly atomic option for a rule that says "Only run one instance of this rule at a time"? That would likely solve all my problems, and obviate the need for this attempted debouncing hack.

24

Why do you have to use two sensors, instead of one?

25

Sorry -- I was unclear here. I have two garage doors, one sensor on each. The rule triggers if either door opens.

26

In the logs above, is the rule running on the same hub as the contact sensor?

You need the rule on the same hub as the contact sensor. By using hubConnect in the middle, you've introduced a variable into the timing that evidently is not going to work right.

Basically, you can't debounce something between two hubs via hubConnect.

27

No, the contact sensors are all on the client and the rule and light are on the server. I'll change that and let you know if it looks better.

28

Didn't quite do it. The rule seems to only be triggering once, which is great. But the "wait for the door to open" is getting 2 "open" triggers itself, and still trying to turn on the lights twice:

app:4492019-09-19 11:53:44.879 infoAction: END-IF
app:4492019-09-19 11:53:44.874 infoAction: END-IF
app:4492019-09-19 11:53:44.787 infoAction: IF (Laundry door open TRUE) On: Kitchen - Pendant Lights
app:4492019-09-19 11:53:44.783 infoAction: IF (Laundry door open TRUE) On: Kitchen - Pendant Lights
app:4492019-09-19 11:53:44.562 infoWait over: Laundry door contact open
app:4492019-09-19 11:53:44.549 infoWait over: Laundry door contact open
dev:3252019-09-19 11:53:44.402 infoLaundry door was opened
dev:3252019-09-19 11:53:44.400 infoLaundry door was opened
app:4492019-09-19 11:53:37.612 infoAction: Wait for events: Laundry door open --> timeout: 0:05:00
app:4492019-09-19 11:53:37.587 infoAction: IF (Laundry door closed(T) [TRUE]) THEN
app:4492019-09-19 11:53:37.551 infoAction: IF (Variable Busy(false) = true FALSE) Exit Rule (skipped)
app:4492019-09-19 11:53:37.465 infoArrive via Garage Triggered
app:4492019-09-19 11:53:37.448 infoArrive via Garage: Garage Door 2 contact open
dev:3232019-09-19 11:53:37.314 infoGarage Door 2 was opened

Next I suppose I'll try a virtual sensor that is triggered by the laundry door (but debounced in its rule), and then put THAT in as the sensor being waited on. Really seems kind of unnecessary. If "debouncing" sensors is such an issue, perhaps there should be some way to set this in the device itself? A general "Ignore changes that happen withing X ms" option? Because I seem to be hitting this for these contact sensors and my motion sensors.

29

I wonder if you couldn't create an effective debounce using a virtual switch or even global variable and two rules. Those double reports 2 msecs apart are a new problem we haven't seen before.

30

It's just too fast. I tried creating a virtual button that gets pushed via a "debounced" rule when the door opens. The button still got pushed twice, the wait ended twice, and the light got turned on twice:

app:4492019-09-19 12:23:07.053 infoDelay Over: Set Busy to false --> delayed: 0:00:02
app:4492019-09-19 12:23:07.016 infoDelay Over: Set Busy to false --> delayed: 0:00:02
app:4502019-09-19 12:23:06.766 infoDelay Over: Set Busy to false --> delayed: 0:00:02
app:4502019-09-19 12:23:06.749 infoDelay Over: Set Busy to false --> delayed: 0:00:02
app:4492019-09-19 12:23:04.934 infoAction: Set Busy to false --> delayed: 0:00:02
app:4492019-09-19 12:23:04.932 infoAction: Set Busy to false --> delayed: 0:00:02
app:4492019-09-19 12:23:04.930 infoAction: END-IF
app:4492019-09-19 12:23:04.928 infoAction: END-IF
app:4492019-09-19 12:23:04.878 infoAction: IF (Laundry door open TRUE) On: Kitchen - Pendant Lights
app:4492019-09-19 12:23:04.869 infoAction: IF (Laundry door open TRUE) On: Kitchen - Pendant Lights
app:4492019-09-19 12:23:04.799 infoWait over: Debounced Contact Button pushed 1
app:4492019-09-19 12:23:04.780 infoWait over: Debounced Contact Button pushed 1
app:4502019-09-19 12:23:04.663 infoAction: Set Busy to false --> delayed: 0:00:02
dev:4182019-09-19 12:23:04.647 infoDebounced Contact Button button 1 was pushed
app:4502019-09-19 12:23:04.623 infoAction: Set Busy to false --> delayed: 0:00:02
dev:4182019-09-19 12:23:04.613 infoDebounced Contact Button button 1 was pushed
app:4502019-09-19 12:23:04.604 infoAction: Push button 1 on Debounced Contact Button
app:4502019-09-19 12:23:04.593 infoAction: Push button 1 on Debounced Contact Button
app:4502019-09-19 12:23:04.547 infoAction: Set Busy to true
app:4502019-09-19 12:23:04.547 infoAction: Set Busy to true
app:4502019-09-19 12:23:04.542 infoAction: IF (Variable Busy(false) = true FALSE) Exit Rule (skipped)
app:4502019-09-19 12:23:04.542 infoAction: IF (Variable Busy(false) = true FALSE) Exit Rule (skipped)
app:4502019-09-19 12:23:04.478 infoDebounced Laundry Door Triggered
app:4502019-09-19 12:23:04.478 infoDebounced Laundry Door Triggered
app:4502019-09-19 12:23:04.466 infoDebounced Laundry Door: Laundry door contact open
app:4502019-09-19 12:23:04.466 infoDebounced Laundry Door: Laundry door contact open
dev:3252019-09-19 12:23:04.375 infoLaundry door was opened
dev:3252019-09-19 12:23:04.373 infoLaundry door was opened
dev:3232019-09-19 12:23:03.048 infoGarage Door 2 was closed
app:4492019-09-19 12:22:58.430 infoAction: Wait for events: Debounced Contact Button button 1 pushed --> timeout: 0:05:00
app:4492019-09-19 12:22:58.409 infoAction: IF (Laundry door closed(T) [TRUE]) THEN
app:4492019-09-19 12:22:58.350 infoAction: Set Busy to true
app:4492019-09-19 12:22:58.346 infoAction: IF (Variable Busy(false) = true FALSE) Exit Rule (skipped)
app:4492019-09-19 12:22:58.277 infoArrive via Garage Triggered
app:4492019-09-19 12:22:58.264 infoArrive via Garage: Garage Door 2 contact open
dev:3232019-09-19 12:22:58.162 infoGarage Door 2 was opened

A truly atomic "only run one instance of this rule" option would REALLY be nice. Right now things are a mess for me. I don't remember having this issue until recently. I'm running 2.1.4.130 now, and have options to roll back to 2.1.4.121 (which I tried earlier and it wasn't any better), or 2.0.8.113 (but I think that doesn't have RM 4).

What I can send you that would help someone there figure out what is going on?

31

You need something with two states, like a switch or a Global Variable.

32

Still can't get it. My virtual switch just turns itself on twice, which triggers the wait twice. I just can get this debouncing thing to work at all.

Here is what my rule looks like for turning on my "debounced" virtual switch:

DBswitch
DBswitch.png861×253 17.2 KB

And this is what I get in my log:

dev:4192019-09-19 13:05:08.031 infoDB Laundry Door was turned on
dev:4192019-09-19 13:05:08.029 infoDB Laundry Door was turned on
app:4502019-09-19 13:05:08.020 infoAction: On: DB Laundry Door
app:4502019-09-19 13:05:08.007 infoAction: On: DB Laundry Door
app:4502019-09-19 13:05:07.961 infoAction: Set Busy to true
app:4502019-09-19 13:05:07.961 infoAction: Set Busy to true
app:4502019-09-19 13:05:07.956 infoAction: IF (Variable Busy(false) = true FALSE) Exit Rule (skipped)
app:4502019-09-19 13:05:07.956 infoAction: IF (Variable Busy(false) = true FALSE) Exit Rule (skipped)
app:4502019-09-19 13:05:07.859 infoDebounced Laundry Door Triggered
app:4502019-09-19 13:05:07.858 infoDebounced Laundry Door Triggered
app:4502019-09-19 13:05:07.847 infoDebounced Laundry Door: Laundry door contact open
app:4502019-09-19 13:05:07.847 infoDebounced Laundry Door: Laundry door contact open
dev:3252019-09-19 13:05:07.732 infoLaundry door was opened
dev:3252019-09-19 13:05:07.726 infoLaundry door was opened

33

Did you try a global variable?

I have a contact sensor here that sometimes does the same thing. I'll play around with this and see if I can come up with something.

34

Tried the global, but it didn't behave any differently. With two instances of the rule running at the same time, they both check "is this rule busy" before either of them get to the line to set the flag "this rule is busy". Doesn't really matter what that flag is. An atomic "check this flag and set it true" test is needed.

Please put "only run 1 instance of this rule at a time" on the wish list for RM updates.

I look forward to seeing what you come up with.

35

How close together in time are the two events from your contact sensor?

36

It is also interesting that the "wait for event" line itself is executed once, but I get TWO "wait over" lines.

Here is a list of the times for my laundry door triggereing:

dev:3252019-09-19 13:51:20.759 infoLaundry door was closed
dev:3252019-09-19 13:51:20.753 infoLaundry door was closed
dev:3252019-09-19 13:51:12.815 infoLaundry door was opened
dev:3252019-09-19 13:51:12.807 infoLaundry door was opened
dev:3252019-09-19 13:51:03.206 infoLaundry door was closed
dev:3252019-09-19 13:51:03.164 infoLaundry door was closed
dev:3252019-09-19 13:50:59.901 infoLaundry door was opened
dev:3252019-09-19 13:50:59.897 infoLaundry door was opened

Looks like the openings are 4-8ms and the close are 6-42ms for these few instances.

A "don't report another event for 100ms" filter would be reasonable (user settable, of course). I certainly can't open and close the door that fast!

37

With 3 msecs between events, it is not conceivable that something could be committed to a database in that time frame to prevent the second event. This may well be the case for any approach taken to prevent it.

38

@aaiyar, @lightingdan

Untitled
Untitled.png1438×907 43.7 KB

39

Is it reasonable to assume the duplication of events is Zwave related (multi-path communication)?

I'd be surprised to hear that this kind of issue hasn't arisen before. I know that when programming with shared memory there are ways to lock access to memory, and I'd expect that with a database there are similar things that can be done (lock the record, check it, modify it, unlock it) so that an atomic "test and set" operation should be possible. If RM has such a feature I can't find it. In any case, am I really the only person having this kind of problem?

40

Is this a Z-Wave contact sensor?