search

ronengr / hass_nuki_bt

Control Nuki Lock over bluetooth
MIT License
32 stars 7 forks source link

Lock failed to set up #34

Closed kanocz closed 6 months ago

kanocz commented 6 months ago

System Health details

System Information

version core-2023.12.1
installation_type Home Assistant Container
dev false
hassio false
docker true
user root
virtualenv false
python_version 3.11.6
os_name Linux
os_version 6.6.5-x64v3-xanmod1
arch x86_64
timezone Europe/Prague
config_dir /config
Home Assistant Community Store GitHub API | ok -- | -- GitHub Content | ok GitHub Web | ok GitHub API Calls Remaining | 4565 Installed Version | 1.33.0 Stage | running Available Repositories | 1349 Downloaded Repositories | 11
Home Assistant Cloud logged_in | false -- | -- can_reach_cert_server | ok can_reach_cloud_auth | ok can_reach_cloud | ok
Dashboards dashboards | 4 -- | -- resources | 6 views | 2 mode | storage
Recorder oldest_recorder_run | December 9, 2023 at 10:46 -- | -- current_recorder_run | December 16, 2023 at 10:20 estimated_db_size | 717.11 MiB database_engine | sqlite database_version | 3.41.2

Checklist

Describe the issue

Trying to add Nuki Lock 3, device descovered, setup step success, but then on devices page it's "Failed to set up" for "Nuki lock"

Reproduction steps

just add new NukiBT device running HA in docker, hass_nuki_bt installed wia hacs as in instruction

Debug logs

it's 2 log entries:

Logger: homeassistant.config_entries
Source: config_entries.py:402
First occurred: 10:23:53 (1 occurrences)
Last logged: 10:23:53

Error setting up entry Nuki for hass_nuki_bt
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/config_entries.py", line 402, in async_setup
    result = await component.async_setup_entry(hass, self)
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/config/custom_components/hass_nuki_bt/__init__.py", line 86, in async_setup_entry
    if not await coordinator.async_wait_ready():
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/config/custom_components/hass_nuki_bt/coordinator.py", line 151, in async_wait_ready
    await self._async_update()
  File "/config/custom_components/hass_nuki_bt/coordinator.py", line 110, in _async_update
    await self.device.update_state()
  File "/usr/local/lib/python3.11/site-packages/pyNukiBT/nuki.py", line 420, in update_state
    await self.connect() # connect so we can identify the device type and update self._const accordingly
    ^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/pyNukiBT/nuki.py", line 384, in connect
    logger.debug(f"Services {[str(s) for s in self._client.services]}")
                                              ^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/bleak/__init__.py", line 686, in services
    if not self._backend.services:
           ^^^^^^^^^^^^^^^^^^^^^^
AttributeError: 'NoneType' object has no attribute 'services'

This error originated from a custom integration.

Logger: custom_components.hass_nuki_bt
Source: components/bluetooth/active_update_coordinator.py:129
Integration: Nuki Lock (documentation, issues)
First occurred: 10:23:53 (1 occurrences)
Last logged: 10:23:53

54:D2:72:FF:1A:55: Failure while polling
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/bluetooth/active_update_coordinator.py", line 129, in _async_poll
    self.data = await self._async_poll_data(self._last_service_info)
                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/bluetooth/active_update_coordinator.py", line 122, in _async_poll_data
    return await self._poll_method(last_service_info)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/config/custom_components/hass_nuki_bt/coordinator.py", line 113, in _async_update
    logs = await self.device.request_log_entries(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/pyNukiBT/nuki.py", line 585, in request_log_entries
    self._const.NukiCommand.REQUEST_DATA,
    ^^^^^^^^^^^
AttributeError: 'NukiDevice' object has no attribute '_const'

Diagnostics dump

No response

kanocz commented 6 months ago

after commenting some debug lines device seted up sucessfully

image

Paul9999999 commented 6 months ago

Hi there, I seem to have the same issue. Which file did you comment out those lines and what was your rational for that please?

kanocz commented 6 months ago

Hi there, I seem to have the same issue. Which file did you comment out those lines and what was your rational for that please?

it's /usr/local/lib/python3.11/site-packages/pyNukiBT/nuki.py file line 384+ problem is that debug outputs something that is not defined... and in next lines you can see "if this is defined then... else..." so really debug has to be on another line I'll create pull request to pyNukiBT problaly

ronengr commented 6 months ago

This looks like some bug in bleak. after calling bleak's connect() function the device should be connected and the call to client.services should not fail. furthermore, bleak's implementation of connect() accesses the same self._backend object that is claimed to be None in the exception. I don't understand how the connect() can succeed but accessing the services property causes an exception

I'm not sure commenting out the log lines is a good solution, as nuki.py is written with the assumption that after calling client.connect() the client is connected and accessible. If we don't get an exception here we might get one at some other location later on.

kanocz commented 6 months ago

@ronengr is it possible to add some loop with few seconds timeout? like if it's None than wait one second more? or one more await needed somewhere? because looks like self._client is not used in this function for SMARTLOCK_1_2 and if become not-None in some time and lock works without any problem after

ronengr commented 6 months ago

The _backend property is an internal property of bleak. pyNukiBT cannot (or at least shouldn't) access it directly. I am not aware of an bleak API that can test whether _backend is none or not. looking at bleak's code, i don't even understand how _backend can be None, as it is initialized during init and never changed.

furthermore, adding random sleep's is bad programming.

regarding await, i'm not sure what you mean about "more await is needed". await is simply the syntax for python async io, every call to a async function should be done with the "await" syntax. there is no way to do "more await".

only thing I can think of is a strange race condition in hass_nuki_bt/pyNukiBT that changes the self._client while awaiting on bleak's connect() to return. I will try add some protection around updating the _client, maybe this will help.

ronengr commented 6 months ago

@kanocz , as I am not able to reproduce the issue, could you test the following change and let me know if it helps?

--- a/pyNukiBT/nuki.py
+++ b/pyNukiBT/nuki.py
@@ -98,7 +98,9 @@ class NukiDevice:
             if self.just_got_beacon:
                 logger.info(f"Ignoring duplicate beacon from Nuki {device.address}")
                 return
-            self.set_ble_device(device)
+
+            if not self._connect_lock.locked():
+                self.set_ble_device(device)
             self.rssi = advertisement_data.rssi
             if not self.last_state or tx_p & 0x1:
                 self._poll_needed = True

But the more I think about it, the more I think this is an issue with bleak. the self._backend in bleak is set during init(), so there should be no way we have a BleakClient object with no _backend. and we know that we have a BleakClient object, as the exception happens inside the BleakClient class.

kanocz commented 6 months ago

sure that random sleep is not the best way :) and it's not about _backend but _client

btw... which version of bleak do you have?.. it looks like I have 0.21.1

ronengr commented 6 months ago

and it's not about _backend but _client

are you sure? from the logs you provided it seems _client is a valid object, only _backend (inside of bleak) is None

File "/usr/local/lib/python3.11/site-packages/bleak/__init__.py", line 686, in services
    if not self._backend.services:
           ^^^^^^^^^^^^^^^^^^^^^^
AttributeError: 'NoneType' object has no attribute 'services'

btw... which version of bleak do you have?.. it looks like I have 0.21.1

I also have 0.21.1 I think this is the default in HA for at least the last few months.

tonicb78 commented 6 months ago

Same error here, I am using a Shelly as a bt proxy. HA detects the nuki but not able to configure. It is a nuki v4.

Nuki hub with a esp32 works perfect, but it would be nice to use bt directly.

ronengr commented 6 months ago

@tonicb78 as far as i know, Shelly only supports passive bt proxy. Nuki lock requires an active connection. esphome bt proxy does support active bt proxy, so if you use it's FW on the shelly device it should work.

tonicb78 commented 6 months ago

@tonicb78 as far as i know, Shelly only supports passive bt proxy. Nuki lock requires an active connection. esphome bt proxy does support active bt proxy, so if you use it's FW on the shelly device it should work.

Thanks for your help. I will try with a esp32. Kind regards.

kanocz commented 6 months ago

@ronengr yes, it looks like issue in bleak at the end :( so closing this issue

gianpo86 commented 6 months ago

Hi, @ronengr and @kanocz, sorry if I post on a closed issue, but I am experiencing almost the same bug and I am not sure about how to proceed.


2023-12-30 11:10:37.137 WARNING (MainThread) [pyNukiBT.nuki] parse error Error in path (parsing) -> crc
wrong checksum, read 37376, computed 27488
2023-12-30 11:10:37.137 WARNING (MainThread) [pyNukiBT.nuki] Got unexpected message length for command 45028. got length:81 expecting length:8
2023-12-30 11:10:37.137 WARNING (MainThread) [pyNukiBT.nuki] Got 73 unknown bytes with value: b"9\xf1\x88\xfb\xdan\x139\\G\xd1\xfe\xd6}]\xc4\xa8\xb9\xf65\x03\x003\x00\xa9\xfa\xff~\xd44)C\xb2\xf6\x8bQ1\x0f`%S\xde\xba>EQ\xd3\xe4\x8d&\x00\x1f\xdes(\xe5U\x17\x0e2\x15\xb6b\xa3'\xe4\xaaz+\x1b\r\xe9o"
2023-12-30 11:10:37.138 ERROR (MainThread) [pyNukiBT.nuki] HomeAssistant: Received unsolicited notification: Container: 
    auth_id = b'G\x7f)\x93' (total 4)
    command = (enum) (unknown) 45028
    payload = None
    crc = 61753
2023-12-30 11:10:37.138 ERROR (MainThread) [pyNukiBT.nuki] was expecting KEYTURNER_STATES
2023-12-30 11:11:09.538 WARNING (MainThread) [pyNukiBT.nuki] parse error Error in path (parsing) -> crc
wrong checksum, read 37376, computed 30461
2023-12-30 11:11:09.538 WARNING (MainThread) [pyNukiBT.nuki] Got unexpected message length for command 37157. got length:81 expecting length:8
2023-12-30 11:11:09.538 WARNING (MainThread) [pyNukiBT.nuki] Got 73 unknown bytes with value: b'\x81\x18\xd8\x08\xd4\xb7\x8b\x8a\xe9\xc2\xd0\xdc\x06\xd2\x9dJ\x95\xa6\xf65\x03\x003\x00a\x08\x1em\xac\xc5\xef\x7f\xe4\x9e\x10-\xce\xc3\xa2;\xe4\xd4H\x01\xc5M\x8a\x9e+\x15\xd5\x02\x1e\xb8W\xba\x06N\x03\n\x16p\xce;\xba\xbb\xf0\x9e\xbbg\x0f\xb9\xc0'
2023-12-30 11:11:09.538 ERROR (MainThread) [pyNukiBT.nuki] HomeAssistant: Received unsolicited notification: Container: 
    auth_id = b"\x19'\x1e-" (total 4)
    command = (enum) (unknown) 37157
    payload = None
    crc = 6273
2023-12-30 11:11:09.538 ERROR (MainThread) [pyNukiBT.nuki] was expecting KEYTURNER_STATES
2023-12-30 11:11:52.617 WARNING (MainThread) [pyNukiBT.nuki] parse error Error in path (parsing) -> crc
wrong checksum, read 37376, computed 1717
2023-12-30 11:11:52.617 WARNING (MainThread) [pyNukiBT.nuki] Got unexpected message length for command 41699. got length:81 expecting length:8
2023-12-30 11:11:52.617 WARNING (MainThread) [pyNukiBT.nuki] Got 73 unknown bytes with value: b'\x1e\x15!\xd9\x84R\xa2\\\x14\xe3|^\xe9\xd6(\xc8\x99z\xf65\x03\x003\x00\\\xf7\xabQ\xf1\x98\x16\xe9\xe3;Y*\xfa\nd!\xc9\xf7\xc4\xad\xfb\x18\x1c,\xb8$g7\x0b\xd0%+\tb?\xf4\x8b-q\xf6\xb0\xeb\xc3!\xc3x.\xe2\x92'
2023-12-30 11:11:52.617 ERROR (MainThread) [pyNukiBT.nuki] HomeAssistant: Received unsolicited notification: Container: 
    auth_id = b'\xfa\xd2\x18\x9e' (total 4)
    command = (enum) (unknown) 41699
    payload = None
    crc = 5406
2023-12-30 11:11:52.617 ERROR (MainThread) [pyNukiBT.nuki] was expecting KEYTURNER_STATES
2023-12-30 11:12:36.763 WARNING (MainThread) [pyNukiBT.nuki] parse error Error in path (parsing) -> crc
wrong checksum, read 37376, computed 24583
2023-12-30 11:12:36.763 WARNING (MainThread) [pyNukiBT.nuki] Got unexpected message length for command 33971. got length:81 expecting length:8
2023-12-30 11:12:36.763 WARNING (MainThread) [pyNukiBT.nuki] Got 73 unknown bytes with value: b'\x83\xd5\xa9\xa2\xda)\x97\xbe\xac9\x06\xf9\x9eY\xe1{\x08\xb6\xf65\x03\x003\x00\xd5Z\xa4\x82\xbb]\x98\xc3tm\xf1\x84\xfb\x98\x1b\x7f\x03\xef\xaf\x03\xe9\x8f\x93\xb2<\xf0#\x18a\x07oC\xbac\xed\xa6\xf2\xeb&\xb0EQ\xa5\x89^\x12\xb1\x17\xdf'
2023-12-30 11:12:36.764 ERROR (MainThread) [pyNukiBT.nuki] HomeAssistant: Received unsolicited notification: Container: 
    auth_id = b'\x8e\xfc\xbcf' (total 4)
    command = (enum) (unknown) 33971
    payload = None
    crc = 54659
2023-12-30 11:12:36.764 ERROR (MainThread) [pyNukiBT.nuki] was expecting KEYTURNER_STATES
2023-12-30 11:15:41.031 ERROR (MainThread) [homeassistant.config_entries] Error setting up entry Nuki_3A1F1775 for hass_nuki_bt
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/config_entries.py", line 402, in async_setup
    result = await component.async_setup_entry(hass, self)
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/config/custom_components/hass_nuki_bt/__init__.py", line 86, in async_setup_entry
    if not await coordinator.async_wait_ready():
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/config/custom_components/hass_nuki_bt/coordinator.py", line 151, in async_wait_ready
    await self._async_update()
  File "/config/custom_components/hass_nuki_bt/coordinator.py", line 110, in _async_update
    await self.device.update_state()
  File "/usr/local/lib/python3.11/site-packages/pyNukiBT/nuki.py", line 420, in update_state
    await self.connect() # connect so we can identify the device type and update self._const accordingly
    ^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/pyNukiBT/nuki.py", line 384, in connect
    logger.debug(f"Services {[str(s) for s in self._client.services]}")
                                              ^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/bleak/__init__.py", line 686, in services
    if not self._backend.services:
           ^^^^^^^^^^^^^^^^^^^^^^
AttributeError: 'NoneType' object has no attribute 'services'
2023-12-30 11:15:47.276 WARNING (MainThread) [pyNukiBT.nuki] parse error Error in path (parsing) -> crc
wrong checksum, read 37376, computed 10587
2023-12-30 11:15:47.276 WARNING (MainThread) [pyNukiBT.nuki] Got unexpected message length for command 52933. got length:81 expecting length:8
2023-12-30 11:15:47.277 WARNING (MainThread) [pyNukiBT.nuki] Got 73 unknown bytes with value: b'\x93\xd5\x99\xbf/\xd1\xd8\x05\xa8u5P\xf3\xaa$\x1c+\xe3\xf65\x03\x003\x00\xa9\x07\x86\x11%B?\xef\x89D\x08\xff|\xeb\x15@K\x9bC\x13*s\xf6\xf9\xbf\x13\x03\x1f\xc2\xafSz\xf1\xef\xe0qC\x06\xc2\x19]\xadA\x82\x16\x12\xefx"'
2023-12-30 11:15:47.277 ERROR (MainThread) [pyNukiBT.nuki] HomeAssistant: Received unsolicited notification: Container: 
    auth_id = b'\xbb\xe4\x08\xb4' (total 4)
    command = (enum) (unknown) 52933
    payload = None
    crc = 54675
2023-12-30 11:15:47.277 ERROR (MainThread) [pyNukiBT.nuki] was expecting KEYTURNER_STATES
2023-12-30 11:16:07.276 ERROR (MainThread) [custom_components.hass_nuki_bt] 54:D2:72:1F:17:75: Failure while polling
Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/pyNukiBT/nuki.py", line 362, in _send_command
    msg = await self._notify_future
          ^^^^^^^^^^^^^^^^^^^^^^^^^
asyncio.exceptions.CancelledError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/bluetooth/active_update_coordinator.py", line 129, in _async_poll
    self.data = await self._async_poll_data(self._last_service_info)
                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/bluetooth/active_update_coordinator.py", line 122, in _async_poll_data
    return await self._poll_method(last_service_info)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/config/custom_components/hass_nuki_bt/coordinator.py", line 110, in _async_update
    await self.device.update_state()
  File "/usr/local/lib/python3.11/site-packages/pyNukiBT/nuki.py", line 421, in update_state
    msg = await self._send_encrtypted_command(
          ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/pyNukiBT/nuki.py", line 189, in _send_encrtypted_command
    return await self._send_command(
           ^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/pyNukiBT/nuki.py", line 361, in _send_command
    async with async_timeout.timeout(self.command_response_timeout):
  File "/usr/local/lib/python3.11/site-packages/async_timeout/__init__.py", line 141, in __aexit__
    self._do_exit(exc_type)
  File "/usr/local/lib/python3.11/site-packages/async_timeout/__init__.py", line 228, in _do_exit
    raise asyncio.TimeoutError
TimeoutError

Is there a solution for this issue? Running Homeassitant OS on Proxmox, using a Bluetooth stick with a USB extension cable and connecting to a Nuki Lock 4 (non pro)

Edit: to be precise I use a Bluetooth 5.0 USB Adapter--CSR8510A10

ronengr commented 6 months ago

@gianpo86 this looks like a different issue. from the logs it seems something is off with the communication. you can see the crc check is failing at the begging of the log snippet.