regevbr / RaspiNukiBridge

Simple Nuki Bridge implementation using asyncio
MIT License
15 stars 3 forks source link

pairing does not work #2

Closed regevbr closed 2 years ago

regevbr commented 2 years ago

As reported in https://github.com/f1ren/RaspiNukiBridge/issues/4 by @saltech1 the pairing doesn't work.

Task exception was never retrieved future: <Task finished name='Task-2' coro=<Nuki.pair() done, defined at /opt/./nuki.py:738> exception=AttributeError("'NoneType' object has no attribute 'put'")> Traceback (most recent call last): File "/opt/./nuki.py", line 743, in pair await self._send_data(self._BLE_PAIRING_CHAR, cmd) File "/opt/./nuki.py", line 653, in _send_data await self.manager.taskQueue.add_task(task) File "/opt/./nuki.py", line 300, in add_task await self._queue.put(wrapper_task) AttributeError: 'NoneType' object has no attribute 'put'

Full log here: https://pastebin.com/YzdKSugb

regevbr commented 2 years ago

I introduced a bug that prevents you from pairing (I did all my work after it was already paired). I just released an alpha version v0.0.23-alpha.6, @saltech1 can you please try pairing with it and let me know if it works, and if not, send full logs. I can't debug myself without factory resetting my nuki and I don't want to do that :-(

To install the repo, please follow the instructions on the readme of this repo

saltech1 commented 2 years ago

I have installed the 0.23a6 version. Trying to run it, it seems to immediately exit.

This line appears in the home assistant logs:

Logger: homeassistant.components.hassio Source: components/hassio/websocket_api.py:122 Integration: Home Assistant Supervisor (documentation, issues) First occurred: 3:28:50 PM (11 occurrences) Last logged: 3:30:54 PM

Failed to to call /addons/4b34517f_nuki_bridge/stats - Failed to to call /host/info - Failed to to call /supervisor/stats -

I am unable to get the logs for NukiBridge. This also makes home assistant less responsive.

Anything else to try?

regevbr commented 2 years ago

very strange, I run it on my HA and it works great... (except the pairing part which I can't test) sadly without the logs I can't do much... Can you try to remove the addon and then re add it? Also try to capture the logs while you start it (once it is stopped you can't access the logs)

saltech1 commented 2 years ago

I will try re-adding.

FWIW, I had this problem of immediately quitting with the version on the other branch (f1ren). Your previous build did not have it (but it failed to pair). The new build you have published has that problem now.

saltech1 commented 2 years ago

Running now - nuki was not in pairing mode:

[s6-init] making user provided files available at /var/run/s6/etc...exited 0. [s6-init] ensuring user provided files have correct perms...exited 0. [fix-attrs.d] applying ownership & permissions fixes... [fix-attrs.d] done. [cont-init.d] executing container initialization scripts... [cont-init.d] 00-banner.sh: executing...

parse error: Expected string key before ':' at line 1, column 4 [15:47:57] ERROR: Unknown HTTP error occured Add-on:


Add-on version: You are running the latest version of this add-on. parse error: Expected string key before ':' at line 1, column 4 [15:48:00] ERROR: Unknown HTTP error occured System: ( / ) Home Assistant Core: Home Assistant Supervisor:

Please, share the above information when looking for help or support in, e.g., GitHub, forums or the Discord chat.

[cont-init.d] 00-banner.sh: exited 0. [cont-init.d] 01-log-level.sh: executing... parse error: Expected string key before ':' at line 1, column 4 [15:48:02] ERROR: Unknown HTTP error occured [cont-init.d] 01-log-level.sh: exited 0. [cont-init.d] done. [services.d] starting services [services.d] done. 2022-07-18 15:48:10.500|I|config.py:143|Access Token: ZZZ 2022-07-18 15:48:10.500|I|config.py:144|app_id: 4175591448 2022-07-18 15:48:10.511|I|config.py:149|Generating new keys 2022-07-18 15:48:10.512|I|config.py:153|bridge_public_key: XXX 2022-07-18 15:48:10.512|I|config.py:154|bridge_private_key: YYY 2022-07-18 15:48:11.840|I|nuki.py:254|Waiting for more tasks with timeout 2022-07-18 15:48:11.843|I|nuki.py:275|Working on task 2022-07-18 15:48:11.844|I|nuki.py:642|Trying to send data. Attempt 1 2022-07-18 15:48:11.846|I|nuki.py:676|Nuki connecting 2022-07-18 15:48:15.841|I|nuki.py:367|Device type: DeviceType.SMARTLOCK_1_2 2022-07-18 15:48:15.919|I|nuki.py:688|Connected 2022-07-18 15:48:15.920|I|nuki.py:647|Sending data to a92ee202-5501-11e4-916c-0800200c9a66: b"\x01\x00\x03\x00'\xa7" 2022-07-18 15:48:15.949|I|nuki.py:657|Data sent on attempt 1 2022-07-18 15:48:15.950|I|nuki.py:277|Finished task 2022-07-18 15:48:15.951|I|nuki.py:254|Waiting for more tasks with timeout Task exception was never retrieved future: <Task finished name='Task-9' coro=<Nuki._notification_handler() done, defined at /opt/./nuki.py:539> exception=error('unpack requires a buffer of 6 bytes')> Traceback (most recent call last): File "/opt/./nuki.py", line 546, in _notification_handler uncrypted = self._decrypt_command(bytes(data)) File "/opt/./nuki.py", line 404, in _decrypt_command auth_id, length = struct.unpack("<IH", data[24:30]) struct.error: unpack requires a buffer of 6 bytes 2022-07-18 15:48:25.954|I|nuki.py:258|No more tasks - cleaning up 2022-07-18 15:48:25.956|I|nuki.py:692|Nuki disconnecting... 2022-07-18 15:48:26.423|I|nuki.py:695|Nuki disconnected 2022-07-18 15:48:26.424|I|nuki.py:181|Starting a scan 2022-07-18 15:48:26.424|I|nuki.py:184|Scanning attempt 1 2022-07-18 15:48:26.520|I|nuki.py:186|Scanning succeeded on attempt 1 2022-07-18 15:48:26.520|I|nuki.py:267|Waiting for next task 2022-07-18 15:48:27.387|I|nuki.py:221|Nuki: 54:D2:72:3F:19:0D, adapter: hci0, RSSI: -75 AdvertisementData(local_name='Nuki_2E3F190D', manufacturer_data={76: b'\x02\x15\xa9.\xe2\x00U\x01\x11\xe4\x91l\x08\x00 \x0c\x9af.?\x19\r\xc9'}, service_uuids=['0000003e-0000-1000-8000-0026bb765291', '00000044-0000-1000-8000-0026bb765291', '00000045-0000-1000-8000-0026bb765291', '00000055-0000-1000-8000-0026bb765291', '00000096-0000-1000-8000-0026bb765291', '000000a2-0000-1000-8000-0026bb765291', '00001800-0000-1000-8000-00805f9b34fb', '0000180a-0000-1000-8000-00805f9b34fb', 'a92ee100-5501-11e4-916c-0800200c9a66', 'a92ee200-5501-11e4-916c-0800200c9a66']) 2022-07-18 15:48:27.388|I|nuki.py:701|Querying Nuki state Task exception was never retrieved future: <Task finished name='Task-16' coro=<NukiManager._detected_ibeacon() done, defined at /opt/./nuki.py:212> exception=TypeError("unsupported operand type(s) for +: 'NoneType' and 'bytes'")> Traceback (most recent call last): File "/opt/./nuki.py", line 238, in _detected_ibeacon await nuki.update_state() File "/opt/./nuki.py", line 704, in update_state cmd = self._encrypt_command(NukiCommand.REQUEST_DATA.value, payload) File "/opt/./nuki.py", line 393, in _encrypt_command unencrypted = self.auth_id + self._prepare_command(cmd_code, payload)[:-2] TypeError: unsupported operand type(s) for +: 'NoneType' and 'bytes'

Will retry after putting in pairing mode

regevbr commented 2 years ago

Did you ever pair you Nuki before? If so you probably need to factory reset it in order for this to work

saltech1 commented 2 years ago

I did not pair it with a bridge or successfully with this software.

This is the error I'm getting now:

[s6-init] making user provided files available at /var/run/s6/etc...exited 0. [s6-init] ensuring user provided files have correct perms...exited 0. [fix-attrs.d] applying ownership & permissions fixes... [fix-attrs.d] done. [cont-init.d] executing container initialization scripts... [cont-init.d] 00-banner.sh: executing...

Add-on: Nuki Bridge Virtual Nuki Bridge to use instead of the physical device

Add-on version: 0.0.23-alpha.6 You are running the latest version of this add-on. System: Home Assistant OS 8.2 (aarch64 / raspberrypi4-64) Home Assistant Core: 2022.7.5 Home Assistant Supervisor: 2022.07.0

Please, share the above information when looking for help or support in, e.g., GitHub, forums or the Discord chat.

[cont-init.d] 00-banner.sh: exited 0. [cont-init.d] 01-log-level.sh: executing... [cont-init.d] 01-log-level.sh: exited 0. [cont-init.d] done. [services.d] starting services [services.d] done. 2022-07-18 15:50:41.939|I|config.py:143|Access Token: XXX 2022-07-18 15:50:41.939|I|config.py:144|app_id: 3349604170 2022-07-18 15:50:41.941|I|config.py:149|Generating new keys 2022-07-18 15:50:41.942|I|config.py:153|bridge_public_key: yyy 2022-07-18 15:50:41.942|I|config.py:154|bridge_private_key: zzz 2022-07-18 15:50:43.209|I|nuki.py:254|Waiting for more tasks with timeout 2022-07-18 15:50:43.211|I|nuki.py:275|Working on task 2022-07-18 15:50:43.211|I|nuki.py:642|Trying to send data. Attempt 1 2022-07-18 15:50:43.212|I|nuki.py:676|Nuki connecting 2022-07-18 15:50:47.108|I|nuki.py:367|Device type: DeviceType.SMARTLOCK_1_2 2022-07-18 15:50:47.167|I|nuki.py:688|Connected 2022-07-18 15:50:47.168|I|nuki.py:647|Sending data to a92ee202-5501-11e4-916c-0800200c9a66: b"\x01\x00\x03\x00'\xa7" 2022-07-18 15:50:47.197|I|nuki.py:657|Data sent on attempt 1 2022-07-18 15:50:47.198|I|nuki.py:277|Finished task 2022-07-18 15:50:47.199|I|nuki.py:254|Waiting for more tasks with timeout Task exception was never retrieved future: <Task finished name='Task-9' coro=<Nuki._notification_handler() done, defined at /opt/./nuki.py:539> exception=error('unpack requires a buffer of 6 bytes')> Traceback (most recent call last): File "/opt/./nuki.py", line 546, in _notification_handler uncrypted = self._decrypt_command(bytes(data)) File "/opt/./nuki.py", line 404, in _decrypt_command auth_id, length = struct.unpack("<IH", data[24:30]) struct.error: unpack requires a buffer of 6 bytes 2022-07-18 15:50:57.211|I|nuki.py:258|No more tasks - cleaning up 2022-07-18 15:50:57.212|I|nuki.py:692|Nuki disconnecting... 2022-07-18 15:51:06.743|I|nuki.py:695|Nuki disconnected 2022-07-18 15:51:07.204|I|nuki.py:181|Starting a scan 2022-07-18 15:51:07.204|I|nuki.py:184|Scanning attempt 1 2022-07-18 15:51:07.494|I|nuki.py:186|Scanning succeeded on attempt 1 2022-07-18 15:51:07.494|I|nuki.py:267|Waiting for next task 2022-07-18 15:51:07.524|I|nuki.py:216|No manufacturer_data (76) in advertisement_data: AdvertisementData(local_name='Nuki_2E3F190D', service_data={'a92ee100-5501-11e4-916c-0800200c9a66': b'.?\x19\r'}, service_uuids=['0000003e-0000-1000-8000-0026bb765291', '00000044-0000-1000-8000-0026bb765291', '00000045-0000-1000-8000-0026bb765291', '00000055-0000-1000-8000-0026bb765291', '00000096-0000-1000-8000-0026bb765291', '000000a2-0000-1000-8000-0026bb765291', '00001800-0000-1000-8000-00805f9b34fb', '0000180a-0000-1000-8000-00805f9b34fb', 'a92ee100-5501-11e4-916c-0800200c9a66', 'a92ee200-5501-11e4-916c-0800200c9a66']) 2022-07-18 15:51:39.681|I|nuki.py:221|Nuki: 54:D2:72:3F:19:0D, adapter: hci0, RSSI: -70 AdvertisementData(local_name='Nuki_2E3F190D', manufacturer_data={76: b'\x02\x15\xa9.\xe2\x00U\x01\x11\xe4\x91l\x08\x00 \x0c\x9af.?\x19\r\xc9'}, service_data={'a92ee100-5501-11e4-916c-0800200c9a66': b'.?\x19\r'}, service_uuids=['0000003e-0000-1000-8000-0026bb765291', '00000044-0000-1000-8000-0026bb765291', '00000045-0000-1000-8000-0026bb765291', '00000055-0000-1000-8000-0026bb765291', '00000096-0000-1000-8000-0026bb765291', '000000a2-0000-1000-8000-0026bb765291', '00001800-0000-1000-8000-00805f9b34fb', '0000180a-0000-1000-8000-00805f9b34fb', 'a92ee100-5501-11e4-916c-0800200c9a66', 'a92ee200-5501-11e4-916c-0800200c9a66']) 2022-07-18 15:51:39.684|I|nuki.py:701|Querying Nuki state Task exception was never retrieved future: <Task finished name='Task-19' coro=<NukiManager._detected_ibeacon() done, defined at /opt/./nuki.py:212> exception=TypeError("unsupported operand type(s) for +: 'NoneType' and 'bytes'")> Traceback (most recent call last): File "/opt/./nuki.py", line 238, in _detected_ibeacon await nuki.update_state() File "/opt/./nuki.py", line 704, in update_state cmd = self._encrypt_command(NukiCommand.REQUEST_DATA.value, payload) File "/opt/./nuki.py", line 393, in _encrypt_command unencrypted = self.auth_id + self._prepare_command(cmd_code, payload)[:-2] TypeError: unsupported operand type(s) for +: 'NoneType' and 'bytes'

Unforuntaely I don't think I'm going to factory reset at this state, similar to your unwillingness to do so... Will probably use the ESP32 nuki hub until this matures a bit. Looking forward to this.

regevbr commented 2 years ago

Ok thanks for trying

saltech1 commented 2 years ago

np. this is an awesome project - I will watch it mature and give another try then.

regevbr commented 2 years ago

@f1ren do you have a way to test this library pairing mode on one of your Nukis by any chance? They need to be factory reset before they can be paired again... (or at least I guess so :-) )

f1ren commented 2 years ago

@regevbr not sure I want to factory reset.

Should I revert your PR in my fork?

regevbr commented 2 years ago

Ok I got it all wrong - no need to factory reset the nuki (I'm so glad I didn't do that lol)

I found the bug (that my hubris introduced) and managed to get the pairing to work again.

@saltech1 can you please try alpha 8? I think it will be easier than setting up an esp32 with a non-compliant API that can't be utilized by the official (and better non-official) nuki integrations

regevbr commented 2 years ago

@regevbr not sure I want to factory reset.

Should I revert your PR in my fork?

no need, I only synced your repo with the original repo and added the addon theatrics.... The change that messed the pairing up is only on my repo (but no more :-) )

and thanks for replying :-)

saltech1 commented 2 years ago

It works!

Note that it took several times to get the addon to start, but now it seems to work.

Also note that it seems there is some delay for the lock/unlock commands, including one attempt that was not actually executed on the lock.

I'm using the official HA integration. Would the nuki_ng one be better?

regevbr commented 2 years ago

Glad to hear! I'm not sure why you have issues, for me it works smoothly... never tried the official one, skipped directly to nuki_ng and I'm happy with it. About the response time, I changed my nuki settings to use medium energy saving (instead of automatic) and it seems to do the trick for me.

I will publish an official release now

regevbr commented 2 years ago

@saltech1 if you still experience issues with responsiveness after changing the energy setting, please open a new issue with full logs and I will try to take a look

saltech1 commented 2 years ago

I will try both the energy settting and nuki_ng. Thank you!

One last question - in the Nuki app, when looking at "Connection status", I'm not seeing the lock connected to a bridge (but the functionality works). Is that expected?

regevbr commented 2 years ago

That is the way it is for me... I'm guessing that is ok :-)