button signal debounce

[Olivierbkk]

Hi,

Sorry I have one more issue, I am using push buttons that seem to not be very good but unfortunately they match my home installation.

When I press once on the push button I get a double and then a single press instead of only a single press: [24/09/2022, 15:41:35] [RPi] Entrance light: Programmable Switch Event: Double Press [24/09/2022, 15:41:36] [RPi] Entrance light: Programmable Switch Event: Single Press [24/09/2022, 15:41:37] [RPi] raspberrypi Entrance: On changed from true to false [24/09/2022, 15:41:37] [RPi] raspberrypi Entrance: set dutyCycle from 0 to 255

My buttons are set like this: { "device": "button", "name": "Entrance light", "gpio": 4, "pulse": 500 },

I see on the wiki that you debounce the input by 20ms, perhaps it's not long enough for my buttons, can you explain me how to change this to be longer?

Thanks in advance

[ebaauw]

A button device doesn't have pulse setting, see Wiki. Unfortunately, the settings dialogue in the Homebridge UI isn't able to show repeated settings conditionally, but the Homebridge log shows a warning:

[9/24/2022, 12:55:54 PM] [RPi] warning: config.json: hosts[x]: devices[x]: pulse: invalid key

Indeed, as mentioned in the WIki, the debounce timeout currently is hardcoded to 20ms. I might make it configurable in a device setting, but never had a trigger to do so, and it's kinda tedious to include it in the UI settings dialogue. Same for the timeouts for Double Press and Long Press.

To change the debouce timeout, edit line 205 in RpiService.js: https://github.com/ebaauw/homebridge-rpi/blob/19f57ef8fe19adac7882e78080b139cc0265b736/lib/RpiService.js#L196-L207 Note that this will affect all input GPIO devices.

For debugging, run Homebridge in DEBUG mode, and set the LogLevel of the RPi accessory to 3 in Eve. You should then see a debug message for each notification from pigpiod with bitmap of the GPIO states, and a message for each debounced button press or release. It's similar to this (for a dht device):

[9/24/2022, 1:10:25 PM] [RPi] pi10: gpio map: [.... .... .... .x.. .... .... .... ....]
[9/24/2022, 1:10:25 PM] [RPi] pi10: gpio map: [.... .... .... .xx. .... .... .... ....]
[9/24/2022, 1:10:25 PM] [RPi] pi10 Dht Temperature: gpio 17: high after 103
[9/24/2022, 1:10:25 PM] [RPi] pi10: gpio map: [.... .... .... .x.. .... .... .... ....]
[9/24/2022, 1:10:25 PM] [RPi] pi10: gpio map: [.... .... .... .xx. .... .... .... ....]
[9/24/2022, 1:10:25 PM] [RPi] pi10 Dht Temperature: gpio 17: high after 134
[9/24/2022, 1:10:25 PM] [RPi] pi10: gpio map: [.... .... .... .x.. .... .... .... ....]
[9/24/2022, 1:10:25 PM] [RPi] pi10: gpio map: [.... .... .... .xx. .... .... .... ....]
[9/24/2022, 1:10:25 PM] [RPi] pi10 Dht Temperature: gpio 17: high after 81
[9/24/2022, 1:10:25 PM] [RPi] pi10: gpio map: [.... .... .... .x.. .... .... .... ....]
[9/24/2022, 1:10:25 PM] [RPi] pi10: gpio map: [.... .... .... .xx. .... .... .... ....]
[9/24/2022, 1:10:25 PM] [RPi] pi10 Dht Temperature: gpio 17: high after 75
[9/24/2022, 1:10:25 PM] [RPi] pi10: gpio map: [.... .... .... .x.. .... .... .... ....]
[9/24/2022, 1:10:25 PM] [RPi] pi10: gpio map: [.... .... .... .xx. .... .... .... ....]
[9/24/2022, 1:10:25 PM] [RPi] pi10 Dht Temperature: gpio 17: high after 80

The timings are actually reported by pigpiod, so there's no impact by any network delay in the communication between Homebridge RPi and pigpiod.

[Olivierbkk]

Thanks, it works if I set the debounce timeout to somewhere above 60ms but then you need to be pressing the button and hold it a bit longer but not too long which is not natural.

FYI I have 5 light switches connected to the RPi and it seems also that they are not all equal... some seem to behave better than other.

There may be two solutions but I am not sure if any is possible without too much trouble: 1 - I only need single press to turn on/off the lights, would it be possible to disable the double press and long press? it's okay if it is so for all buttons in my case. 2 - In the previous setup, the input card was reading a state change of on/off switches (rising or falling) to activate what we could compare with a single press (the light switches were normal on/off switches). Is that doable? (I would then replace back the push button by the old on/off switches).

[Olivierbkk]

UPDATE

I edited the RpiService.js file and commented these lines (I also changed the last value to 100 which seems to reduce the light switch latency and put back the debounce timeout to 20ms).

      if (value) { // button released
        if (this.pressed != null) {
          const duration = now - this.pressed
          this.debug('button released after %d msec', duration)
          this.pressed = null
//          if (duration > 1000) {
//            this.values.buttonevent =
//              this.Characteristics.hap.ProgrammableSwitchEvent.LONG_PRESS
//          } else if (this.singlePressTimeout != null) {
//            clearTimeout(this.singlePressTimeout)
//            delete this.singlePressTimeout
//            this.released = null
//            this.values.buttonevent =
//              this.Characteristics.hap.ProgrammableSwitchEvent.DOUBLE_PRESS
//          } else {
            this.released = now
            this.singlePressTimeout = setTimeout(() => {
              this.released = null
              delete this.singlePressTimeout
              this.values.buttonevent =
                this.Characteristics.hap.ProgrammableSwitchEvent.SINGLE_PRESS
            }, 100)
//          }
        }
      } else { // button pressed

It is pretty reliable now as I do not have fake double press any more.

I understand that in this case if there is a plugin update I will probably need to modify the code again. Is that correct? Unless you could have the double press and long press optional in the UI? (just a suggestion)

I am still curious if solution 2 in my previous post is also possible....?

[ebaauw]

Thanks, it works if I set the debounce timeout to somewhere above 60ms but then you need to be pressing the button and hold it a bit longer but not too long which is not natural.

The gpio event is emitted only after the debounce timeout. Maybe I could emit it the on the first change and then ignore changes until the debounce timeout.

I edited the RpiService.js file and commented these lines

Instead of commenting out these lines, could you simply change the 1000 (the hardcoded Long Press timeout) to a ridiculously large number (Infinity) and the 500 (the hardcoded Double Press timeout) to 0? That would be similar to making the timeouts configurable.

I also changed the last value to 100 which seems to reduce the light switch latency

The singlePressTimeout delays sending a Single Press to HomeKit for 500ms, waiting to see if a Double Press should be issued instead. If you set this to 0, the wait will be over immediately and the code to issue a Double Press is never reached.

and put back the debounce timeout to 20ms It is pretty reliable now as I do not have fake double press any more.

I suppose you still get multiple Single Press events in short succession on a single push button press/release. That would be OK if your automations are idempotent (e.g. turn a light on), but wouldn’t work for others (e.g. a toggle a light).

In the previous setup, the input card was reading a state change of on/off switches

Sorry, I don’t understand. Previous setup of what? What is an input card?

Do I understand that you have a stateful rocker switch, which you would like to expose as a Stateless Programmable Switch, issuing a Single Press on each state change? That’s technically feasible, but it would be a new device type.

[Olivierbkk]

The gpio event is emitted only after the debounce timeout. Maybe I could emit it the on the first change and then ignore changes until the debounce timeout.

Yes that may help

Instead of commenting out these lines, could you simply change the 1000 (the hardcoded Long Press timeout) to a ridiculously large number (Infinity) and the 500 (the hardcoded Double Press timeout) to 0? That would be similar to making the timeouts configurable.

I tried but it was less reliable, some press didn't get registered and still got double press. so finally I went back to the same as my previous post

I suppose you still get multiple Single Press events in short succession on a single push button press/release. That would be OK if your automations are idempotent (e.g. turn a light on), but wouldn’t work for others (e.g. a toggle a light).

I do get multiple single press events but it still works. Note that I use this to toggle a light using a shortcut in my mac and it works, I suppose having the single press events so close to each other that homekit sees or processes only one.

Sorry, I don’t understand. Previous setup of what? What is an input card?

My home had a "no name" smart home system, 10+ years old, obsolete and broken. There was an input card in that system for the switches

Do I understand that you have a stateful rocker switch, which you would like to expose as a Stateless Programmable Switch, issuing a Single Press on each state change? That’s technically feasible, but it would be a new device type.

Yes that's the idea no 2 in my second post.

Let me explain a bit more my setup: in each light switch box there is a 12VDC relay controlled by the RPi that replaces the "mechanical" switch. The mechanical switch is connected to an input on the Rpi. There is a 4 wires telephone cable between the RPI and all the light swicth boxes (2 wires for the switch, 2 wires for the relay). The advantage is that if the RPi dies, I can hard wire the light 220V phase to the mechanical switch in the switch box so at least I can still operate the light. For this it is better to use normal light switches instead of push buttons. Anyway I already replaced all the toggle switches by push buttons to work with your plugin.

[Olivierbkk]

I think I finally found the debounce problem cause, it is not from the switches, there was a defective ground wire between the Pi and the optocoupler isolation board for the inputs....

I found that when I started connecting the door sensors, I had repeated triggers, about 10 per second even though the input were continuously connected (see below).

I have put the RpiService.js back to the original and it seems like it works well now. I will monitor and let you know if the issue comes back but I am pretty confident it will be OK.

Very sorry to have bothered you with that... it was a hardware issue.

I am still interested in the rocker switch whenever you have the time to work on it though.

---

Here is an extract of the log I was getting: [28/09/2022, 20:27:01] [RPi] Entrance: set Contact Sensor State from 1 to 0 [28/09/2022, 20:27:01] [RPi] Entrance: set Contact Sensor State from 0 to 1 [28/09/2022, 20:27:01] [RPi] Entrance: set Times Opened from 4499 to 4500 [28/09/2022, 20:27:01] [RPi] Entrance: set Contact Sensor State from 1 to 0 [28/09/2022, 20:27:01] [RPi] Entrance: set Contact Sensor State from 0 to 1 [28/09/2022, 20:27:01] [RPi] Entrance: set Times Opened from 4500 to 4501 [28/09/2022, 20:27:01] [RPi] Entrance: set Contact Sensor State from 1 to 0 [28/09/2022, 20:27:01] [RPi] Entrance: set Contact Sensor State from 0 to 1 [28/09/2022, 20:27:01] [RPi] Entrance: set Times Opened from 4501 to 4502 [28/09/2022, 20:27:01] [RPi] Entrance: set Contact Sensor State from 1 to 0 [28/09/2022, 20:27:01] [RPi] Entrance: set Contact Sensor State from 0 to 1 [28/09/2022, 20:27:01] [RPi] Entrance: set Times Opened from 4502 to 4503 [28/09/2022, 20:27:01] [RPi] Entrance: set Contact Sensor State from 1 to 0 [28/09/2022, 20:27:01] [RPi] Entrance: set Last Activation from 1908228 seconds to 1908229 seconds [28/09/2022, 20:27:01] [RPi] Entrance: set Contact Sensor State from 0 to 1 [28/09/2022, 20:27:01] [RPi] Entrance: set Times Opened from 4503 to 4504 [28/09/2022, 20:27:01] [RPi] Entrance: set Contact Sensor State from 1 to 0 [28/09/2022, 20:27:01] [RPi] Entrance: set Contact Sensor State from 0 to 1 [28/09/2022, 20:27:01] [RPi] Entrance: set Times Opened from 4504 to 4505 [28/09/2022, 20:27:01] [RPi] Entrance: set Contact Sensor State from 1 to 0 [28/09/2022, 20:27:01] [RPi] Entrance: set Contact Sensor State from 0 to 1 [28/09/2022, 20:27:01] [RPi] Entrance: set Times Opened from 4505 to 4506 [28/09/2022, 20:27:01] [RPi] Entrance: set Contact Sensor State from 1 to 0 [28/09/2022, 20:27:01] [RPi] Entrance: set Contact Sensor State from 0 to 1 [28/09/2022, 20:27:01] [RPi] Entrance: set Times Opened from 4506 to 4507 [28/09/2022, 20:27:01] [RPi] Entrance: set Contact Sensor State from 1 to 0 [28/09/2022, 20:27:02] [RPi] Entrance: set Contact Sensor State from 0 to 1 [28/09/2022, 20:27:02] [RPi] Entrance: set Times Opened from 4507 to 4508

[ebaauw]

v1.5.0 adds support for rocker device and new config parameters debounceTimeout for GPIO input devices, and doublePressTimeout and LongPressTimeout for button devices.

[Olivierbkk]

wow that was fast!

The new Rocker device is working, I am trying it on one of the switches for now attached to GPIO 7.

I get this in the log when I restart the HB server:

[01/10/2022, 08:01:05] [RPi] Initializing RPi platform...
[01/10/2022, 08:01:05] [RPi] homebridge-rpi v1.5.0, node v16.17.1, homebridge v1.5.0, homebridge-lib v5.6.8
[01/10/2022, 08:01:05] [RPi] warning: config.json: hosts[0]: devices[1]: pulse: invalid key
[01/10/2022, 08:01:05] [RPi] warning: config.json: hosts[0]: devices[3]: pulse: invalid key
[01/10/2022, 08:01:05] [RPi] warning: config.json: hosts[0]: devices[5]: pulse: invalid key
[01/10/2022, 08:01:05] [RPi] warning: config.json: hosts[0]: devices[7]: doublePressTimeout: invalid key
[01/10/2022, 08:01:05] [RPi] warning: config.json: hosts[0]: devices[7]: longPressTimeout: invalid key
[01/10/2022, 08:01:05] [RPi] warning: config.json: hosts[0]: devices[7]: pulse: invalid key
[01/10/2022, 08:01:05] [RPi] warning: config.json: hosts[0]: devices[9]: pulse: invalid key
[01/10/2022, 08:01:05] [RPi] warning: config.json: hosts[0]: devices[11]: pulse: invalid key

I have set the parameters for the rocker from the UI (I didn't touch any of the other devices setting) and here is what's in the config file:

                    "devices": [
                        {
                            "device": "light",
                            "name": "Gate",
                            "gpio": 8,
                            "reversed": true
                        },
                        {
                            "device": "button",
                            "name": "Gate light",
                            "gpio": 25,
                            "pulse": 500
                        },
                        {
                            "device": "light",
                            "name": "Garage",
                            "gpio": 9,
                            "reversed": true
                        },
                        {
                            "device": "button",
                            "name": "Garage light",
                            "gpio": 27,
                            "pulse": 500
                        },
                        {
                            "device": "light",
                            "name": "Entrance",
                            "gpio": 10,
                            "reversed": true
                        },
                        {
                            "device": "button",
                            "name": "Entrance light",
                            "gpio": 4,
                            "pulse": 500
                        },
                        {
                            "device": "light",
                            "name": "Dining area",
                            "gpio": 15,
                            "reversed": true
                        },
                        {
                            "device": "rocker",
                            "name": "Dining area light",
                            "gpio": 7,
                            "doublePressTimeout": 0,
                            "longPressTimeout": 0,
                            "pulse": 500
                        },
                        {
                            "device": "light",
                            "name": "Office",
                            "gpio": 17,
                            "reversed": true
                        },
                        {
                            "device": "button",
                            "name": "Office light",
                            "gpio": 11,
                            "pulse": 500
                        },
                        {
                            "device": "contact",
                            "name": "Gate",
                            "gpio": 14,
                            "reversed": false
                        },
                        {
                            "device": "contact",
                            "name": "Entrance",
                            "gpio": 22,
                            "reversed": false,
                            "pulse": 2523
                        },
                        {
                            "device": "contact",
                            "name": "Left zone",
                            "gpio": 23
                        },
                        {
                            "device": "contact",
                            "name": "Right zone",
                            "gpio": 24
                        },
                        {
                            "device": "switch",
                            "name": "Gate open-close",
                            "gpio": 18,
                            "reversed": true,
                            "pulse": 500
                        }
                    ]

I also noticed the latency seems to be longer between the trigger and the light to turn on than when I manually changed it to 100ms in the RpiService.js file. That's just a feeling but I wonder if it is related to the warning in the log.

The server seems to be restarting a lot faster also and i get less of these: [01/10/2022, 08:29:05] [RPi] warning: heartbeat 0, drift 2585 I can tell you have been working hard!

[Olivierbkk]

UPDATE

I manually deleted the pulse parameter from the config file for one of the button (just to try) and while I was at it I set the double and long press time out to 0 in the UI:

                        {
                            "device": "button",
                            "name": "Gate light",
                            "gpio": 25,
                            "doublePressTimeout": 0,
                            "longPressTimeout": 0
                        },

now I get these warnings, the one for device (1) has disappeared and it is still working.

[01/10/2022, 08:35:10] [RPi] warning: config.json: hosts[0]: devices[3]: pulse: invalid key
[01/10/2022, 08:35:10] [RPi] warning: config.json: hosts[0]: devices[5]: pulse: invalid key
[01/10/2022, 08:35:10] [RPi] warning: config.json: hosts[0]: devices[7]: doublePressTimeout: invalid key
[01/10/2022, 08:35:10] [RPi] warning: config.json: hosts[0]: devices[7]: longPressTimeout: invalid key
[01/10/2022, 08:35:10] [RPi] warning: config.json: hosts[0]: devices[7]: pulse: invalid key
[01/10/2022, 08:35:10] [RPi] warning: config.json: hosts[0]: devices[9]: pulse: invalid key
[01/10/2022, 08:35:10] [RPi] warning: config.json: hosts[0]: devices[11]: pulse: invalid key

Should I go ahead and delete the pulse line in config file for all the device I get a warning?

What about device (7) single and double press time out invalid keys?

[Olivierbkk]

UPDATE 2

when I ask Siri to turn off the light it turns off device (7) and turns it back on after about 1 second. I wll try to detail this more later if you need. (leaving for the week end now)

[ebaauw]

Please see the Wiki and the description in the UI setting what settings are supported for what GPIO device type. As I mentioned before, unfortunately the UI cannot enforce this, but Homebridge RPi will ignore any invalid setting, issuing a warning. Note that the array index starts at 0.

I also noticed the latency seems to be longer between the trigger and the light to turn on than when I manually changed it to 100ms in the RpiService.js file. That's just a feeling but I wonder if it is related to the warning in the log.

Check the log to understand whether it’s the latency between a button action and Homebridge RPi issuing the press event, or between the press event and the lights reacting. If the latter: make sure your home hubs are up to date, power cycle them, and double-check they maintain a connection to Homebridge, using netstat on the Homebridge server. If it’s the former: with Log Level set to 2, and running Homebridge in DEBUG mode, Homebridge RPi now logs detailed debug messages of the GPIO state changes and timeouts. Set the press timeouts to 0 for button or use rocker, to disable Double Press and Long Press, so Homebridge RPi no longer needs to use timers, to wait for the next press or release before issuing a Single Press or Long Press.

[Olivierbkk]

Hi, I will check the latency sometimes this week but before I need to get the basics working. I have weird thing happening since the last update, there are some spontaneous events happening after I turn off or on (especially off) a light, here is an example where I turned on and off the light via the home app, I get a single press event from that switch.

[02/10/2022, 19:41:57] [RPi] raspberrypi Dining area: On changed from false to true
[02/10/2022, 19:41:57] [RPi] raspberrypi Dining area: set dutyCycle from 255 to 0
[02/10/2022, 19:42:02] [RPi] raspberrypi Dining area: On changed from true to false
[02/10/2022, 19:42:02] [RPi] raspberrypi Dining area: set dutyCycle from 0 to 255
[02/10/2022, 19:42:02] [RPi] Dining area light: Programmable Switch Event: Single Press
[02/10/2022, 19:42:05] [RPi] raspberrypi Dining area: On changed from false to true
[02/10/2022, 19:42:05] [RPi] raspberrypi Dining area: set dutyCycle from 255 to 0

here is another one where I turned off the dining area and a myriad of things happened

[02/10/2022, 19:47:38] [RPi] raspberrypi Dining area: On changed from true to false
[02/10/2022, 19:47:38] [RPi] raspberrypi Dining area: set dutyCycle from 0 to 255
[02/10/2022, 19:47:38] [RPi] Gate: set Contact Sensor State from 1 to 0
[02/10/2022, 19:47:38] [RPi] Gate: set Last Activation from 2250066 seconds to 2251466 seconds
[02/10/2022, 19:47:38] [RPi] Left zone: set Contact Sensor State from 1 to 0
[02/10/2022, 19:47:38] [RPi] Left zone: set Last Activation from 2250066 seconds to 2251466 seconds
[02/10/2022, 19:47:39] [RPi] Gate light: Programmable Switch Event: Long Press
[02/10/2022, 19:47:39] [RPi] Garage light: Programmable Switch Event: Long Press
[02/10/2022, 19:47:39] [RPi] Entrance light: Programmable Switch Event: Long Press
[02/10/2022, 19:47:39] [RPi] Office light: Programmable Switch Event: Long Press

I need to check the hardware, there might be something funny but that started to happen exactly after I updated the plugin (perhaps a coincidence).

[Olivierbkk]

I rolled back to v1.4.1 of the plugin without touching anything in the wiring at all and everythings works back as before. So I am afraid it might be software this time.

In the log below I cycled two lights using the buttons and all is good. It also works fine from the home app. No other spontaneous events any more.

[03/10/2022, 08:23:45] [RPi] Entrance light: Programmable Switch Event: Single Press
[03/10/2022, 08:23:46] [RPi] raspberrypi Entrance: On changed from false to true
[03/10/2022, 08:23:46] [RPi] raspberrypi Entrance: set dutyCycle from 255 to 0
[03/10/2022, 08:23:47] [RPi] Entrance light: Programmable Switch Event: Single Press
[03/10/2022, 08:23:48] [RPi] raspberrypi Entrance: On changed from true to false
[03/10/2022, 08:23:48] [RPi] raspberrypi Entrance: set dutyCycle from 0 to 255
[03/10/2022, 08:23:52] [RPi] Gate light: Programmable Switch Event: Single Press
[03/10/2022, 08:23:53] [RPi] raspberrypi Gate: On changed from false to true
[03/10/2022, 08:23:53] [RPi] raspberrypi Gate: set dutyCycle from 255 to 0
[03/10/2022, 08:23:54] [RPi] Gate light: Programmable Switch Event: Single Press
[03/10/2022, 08:23:55] [RPi] raspberrypi Gate: On changed from true to false
[03/10/2022, 08:23:55] [RPi] raspberrypi Gate: set dutyCycle from 0 to 255

[ebaauw]

Please capture any attach a debug log file, running Homebridge in DEBUG mode and with Log Level set to 3. I need to see the Homebridge startup and the weird behaviour of v1.5.0.

[Olivierbkk]

see attached file, I am not sure if this is what you want... let me know

rename the file to .rtf before opening as I couldn't upload a .rtf file

Note that I trimmed a few things not related to RPi plugin and some which I believe were confidentiality related

log.txt

[ebaauw]

You tried to start Homebridge while it was already running. so the file doesn't contain anything useful. Please capture a plain txt file - no word, rtf or whatever. See https://github.com/ebaauw/homebridge-hue/wiki/FAQ#homebridge for details how to capture a debug log file.

[Olivierbkk]

See the attached file, here is exactly what I did:

• restarted
• activated the dining light rocker to turn on the dining light, waited a few seconds, activated the rocker to turn off
• pressed the gate light button once to turn on the gate light, waited a few seconds, pressed the button again to turn it off
• opened the front door, waited a few seconds (for my dog to go out) and closed it back (it still shows open although the door is closed, this sensor is working normally with the previous plugin version and shows the correct status)
• turned on the gate light from the home app, waited a few seconds, turned it off from the home app (the dining light came on by itself for a short while even though I DID NOT TOUCH THE DINING LIGHT SWITCH)
• Downloaded the log file

That's all I did, you can see that there a many more events.

homebridge.log.txt

[Olivierbkk]

In case it helps, here is a log using v1.4.1 of the plugin. See the attached file, here is exactly what I did:

• restarted
• pressed the gate light button once to turn on the gate light, waited a few seconds, pressed the button again to turn it off
• opened the front door, waited a few seconds (for my dog to go out) and closed it back
• turned on the gate light from the home app, waited a few seconds, turned it off from the home app
• Downloaded the log file

Everything works normally.

homebridge.log-2.txt

[ebaauw]

See the attached file

Thanks, that's very useful.

I think you might still have a hardware issue, maybe related to grounding.

[04/10/2022, 07:56:21] [RPi] raspberrypi: gpio map: [.... x.xx x... .x.. .x.. x... ...x ....], tick: 2148422316
[04/10/2022, 07:56:21] [RPi] raspberrypi: gpio map: [.... x..x .... .x.. .... .... .... ....], tick: 2148422321
[04/10/2022, 07:56:21] [RPi] raspberrypi: gpio map: [.... x.xx x... .x.. .x.. x... ...x ....], tick: 2148422326

The Pi dropped GPIO pins 5, 8, 11, 14, 20, and 22 for 5 microseconds.
In v1.4.1 this doesn't cause a problem, since the debouncing would ignore initial pin changes. But with the changed debounce logic in v1.5.0 the first change is honoured, and subsequent changes are ignored. Bad idea in retrospect.

[04/10/2022, 07:59:49] [RPi] raspberrypi: gpio map: [.... x.xx x... .x.. .x.. x... ...x ....], tick: 2356722153
[04/10/2022, 07:59:49] [RPi] Dining area light: gpio 7: low after 114430 µs
[04/10/2022, 07:59:49] [RPi] Dining area light: gpio 7: rocker flipped to low after 114 ms
[04/10/2022, 07:59:49] [RPi] Dining area light: Programmable Switch Event: Single Press
[04/10/2022, 07:59:49] [RPi] raspberrypi: gpio map: [.... x.xx x... .x.. .x.. x... x..x ....], tick: 2356722158
[04/10/2022, 07:59:49] [RPi] Dining area light: gpio 7: high after 5 µs
[04/10/2022, 07:59:49] [RPi] Dining area light: gpio 7: debouncing
...
[04/10/2022, 07:59:56] [RPi] raspberrypi: gpio map: [.... x.xx x... .x.. .x.. x... ...x ....], tick: 2356997294
[04/10/2022, 07:59:56] [RPi] Dining area light: gpio 7: low after 5655 µs
[04/10/2022, 07:59:56] [RPi] Dining area light: gpio 7: debouncing
[04/10/2022, 07:59:56] [RPi] raspberrypi: gpio map: [.... x.xx x... .x.. .x.. x... x..x ....], tick: 2357017244
[04/10/2022, 07:59:56] [RPi] Dining area light: gpio 7: high after 25605 µs
[04/10/2022, 07:59:56] [RPi] Dining area light: gpio 7: rocker flipped to high after 26 ms
[04/10/2022, 07:59:56] [RPi] Dining area light: Programmable Switch Event: Single Press
[04/10/2022, 07:59:56] [RPi] raspberrypi: gpio map: [.... x.xx x... .x.. .x.. x... ...x ....], tick: 2357017384
[04/10/2022, 07:59:56] [RPi] Dining area light: gpio 7: low after 140 µs
[04/10/2022, 07:59:56] [RPi] Dining area light: gpio 7: debouncing

GPIO pin 7 seems hanging, changing state over 300 times in 200ms, causing a dozen Single Press events. However, it seems that Homebridge RPi takes a good six seconds to process these?!

04/10/2022, 07:59:50] [RPi] raspberrypi: data: {"type":"Buffer","data": [...]}

Homebridge RPi received a lot of these GPIO changes in a single buffer.

[04/10/2022, 07:59:56] [RPi] warning: heartbeat 385, drift 6328
[04/10/2022, 07:59:56] [RPi] warning: heartbeat 386, drift 5360
[04/10/2022, 07:59:56] [RPi] warning: heartbeat 387, drift 4432
[04/10/2022, 07:59:57] [RPi] warning: heartbeat 388, drift 3461
[04/10/2022, 07:59:57] [RPi] warning: heartbeat 389, drift 2472
[04/10/2022, 07:59:57] [RPi] warning: heartbeat 390, drift 1484
[04/10/2022, 07:59:57] [RPi] warning: heartbeat 391, drift 499

This indicates the NodeJS process was blocked (not processing events), causing the heartbeat to be delayed by 6 seconds. It would seem that handling the incoming buffer somehow causes this. I don't understand how this can be; as far as I'm aware, no synchronous I/O is happening, other than maybe issuing the log messages.

Are you running Homebridge RPi in a child bridge? If not, it might be another plugin doing synchronous I/O and blocking NodeJS, but the timing of this is too suspicious to be coincidental.

[Olivierbkk]

It might indeed be a hardware problem again as it seems to be working if I basically disconnect everyting from the pi (looking at the log I don't see the 5microsec drops any more).

Let me find out where the problem is coming from.

anyway the system has become very sensitive with the update.

[Olivierbkk]

I narrowed it down to the output relay board, whenever this is powered with 5VDC I get the drops. I tried powering from external supply or through the Pi, it's the same.

The relay board also has optocouplers to isolate the signal to the pi so it should not happen.

I am still getting these kind of erratic behavior every now and then (an example below):

[04/10/2022, 17:56:18] [RPi] raspberrypi Dining area: On changed from true to false
[04/10/2022, 17:56:18] [RPi] raspberrypi Dining area: set dutyCycle from 0 to 255
[04/10/2022, 17:56:18] [RPi] raspberrypi Dining area: set duty cycle to 255
[04/10/2022, 17:56:18] [RPi] raspberrypi: command PWM (5) 15 255 ""
[04/10/2022, 17:56:18] [RPi] raspberrypi: request: {"type":"Buffer","data":[5,0,0,0,15,0,0,0,255,0,0,0,0,0,0,0]}
[04/10/2022, 17:56:18] [RPi] raspberrypi: data: {"type":"Buffer","data":[5,0,0,0,15,0,0,0,255,0,0,0,0,0,0,0]}
[04/10/2022, 17:56:18] [RPi] raspberrypi: command PWM (5) => 0
[04/10/2022, 17:56:18] [RPi] raspberrypi: data: {"type":"Buffer","data":[126,0,0,0,212,59,162,68,111,135,7,9,127,0,0,0,217,59,162,68,127,207,135,11]}
[04/10/2022, 17:56:18] [RPi] raspberrypi: gpio map: [.... x..x .... .x.. .... .... .... ....], tick: 1151482836
[04/10/2022, 17:56:18] [RPi] Gate light: gpio 25: low after 109590113 µs
[04/10/2022, 17:56:18] [RPi] Gate light: button pressed after 109590 ms
[04/10/2022, 17:56:18] [RPi] Entrance light: gpio 4: low after 109590113 µs
[04/10/2022, 17:56:18] [RPi] Entrance light: button pressed after 109590 ms
[04/10/2022, 17:56:18] [RPi] Office light: gpio 11: low after 109590113 µs
[04/10/2022, 17:56:18] [RPi] Office light: button pressed after 109590 ms
[04/10/2022, 17:56:18] [RPi] Gate: gpio 14: low after 109590113 µs
[04/10/2022, 17:56:18] [RPi] Gate: gpio 14: low
[04/10/2022, 17:56:18] [RPi] Left zone: gpio 23: low after 109590113 µs
[04/10/2022, 17:56:18] [RPi] Left zone: gpio 23: low
[04/10/2022, 17:56:18] [RPi] raspberrypi: gpio map: [.... x.xx x... .x.. .x.. x... ...x ....], tick: 1151482841
[04/10/2022, 17:56:18] [RPi] Gate light: gpio 25: high after 5 µs
[04/10/2022, 17:56:18] [RPi] Gate light: gpio 25: debouncing
[04/10/2022, 17:56:18] [RPi] Entrance light: gpio 4: high after 5 µs
[04/10/2022, 17:56:18] [RPi] Entrance light: gpio 4: debouncing
[04/10/2022, 17:56:18] [RPi] Office light: gpio 11: high after 5 µs
[04/10/2022, 17:56:18] [RPi] Office light: gpio 11: debouncing
[04/10/2022, 17:56:18] [RPi] Gate: gpio 14: high after 5 µs
[04/10/2022, 17:56:18] [RPi] Gate: gpio 14: debouncing
[04/10/2022, 17:56:18] [RPi] Left zone: gpio 23: high after 5 µs
[04/10/2022, 17:56:18] [RPi] Left zone: gpio 23: debouncing
[04/10/2022, 17:56:19] [RPi] Gate light: long press timeout after 1000 ms
[04/10/2022, 17:56:19] [RPi] Gate light: Programmable Switch Event: Long Press
[04/10/2022, 17:56:19] [RPi] Entrance light: long press timeout after 1000 ms
[04/10/2022, 17:56:19] [RPi] Entrance light: Programmable Switch Event: Long Press
[04/10/2022, 17:56:19] [RPi] Office light: long press timeout after 1000 ms
[04/10/2022, 17:56:19] [RPi] Office light: Programmable Switch Event: Long Press

[Olivierbkk]

I came across this: https://forums.raspberrypi.com/viewtopic.php?t=134394

apparently I am not the only one to have this issue, any chance you debounce the same way as in v1.4.1? it seems to work better.

No pressure of course, do what you think is right

[ebaauw]

anyway the system has become very sensitive with the update

Yes, the changed debounce logic would make it more sensitive.

I came across this: https://forums.raspberrypi.com/viewtopic.php?t=134394

Not sure that's relevant for Homebridge RPi; they're using different software (than pigpiod) to interact with the GPIO pins.

I'm quite impressed by the pigpio library. I recently added support for DHTxx temperature/humidity sensors, that use a single input GPIO pin to encode a bit stream, using the timing between rising edges to distinguish between a binary 0 (between 60 and 100µs) and 1 (between 100 and 150µs). I works without fail in my tests, even when using the internal pull resistor. The push button on my FanSHIM also works without fail - I don't seen any state flips requiring debouncing. In fact, the only time I've needed debouncing is when simulating other input devices using a jumper wire to connect the pin to ground.

any chance you debounce the same way as in v1.4.1? it seems to work better. No pressure of course, do what you think is right

Way ahead of you - could you please try beta v1.5.1-0? I would appreciate a log file capturing the erratic pin drops, (hopefully) being ignored due to the reverted debouncing logic.

[ebaauw]

Could you also try out beta v1.5.1-1? This version uses the debounce feature of pigpiod instead of NodeJS timers. That should even be more resilient, as NodeJS now only receives notifications for debounced changes. Consequently, you should no longer see the erratic pin drops in the Homebridge log.

I also want to see if I can use the pigpiod watchdog timer for double press and long press timeouts, but that's taking me a bit more time.

[Olivierbkk]

I don't see the beta v1.5.1-0 in the alternate version list so I am only testing beta v1.5.1-1. See the attached log file.

Note that I put back the hardware to what seemed to produce the most erratic behavior although I am not certain it actually has an effect (powering the output relay board through the Pi).

Here is what I did:

• restarted server
• activated the dining light rocker to turn on, waited a few seconds, activated the rocker to turn off
• pressed the gate light button once to turn on the gate light, waited a few seconds, pressed the button again to turn it off
• pressed the entrance light button once to turn on the entrance light, waited a few seconds, pressed the button again to turn it off
• open the front door, waited a few seconds (for my dog to go out) and closed it back
• turned on and off random lights from the home app
• Downloaded the log file

Everything seems to be working normally as far as I can tell but you can check the log. Let me know if you need me to test anything else. I will stick to this version for now.

homebridge.log-4.txt

[ebaauw]

I don't see the beta v1.5.1-0 in the alternate version list

Weird. That must be a “feature” of the Homebridge UI; the version is available alright in the npm registry, see https://www.npmjs.com/package/homebridge-rpi.

Everything seems to be working normally I will stick to this version for now.

Cool. Still working on the double and long press timeouts, so will do another beta before the v1.5.1 release.

you can check the log

Looks OK, but I do notice two things:

(node:19882) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 notification listeners added to [PigpioClient]. Use emitter.setMaxListeners() to increase limit

I suppose this warning was there earlier, but you filtered it out? No memory leak: 10 input devices and 1 for logging. I do need to increase the limit.

[05/10/2022, 08:12:00] [RPi] raspberrypi: gpio map: [.... x.xx x... .x.. .x.. x... x..x ....], tick: 1744945524, flags: 0x40, seqno: 0

Unexpected value for flags - need to check if this means anything.

[Olivierbkk]

I don't see the beta v1.5.1-0 in the alternate version list Weird. That must be a “feature” of the Homebridge UI; the version is available alright in the npm registry, see https://www.npmjs.com/package/homebridge-rpi.

see picture below (couldn't do a screenshot without the menu to fold)

(node:19882) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 notification listeners added to [PigpioClient]. Use emitter.setMaxListeners() to increase limit I suppose this warning was there earlier, but you filtered it out? No memory leak: 10 input devices and 1 for logging. I do need to increase the limit.

Yes I think it was here before

[Olivierbkk]

BTW I noticed the long press doesn't wait until we release the button to do the action, that is good

[ebaauw]

BTW I noticed the long press doesn't wait until we release the button to do the action, that is good

Yeah, logic should now be:

• Single Press: doublePressTimeout ms after release within longPressTimeout ms after press, when no (second) press has occurred;
• Double Press: immediately after (second) press within doublePressTimeout ms after release within longPressTimeout ms after (first) press;
• Long Press: longPressTimeout ms after press, when no release has occurred.

When doublePressTimeout is 0, Single Press is issued immediately on release.

When both doublePressTimeout and longPressTimeout are 0, Single Press is issued on press, just like for doorbell devices and similar to rocker devices, that issue Single Press immediately on flipping the rocker (hence neither of these devices supports these timeouts).

The only weird (unintuitive) behaviour is when longPressTimeout is 0 and doublePressTimeout is > 0. In that case nothing happens while holding the button after the first press. Maybe I should just issue a Single Press after doublePressTimeout ms.

Note that I put back the hardware to what seemed to produce the most erratic behavior although I am not certain it actually has an effect (powering the output relay board through the Pi).

For "fun", you might set debouceTimeout to 0, to still get the erratic behaviour and corresponding log messages.

[Olivierbkk]

For "fun", you might set debouceTimeout to 0, to still get the erratic behaviour and corresponding log messages.

do you actually need me to try and send you a log file?

[ebaauw]

do you actually need me to try and send you a log file?

No, thanks.

[Olivierbkk]

So far v1.5.1-1 is working without a glitch, I still have latency but it could be from my wifi (or my vintage Pi). I put a repeater but it is also struggling with the signal, the installation location is not ideal. I will wire the Pi to the router, a daunting task in my house.

On a side note I have a couple of questions:

• I cannot find a log level that only logs the event related to the GPIO without logging the CPU temperature and load. Do you have this? Have you documented the log levels somewhere?
• Is there a siren device in homekit? I don't see it in your supported device list. Of course I could use a valve/light/switch and rename it in the home app.

[ebaauw]

I cannot find a log level that only logs the event related to the GPIO without logging the CPU temperature and load. Do you have this? Have you documented the log levels somewhere?

Log levels are explained here: https://github.com/ebaauw/homebridge-lib/wiki/Log-Messages.

The scope of log level depends a bit on the nature of the device being exposed by a plugin. From a debugging perspective, I want to set the log level per client connection. So Homebridge ZP supports a log level per zone player; Homebridge NB supports a log level per Nuki bridge, shared by all devices connected to that bridge; and Homebridge WS supports a single log level for the plugin, since there's only one OpenWeatherMap client shared by all accessories.

Homebridge RPi supports a log level per Raspberry Pi that is shared by the accessory for the Pi and the accessories for the GPIO-connected devices to that Pi. I might change that in the future, but not anytime soon. Currently the log level is set from HomeKit, using the Log Level characteristic. While this approach works, I don't like polluting HomeKit with admin-like settings. I'm hoping to support these dynamic (!) settings (like Log Level, but also settings like Heartrate, Low Battery Threshold, etc) from the Homebridge UI in future. Homebridge deCONZ will be my first plugin to support that; after I'll make the change to other plugins.

Is there a siren device in homekit? I don't see it in your supported device list. Of course I could use a valve/light/switch and rename it in the home app.

I don't think there is. In Homebridge Hue and Homebridge deCONZ, I expose Zigbee sirens as Outlet, praying that Siri won't inadvertently activate them when asking her to turn on the room they're in.

[Olivierbkk]

Understood about the log, with the heartbeat set to maximum it's fine.

For the siren I will use something else, no problem. I have the "security system" and "siren" in what I call "control center" in the home app which is a virtual room where I put all the "mess" that people in the house need not to see (including the buttons/rockers created by RPi and other Ikea buttons) so the chance to be triggered by Siri by mistake is slim.

Thanks for the answer as always.

[ebaauw]

Could you please try beta v1.5.1-2?

Another refactor to analyse the notifications by pigpio in one place (in PigpioClient) and issue GPIO-specific NodeJS events, instead of issuing generic notification events that each device needs to pick up separately, causing the MaxListenersExceededWarning.

Also, this version sets up a watchdog timer in pigpio for each button (with doublePressTimeout > 0 or longPressTimeout > 0), causing a dummy notification every 500ms (by default). This is now used for the double press and long press timeouts, instead of NodeJS timers. It works fine in my tests with one button, but I cannot test how well this scales with multiple buttons. I don't expect any issues, though; the notification rate for DTHxx sensors is much higher.

[Olivierbkk]

ok tested v1.6.0-0 which is the only beta I can see.

Here is the log file, I activated a few physical switches, sensors and rockers and through the home app.

homebridge.log-4.txt

the log file is very long...

[ebaauw]

Thanks!

the log file is very long...

Yes. Log Level 3 is really only for analysing issues; normally you’d use 2 at most.

I see I messed up the map, which always shows empty, but functionally, everything seems to work just fine?

[Olivierbkk]

yes it all works normally.

let me know if you want me to test further.

once I will be out of the beta version I will check where the latency is coming from and let you know if you are interested.

[ebaauw]

Published v1.6.0.

Please open a new issue for any latency caused unjustly by Homebridge RPi.

[Olivierbkk]

Thanks a lot for all the efforts !

I must admit it's quite addicting...

[ebaauw]

I suppose we all need something to keep us off the streets…