search

home-assistant / core

:house_with_garden: Open source home automation that puts local control and privacy first.
https://www.home-assistant.io
Apache License 2.0
72.48k stars 30.33k forks source link

Lock SwitchBot Bluetooth connection takes a long time when using local adapter but OK with proxy #93171

Closed KitHubek closed 1 year ago

KitHubek commented 1 year ago

The problem

@bdraco

Iam using HA with Yours fix esphome folder in dir custom component and all as i wrote in this https://github.com/home-assistant/core/issues/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 successfully

Additional information

No response

KitHubek commented 1 year ago

System Information

version core-2023.5.4
installation_type Home Assistant OS
dev false
hassio true
docker true
user root
virtualenv false
python_version 3.10.11
os_name Linux
os_version 6.1.25
arch x86_64
timezone Europe/Warsaw
config_dir /config
Home Assistant Community Store GitHub API | ok -- | -- GitHub Content | ok GitHub Web | ok GitHub API Calls Remaining | 4850 Installed Version | 1.32.1 Stage | running Available Repositories | 1282 Downloaded Repositories | 7
Home Assistant Cloud logged_in | false -- | -- can_reach_cert_server | ok can_reach_cloud_auth | ok can_reach_cloud | ok
GIOŚ can_reach_server | ok -- | --
Home Assistant Supervisor host_os | Home Assistant OS 10.1 -- | -- update_channel | stable supervisor_version | supervisor-2023.04.1 agent_version | 1.5.1 docker_version | 23.0.3 disk_total | 234.0 GB disk_used | 39.6 GB healthy | true supported | true board | generic-x86-64 supervisor_api | ok version_api | ok installed_addons | Studio Code Server (5.6.1), Mosquitto broker (6.2.1), Samba share (10.0.2), Duck DNS (1.15.0), NGINX Home Assistant SSL proxy (3.5.0), Zigbee2MQTT (1.30.4-1), Terminal & SSH (9.7.0), ESPHome (2023.5.5), MariaDB (2.6.1), Advanced SSH & Web Terminal (15.0.2)
Dashboards dashboards | 6 -- | -- resources | 4 views | 26 mode | storage
Recorder oldest_recorder_run | 7 maja 2023 10:14 -- | -- current_recorder_run | 29 maja 2023 23:24 estimated_db_size | 4542.75 MiB database_engine | mysql database_version | 10.6.12
Spotify api_endpoint_reachable | ok -- | --
KitHubek commented 1 year ago

@bdraco

today i made test. I disabled all integrations, all devices. Stays onlu Supervisor, reboot HA and run in terminal py-spy command as below:

pyspytermina

and HA freeze and after about 10 minutes rebooted But when HA freeze i connect to HA host via ssh and done top command, because i think that CPUI usage will 100% and host will unresponsive, byt NOT. I can connect cia ssh, and CPU usage is very low. See screen below:

pyspyTOP

KitHubek commented 1 year ago

@bdraco

after update HA to 2023.6.0 py-spy working!

here is svg file after command:

./py-spy record --pid 66 --rate 10 --duration 60 --output spy.svg

spy

bdraco commented 1 year ago

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

KitHubek commented 1 year ago

ok @bdraco done with sample: 100 150 200 500

pyspy_test.zip

bdraco commented 1 year ago

The websocket looks a bit busy. If you open the inspector panel in your browser, how fast are the messages coming in?

KitHubek commented 1 year ago

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

bdraco commented 1 year ago
Screenshot 2023-06-08 at 4 25 59 PM

In the network tab, find the websocket. You can look at the messages come over.

You may need to shift + reload to get it to appear

KitHubek commented 1 year ago

ok, this load right away. i cant see any delay

Adnotacja 2023-06-08 234740

bdraco commented 1 year ago

I think the problem is likely higher up the bluetooth stack in bluez or bleak

I just found https://github.com/hbldh/bleak/pull/1329 but there seems to be more issues

bdraco commented 1 year ago

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

KitHubek commented 1 year ago

ok, thanks for this work. But is main question: What now? What next? Lock working ok with only btproxy but, as You know, this is another device, another power plug, another wifi ora lan client. This is not the same as local bt adapter plugged into HA hardware.

big thanks

bdraco commented 1 year ago

https://github.com/hbldh/bleak/pull/1329 will fix the cases where we wait the whole timeout for the device to reappear

bdraco commented 1 year ago

https://github.com/home-assistant/core/pull/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.