After update from 2023.2.5 to 2023.3.6 esphome bluetooth stack takes 25 to retry connecting after error (error not seen) #90265
Comments
|
Hey there @bdraco, @Danielhiversen, @RenierM26, @murtas, @Eloston, @dsypniewski, mind taking a look at this issue as it has been labeled with an integration ( Code owner commandsCode owners of
(message by CodeOwnersMention) switchbot documentation |
KitHubek
changed the title
|
i downgrade HA to 2023.2.5 and problem non exsist. Lock and all other devices from SwitchBot workind excellent |
|
I would try to solve your other issue first as it seems your instance is being overloaded by something which will make this very difficult to track down: |
|
@bdraco please look at this comment: #89061 (comment) the same problem as mine |
There's no logs in that comment to indicate that the problem is the same so I think it's a bit premature to make that conclusion Bluetooth devices have so many failure modes that it's best not to drawn conclusions too quickly especially without logs as we can end up spending months trying to solve the wrong problem |
|
ok, so what i should to do? |
If you mail me the lock and the Bluetooth proxy I'm sure I can figure out what's going wrong. |
|
thanks, but its impossible, because this devixes are on production and if i send You devices i and all users cant enter home. |
|
Here are a few options
|
|
You could also try posting the logs with debug for for switchbot enabled in case there is something more obvious going on there |
|
I added some more debug logging as well in #90317 which will be in 2023.3.7 Note that this is not a fix. Its only to make it easier to track down the issue |
|
ok, when avialable 2023.3.7 will update and send logs here. For now stays on 2023.2.5 because its lastes ver. working ok |
|
today updated to 2023.4 HA core and problem still exsist. Iam using bt proxy, and this problem NO exsist in version 2023.2.6 and lower, From version 2023.3 and higher this problem is all time I turned on debug mode on SwitchBot integration, and here is log: Logger: homeassistant.core Error executing service: <ServiceCall lock.unlock (c:01GXB2D587KQ78QC6XK1EX8BH7): entity_id=['lock.switchbot']> During handling of the above exception, another exception occurred: Traceback (most recent call last): The above exception was the direct cause of the following exception: Traceback (most recent call last): The above exception was the direct cause of the following exception: Traceback (most recent call last): The above exception was the direct cause of the following exception: Traceback (most recent call last): and Logger: switchbot.devices.device (LOCKMACADDRESS): device not found, no longer in range, or poor RSSI: -68 During handling of the above exception, another exception occurred: Traceback (most recent call last): The above exception was the direct cause of the following exception: Traceback (most recent call last): The above exception was the direct cause of the following exception: Traceback (most recent call last): The above exception was the direct cause of the following exception: Traceback (most recent call last): and Logger: aioesphomeapi.connection bt-proxy-esp32 @ 192.168.10.206: Connection error occurred: [Errno 104] Connection reset by peer |
|
Your esphome proxy is likely crashing. Make sure you have the latest firmware and try reducing the config https://esphome.io/components/bluetooth_proxy.html |
|
i have fw 2023.3.2 (Apr 6 2023, 10:49:32) |
|
INFO Reading configuration /config/esphome/bt-proxy-esp32.yaml... |
|
and here is my config: substitutions: wifi: |
|
Try doing a serial flash to make sure nvs is cleared (use a cable instead of ota) |
|
I've experienced the same problem today.. but now, after trying to collect diagnostics from both, HA and esphome bt proxy, the lock works every single time... I will let it sit for like, 1h, and try again. This happened after upgrading HA from 2023.3.6 to 2023.4.0 udpate: Logs from after the downgrade - it only takes 1s: locking: |
|
ok, i do flash via PC and USB cable. Now has config near from here, as You posted: https://esphome.io/components/bluetooth_proxy.html#complete-sample-recommended-configuration and start log fro ESP HOME: will check and report if this changed something or no. |
|
Drop the and use the defaults Those values are for ethernet proxies and will dedicate too much time to the bluetooth radio which may make the wifi unreliable. |
|
can someone check if this was fixed in 23.4.1? |
|
for me in ver 2023.4.1 still not working. @bdraco I do config as You say, now is: tested with thic changes from mornig till now, and, i must say, that is worse than it was before. Before changing the BT proxy configuration, the lock performed the command after a long time, about a minute, and now the lock does not execute the opening command at all. I am sending logs from today. Logger: homeassistant.core Error executing service: <ServiceCall lock.unlock (c:01GXE103CBG0N8BM1VS7JWWD48): entity_id=['lock.zamek']> During handling of the above exception, another exception occurred: Traceback (most recent call last): The above exception was the direct cause of the following exception: Traceback (most recent call last): The above exception was the direct cause of the following exception: Traceback (most recent call last): The above exception was the direct cause of the following exception: and if i want operate lock via switch bot app, response is very good. less than 1 sec. And i have more Switch bot devices, for example door open/close sensor, and i see, that this sensor report ble rssi every some seconds, not more that every 60, and lock not report this value. Lock report this value only when operating (lock/unlock). If not locking/unlocking for example 10 hours, this value not change, rssi is the same, not changing, last report when last lock/unlock. |
|
Thank you for validating this bug in 23.4.1 @KitHubek unless a lot was changed for esphome ble proxy stuff.. the I will stay in the older version for now... wife didn't aprove having to wait 30s in front of our door last night... :( |
|
Hey there @OttoWinter, @jesserockz, mind taking a look at this issue as it has been labeled with an integration ( Code owner commandsCode owners of
(message by CodeOwnersMention) esphome documentation |
bdraco
changed the title
|
related PRs during that timeframe |
|
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 esphome/aioesphomeapi#391 now resolves the connect right away we never see the error and we have to wait the full timeout |
|
|
esphome/aioesphomeapi#391 is definitely the cause of the breakage |
|
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 |
|
@KitHubek I've confident the linked PR will fix the issue, but it would be great to get a test Verify that the version displayed above is "aioesphomeapi==13.7.4" and NOT 3.7.3 Restart HA Test Delete |
|
Helps to be looking in the right place. Thanks @KitHubek for all the debugging and logs 👍 |
|
@bdraco ok iam on 2023.2.5, updating to 2023..5.2 |
|
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 |
|
Yes i updated to 2023.5.2 and HA starting ok. 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? |
I didn't realize you were trying on the old version. It will only work on 2023.5.x
Yes thats the goal. |
|
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. |
|
I also fixed the disconnection race while I reworked that esphome code so it should be a bit more reliable as well |
|
:) |
|
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) at bt proxy nothing: --EDIT-- HERE below log when connection goes via bt=proxy and all working ok |
|
Please continue in a new issue since it’s a new problem |
|
ok, will open new issue. thanks |
bdraco
changed the title
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.0sAdditional information
No response
The text was updated successfully, but these errors were encountered: