Lock SwitchBot Bluetooth connection takes a long time when using local adapter but OK with proxy #93171
Assignees
Labels
integration: bluetooth
integration: switchbot
problem in dependency
waiting-for-upstream
We're waiting for a change upstream
Comments
|
Hey there @OttoWinter, @jesserockz, mind taking a look at this issue as it has been labeled with an integration ( Code owner commandsCode owners of
(message by CodeOwnersMention) esphome documentation |
|
If its slow when NOT using the proxy but fast when using the proxy, its a problem with the local adapter. Which bluetooth adapter are you using? |
|
Hey there @Danielhiversen, @RenierM26, @murtas, @Eloston, @dsypniewski, mind taking a look at this issue as it has been labeled with an integration ( Code owner commandsCode owners of
(message by CodeOwnersMention) switchbot documentation |
bdraco
changed the title
|
now iam using UGREEN CM109 (CSR8510A10) |
It looks like the connection get dropped almost right away. We will probably need the |
|
ok, i will turn on logging debug level for bleak and as soon as i get proper logs i will write here, thanks |
|
below LOG |
|
That looks like either the buggy firmware on the RTL8761BU (anything older than 0xDFC6_D922 is pretty broken from my experience or an interference problem. Which adapter are you using? |
|
as i wrote posts before
this adapter has CSR chip not RTL :/ I dont think so, that this is interference, because:
|
Sorry about that, thats a known good adapter -- jumping between this and another issue and trying to not mix them up 👍 I think at this point we need a btmon dump to see what is going on lower in the bluetooth stack. https://github.com/bluez/bluez/wiki/btmon#capture-the-traces-from-hci0-to-hcidumplog-file |
|
@bdraco btmon: command not found |
|
I do some update. I placed bt dongle about 2m near lock, clean area, no walls, nothing. BT signal: about -40rssi - -50rssi. One bt proxy Update HA to newest esphome update too today log: I noticed, that all logs contain always: RSSI: -71 |
|
after update to newest ESPHome 2023.5.4 (problem still exsist) |
|
I bought the same hardware and going to give it a try on an HA blue now |
|
also using this for an extension cable |
|
lock setup and connected fine. config flow took a bit longer than expected but ok |
|
its pretty quick for me. Here is my connection log with various debug loggers enabled |
|
Also I'm using this hardware for the HA system https://www.hardkernel.com/shop/odroid-n2-with-4gbyte-ram-2/ |
|
i dont know what to say, but as i wrote many times (and some other users too): lock working ok after reboot, manual open/close, some action on it. But, wait about 30min, 1h and more and then is problem - i had lag and have to wait for action. Lock i dont know, goes to sleep mode ? now i know that NO, but behavior is like this. |
|
I waited 25 minutes from the last attempt and result is the same, still quick to connect I'll try again in an hour |
|
It seems like you have an integration or a core change in recent versions that is making your system. You could try the dump command instead or record |
|
now i tried with duration and rate 1 ONE and:
|
|
|
|
Looks like the number of threads is ok with |
|
when do record HA freeze and restart i see that i have python v3.10.11 and You have v3.11.3. this can do problem or not? |
|
2023.6.0 will have python 3.11 It comes out next Wednesday so maybe it would be good to try again than |
|
i dont know wht to do more. Something is wrong, but all working ok. I have many devices and automations and all working ok. Now with only btproxy lock working ok too. |
System Information
Home Assistant Community Store
Home Assistant Cloud
GIOŚ
Home Assistant Supervisor
Dashboards
Recorder
Spotify
|
|
today i made test. I disabled all integrations, all devices. Stays onlu Supervisor, reboot HA and run in terminal py-spy command as below:
and HA freeze and after about 10 minutes rebooted
|
|
after update HA to 2023.6.0 py-spy working! here is svg file after command:
|
|
Great. Can you zip up the file before posting? GitHub compresses them and mutates them. also if you can capture at a higher rate that would help |
|
ok @bdraco done with sample: 100 150 200 500 |
|
The websocket looks a bit busy. If you open the inspector panel in your browser, how fast are the messages coming in? |
|
You mean: open HA in browser (in my case: newest chrome) right click and INSPECT? If yes, its open about 1 sec or less. I can say: right away |
In the network tab, find the websocket. You can look at the messages come over. You may need to |
|
ok, this load right away. i cant see any delay
|
|
I think the problem is likely higher up the bluetooth stack in bluez or bleak I just found hbldh/bleak#1329 but there seems to be more issues |
|
I setup an x86_64 intel nuc system with the exact same adapter (I moved it from an aarch64 ARM system) and I'm having trouble with it as well. It works perfectly fine on the aarch64 ARM system It seems like the problem is in the kernel or bluez |
|
ok, thanks for this work. big thanks |
|
hbldh/bleak#1329 will fix the cases where we wait the whole timeout for the device to reappear |
bdraco
added
problem in dependency
waiting-for-upstream
bdraco
added a commit
that referenced
this issue
Sep 2, 2023
fixes #93036 (comment) fixes #93222 (comment) fixes #93171 changelog: hbldh/bleak@v0.20.2...v0.21.0
|
#99520 will fix the case where the device is removed from the bus while connecting and than we take a long time to timeout. If that doesn't fix it we can reopen this case and hopefully the new logging will give us a hint what is going on. |
Sign up for free
to subscribe to this conversation on GitHub.
Already have an account?
Sign in.
The problem
@bdraco
Iam using HA with Yours fix esphome folder in dir custom component and all as i wrote in this #90265 thread worked fine.
BUT
When i see new verison 2023.5.3 HA included this fix i delete esphome dir from custom component dir and update HA. This was 14 may. Today is 16 may, i tested many scenario, and i have to say that something is wrong. Something another than before.
Now problem is, that connection not go via bt-proxy and this make another delay. I not made any change in my config, only one change was: delete esphome folder from custom component and update HA to 2023.5.3. When connection is via bt-proxy all is ok and without delay. But i dont know why, not every connection going via bt-proxy. Before update to 2023.5.3 everyome lock connection go via bt-proxy
what to do?
Below logs when connection go via proxy and NOT (via app: tap unlock and when unlocked tap lock and lock locked)
What version of Home Assistant Core has the issue?
2023.5.3
What was the last working version of Home Assistant Core?
2023.5.2 with custom fix and earlier
What type of installation are you running?
Home Assistant OS
Integration causing the issue
ESPHome
Link to integration documentation on our website
https://www.home-assistant.io/integrations/esphome
Diagnostics information
No response
Example YAML snippet
No response
Anything in the logs that might be useful for us?
HERE below log when connection goes via bt=proxy and all working ok 2023-05-16 18:07:46.336 DEBUG (MainThread) [switchbot.devices.device] (LOCKMACADDR): Scheduling command 570000000f210381 2023-05-16 18:07:46.336 DEBUG (MainThread) [switchbot.devices.device] (LOCKMACADDR): Connecting; RSSI: -79 2023-05-16 18:07:46.336 DEBUG (MainThread) [bleak_retry_connector] (LOCKMACADDR) - LOCKMACADDR: Connection attempt: 1 2023-05-16 18:07:46.684 DEBUG (MainThread) [switchbot.devices.device] WoLock (LOCKMACADDR): Connected; RSSI: -79 2023-05-16 18:07:46.684 DEBUG (MainThread) [switchbot.devices.device] WoLock (LOCKMACADDR): Starting notify and disconnect timer; RSSI: -79 2023-05-16 18:07:46.685 DEBUG (MainThread) [switchbot.devices.device] WoLock (LOCKMACADDR): Subscribe to notifications; RSSI: -79 2023-05-16 18:07:46.726 DEBUG (MainThread) [switchbot.devices.device] WoLock (LOCKMACADDR): Sending command: 570000000f210381 2023-05-16 18:07:46.850 DEBUG (MainThread) [switchbot.devices.device] WoLock (LOCKMACADDR): Notification received: 010000007dc0bc8cdf3f6be57f426f0a88c23050 2023-05-16 18:07:46.851 DEBUG (MainThread) [switchbot.devices.device] WoLock (LOCKMACADDR): Scheduling command 57817dc0f7349d19fac6837e 2023-05-16 18:07:46.851 DEBUG (MainThread) [switchbot.devices.device] WoLock (LOCKMACADDR): Already connected before obtaining lock, resetting timer; RSSI: -79 2023-05-16 18:07:46.851 DEBUG (MainThread) [switchbot.devices.device] WoLock (LOCKMACADDR): Sending command: 57817dc0f7349d19fac6837e 2023-05-16 18:07:46.992 DEBUG (MainThread) [switchbot.devices.device] WoLock (LOCKMACADDR): Received unsolicited notification: bytearray(b'\x0f\x81}\xc0{<\x12\x93m\xc6\x02\x7f?\xb0E=\xc3\xb0') 2023-05-16 18:07:46.993 DEBUG (MainThread) [switchbot.devices.device] WoLock (LOCKMACADDR): Notification received: 01817dc0 2023-05-16 18:07:46.994 DEBUG (MainThread) [switchbot.devices.device] WoLock (LOCKMACADDR): Scheduling command 57817dc0f67b9c06ea46 2023-05-16 18:07:46.994 DEBUG (MainThread) [switchbot.devices.device] WoLock (LOCKMACADDR): Already connected before obtaining lock, resetting timer; RSSI: -79 2023-05-16 18:07:46.994 DEBUG (MainThread) [switchbot.devices.device] WoLock (LOCKMACADDR): Sending command: 57817dc0f67b9c06ea46 2023-05-16 18:07:47.163 DEBUG (MainThread) [switchbot.devices.device] (LOCKMACADDR): Notification received: 01817dc04ba00990fa 2023-05-16 18:07:47.166 DEBUG (MainThread) [switchbot.devices.device] (LOCKMACADDR): Scheduling command 57817dc0fb 2023-05-16 18:07:47.166 DEBUG (MainThread) [switchbot.devices.device] (LOCKMACADDR): Already connected before obtaining lock, resetting timer; RSSI: -79 2023-05-16 18:07:47.166 DEBUG (MainThread) [switchbot.devices.device] (LOCKMACADDR): Sending command: 57817dc0fb 2023-05-16 18:07:47.254 DEBUG (MainThread) [switchbot.devices.device] (LOCKMACADDR): Fire callbacks 2023-05-16 18:07:47.348 DEBUG (MainThread) [switchbot.devices.device] (LOCKMACADDR): Notification received: 01817dc09b749907fac6 2023-05-16 18:07:47.350 DEBUG (MainThread) [switchbot.devices.device] (LOCKMACADDR): Fire callbacks 2023-05-16 18:07:47.562 DEBUG (MainThread) [switchbot.devices.device] WoLock (LOCKMACADDR): Fire callbacks 2023-05-16 18:07:47.591 DEBUG (MainThread) [switchbot.adv_parsers.lock] mfr_data: c189444b2ba5efb30820 2023-05-16 18:07:47.592 DEBUG (MainThread) [switchbot.adv_parsers.lock] data: 6f8062 2023-05-16 18:07:53.317 DEBUG (MainThread) [switchbot.devices.device] (LOCKMACADDR): Fire callbacks 2023-05-16 18:07:54.888 DEBUG (MainThread) [switchbot.devices.device] (LOCKMACADDR): Scheduling command 57817dc0f67b9c06eac6 2023-05-16 18:07:54.889 DEBUG (MainThread) [switchbot.devices.device] (LOCKMACADDR): Already connected before obtaining lock, resetting timer; RSSI: -79 2023-05-16 18:07:54.889 DEBUG (MainThread) [switchbot.devices.device] (LOCKMACADDR): Sending command: 57817dc0f67b9c06eac6 2023-05-16 18:07:55.028 DEBUG (MainThread) [switchbot.devices.device] (LOCKMACADDR): Notification received: 01817dc059a80990fa 2023-05-16 18:07:55.029 DEBUG (MainThread) [switchbot.devices.device] (LOCKMACADDR): Scheduling command 57817dc0fb 2023-05-16 18:07:55.029 DEBUG (MainThread) [switchbot.devices.device] (LOCKMACADDR): Already connected before obtaining lock, resetting timer; RSSI: -79 2023-05-16 18:07:55.030 DEBUG (MainThread) [switchbot.devices.device] (LOCKMACADDR): Sending command: 57817dc0fb 2023-05-16 18:07:55.078 DEBUG (MainThread) [switchbot.devices.device] (LOCKMACADDR): Fire callbacks 2023-05-16 18:07:55.138 DEBUG (MainThread) [switchbot.devices.device] (LOCKMACADDR): Notification received: 01817dc09b749907fac6 2023-05-16 18:07:55.139 DEBUG (MainThread) [switchbot.devices.device] (LOCKMACADDR): Fire callbacks 2023-05-16 18:08:00.166 DEBUG (MainThread) [switchbot.devices.device] (LOCKMACADDR): Fire callbacks 2023-05-16 18:08:01.787 DEBUG (MainThread) [switchbot.adv_parsers.lock] mfr_data: c189444b2ba5f2830820 2023-05-16 18:08:01.787 DEBUG (MainThread) [switchbot.adv_parsers.lock] data: 6f8062 2023-05-16 18:08:08.666 DEBUG (MainThread) [switchbot.devices.device] (LOCKMACADDR): Executing timed disconnect after timeout of 8.5 2023-05-16 18:08:08.666 DEBUG (MainThread) [switchbot.devices.device] (LOCKMACADDR): Executing disconnect 2023-05-16 18:08:08.667 DEBUG (MainThread) [switchbot.devices.device] (LOCKMACADDR): Executing disconnect with lock 2023-05-16 18:08:08.667 DEBUG (MainThread) [switchbot.devices.device] (LOCKMACADDR): Disconnecting 2023-05-16 18:08:08.758 DEBUG (MainThread) [switchbot.devices.device] (LOCKMACADDR): Disconnected from device; RSSI: -79 2023-05-16 18:08:08.760 DEBUG (MainThread) [switchbot.devices.device] (LOCKMACADDR): Disconnect completed successfully AND HERE below log when connection NOT goes via bt=proxy and all NOT working ok. BIG DELAY, but finally lock unlock and lock 2023-05-16 17:52:40.318 DEBUG (MainThread) [switchbot.devices.device] (LOCKMACADDR): Scheduling command 570000000f210381 2023-05-16 17:52:40.319 DEBUG (MainThread) [switchbot.devices.device] (LOCKMACADDR): Connecting; RSSI: -79 2023-05-16 17:52:40.319 DEBUG (MainThread) [bleak_retry_connector] (LOCKMACADDR) - LOCKMACADDR: Connection attempt: 1 2023-05-16 17:52:40.742 DEBUG (MainThread) [switchbot.devices.device] (LOCKMACADDR): Disconnected from device; RSSI: -79 2023-05-16 17:52:46.404 DEBUG (MainThread) [switchbot.devices.device] (LOCKMACADDR): Disconnected from device; RSSI: -79 2023-05-16 17:52:52.166 DEBUG (MainThread) [switchbot.devices.device] (LOCKMACADDR): Connected; RSSI: -79 2023-05-16 17:52:52.167 DEBUG (MainThread) [switchbot.devices.device] (LOCKMACADDR): Starting notify and disconnect timer; RSSI: -79 2023-05-16 17:52:52.167 DEBUG (MainThread) [switchbot.devices.device] (LOCKMACADDR): Subscribe to notifications; RSSI: -79 2023-05-16 17:52:52.661 DEBUG (MainThread) [switchbot.devices.device] (LOCKMACADDR): Sending command: 570000000f210381 2023-05-16 17:52:52.760 DEBUG (MainThread) [switchbot.devices.device] (LOCKMACADDR): Notification received: 010000007cd70c72c1e596bbb70fe0bc0b8709b7 2023-05-16 17:52:52.761 DEBUG (MainThread) [switchbot.devices.device] (LOCKMACADDR): Scheduling command 57817cd79796c03693e48941 2023-05-16 17:52:52.762 DEBUG (MainThread) [switchbot.devices.device] (LOCKMACADDR): Already connected before obtaining lock, resetting timer; RSSI: -79 2023-05-16 17:52:52.762 DEBUG (MainThread) [switchbot.devices.device] (LOCKMACADDR): Sending command: 57817cd79796c03693e48941 2023-05-16 17:52:52.860 DEBUG (MainThread) [switchbot.devices.device] (LOCKMACADDR): Notification received: 01817cd7 2023-05-16 17:52:52.861 DEBUG (MainThread) [switchbot.devices.device] (LOCKMACADDR): Scheduling command 57817cd796d9c1298364 2023-05-16 17:52:52.861 DEBUG (MainThread) [switchbot.devices.device] (LOCKMACADDR): Already connected before obtaining lock, resetting timer; RSSI: -79 2023-05-16 17:52:52.862 DEBUG (MainThread) [switchbot.devices.device] (LOCKMACADDR): Sending command: 57817cd796d9c1298364 2023-05-16 17:52:53.060 DEBUG (MainThread) [switchbot.devices.device] (LOCKMACADDR): Notification received: 01817cd72b0254bf93 2023-05-16 17:52:53.062 DEBUG (MainThread) [switchbot.devices.device] (LOCKMACADDR): Scheduling command 57817cd79b 2023-05-16 17:52:53.063 DEBUG (MainThread) [switchbot.devices.device] (LOCKMACADDR): Already connected before obtaining lock, resetting timer; RSSI: -79 2023-05-16 17:52:53.063 DEBUG (MainThread) [switchbot.devices.device] (LOCKMACADDR): Sending command: 57817cd79b 2023-05-16 17:52:53.111 DEBUG (MainThread) [switchbot.devices.device] (LOCKMACADDR): Fire callbacks 2023-05-16 17:52:53.160 DEBUG (MainThread) [switchbot.devices.device] (LOCKMACADDR): Notification received: 01817cd7fbd6c42893e4 2023-05-16 17:52:53.162 DEBUG (MainThread) [switchbot.devices.device] (LOCKMACADDR): Fire callbacks 2023-05-16 17:52:54.419 DEBUG (MainThread) [switchbot.adv_parsers.lock] mfr_data: c189444b2ba5ebb30820 2023-05-16 17:52:54.419 DEBUG (MainThread) [switchbot.adv_parsers.lock] data: 6f8062 2023-05-16 17:52:58.261 DEBUG (MainThread) [switchbot.devices.device] (LOCKMACADDR): Fire callbacks 2023-05-16 17:52:59.012 DEBUG (MainThread) [switchbot.devices.device] (LOCKMACADDR): Scheduling command 57817cd796d9c12983e4 2023-05-16 17:52:59.012 DEBUG (MainThread) [switchbot.devices.device] (LOCKMACADDR): Already connected before obtaining lock, resetting timer; RSSI: -79 2023-05-16 17:52:59.012 DEBUG (MainThread) [switchbot.devices.device] (LOCKMACADDR): Sending command: 57817cd796d9c12983e4 2023-05-16 17:52:59.160 DEBUG (MainThread) [switchbot.devices.device] (LOCKMACADDR): Notification received: 01817cd7390a54bf93 2023-05-16 17:52:59.162 DEBUG (MainThread) [switchbot.devices.device] (LOCKMACADDR): Scheduling command 57817cd79b 2023-05-16 17:52:59.162 DEBUG (MainThread) [switchbot.devices.device] (LOCKMACADDR): Already connected before obtaining lock, resetting timer; RSSI: -79 2023-05-16 17:52:59.162 DEBUG (MainThread) [switchbot.devices.device] (LOCKMACADDR): Sending command: 57817cd79b 2023-05-16 17:52:59.163 DEBUG (MainThread) [switchbot.devices.device] (LOCKMACADDR): Fire callbacks 2023-05-16 17:52:59.260 DEBUG (MainThread) [switchbot.devices.device] (LOCKMACADDR): Notification received: 01817cd7fbd6c42893e4 2023-05-16 17:52:59.261 DEBUG (MainThread) [switchbot.devices.device] (LOCKMACADDR): Fire callbacks 2023-05-16 17:53:02.103 DEBUG (MainThread) [switchbot.adv_parsers.lock] mfr_data: c189444b2ba5eda30820 2023-05-16 17:53:02.103 DEBUG (MainThread) [switchbot.adv_parsers.lock] data: 6f8062 2023-05-16 17:53:03.961 DEBUG (MainThread) [switchbot.devices.device] (LOCKMACADDR): Fire callbacks 2023-05-16 17:53:07.219 DEBUG (MainThread) [switchbot.adv_parsers.lock] mfr_data: c189444b2ba5ee830820 2023-05-16 17:53:07.219 DEBUG (MainThread) [switchbot.adv_parsers.lock] data: 6f8062 2023-05-16 17:53:12.462 DEBUG (MainThread) [switchbot.devices.device] (LOCKMACADDR): Executing timed disconnect after timeout of 8.5 2023-05-16 17:53:12.462 DEBUG (MainThread) [switchbot.devices.device] (LOCKMACADDR): Executing disconnect 2023-05-16 17:53:12.462 DEBUG (MainThread) [switchbot.devices.device] (LOCKMACADDR): Executing disconnect with lock 2023-05-16 17:53:12.462 DEBUG (MainThread) [switchbot.devices.device] (LOCKMACADDR): Disconnecting 2023-05-16 17:53:14.912 DEBUG (MainThread) [switchbot.devices.device] (LOCKMACADDR): Disconnected from device; RSSI: -79 2023-05-16 17:53:14.913 DEBUG (MainThread) [switchbot.devices.device] (LOCKMACADDR): Disconnect completed successfullyAdditional information
No response
The text was updated successfully, but these errors were encountered: