search

I-Connect / NukiBleEsp32

MIT License
37 stars 21 forks source link

The "pairing" does not work #38

Closed jansolarski closed 1 year ago

jansolarski commented 1 year ago

Thank you for developing the software. This is exactly what I was looking for. Unfortunately it does not work properly for me yet. The "pairing" does not work, although the "Nuki" is in "pairing" mode and I have not defined a PIN. I downloaded the latest software from Github today (04.04.2023). I use the "NUKI SMART LOCK 3.0" with the address "54:d2:72:b9:da:74".

The cause is unclear to me. In the log I find 2 suspicious places:

After the "nukiLock.initialize()" comes the message:

[ 381][E][Preferences.cpp:503] getBytesLength(): nvs_get_blob len fail: bleAddress NOT_FOUND [ 381][E][NukiBle.cpp:635] retrieveCredentials(): Getting data from NVS issue

while scanning my "NUKI SMART LOCK" (54:d2:72:b9:da:74) is found several times, but afterwards I get the message:

I NimBLEScan: New advertiser: 54:d2:72:b9:da:74 I NimBLEAdvertisedDevice: No service data found D NimBLEScan: erase device: 54:d2:72:b9:da:74

Here is the complete log: Executing task: C:\Users\Jan.platformio\penv\Scripts\platformio.exe device monitor

--- Terminal on COM3 | 115200 8-N-1 --- Available filters and text transformations: colorize, debug, default, direct, esp32_exception_decoder, hexlify, log2file, nocontrol, printable, send_on_enter, time --- More details at https://bit.ly/pio-monitor-filters --- Quit: Ctrl+C | Menu: Ctrl+T | Help: Ctrl+T followed by Ctrl+H [ 38][D][esp32-hal-cpu.c:244] setCpuFrequencyMhz(): PLL: 480 / 2 = 240 Mhz, APB: 80000000 Hz [ 72][D][NukiSmartlockTest.h:174] setup(): Starting NUKI BLE... I NimBLEDevice: BLE Host Task Started I NimBLEDevice: NimBle host synced. [ 381][E][Preferences.cpp:503] getBytesLength(): nvs_get_blob len fail: bleAddress NOT_FOUND [ 381][E][NukiBle.cpp:635] retrieveCredentials(): Getting data from NVS issue D NimBLEScan: >> start: duration=0 D NimBLEScan: << start() [ 396][E][Preferences.cpp:503] getBytesLength(): nvs_get_blob len fail: bleAddress NOT_FOUND [ 401][E][NukiBle.cpp:635] retrieveCredentials(): Getting data from NVS issue [ 408][D][NukiBle.cpp:107] pairNuki(): No nuki in pairing mode found [ 415][D][NukiBle.cpp:112] pairNuki(): pairing result 0 I NimBLEScan: New advertiser: 14:bb:6e:81:d3:00 D NimBLEScan: erase device: 14:bb:6e:81:d3:00
I NimBLEScan: New advertiser: 54:d2:72:b9:da:74 I NimBLEAdvertisedDevice: No service data found D NimBLEScan: erase device: 54:d2:72:b9:da:74 I NimBLEScan: New advertiser: 14:bb:6e:81:d3:00 D NimBLEScan: erase device: 14:bb:6e:81:d3:00
I NimBLEScan: New advertiser: a4:c1:38:fb:78:b3 I NimBLEAdvertisedDevice: No service data found D NimBLEScan: erase device: a4:c1:38:fb:78:b3
I NimBLEScan: New advertiser: 54:d2:72:b9:da:74 I NimBLEAdvertisedDevice: No service data found D NimBLEScan: erase device: 54:d2:72:b9:da:74
I NimBLEScan: New advertiser: 14:bb:6e:81:d3:00 D NimBLEScan: erase device: 14:bb:6e:81:d3:00 I NimBLEScan: New advertiser: 14:bb:6e:81:d3:00 D NimBLEScan: erase device: 14:bb:6e:81:d3:00 [ 920][E][Preferences.cpp:503] getBytesLength(): nvs_get_blob len fail: bleAddress NOT_FOUND [ 920][E][NukiBle.cpp:635] retrieveCredentials(): Getting data from NVS issue [ 924][D][NukiBle.cpp:107] pairNuki(): No nuki in pairing mode found [ 930][D][NukiBle.cpp:112] pairNuki(): pairing result 0 I NimBLEScan: New advertiser: 14:bb:6e:81:d3:00 D NimBLEScan: erase device: 14:bb:6e:81:d3:00 I NimBLEScan: New advertiser: 54:d2:72:b9:da:74 I NimBLEAdvertisedDevice: No service data found D NimBLEScan: erase device: 54:d2:72:b9:da:74 I NimBLEScan: New advertiser: f8:c9:94:63:39:ba I NimBLEAdvertisedDevice: No service data found D NimBLEScan: erase device: f8:c9:94:63:39:ba I NimBLEScan: New advertiser: a4:c1:38:7d:72:be I NimBLEAdvertisedDevice: No service data found D NimBLEScan: erase device: a4:c1:38:7d:72:be I NimBLEScan: New advertiser: 60:7f:01:23:1e:a0 I NimBLEAdvertisedDevice: No service data found D NimBLEScan: erase device: 60:7f:01:23:1e:a0 I NimBLEScan: New advertiser: 54:d2:72:b9:da:74 I NimBLEAdvertisedDevice: No service data found D NimBLEScan: erase device: 54:d2:72:b9:da:74 ...

I-Connect commented 1 year ago

HI

[ 381][E][Preferences.cpp:503] getBytesLength(): nvs_get_blob len fail: bleAddress NOT_FOUND
[ 381][E][NukiBle.cpp:635] retrieveCredentials(): Getting data from NVS issue

This is because there is no data stored yet, this is only done when the pairing is successful

[ 408][D][NukiBle.cpp:107] pairNuki(): No nuki in pairing mode found This means it did not find a Nuki in pairing mode, I assume you made sure the Nuki is in pairing mode (button pressed for about 10 seconds after which the led ring lights up) The pairing mode times out so you need to make sure you rather quickly start the pairing on the esp.

You could turn on all debugging (does create a lot of logging) as described in the readme, and post this, then I will take a look.

jansolarski commented 1 year ago

Thanks for the quick reply and for the tips.

Yes, I made sure the Nuki is in pairing mode (button pressed for about 10 seconds after which the led ring lights up) I am a platformio beginner. I have changed the debugging in platformio.ini like this:

; monitor_filters = esp32_exception_decoder

[env:debug] build_type = debug build_flags = ${env.build_flags} -DCORE_DEBUG_LEVEL=ARDUHAL_LOG_LEVEL_DEBUG -DDEBUG_NUKI_CONNECT -DDEBUG_NUKI_COMMUNICATION -DDEBUG_NUKI_HEX_DATA -DDEBUG_NUKI_READABLE_DATA

however, the protocol has not changed.

And one more thing. I receive warnings during the build:

Compiling .pio\build\debug\src\NukiOpener.cpp.o src/NukiBle.cpp: In member function 'Nuki::PairingState Nuki::NukiBle::pairStateMachine(Nuki::PairingState)': src/NukiBle.cpp:698:35: warning: ignoring return value of 'int crypto_scalarmult_curve25519(unsigned char, const unsigned char, const unsigned char*)', declared with attribute warn_unused_result [-Wunused-result] crypto_scalarmult_curve25519(sharedKeyS, myPrivateKey, remotePublicKey);


.
.
.
Compiling .pio\build\debug\libd8a\NimBLE-Arduino\nimble\esp_port\esp-hci\src\esp_nimble_hci.c.o
cc1.exe: warning: command line option '-Wno-reorder' is valid for C++/ObjC++ but not for C
Compiling .pio\build\debug\libd8a\NimBLE-Arduino\nimble\esp_port\port\src\esp_nimble_mem.c.o
cc1.exe: warning: command line option '-Wno-reorder' is valid for C++/ObjC++ but not for C
Compiling .pio\build\debug\libd8a\NimBLE-Arduino\nimble\ext\tinycrypt\src\aes_decrypt.c.o
Compiling .pio\build\debug\libd8a\NimBLE-Arduino\nimble\ext\tinycrypt\src\aes_encrypt.c.o
Compiling .pio\build\debug\libd8a\NimBLE-Arduino\nimble\ext\tinycrypt\src\cbc_mode.c.o
cc1.exe: warning: command line option '-Wno-reorder' is valid for C++/ObjC++ but not for C
cc1.exe: warning: command line option '-Wno-reorder' is valid for C++/ObjC++ but not for C
………………
jansolarski commented 1 year ago

One more thing occurred to me. Searching for service data is extremely fast. Maybe the timeout is too small. Where is the place with the setting of timeout?

I-Connect commented 1 year ago

One more thing occurred to me. Searching for service data is extremely fast. Maybe the timeout is too small. Where is the place with the setting of timeout?

There is no timeout on searching for services, this happens continuously. See NukiBle.cpp line 199 onwards

I have changed the debugging in platformio.ini like this:

Previously you also saw the log "No nuki in pairing mode found", this is in one of the log defines:

#ifdef DEBUG_NUKI_CONNECT
    log_d("No nuki in pairing mode found");
#endif

So you should be able to get the other debug defines enabled also. We have this defined in platformio.ini

[env:debug]
build_type = debug
build_flags = 
    ${env.build_flags}
        -DDEBUG_NUKI_COMMAND
        -DDEBUG_NUKI_CONNECT
        -DDEBUG_NUKI_COMMUNICATION
    -DDEBUG_NUKI_HEX_DATA
    -DDEBUG_NUKI_READABLE_DATA

Are you working from the example or have you written your own project-code?

jansolarski commented 1 year ago

I am trying to make the example work. The build_flags do not change anything in the log. I looked in the code, in the part that is processed, there is no additional "log_d(...);".

technyon commented 1 year ago

@jansolarski Is your lock firmware up-to-date?

jansolarski commented 1 year ago

My lock firmware is up-to-date.

I-Connect commented 1 year ago

@jansolarski can you test with this branch?

https://github.com/I-Connect/NukiBleEsp32/tree/pair-and-unpair-refactor

jansolarski commented 1 year ago

I am on holiday at the moment. I will test it in about 3 weeks.

victorigualada commented 1 year ago

Hi!

I come from the ESPHome project created by @uriyacovy using your library. I'm facing the same issue.

I have a Nuki Smart Lock 3.0 with firmware version 3.5.12. I'm running it on an ESP32 WROOM CH340C

I see exactly the same errors:

[   344][E][Preferences.cpp:503] getBytesLength(): nvs_get_blob len fail: bleAddress NOT_FOUND
[   344][E][NukiBle.cpp:635] retrieveCredentials(): Getting data from NVS issue

I tried using the pair-and-unpair-refactor branch but the error persists.

Is there something I can do to give you more info? Thanks!

I-Connect commented 1 year ago

Hi @victorigualada,

This error can also mean that the lock is unpaired or has never been paired before ( then there is nothing stored in nvs which throws this error).

If you are testing with the branch you say you should also see: "No preferences stored or issue reading data, maybe never paired before" ?

Can you post a larger section of your logging while using pair-and-unpair-refactor branch?

victorigualada commented 1 year ago

That was a fast response! Thanks!

So the lock is paired, in fact I managed to get that project working last month in another board that I ended up burning...

When I install ESPHome it actually says it's using the pair-and-unpair-refactor branch:


Library Manager: Installing git+https://github.com/I-Connect/NukiBleEsp32#pair-and-unpair-refactor
INFO Installing git+https://github.com/I-Connect/NukiBleEsp32#pair-and-unpair-refactor
git version 2.30.2
Cloning into '/data/cache/platformio/cache/tmp/pkg-installing-6dhp9xb1'...
Library Manager: NukiBleEsp@2.0.0+sha.d23f6d7 has been installed!
INFO NukiBleEsp@2.0.0+sha.d23f6d7 has been installed!

Note the NukiBleEsp@2.0.0+sha.d23f6d7 which corresponds with the commit for the branch.

Although I do not see the line No preferences stored or issue reading data, maybe never paired before that you mention. I think it makes sense since the lock is paired with my phone.

I can post the logs but they come from ESPHome and not this project directly. I only see the two lines I posted above coming from NukiBleEsp32

victorigualada commented 1 year ago

When installing it I see the following warning:

/data/nukko/.piolibdeps/nukko/NukiBleEsp/src/NukiBle.cpp: In member function 'Nuki::PairingState Nuki::NukiBle::pairStateMachine(Nuki::PairingState)':
/data/nukko/.piolibdeps/nukko/NukiBleEsp/src/NukiBle.cpp:698:35: warning: ignoring return value of 'int crypto_scalarmult_curve25519(unsigned char*, const unsigned char*, const unsigned char*)', declared with attribute warn_unused_result [-Wunused-result]
       crypto_scalarmult_curve25519(sharedKeyS, myPrivateKey, remotePublicKey);

I don't know if it's related.

victorigualada commented 1 year ago

Another thing that I didn't mention is that the two error lines keep repeating infinitely:

[23:42:49][ 14416][E][Preferences.cpp:503] getBytesLength(): nvs_get_blob len fail: bleAddress NOT_FOUND
[23:42:49][ 14416][E][NukiBle.cpp:635] retrieveCredentials(): Getting data from NVS issue
[23:42:49][ 14468][E][Preferences.cpp:503] getBytesLength(): nvs_get_blob len fail: bleAddress NOT_FOUND
[23:42:49][ 14468][E][NukiBle.cpp:635] retrieveCredentials(): Getting data from NVS issue
[23:42:51][ 16517][E][Preferences.cpp:503] getBytesLength(): nvs_get_blob len fail: bleAddress NOT_FOUND
[23:42:51][ 16517][E][NukiBle.cpp:635] retrieveCredentials(): Getting data from NVS issue
[23:42:51][ 16548][E][Preferences.cpp:503] getBytesLength(): nvs_get_blob len fail: bleAddress NOT_FOUND
[23:42:51][ 16549][E][NukiBle.cpp:635] retrieveCredentials(): Getting data from NVS issue
[23:42:53][ 18617][E][Preferences.cpp:503] getBytesLength(): nvs_get_blob len fail: bleAddress NOT_FOUND
[23:42:53][ 18617][E][NukiBle.cpp:635] retrieveCredentials(): Getting data from NVS issue
[23:42:53][ 18669][E][Preferences.cpp:503] getBytesLength(): nvs_get_blob len fail: bleAddress NOT_FOUND
[23:42:53][ 18669][E][NukiBle.cpp:635] retrieveCredentials(): Getting data from NVS issue
[23:42:53][ 18702][E][Preferences.cpp:503] getBytesLength(): nvs_get_blob len fail: bleAddress NOT_FOUND
[23:42:53][ 18703][E][NukiBle.cpp:635] retrieveCredentials(): Getting data from NVS issue
[23:42:55][ 20717][E][Preferences.cpp:503] getBytesLength(): nvs_get_blob len fail: bleAddress NOT_FOUND
[23:42:55][ 20717][E][NukiBle.cpp:635] retrieveCredentials(): Getting data from NVS issue
[23:42:55][ 20747][E][Preferences.cpp:503] getBytesLength(): nvs_get_blob len fail: bleAddress NOT_FOUND
[23:42:55][ 20747][E][NukiBle.cpp:635] retrieveCredentials(): Getting data from NVS issue
[23:42:57][ 22817][E][Preferences.cpp:503] getBytesLength(): nvs_get_blob len fail: bleAddress NOT_FOUND
[23:42:57][ 22817][E][NukiBle.cpp:635] retrieveCredentials(): Getting data from NVS issue
[23:42:57][ 22865][E][Preferences.cpp:503] getBytesLength(): nvs_get_blob len fail: bleAddress NOT_FOUND
[23:42:57][ 22866][E][NukiBle.cpp:635] retrieveCredentials(): Getting data from NVS issue
[23:42:59][ 24917][E][Preferences.cpp:503] getBytesLength(): nvs_get_blob len fail: bleAddress NOT_FOUND
[23:42:59][ 24917][E][NukiBle.cpp:635] retrieveCredentials(): Getting data from NVS issue
[23:42:59][ 24948][E][Preferences.cpp:503] getBytesLength(): nvs_get_blob len fail: bleAddress NOT_FOUND
[23:42:59][ 24949][E][NukiBle.cpp:635] retrieveCredentials(): Getting data from NVS issue
[23:43:01][ 27017][E][Preferences.cpp:503] getBytesLength(): nvs_get_blob len fail: bleAddress NOT_FOUND
[23:43:01][ 27017][E][NukiBle.cpp:635] retrieveCredentials(): Getting data from NVS issue
[23:43:01][ 27050][E][Preferences.cpp:503] getBytesLength(): nvs_get_blob len fail: bleAddress NOT_FOUND
[23:43:01][ 27051][E][NukiBle.cpp:635] retrieveCredentials(): Getting data from NVS issue
[23:43:03][ 29117][E][Preferences.cpp:503] getBytesLength(): nvs_get_blob len fail: bleAddress NOT_FOUND
[23:43:03][ 29117][E][NukiBle.cpp:635] retrieveCredentials(): Getting data from NVS issue
[23:43:03][ 29144][E][Preferences.cpp:503] getBytesLength(): nvs_get_blob len fail: bleAddress NOT_FOUND
[23:43:03][ 29145][E][NukiBle.cpp:635] retrieveCredentials(): Getting data from NVS issue
[23:43:03][ 29199][E][Preferences.cpp:503] getBytesLength(): nvs_get_blob len fail: bleAddress NOT_FOUND
[23:43:03][ 29200][E][NukiBle.cpp:635] retrieveCredentials(): Getting data from NVS issue
[23:43:05][ 31217][E][Preferences.cpp:503] getBytesLength(): nvs_get_blob len fail: bleAddress NOT_FOUND
[23:43:05][ 31217][E][NukiBle.cpp:635] retrieveCredentials(): Getting data from NVS issue
[23:43:05][ 31260][E][Preferences.cpp:503] getBytesLength(): nvs_get_blob len fail: bleAddress NOT_FOUND
[23:43:05][ 31261][E][NukiBle.cpp:635] retrieveCredentials(): Getting data from NVS issue
[23:43:08][ 33317][E][Preferences.cpp:503] getBytesLength(): nvs_get_blob len fail: bleAddress NOT_FOUND
[23:43:08][ 33317][E][NukiBle.cpp:635] retrieveCredentials(): Getting data from NVS issue
[23:43:08][ 33350][E][Preferences.cpp:503] getBytesLength(): nvs_get_blob len fail: bleAddress NOT_FOUND
[23:43:08][ 33350][E][NukiBle.cpp:635] retrieveCredentials(): Getting data from NVS issue
[23:43:10][ 35417][E][Preferences.cpp:503] getBytesLength(): nvs_get_blob len fail: bleAddress NOT_FOUND
[23:43:10][ 35417][E][NukiBle.cpp:635] retrieveCredentials(): Getting data from NVS issue
[23:43:10][ 35461][E][Preferences.cpp:503] getBytesLength(): nvs_get_blob len fail: bleAddress NOT_FOUND
[23:43:10][ 35462][E][NukiBle.cpp:635] retrieveCredentials(): Getting data from NVS issue
[23:43:12][ 37517][E][Preferences.cpp:503] getBytesLength(): nvs_get_blob len fail: bleAddress NOT_FOUND
[23:43:12][ 37517][E][NukiBle.cpp:635] retrieveCredentials(): Getting data from NVS issue
[23:43:12][ 37562][E][Preferences.cpp:503] getBytesLength(): nvs_get_blob len fail: bleAddress NOT_FOUND
[23:43:12][ 37563][E][NukiBle.cpp:635] retrieveCredentials(): Getting data from NVS issue
[23:43:14][ 39617][E][Preferences.cpp:503] getBytesLength(): nvs_get_blob len fail: bleAddress NOT_FOUND
[23:43:14][ 39617][E][NukiBle.cpp:635] retrieveCredentials(): Getting data from NVS issue
[23:43:14][ 39663][E][Preferences.cpp:503] getBytesLength(): nvs_get_blob len fail: bleAddress NOT_FOUND
[23:43:14][ 39664][E][NukiBle.cpp:635] retrieveCredentials(): Getting data from NVS issue
[23:43:14][ 39699][E][Preferences.cpp:503] getBytesLength(): nvs_get_blob len fail: bleAddress NOT_FOUND
[23:43:14][ 39700][E][NukiBle.cpp:635] retrieveCredentials(): Getting data from NVS issue
[23:43:16][ 41717][E][Preferences.cpp:503] getBytesLength(): nvs_get_blob len fail: bleAddress NOT_FOUND
[23:43:16][ 41717][E][NukiBle.cpp:635] retrieveCredentials(): Getting data from NVS issue
victorigualada commented 1 year ago

And I also have to say two more things. Sorry for all the fragmented information in different comments.

  1. I can successfully use @technyon 's project https://github.com/technyon/nuki_hub with the lock
  2. I tried the ESPHome version in a Wemos D1 mini and I have the same problem
I-Connect commented 1 year ago

Response in order of your fragments ;-)

I am puzzled, you state the lock is paired but you have an issue with pairing? (you need to re-pair for each different application)

the warning is not related to this.

The repeating lines are related to probably repeated calling pairNuki() but I would need to know more about the application using the library (btw if you would be using the pair-and-unpair-refactor branch the message would be different, so the application (espHome?) is using main)

And I am afraid I have too little knowledge of how ESP home works, maybe @uriyacovy can assist with troubleshooting.

victorigualada commented 1 year ago

Ok so back to your original comment, I managed to install NukiBleEsp32 into the board directly, using the pair-and-unpair-refactor branch and this is what I get:

[ 73692][E][Preferences.cpp:503] getBytesLength(): nvs_get_blob len fail: bleAddress NOT_FOUND
[ 73692][W][NukiBle.cpp:634] retrieveCredentials(): No preferences stored or issue reading data, maybe never paired before
[ 73700][D][NukiBle.cpp:107] pairNuki(): No nuki in pairing mode found
[ 73706][D][NukiBle.cpp:112] pairNuki(): pairing result 0
I NimBLEScan: New advertiser: 54:d2:72:b9:46:ad
[ 74165][D][NukiBle.cpp:254] onResult(): Found nuki in pairing state:  addr: 54:d2:72:b9:46:ad
D NimBLEScan: erase device: 54:d2:72:b9:46:ad
[ 74212][E][Preferences.cpp:503] getBytesLength(): nvs_get_blob len fail: bleAddress NOT_FOUND
[ 74212][W][NukiBle.cpp:634] retrieveCredentials(): No preferences stored or issue reading data, maybe never paired before
[ 74220][D][NukiBle.cpp:85] pairNuki(): Nuki in pairing mode found
D NimBLEScan: >> stop()
D NimBLEScan: << stop()
[ 74230][D][NukiBle.cpp:132] connectBle(): connecting within: loopTask
[ 74237][D][NukiBle.cpp:139] connectBle(): connection attempt 0
D NimBLEClient: >> connect(54:d2:72:b9:46:ad)
D NimBLEClient: Got Client event 
I NimBLEClient: Connected event
lld_pdu_get_tx_flush_nb HCI packet count mismatch (1, 2)
D NimBLEClient: Got Client event 
E NimBLEClient: Connection failed; status=574 
D NimBLEClient: >> disconnect()
D NimBLEClient: Not connected to any peers
D NimBLEClient: << disconnect()
[ 75190][W][NukiBle.cpp:151] connectBle(): BLE Connect failed, 4 retries left
[ 75207][D][NukiBle.cpp:139] connectBle(): connection attempt 1
D NimBLEClient: >> connect(54:d2:72:b9:46:ad)
D NimBLEClient: Got Client event 
I NimBLEClient: Connected event
lld_pdu_get_tx_flush_nb HCI packet count mismatch (1, 2)
D NimBLEClient: Got Client event 
E NimBLEClient: Connection failed; status=574 
D NimBLEClient: >> disconnect()
D NimBLEClient: Not connected to any peers
D NimBLEClient: << disconnect()
[ 76270][W][NukiBle.cpp:151] connectBle(): BLE Connect failed, 3 retries left
[ 76287][D][NukiBle.cpp:139] connectBle(): connection attempt 2
D NimBLEClient: >> connect(54:d2:72:b9:46:ad)
D NimBLEClient: Got Client event 
E NimBLEClient: Connection failed; status=13 
D NimBLEClient: >> disconnect()
D NimBLEClient: Not connected to any peers
D NimBLEClient: << disconnect()
[ 77296][W][NukiBle.cpp:151] connectBle(): BLE Connect failed, 2 retries left
[ 77313][D][NukiBle.cpp:139] connectBle(): connection attempt 3
D NimBLEClient: >> connect(54:d2:72:b9:46:ad)
D NimBLEClient: Got Client event 
I NimBLEClient: Connected event
lld_pdu_get_tx_flush_nb HCI packet count mismatch (1, 2)
D NimBLEClient: Got Client event 
E NimBLEClient: Connection failed; status=574 
D NimBLEClient: >> disconnect()
D NimBLEClient: Not connected to any peers
D NimBLEClient: << disconnect()
[ 78510][W][NukiBle.cpp:151] connectBle(): BLE Connect failed, 1 retries left
[ 78527][D][NukiBle.cpp:139] connectBle(): connection attempt 4
D NimBLEClient: >> connect(54:d2:72:b9:46:ad)
D NimBLEClient: Got Client event 
E NimBLEClient: Connection failed; status=13 
D NimBLEClient: >> disconnect()
D NimBLEClient: Not connected to any peers
D NimBLEClient: << disconnect()
[ 79536][W][NukiBle.cpp:151] connectBle(): BLE Connect failed, 0 retries left
[ 79553][W][NukiBle.cpp:164] connectBle(): BLE Connect failed
[ 79553][D][NukiBle.cpp:112] pairNuki(): pairing result 0

It finds the Lock in pairing mode but is not able to pair. Just for reference I tried with the main branch and other older commits and it's not finding the Lock in pairing mode at all.

I-Connect commented 1 year ago

we changed the detection of a lock in pairing state so that it does not work on main makes (a bit) sense.

So I see the esp setting up a BLE connection but it seems after the "Got Client event" it disconnects

Could you enable the debug flags:

DEBUG_NUKI_CONNECT DEBUG_NUKI_COMMUNICATION DEBUG_NUKI_HEX_DATA DEBUG_NUKI_READABLE_DATA

and post the logging.

It should give some more details where the connection is dropped.

Do you have any other devices connecting to the lock like a bridge or app? I suggest to disconnect/turn them off during troubleshooting.

victorigualada commented 1 year ago

This is how my config looks like:

[env:debug]
build_type = debug
build_flags = 
    ${env.build_flags}
    -DCORE_DEBUG_LEVEL=ARDUHAL_LOG_LEVEL_DEBUG
    -DEBUG_NUKI_CONNECT
    -DEBUG_NUKI_COMMUNICATION
    -DEBUG_NUKI_HEX_DATA
    -DEBUG_NUKI_READABLE_DATA

But I don't see any other logs than the already posted.

I disconnect all the devices that could connect to the Lock when troubleshooting.

Just for reference, I think the platformio.ini DEBUG flags are mispelled. They have 2 D instead of one:

https://github.com/I-Connect/NukiBleEsp32/blob/1de629002a03e6fffc9acd8b746baf498b50f77b/platformio.ini#L41-L44

Although I tried with both versions and I still don't see any new logs

technyon commented 1 year ago

I think the double D is correct, -D means passing an option and the rest is the actual option. You could also write it as "-D DEBUG_NUKI_CONNECT"

victorigualada commented 1 year ago

I just tried that also and no new log messages. What could cause that?

I-Connect commented 1 year ago

correct.

You should see something like this with the -DDEBUG_NUKI_CONNECT:

[ 31636][E][Preferences.cpp:503] getBytesLength(): nvs_get_blob len fail: bleAddress NOT_FOUND
[ 31636][W][NukiBle.cpp:633] retrieveCredentials(): No preferences stored or issue reading data, maybe never paired before[ 31644][D][NukiBle.cpp:108] pairNuki(): No nuki in pairing mode found
[ 31650][D][NukiBle.cpp:113] pairNuki(): pairing result 0
[ 32156][E][Preferences.cpp:503] getBytesLength(): nvs_get_blob len fail: bleAddress NOT_FOUND
[ 32156][W][NukiBle.cpp:633] retrieveCredentials(): No preferences stored or issue reading data, maybe never paired before[ 32164][D][NukiBle.cpp:108] pairNuki(): No nuki in pairing mode found
[ 32170][D][NukiBle.cpp:113] pairNuki(): pairing result 0
[ 32217][D][NukiBle.cpp:255] onResult(): Found nuki in pairing state:  addr: 54:d2:72:4f:98:84
[ 32676][E][Preferences.cpp:503] getBytesLength(): nvs_get_blob len fail: bleAddress NOT_FOUND
[ 32676][W][NukiBle.cpp:633] retrieveCredentials(): No preferences stored or issue reading data, maybe never paired before[ 32684][D][NukiBle.cpp:85] pairNuki(): Nuki in pairing mode found
[ 32691][D][NukiBle.cpp:133] connectBle(): connecting within: loopTask
[ 32696][D][NukiBle.cpp:140] connectBle(): connection attempt 0
lld_pdu_get_tx_flush_nb HCI packet count mismatch (1, 2)
E NimBLEClient: Connection failed; status=574
[ 33378][W][NukiBle.cpp:152] connectBle(): BLE Connect failed, 4 retries left
[ 33391][D][NukiBle.cpp:140] connectBle(): connection attempt 1
[ 34003][D][NukiBle.cpp:1171] onConnect(): BLE connected
[ 34988][D][NukiBle.cpp:672] pairStateMachine(): ##################### REQUEST REMOTE PUBLIC KEY #########################[ 35238][D][NukiBle.cpp:688] pairStateMachine(): ##################### SEND CLIENT PUBLIC KEY #########################
[ 35264][D][NukiBle.cpp:695] pairStateMachine(): ##################### CALCULATE DH SHARED KEY s #########################[ 35282][D][NukiBle.cpp:702] pairStateMachine(): ##################### DERIVE LONG TERM SHARED SECRET KEY k #########################
[ 35282][D][NukiBle.cpp:714] pairStateMachine(): ##################### CALCULATE/VERIFY AUTHENTICATOR #########################
[ 35345][D][NukiBle.cpp:731] pairStateMachine(): ##################### SEND AUTHENTICATOR #########################
[ 35518][D][NukiBle.cpp:739] pairStateMachine(): ##################### SEND AUTHORIZATION DATA #########################
[ 35630][D][NukiBle.cpp:778] pairStateMachine(): ##################### SEND AUTHORIZATION ID confirmation #########################
[ 35755][D][NukiBle.cpp:799] pairStateMachine(): ####################### PAIRING DONE ###############################################
[ 35806][E][Preferences.cpp:503] getBytesLength(): nvs_get_blob len fail: bleAddress NOT_FOUND
[ 35813][D][NukiBle.cpp:566] saveCredentials(): Credentials saved:
[ 35813][D][NukiBle.cpp:570] saveCredentials(): pincode: 0
[ 35814][D][NukiBle.cpp:113] pairNuki(): pairing result 1
victorigualada commented 1 year ago

I went through the code and saw those log messages in the switch case in NukiBle.cpp. Although the messages are not there which indicates me that is not hitting any of these cases.

Probably remaining in one of the states that is not logging anything:

https://github.com/I-Connect/NukiBleEsp32/blob/1de629002a03e6fffc9acd8b746baf498b50f77b/src/NukiBle.cpp#L662-L668

https://github.com/I-Connect/NukiBleEsp32/blob/1de629002a03e6fffc9acd8b746baf498b50f77b/src/NukiBle.cpp#L680-L685

Will add logging there this evening and pos the logs.

victorigualada commented 1 year ago

After some digging, I came to the conclusion that the problem comes from NimBLEClient#connect method. It never goes further than that.

Is there a way to enable the NimBLE logs?

I-Connect commented 1 year ago

yes, you can change this define in platformio.ini:

-DCONFIG_NIMBLE_CPP_LOG_LEVEL=2

btw, in you earlier posted logs I do see a connected event: image

jansolarski commented 1 year ago

I have been testing with this branch:

https://github.com/I-Connect/NukiBleEsp32/tree/pair-and-unpair-refactor

The pairing works well. This solves my problem. Thank you for the solution.

I-Connect commented 1 year ago

ah nice, that is good to hear, bit busy at the moment but we will merge this later on into main