search

thomasloven / hass-plejd

🔹 Plejd BLE integration for Home Assistant
96 stars 9 forks source link

Mesh re-connection flooding #66

Open pierrei opened 6 months ago

pierrei commented 6 months ago

I've noticed that after a while running HA with the integration it starts taking time for a change in HA to actually happen with lights/switches. While debugging I saw that the pyplejd lib used in this integration was "Trying to connect to mesh" over and over again. Not sure if this is the cause of the slowness issue or not but it looks suspicious. Is it supposed to attempt to reconnect over and over again? It seems to happen less often just after a restart but when it's been running for a day this fills the logs completely.

Excerpt from the logs when debug logging is on:

2024-05-10 09:27:19.148 DEBUG (MainThread) [pyplejd.ble] Pong(51)
2024-05-10 09:27:19.148 DEBUG (MainThread) [pyplejd.ble] Polling mesh for current state
2024-05-10 09:27:19.786 DEBUG (MainThread) [pyplejd.ble] Trying to connect to mesh
2024-05-10 09:27:19.786 DEBUG (MainThread) [pyplejd.ble] Ping(197)
2024-05-10 09:27:20.307 DEBUG (MainThread) [pyplejd.ble] Parsing LIGHTLEVEL: 0b0000232907070023290c000023260707002326
2024-05-10 09:27:20.308 DEBUG (MainThread) [pyplejd.ble] Address: 11, state: False, dim: 1799
2024-05-10 09:27:20.308 DEBUG (MainThread) [pyplejd.ble] LL message: bytearray(b'\x0b\x00\x00#)\x07\x07\x00#)')
2024-05-10 09:27:20.309 DEBUG (MainThread) [pyplejd.ble] Address: 12, state: False, dim: 1799
2024-05-10 09:27:20.309 DEBUG (MainThread) [pyplejd.ble] LL message: bytearray(b'\x0c\x00\x00#&\x07\x07\x00#&')
2024-05-10 09:27:21.267 DEBUG (MainThread) [pyplejd.ble] Parsing LIGHTLEVEL: 0d000002d000000000000e000002d10000000000
2024-05-10 09:27:21.268 DEBUG (MainThread) [pyplejd.ble] Address: 13, state: False, dim: 0
2024-05-10 09:27:21.268 DEBUG (MainThread) [pyplejd.ble] LL message: bytearray(b'\r\x00\x00\x02\xd0\x00\x00\x00\x00\x00')
2024-05-10 09:27:21.269 DEBUG (MainThread) [pyplejd.ble] Address: 14, state: False, dim: 0
2024-05-10 09:27:21.269 DEBUG (MainThread) [pyplejd.ble] LL message: bytearray(b'\x0e\x00\x00\x02\xd1\x00\x00\x00\x00\x00')
2024-05-10 09:27:21.467 DEBUG (MainThread) [pyplejd.ble] Parsing LIGHTLEVEL: 100000232bff7f00232b11000023237d7d002323
2024-05-10 09:27:21.468 DEBUG (MainThread) [pyplejd.ble] Address: 16, state: False, dim: 32767
2024-05-10 09:27:21.469 DEBUG (MainThread) [pyplejd.ble] LL message: bytearray(b'\x10\x00\x00#+\xff\x7f\x00#+')
2024-05-10 09:27:21.469 DEBUG (MainThread) [pyplejd.ble] Address: 17, state: False, dim: 32125
2024-05-10 09:27:21.470 DEBUG (MainThread) [pyplejd.ble] LL message: bytearray(b'\x11\x00\x00##}}\x00##')
2024-05-10 09:27:21.787 DEBUG (MainThread) [pyplejd.ble] Parsing LIGHTLEVEL: 130000232dffff00232d140000232ef02800232e
2024-05-10 09:27:21.788 DEBUG (MainThread) [pyplejd.ble] Address: 19, state: False, dim: 65535
2024-05-10 09:27:21.788 DEBUG (MainThread) [pyplejd.ble] LL message: bytearray(b'\x13\x00\x00#-\xff\xff\x00#-')
2024-05-10 09:27:21.789 DEBUG (MainThread) [pyplejd.ble] Address: 20, state: False, dim: 10480
2024-05-10 09:27:21.789 DEBUG (MainThread) [pyplejd.ble] LL message: bytearray(b'\x14\x00\x00#.\xf0(\x00#.')
2024-05-10 09:27:21.987 DEBUG (MainThread) [pyplejd.ble] Parsing LIGHTLEVEL: 1600002325b082002325170000232a000000232a
2024-05-10 09:27:21.988 DEBUG (MainThread) [pyplejd.ble] Address: 22, state: False, dim: 33456
2024-05-10 09:27:21.988 DEBUG (MainThread) [pyplejd.ble] LL message: bytearray(b'\x16\x00\x00#%\xb0\x82\x00#%')
2024-05-10 09:27:21.989 DEBUG (MainThread) [pyplejd.ble] Address: 23, state: False, dim: 0
2024-05-10 09:27:21.989 DEBUG (MainThread) [pyplejd.ble] LL message: bytearray(b'\x17\x00\x00#*\x00\x00\x00#*')
2024-05-10 09:27:22.627 DEBUG (MainThread) [pyplejd.ble] Parsing LIGHTLEVEL: 19000023271d1d0023271a000023220000002322
2024-05-10 09:27:22.628 DEBUG (MainThread) [pyplejd.ble] Address: 25, state: False, dim: 7453
2024-05-10 09:27:22.628 DEBUG (MainThread) [pyplejd.ble] LL message: bytearray(b"\x19\x00\x00#\'\x1d\x1d\x00#\'")
2024-05-10 09:27:22.628 DEBUG (MainThread) [pyplejd.ble] Address: 26, state: False, dim: 0
2024-05-10 09:27:22.629 DEBUG (MainThread) [pyplejd.ble] LL message: bytearray(b'\x1a\x00\x00#"\x00\x00\x00#"')
2024-05-10 09:27:22.787 DEBUG (MainThread) [pyplejd.ble] Parsing LIGHTLEVEL: 1b000023241d1d0023241d000023280000002328
2024-05-10 09:27:22.788 DEBUG (MainThread) [pyplejd.ble] Address: 27, state: False, dim: 7453
2024-05-10 09:27:22.788 DEBUG (MainThread) [pyplejd.ble] LL message: bytearray(b'\x1b\x00\x00#$\x1d\x1d\x00#$')
2024-05-10 09:27:22.789 DEBUG (MainThread) [pyplejd.ble] Address: 29, state: False, dim: 0
2024-05-10 09:27:22.789 DEBUG (MainThread) [pyplejd.ble] LL message: bytearray(b'\x1d\x00\x00#(\x00\x00\x00#(')
2024-05-10 09:27:23.787 DEBUG (MainThread) [pyplejd.ble] Parsing LIGHTLEVEL: 1e0000232c000000232c
2024-05-10 09:27:23.788 DEBUG (MainThread) [pyplejd.ble] Address: 30, state: False, dim: 0
2024-05-10 09:27:23.788 DEBUG (MainThread) [pyplejd.ble] LL message: bytearray(b'\x1e\x00\x00#,\x00\x00\x00#,')
2024-05-10 09:27:24.108 DEBUG (MainThread) [pyplejd.ble] Pong(198)
2024-05-10 09:27:24.108 DEBUG (MainThread) [pyplejd.ble] Polling mesh for current state
2024-05-10 09:27:24.347 DEBUG (MainThread) [pyplejd.ble] Trying to connect to mesh
2024-05-10 09:27:24.348 DEBUG (MainThread) [pyplejd.ble] Ping(0)
2024-05-10 09:27:24.427 DEBUG (MainThread) [pyplejd.ble] Parsing LIGHTLEVEL: 0b0000232907070023290c000023260707002326
2024-05-10 09:27:24.427 DEBUG (MainThread) [pyplejd.ble] Address: 11, state: False, dim: 1799
2024-05-10 09:27:24.428 DEBUG (MainThread) [pyplejd.ble] LL message: bytearray(b'\x0b\x00\x00#)\x07\x07\x00#)')
2024-05-10 09:27:24.428 DEBUG (MainThread) [pyplejd.ble] Address: 12, state: False, dim: 1799
2024-05-10 09:27:24.428 DEBUG (MainThread) [pyplejd.ble] LL message: bytearray(b'\x0c\x00\x00#&\x07\x07\x00#&')
2024-05-10 09:27:24.747 DEBUG (MainThread) [pyplejd.ble] Parsing LIGHTLEVEL: 0d000002d000000000000e000002d10000000000
2024-05-10 09:27:24.748 DEBUG (MainThread) [pyplejd.ble] Address: 13, state: False, dim: 0
2024-05-10 09:27:24.748 DEBUG (MainThread) [pyplejd.ble] LL message: bytearray(b'\r\x00\x00\x02\xd0\x00\x00\x00\x00\x00')
2024-05-10 09:27:24.749 DEBUG (MainThread) [pyplejd.ble] Address: 14, state: False, dim: 0
2024-05-10 09:27:24.749 DEBUG (MainThread) [pyplejd.ble] LL message: bytearray(b'\x0e\x00\x00\x02\xd1\x00\x00\x00\x00\x00')
2024-05-10 09:27:24.947 DEBUG (MainThread) [pyplejd.ble] Parsing LIGHTLEVEL: 100000232bff7f00232b11000023237d7d002323
2024-05-10 09:27:24.948 DEBUG (MainThread) [pyplejd.ble] Address: 16, state: False, dim: 32767
2024-05-10 09:27:24.948 DEBUG (MainThread) [pyplejd.ble] LL message: bytearray(b'\x10\x00\x00#+\xff\x7f\x00#+')
2024-05-10 09:27:24.949 DEBUG (MainThread) [pyplejd.ble] Address: 17, state: False, dim: 32125
2024-05-10 09:27:24.950 DEBUG (MainThread) [pyplejd.ble] LL message: bytearray(b'\x11\x00\x00##}}\x00##')
2024-05-10 09:27:25.387 DEBUG (MainThread) [pyplejd.ble] Parsing LIGHTLEVEL: 130000232dffff00232d140000232ef02800232e
2024-05-10 09:27:25.388 DEBUG (MainThread) [pyplejd.ble] Address: 19, state: False, dim: 65535
2024-05-10 09:27:25.388 DEBUG (MainThread) [pyplejd.ble] LL message: bytearray(b'\x13\x00\x00#-\xff\xff\x00#-')
2024-05-10 09:27:25.388 DEBUG (MainThread) [pyplejd.ble] Address: 20, state: False, dim: 10480
2024-05-10 09:27:25.389 DEBUG (MainThread) [pyplejd.ble] LL message: bytearray(b'\x14\x00\x00#.\xf0(\x00#.')
2024-05-10 09:27:25.707 DEBUG (MainThread) [pyplejd.ble] Parsing LIGHTLEVEL: 1600002325b082002325170000232a000000232a
2024-05-10 09:27:25.708 DEBUG (MainThread) [pyplejd.ble] Address: 22, state: False, dim: 33456
2024-05-10 09:27:25.708 DEBUG (MainThread) [pyplejd.ble] LL message: bytearray(b'\x16\x00\x00#%\xb0\x82\x00#%')
2024-05-10 09:27:25.709 DEBUG (MainThread) [pyplejd.ble] Address: 23, state: False, dim: 0
2024-05-10 09:27:25.709 DEBUG (MainThread) [pyplejd.ble] LL message: bytearray(b'\x17\x00\x00#*\x00\x00\x00#*')
2024-05-10 09:27:25.747 DEBUG (MainThread) [pyplejd.ble] Parsing LIGHTLEVEL: 19000023271d1d0023271a000023220000002322
2024-05-10 09:27:25.748 DEBUG (MainThread) [pyplejd.ble] Address: 25, state: False, dim: 7453
2024-05-10 09:27:25.748 DEBUG (MainThread) [pyplejd.ble] LL message: bytearray(b"\x19\x00\x00#\'\x1d\x1d\x00#\'")
2024-05-10 09:27:25.750 DEBUG (MainThread) [pyplejd.ble] Address: 26, state: False, dim: 0
2024-05-10 09:27:25.750 DEBUG (MainThread) [pyplejd.ble] LL message: bytearray(b'\x1a\x00\x00#"\x00\x00\x00#"')
2024-05-10 09:27:25.827 DEBUG (MainThread) [pyplejd.ble] Parsing LIGHTLEVEL: 1b000023241d1d0023241d000023280000002328
2024-05-10 09:27:25.828 DEBUG (MainThread) [pyplejd.ble] Address: 27, state: False, dim: 7453
2024-05-10 09:27:25.828 DEBUG (MainThread) [pyplejd.ble] LL message: bytearray(b'\x1b\x00\x00#$\x1d\x1d\x00#$')
2024-05-10 09:27:25.829 DEBUG (MainThread) [pyplejd.ble] Address: 29, state: False, dim: 0
2024-05-10 09:27:25.829 DEBUG (MainThread) [pyplejd.ble] LL message: bytearray(b'\x1d\x00\x00#(\x00\x00\x00#(')
2024-05-10 09:27:26.706 DEBUG (MainThread) [pyplejd.ble] Parsing LIGHTLEVEL: 1e0000232c000000232c
2024-05-10 09:27:26.707 DEBUG (MainThread) [pyplejd.ble] Address: 30, state: False, dim: 0
2024-05-10 09:27:26.707 DEBUG (MainThread) [pyplejd.ble] LL message: bytearray(b'\x1e\x00\x00#,\x00\x00\x00#,')
2024-05-10 09:27:26.867 DEBUG (MainThread) [pyplejd.ble] Pong(1)
2024-05-10 09:27:26.867 DEBUG (MainThread) [pyplejd.ble] Polling mesh for current state
2024-05-10 09:27:27.187 DEBUG (MainThread) [pyplejd.ble] Trying to connect to mesh
2024-05-10 09:27:27.188 DEBUG (MainThread) [pyplejd.ble] Ping(109)
2024-05-10 09:27:27.228 DEBUG (MainThread) [pyplejd.ble] Parsing LIGHTLEVEL: 0b0000232907070023290c000023260707002326
2024-05-10 09:27:27.229 DEBUG (MainThread) [pyplejd.ble] Address: 11, state: False, dim: 1799
2024-05-10 09:27:27.229 DEBUG (MainThread) [pyplejd.ble] LL message: bytearray(b'\x0b\x00\x00#)\x07\x07\x00#)')
2024-05-10 09:27:27.230 DEBUG (MainThread) [pyplejd.ble] Address: 12, state: False, dim: 1799
2024-05-10 09:27:27.230 DEBUG (MainThread) [pyplejd.ble] LL message: bytearray(b'\x0c\x00\x00#&\x07\x07\x00#&')
2024-05-10 09:27:27.386 DEBUG (MainThread) [pyplejd.ble] Parsing LIGHTLEVEL: 0d000002d000000000000e000002d10000000000
2024-05-10 09:27:27.386 DEBUG (MainThread) [pyplejd.ble] Address: 13, state: False, dim: 0
2024-05-10 09:27:27.386 DEBUG (MainThread) [pyplejd.ble] LL message: bytearray(b'\r\x00\x00\x02\xd0\x00\x00\x00\x00\x00')
2024-05-10 09:27:27.386 DEBUG (MainThread) [pyplejd.ble] Address: 14, state: False, dim: 0
2024-05-10 09:27:27.387 DEBUG (MainThread) [pyplejd.ble] LL message: bytearray(b'\x0e\x00\x00\x02\xd1\x00\x00\x00\x00\x00')
2024-05-10 09:27:27.547 DEBUG (MainThread) [pyplejd.ble] Parsing LIGHTLEVEL: 100000232bff7f00232b11000023237d7d002323
2024-05-10 09:27:27.548 DEBUG (MainThread) [pyplejd.ble] Address: 16, state: False, dim: 32767
2024-05-10 09:27:27.548 DEBUG (MainThread) [pyplejd.ble] LL message: bytearray(b'\x10\x00\x00#+\xff\x7f\x00#+')
2024-05-10 09:27:27.549 DEBUG (MainThread) [pyplejd.ble] Address: 17, state: False, dim: 32125
2024-05-10 09:27:27.549 DEBUG (MainThread) [pyplejd.ble] LL message: bytearray(b'\x11\x00\x00##}}\x00##')
2024-05-10 09:27:28.027 DEBUG (MainThread) [pyplejd.ble] Parsing LIGHTLEVEL: 130000232dffff00232d140000232ef02800232e
2024-05-10 09:27:28.027 DEBUG (MainThread) [pyplejd.ble] Address: 19, state: False, dim: 65535
2024-05-10 09:27:28.027 DEBUG (MainThread) [pyplejd.ble] LL message: bytearray(b'\x13\x00\x00#-\xff\xff\x00#-')
2024-05-10 09:27:28.028 DEBUG (MainThread) [pyplejd.ble] Address: 20, state: False, dim: 10480
2024-05-10 09:27:28.028 DEBUG (MainThread) [pyplejd.ble] LL message: bytearray(b'\x14\x00\x00#.\xf0(\x00#.')
2024-05-10 09:27:28.667 DEBUG (MainThread) [pyplejd.ble] Parsing LIGHTLEVEL: 1600002325b082002325170000232a000000232a
2024-05-10 09:27:28.668 DEBUG (MainThread) [pyplejd.ble] Address: 22, state: False, dim: 33456
2024-05-10 09:27:28.668 DEBUG (MainThread) [pyplejd.ble] LL message: bytearray(b'\x16\x00\x00#%\xb0\x82\x00#%')
2024-05-10 09:27:28.669 DEBUG (MainThread) [pyplejd.ble] Address: 23, state: False, dim: 0
2024-05-10 09:27:28.669 DEBUG (MainThread) [pyplejd.ble] LL message: bytearray(b'\x17\x00\x00#*\x00\x00\x00#*')
2024-05-10 09:27:28.827 DEBUG (MainThread) [pyplejd.ble] Parsing LIGHTLEVEL: 19000023271d1d0023271a000023220000002322
2024-05-10 09:27:28.828 DEBUG (MainThread) [pyplejd.ble] Address: 25, state: False, dim: 7453
2024-05-10 09:27:28.828 DEBUG (MainThread) [pyplejd.ble] LL message: bytearray(b"\x19\x00\x00#\'\x1d\x1d\x00#\'")
2024-05-10 09:27:28.829 DEBUG (MainThread) [pyplejd.ble] Address: 26, state: False, dim: 0
2024-05-10 09:27:28.829 DEBUG (MainThread) [pyplejd.ble] LL message: bytearray(b'\x1a\x00\x00#"\x00\x00\x00#"')
2024-05-10 09:27:29.187 DEBUG (MainThread) [pyplejd.ble] Parsing LIGHTLEVEL: 1b000023241d1d0023241d000023280000002328
2024-05-10 09:27:29.188 DEBUG (MainThread) [pyplejd.ble] Address: 27, state: False, dim: 7453
2024-05-10 09:27:29.188 DEBUG (MainThread) [pyplejd.ble] LL message: bytearray(b'\x1b\x00\x00#$\x1d\x1d\x00#$')
2024-05-10 09:27:29.189 DEBUG (MainThread) [pyplejd.ble] Address: 29, state: False, dim: 0
2024-05-10 09:27:29.189 DEBUG (MainThread) [pyplejd.ble] LL message: bytearray(b'\x1d\x00\x00#(\x00\x00\x00#(')
2024-05-10 09:27:29.827 DEBUG (MainThread) [pyplejd.ble] Parsing LIGHTLEVEL: 1e0000232c000000232c
2024-05-10 09:27:29.828 DEBUG (MainThread) [pyplejd.ble] Address: 30, state: False, dim: 0
2024-05-10 09:27:29.828 DEBUG (MainThread) [pyplejd.ble] LL message: bytearray(b'\x1e\x00\x00#,\x00\x00\x00#,')
2024-05-10 09:27:30.147 DEBUG (MainThread) [pyplejd.ble] Pong(110)
pierrei commented 6 months ago

Looking closer at the code it seems like the built in pinging does a connect, so I suppose this is as expected. The delay in commands I see after running HA for > 1 day should be because of something else I guess then 🤔

pierrei commented 6 months ago

I added some more logging and ran that version to see what's going on in more detail. It looks like this is the problem. When a bluetooth device is discovered it triggers a ping, which seems to discover the device again and the loop starts. I'm not sure why this ping on discovery is needed or what benefit it brings. Would it be possible to remove this ping or only do a ping if the device hasn't been seen before?

An example from the custom logging I added in plejd_site.py for both _ping and _discovered:

2024-05-11 21:41:13.746 INFO (MainThread) [custom_components.plejd.plejd_site] Discovered device S38 D93A LE
2024-05-11 21:41:13.746 INFO (MainThread) [custom_components.plejd.plejd_site] Discovered device, creating ping task
2024-05-11 21:41:13.747 INFO (MainThread) [custom_components.plejd.plejd_site] Ping
2024-05-11 21:41:13.804 INFO (MainThread) [custom_components.plejd.plejd_site] Discovered device S19 A86D LE
2024-05-11 21:41:13.804 INFO (MainThread) [custom_components.plejd.plejd_site] Discovered device, creating ping task
2024-05-11 21:41:13.805 INFO (MainThread) [custom_components.plejd.plejd_site] Ping
2024-05-11 21:41:13.892 INFO (MainThread) [custom_components.plejd.plejd_site] Discovered device S38 D93A LE
2024-05-11 21:41:13.893 INFO (MainThread) [custom_components.plejd.plejd_site] Discovered device, creating ping task
2024-05-11 21:41:13.893 INFO (MainThread) [custom_components.plejd.plejd_site] Ping
2024-05-11 21:41:14.428 INFO (MainThread) [custom_components.plejd.plejd_site] Discovered device S38 D93A LE
2024-05-11 21:41:14.429 INFO (MainThread) [custom_components.plejd.plejd_site] Discovered device, creating ping task
2024-05-11 21:41:14.429 INFO (MainThread) [custom_components.plejd.plejd_site] Ping
2024-05-11 21:41:14.488 INFO (MainThread) [custom_components.plejd.plejd_site] Discovered device S38 D93A LE
2024-05-11 21:41:14.489 INFO (MainThread) [custom_components.plejd.plejd_site] Discovered device, creating ping task
2024-05-11 21:41:14.489 INFO (MainThread) [custom_components.plejd.plejd_site] Ping
2024-05-11 21:41:15.986 INFO (MainThread) [custom_components.plejd.plejd_site] Discovered device S19 A86D LE
2024-05-11 21:41:15.986 INFO (MainThread) [custom_components.plejd.plejd_site] Discovered device, creating ping task
2024-05-11 21:41:15.986 INFO (MainThread) [custom_components.plejd.plejd_site] Ping
2024-05-11 21:41:16.226 INFO (MainThread) [custom_components.plejd.plejd_site] Discovered device S19 A86D LE
2024-05-11 21:41:16.226 INFO (MainThread) [custom_components.plejd.plejd_site] Discovered device, creating ping task
2024-05-11 21:41:16.226 INFO (MainThread) [custom_components.plejd.plejd_site] Ping
pierrei commented 6 months ago

I also realized I seem to get calls to _discovered for other types of Bluetooth devices. I guess the service_uuid thing is supposed to filter on only the Plejd mesh but seems like it's not working for some reason 🤔

pierrei commented 5 months ago

Created two PRs to see if @thomasloven agrees it could fix this issue.

https://github.com/thomasloven/pyplejd/pull/7: To return true if a added device is new https://github.com/thomasloven/hass-plejd/pull/70: To use the previous to only send a ping if the device discovered was new

thomasloven commented 5 months ago

This makes perfect sense to me. I'll merge it as soon as I find the time. Thanks!