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
73.68k stars 30.81k forks source link

Switchbot Lock very slow response #92370

Closed wardwolfram closed 1 year ago

wardwolfram commented 1 year ago

The problem

I re-installed HA with the latest code. Most things work very well on this 'clean' system, but my Switchbot Lock is very slow to respond to a un/lock command. Responses range from 10-20 seconds after a command is issued.

If I immediately issue another un/lock command, the response if quick. In summary, it seems that the lock sleeps after a bit when no commands are issued to it.

Also, my previous installation had no issues with the delay in response. I was running 1-2 versions back I believe?

I have tried re-installing hardware and software with the same results. Switchbot reported back to me stating that this is a Home Assistant issue.

What version of Home Assistant Core has the issue?

core-2023.4.6

What was the last working version of Home Assistant Core?

1 or 2 versions behind

What type of installation are you running?

Home Assistant OS

Integration causing the issue

Switchbot

Link to integration documentation on our website

https://www.home-assistant.io/integrations/switchbot/

Diagnostics information

No diagnostic download available for the Switchbot integration.

Example YAML snippet

type: entities
entities:
  - entity: lock.lock_69b3
state_color: true
title: Front Door Lock
show_header_toggle: false

Anything in the logs that might be useful for us?

Nothing reported in the logs.

Additional information

The lock unlocks/lock with out errors, but the issue is the delay in response making the unit almost unusable.

home-assistant[bot] commented 1 year ago

Hey there @bdraco, @danielhiversen, @renierm26, @murtas, @eloston, @dsypniewski, mind taking a look at this issue as it has been labeled with an integration (switchbot) you are listed as a code owner for? Thanks!

Code owner commands Code owners of `switchbot` can trigger bot actions by commenting: - `@home-assistant close` Closes the issue. - `@home-assistant rename Awesome new title` Renames the issue. - `@home-assistant reopen` Reopen the issue. - `@home-assistant unassign switchbot` Removes the current integration label and assignees on the issue, add the integration domain after the command.

(message by CodeOwnersMention)

switchbot documentation switchbot source (message by IssueLinks)

KitHubek commented 1 year ago

welcome to the club. Same for me since March HA version. https://github.com/home-assistant/core/issues/90265

andiukas commented 1 year ago

i had the same problem, additional external bluetooth helped

wardwolfram commented 1 year ago

A bit more information. My Bluetooth adapter is: XDO Class 1 USB Bluetooth Adapter which is listed as supported in the HA documentation. Also, it is positioned ~ 2ft away from the PC via a usb cable to avoid any interference.

The major change in my re-implementation of my smart home is the latest version of HA. I am using the same hardware and most of the same integrations. Rebooted numerous times. HA is still/yet installed in a virtualbox VM.

Thanks in advance for looking into this issue.

bdraco commented 1 year ago

A bit more information. My Bluetooth adapter is: XDO Class 1 USB Bluetooth Adapter which is listed as supported in the HA documentation.

That adapter is expected to be very slow. It’s not on the high performance list

wardwolfram commented 1 year ago

Thanks for the feedback. The XDO performed near immediately before the re-install. I will try another and report my findings.

bdraco commented 1 year ago

It’s hit or miss based on interference and number of devices in the area. For some users is fine for others it’s bad today and good tomorrow. The high performance ones work consistently

wardwolfram commented 1 year ago

I have installed an Avantree BTDG-40S (High-performance adapters) into HA and the Switchbot Lock is behaving the same. If sitting idle for a bit, ~15-20second delay. What direction would you try at this point if you were in my shoes? Are there other options or tests that may lead me to a solution? Thanks much in advance.

bdraco commented 1 year ago

Turn on debug logs for

switchbot bleak_retry_connector

https://www.home-assistant.io/integrations/logger/

Than lock and unlock the log and post the full log

wardwolfram commented 1 year ago

I do not understand YAML instructions well. Do I enter this into the configuration.yaml file?

logger: logs: switchbot bleak_retry_connector: debug

wardwolfram commented 1 year ago

logger: logs: switchbot bleak_retry_connector: debug

wardwolfram commented 1 year ago

the indentation does not take here....

bdraco commented 1 year ago 
# Example configuration.yaml entry
logger:
  default: info
  logs:
    bleak_retry_connector: debug
    switchbot: debug
wardwolfram commented 1 year ago

I'll let the lock sit idle for a bit to reproduce the issue and post. Thanks for taking a look at this.

wardwolfram commented 1 year ago

I think I figured getting the logs. Also, note - the lock has been very responsive the past 2 hours, without the ~15 second delay as noticed earlier. The attached logs are from a 'very good' response time from command to locking/unlocking. I'll try to gather bad behavior soon. Anything odd about the logs here?

2023-05-05 16:48:50.568 DEBUG (MainThread) [switchbot.devices.device] WoLock (F0:3F:66:45:69:B3): Scheduling command 570000000f2103a0 2023-05-05 16:48:50.570 DEBUG (MainThread) [switchbot.devices.device] WoLock (F0:3F:66:45:69:B3): Connecting; RSSI: -58 2023-05-05 16:48:51.195 DEBUG (MainThread) [switchbot.devices.device] WoLock (F0:3F:66:45:69:B3): Connected; RSSI: -58 2023-05-05 16:48:51.196 DEBUG (MainThread) [switchbot.devices.device] WoLock (F0:3F:66:45:69:B3): Starting notify and disconnect timer; RSSI: -58 2023-05-05 16:48:51.196 DEBUG (MainThread) [switchbot.devices.device] WoLock (F0:3F:66:45:69:B3): Subscribe to notifications; RSSI: -58 2023-05-05 16:48:51.835 DEBUG (MainThread) [switchbot.devices.device] WoLock (F0:3F:66:45:69:B3): Sending command: 570000000f2103a0 2023-05-05 16:48:51.933 DEBUG (MainThread) [switchbot.devices.device] WoLock (F0:3F:66:45:69:B3): Notification received: 01000000f400057f02f9fe39e8f81745fb4b60bf 2023-05-05 16:48:51.935 DEBUG (MainThread) [switchbot.devices.device] WoLock (F0:3F:66:45:69:B3): Scheduling command 57a0f4000a187b52daa95e7c 2023-05-05 16:48:51.936 DEBUG (MainThread) [switchbot.devices.device] WoLock (F0:3F:66:45:69:B3): Already connected before obtaining lock, resetting timer; RSSI: -58 2023-05-05 16:48:51.936 DEBUG (MainThread) [switchbot.devices.device] WoLock (F0:3F:66:45:69:B3): Sending command: 57a0f4000a187b52daa95e7c 2023-05-05 16:48:52.083 DEBUG (MainThread) [switchbot.devices.device] WoLock (F0:3F:66:45:69:B3): Received unsolicited notification: bytearray(b'\x0f\xa0\xf4\x00\x84\x11\x1e\x17H\xa9\xdf}\x9f{\xe6\x1fL\x88') 2023-05-05 16:48:52.084 DEBUG (MainThread) [switchbot.devices.device] WoLock (F0:3F:66:45:69:B3): Notification received: 01a0f400 2023-05-05 16:48:52.085 DEBUG (MainThread) [switchbot.devices.device] WoLock (F0:3F:66:45:69:B3): Scheduling command 57a0f4000b577a4dca29 2023-05-05 16:48:52.086 DEBUG (MainThread) [switchbot.devices.device] WoLock (F0:3F:66:45:69:B3): Already connected before obtaining lock, resetting timer; RSSI: -58 2023-05-05 16:48:52.086 DEBUG (MainThread) [switchbot.devices.device] WoLock (F0:3F:66:45:69:B3): Sending command: 57a0f4000b577a4dca29 2023-05-05 16:48:52.182 DEBUG (MainThread) [switchbot.devices.device] WoLock (F0:3F:66:45:69:B3): Notification received: 01a0f400b44320deda 2023-05-05 16:48:52.184 DEBUG (MainThread) [switchbot.devices.device] WoLock (F0:3F:66:45:69:B3): Scheduling command 57a0f40006 2023-05-05 16:48:52.184 DEBUG (MainThread) [switchbot.devices.device] WoLock (F0:3F:66:45:69:B3): Already connected before obtaining lock, resetting timer; RSSI: -58 2023-05-05 16:48:52.185 DEBUG (MainThread) [switchbot.devices.device] WoLock (F0:3F:66:45:69:B3): Sending command: 57a0f40006 2023-05-05 16:48:52.282 DEBUG (MainThread) [switchbot.devices.device] WoLock (F0:3F:66:45:69:B3): Notification received: 01a0f40060587f4cdaa9 2023-05-05 16:48:52.284 DEBUG (MainThread) [switchbot.devices.device] WoLock (F0:3F:66:45:69:B3): Fire callbacks 2023-05-05 16:48:52.383 DEBUG (MainThread) [switchbot.devices.device] WoLock (F0:3F:66:45:69:B3): Fire callbacks 2023-05-05 16:48:54.183 DEBUG (MainThread) [switchbot.devices.device] WoLock (F0:3F:66:45:69:B3): Fire callbacks 2023-05-05 16:48:55.046 DEBUG (MainThread) [switchbot.devices.device] WoLock (F0:3F:66:45:69:B3): Scheduling command 57a0f4000b577a4dcaa9 2023-05-05 16:48:55.047 DEBUG (MainThread) [switchbot.devices.device] WoLock (F0:3F:66:45:69:B3): Already connected before obtaining lock, resetting timer; RSSI: -58 2023-05-05 16:48:55.047 DEBUG (MainThread) [switchbot.devices.device] WoLock (F0:3F:66:45:69:B3): Sending command: 57a0f4000b577a4dcaa9 2023-05-05 16:48:55.131 DEBUG (MainThread) [switchbot.devices.device] WoLock (F0:3F:66:45:69:B3): Notification received: 01a0f400a68a20deda 2023-05-05 16:48:55.133 DEBUG (MainThread) [switchbot.devices.device] WoLock (F0:3F:66:45:69:B3): Scheduling command 57a0f40006 2023-05-05 16:48:55.133 DEBUG (MainThread) [switchbot.devices.device] WoLock (F0:3F:66:45:69:B3): Already connected before obtaining lock, resetting timer; RSSI: -58 2023-05-05 16:48:55.134 DEBUG (MainThread) [switchbot.devices.device] WoLock (F0:3F:66:45:69:B3): Sending command: 57a0f40006 2023-05-05 16:48:55.232 DEBUG (MainThread) [switchbot.devices.device] WoLock (F0:3F:66:45:69:B3): Notification received: 01a0f40060587f4cdaa9 2023-05-05 16:48:55.232 DEBUG (MainThread) [switchbot.devices.device] WoLock (F0:3F:66:45:69:B3): Fire callbacks 2023-05-05 16:48:55.533 DEBUG (MainThread) [switchbot.devices.device] WoLock (F0:3F:66:45:69:B3): Fire callbacks 2023-05-05 16:48:57.182 DEBUG (MainThread) [switchbot.devices.device] WoLock (F0:3F:66:45:69:B3): Fire callbacks

Shahzadimalik commented 1 year ago

Block all

On Sat, 6 May 2023, 2:58 am wardwolfram, @.***> wrote:

I think I figured getting the logs. Also, note - the lock has been very responsive the past 2 hours, without the ~15 second delay as noticed earlier. The attached logs are from a 'very good' response time from command to locking/unlocking. I'll try to gather bad behavior soon. Anything odd about the logs here?

2023-05-05 16:48:50.568 DEBUG (MainThread) [switchbot.devices.device] WoLock (F0:3F:66:45:69:B3): Scheduling command 570000000f2103a0 2023-05-05 16:48:50.570 DEBUG (MainThread) [switchbot.devices.device] WoLock (F0:3F:66:45:69:B3): Connecting; RSSI: -58 2023-05-05 16:48:51.195 DEBUG (MainThread) [switchbot.devices.device] WoLock (F0:3F:66:45:69:B3): Connected; RSSI: -58 2023-05-05 16:48:51.196 DEBUG (MainThread) [switchbot.devices.device] WoLock (F0:3F:66:45:69:B3): Starting notify and disconnect timer; RSSI: -58 2023-05-05 16:48:51.196 DEBUG (MainThread) [switchbot.devices.device] WoLock (F0:3F:66:45:69:B3): Subscribe to notifications; RSSI: -58 2023-05-05 16:48:51.835 DEBUG (MainThread) [switchbot.devices.device] WoLock (F0:3F:66:45:69:B3): Sending command: 570000000f2103a0 2023-05-05 16:48:51.933 DEBUG (MainThread) [switchbot.devices.device] WoLock (F0:3F:66:45:69:B3): Notification received: 01000000f400057f02f9fe39e8f81745fb4b60bf 2023-05-05 16:48:51.935 DEBUG (MainThread) [switchbot.devices.device] WoLock (F0:3F:66:45:69:B3): Scheduling command 57a0f4000a187b52daa95e7c 2023-05-05 16:48:51.936 DEBUG (MainThread) [switchbot.devices.device] WoLock (F0:3F:66:45:69:B3): Already connected before obtaining lock, resetting timer; RSSI: -58 2023-05-05 16:48:51.936 DEBUG (MainThread) [switchbot.devices.device] WoLock (F0:3F:66:45:69:B3): Sending command: 57a0f4000a187b52daa95e7c 2023-05-05 16:48:52.083 DEBUG (MainThread) [switchbot.devices.device] WoLock (F0:3F:66:45:69:B3): Received unsolicited notification: bytearray(b'\x0f\xa0\xf4\x00\x84\x11\x1e\x17H\xa9\xdf}\x9f{\xe6\x1fL\x88') 2023-05-05 16:48:52.084 DEBUG (MainThread) [switchbot.devices.device] WoLock (F0:3F:66:45:69:B3): Notification received: 01a0f400 2023-05-05 16:48:52.085 DEBUG (MainThread) [switchbot.devices.device] WoLock (F0:3F:66:45:69:B3): Scheduling command 57a0f4000b577a4dca29 2023-05-05 16:48:52.086 DEBUG (MainThread) [switchbot.devices.device] WoLock (F0:3F:66:45:69:B3): Already connected before obtaining lock, resetting timer; RSSI: -58 2023-05-05 16:48:52.086 DEBUG (MainThread) [switchbot.devices.device] WoLock (F0:3F:66:45:69:B3): Sending command: 57a0f4000b577a4dca29 2023-05-05 16:48:52.182 DEBUG (MainThread) [switchbot.devices.device] WoLock (F0:3F:66:45:69:B3): Notification received: 01a0f400b44320deda 2023-05-05 16:48:52.184 DEBUG (MainThread) [switchbot.devices.device] WoLock (F0:3F:66:45:69:B3): Scheduling command 57a0f40006 2023-05-05 16:48:52.184 DEBUG (MainThread) [switchbot.devices.device] WoLock (F0:3F:66:45:69:B3): Already connected before obtaining lock, resetting timer; RSSI: -58 2023-05-05 16:48:52.185 DEBUG (MainThread) [switchbot.devices.device] WoLock (F0:3F:66:45:69:B3): Sending command: 57a0f40006 2023-05-05 16:48:52.282 DEBUG (MainThread) [switchbot.devices.device] WoLock (F0:3F:66:45:69:B3): Notification received: 01a0f40060587f4cdaa9 2023-05-05 16:48:52.284 DEBUG (MainThread) [switchbot.devices.device] WoLock (F0:3F:66:45:69:B3): Fire callbacks 2023-05-05 16:48:52.383 DEBUG (MainThread) [switchbot.devices.device] WoLock (F0:3F:66:45:69:B3): Fire callbacks 2023-05-05 16:48:54.183 DEBUG (MainThread) [switchbot.devices.device] WoLock (F0:3F:66:45:69:B3): Fire callbacks 2023-05-05 16:48:55.046 DEBUG (MainThread) [switchbot.devices.device] WoLock (F0:3F:66:45:69:B3): Scheduling command 57a0f4000b577a4dcaa9 2023-05-05 16:48:55.047 DEBUG (MainThread) [switchbot.devices.device] WoLock (F0:3F:66:45:69:B3): Already connected before obtaining lock, resetting timer; RSSI: -58 2023-05-05 16:48:55.047 DEBUG (MainThread) [switchbot.devices.device] WoLock (F0:3F:66:45:69:B3): Sending command: 57a0f4000b577a4dcaa9 2023-05-05 16:48:55.131 DEBUG (MainThread) [switchbot.devices.device] WoLock (F0:3F:66:45:69:B3): Notification received: 01a0f400a68a20deda 2023-05-05 16:48:55.133 DEBUG (MainThread) [switchbot.devices.device] WoLock (F0:3F:66:45:69:B3): Scheduling command 57a0f40006 2023-05-05 16:48:55.133 DEBUG (MainThread) [switchbot.devices.device] WoLock (F0:3F:66:45:69:B3): Already connected before obtaining lock, resetting timer; RSSI: -58 2023-05-05 16:48:55.134 DEBUG (MainThread) [switchbot.devices.device] WoLock (F0:3F:66:45:69:B3): Sending command: 57a0f40006 2023-05-05 16:48:55.232 DEBUG (MainThread) [switchbot.devices.device] WoLock (F0:3F:66:45:69:B3): Notification received: 01a0f40060587f4cdaa9 2023-05-05 16:48:55.232 DEBUG (MainThread) [switchbot.devices.device] WoLock (F0:3F:66:45:69:B3): Fire callbacks 2023-05-05 16:48:55.533 DEBUG (MainThread) [switchbot.devices.device] WoLock (F0:3F:66:45:69:B3): Fire callbacks 2023-05-05 16:48:57.182 DEBUG (MainThread) [switchbot.devices.device] WoLock (F0:3F:66:45:69:B3): Fire callbacks

— Reply to this email directly, view it on GitHub https://github.com/home-assistant/core/issues/92370#issuecomment-1536826187, or unsubscribe https://github.com/notifications/unsubscribe-auth/A6XBKUA3IUN2NKSAEZQVRMDXEVZ2BANCNFSM6AAAAAAXTPGJVM . You are receiving this because you are subscribed to this thread.Message ID: @.***>

bdraco commented 1 year ago

That log looks good but its only a partial log so its hard to give you feedback without the full log

KitHubek commented 1 year ago

@bdraco

I added this to my conf:

logger: default: info logs: bleak_retry_connector: debug switchbot: debug

And below is log when lock not response. And i have to open it via key. 

2023-05-06 13:22:17.650 DEBUG (MainThread) [switchbot.devices.device]  (LO:CK:MA:CA:DD:RE:SS): Scheduling command 570000000f210381
2023-05-06 13:22:17.650 DEBUG (MainThread) [switchbot.devices.device]  (LO:CK:MA:CA:DD:RE:SS): Connecting; RSSI: -77
2023-05-06 13:22:17.650 DEBUG (MainThread) [bleak_retry_connector]  (LO:CK:MA:CA:DD:RE:SS) - LO:CK:MA:CA:DD:RE:SS: Connection attempt: 1
2023-05-06 13:22:30.833 DEBUG (MainThread) [switchbot.devices.device]  (LO:CK:MA:CA:DD:RE:SS): Scheduling command 570000000f210381
2023-05-06 13:22:30.833 DEBUG (MainThread) [switchbot.devices.device]  (LO:CK:MA:CA:DD:RE:SS): Operation already in progress, waiting for it to complete; RSSI: -77
2023-05-06 13:22:36.542 DEBUG (MainThread) [switchbot.adv_parsers.lock] mfr_data: c189444b2ba5f6930020
2023-05-06 13:22:36.542 DEBUG (MainThread) [switchbot.adv_parsers.lock] data: 6f8062
2023-05-06 13:22:38.516 DEBUG (MainThread) [switchbot.adv_parsers.lock] mfr_data: c189444b2ba5f7970020
2023-05-06 13:22:38.516 DEBUG (MainThread) [switchbot.adv_parsers.lock] data: 6f8062
2023-05-06 13:22:42.657 DEBUG (MainThread) [bleak_retry_connector]  (LO:CK:MA:CA:DD:RE:SS) - LO:CK:MA:CA:DD:RE:SS: Timed out trying to connect (attempt: 1, last rssi: None)
2023-05-06 13:22:42.908 DEBUG (MainThread) [bleak_retry_connector]  (LO:CK:MA:CA:DD:RE:SS) - LO:CK:MA:CA:DD:RE:SS: Connection attempt: 2
2023-05-06 13:22:53.482 DEBUG (MainThread) [switchbot.adv_parsers.lock] mfr_data: c189444b2ba5f9a30420
2023-05-06 13:22:53.483 DEBUG (MainThread) [switchbot.adv_parsers.lock] data: 6f8062
2023-05-06 13:22:55.372 DEBUG (MainThread) [switchbot.adv_parsers.lock] mfr_data: c189444b2ba5fa830420
2023-05-06 13:22:55.372 DEBUG (MainThread) [switchbot.adv_parsers.lock] data: 6f8062
2023-05-06 13:23:07.912 DEBUG (MainThread) [bleak_retry_connector]  (LO:CK:MA:CA:DD:RE:SS) - LO:CK:MA:CA:DD:RE:SS: Timed out trying to connect (attempt: 2, last rssi: None)
2023-05-06 13:23:08.163 DEBUG (MainThread) [bleak_retry_connector]  (LO:CK:MA:CA:DD:RE:SS) - LO:CK:MA:CA:DD:RE:SS: Connection attempt: 3
2023-05-06 13:23:08.639 DEBUG (MainThread) [switchbot.devices.device]  (LO:CK:MA:CA:DD:RE:SS): Connected; RSSI: -77
2023-05-06 13:23:08.639 DEBUG (MainThread) [switchbot.devices.device]  (LO:CK:MA:CA:DD:RE:SS): Starting notify and disconnect timer; RSSI: -77
2023-05-06 13:23:08.639 DEBUG (MainThread) [switchbot.devices.device]  (LO:CK:MA:CA:DD:RE:SS): Subscribe to notifications; RSSI: -77
2023-05-06 13:23:08.673 DEBUG (MainThread) [switchbot.devices.device]  (LO:CK:MA:CA:DD:RE:SS): Sending command: 570000000f210381
2023-05-06 13:23:08.875 DEBUG (MainThread) [switchbot.devices.device]  (LO:CK:MA:CA:DD:RE:SS): Notification received: 010000002f944e5ccf7cc9d3c3e1d846b1f9fcb7
2023-05-06 13:23:08.876 DEBUG (MainThread) [switchbot.devices.device]  (LO:CK:MA:CA:DD:RE:SS): Scheduling command 57812f94db7470583155a807
2023-05-06 13:23:08.877 DEBUG (MainThread) [switchbot.devices.device]  (LO:CK:MA:CA:DD:RE:SS): Already connected before obtaining lock, resetting timer; RSSI: -77
2023-05-06 13:23:08.877 DEBUG (MainThread) [switchbot.devices.device]  (LO:CK:MA:CA:DD:RE:SS): Sending command: 570000000f210381
2023-05-06 13:23:09.360 DEBUG (MainThread) [switchbot.devices.device]  (LO:CK:MA:CA:DD:RE:SS): Notification received: 010000002f944e5ccf7cc9d3c3e1d846b1f9fcb7
2023-05-06 13:23:09.362 DEBUG (MainThread) [switchbot.devices.device]  (LO:CK:MA:CA:DD:RE:SS): Scheduling command 57812f94db7470583155a807
2023-05-06 13:23:09.364 DEBUG (MainThread) [switchbot.devices.device]  (LO:CK:MA:CA:DD:RE:SS): Already connected before obtaining lock, resetting timer; RSSI: -77
2023-05-06 13:23:09.364 DEBUG (MainThread) [switchbot.devices.device]  (LO:CK:MA:CA:DD:RE:SS): Sending command: 57812f94db7470583155a807
2023-05-06 13:23:09.462 DEBUG (MainThread) [switchbot.devices.device]  (LO:CK:MA:CA:DD:RE:SS): Received unsolicited notification: bytearray(b'\x0f\x81/\x94Wp\xe5\xd2\xa6U)\x06\xd5\xd3\xd6\x9eX\xe2')
2023-05-06 13:23:09.463 DEBUG (MainThread) [switchbot.devices.device]  (LO:CK:MA:CA:DD:RE:SS): Notification received: 01812f94
2023-05-06 13:23:09.465 DEBUG (MainThread) [switchbot.devices.device]  (LO:CK:MA:CA:DD:RE:SS): Scheduling command 57812f94da3b714721d5
2023-05-06 13:23:09.465 DEBUG (MainThread) [switchbot.devices.device]  (LO:CK:MA:CA:DD:RE:SS): Already connected before obtaining lock, resetting timer; RSSI: -77
2023-05-06 13:23:09.466 DEBUG (MainThread) [switchbot.devices.device]  (LO:CK:MA:CA:DD:RE:SS): Sending command: 57812f94db7470583155a807
2023-05-06 13:23:09.557 DEBUG (MainThread) [switchbot.devices.device]  (LO:CK:MA:CA:DD:RE:SS): Notification received: 01812f94
2023-05-06 13:23:09.558 DEBUG (MainThread) [switchbot.devices.device]  (LO:CK:MA:CA:DD:RE:SS): Scheduling command 57812f94da3b714721d5
2023-05-06 13:23:09.558 DEBUG (MainThread) [switchbot.devices.device]  (LO:CK:MA:CA:DD:RE:SS): Already connected before obtaining lock, resetting timer; RSSI: -77
2023-05-06 13:23:09.558 DEBUG (MainThread) [switchbot.devices.device]  (LO:CK:MA:CA:DD:RE:SS): Sending command: 57812f94da3b714721d5
2023-05-06 13:23:09.759 DEBUG (MainThread) [switchbot.devices.device]  (LO:CK:MA:CA:DD:RE:SS): Notification received: 01812f9467e0e4d131
2023-05-06 13:23:09.760 DEBUG (MainThread) [switchbot.devices.device]  (LO:CK:MA:CA:DD:RE:SS): Scheduling command 57812f94d7
2023-05-06 13:23:09.762 DEBUG (MainThread) [switchbot.devices.device]  (LO:CK:MA:CA:DD:RE:SS): Already connected before obtaining lock, resetting timer; RSSI: -77
2023-05-06 13:23:09.762 DEBUG (MainThread) [switchbot.devices.device]  (LO:CK:MA:CA:DD:RE:SS): Sending command: 57812f94da3b714721d5
2023-05-06 13:23:09.995 DEBUG (MainThread) [switchbot.devices.device]  (LO:CK:MA:CA:DD:RE:SS): Notification received: 01812f9467e0e4d131
2023-05-06 13:23:09.998 DEBUG (MainThread) [switchbot.devices.device]  (LO:CK:MA:CA:DD:RE:SS): Scheduling command 57812f94d7
2023-05-06 13:23:09.999 DEBUG (MainThread) [switchbot.devices.device]  (LO:CK:MA:CA:DD:RE:SS): Already connected before obtaining lock, resetting timer; RSSI: -77
2023-05-06 13:23:09.999 DEBUG (MainThread) [switchbot.devices.device]  (LO:CK:MA:CA:DD:RE:SS): Sending command: 57812f94d7
2023-05-06 13:23:10.087 DEBUG (MainThread) [switchbot.devices.device]  (LO:CK:MA:CA:DD:RE:SS): Fire callbacks
2023-05-06 13:23:10.270 DEBUG (MainThread) [switchbot.devices.device]  (LO:CK:MA:CA:DD:RE:SS): Notification received: 01812f94b73474463155
2023-05-06 13:23:10.271 DEBUG (MainThread) [switchbot.devices.device]  (LO:CK:MA:CA:DD:RE:SS): Fire callbacks
2023-05-06 13:23:10.273 DEBUG (MainThread) [switchbot.devices.device]  (LO:CK:MA:CA:DD:RE:SS): Already connected before obtaining lock, resetting timer; RSSI: -77
2023-05-06 13:23:10.273 DEBUG (MainThread) [switchbot.devices.device]  (LO:CK:MA:CA:DD:RE:SS): Sending command: 57812f94d7
2023-05-06 13:23:10.311 DEBUG (MainThread) [switchbot.adv_parsers.lock] mfr_data: c189444b2ba5fbb30820
2023-05-06 13:23:10.312 DEBUG (MainThread) [switchbot.adv_parsers.lock] data: 6f8062
2023-05-06 13:23:10.373 DEBUG (MainThread) [switchbot.devices.device]  (LO:CK:MA:CA:DD:RE:SS): Notification received: 01812f94b73474463155
2023-05-06 13:23:10.374 DEBUG (MainThread) [switchbot.devices.device]  (LO:CK:MA:CA:DD:RE:SS): Fire callbacks
2023-05-06 13:23:14.572 DEBUG (MainThread) [switchbot.devices.device]  (LO:CK:MA:CA:DD:RE:SS): Fire callbacks
2023-05-06 13:23:15.326 DEBUG (MainThread) [switchbot.adv_parsers.lock] mfr_data: c189444b2ba5fc930820
2023-05-06 13:23:15.327 DEBUG (MainThread) [switchbot.adv_parsers.lock] data: 6f8062
2023-05-06 13:23:23.073 DEBUG (MainThread) [switchbot.devices.device]  (LO:CK:MA:CA:DD:RE:SS): Executing timed disconnect after timeout of 8.5
2023-05-06 13:23:23.073 DEBUG (MainThread) [switchbot.devices.device]  (LO:CK:MA:CA:DD:RE:SS): Executing disconnect
2023-05-06 13:23:23.074 DEBUG (MainThread) [switchbot.devices.device]  (LO:CK:MA:CA:DD:RE:SS): Executing disconnect with lock
2023-05-06 13:23:23.074 DEBUG (MainThread) [switchbot.devices.device]  (LO:CK:MA:CA:DD:RE:SS): Disconnecting
2023-05-06 13:23:23.076 DEBUG (MainThread) [switchbot.devices.device]  (LO:CK:MA:CA:DD:RE:SS): Disconnect completed successfully
2023-05-06 13:23:57.811 DEBUG (MainThread) [switchbot.devices.device]  (LO:CK:MA:CA:DD:RE:SS): Scheduling command 570000000f210381
2023-05-06 13:23:57.812 DEBUG (MainThread) [switchbot.devices.device]  (LO:CK:MA:CA:DD:RE:SS): Connecting; RSSI: -77
2023-05-06 13:23:57.812 DEBUG (MainThread) [bleak_retry_connector]  (LO:CK:MA:CA:DD:RE:SS) - LO:CK:MA:CA:DD:RE:SS: Connection attempt: 1
2023-05-06 13:23:58.563 DEBUG (MainThread) [switchbot.devices.device]  (LO:CK:MA:CA:DD:RE:SS): Connected; RSSI: -77
2023-05-06 13:23:58.563 DEBUG (MainThread) [switchbot.devices.device]  (LO:CK:MA:CA:DD:RE:SS): Starting notify and disconnect timer; RSSI: -77
2023-05-06 13:23:58.563 DEBUG (MainThread) [switchbot.devices.device]  (LO:CK:MA:CA:DD:RE:SS): Subscribe to notifications; RSSI: -77
2023-05-06 13:23:58.718 DEBUG (MainThread) [switchbot.devices.device]  (LO:CK:MA:CA:DD:RE:SS): Sending command: 570000000f210381
2023-05-06 13:23:58.918 DEBUG (MainThread) [switchbot.devices.device]  (LO:CK:MA:CA:DD:RE:SS): Notification received: 0100000026d884f80512d90ed64b36673edcd771
2023-05-06 13:23:58.920 DEBUG (MainThread) [switchbot.devices.device]  (LO:CK:MA:CA:DD:RE:SS): Scheduling command 578126d8418fac47c7f12d3b
2023-05-06 13:23:58.920 DEBUG (MainThread) [switchbot.devices.device]  (LO:CK:MA:CA:DD:RE:SS): Already connected before obtaining lock, resetting timer; RSSI: -77
2023-05-06 13:23:58.920 DEBUG (MainThread) [switchbot.devices.device]  (LO:CK:MA:CA:DD:RE:SS): Sending command: 578126d8418fac47c7f12d3b
2023-05-06 13:23:59.142 DEBUG (MainThread) [switchbot.devices.device]  (LO:CK:MA:CA:DD:RE:SS): Received unsolicited notification: bytearray(b'\x0f\x81&\xd8\xdd\x87\x07\xcdP\xf1\xac:\xb8\xb2\x99;\x1c\x94')
2023-05-06 13:23:59.142 DEBUG (MainThread) [switchbot.devices.device]  (LO:CK:MA:CA:DD:RE:SS): Notification received: 018126d8
2023-05-06 13:23:59.143 DEBUG (MainThread) [switchbot.devices.device]  (LO:CK:MA:CA:DD:RE:SS): Scheduling command 578126d840c0ad58d7f1
2023-05-06 13:23:59.144 DEBUG (MainThread) [switchbot.devices.device]  (LO:CK:MA:CA:DD:RE:SS): Already connected before obtaining lock, resetting timer; RSSI: -77
2023-05-06 13:23:59.144 DEBUG (MainThread) [switchbot.devices.device]  (LO:CK:MA:CA:DD:RE:SS): Sending command: 578126d840c0ad58d7f1
2023-05-06 13:23:59.528 DEBUG (MainThread) [switchbot.devices.device]  (LO:CK:MA:CA:DD:RE:SS): Notification received: 018126d8ef1238cec7
2023-05-06 13:23:59.530 DEBUG (MainThread) [switchbot.devices.device]  (LO:CK:MA:CA:DD:RE:SS): Scheduling command 578126d84d
2023-05-06 13:23:59.530 DEBUG (MainThread) [switchbot.devices.device]  (LO:CK:MA:CA:DD:RE:SS): Already connected before obtaining lock, resetting timer; RSSI: -77
2023-05-06 13:23:59.531 DEBUG (MainThread) [switchbot.devices.device]  (LO:CK:MA:CA:DD:RE:SS): Sending command: 578126d84d
2023-05-06 13:23:59.632 DEBUG (MainThread) [switchbot.devices.device]  (LO:CK:MA:CA:DD:RE:SS): Notification received: 018126d82dcfa859c7f1
2023-05-06 13:23:59.632 DEBUG (MainThread) [switchbot.devices.device]  (LO:CK:MA:CA:DD:RE:SS): Fire callbacks
2023-05-06 13:23:59.731 DEBUG (MainThread) [switchbot.devices.device]  (LO:CK:MA:CA:DD:RE:SS): Fire callbacks
2023-05-06 13:24:00.329 DEBUG (MainThread) [switchbot.adv_parsers.lock] mfr_data: c189444b2ba5fda30820
2023-05-06 13:24:00.329 DEBUG (MainThread) [switchbot.adv_parsers.lock] data: 6f8062
2023-05-06 13:24:04.236 DEBUG (MainThread) [switchbot.devices.device]  (LO:CK:MA:CA:DD:RE:SS): Fire callbacks
2023-05-06 13:24:04.408 DEBUG (MainThread) [switchbot.adv_parsers.lock] mfr_data: c189444b2ba5fe830820
2023-05-06 13:24:04.408 DEBUG (MainThread) [switchbot.adv_parsers.lock] data: 6f8062
2023-05-06 13:24:12.737 DEBUG (MainThread) [switchbot.devices.device]  (LO:CK:MA:CA:DD:RE:SS): Executing timed disconnect after timeout of 8.5
2023-05-06 13:24:12.737 DEBUG (MainThread) [switchbot.devices.device]  (LO:CK:MA:CA:DD:RE:SS): Executing disconnect
2023-05-06 13:24:12.737 DEBUG (MainThread) [switchbot.devices.device]  (LO:CK:MA:CA:DD:RE:SS): Executing disconnect with lock
2023-05-06 13:24:12.737 DEBUG (MainThread) [switchbot.devices.device]  (LO:CK:MA:CA:DD:RE:SS): Disconnecting
2023-05-06 13:24:12.739 DEBUG (MainThread) [switchbot.devices.device]  (LO:CK:MA:CA:DD:RE:SS): Disconnect completed successfully

Tested on:

Home Assistant 2023.5.2 Supervisor 2023.04.1 Operating System 10.1 Interface: 20230503.2 - latest ESPHome: 2023.4.4

Situation timeline:

open app, tap open lock waiting tap again waiting nothing happens opened locjk via key enter home lock auto locked after few moment lock unlocked lock it via app it all

wardwolfram commented 1 year ago

@bdraco, the change to the Avantree BTDG-40S adapter did the trick. The SwitchBot Lock now has <1 second response time. Thank you for your time to point me in the right direction. Besides getting things to work with the lock, I now have a better understand troubleshooting and using the logs. Thanks again!

bdraco commented 1 year ago

@wardwolfram Glad it solved for you 👍

bdraco commented 1 year ago

@KitHubek Please copy your comment to your issue and lets continue there. Also please add the logs complete log as 2023-05-06 13:22:30.833 DEBUG (MainThread) [switchbot.devices.device] (LO:CK:MA:CA:DD:RE:SS): Operation already in progress, waiting for it to complete; RSSI: -77 implies the lock was already doing something when you tried to connect and the logs before that line are missing

wardwolfram commented 1 year ago

Hello dbraco, the switchbot lock with the new adapter has become slow again, but not as slow to respond as the initial BT adapter you asked me to swap out. I have changed ports, adapters, and yet, the lock is slow enough to respond to make it very irritating (the performance is inconsistent, at times it will respond within 2 seconds, but more often, the lock responds within 15-20 seconds).

I have read that a BT proxy eliminates this issue. If this is true, what BT proxy would you recommend that I use to help this locks performance? Thanks in advance.

bdraco commented 1 year ago

https://esphome.github.io/bluetooth-proxies/

Olimex ESP32 Power-over-Ethernet ISO has predefined configs above so its very easy to setup.

Personally I use these (but its a manual config) since the relays are useful as well for other tasks for a dual purpose device. I get the ESP32-EVB-EA-IND for the external antenna and better components https://www.olimex.com/Products/IoT/ESP32/ESP32-EVB/open-source-hardware https://www.olimex.com/Products/IoT/ESP32/BOX-ESP32-EVB-EA/

wardwolfram commented 1 year ago

https://esphome.github.io/bluetooth-proxies/

Olimex ESP32 Power-over-Ethernet ISO has predefined configs above so its very easy to setup.

Personally I use these (but its a manual config) since the relays are useful as well for other tasks for a dual purpose device. I get the ESP32-EVB-EA-IND for the external antenna and better components https://www.olimex.com/Products/IoT/ESP32/ESP32-EVB/open-source-hardware https://www.olimex.com/Products/IoT/ESP32/BOX-ESP32-EVB-EA/

I am not versed in YAML, and coding, would this unit be simple to integrate with HA?

bdraco commented 1 year ago

The Olimex ESP32 Power-over-Ethernet ISO unit can be flashed from the website with no yaml knowledge: https://esphome.github.io/bluetooth-proxies/

KitHubek commented 1 year ago

@wardwolfram

sorry to interrupt the conversation, but I am more than 100% sure that replacing the hardware will not solve your problem. I've had the same problem since March and I'm still fighting it. I have already replaced all the hardware: rpi4/8GB for a mini PC, various bluetooth adapters, btProxy from ESP32 chips with wifi to chips with RJ45 port, m5stack and olimpex ESP32 POE ISO. And in the end it didn't change anything. Currently the bluetooth adapter is about 2 meters in a straight line, unobstructed from the lock and guess what? The issue still exists. Ultimately, it doesn't matter whether you use btProxy or not. Sometimes the lock responds almost immediately and sometimes I or my wife or kids have to wait 10 seconds or more. For me, the lock worked immediately on a bluetooth adapter for a couple of bucks away from the lock almost 20 meters in the HA 2023.2.5 version. The lock responded immediately and there were no problems. From the March version of HA everything started to break down. Believe me, I've spent many weeks on this and I'm still figuring out what to do, but I know one thing for sure: changing the hardware doesn't matter because I currently have the OVERKILL config and the problem is still there. What proof do I have? All I have to do is downgrade the HA version to 2023.2.5 (and ESPHome) and the lock works wonderfully immediately. I had to write this because I'm already frustrated and at the moment I have absolutely no idea what to do other than to stay on the February HA version

bdraco commented 1 year ago

@KitHubek disable the local adapters and only use the esphome proxies

You have other problems with your install, and that doesn’t mean everyone has the same issue

wardwolfram commented 1 year ago

Thanks @KitHubek , I will install the 2023.2.5 version in a virtual machine an test this out. I also had a great running switchbot lock running great on a non-premium (high performance) BT adapter. It worked great and loved it but stopped working like this early this year as well. I'll give this version a try.

wardwolfram commented 1 year ago

@LitHubek and @bdraco - I installed 2023.2.5 and got the same delays with the switchbot as I see with the current version of HA. I tried both a non-performance and recommended high-performance HT adapters with delays (this delay happens when the lock is idle >5 or so minutes). The adapter is behind 1 door and ~12-15 feet away from the lock. Thank you for your inputs and tips to try.

bdraco commented 1 year ago

Did you try downgrading to HAOS 9.5?

KitHubek commented 1 year ago

@bdraco

I done as You say and... From 2 days iam using only btProxy (disabled bt adapter) and have to say: lock working ok. Response about 1-2 sec or less. This is ok for me. I dont know why, btproxy connected via wifi working better with loch than btproxy connected via LAN.

And question: why lock working very good with btproxy, but with local bt adapter has problem and big lag ? What with other devices connected with bt to HA? I have for example Xiaomi BT temp. sensors and some other devices, this devices working via bt proxy but better with bt adapter

bdraco commented 1 year ago

HAOS 10.x uses a newer kernel and bluez which seems have problems on some hardware platforms with local adapters. Did you try downgrading to HAOS 9.5 to see if it solves the local adapter performance?

wardwolfram commented 1 year ago

@bdraco, the Olimex ESP32 Power-over-Ethernet ISO unit that you recommended has been running for ~2 weeks for me and has resulted in noticeable improvements. The response is close to the response I get when using the switchbot app on my phone. Thus, this solution is acceptable for me. Thank you for your recommendation. I am a bit confuse on a quality case for this unit. Do you have recommendations for one to purchase (I do not have a 3-D printer). Thanks again.

bdraco commented 1 year ago

I bought a case for mine on etsy

It should be a bit faster in 2023.7.x since https://github.com/esphome/esphome/pull/4924 will reduce the traffic