Contact bounce - lost events?

Setup, Configuration and Use Beginners
,
1

Hello, I’m new to OpenHab so still examined things which can be simple and clear to you.
I have rule:

rule "light"
when
    Item sw1 changed from OPEN to CLOSED
    or Item sw1 changed from CLOSED to OPEN
then
    logWarn("gt", "begin")
    lock.lock()        
    logWarn("gt", "begin2")
    try {
        light.sendCommand(if(light.state == ON) OFF else ON)
    } finally{
        logWarn("gt", "end")
        lock.unlock()
    }
  end

with items:

Contact sw1 "sw1" { gpio="pin:19" }
Switch light "light" { gpio="pin:18" }

So I want toggle light on contact change.
(Please don’t be surprised why I control light that way, this is simplified from multi-way wall switch, see in Multiway switch )
I’m using OpenHab2, updated few days ago.

Contact sw1 controls light and at beginning: sw1 closed = light on (sw1 open = light off)
Problem isn’t contact bounce, but that it sometimes lost synchronization and function reverse.

If I try to stress it and achieve contact bounce, then the log appear as:
(Initial state: light - ON, sw1 - CLOSED)

23:52:21.657 [INFO ] [marthome.event.ItemStateChangedEvent] - sw1 changed from CLOSED to OPEN
23:52:21.678 [INFO ] [marthome.event.ItemStateChangedEvent] - sw1 changed from OPEN to CLOSED
23:52:21.702 [WARN ] [rg.eclipse.smarthome.model.script.gt] - begin
23:52:21.712 [INFO ] [marthome.event.ItemStateChangedEvent] - sw1 changed from CLOSED to OPEN
23:52:21.721 [WARN ] [rg.eclipse.smarthome.model.script.gt] - begin
23:52:21.727 [WARN ] [rg.eclipse.smarthome.model.script.gt] - begin2
23:52:21.737 [WARN ] [rg.eclipse.smarthome.model.script.gt] - begin
23:52:21.784 [INFO ] [smarthome.event.ItemCommandEvent ] - Item ‘light’ received command OFF
23:52:21.785 [WARN ] [rg.eclipse.smarthome.model.script.gt] - end
23:52:21.803 [WARN ] [rg.eclipse.smarthome.model.script.gt] - begin2
23:52:21.827 [INFO ] [marthome.event.ItemStateChangedEvent] - light changed from ON to OFF
23:52:21.862 [INFO ] [smarthome.event.ItemCommandEvent ] - Item ‘light’ received command ON
23:52:21.860 [WARN ] [rg.eclipse.smarthome.model.script.gt] - end
23:52:21.875 [WARN ] [rg.eclipse.smarthome.model.script.gt] - begin2
23:52:21.926 [INFO ] [smarthome.event.ItemCommandEvent ] - Item ‘light’ received command ON
^----- here arrived again ON and so from now the function is reversed (contact closed = light off)
23:52:21.928 [INFO ] [marthome.event.ItemStateChangedEvent] - light changed from OFF to ON
^^— this I probably need to arrive before previous ItemCommandEvent
23:52:21.933 [WARN ] [rg.eclipse.smarthome.model.script.gt] - end
23:52:23.147 [INFO ] [marthome.event.ItemStateChangedEvent] - sw1 changed from CLOSED to OPEN
^----- again closed to open?
23:52:23.155 [INFO ] [marthome.event.ItemStateChangedEvent] - sw1 changed from OPEN to CLOSED
23:52:23.185 [WARN ] [rg.eclipse.smarthome.model.script.gt] - begin
23:52:23.197 [WARN ] [rg.eclipse.smarthome.model.script.gt] - begin
23:52:23.198 [WARN ] [rg.eclipse.smarthome.model.script.gt] - begin2
23:52:23.211 [INFO ] [marthome.event.ItemStateChangedEvent] - sw1 changed from OPEN to CLOSED
^---- again open to closed?
23:52:23.219 [WARN ] [rg.eclipse.smarthome.model.script.gt] - begin
23:52:23.246 [INFO ] [smarthome.event.ItemCommandEvent ] - Item ‘light’ received command OFF
23:52:23.250 [WARN ] [rg.eclipse.smarthome.model.script.gt] - end
23:52:23.291 [WARN ] [rg.eclipse.smarthome.model.script.gt] - begin2
23:52:23.316 [INFO ] [marthome.event.ItemStateChangedEvent] - light changed from ON to OFF
23:52:23.345 [WARN ] [rg.eclipse.smarthome.model.script.gt] - end
23:52:23.344 [INFO ] [smarthome.event.ItemCommandEvent ] - Item ‘light’ received command ON
23:52:23.368 [WARN ] [rg.eclipse.smarthome.model.script.gt] - begin2
23:52:23.383 [INFO ] [marthome.event.ItemStateChangedEvent] - light changed from OFF to ON
23:52:23.387 [INFO ] [smarthome.event.ItemCommandEvent ] - Item ‘light’ received command OFF
23:52:23.387 [WARN ] [rg.eclipse.smarthome.model.script.gt] - end
23:52:23.393 [INFO ] [marthome.event.ItemStateChangedEvent] - light changed from ON to OFF
23:52:24.682 [INFO ] [marthome.event.ItemStateChangedEvent] - sw1 changed from CLOSED to OPEN
23:52:24.709 [WARN ] [rg.eclipse.smarthome.model.script.gt] - begin
23:52:24.728 [WARN ] [rg.eclipse.smarthome.model.script.gt] - begin2
23:52:24.768 [INFO ] [smarthome.event.ItemCommandEvent ] - Item ‘light’ received command ON
23:52:24.768 [WARN ] [rg.eclipse.smarthome.model.script.gt] - end
23:52:24.826 [INFO ] [marthome.event.ItemStateChangedEvent] - light changed from OFF to ON

I can continue switching and light is toggled by contact change, but function is reversed.
For me it looks like if i guard/lock around the sendCommand, it didn’t guard against the real “ItemStateChangedEvent”?

Can I avoid this situation?
Or should I try find another solution and use toggle?

2

I would say that a queued run of the rule has happened in-between a previous run sending a command to the light, and that command propagating a “received command” event back to the item. In other words, a repeat run of the rule based its action on the current state of the light which is slightly out of date.

I think you can avoid that by applying a short delay before releasing the lock at the end of the thread, say Thread::sleep(100), to allow time for the light command to complete. You’ll still get a burst of off-on, but sequence will be kept.

The “proper” fix is to de-bounce the contacts. You might do it electronically at source, add R-C filter usually.
Or you could do it with rules, so that extra changes within say 100mS are ignored completely rather than queued.

In this case I think you will have multiple switches? You might have a rule for changes of those triggering a change in a virtual switch Item, and starting a short global timer to lock out further changes to the virtual switch. The virtual switch then controls the actual light, via a separate rule which ignores triggers while the timer is running…

Again in your particular case, I think you had just such a ‘virtual’ switch to allow control from a web interface? You can re-use that for debouncing as well.