Unpair Nuki not working correctly

[deadly667]

How to recreate:

• fully working connection Nuki 2.0 - Nuki Hub 8.18
• factory reset Nuki 2.0 and set it up via mobile phone
• Nuki Hub will show paired but "NUKI Lock state" is undefined and all actions ends in timeout/error
• unpair Nuki from Nuki Hub web interface
• after restart Nuki Hub will pair again but still all operations after pair will end in timeout and error

I tried multiple times unpair, restart, reset to AP mode and setup WIFI again but always had the same outcome.

What worked was flash ESP32 again with the same firmware 8.18 so that flash wipes all the data and then everything was as it should be, from the first try successful.

I will assume that some token or information still remains there after unpair which then got reused after pair which in my case of factory reset was not correct.

Nuki Hub - 8.18
Nuki 2.0
Lock firmware version: 2.14.5
Lock hardware version: 11.1

[technyon]

Hi, I was able to unpair and re-pair without issues. Communication with the lock was restored as soon as pairing was completed. Can you record logs during unpair/re-pair ? MQTT logs should suffice in this case.

[technyon]

@deadly667 Do you have any update on this? It's always unfortunate if I can't reproduce the issue, but so far you're the only one who reported this.

[bcutter]

but so far you're the only one who reported this.

+1 ❗

#176

There you should find enough information to test this by yourself. For the records in case it might be of help (maybe hardware dependant? I don't think so but who knows) I use these ESPs: https://www.amazon.de/AZDelivery-LOLIN32-Bluetooth-kompatibel-Arduino/dp/B086V1P4BL

Disclosure: And I'm done with testing and Nuki hub for a while, so currently not in the mood of providing further logs or stuff (spending time).

And if @deadly667 would have responded during the last month, I would probably have saved 3 hours of this weekend...

Hopefully not many others will run into this. I don't think so as re-pairing seems to be a corner-case based on the assumed usual usage (flash, pair, leave it/only maintain it with updates etc.).

[technyon]

@deadly667

Can you give this binary a try?

nuki_hub-8.23-pre-2.zip

[deadly667]

I will try to do it today evening. As I have only one Nuki and it's on main door I need to be careful with WAF :P and also need to find spare time for this operation (flash, try to recreate, flash to stable and make everything work as it was before)

[technyon]

There's no need to mess with your current setup. You can just use another ESP for testing, just check "Register as App" before pairing. If you do that, you main ESP will stay paired with the lock.

[deadly667]

I have good and bad news. 8.23 version (the one you provide me) didn't solve the problem. Good news is that I have now full logs.

Main Nuki hub, it was on version 8.21.
I did factory reset of my Nuki lock. As described it pairs but something is not correct (unpair dont helps)

Then I update it to your version (via web ui) and the same issue. See the logs:

[20:37:45]Querying lock state: Querying lock battery state: timeOut
20:37:56]Reading config. Result: timeOut
[20:37:56]Reading advanced config. Result: error
[20:38:22]lld_pdu_get_tx_flush_nb HCI packet count mismatch (1, 2)
[20:38:45]Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Unable to disable HASS. Invalid config received.


-----------> here I did unpair




[20:38:48]ets Jun  8 2016 00:22:57
[20:38:48]
[20:38:48]rst:0xc (SW_CPU_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
[20:38:48]configsip: 0, SPIWP:0xee
[20:38:48]clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
[20:38:48]mode:DIO, clock div:1
[20:38:48]load:0x3fff0018,len:4
[20:38:48]load:0x3fff001c,len:1044
[20:38:48]load:0x40078000,len:8896
[20:38:48]load:0x40080400,len:5816
[20:38:48]entry 0x400806ac
[20:38:48]E (551) esp_core_dump_flash: N
[20:38:48]E (551) esp_core_dump_flash: No core dump partition found!
[20:38:48]NUKI Hub version 8.23-pre-2
[20:38:48]IP address empty, falling back to DHCP.
[20:38:48]IP configuration: DHCP
[20:38:48]Hardware detect     : 2
[20:38:48]Switching to WiFi device as fallback.
[20:38:48]MQTT without TLS.
[20:38:48]*wm:AutoConnect 
[20:38:48]*wm:Connecting to SAVED AP: xxxxxxxxxx
[20:38:49]*wm:connectTimeout not set, ESP waitForConnectResult... 
[20:38:49]*wm:AutoConnect: SUCCESS 
[20:38:49]*wm:STA IP Address: 192.168.x.xx
[20:38:49]WiFi connected: 192.168.x.xx
[20:38:49]Host name: nukihub
[20:38:49]MQTT Broker: 192.168.x.xx:1883
[20:38:49]NUKI Lock enabled
[20:38:49]Lock state interval: 1800 | Battery interval: 1800 | Publish auth data: yes
[20:38:49]NUKI Opener disabled
[20:38:49]##### xxxx
[20:38:49]Presence detection timeout (ms): 60000
[20:38:49]Attempting MQTT connection
[20:38:49]MQTT: Connecting with user: xxxxxx
[20:38:49]MQTT connected
[20:38:54]Nuki start pairing
[20:38:54]Nuki paired
[20:39:17]Querying lock state: Querying lock battery state: timeOut
[20:39:27]Reading config. Result: timeOut
[20:39:27]Reading advanced config. Result: error
[20:42:46]lld_pdu_get_tx_flush_nb HCI packet count mismatch (1, 2)
[20:43:17]lld_pdu_get_tx_flush_nb HCI packet count mismatch (1, 2)
[20:45:49]lld_pdu_get_tx_flush_nb HCI packet count mismatch (1, 2)
[20:46:27]lld_pdu_get_tx_flush_nb HCI packet count mismatch (1, 2)
[20:47:05]lld_pdu_get_tx_flush_nb HCI packet count mismatch (1, 2)
[20:47:44]lld_pdu_get_tx_flush_nb HCI packet count mismatch (1, 2)
[20:49:42]lld_pdu_get_tx_flush_nb HCI packet count mismatch (1, 2)
[20:49:55]lld_pdu_get_tx_flush_nb HCI packet count mismatch (1, 2)
[20:50:06]Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock st
[20:50:44]lld_pdu_get_tx_flush_nb HCI packet count mismatch (1, 2)
[20:50:46]lld_pdu_get_tx_flush_nb HCI packet count mismatch (1, 2)
[20:52:13]lld_pdu_get_tx_flush_nb HCI packet count mismatch (1, 2)
[20:54:35]lld_pdu_get_tx_flush_nb HCI packet count mismatch (1, 2)
[20:55:18]lld_pdu_get_tx_flush_nb HCI packet count mismatch (1, 2)
[20:56:35]lld_pdu_get_tx_flush_nb HCI packet count mismatch (1, 2)
[20:57:36]lld_pdu_get_tx_flush_nb HCI packet count mismatch (1, 2)
[20:58:58]lld_pdu_get_tx_flush_nb HCI packet count mismatch (1, 2)
[21:00:39]ate: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lo
[21:00:52]lld_pdu_get_tx_flush_nb HCI packet count mismatch (1, 2)
[21:09:15]ck state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock battery state: timeOut
[21:09:27]Reading config. Result: timeOut
[21:09:27]Reading advanced config. Result: error
[21:09:41]lld_pdu_get_tx_flush_nb HCI packet count mismatch (1, 2)
[21:10:46]lld_pdu_get_tx_flush_nb HCI packet count mismatch (1, 2)
[21:11:01]lld_pdu_get_tx_flush_nb HCI packet count mismatch (1, 2)
[21:13:07]lld_pdu_get_tx_flush_nb HCI packet count mismatch (1, 2)

I masked some sensitive numbers and data with xxxxx.

[deadly667]

this is what I have under info

So for recreating it's important to factory reset Nuki lock trough Nuki APP. Unapir and pair without factory reset working fine but as I said I assume that during Factory reset of Nuki Lock, some information are getting changed but Nuki hub don't override old value with unpair and communication ends in timeouts/errors.

Can I do something else while I'm in this faulty mode?

[technyon]

Hi,

thanks I'll look into it. There are four values stored by the library handling the NUKI communication. In this test binary, all four values are deleted. I can't think of anything else that's stored on the ESP that has to to with pairing ... its somewhat of a mystery.

[deadly667]

Ok. Maybe I have one more important clue. When Hub is in Register as app mode everything works (8.23 version)!! I can unpair and when it's paired again everything works.

app mode - unpair/pair works
bridge mode - unpair/pair don't work

Are we maybe looking in the wrong direction? Maybe something is not sent to Nuki lock what is needed when in bridge mode? I don't know how communication looks like so just guessing.

Here is the log of app mode where everything works. It's restart after repair (I forgot to take a log while repair in app mode)

app mode:

[23:35:20]MQTT Broker not configured, aborting connection attempt.
[23:35:24]ets Jun  8 2016 00:22:57
[23:35:24]
[23:35:24]rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
[23:35:24]configsip: 0, SPIWP:0xee
[23:35:24]clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
[23:35:24]mode:DIO, clock div:1
[23:35:24]load:0x3fff0018,len:4
[23:35:24]load:0x3fff001c,len:1044
[23:35:24]load:0x40078000,len:8896
[23:35:24]load:0x40080400,len:5816
[23:35:24]entry 0x400806ac
[23:35:25]E (550) esp_core_dump_flash: Ncore dump partition found!
[23:35:25]E (550) esp_core_dump_flash: No core dump partition found!
[23:35:25]NUKI Hub version 8.23-pre-2
[23:35:25]IP address empty, falling back to DHCP.
[23:35:25]IP configuration: DHCP
[23:35:25]Hardware detect     : 1
[23:35:25]Network device: Wifi only
[23:35:25]MQTT without TLS.
[23:35:25]*wm:AutoConnect 
[23:35:25]*wm:Connecting to SAVED AP: xxxxxxxx
[23:35:26]*wm:connectTimeout not set, ESP waitForConnectResult... 
[23:35:26]*wm:AutoConnect: SUCCESS 
[23:35:26]*wm:STA IP Address: 192.168.x.xx
[23:35:26]WiFi connected: 192.168.xx.xx
[23:35:26]Host name: nukihub
[23:35:26]MQTT Broker: :1883
[23:35:26]NUKI Lock enabled
[23:35:26]Lock state interval: 1800 | Battery interval: 1800 | Publish auth data: no
[23:35:26]NUKI Opener disabled
[23:35:26]##### 0
[23:35:26]Presence detection timeout (ms): 60000
[23:35:26]MQTT Broker not configured, aborting connection attempt.
[23:35:31]Nuki start pairing
[23:35:31]Nuki paired
[23:35:31]Querying lock state: MQTT Broker not configured, aborting connection attempt.
[23:35:33]locked
[23:35:34]Querying lock battery state: success
[23:35:34]Reading config. Result: success
[23:35:34]Reading advanced config. Result: success
[23:35:36]MQTT Broker not configured, aborting connection attempt.
[23:35:41]MQTT Broker not configured, aborting connection attempt.
[23:35:46]MQTT Broker not configured, aborting connection attempt.
[23:35:51]MQTT Broker not configured, aborting connection attempt.
[23:35:56]MQTT Broker not configured, aborting connection attempt.
[23:36:01]MQTT Broker not configured, aborting connection attempt.
[23:36:06]MQTT Broker not configured, aborting connection attempt.

[technyon]

After factory resetting the lock, did you set it up in the smartphone app before pairing it to the ESP? I've noticed it paired only after configuring via the smartphone app.

If you can exclude that as a reason, can you test this binary? I've noticed there's there one more thing stored on the ESP, the device id that each device identifies itself to the lock. I've added some code so that after unpairing, a new random device id is generated.

nuki_hub-8.23-pre-3.zip

[deadly667]

Yes, after factory reset the lock I set it up fully via the smartphone app and then when all is configured I pairing it to the ESP.

Unfortunately, we still have the same problem. device identifier didn't help.

Showing logs:
[20:40:13]timeOut
[20:40:25]Reading config. Result: timeOut
[20:40:25]Reading advanced config. Result: error
[20:40:43]Querying lock state: Querying lock state: Querying lock state: Querying lock state: lld_pdu_get_tx_flush_nb HCI packet count mismatch (1, 2)
[20:41:13]Querying lock state: Querying lock state: Unable to disable HASS. Invalid config received.
[20:41:20]ets Jun  8 2016 00:22:57
[20:41:20]
[20:41:20]rst:0xc (SW_CPU_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
[20:41:20]configsip: 0, SPIWP:0xee
[20:41:20]clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
[20:41:20]mode:DIO, clock div:1
[20:41:20]load:0x3fff0018,len:4
[20:41:20]load:0x3fff001c,len:1044
[20:41:20]load:0x40078000,len:8896
[20:41:20]load:0x40080400,len:5816
[20:41:20]entry 0x400806ac
[20:41:20]E (549) esp_core_dump_flash: N[20:41:20]E (549) esp_core_dump_flash: No core dump partition found!
[20:41:20]NUKI Hub version 8.23-pre-3
[20:41:21]IP address empty, falling back to DHCP.
[20:41:21]IP configuration: DHCP
[20:41:21]Hardware detect     : 1
[20:41:21]Network device: Wifi only
[20:41:21]MQTT without TLS.
[20:41:21]*wm:AutoConnect 
[20:41:21]*wm:Connecting to SAVED AP: xxxxxxxxxx
[20:41:21]*wm:connectTimeout not set, ESP waitForConnectResult... 
[20:41:21]*wm:AutoConnect: SUCCESS 
[20:41:21]*wm:STA IP Address: 192.168.x.xx
[20:41:21]WiFi connected: 192.168.x.xx
[20:41:21]Host name: nukihub
[20:41:21]MQTT Broker: 192.168.x.xxx:1883
[20:41:22]NUKI Lock enabled
[20:41:22]Lock state interval: 1800 | Battery interval: 1800 | Publish auth data: yes
[20:41:22]NUKI Opener disabled
[20:41:22]Presence detection timeout (ms): 60000
[20:41:22]Attempting MQTT connection
[20:41:22]MQTT: Connecting with user: xxxxxxx
[20:41:22]MQTT connected
[20:41:27]Nuki start pairing
[20:41:27]Nuki paired
[20:41:49]Querying lock state: Querying lock battery state: timeOut
[20:42:00]Reading config. Result: timeOut
[20:42:00]Reading advanced config. Result: error
[20:42:38]Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: Querying lock state: lld_pdu_get_tx_flush_nb HCI packet count mismatch (1, 2)

I noticed that when unpair and then start pairing that it pairs like instant (but ends in error), but when I reflash ESP (clean ESP ) it takes a few seconds to pair.

Also what I capture during reflashed (clean ESP) pairing is this log:

[20:54:05]Nk atpiig
[20:54:10]ui atpiig
[20:54:15]uk atpiig
[20:54:20]Nstpair
[20:54:26]uistr arnNkstr arnNistr arnuki art ing sartrig
[20:54:26]uistr arnNkstr arnNistr arnuki art ing sartrig
Serial port closed!
[20:54:31]Nuki start pairing
[20:54:33]Nuki paired
[20:54:33]Querying lock state: locked
[20:54:33]Querying lock battery state: success
[20:54:33]Reading config. Result: success
[20:54:33]Reading advanced config. Result: success
[20:54:33]HASS setup for lock completed.
[20:54:33]HASS setup for lock completed.

It can be that it's only a glitch in the serial port in that moment, but I don't see anything like that when unpair/pair which ends in errors and timeouts.

[technyon]

I'm out of ideas so far. Like I said, there four values saved after pairing, which are deleted when unpairing. The state regarding pairing should be exactly the same as when reflashing. I'll add this to the readme for now.