Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Unreliable Bluetooth performance with August Smart Lock with Orica BTA-403 #100275

Closed
Samywamy10 opened this issue Sep 13, 2023 · 20 comments
Closed

Comments

@Samywamy10
Copy link

Samywamy10 commented Sep 13, 2023

The problem

Intermittently the August Smart Lock via the Yale Bluetooth integration doesn't respond instantly, and can take up to a few minutes to respond. I've included some errors I've found in the logs, and also a debug log of when the issue actually happened.

I'm using the Orica BTA-403 which I specifically purchased as it was on the high performance adapters list. The lock is 3.491m from the Bluetooth adapter with direct line of sight

Given I ran into this issue I suspect perhaps it's something to do with the Bluetooth adapter itself being reset.

What version of Home Assistant Core has the issue?

core-2023.9.2

What was the last working version of Home Assistant Core?

No response

What type of installation are you running?

Home Assistant OS

Integration causing the issue

Yale Access Bluetooth

Link to integration documentation on our website

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

Diagnostics information

This captures me unlocking from Homekit at 18:43:39, which takes to 18:43:48 to actually respond, and then locking it again, which happens instantly.
home-assistant_yalexs_ble_2023-09-13T08-43-55.898Z.pruned.log

This logbook is a screenshot of what was happening. Basically I hit unlock (6:43:39 PM) , and then you can see the Lock actually responds at 6:43:48 PM, a delay of 9 seconds. I also don't know why there are duplicated events. I only hit lock and unlock once, and the lock only locked and unlocked once.

image

Example YAML snippet

No response

Anything in the logs that might be useful for us?

I've also seen both of these errors:

2023-09-13 18:35:17.300 DEBUG (MainThread) [homeassistant.components.bluetooth.wrappers] 78:9C:85:21:48:F8 - L5000F5 -> /org/bluez/hci0: Connecting (last rssi: -79)
2023-09-13 18:35:28.141 DEBUG (MainThread) [homeassistant.components.bluetooth.manager] hci0 (00:1A:7D:DA:71:13) [connectable]: 78:9C:85:21:48:F8 AdvertisementData(local_name='L5000F5', manufacturer_data={465: b'\x00\x00}\x1c\xb6C\x8cvN4\x82\x9dy\xf5\x13lq\xb6', 76: b'\x061\x01\xe1\xac\xeb\xbadd\x06\x00\xa9\x15\x01\x02\x17\xf5\x9d\x9a'}, service_uuids=['0000003e-0000-1000-8000-0026bb765291', '00000044-0000-1000-8000-0026bb765291', '00000045-0000-1000-8000-0026bb765291', '00000055-0000-1000-8000-0026bb765291', '000000a2-0000-1000-8000-0026bb765291', '00001800-0000-1000-8000-00805f9b34fb', '00001801-0000-1000-8000-00805f9b34fb', '0000180a-0000-1000-8000-00805f9b34fb', '0000fe24-0000-1000-8000-00805f9b34fb'], rssi=-81) match: set()
2023-09-13 18:35:33.076 DEBUG (MainThread) [homeassistant.components.bluetooth.base_scanner] hci0 (00:1A:7D:DA:71:13): Scanner watchdog time_since_last_detection: 3.999923994007986
2023-09-13 18:35:34.343 DEBUG (MainThread) [homeassistant.components.bluetooth.wrappers] 78:9C:85:21:48:F8 - L5000F5 -> /org/bluez/hci0: Connected (last rssi: -79)
2023-09-13 18:35:34.344 DEBUG (MainThread) [bleak_retry_connector] Front Door (L5000F5) - 78:9C:85:21:48:F8: Connected after 1 attempts
2023-09-13 18:35:38.044 ERROR (MainThread) [yalexs_ble.push] Front Door (L5000F5): Disconnected while updating
Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/yalexs_ble/push.py", line 999, in _execute_deferred_update
    await self._update()
  File "/usr/local/lib/python3.11/site-packages/yalexs_ble/push.py", line 109, in _async_wrap_operation_lock
    return await func(self, *args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/yalexs_ble/push.py", line 153, in _async_wrap_retry_bluetooth_connection_error
    return await func(self, *args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/yalexs_ble/push.py", line 696, in _update
    battery_state = await lock.battery()
                    ^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/yalexs_ble/lock.py", line 81, in _async_wrap_connected_operation
    raise DisconnectedError("Lock is not connected")
yalexs_ble.session.DisconnectedError: Lock is not connected
Logger: yalexs_ble.push
Source: /usr/local/lib/python3.11/site-packages/yalexs_ble/push.py:1020
First occurred: 6:16:30 PM (1 occurrences)
Last logged: 6:16:30 PM

Front Door (L5000F5): Bluetooth error updating
Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/yalexs_ble/push.py", line 999, in _execute_deferred_update
    await self._update()
  File "/usr/local/lib/python3.11/site-packages/yalexs_ble/push.py", line 109, in _async_wrap_operation_lock
    return await func(self, *args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/yalexs_ble/push.py", line 153, in _async_wrap_retry_bluetooth_connection_error
    return await func(self, *args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/yalexs_ble/push.py", line 686, in _update
    lock = await self._ensure_connected()
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/yalexs_ble/push.py", line 559, in _ensure_connected
    await self._client.connect()
  File "/usr/local/lib/python3.11/site-packages/yalexs_ble/lock.py", line 184, in connect
    await self.secure_session.start_notify()
  File "/usr/local/lib/python3.11/site-packages/yalexs_ble/session.py", line 211, in start_notify
    await self._start_notify(self._notify)
  File "/usr/local/lib/python3.11/site-packages/yalexs_ble/session.py", line 224, in _start_notify
    await self.client.start_notify(self.read_characteristic, callback)
  File "/usr/local/lib/python3.11/site-packages/bleak/__init__.py", line 834, in start_notify
    await self._backend.start_notify(characteristic, wrapped_callback, **kwargs)
  File "/usr/local/lib/python3.11/site-packages/bleak/backends/bluezdbus/client.py", line 958, in start_notify
    assert_reply(reply)
  File "/usr/local/lib/python3.11/site-packages/bleak/backends/bluezdbus/utils.py", line 22, in assert_reply
    raise BleakDBusError(reply.error_name, reply.body)
bleak.exc.BleakDBusError: [org.freedesktop.DBus.Error.UnknownObject] Method "StartNotify" with signature "" on interface "org.bluez.GattCharacteristic1" doesn't exist

Additional information

No response

@home-assistant
Copy link

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

Code owner commands

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

(message by CodeOwnersMention)


bluetooth documentation
bluetooth source
(message by IssueLinks)

@home-assistant
Copy link

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

Code owner commands

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

(message by CodeOwnersMention)


yalexs_ble documentation
yalexs_ble source
(message by IssueLinks)

@Samywamy10 Samywamy10 changed the title Bluetooth Error Updating with August Smart Lock Slow Bluetooth Performance with August Smart Lock Sep 13, 2023
@Samywamy10
Copy link
Author

Samywamy10 commented Sep 13, 2023

Some more info, it periodically becomes unavailable:
image

Attached relevant logs for when it disconnects between 20:00:58 and 20:03:25
relevant-logs.log

I'm actually seeing this for other bluetooth devices too. This is an Eve door sensor on the same door for example
image

@Samywamy10 Samywamy10 changed the title Slow Bluetooth Performance with August Smart Lock Unreliable Bluetooth Performance with August Smart Lock Sep 13, 2023
@Samywamy10 Samywamy10 changed the title Unreliable Bluetooth Performance with August Smart Lock Unreliable Bluetooth performance with August Smart Lock Sep 13, 2023
@bdraco
Copy link
Member

bdraco commented Sep 13, 2023

How far away is your lock from your Bluetooth adapter ?

@Samywamy10
Copy link
Author

I used a laser measurer, so 3.491m from the Bluetooth adapter with direct line of sight.

@bdraco
Copy link
Member

bdraco commented Sep 14, 2023

Thats a bit far since the stated range on the lock is 20ft. From my experience the range isn't great on these.

You might have better luck if you add a bluetooth proxy https://esphome.github.io/bluetooth-proxies/ or https://www.aliexpress.us/item/2255799901392975.html

@Samywamy10
Copy link
Author

That's only 11ft away with direct line of sight 🤔 . I'm getting similar with the Eve door sensor on the same door.

I've just ordered some esp32 but it wouldn't be that much closer/wouldn't have line of sight

@bdraco
Copy link
Member

bdraco commented Sep 14, 2023

lol, I read that wrong :). Yeah 11ft should be ok

@bdraco
Copy link
Member

bdraco commented Sep 14, 2023

I expect the Esp32 will be much better, but you could try turning on always connected in the options flow in the mean time.

@alexandrechoske
Copy link

alexandrechoske commented Sep 14, 2023

Im having the same issue after updating ha to 23.9,
I reboot my HA every night, and some days it became unavaiable.

image
image

before 23.9 I literally had 0 problem with this, not changed my esp distance at all...

@bdraco
Copy link
Member

bdraco commented Sep 14, 2023

@alexandrechoske Please provide logs. Do they show the same issue as the op?

@bdraco bdraco changed the title Unreliable Bluetooth performance with August Smart Lock Unreliable Bluetooth performance with August Smart Lock with Orica BTA-403 Sep 14, 2023
@bdraco
Copy link
Member

bdraco commented Sep 14, 2023

@Samywamy10 Can you also try watching bluetoothctl from the CLI while you are connecting to the lock. Is the device being constantly being added and removed from the bus?

@bdraco
Copy link
Member

bdraco commented Sep 14, 2023

I'll also add some more logging to bleak-retry-connector so we can get a better idea why the device is being removed from the bus (this all happens at a level below Home Assistant core though so its likely if there is something to fix it will be upstream)

@Samywamy10
Copy link
Author

Samywamy10 commented Sep 14, 2023

Will give it a better try tomorrow as it seems to be paired at the moment and I can't see it showing up in all the other devices that are NEW and DEL:

[L5000F5]# devices
Device 78:9C:85:21:48:F8 L5000F5
[DEL] Device CA:EB:06:8A:34:B1 CA-EB-06-8A-34-B1
[DEL] Device EE:58:2F:BA:8B:7F EE-58-2F-BA-8B-7F
...

IIUC 78:9C:85:21:48:F8 is the lock

@alexandrechoske
Copy link

alexandrechoske commented Sep 14, 2023

@alexandrechoske Please provide logs. Do they show the same issue as the op?

Hi bdraco, here it is, the logs around the time I detected it was unavaiable.

Those are the only two logs that appeard.

Logger: yalexs_ble.push
Source: /usr/local/lib/python3.11/site-packages/yalexs_ble/push.py:1025
First occurred: 08:35:51 (1 occurrences)
Last logged: 08:35:51

Porta Frente (78:9C:85:07:86:25): Disconnected while updating
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 645, in write_gatt_char
    await self._client.bluetooth_gatt_write(
  File "/usr/local/lib/python3.11/site-packages/aioesphomeapi/client.py", line 881, in bluetooth_gatt_write
    await self._send_bluetooth_message_await_response(
  File "/usr/local/lib/python3.11/site-packages/aioesphomeapi/client.py", line 509, in _send_bluetooth_message_await_response
    raise BluetoothGATTAPIError(BluetoothGATTError.from_pb(resp[0]))
aioesphomeapi.core.BluetoothGATTAPIError: Bluetooth GATT Error address=78:9C:85:07:86:25 handle=23 error=133 description=Error

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

Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/yalexs_ble/session.py", line 269, in execute
    return await self._write(command, command_name)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/yalexs_ble/session.py", line 137, in _write
    return await self._locked_write(command, command_name)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/yalexs_ble/session.py", line 192, in _locked_write
    await self.client.write_gatt_char(
  File "/usr/local/lib/python3.11/site-packages/bleak/__init__.py", line 776, in write_gatt_char
    await self._backend.write_gatt_char(characteristic, data, response)
  File "/usr/src/homeassistant/homeassistant/components/esphome/bluetooth/client.py", line 86, in _async_wrap_bluetooth_connected_operation
    return await func(self, *args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/esphome/bluetooth/client.py", line 122, in _async_wrap_bluetooth_operation
    raise BleakError(str(ex)) from ex
bleak.exc.BleakError: Bluetooth GATT Error address=78:9C:85:07:86:25 handle=23 error=133 description=Error

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

Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/yalexs_ble/push.py", line 999, in _execute_deferred_update
    await self._update()
  File "/usr/local/lib/python3.11/site-packages/yalexs_ble/push.py", line 109, in _async_wrap_operation_lock
    return await func(self, *args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/yalexs_ble/push.py", line 153, in _async_wrap_retry_bluetooth_connection_error
    return await func(self, *args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/yalexs_ble/push.py", line 686, in _update
    lock = await self._ensure_connected()
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/yalexs_ble/push.py", line 559, in _ensure_connected
    await self._client.connect()
  File "/usr/local/lib/python3.11/site-packages/yalexs_ble/lock.py", line 186, in connect
    await self._setup_session()
  File "/usr/local/lib/python3.11/site-packages/yalexs_ble/lock.py", line 263, in _setup_session
    response = await self.secure_session.execute(cmd, "SEC_INITIALIZATION_COMMAND")
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/yalexs_ble/session.py", line 276, in execute
    raise DisconnectedError(f"{self.name}: {err}") from err
yalexs_ble.session.DisconnectedError: Porta Frente (78:9C:85:07:86:25): Bluetooth GATT Error address=78:9C:85:07:86:25 handle=23 error=133 description=Error

Logger: yalexs_ble.push
Source: /usr/local/lib/python3.11/site-packages/yalexs_ble/push.py:1020
First occurred: 08:41:56 (1 occurrences)
Last logged: 08:41:56

Porta Frente (78:9C:85:07:86:25): Bluetooth error updating
Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/bleak_retry_connector/__init__.py", line 350, in establish_connection
    await client.connect(
  File "/usr/src/homeassistant/homeassistant/components/bluetooth/wrappers.py", line 292, in connect
    connected = await super().connect(**kwargs)
                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/bleak/__init__.py", line 605, in connect
    return await self._backend.connect(**kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  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 367, in connect
    await connected_future
bleak.exc.BleakError: Error ESP_GATT_CONN_TIMEOUT while connecting: Connection failed due to timeout

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

Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/yalexs_ble/push.py", line 999, in _execute_deferred_update
    await self._update()
  File "/usr/local/lib/python3.11/site-packages/yalexs_ble/push.py", line 109, in _async_wrap_operation_lock
    return await func(self, *args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/yalexs_ble/push.py", line 153, in _async_wrap_retry_bluetooth_connection_error
    return await func(self, *args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/yalexs_ble/push.py", line 686, in _update
    lock = await self._ensure_connected()
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/yalexs_ble/push.py", line 559, in _ensure_connected
    await self._client.connect()
  File "/usr/local/lib/python3.11/site-packages/yalexs_ble/lock.py", line 153, in connect
    raise err
  File "/usr/local/lib/python3.11/site-packages/yalexs_ble/lock.py", line 143, in connect
    self.client = await establish_connection(
                  ^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/bleak_retry_connector/__init__.py", line 438, in establish_connection
    _raise_if_needed(name, device.address, exc)
  File "/usr/local/lib/python3.11/site-packages/bleak_retry_connector/__init__.py", line 323, in _raise_if_needed
    raise BleakAbortedError(f"{msg}: {ABORT_ADVICE}") from exc
bleak_retry_connector.BleakAbortedError: Porta Frente (78:9C:85:07:86:25) - 78:9C:85:07:86:25: Failed to connect after 5 attempt(s): Error ESP_GATT_CONN_TIMEOUT while connecting: Connection failed due to timeout: Interference/range; External Bluetooth adapter w/extension may help; Extension cables reduce USB 3 port interference

Now by the time I write this post, the lock is working fine and connection is ok.
Maybe it connected in the mean time...

@bdraco
Copy link
Member

bdraco commented Sep 14, 2023

Thanks. Looks like a completely different issue but the net effect is the same

@Samywamy10
Copy link
Author

Ok got my ESP32s. I realise this is a bit unrelated to the original thread, happy to start a new issue but want to confirm where the problem lies...

This is with a Bluetooth proxy about ~1.5m from the door but through a wall. You can see it takes ~4 seconds to unlock when I first trigger, but 1 second when I go to lock it.

image

Relevant logs:

home-assistant_yalexs_ble_2023-09-16T01-12-49.427Z.log

In an earlier test it took 8 seconds but didn't have debug logging enabled:
image

@bdraco
Copy link
Member

bdraco commented Sep 16, 2023

4s isn't that bad considering it has to make the connection and best case each transaction is ~100ms and you'll take at least 3 to exchange the key let alone the unlock commands. It's much faster once it's already connected. After you do a transaction it stays connected for 10-15s so once it's connected it's faster

Enable always connected mode if you need it to be faster. https://www.home-assistant.io/integrations/yalexs_ble/#options

Make sure you have flashed with esp-idf framework to ensure caching services works

@bdraco
Copy link
Member

bdraco commented Sep 16, 2023

Also if you did the Wi-Fi based esp32s they have to share radio time between the Bluetooth and WiFi since they use the same radio. The Ethernet connected ones don't have this issue so they will be faster

@issue-triage-workflows
Copy link

There hasn't been any activity on this issue recently. Due to the high number of incoming GitHub notifications, we have to clean some of the old issues, as many of them have already been resolved with the latest updates.
Please make sure to update to the latest Home Assistant version and check if that solves the issue. Let us know if that works for you by adding a comment 👍
This issue has now been marked as stale and will be closed if no further activity occurs. Thank you for your contributions.

@issue-triage-workflows issue-triage-workflows bot closed this as not planned Won't fix, can't repro, duplicate, stale Dec 22, 2023
@github-actions github-actions bot locked and limited conversation to collaborators Jan 21, 2024
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

No branches or pull requests

3 participants