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
71.57k stars 29.91k forks source link

After update from 2023.2.5 to 2023.3.6 esphome bluetooth stack takes 25 to retry connecting after error (error not seen) #90265

Closed KitHubek closed 1 year ago

KitHubek commented 1 year ago

The problem

As a topic. As we know, since 2023.3 update we had problem with error index array out of range. We have update HA 2023.3.6 and this problem was fixed, but, new problem happends.

Lock FW is newest

Iam using BT-proxy - just say this to know that BT connections and signal strength should be very fine. Hardware with High performance bt dongle, 3m USB cable, away from USB 3.0 ports. Till 2023.x HA everything working very well.

Now problem is, that lock goes offline. Not unavialable, just offline - this says log. Cant connect to it, via HA. BT proxy log, says this, HA logs too. Connection takes over 50 seconds. I must say, that if i using Switchbot app - everything working ok, lock/unlock takes less than 1 sec.

And i have other devices from Switchbot and everyone working ok, without problem, without delay etc.

What version of Home Assistant Core has the issue?

2023.3.6

What was the last working version of Home Assistant Core?

2023.2.x

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 response

Example YAML snippet

No response

Anything in the logs that might be useful for us?

C1:89:44:4B:2B:A5

From bbt proxy log:

[13:14:00][I][bluetooth_proxy:250]: [0] [lockmacaddress] Connecting v3 with cache
[13:14:00][D][esp32_ble_tracker:214]: Pausing scan to make connection...
[13:14:00][I][esp32_ble_client:064]: [0] [lockmacaddress] 0x01 Attempting BLE connection
......
[13:14:01][W][esp32_ble_client:134]: [0] [] Connection failed, status=133
.....
.....
[13:14:51][D][esp-idf:000]: W (60434078) BT_HCI: hcif disc complete: hdl 0x0, rsn 0x3e

as You see, from unlock command to completed and lock unlock - 51sec

from HA logs:

Logger: homeassistant.core
Source: components/switchbot/lock.py:54
First occurred: 12:43:35 (1 occurrences)
Last logged: 12:43:35

Error executing service: <ServiceCall lock.unlock (c:01GWC96ENHARJM7KZGYPZCJM69): entity_id=['lock.zamek_switchbot']>
Traceback (most recent call last):
  File "/usr/local/lib/python3.10/site-packages/aioesphomeapi/client.py", line 550, in bluetooth_device_connect
    await event.wait()
  File "/usr/local/lib/python3.10/asyncio/locks.py", line 214, in wait
    await fut
asyncio.exceptions.CancelledError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.10/site-packages/aioesphomeapi/client.py", line 549, in bluetooth_device_connect
    async with async_timeout.timeout(timeout):
  File "/usr/local/lib/python3.10/site-packages/async_timeout/__init__.py", line 129, in __aexit__
    self._do_exit(exc_type)
  File "/usr/local/lib/python3.10/site-packages/async_timeout/__init__.py", line 212, in _do_exit
    raise asyncio.TimeoutError
asyncio.exceptions.TimeoutError

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/esphome/bluetooth/client.py", line 100, in _async_wrap_bluetooth_operation
    return await func(self, *args, **kwargs)
  File "/usr/src/homeassistant/homeassistant/components/esphome/bluetooth/client.py", line 314, in connect
    await self._client.bluetooth_device_connect(
  File "/usr/local/lib/python3.10/site-packages/aioesphomeapi/client.py", line 575, in bluetooth_device_connect
    raise TimeoutAPIError(
aioesphomeapi.core.TimeoutAPIError: Timeout waiting for connect response while connecting to lockmacaddress after 20.0s, disconnect timed out: True,  after 5.0s

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/local/lib/python3.10/site-packages/bleak_retry_connector/__init__.py", line 342, in establish_connection
    await client.connect(
  File "/usr/src/homeassistant/homeassistant/components/bluetooth/wrappers.py", line 249, in connect
    connected = await super().connect(**kwargs)
  File "/usr/local/lib/python3.10/site-packages/bleak/__init__.py", line 471, in connect
    return await self._backend.connect(**kwargs)
  File "/usr/src/homeassistant/homeassistant/components/esphome/bluetooth/client.py", line 102, in _async_wrap_bluetooth_operation
    raise asyncio.TimeoutError(str(err)) from err
asyncio.exceptions.TimeoutError: Timeout waiting for connect response while connecting to lockmacaddress after 20.0s, disconnect timed out: True,  after 5.0s

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/core.py", line 1826, in catch_exceptions
    await coro_or_task
  File "/usr/src/homeassistant/homeassistant/core.py", line 1845, in _execute_service
    await cast(Callable[[ServiceCall], Awaitable[None]], handler.job.target)(
  File "/usr/src/homeassistant/homeassistant/helpers/entity_component.py", line 213, in handle_service
    await service.entity_service_call(
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 686, in entity_service_call
    future.result()  # pop exception if have
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 961, in async_request_call
    await coro
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 726, in _handle_entity_call
    await result
  File "/usr/src/homeassistant/homeassistant/components/lock/__init__.py", line 106, in _async_unlock
    await entity.async_unlock(**remove_entity_service_fields(service_call))
  File "/usr/src/homeassistant/homeassistant/components/switchbot/lock.py", line 54, in async_unlock
    self._last_run_success = await self._device.unlock()
  File "/usr/local/lib/python3.10/site-packages/switchbot/devices/lock.py", line 168, in unlock
    return await self._lock_unlock(
  File "/usr/local/lib/python3.10/site-packages/switchbot/devices/lock.py", line 189, in _lock_unlock
    await self._enable_notifications()
  File "/usr/local/lib/python3.10/site-packages/switchbot/devices/lock.py", line 255, in _enable_notifications
    result = await self._send_command(COMMAND_ENABLE_NOTIFICATIONS)
  File "/usr/local/lib/python3.10/site-packages/switchbot/devices/lock.py", line 299, in _send_command
    result = await self._ensure_encryption_initialized()
  File "/usr/local/lib/python3.10/site-packages/switchbot/devices/lock.py", line 314, in _ensure_encryption_initialized
    result = await self._send_command(
  File "/usr/local/lib/python3.10/site-packages/switchbot/devices/lock.py", line 297, in _send_command
    return await super()._send_command(key[:2] + "000000" + key[2:], retry)
  File "/usr/local/lib/python3.10/site-packages/switchbot/devices/device.py", line 180, in _send_command
    return await self._send_command_locked(key, command)
  File "/usr/local/lib/python3.10/site-packages/switchbot/devices/device.py", line 397, in _send_command_locked
    await self._ensure_connected()
  File "/usr/local/lib/python3.10/site-packages/switchbot/devices/device.py", line 264, in _ensure_connected
    client: BleakClientWithServiceCache = await establish_connection(
  File "/usr/local/lib/python3.10/site-packages/bleak_retry_connector/__init__.py", line 359, in establish_connection
    _raise_if_needed(name, device.address, exc)
  File "/usr/local/lib/python3.10/site-packages/bleak_retry_connector/__init__.py", line 308, in _raise_if_needed
    raise BleakNotFoundError(msg) from exc
bleak_retry_connector.BleakNotFoundError:  (lockmacaddress) - lockmacaddress: Failed to connect: Timeout waiting for connect response while connecting to lockmacaddress after 20.0s, disconnect timed out: True,  after 5.0s

and

Logger: switchbot.devices.device
Source: /usr/local/lib/python3.10/site-packages/switchbot/devices/device.py:182
First occurred: 12:43:35 (1 occurrences)
Last logged: 12:43:35

(lockmacaddress): device not found, no longer in range, or poor RSSI: -73
Traceback (most recent call last):
  File "/usr/local/lib/python3.10/site-packages/aioesphomeapi/client.py", line 550, in bluetooth_device_connect
    await event.wait()
  File "/usr/local/lib/python3.10/asyncio/locks.py", line 214, in wait
    await fut
asyncio.exceptions.CancelledError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.10/site-packages/aioesphomeapi/client.py", line 549, in bluetooth_device_connect
    async with async_timeout.timeout(timeout):
  File "/usr/local/lib/python3.10/site-packages/async_timeout/__init__.py", line 129, in __aexit__
    self._do_exit(exc_type)
  File "/usr/local/lib/python3.10/site-packages/async_timeout/__init__.py", line 212, in _do_exit
    raise asyncio.TimeoutError
asyncio.exceptions.TimeoutError

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/esphome/bluetooth/client.py", line 100, in _async_wrap_bluetooth_operation
    return await func(self, *args, **kwargs)
  File "/usr/src/homeassistant/homeassistant/components/esphome/bluetooth/client.py", line 314, in connect
    await self._client.bluetooth_device_connect(
  File "/usr/local/lib/python3.10/site-packages/aioesphomeapi/client.py", line 575, in bluetooth_device_connect
    raise TimeoutAPIError(
aioesphomeapi.core.TimeoutAPIError: Timeout waiting for connect response while connecting to lockmacaddress after 20.0s, disconnect timed out: True,  after 5.0s

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/local/lib/python3.10/site-packages/bleak_retry_connector/__init__.py", line 342, in establish_connection
    await client.connect(
  File "/usr/src/homeassistant/homeassistant/components/bluetooth/wrappers.py", line 249, in connect
    connected = await super().connect(**kwargs)
  File "/usr/local/lib/python3.10/site-packages/bleak/__init__.py", line 471, in connect
    return await self._backend.connect(**kwargs)
  File "/usr/src/homeassistant/homeassistant/components/esphome/bluetooth/client.py", line 102, in _async_wrap_bluetooth_operation
    raise asyncio.TimeoutError(str(err)) from err
asyncio.exceptions.TimeoutError: Timeout waiting for connect response while connecting to lockmacaddress after 20.0s, disconnect timed out: True,  after 5.0s

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/local/lib/python3.10/site-packages/switchbot/devices/device.py", line 180, in _send_command
    return await self._send_command_locked(key, command)
  File "/usr/local/lib/python3.10/site-packages/switchbot/devices/device.py", line 397, in _send_command_locked
    await self._ensure_connected()
  File "/usr/local/lib/python3.10/site-packages/switchbot/devices/device.py", line 264, in _ensure_connected
    client: BleakClientWithServiceCache = await establish_connection(
  File "/usr/local/lib/python3.10/site-packages/bleak_retry_connector/__init__.py", line 359, in establish_connection
    _raise_if_needed(name, device.address, exc)
  File "/usr/local/lib/python3.10/site-packages/bleak_retry_connector/__init__.py", line 308, in _raise_if_needed
    raise BleakNotFoundError(msg) from exc
bleak_retry_connector.BleakNotFoundError:  (lockmacaddress) - lockmacaddress: Failed to connect: Timeout waiting for connect response while connecting to lockmacaddress after 20.0s, disconnect timed out: True,  after 5.0s

Additional information

No response

KitHubek commented 1 year ago

now error starting integration:

Logger: homeassistant.setup
Source: setup.py:213
First occurred: 19:47:58 (1 occurrences)
Last logged: 19:47:58

Setup failed for custom integration switchbot: Unable to import component: Exception importing custom_components.switchbot
Logger: homeassistant.loader
Source: custom_components/switchbot/const.py:40
Integration: SwitchBot
First occurred: 19:47:58 (8 occurrences)
Last logged: 19:48:11

Unexpected exception importing component custom_components.switchbot
Unexpected exception importing platform custom_components.switchbot.config_flow
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/loader.py", line 760, in get_component
    cache[self.domain] = importlib.import_module(self.pkg_path)
  File "/usr/local/lib/python3.10/importlib/__init__.py", line 126, in import_module
    return _bootstrap._gcd_import(name[level:], package, level)
  File "<frozen importlib._bootstrap>", line 1050, in _gcd_import
  File "<frozen importlib._bootstrap>", line 1027, in _find_and_load
  File "<frozen importlib._bootstrap>", line 1006, in _find_and_load_unlocked
  File "<frozen importlib._bootstrap>", line 688, in _load_unlocked
  File "<frozen importlib._bootstrap_external>", line 883, in exec_module
  File "<frozen importlib._bootstrap>", line 241, in _call_with_frames_removed
  File "/config/custom_components/switchbot/__init__.py", line 21, in <module>
    from .const import (
  File "/config/custom_components/switchbot/const.py", line 40, in <module>
    SwitchbotModel.BLIND_TILT: SupportedModels.BLIND_TILT,
  File "/usr/local/lib/python3.10/enum.py", line 437, in __getattr__
    raise AttributeError(name) from None
AttributeError: BLIND_TILT
Logger: homeassistant.config_entries
Source: config_entries.py:858
First occurred: 19:48:11 (7 occurrences)
Last logged: 19:48:11

Error occurred loading flow for integration switchbot: Exception importing custom_components.switchbot.config_flow
KitHubek commented 1 year ago

manifest file:

{
  "domain": "switchbot",
  "version": "2023.5.0",
  "name": "SwitchBot",
  "bluetooth": [
    {
      "service_data_uuid": "00000d00-0000-1000-8000-00805f9b34fb",
      "connectable": false
    },
    {
      "service_data_uuid": "0000fd3d-0000-1000-8000-00805f9b34fb",
      "connectable": false
    },
    {
      "service_uuid": "cba20d00-224d-11e6-9fb8-0002a5d5c51b",
      "connectable": false
    },
    {
      "manufacturer_id": 2409,
      "connectable": false
    },
    {
      "manufacturer_id": 89,
      "connectable": true
    },
    {
      "manufacturer_id": 741,
      "connectable": true
    }
  ],
  "codeowners": [
    "@bdraco",
    "@danielhiversen",
    "@RenierM26",
    "@murtas",
    "@Eloston",
    "@dsypniewski"
  ],
  "config_flow": true,
  "dependencies": ["bluetooth_adapters"],
  "documentation": "https://www.home-assistant.io/integrations/switchbot",
  "iot_class": "local_push",
  "loggers": ["switchbot"],
  "requirements": ["PySwitchbot==0.36.4"]
}
bdraco commented 1 year ago

I forgot about the blind tilt being added.

You'll have to strip it out to get it to load.

You can run git revert a26d41f260809ee3db444608bd48b5bc1c7cd255 on the checked out repo before copying over the files

KitHubek commented 1 year ago

after revert command:

Auto-merging homeassistant/components/switchbot/manifest.json
CONFLICT (content): Merge conflict in homeassistant/components/switchbot/manifest.json
Auto-merging requirements_all.txt
CONFLICT (content): Merge conflict in requirements_all.txt
Auto-merging requirements_test_all.txt
CONFLICT (content): Merge conflict in requirements_test_all.txt
error: could not revert a26d41f260... Implement Switchbot Blind Tilt (#86591)
hint: After resolving the conflicts, mark them with
hint: "git add/rm <pathspec>", then run
hint: "git revert --continue".
hint: You can instead skip this commit with "git revert --skip".
hint: To abort and get back to the state before "git revert",
hint: run "git revert --abort".

and manifest file looks diferent (i just added version 2023.5.0)

{
  "domain": "switchbot",
  "version": "2023.5.0",
  "name": "SwitchBot",
  "bluetooth": [
    {
      "service_data_uuid": "00000d00-0000-1000-8000-00805f9b34fb",
      "connectable": false
    },
    {
      "service_data_uuid": "0000fd3d-0000-1000-8000-00805f9b34fb",
      "connectable": false
    },
    {
      "service_uuid": "cba20d00-224d-11e6-9fb8-0002a5d5c51b",
      "connectable": false
    },
    {
      "manufacturer_id": 2409,
      "connectable": false
    },
    {
      "manufacturer_id": 89,
      "connectable": true
    },
    {
      "manufacturer_id": 741,
      "connectable": true
    }
  ],
  "codeowners": [
    "@bdraco",
    "@danielhiversen",
    "@RenierM26",
    "@murtas",
    "@Eloston",
    "@dsypniewski"
  ],
  "config_flow": true,
  "dependencies": ["bluetooth_adapters"],
  "documentation": "https://www.home-assistant.io/integrations/switchbot",
  "iot_class": "local_push",
  "loggers": ["switchbot"],
<<<<<<< HEAD
  "requirements": ["PySwitchbot==0.37.6"]
=======
  "requirements": ["PySwitchbot==0.36.4"]
>>>>>>> parent of a26d41f260 (Implement Switchbot Blind Tilt (#86591))
}
bdraco commented 1 year ago

You'll need to manually edit those files to resolve the conflict and than commit the result with git commit -a

In this case you want to replace

<<<<<<< HEAD
  "requirements": ["PySwitchbot==0.37.6"]
=======
  "requirements": ["PySwitchbot==0.36.4"]
>>>>>>> parent of a26d41f260 (Implement Switchbot Blind Tilt (#86591))

with

  "requirements": ["PySwitchbot==0.36.4"]
KitHubek commented 1 year ago

ok, thanks. All done, but after doing yhis changes, HA started normallly, but lock response took long time :/

KitHubek commented 1 year ago

so this test i think, shows, that this problem isnt with switchbot integration and istn with pyswitchbot :/

KitHubek commented 1 year ago

what i can do more to solve this problem?

I'm wondering if I'm the only one having this problem? If so, something is wrong with me. What else can I do? I have already replaced: rpi4 for miniPC bt dongle for high performance I added bt-proxy I added bt-proxy with LAN connectivity I bought a second lock to eliminate the problem with the lock itself

I wonder if the lock would work if I installed a clean HA install on a new device and added only switchbot integration with this lock. And if so, what then? I have too many devices and automation to set it all up from scratch. I have over 160 devices added...

bdraco commented 1 year ago

Have you tried disabling Bluetooth adapters one by one so only one is active at a time to see if it’s a problem with the Bluetooth implementation for that adapter/esphome device on newer versions ?

KitHubek commented 1 year ago

iam using only one bt adapter at time. Its UGREEN CM109 (CSR8510A10). I have 2 bt-proxy, but i made tests with one of them, with two at time and without bt-proxy. Result is the same :(

I can buy other bt-dongle and make tests, but which one?

bdraco commented 1 year ago

I use this one for my production https://www.aliexpress.us/item/2255799901392975.html?spm=a2g0o.productlist.main.3.40e3c438CuLAdr&algo_pvid=32606d24-66d0-490c-a9a8-d737df929da8&algo_exp_id=32606d24-66d0-490c-a9a8-d737df929da8-1&pdp_npi=3%40dis%21USD%2114.99%2114.99%21%21%21%21%21%40211be10916830719010728193d07e2%2110000000234049415%21sea%21US%21706433319&curPageLogUid=ecd0kcejxXUV https://www.aliexpress.us/item/2255800893640297.html?spm=a2g0o.productlist.main.1.40e3c438CuLAdr&algo_pvid=32606d24-66d0-490c-a9a8-d737df929da8&algo_exp_id=32606d24-66d0-490c-a9a8-d737df929da8-0&pdp_npi=3%40dis%21USD%2114.99%2114.99%21%21%21%21%21%40211be10916830719010728193d07e2%2110000014219531021%21sea%21US%21706433319&curPageLogUid=y4xvcQySUkZ0

KitHubek commented 1 year ago

ok i can buy this adapter, and anothers and test with it. Will do it. Please see here: https://github.com/home-assistant/core/issues/92370 another users have the same problema as me.

jpconfessor commented 1 year ago

what i can do more to solve this problem?

I'm wondering if I'm the only one having this problem? If so, something is wrong with me. What else can I do? I have already replaced: rpi4 for miniPC bt dongle for high performance I added bt-proxy I added bt-proxy with LAN connectivity I bought a second lock to eliminate the problem with the lock itself

I wonder if the lock would work if I installed a clean HA install on a new device and added only switchbot integration with this lock. And if so, what then? I have too many devices and automation to set it all up from scratch. I have over 160 devices added...

Nope.. you are not the only one, and this issue should be very simple to reproduce in any environment, using local bluetooth or bt-proxies.

I don't think buying another dongle will help you out... since you did probably all type of scenarios using dongles and bt-proxies

So far, I've noticed that the main difference between your problem and mine are versions: Your problem happens when you upgrade to 2023.3.X.. and mine starts at 2023.4.X.... as I said before, 2023.3.6 is running fine here: I am not using local bt connected to home assistant (box is too far from the lock)... only bt-proxy via M5Stack Atom Lite - ESPHome version: 2023.4.3 and btw, my lock's firmware is v5.6 (latest - as of today 2023-05-04)

You did a good job testing different versions and trying to eliminate main factors. I think someone has to take ownership of this issue and, based on what was tested so far, come up with some concrete ideas on what needs to be changed and where.

I wish I knew how to debug this... for me, having to reverse-engineering this will take ages...

btw, as a "workaround" you can always control the lock via smartthings integration, which uses API instead of bluetooth. There are some problems with this: 1 - This is not local.. requires internet 2 - You must have their switchbot hub for this (homeassistant -> smartthings cloud -> switchbot cloud -> switchbot hub -> (bluetooth) -> switchbot lock. 3 - (the main one to me) Latency.. it takes between 5-10s to lock/unlock... and even worse, the lock status updates are done every 30s (if I am not mistaken) due to a limitation on the number of API calls per day against switchbot servers

Good thing is, you don't need any smartthings hub.. you just need to download smartthings app, create an account, add the switchbot integration, add your lock there, then add the integration in homeassistant.

KitHubek commented 1 year ago

@jpconfessor

thanks for the kind word and support. Thanks for the advice from SmartThings but unfortunately it will not apply to me. I got rid of Hub from Switchbot just for local integration via BlueTooth with HomeAssistant. At the very beginning, I had it configured via Hub SwitchBot Mini but there was a delay and that's why I switched to HA integration. I can't imagine going back to using the lock with a 10 second delay and depending on the cloud. Not now as I already have positive experiences with HA and a 1 second lock, unfortunately only up to version 2023.2.5. I will not update HA any time soon.

@bdraco

To completely eliminate the hardware problem I ordered and received today various BlueTooth to USB adapters - see which ones below. Including the one you wrote about.

DIGITUS DN-30210-1 (CSR chip) Feasycom FSC-BP119 (CSR chip) ORICO BTA-409 (CSR chip) ASUS USB-BT400 (BCM chip) Kinivo BTD-400 (BCM chip) Targus ACB10US1 (BCM chip) ASUS USB-BT500 (RTL chip) UGREEN CM390 (RTL chip)

I tested each of them on the latest versions of everything, which is:

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

And no, but that doesn't change anything. It's still the same. All adapters work but the lock responds immediately ONLY to HA max 2023.2.5. I tested everyone on all previous HA versions, amd all versions above are bugs and behaviors described by me in the previous post. Changing the BT adapter has no effect on this situation at all.

I return all adapters to the sellers. It immediately seemed to me that it would not be a matter of the adapter itself, but I had to try.

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

Originally posted by @KitHubek in https://github.com/home-assistant/core/issues/92370#issuecomment-1537123282

@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

this is complete log. I cut only this:

2023-05-06 13:22:24.050 ERROR (MainThread) [homeassistant.components.xiaomi_miio] Error fetching Wentylator TV data: Unable to discover the device ipaddr 2023-05-06 13:22:26.475 INFO (MainThread) [homeassistant.components.automation.timer_20_sec_loop] Timer 20 sec loop: Skipped disabled step if 2023-05-06 13:22:26.476 INFO (MainThread) [homeassistant.components.automation.timer_20_sec_loop] Timer 20 sec loop: Executing step call service 2023-05-06 13:22:26.483 INFO (MainThread) [homeassistant.components.automation.timer_20_sec_loop] Timer 20 sec loop: Executing step delay 0:00:10

2023-05-06 13:22:30.833 as i wrote in timeline:

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

2023-05-06 13:22:30.833 - i tap in app open lock again

bdraco commented 1 year ago 
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: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: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

I see it taking ~30-40s to connect in the log because the first 2 attempts fail. Connecting is done at a level outside of Home Assistant though so we will need to go a bit deeper to find out why.

Also the mac address is floating around in the air so there isn't much point in obscuring it.

bdraco commented 1 year ago

Please try again with logs for homeassistant.components.bluetooth and bleak added to the logger list.

This will generate a LOT of logs

KitHubek commented 1 year ago

okay, ready. I'll post the log here in a while

omg, this generates so many logs that if I wait about an hour the log will probably be 1 GB or more :/

KitHubek commented 1 year ago

@bdraco ok, here is full log. Command unlock via app not working, lock finally opened manually. I upload it via file, because log have over 11k lines bt.log

bdraco commented 1 year ago

It looks like its connecting via BT-PROXY ESP32 (b4:8a:0a:8c:f3:c8)

Can you pull the console logs from that esphome device while its connecting ?

KitHubek commented 1 year ago

example logs from this bt-proxy when lock connecting via this proxy and command fail

[00:11:26][C][api:141]:   Using noise encryption: YES
[00:11:27][C][improv_serial:032]: Improv Serial:
[00:14:04][I][bluetooth_proxy:254]: [0] [C1:89:44:4B:2B:A5] Connecting v3 without cache
[00:14:04][D][esp32_ble_tracker:214]: Pausing scan to make connection...
[00:14:04][I][esp32_ble_client:064]: [0] [C1:89:44:4B:2B:A5] 0x01 Attempting BLE connection
[00:14:04][D][esp-idf:000]: W (118767534) BT_HCI: hcif disc complete: hdl 0x0, rsn 0x3e
[00:14:05][D][esp-idf:000]: W (118767956) BT_HCI: hcif disc complete: hdl 0x0, rsn 0x3e
[00:14:05][D][esp-idf:000]: W (118768169) BT_HCI: hcif disc complete: hdl 0x0, rsn 0x3e
[00:14:05][D][esp-idf:000]: W (118768705) BT_HCI: hcif disc complete: hdl 0x0, rsn 0x3e
[00:14:05][D][esp-idf:000]: W (118768710) BT_APPL: gattc_conn_cb: if=3 st=0 id=3 rsn=0x3e
[00:14:05][D][esp-idf:000]: W (118768713) BT_APPL: gattc_conn_cb: if=4 st=0 id=4 rsn=0x3e
[00:14:05][D][esp-idf:000]: W (118768714) BT_APPL: gattc_conn_cb: if=5 st=0 id=5 rsn=0x3e
[00:14:05][W][esp32_ble_client:134]: [0] [] Connection failed, status=133
[00:14:05][D][esp32_ble_tracker:246]: Starting scan...
[00:14:29][I][bluetooth_proxy:254]: [0] [C1:89:44:4B:2B:A5] Connecting v3 without cache
[00:14:29][D][esp32_ble_tracker:214]: Pausing scan to make connection...
[00:14:29][I][esp32_ble_client:064]: [0] [C1:89:44:4B:2B:A5] 0x01 Attempting BLE connection
[00:14:29][D][esp-idf:000]: W (118792646) BT_HCI: hcif disc complete: hdl 0x0, rsn 0x3e
[00:14:30][D][esp-idf:000]: W (118793066) BT_HCI: hcif disc complete: hdl 0x0, rsn 0x3e
[00:14:30][D][esp-idf:000]: W (118793174) BT_HCI: hcif disc complete: hdl 0x0, rsn 0x3e
[00:14:30][D][esp-idf:000]: W (118793276) BT_HCI: hcif disc complete: hdl 0x0, rsn 0x3e
[00:14:30][D][esp-idf:000]: W (118793283) BT_APPL: gattc_conn_cb: if=3 st=0 id=3 rsn=0x3e
[00:14:30][D][esp-idf:000]: W (118793286) BT_APPL: gattc_conn_cb: if=4 st=0 id=4 rsn=0x3e
[00:14:30][D][esp-idf:000]: W (118793288) BT_APPL: gattc_conn_cb: if=5 st=0 id=5 rsn=0x3e
[00:14:30][W][esp32_ble_client:134]: [0] [] Connection failed, status=133
[00:14:30][D][esp32_ble_tracker:246]: Starting scan...

Finally connected to second bt-proxy after 76sec and lock unlocked

[00:11:28][C][api:141]:   Using noise encryption: YES
[00:15:15][I][bluetooth_proxy:254]: [0] [C1:89:44:4B:2B:A5] Connecting v3 without cache
[00:15:15][D][esp32_ble_tracker:214]: Pausing scan to make connection...
[00:15:15][I][esp32_ble_client:064]: [0] [C1:89:44:4B:2B:A5] 0x01 Attempting BLE connection
[00:15:15][D][esp-idf:000]: W (231858948) BT_HCI: hcif disc complete: hdl 0x0, rsn 0x3e
[00:15:15][I][esp32_ble_client:196]: [0] [C1:89:44:4B:2B:A5] Connected
[00:15:15][D][esp32_ble_tracker:246]: Starting scan...
[00:15:36][I][esp32_ble_client:081]: [0] [C1:89:44:4B:2B:A5] Disconnecting.
[00:15:36][D][esp-idf:000]: W (231880034) BT_HCI: hci cmd send: disconnect: hdl 0x0, rsn:0x13
[00:15:36][D][esp-idf:000]: W (231880037) BT_APPL: gattc_conn_cb: if=3 st=0 id=3 rsn=0x16
[00:15:36][D][esp-idf:000]: W (231880038) BT_APPL: gattc_conn_cb: if=4 st=0 id=4 rsn=0x16
[00:15:36][D][esp-idf:000]: W (231880039) BT_APPL: gattc_conn_cb: if=5 st=0 id=5 rsn=0x16
[00:15:36][D][esp-idf:000]: W (231880059) BT_HCI: hcif disc complete: hdl 0x0, rsn 0x16
bdraco commented 1 year ago

[00:14:04][I][bluetooth_proxy:254]: [0] [C1:89:44:4B:2B:A5] Connecting v3 without cache

Does the second attempt connect with the cache after you were already successful or does it always say without cache?

KitHubek commented 1 year ago

with cache, and lock unlock less than 1 sec

[00:20:19][C][api:141]:   Using noise encryption: YES
[00:20:19][C][improv_serial:032]: Improv Serial:
[00:20:24][I][bluetooth_proxy:250]: [0] [C1:89:44:4B:2B:A5] Connecting v3 with cache
[00:20:24][D][esp32_ble_tracker:214]: Pausing scan to make connection...
[00:20:24][I][esp32_ble_client:064]: [0] [C1:89:44:4B:2B:A5] 0x01 Attempting BLE connection
[00:20:24][D][esp-idf:000]: W (119147437) BT_HCI: hcif disc complete: hdl 0x0, rsn 0x3e
[00:20:24][I][esp32_ble_client:144]: [0] [C1:89:44:4B:2B:A5] Connected
[00:20:24][D][esp32_ble_tracker:246]: Starting scan...
[00:20:45][I][esp32_ble_client:081]: [0] [C1:89:44:4B:2B:A5] Disconnecting.
[00:20:45][D][esp-idf:000]: W (119168451) BT_HCI: hci cmd send: disconnect: hdl 0x0, rsn:0x13
[00:20:45][D][esp-idf:000]: W (119168460) BT_APPL: gattc_conn_cb: if=3 st=0 id=3 rsn=0x16
[00:20:45][D][esp-idf:000]: W (119168464) BT_APPL: gattc_conn_cb: if=4 st=0 id=4 rsn=0x16
[00:20:45][D][esp-idf:000]: W (119168468) BT_APPL: gattc_conn_cb: if=5 st=0 id=5 rsn=0x16
[00:20:45][D][esp-idf:000]: W (119168503) BT_HCI: hcif disc complete: hdl 0x0, rsn 0x16
bdraco commented 1 year ago

Can you post the esphome yaml config for BT-PROXY ESP32 (b4:8a:0a:8c:f3:c8)

KitHubek commented 1 year ago

config is default, device was flashed via online flasher

substitutions:
  name: esp32-bluetooth-proxy-8cf3c8
  friendly_name: Bluetooth Proxy
packages:
  esphome.bluetooth-proxy: github://esphome/bluetooth-proxies/esp32-generic.yaml@main
esphome:
  name: ${name}
  name_add_mac_suffix: false
  friendly_name: ${friendly_name}
api:
  encryption:
    key: myKEY

wifi:
  ssid: !secret wifi_ssid
  password: !secret wifi_password
INFO Reading configuration /config/esphome/esp32-bluetooth-proxy-8cf3c8.yaml...
INFO Starting log output from esp32-bluetooth-proxy-8cf3c8.local using esphome API
INFO Successfully connected to esp32-bluetooth-proxy-8cf3c8.local
[09:42:50][I][app:102]: ESPHome version 2023.4.4 compiled on May  4 2023, 07:51:56
[09:42:50][I][app:104]: Project esphome.bluetooth-proxy version 1.0
[09:42:50][C][wifi:505]: WiFi:
[09:42:50][C][wifi:363]:   Local MAC: B4:8A:0A:8C:F3:C8
[09:42:50][C][wifi:364]:   SSID: [redacted]
[09:42:50][C][wifi:365]:   IP Address: IPADDR
[09:42:50][C][wifi:367]:   BSSID: [redacted]
[09:42:50][C][wifi:368]:   Hostname: 'esp32-bluetooth-proxy-8cf3c8'
[09:42:50][C][wifi:370]:   Signal strength: -55 dB ▂▄▆█
[09:42:50][C][wifi:374]:   Channel: 1
[09:42:50][C][wifi:375]:   Subnet: 255.255.255.0
[09:42:50][C][wifi:376]:   Gateway: GATEIPADDR
[09:42:50][C][wifi:377]:   DNS1: MYDNS
[09:42:50][C][wifi:378]:   DNS2: MYDNS2
[09:42:50][C][logger:294]: Logger:
[09:42:50][C][logger:295]:   Level: DEBUG
[09:42:50][C][logger:296]:   Log Baud Rate: 115200
[09:42:50][C][bluetooth_proxy:065]: Bluetooth Proxy:
[09:42:50][C][bluetooth_proxy:066]:   Active: YES
[09:42:50][C][safe_mode.button:022]: Safe Mode Button 'Safe Mode Boot'
[09:42:50][C][safe_mode.button:022]:   Icon: 'mdi:restart-alert'
[09:42:50][C][esp32_ble:218]: ESP32 BLE:
[09:42:50][C][esp32_ble:220]:   MAC address: B4:8A:0A:8C:F3:CA
[09:42:50][C][esp32_ble_tracker:591]: BLE Tracker:
[09:42:50][C][esp32_ble_tracker:592]:   Scan Duration: 300 s
[09:42:50][C][esp32_ble_tracker:593]:   Scan Interval: 320.0 ms
[09:42:50][C][esp32_ble_tracker:594]:   Scan Window: 30.0 ms
[09:42:50][C][esp32_ble_tracker:595]:   Scan Type: ACTIVE
[09:42:50][C][esp32_ble_tracker:596]:   Continuous Scanning: True
[09:42:50][C][mdns:108]: mDNS:
[09:42:50][C][mdns:109]:   Hostname: esp32-bluetooth-proxy-8cf3c8
[09:42:50][C][ota:093]: Over-The-Air Updates:
[09:42:50][C][ota:094]:   Address: esp32-bluetooth-proxy-8cf3c8.local:3232
[09:42:50][C][api:138]: API Server:
[09:42:50][C][api:139]:   Address: esp32-bluetooth-proxy-8cf3c8.local:6053
[09:42:50][C][api:141]:   Using noise encryption: YES
[09:42:51][C][improv_serial:032]: Improv Serial:
KitHubek commented 1 year ago

@bdraco

and log from today minutes ago. Timeline: open app, tap unlock, wait, wait, nothing, wait, after some time lock opened, lock it via app by tap lock command.

2023-05-07 09:54:44.721 DEBUG (MainThread) [switchbot.adv_parsers.lock] mfr_data: c189444b2ba51f830820
2023-05-07 09:54:44.722 DEBUG (MainThread) [switchbot.adv_parsers.lock] data: 6f8062
2023-05-07 10:13:04.660 DEBUG (MainThread) [switchbot.devices.device]  (C1:89:44:4B:2B:A5): Scheduling command 570000000f210381
2023-05-07 10:13:04.661 DEBUG (MainThread) [switchbot.devices.device]  (C1:89:44:4B:2B:A5): Connecting; RSSI: -64
2023-05-07 10:13:04.661 DEBUG (MainThread) [bleak_retry_connector]  (C1:89:44:4B:2B:A5) - C1:89:44:4B:2B:A5: Connection attempt: 1
2023-05-07 10:13:04.685 DEBUG (MainThread) [switchbot.adv_parsers.lock] mfr_data: c189444b2ba51f830820
2023-05-07 10:13:04.685 DEBUG (MainThread) [switchbot.adv_parsers.lock] data: 6f8062
2023-05-07 10:13:29.667 DEBUG (MainThread) [bleak_retry_connector]  (C1:89:44:4B:2B:A5) - C1:89:44:4B:2B:A5: Timed out trying to connect (attempt: 1, last rssi: None)
2023-05-07 10:13:29.918 DEBUG (MainThread) [bleak_retry_connector]  (C1:89:44:4B:2B:A5) - C1:89:44:4B:2B:A5: Connection attempt: 2
2023-05-07 10:13:30.413 DEBUG (MainThread) [switchbot.devices.device]  (C1:89:44:4B:2B:A5): Connected; RSSI: -64
2023-05-07 10:13:30.413 DEBUG (MainThread) [switchbot.devices.device]  (C1:89:44:4B:2B:A5): Starting notify and disconnect timer; RSSI: -64
2023-05-07 10:13:30.413 DEBUG (MainThread) [switchbot.devices.device]  (C1:89:44:4B:2B:A5): Subscribe to notifications; RSSI: -64
2023-05-07 10:13:30.470 DEBUG (MainThread) [switchbot.devices.device]  (C1:89:44:4B:2B:A5): Sending command: 570000000f210381
2023-05-07 10:13:30.661 DEBUG (MainThread) [switchbot.devices.device]  (C1:89:44:4B:2B:A5): Notification received: 01000000126998b96c1d08be9dd2cd765a8a89b3
2023-05-07 10:13:30.662 DEBUG (MainThread) [switchbot.devices.device]  (C1:89:44:4B:2B:A5): Scheduling command 5781126958df2ed5b379b50b
2023-05-07 10:13:30.663 DEBUG (MainThread) [switchbot.devices.device]  (C1:89:44:4B:2B:A5): Already connected before obtaining lock, resetting timer; RSSI: -64
2023-05-07 10:13:30.663 DEBUG (MainThread) [switchbot.devices.device]  (C1:89:44:4B:2B:A5): Sending command: 5781126958df2ed5b379b50b
2023-05-07 10:13:30.768 DEBUG (MainThread) [switchbot.devices.device]  (C1:89:44:4B:2B:A5): Received unsolicited notification: bytearray(b'\x0f\x81\x12i\xd4\xd7\xbb_$y4\n\x1d\xebw\xee}p')
2023-05-07 10:13:30.768 DEBUG (MainThread) [switchbot.devices.device]  (C1:89:44:4B:2B:A5): Notification received: 01811269
2023-05-07 10:13:30.768 DEBUG (MainThread) [switchbot.devices.device]  (C1:89:44:4B:2B:A5): Scheduling command 5781126959902fcaa3f9
2023-05-07 10:13:30.769 DEBUG (MainThread) [switchbot.devices.device]  (C1:89:44:4B:2B:A5): Already connected before obtaining lock, resetting timer; RSSI: -64
2023-05-07 10:13:30.769 DEBUG (MainThread) [switchbot.devices.device]  (C1:89:44:4B:2B:A5): Sending command: 5781126959902fcaa3f9
2023-05-07 10:13:30.866 DEBUG (MainThread) [switchbot.devices.device]  (C1:89:44:4B:2B:A5): Notification received: 01811269e44bba5cb3
2023-05-07 10:13:30.868 DEBUG (MainThread) [switchbot.devices.device]  (C1:89:44:4B:2B:A5): Scheduling command 5781126954
2023-05-07 10:13:30.868 DEBUG (MainThread) [switchbot.devices.device]  (C1:89:44:4B:2B:A5): Already connected before obtaining lock, resetting timer; RSSI: -64
2023-05-07 10:13:30.868 DEBUG (MainThread) [switchbot.devices.device]  (C1:89:44:4B:2B:A5): Sending command: 5781126954
2023-05-07 10:13:30.972 DEBUG (MainThread) [switchbot.devices.device]  (C1:89:44:4B:2B:A5): Notification received: 01811269349f2acbb379
2023-05-07 10:13:30.974 DEBUG (MainThread) [switchbot.devices.device]  (C1:89:44:4B:2B:A5): Fire callbacks
2023-05-07 10:13:31.085 DEBUG (MainThread) [switchbot.devices.device]  (C1:89:44:4B:2B:A5): Fire callbacks
2023-05-07 10:13:31.227 DEBUG (MainThread) [switchbot.adv_parsers.lock] mfr_data: c189444b2ba520b30820
2023-05-07 10:13:31.227 DEBUG (MainThread) [switchbot.adv_parsers.lock] data: 6f8062
2023-05-07 10:13:35.891 DEBUG (MainThread) [switchbot.devices.device] C1-89-44-4B-2B-A5 (C1:89:44:4B:2B:A5): Fire callbacks
2023-05-07 10:13:36.207 DEBUG (MainThread) [switchbot.adv_parsers.lock] mfr_data: c189444b2ba521930820
2023-05-07 10:13:36.207 DEBUG (MainThread) [switchbot.adv_parsers.lock] data: 6f8062
2023-05-07 10:13:40.592 DEBUG (MainThread) [switchbot.devices.device] C1-89-44-4B-2B-A5 (C1:89:44:4B:2B:A5): Scheduling command 5781126959902fcaa379
2023-05-07 10:13:40.593 DEBUG (MainThread) [switchbot.devices.device] C1-89-44-4B-2B-A5 (C1:89:44:4B:2B:A5): Already connected before obtaining lock, resetting timer; RSSI: -64
2023-05-07 10:13:40.593 DEBUG (MainThread) [switchbot.devices.device] C1-89-44-4B-2B-A5 (C1:89:44:4B:2B:A5): Sending command: 5781126959902fcaa379
2023-05-07 10:13:40.799 DEBUG (MainThread) [switchbot.devices.device] C1-89-44-4B-2B-A5 (C1:89:44:4B:2B:A5): Notification received: 01811269f643ba5cb3
2023-05-07 10:13:40.802 DEBUG (MainThread) [switchbot.devices.device] C1-89-44-4B-2B-A5 (C1:89:44:4B:2B:A5): Scheduling command 5781126954
2023-05-07 10:13:40.802 DEBUG (MainThread) [switchbot.devices.device] C1-89-44-4B-2B-A5 (C1:89:44:4B:2B:A5): Already connected before obtaining lock, resetting timer; RSSI: -64
2023-05-07 10:13:40.803 DEBUG (MainThread) [switchbot.devices.device] C1-89-44-4B-2B-A5 (C1:89:44:4B:2B:A5): Sending command: 5781126954
2023-05-07 10:13:40.907 DEBUG (MainThread) [switchbot.devices.device]  (C1:89:44:4B:2B:A5): Notification received: 01811269349f2acbb379
2023-05-07 10:13:40.908 DEBUG (MainThread) [switchbot.devices.device]  (C1:89:44:4B:2B:A5): Fire callbacks
2023-05-07 10:13:41.004 DEBUG (MainThread) [switchbot.devices.device]  (C1:89:44:4B:2B:A5): Fire callbacks
2023-05-07 10:13:41.223 DEBUG (MainThread) [switchbot.adv_parsers.lock] mfr_data: c189444b2ba522a30820
2023-05-07 10:13:41.223 DEBUG (MainThread) [switchbot.adv_parsers.lock] data: 6f8062
2023-05-07 10:13:45.516 DEBUG (MainThread) [switchbot.devices.device]  (C1:89:44:4B:2B:A5): Fire callbacks
2023-05-07 10:13:45.817 DEBUG (MainThread) [switchbot.devices.device] C1-89-44-4B-2B-A5 (C1:89:44:4B:2B:A5): Fire callbacks
2023-05-07 10:13:46.662 DEBUG (MainThread) [switchbot.adv_parsers.lock] mfr_data: c189444b2ba523830820
2023-05-07 10:13:46.662 DEBUG (MainThread) [switchbot.adv_parsers.lock] data: 6f8062
2023-05-07 10:13:54.318 DEBUG (MainThread) [switchbot.devices.device]  (C1:89:44:4B:2B:A5): Executing timed disconnect after timeout of 8.5
2023-05-07 10:13:54.319 DEBUG (MainThread) [switchbot.devices.device]  (C1:89:44:4B:2B:A5): Executing disconnect
2023-05-07 10:13:54.319 DEBUG (MainThread) [switchbot.devices.device]  (C1:89:44:4B:2B:A5): Executing disconnect with lock
2023-05-07 10:13:54.319 DEBUG (MainThread) [switchbot.devices.device]  (C1:89:44:4B:2B:A5): Disconnecting
2023-05-07 10:13:54.322 DEBUG (MainThread) [switchbot.devices.device]  (C1:89:44:4B:2B:A5): Disconnect completed successfully
KitHubek commented 1 year ago

Next test:

Disabled BT-PROXY ESP32 (b4:8a:0a:8c:f3:c8) disabled it in integration and plug off device

and enabled only wt32-eth01-bt-proxy-b31b1c which is LAN proxy, and result below.

First: Fail even connection witch cache Second the same Third - success


----start loging

INFO Reading configuration /config/esphome/wt32-eth01-bt-proxy-b31b1c.yaml...
INFO Starting log output from wt32-eth01-bt-proxy-b31b1c.local using esphome API
INFO Successfully connected to wt32-eth01-bt-proxy-b31b1c.local
[10:58:48][I][app:102]: ESPHome version 2023.4.4 compiled on May  4 2023, 07:49:27
[10:58:48][I][app:104]: Project esphome.bluetooth-proxy version 1.0
[10:58:48][C][logger:294]: Logger:
[10:58:48][C][logger:295]:   Level: DEBUG
[10:58:48][C][logger:296]:   Log Baud Rate: 115200
[10:58:48][C][logger:297]:   Hardware UART: UART0
[10:58:48][C][bluetooth_proxy:065]: Bluetooth Proxy:
[10:58:48][C][bluetooth_proxy:066]:   Active: YES
[10:58:48][C][safe_mode.button:022]: Safe Mode Button 'Safe Mode Boot'
[10:58:48][C][safe_mode.button:022]:   Icon: 'mdi:restart-alert'
[10:58:48][C][esp32_ble:218]: ESP32 BLE:
[10:58:48][C][esp32_ble:220]:   MAC address: C4:DE:E2:B3:1B:1E
[10:58:48][C][esp32_ble_tracker:591]: BLE Tracker:
[10:58:48][C][esp32_ble_tracker:592]:   Scan Duration: 300 s
[10:58:48][C][esp32_ble_tracker:593]:   Scan Interval: 1100.0 ms
[10:58:48][C][esp32_ble_tracker:594]:   Scan Window: 1100.0 ms
[10:58:48][C][esp32_ble_tracker:595]:   Scan Type: ACTIVE
[10:58:48][C][esp32_ble_tracker:596]:   Continuous Scanning: True
[10:58:48][C][ethernet:179]: Ethernet:
[10:58:48][C][ethernet:306]:   IP Address: IPADDR
[10:58:48][C][ethernet:307]:   Hostname: 'wt32-eth01-bt-proxy-b31b1c'
[10:58:48][C][ethernet:308]:   Subnet: 255.255.255.0
[10:58:48][C][ethernet:309]:   Gateway: GATEIPADDR
[10:58:48][C][ethernet:318]:   DNS1: DNSADDR
[10:58:48][C][ethernet:319]:   DNS2: DNSADDR
[10:58:48][C][ethernet:327]:   MAC Address: C4:DE:E2:B3:1B:1F
[10:58:48][C][ethernet:332]:   Is Full Duplex: YES
[10:58:48][C][ethernet:337]:   Link Speed: 100
[10:58:48][C][ethernet:182]:   Power Pin: 16
[10:58:48][C][ethernet:184]:   MDC Pin: 23
[10:58:48][C][ethernet:185]:   MDIO Pin: 18
[10:58:48][C][ethernet:186]:   Type: LAN8720
[10:58:48][C][ethernet:187]:   PHY addr: 1
[10:58:48][C][mdns:108]: mDNS:
[10:58:48][C][mdns:109]:   Hostname: wt32-eth01-bt-proxy-b31b1c
[10:58:48][C][ota:093]: Over-The-Air Updates:
[10:58:48][C][ota:094]:   Address: wt32-eth01-bt-proxy-b31b1c.local:3232
[10:58:48][C][api:138]: API Server:
[10:58:48][C][api:139]:   Address: wt32-eth01-bt-proxy-b31b1c.local:6053
[10:58:48][C][api:141]:   Using noise encryption: YES
[11:00:18][D][esp32_ble_tracker:246]: Starting scan...
[11:05:18][D][esp32_ble_tracker:246]: Starting scan...
[11:10:18][D][esp32_ble_tracker:246]: Starting scan...
[11:15:18][D][esp32_ble_tracker:246]: Starting scan...
[11:20:18][D][esp32_ble_tracker:246]: Starting scan...
[11:25:18][D][esp32_ble_tracker:246]: Starting scan...

--- OPEN APP AND TRY UNLOCK

[11:30:16][I][bluetooth_proxy:250]: [0] [C1:89:44:4B:2B:A5] Connecting v3 with cache
[11:30:16][D][esp32_ble_tracker:214]: Pausing scan to make connection...
[11:30:16][I][esp32_ble_client:064]: [0] [C1:89:44:4B:2B:A5] 0x01 Attempting BLE connection
[11:30:17][D][esp-idf:000]: W (272360756) BT_HCI: hcif disc complete: hdl 0x0, rsn 0x3e
[11:30:17][D][esp-idf:000]: W (272360861) BT_HCI: hcif disc complete: hdl 0x0, rsn 0x3e
[11:30:17][D][esp-idf:000]: W (272360966) BT_HCI: hcif disc complete: hdl 0x0, rsn 0x3e
[11:30:17][D][esp-idf:000]: W (272361071) BT_HCI: hcif disc complete: hdl 0x0, rsn 0x3e
[11:30:17][D][esp-idf:000]: W (272361074) BT_APPL: gattc_conn_cb: if=3 st=0 id=3 rsn=0x3e
[11:30:17][D][esp-idf:000]: W (272361076) BT_APPL: gattc_conn_cb: if=4 st=0 id=4 rsn=0x3e
[11:30:17][D][esp-idf:000]: W (272361077) BT_APPL: gattc_conn_cb: if=5 st=0 id=5 rsn=0x3e
[11:30:17][W][esp32_ble_client:134]: [0] [] Connection failed, status=133
[11:30:17][D][esp32_ble_tracker:246]: Starting scan...
[11:30:42][I][bluetooth_proxy:250]: [0] [C1:89:44:4B:2B:A5] Connecting v3 with cache
[11:30:42][D][esp32_ble_tracker:214]: Pausing scan to make connection...
[11:30:42][I][esp32_ble_client:064]: [0] [C1:89:44:4B:2B:A5] 0x01 Attempting BLE connection
[11:30:42][D][esp-idf:000]: W (272385896) BT_HCI: hcif disc complete: hdl 0x0, rsn 0x3e
[11:30:42][D][esp-idf:000]: W (272385998) BT_HCI: hcif disc complete: hdl 0x0, rsn 0x3e
[11:30:42][D][esp-idf:000]: W (272386106) BT_HCI: hcif disc complete: hdl 0x0, rsn 0x3e
[11:30:42][D][esp-idf:000]: W (272386211) BT_HCI: hcif disc complete: hdl 0x0, rsn 0x3e
[11:30:42][D][esp-idf:000]: W (272386215) BT_APPL: gattc_conn_cb: if=3 st=0 id=3 rsn=0x3e
[11:30:42][D][esp-idf:000]: W (272386216) BT_APPL: gattc_conn_cb: if=4 st=0 id=4 rsn=0x3e
[11:30:42][D][esp-idf:000]: W (272386217) BT_APPL: gattc_conn_cb: if=5 st=0 id=5 rsn=0x3e
[11:30:42][W][esp32_ble_client:134]: [0] [] Connection failed, status=133

---LOCK finally unlock and i go out

[11:30:42][D][esp32_ble_tracker:246]: Starting scan...
[11:35:42][D][esp32_ble_tracker:246]: Starting scan...
[11:40:42][D][esp32_ble_tracker:246]: Starting scan...
[11:45:42][D][esp32_ble_tracker:246]: Starting scan...

---BACK HOME, open app and try unlock

[11:49:14][I][bluetooth_proxy:250]: [0] [C1:89:44:4B:2B:A5] Connecting v3 with cache
[11:49:14][D][esp32_ble_tracker:214]: Pausing scan to make connection...
[11:49:14][I][esp32_ble_client:064]: [0] [C1:89:44:4B:2B:A5] 0x01 Attempting BLE connection
[11:49:14][D][esp-idf:000]: W (273497936) BT_HCI: hcif disc complete: hdl 0x0, rsn 0x3e
[11:49:14][D][esp-idf:000]: W (273498038) BT_HCI: hcif disc complete: hdl 0x0, rsn 0x3e
[11:49:14][D][esp-idf:000]: W (273498131) BT_HCI: hcif disc complete: hdl 0x0, rsn 0x3e
[11:49:14][D][esp-idf:000]: W (273498248) BT_HCI: hcif disc complete: hdl 0x0, rsn 0x3e
[11:49:14][D][esp-idf:000]: W (273498251) BT_APPL: gattc_conn_cb: if=3 st=0 id=3 rsn=0x3e
[11:49:14][D][esp-idf:000]: W (273498253) BT_APPL: gattc_conn_cb: if=4 st=0 id=4 rsn=0x3e
[11:49:14][D][esp-idf:000]: W (273498254) BT_APPL: gattc_conn_cb: if=5 st=0 id=5 rsn=0x3e
[11:49:14][W][esp32_ble_client:134]: [0] [] Connection failed, status=133
[11:49:14][D][esp32_ble_tracker:246]: Starting scan...
[11:49:39][I][bluetooth_proxy:250]: [0] [C1:89:44:4B:2B:A5] Connecting v3 with cache
[11:49:39][D][esp32_ble_tracker:214]: Pausing scan to make connection...
[11:49:39][I][esp32_ble_client:064]: [0] [C1:89:44:4B:2B:A5] 0x01 Attempting BLE connection
[11:49:39][D][esp-idf:000]: W (273523226) BT_HCI: hcif disc complete: hdl 0x0, rsn 0x3e
[11:49:39][D][esp-idf:000]: W (273523328) BT_HCI: hcif disc complete: hdl 0x0, rsn 0x3e
[11:49:39][D][esp-idf:000]: W (273523421) BT_HCI: hcif disc complete: hdl 0x0, rsn 0x3e
[11:49:39][D][esp-idf:000]: W (273523646) BT_HCI: hcif disc complete: hdl 0x0, rsn 0x3e
[11:49:39][D][esp-idf:000]: W (273523649) BT_APPL: gattc_conn_cb: if=3 st=0 id=3 rsn=0x3e
[11:49:39][D][esp-idf:000]: W (273523651) BT_APPL: gattc_conn_cb: if=4 st=0 id=4 rsn=0x3e
[11:49:39][D][esp-idf:000]: W (273523652) BT_APPL: gattc_conn_cb: if=5 st=0 id=5 rsn=0x3e
[11:49:39][W][esp32_ble_client:134]: [0] [] Connection failed, status=133
[11:49:39][D][esp32_ble_tracker:246]: Starting scan...

---FAIL, finally unlock via key

--- TRY unlock via app

[11:52:56][I][bluetooth_proxy:250]: [0] [C1:89:44:4B:2B:A5] Connecting v3 with cache
[11:52:56][D][esp32_ble_tracker:214]: Pausing scan to make connection...
[11:52:56][I][esp32_ble_client:064]: [0] [C1:89:44:4B:2B:A5] 0x01 Attempting BLE connection
[11:52:57][D][esp-idf:000]: W (273720851) BT_HCI: hcif disc complete: hdl 0x0, rsn 0x3e
[11:52:57][D][esp-idf:000]: W (273720956) BT_HCI: hcif disc complete: hdl 0x0, rsn 0x3e
[11:52:57][D][esp-idf:000]: W (273721058) BT_HCI: hcif disc complete: hdl 0x0, rsn 0x3e
[11:52:57][I][esp32_ble_client:144]: [0] [C1:89:44:4B:2B:A5] Connected
[11:52:57][D][esp32_ble_tracker:246]: Starting scan...

--- here success, lock unloock afr=ter 1 sec.

[11:53:26][I][esp32_ble_client:081]: [0] [C1:89:44:4B:2B:A5] Disconnecting.
[11:53:26][D][esp-idf:000]: W (273750574) BT_HCI: hci cmd send: disconnect: hdl 0x0, rsn:0x13
[11:53:26][D][esp-idf:000]: W (273750576) BT_APPL: gattc_conn_cb: if=3 st=0 id=3 rsn=0x16
[11:53:26][D][esp-idf:000]: W (273750577) BT_APPL: gattc_conn_cb: if=4 st=0 id=4 rsn=0x16
[11:53:26][D][esp-idf:000]: W (273750578) BT_APPL: gattc_conn_cb: if=5 st=0 id=5 rsn=0x16
[11:53:26][D][esp-idf:000]: W (273750615) BT_HCI: hcif disc complete: hdl 0x0, rsn 0x16

---- end of test with LAN proxy
KitHubek commented 1 year ago

The most interesting thing is that I performed exactly the same tests on version 2023.2.5. All add-ons have the same versions, the difference is only in the HA version. And every time the lock responds right away. Zero bugs, just works right away.

KitHubek commented 1 year ago

@bdraco Maby i found problem and solution.

i see at this bt-proxy log and i see dependencies and there is one thing that repeats itself.

On version 2023.2.5, if there is a connection error status 133, a reconnection attempt is made immediately, which is usually successful and, without looking at the logs for the user standing at the door, it is a maximum of 1 second delay, which he does not notice and assumes that the lock opens right away. And that's how it is.

For any HA version above 2023.2.5, if there is a connection failure, there is no retrying the connection immediately. There is ALWAYS a delay of about 25 seconds. Always. Check out my logs posted in this thread with bt-proxy for example from April. Yes it is exactly the same. There is always about a 25 second delay before the connection is attempted again.

[11:30:16][I][bluetooth_proxy:250]: [0] [C1:89:44:4B:2B:A5] Connecting v3 with cache
[11:30:17][W][esp32_ble_client:134]: [0] [] Connection failed, status=133
[11:30:42][I][esp32_ble_client:064]: [0] [C1:89:44:4B:2B:A5] 0x01 Attempting BLE connection

25 sec

[11:49:14][I][bluetooth_proxy:250]: [0] [C1:89:44:4B:2B:A5] Connecting v3 with cache
[11:49:14][W][esp32_ble_client:134]: [0] [] Connection failed, status=133
[11:49:39][I][esp32_ble_client:064]: [0] [C1:89:44:4B:2B:A5] 0x01 Attempting BLE connection

25 sec

[00:14:04][I][bluetooth_proxy:254]: [0] [C1:89:44:4B:2B:A5] Connecting v3 without cache
[00:14:05][W][esp32_ble_client:134]: [0] [] Connection failed, status=133
[00:14:29][I][esp32_ble_client:064]: [0] [C1:89:44:4B:2B:A5] 0x01 Attempting BLE connection

25 sec

[20:33:52][I][bluetooth_proxy:250]: [0] [MA:C:ADDR] Connecting v3 with cache
[20:33:53][W][esp32_ble_client:134]: [0] [] Connection failed, status=133
[20:34:17][I][bluetooth_proxy:250]: [0] [MA:C:ADDR] Connecting v3 with cache

25sec

In my opinion, you need to find this delay in the code and remove it and it will solve the problem.

bdraco commented 1 year ago

So the problem is likely that the error isn’t being propagated back. 25 seconds is the timeout to try again if we get no response

bdraco commented 1 year ago

It’s good to know that the problem isn’t in the SwitchBot integration and it’s deeper in the Bluetooth stack.

I’ve spent most of the available time digging through the SwitchBot code so I’ve put the effort in the wrong place.

My day job is really busy right now but I will try to find some time this week to dig through the Bluetooth stack (it’s 7 or 8 libraries) and see if I can at least get a better way to debug this

bdraco commented 1 year ago

In the mean time can you turn off logs for bleak and turn on logs for aioesphomeapi and homeassistant.components.esphome and get it to fail to connect again?

home-assistant[bot] commented 1 year ago

bluetooth documentation bluetooth source

home-assistant[bot] commented 1 year ago

Hey there @ottowinter, @jesserockz, mind taking a look at this issue as it has been labeled with an integration (esphome) you are listed as a code owner for? Thanks!

Code owner commands Code owners of `esphome` 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 esphome` Removes the current integration label and assignees on the issue, add the integration domain after the command.

(message by CodeOwnersMention)

esphome documentation esphome source (message by IssueLinks)

bdraco commented 1 year ago

related PRs during that timeframe

https://github.com/esphome/aioesphomeapi/pull/391

bdraco commented 1 year ago

So I suspect what is happening is the connection is initially successful that than we get a follow message that the connection has failed and since https://github.com/esphome/aioesphomeapi/pull/391 now resolves the connect right away we never see the error and we have to wait the full timeout

bdraco commented 1 year ago 
# grep -A 2 BluetoothDeviceConnectionResponse home-assistant.log
2023-05-07 13:27:01.625 DEBUG (MainThread) [aioesphomeapi.connection] master_tvcabinet_32 @ 192.168.106.86: Got message of type <class 'api_pb2.BluetoothDeviceConnectionResponse'>: address: 132613642173324
connected: true
mtu: 512
bdraco commented 1 year ago

https://github.com/esphome/aioesphomeapi/pull/391 is definitely the cause of the breakage

bdraco commented 1 year ago

https://github.com/home-assistant/core/pull/new/ble_retry_fix

The fix is in this branch.

Github is having problems at the moment so I can't create a PR to fix it

bdraco commented 1 year ago

@KitHubek I've confident the linked PR will fix the issue, but it would be great to get a test

cd /config
curl -o- -sSL https://gist.githubusercontent.com/bdraco/43f8043cb04b9838383fd71353e99b18/raw/core_integration_pr | bash /dev/stdin -d esphome -p 92741
cat /config/custom_components/esphome/manifest.json

Verify that the version displayed above is "aioesphomeapi==13.7.4" and NOT 3.7.3

Restart HA

Test

Delete /config/custom_components/esphome and restart after testing is completed to restore the core version

bdraco commented 1 year ago

Helps to be looking in the right place.

Thanks @KitHubek for all the debugging and logs 👍

KitHubek commented 1 year ago

@bdraco Ok, done this commands. Version is aioesphomeapi==13.7.4 restarted and HA not starting, here error:

2023-05-07 21:01:07.680 ERROR (MainThread) [homeassistant.loader] Unable to resolve dependencies for esphome:  we are unable to resolve (sub)dependency assist_pipeline
2023-05-07 21:01:07.693 ERROR (MainThread) [root] Uncaught exception
Traceback (most recent call last):
  File "/usr/local/lib/python3.10/runpy.py", line 196, in _run_module_as_main
    return _run_code(code, main_globals, None,
  File "/usr/local/lib/python3.10/runpy.py", line 86, in _run_code
    exec(code, run_globals)
  File "/usr/src/homeassistant/homeassistant/__main__.py", line 226, in <module>
    sys.exit(main())
  File "/usr/src/homeassistant/homeassistant/__main__.py", line 214, in main
    exit_code = runner.run(runtime_conf)
  File "/usr/src/homeassistant/homeassistant/runner.py", line 128, in run
    return loop.run_until_complete(setup_and_run_hass(runtime_config))
  File "/usr/local/lib/python3.10/asyncio/base_events.py", line 646, in run_until_complete
    return future.result()
  File "/usr/src/homeassistant/homeassistant/runner.py", line 109, in setup_and_run_hass
    hass = await bootstrap.async_setup_hass(runtime_config)
  File "/usr/src/homeassistant/homeassistant/bootstrap.py", line 151, in async_setup_hass
    await async_from_config_dict(config_dict, hass) is not None
  File "/usr/src/homeassistant/homeassistant/bootstrap.py", line 291, in async_from_config_dict
    await _async_set_up_integrations(hass, config)
  File "/usr/src/homeassistant/homeassistant/bootstrap.py", line 562, in _async_set_up_integrations
    for dep in itg.all_dependencies:
  File "/usr/src/homeassistant/homeassistant/loader.py", line 678, in all_dependencies
    raise RuntimeError("Dependencies not resolved!")
RuntimeError: Dependencies not resolved!

ok iam on 2023.2.5, updating to 2023..5.2

bdraco commented 1 year ago

It looks like it won't work because of the conflict with the sub dep. Thats a shame as I would really have liked to get a good test but I'm 99% sure I've solved it so go ahead and remove the custom version and let's see if 2023.5.3 does the trick

KitHubek commented 1 year ago

Yes i updated to 2023.5.2 and HA starting ok. Now i will do test with loock.

I understand correctly that in the bt-proxy log there should no longer be a delay of 25 seconds, but there should be a reconnection right away? Should I pay attention to that?

bdraco commented 1 year ago

Yes i updated to 2023.5.2 and HA starting ok.

I didn't realize you were trying on the old version. It will only work on 2023.5.x

I understand correctly that in the bt-proxy log there should no longer be a delay of 25 seconds, but there should be a reconnection right away? Should I pay attention to that?

Yes thats the goal.

KitHubek commented 1 year ago

ok iam for 99% sure that problem solved. Even if first time connection failes, reconnect is right away and finally second time lock opened. Its takes about 2 sec and its very ok.

[21:26:35][I][bluetooth_proxy:254]: [0] [C1:89:44:4B:2B:A5] Connecting v3 without cache
[21:26:35][D][esp32_ble_tracker:214]: Pausing scan to make connection...
[21:26:35][I][esp32_ble_client:064]: [0] [C1:89:44:4B:2B:A5] 0x01 Attempting BLE connection
[21:26:35][D][esp-idf:000]: W (33716892) BT_HCI: hcif disc complete: hdl 0x0, rsn 0x3e
[21:26:35][D][esp-idf:000]: W (33716994) BT_HCI: hcif disc complete: hdl 0x0, rsn 0x3e
[21:26:35][D][esp-idf:000]: W (33717102) BT_HCI: hcif disc complete: hdl 0x0, rsn 0x3e
[21:26:35][D][esp-idf:000]: W (33717204) BT_HCI: hcif disc complete: hdl 0x0, rsn 0x3e
[21:26:35][D][esp-idf:000]: W (33717209) BT_APPL: gattc_conn_cb: if=3 st=0 id=3 rsn=0x3e
[21:26:35][D][esp-idf:000]: W (33717211) BT_APPL: gattc_conn_cb: if=4 st=0 id=4 rsn=0x3e
[21:26:35][D][esp-idf:000]: W (33717212) BT_APPL: gattc_conn_cb: if=5 st=0 id=5 rsn=0x3e
[21:26:35][W][esp32_ble_client:134]: [0] [] Connection failed, status=133
[21:26:35][D][esp32_ble_tracker:246]: Starting scan...
[21:26:36][I][bluetooth_proxy:254]: [0] [C1:89:44:4B:2B:A5] Connecting v3 without cache
[21:26:36][D][esp32_ble_tracker:214]: Pausing scan to make connection...
[21:26:36][I][esp32_ble_client:064]: [0] [C1:89:44:4B:2B:A5] 0x01 Attempting BLE connection
[21:26:36][D][esp-idf:000]: W (33718482) BT_HCI: hcif disc complete: hdl 0x0, rsn 0x3e
[21:26:37][I][esp32_ble_client:196]: [0] [C1:89:44:4B:2B:A5] Connected
[21:26:37][D][esp32_ble_tracker:246]: Starting scan...
[21:26:51][I][esp32_ble_client:081]: [0] [C1:89:44:4B:2B:A5] Disconnecting.
[21:26:51][D][esp-idf:000]: W (33733344) BT_HCI: hci cmd send: disconnect: hdl 0x0, rsn:0x13
[21:26:51][D][esp-idf:000]: W (33733353) BT_APPL: gattc_conn_cb: if=3 st=0 id=3 rsn=0x16
[21:26:51][D][esp-idf:000]: W (33733356) BT_APPL: gattc_conn_cb: if=4 st=0 id=4 rsn=0x16
[21:26:51][D][esp-idf:000]: W (33733359) BT_APPL: gattc_conn_cb: if=5 st=0 id=5 rsn=0x16
[21:26:51][D][esp-idf:000]: W (33733383) BT_HCI: hcif disc complete: hdl 0x0, rsn 0x16
bdraco commented 1 year ago

I also fixed the disconnection race while I reworked that esphome code so it should be a bit more reliable as well

KitHubek commented 1 year ago

:) big thanks for Your support and time.

KitHubek commented 1 year ago

@bdraco

Iam using HA with Yours fix esphome folder in dir custom component and all as i wrote in this 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 log (via app: tap unlock and when unlocked tap lock and lock locked)


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

at bt proxy nothing:

[17:43:20][D][esp32_ble_tracker:246]: Starting scan...
[17:48:20][D][esp32_ble_tracker:246]: Starting scan...
[17:53:20][D][esp32_ble_tracker:246]: Starting scan...
[17:58:20][D][esp32_ble_tracker:246]: Starting scan...
[18:03:20][D][esp32_ble_tracker:246]: Starting scan...

--EDIT--

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
bdraco commented 1 year ago

Please continue in a new issue since it’s a new problem