search

ronengr / hass_nuki_bt

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

Nuki Smart Lock 4 (non-pro) stuck on initializing #36

Closed cicero200272 closed 2 months ago

cicero200272 commented 4 months ago

System Health details

System Information

version core-2024.2.1
installation_type Home Assistant Container
dev false
hassio false
docker true
user root
virtualenv false
python_version 3.12.1
os_name Linux
os_version 5.10.103-v7l+
arch armv7l
timezone Europe/Berlin
config_dir /config
Home Assistant Community Store GitHub API | ok -- | -- GitHub Content | ok GitHub Web | ok GitHub API Calls Remaining | 4391 Installed Version | 1.34.0 Stage | running Available Repositories | 1398 Downloaded Repositories | 34
Home Assistant Cloud logged_in | true -- | -- subscription_expiration | 21. September 2024 um 02:00 relayer_connected | true relayer_region | eu-central-1 remote_enabled | true remote_connected | true alexa_enabled | true google_enabled | false remote_server | eu-central-1-7.ui.nabu.casa certificate_status | ready instance_id | 35c5ebd370f5454f90f48a8a563ac01f can_reach_cert_server | ok can_reach_cloud_auth | ok can_reach_cloud | ok
Dashboards dashboards | 4 -- | -- resources | 19 views | 8 mode | yaml
Recorder oldest_recorder_run | 14. Februar 2024 um 09:58 -- | -- current_recorder_run | 20. Februar 2024 um 16:45 estimated_db_size | 233.30 MiB database_engine | mysql database_version | 10.6.11
Spotify api_endpoint_reachable | ok -- | --

Checklist

Describe the issue

My Nuki lock (4th generation) non-pro cannot be initialized. It is automatically discovered and paired, but then the initialization process runs of the integration over and over again.

image

HA runs in a docker container on my Raspberry Pi 4, for bluetooth I use an ESP32 BT proxy.

Seems closely related to https://github.com/ronengr/hass_nuki_bt/issues/34#issuecomment-1872500072 and https://github.com/ronengr/hass_nuki_bt/issues/35

Reproduction steps

  1. Add custom repo & download the addon in HACS
  2. Restart HA -> lock is automatically detected
  3. Click "Configure", set lock in pairing mode and let the integration automatically configure the lock (bridge mode)
  4. Integration is created, but never finishes the initialization process

Debug logs

2024-02-20 17:17:26.133 INFO (MainThread) [pyNukiBT.nuki] Nuki: XX:XX:XX:XX:XX:XX, RSSI: -82
2024-02-20 17:17:26.133 INFO (MainThread) [pyNukiBT.nuki] Querying Nuki state
2024-02-20 17:17:26.140 INFO (MainThread) [pyNukiBT.nuki] Querying Nuki state
2024-02-20 17:17:26.140 INFO (MainThread) [pyNukiBT.nuki] update state already in progress. ignoring
2024-02-20 17:17:29.797 DEBUG (MainThread) [pyNukiBT.nuki] Services ['00001801-0000-1000-8000-00805f9b34fb (Handle: 1): Generic Attribute Profile', '00001800-0000-1000-8000-00805f9b34fb (Handle: 9): Generic Access Profile', '0000180a-0000-1000-8000-00805f9b34fb (Handle: 14): Device Information', 'a92ee100-5501-11e4-916c-0800200c9a66 (Handle: 23): Unknown', 'a92ee200-5501-11e4-916c-0800200c9a66 (Handle: 27): Unknown', '0000fff6-0000-1000-8000-00805f9b34fb (Handle: 36): Vendor specific']
2024-02-20 17:17:29.798 DEBUG (MainThread) [pyNukiBT.nuki] Characteristics ['00002a05-0000-1000-8000-00805f9b34fb (Handle: 3): Service Changed', '00002b2a-0000-1000-8000-00805f9b34fb (Handle: 6): Database Hash', '00002b29-0000-1000-8000-00805f9b34fb (Handle: 8): Client Supported Features', '00002a00-0000-1000-8000-00805f9b34fb (Handle: 11): Device Name', '00002a01-0000-1000-8000-00805f9b34fb (Handle: 13): Appearance', '00002a25-0000-1000-8000-00805f9b34fb (Handle: 16): Serial Number String', '00002a27-0000-1000-8000-00805f9b34fb (Handle: 18): Hardware Revision String', '00002a26-0000-1000-8000-00805f9b34fb (Handle: 20): Firmware Revision String', '00002a24-0000-1000-8000-00805f9b34fb (Handle: 22): Model Number String', 'a92ee101-5501-11e4-916c-0800200c9a66 (Handle: 25): Unknown', 'a92ee201-5501-11e4-916c-0800200c9a66 (Handle: 29): Unknown', 'a92ee202-5501-11e4-916c-0800200c9a66 (Handle: 32): Unknown', 'a92ee203-5501-11e4-916c-0800200c9a66 (Handle: 35): Unknown', '18ee2ef5-263d-4559-959f-4f9c429f9d11 (Handle: 38): Unknown', '18ee2ef5-263d-4559-959f-4f9c429f9d12 (Handle: 40): Unknown']
2024-02-20 17:17:29.900 INFO (MainThread) [pyNukiBT.nuki] Connected
2024-02-20 17:17:29.901 INFO (MainThread) [pyNukiBT.nuki] sending encrypted command REQUEST_DATA
2024-02-20 17:17:29.901 INFO (MainThread) [pyNukiBT.nuki] Trying to send data. Attempt 1
2024-02-20 17:17:29.901 INFO (MainThread) [pyNukiBT.nuki] Connected
2024-02-20 17:17:29.901 INFO (MainThread) [pyNukiBT.nuki] Sending data to Nuki
2024-02-20 17:17:30.059 DEBUG (MainThread) [pyNukiBT.nuki] Notification handler: a92ee202-5501-11e4-916c-0800200c9a66 (Handle: 32): Unknown, data: bytearray(b'\r\xe8\xaa\xb0Y\xdc\xc1\xfa\xf7\x0f\xae\x17?o\xabo\xa1\'1\xe4\xdb1n\x1b>\xa1\x01\x003\x00Wr{\x11\xf9"\x83\xa4\xbe\xbfF\xb3\xc4\xc8\x06\xc5\xd2\x8c\x80\xde\x03\x9bd\xd9\xbf>\xba\xb0\x05\xec\x04\x99L\x9eB \x8c\x0bH^&\xf1}Ja\xff\xb7\xa1\xf39Q')
2024-02-20 17:17:30.061 INFO (MainThread) [pyNukiBT.nuki] Data sent on attempt 1
2024-02-20 17:17:30.062 DEBUG (MainThread) [pyNukiBT.nuki] State: Container: 
    nuki_state = (enum) DOOR_MODE 2
    lock_state = (enum) UNLOCKED 3
    trigger = (enum) SYSTEM 0
    current_time = Container: 
        year = 2024
        month = 2
        day = 20
        hour = 16
        minute = 17
        second = 31
    timezone_offset = 0
    critical_battery_state = 200
    config_update_count = 3
    lock_n_go_timer = 0
    last_lock_action = (enum) UNLOCK 1
    last_lock_action_trigger = (enum) SYSTEM 0
    last_lock_action_completion_status = (enum) SUCCESS 0
    door_sensor_state = (enum) UNAVAILABLE 0
    nightmode_active = 0
    accessory_battery_state = 3
2024-02-20 17:17:30.063 INFO (MainThread) [pyNukiBT.nuki] Retrieve nuki configuration
2024-02-20 17:17:30.063 INFO (MainThread) [pyNukiBT.nuki] Connected
2024-02-20 17:17:30.065 INFO (MainThread) [pyNukiBT.nuki] sending encrypted command REQUEST_DATA
2024-02-20 17:17:30.065 INFO (MainThread) [pyNukiBT.nuki] Trying to send data. Attempt 1
2024-02-20 17:17:30.065 INFO (MainThread) [pyNukiBT.nuki] Connected
2024-02-20 17:17:30.066 INFO (MainThread) [pyNukiBT.nuki] Sending data to Nuki
2024-02-20 17:17:30.206 DEBUG (MainThread) [pyNukiBT.nuki] Notification handler: a92ee202-5501-11e4-916c-0800200c9a66 (Handle: 32): Unknown, data: bytearray(b'\x17\x99c{\xfe\xf2\xfd\x90\xc0\xf8;\x10\x1cq\xb2u\x18\xa1\xd7[\xb1\x12\xfb4>\xa1\x01\x008\x00\x04\x86-~\xf4Y(\x996\\\t\xd7\x0f\xb4\xd9\xb4\x08\xd7\xfc\xc8A\x12W\x91}B\x1c<\x19\xc6\x9a:\xa1U\xe9\xb6\x81\x00@\xfe\xe8\xbf{\x01\xf4\xcdV\xb9H\x98\x9b\xf6\\*\x16\xe9')
2024-02-20 17:17:30.208 INFO (MainThread) [pyNukiBT.nuki] Data sent on attempt 1
2024-02-20 17:17:30.210 INFO (MainThread) [pyNukiBT.nuki] sending encrypted command REQUEST_CONFIG
2024-02-20 17:17:30.210 INFO (MainThread) [pyNukiBT.nuki] Trying to send data. Attempt 1
2024-02-20 17:17:30.211 INFO (MainThread) [pyNukiBT.nuki] Connected
2024-02-20 17:17:30.211 INFO (MainThread) [pyNukiBT.nuki] Sending data to Nuki
2024-02-20 17:17:30.320 DEBUG (MainThread) [pyNukiBT.nuki] Notification handler: a92ee202-5501-11e4-916c-0800200c9a66 (Handle: 32): Unknown, data: bytearray(b'\xc9p\x08\x93C\xdd\x84\x0b:\xe5\xf3n\xb5_A\xb3\x90\xba\x1fI\x1e\xf4\x05\xf2>\xa1\x01\x00f\x00MNw\x10$wa:\x83\xb8O!\xf6\xea/\n\x18qGo\x85\xb7+\xa2\xed[\x02\xeb#\x7f\xd3\x87P\xcaR\xecu\xbd:\xc2\x16*}\x06\xb0\xd0\xe4j\xe3\x0b\x01G\xa5%\x1d\xc1\x1c\xbb\xa6y\xd1\xef\xbc\xd2+F\x9c\xaeh\x90\xb9\x95\x82\xb0\xa1\xab}*\r\x85\x8c\xdb#|n/!I"\x1b\xc2\xe76?he7\x93\x88xr\x0e')
2024-02-20 17:17:30.322 WARNING (MainThread) [pyNukiBT.nuki] parse error Error in path (parsing) -> crc
wrong checksum, read 54529, computed 29660
2024-02-20 17:17:30.323 WARNING (MainThread) [pyNukiBT.nuki] Got unexpected message length for command 56643. got length:132 expecting length:8
2024-02-20 17:17:30.323 WARNING (MainThread) [pyNukiBT.nuki] Got 124 unknown bytes with value: b'\x84\x0b:\xe5\xf3n\xb5_A\xb3\x90\xba\x1fI\x1e\xf4\x05\xf2>\xa1\x01\x00f\x00MNw\x10$wa:\x83\xb8O!\xf6\xea/\n\x18qGo\x85\xb7+\xa2\xed[\x02\xeb#\x7f\xd3\x87P\xcaR\xecu\xbd:\xc2\x16*}\x06\xb0\xd0\xe4j\xe3\x0b\x01G\xa5%\x1d\xc1\x1c\xbb\xa6y\xd1\xef\xbc\xd2+F\x9c\xaeh\x90\xb9\x95\x82\xb0\xa1\xab}*\r\x85\x8c\xdb#|n/!I"\x1b\xc2\xe76?he7\x93\x88x'
2024-02-20 17:17:30.323 ERROR (MainThread) [pyNukiBT.nuki] HomeAssistant: Received unsolicited notification: Container: 
    auth_id = b'\xc9p\x08\x93' (total 4)
    command = (enum) (unknown) 56643
    payload = None
    crc = 2948
2024-02-20 17:17:30.324 ERROR (MainThread) [pyNukiBT.nuki] was expecting CONFIG
2024-02-20 17:17:30.326 INFO (MainThread) [pyNukiBT.nuki] Data sent on attempt 1

Diagnostics dump

No response

fjfricke commented 4 months ago

same here. Got: ` Logger: pyNukiBT.nuki Source: runner.py:188 First occurred: 13:36:44 (25 occurrences) Last logged: 13:38:32

parse error Error in path (parsing) -> crc wrong checksum, read 36355, computed 18825 Got unexpected message length for command 49960. got length:132 expecting length:8 Got 124 unknown bytes with value: b'x\xc0\x81\xbe_\x83\x862\x95C\xd1\xcd\x88\xa5\x93\x94\x0c\x92\xff\x1b\x01\x00f\x00h f\x02\x99\x13\xd6wz\x15~\xbb\x92\x99\xf0\x94W\x00\x9fx5\xed\xab \xb4\xb9\xf4\x10\xa6\x05\\xc9\xcb\xc2[TO%\xe6\xd1\x95\xce\xd8\x07\x83"\x1d\xa5\xb9\x85h]\xc6\xef\xf2B\xfc\x81\xcf\xa7\'\xe1j\x99\xe4"\x10D#\xf5+\x04=\xc8[\xca<\x9efR]\xc8{\xc3\xad!D<\xae\xb7<\x0edzW\x18f[\x8c\x0f' HomeAssistant: Received unsolicited notification: Container: auth_id = b'\x15Ga7' (total 4) command = (enum) (unknown) 49960 payload = None crc = 49272 was expecting CONFIG `

Marcus27-03 commented 4 months ago

Same Problem with nuki 2.0 0026bb765291 (Handle: 50): Unknown', '00000023-0000-1000-8000-0026bb765291 (Handle: 178): Unknown', '00000068-0000-1000-8000-0026bb765291 (Handle: 160): Unknown', 'e604e95d-a759-4817-87d3-aa005083a0d1 (Handle: 158): Unknown', '00000079-0000-1000-8000-0026bb765291 (Handle: 172): Unknown', '0000008f-0000-1000-8000-0026bb765291 (Handle: 166): Unknown', 'a92ee101-5501-11e4-916c-0800200c9a66 (Handle: 138): Unknown', '0000001d-0000-1000-8000-0026bb765291 (Handle: 101): Unknown', '00000023-0000-1000-8000-0026bb765291 (Handle: 119): Unknown', 'e604e95d-a759-4817-87d3-aa005083a0d1 (Handle: 93): Unknown', '0000001e-0000-1000-8000-0026bb765291 (Handle: 110): MCAP Control Channel', '000000a5-0000-1000-8000-0026bb765291 (Handle: 95): Unknown', '00000019-0000-1000-8000-0026bb765291 (Handle: 127): AVDTP', '00000037-0000-1000-8000-0026bb765291 (Handle: 132): Unknown', 'e604e95d-a759-4817-87d3-aa005083a0d1 (Handle: 125): Unknown', 'e604e95d-a759-4817-87d3-aa005083a0d1 (Handle: 70): Unknown', '00000050-0000-1000-8000-0026bb765291 (Handle: 87): Unknown', '0000004e-0000-1000-8000-0026bb765291 (Handle: 77): Unknown', '0000004f-0000-1000-8000-0026bb765291 (Handle: 82): Unknown', '0000004c-0000-1000-8000-0026bb765291 (Handle: 72): Unknown', 'a92ee203-5501-11e4-916c-0800200c9a66 (Handle: 148): Unknown', 'a92ee202-5501-11e4-916c-0800200c9a66 (Handle: 145): Unknown', 'a92ee201-5501-11e4-916c-0800200c9a66 (Handle: 142): Unknown', 'e604e95d-a759-4817-87d3-aa005083a0d1 (Handle: 9): Unknown', '000000a5-0000-1000-8000-0026bb765291 (Handle: 16): Unknown', '00000037-0000-1000-8000-0026bb765291 (Handle: 11): Unknown', '00002a26-0000-1000-8000-00805f9b34fb (Handle: 155): Firmware Revision String', '00002a27-0000-1000-8000-00805f9b34fb (Handle: 153): Hardware Revision String', '00002a25-0000-1000-8000-00805f9b34fb (Handle: 151): Serial Number String'] 2024-02-25 22:32:14.493 INFO (MainThread) [pyNukiBT.nuki] Connected 2024-02-25 22:32:14.493 INFO (MainThread) [pyNukiBT.nuki] Sending data to Nuki 2024-02-25 22:32:14.523 INFO (MainThread) [pyNukiBT.nuki] Data sent on attempt 1 2024-02-25 22:32:14.525 DEBUG (MainThread) [pyNukiBT.nuki] Notification handler: a92ee202-5501-11e4-916c-0800200c9a66 (Handle: 145): Unknown, data: bytearray(b'\x10\xd3%\xf3J\xa2\xf2\xd1,\xa4\xbf4h\xd7\x9e\x84\xfe_P\x98\xcfs\x0c\x1b\xe6\\4\x008\x00=\xa7X\xd5-;u\xcc\xe8\xfa%\xc0\xf0\x0c\\:\xd3*\x1e\rm\x90\x8d\r\xdd\xf2\xab\xb7\x93\xcd\x03K!\xad0f\x8c\xc5\xd6L\xa8\x8b\x16\x0bz\xee\x17d\x9c\x0c\x1d^\x8dKd') 2024-02-25 22:32:14.527 INFO (MainThread) [pyNukiBT.nuki] sending encrypted command REQUEST_LOG_ENTRIES 2024-02-25 22:32:14.528 INFO (MainThread) [pyNukiBT.nuki] Trying to send data. Attempt 1 2024-02-25 22:32:14.528 INFO (MainThread) [pyNukiBT.nuki] Connected 2024-02-25 22:32:14.528 INFO (MainThread) [pyNukiBT.nuki] Sending data to Nuki 2024-02-25 22:32:14.552 INFO (MainThread) [pyNukiBT.nuki] Data sent on attempt 1 2024-02-25 22:32:14.555 DEBUG (MainThread) [pyNukiBT.nuki] Notification handler: a92ee202-5501-11e4-916c-0800200c9a66 (Handle: 145): Unknown, data: bytearray(b'\xef!J\x92W\x0c@\xca%\x95=\x1b\x94\xec\xec\xbeYyyj~\x8f\xcb\xa9\xe6\4\x00M\x00f\x05"\xbb\xdf\x85\xe9\xb0\xd1\xd2it\x19\x8f\x87\x82\x1b\xca\xc6\x8d\xd1\xb7\x11,~\xfe\xcb\x97\xd8K\xed\xe1\xa0\xc2\x07i\x01\xd6\xe8=\xef\x13a\xfb+rTp\x01\x7fTXs\xf2\x88\x9f\xd0\xb9k\x93\xd7\r8\xa4\xe0\xd0b\xe1\xf5\x0c\xa4\xcd\x8aR\xb8') 2024-02-25 22:32:14.583 DEBUG (MainThread) [pyNukiBT.nuki] Notification handler: a92ee202-5501-11e4-916c-0800200c9a66 (Handle: 145): Unknown, data: bytearray(b'dz\xfdA$d\xa8\x83(\x1e\xfb\x06CZ\xa9\xe4\xfd\x1d\x92\x1f-\x16_D\xe6\4\x00\x19\x00WQ)x\xb7\x95\x99]\xf2\xa8\xa2g\x81\xcb\x8d\x17\x18K\xb8KF\xcc\x92^\x17') 2024-02-25 22:32:14.584 DEBUG (MainThread) [pyNukiBT.nuki] Last action: COMPLETED 2024-02-25 22:32:14.584 DEBUG (MainThread) [pyNukiBT.nuki] Container: status = (enum) COMPLETED 0 2024-02-25 22:32:14.584 DEBUG (MainThread) [pyNukiBT.nuki] [Container(index=47, timestamp=Container(year=2024, month=2, day=25, hour=20, minute=27, second=54), auth_id=4294967295, name=u'', type=uEnumIntegerString.new(2, 'LOCK_ACTION'), data=Container(lock_action=uEnumIntegerString.new(2, 'LOCK'), trigger=uEnumIntegerString.new(2, 'BUTTON'), flags=0, completion_status=uEnumIntegerString.new(0, 'SUCCESS'), padding=None))]`

ronengr commented 2 months ago

@cicero200272 could it be that the new nuki4 has a different communication protocol? I see that the pairing was successful and that we got the lock status correctly, but for some reason we got an unexpected message when we asked the lock for config.

i don't have a nuki4, so i don't really have a way to debug this myself so i may need your help. is there any log after what you sent me? basically if we get an unexpected message we ignore it and continue to wait for the correct one. so you should either get the config info and continue or get a timeout error if the config message is not received

ronengr commented 2 months ago

@Marcus27-03 from your logs i don't see any issue with the nuki2

Last action: COMPLETED and completion_status=uEnumIntegerString.new(0, 'SUCCESS')

so from the logs it seems everything is ok

ronengr commented 2 months ago

@cicero200272 @fjfricke @Marcus27-03 please try the latest version (0.0.12). i've fixed some issues related to nuki 4