BLE (Re-)Bonding fails 'authentication failure with reason = 11' (SM_REASON_DHKEY_CHECK_FAILED)

[Franz Schnyder]

Hi all

I use BtSTack on a pico2_w to create BLE peripheral. I have an issue when a central tries to connect and bond to my peripheral it connected and bonded before butthe central lost its bonding information (pairing deleted on the phone) but my  peripheral still has it.  

In the first attempt, the bonding fails (full log output at the end)

> Pairing failed, authentication failure with reason = 11

which matches to my understanding maches 
> #define SM_REASON_DHKEY_CHECK_FAILED           0x0b

Even though before it logs, like it would delete the 

> Re-encryption failed, bonding information missing
> Assuming remote lost bonding information
> Deleting local bonding information to allow for new pairing...

but in a second connect and bond attempt, the bonding works. 

I stripped it down to an example that matches the `sm_pairing_peripheral.c` with "LE Secure Connections, Just Works" configured the code can be found here.

I tested it with the 'nRF Connect' app on an Android.

So in the nRF connect app I do 

1. Scan to find my peripheral
2. Connect
3. Bond
4. Disconnect
5. Delete bond information
6. Connect 
7. Bond => Fails

Is there an error in my code and in the  `sm_pairing_peripheral.c` example?
What would I need to do so that a Central that deleted/lost its bond information can rebond in one attempt and does not need to try twice?

Thanks for any hints and insights.

Regards 
Franz



_____
Full Log 

[00:01:28.014] EVT <= 3E 13 01 00 40 00 01 00 62 CF D2 7B 33 5C 0C 00 00 00 F4 01 05
[00:01:28.015] LOG -- hci.c.3387: LE Connection_complete (status=0) type 0, 5C:33:7B:D2:CF:62
[00:01:28.016] LOG -- hci.c.329: create_connection_for_addr 5C:33:7B:D2:CF:62, type 0
[00:01:28.016] LOG -- hci.c.1667: state 4, role 1, le_con 1
[00:01:28.016] LOG -- hci.c.1673: Num LE Peripheral roles: 1 of 1
[00:01:28.016] LOG -- hci.c.3517: New connection: handle 64, 5C:33:7B:D2:CF:62
[00:01:28.016] LOG -- att_server.c.404: SM_EVENT_IDENTITY_RESOLVING_STARTED
sm_packet_handler: packet_type 4
sm_packet_handler: event_type 205
[00:01:28.017] LOG -- btstack_tlv_flash_bank.c.408: Found tag '4254440f' at position 260
[00:01:28.017] LOG -- sm.c.2287: LE Device Lookup: device 15 of 16 - type 0, 5C:33:7B:D2:CF:62
[00:01:28.017] LOG -- sm.c.2293: LE Device Lookup: found by { addr_type, address}
[00:01:28.017] LOG -- sm.c.1325: ADDRESS_RESOLUTION_SUCCEEDED, index 15
[00:01:28.018] LOG -- btstack_tlv_flash_bank.c.408: Found tag '4254440f' at position 260
[00:01:28.018] LOG -- le_device_db_tlv.c.338: LE Device DB encryption for 15, ediv x0000, keysize 16, authenticated 0, authorized 0, secure connection 1
[00:01:28.018] LOG -- sm.c.1349: peripheral: pairing request local 0, have_ltk 1 => trigger_security_request 0
[00:01:28.018] LOG -- btstack_tlv_flash_bank.c.408: Found tag '4254440f' at position 260
[00:01:28.019] LOG -- att_server.c.415: SM_EVENT_IDENTITY_RESOLVING_SUCCEEDED
sm_packet_handler: packet_type 4
sm_packet_handler: event_type 207
Identity resolved: type 0 address 5C:33:7B:D2:CF:62
hci_packet_handler: Connection complete
[00:01:28.019] LOG -- hci.c.8232: BTSTACK_EVENT_NR_CONNECTIONS_CHANGED 1
hciHanldeEventPacket: le subevent=1
BLE connection complete, con_handle 0x0040
[00:01:28.020] EVT <= 3E 04 14 40 00 01
hciHanldeEventPacket: le subevent=14
[00:01:28.048] EVT <= 3E 0B 07 40 00 FB 00 48 08 1B 00 48 01
hciHanldeEventPacket: le subevent=7
[00:01:28.108] ACL <= 40 20 0B 00 07 00 04 00 08 01 00 FF FF 00 2A
[00:01:28.109] LOG -- att_db.c.615: ATT_READ_BY_TYPE_REQUEST: from 0001 to FFFF, type:
[00:01:28.109] LOG -- 0x00, 0x2A,
[00:01:28.109] ACL => 40 00 14 00 10 00 04 00 09 0E 03 00 50 69 63 6F 20 42 6F 6E 64 69 6E 67
[00:01:28.110] CMD => 35 0C 05 01 40 00 01 00
[00:01:28.168] ACL <= 40 20 0B 00 07 00 04 00 08 01 00 FF FF 2A 2B
[00:01:28.169] LOG -- att_db.c.615: ATT_READ_BY_TYPE_REQUEST: from 0001 to FFFF, type:
[00:01:28.169] LOG -- 0x2A, 0x2B,
[00:01:28.169] ACL => 40 00 18 00 14 00 04 00 09 12 06 00 D6 98 F0 C8 7B 9E D6 89 AB 5C 6B F8 0B A4 84 17
[00:01:28.170] CMD => 35 0C 05 01 40 00 01 00
[00:01:28.198] ACL <= 40 20 0B 00 07 00 04 00 08 01 00 FF FF 01 2A
[00:01:28.199] LOG -- att_db.c.615: ATT_READ_BY_TYPE_REQUEST: from 0001 to FFFF, type:
[00:01:28.199] LOG -- 0x01, 0x2A,
[00:01:28.199] ACL => 40 00 09 00 05 00 04 00 01 08 01 00 0A
[00:01:28.200] CMD => 35 0C 05 01 40 00 01 00
[00:01:28.201] EVT <= 13 05 01 40 00 02 00
[00:01:28.228] ACL <= 40 20 0B 00 07 00 04 00 10 01 00 FF FF 00 28
[00:01:28.229] LOG -- att_db.c.994: ATT_READ_BY_GROUP_TYPE_REQUEST: from 0001 to FFFF, buffer size 23, type:
[00:01:28.229] LOG -- 0x00, 0x28,
[00:01:28.229] ACL => 40 00 12 00 0E 00 04 00 11 06 01 00 03 00 00 18 04 00 06 00 01 18
[00:01:28.230] CMD => 35 0C 05 01 40 00 01 00
[00:01:28.258] ACL <= 40 20 0B 00 07 00 04 00 10 07 00 FF FF 00 28
[00:01:28.259] LOG -- att_db.c.994: ATT_READ_BY_GROUP_TYPE_REQUEST: from 0007 to FFFF, buffer size 23, type:
[00:01:28.259] LOG -- 0x00, 0x28,
[00:01:28.260] ACL => 40 00 1A 00 16 00 04 00 11 14 07 00 09 00 FB 34 9B 5F 80 00 00 80 00 10 00 00 10 FF 00 00
[00:01:28.260] CMD => 35 0C 05 01 40 00 01 00
[00:01:28.261] EVT <= 13 05 01 40 00 02 00
[00:01:28.288] ACL <= 40 20 0B 00 07 00 04 00 10 0A 00 FF FF 00 28
[00:01:28.289] LOG -- att_db.c.994: ATT_READ_BY_GROUP_TYPE_REQUEST: from 000A to FFFF, buffer size 23, type:
[00:01:28.289] LOG -- 0x00, 0x28,
[00:01:28.289] ACL => 40 00 09 00 05 00 04 00 01 10 0A 00 0A
[00:01:28.290] CMD => 35 0C 05 01 40 00 01 00
[00:01:28.318] ACL <= 40 20 0B 00 07 00 04 00 08 01 00 03 00 02 28
[00:01:28.319] LOG -- att_db.c.615: ATT_READ_BY_TYPE_REQUEST: from 0001 to 0003, type:
[00:01:28.319] LOG -- 0x02, 0x28,
[00:01:28.319] ACL => 40 00 09 00 05 00 04 00 01 08 01 00 0A
[00:01:28.320] CMD => 35 0C 05 01 40 00 01 00
[00:01:28.321] EVT <= 13 05 01 40 00 02 00
[00:01:28.348] ACL <= 40 20 0B 00 07 00 04 00 08 01 00 03 00 03 28
[00:01:28.349] LOG -- att_db.c.615: ATT_READ_BY_TYPE_REQUEST: from 0001 to 0003, type:
[00:01:28.349] LOG -- 0x03, 0x28,
[00:01:28.349] ACL => 40 00 0D 00 09 00 04 00 09 07 02 00 02 03 00 00 2A
[00:01:28.350] CMD => 35 0C 05 01 40 00 01 00
[00:01:28.378] ACL <= 40 20 0B 00 07 00 04 00 08 03 00 03 00 03 28
[00:01:28.379] LOG -- att_db.c.615: ATT_READ_BY_TYPE_REQUEST: from 0003 to 0003, type:
[00:01:28.379] LOG -- 0x03, 0x28,
[00:01:28.379] ACL => 40 00 09 00 05 00 04 00 01 08 03 00 0A
[00:01:28.380] CMD => 35 0C 05 01 40 00 01 00
[00:01:28.381] EVT <= 13 05 01 40 00 02 00
[00:01:28.408] ACL <= 40 20 0B 00 07 00 04 00 08 04 00 06 00 02 28
[00:01:28.409] LOG -- att_db.c.615: ATT_READ_BY_TYPE_REQUEST: from 0004 to 0006, type:
[00:01:28.409] LOG -- 0x02, 0x28,
[00:01:28.409] ACL => 40 00 09 00 05 00 04 00 01 08 04 00 0A
[00:01:28.410] CMD => 35 0C 05 01 40 00 01 00
[00:01:28.439] ACL <= 40 20 0B 00 07 00 04 00 08 04 00 06 00 03 28
[00:01:28.439] LOG -- att_db.c.615: ATT_READ_BY_TYPE_REQUEST: from 0004 to 0006, type:
[00:01:28.439] LOG -- 0x03, 0x28,
[00:01:28.439] ACL => 40 00 0D 00 09 00 04 00 09 07 05 00 02 06 00 2A 2B
[00:01:28.440] CMD => 35 0C 05 01 40 00 01 00
[00:01:28.441] EVT <= 13 05 01 40 00 02 00
[00:01:28.468] ACL <= 40 20 0B 00 07 00 04 00 08 06 00 06 00 03 28
[00:01:28.469] LOG -- att_db.c.615: ATT_READ_BY_TYPE_REQUEST: from 0006 to 0006, type:
[00:01:28.469] LOG -- 0x03, 0x28,
[00:01:28.469] ACL => 40 00 09 00 05 00 04 00 01 08 06 00 0A
[00:01:28.470] CMD => 35 0C 05 01 40 00 01 00
[00:01:28.498] ACL <= 40 20 0B 00 07 00 04 00 08 07 00 09 00 02 28
[00:01:28.499] LOG -- att_db.c.615: ATT_READ_BY_TYPE_REQUEST: from 0007 to 0009, type:
[00:01:28.499] LOG -- 0x02, 0x28,
[00:01:28.499] ACL => 40 00 09 00 05 00 04 00 01 08 07 00 0A
[00:01:28.500] CMD => 35 0C 05 01 40 00 01 00
[00:01:28.501] EVT <= 13 05 01 40 00 02 00
[00:01:28.528] ACL <= 40 20 0B 00 07 00 04 00 08 07 00 09 00 03 28
[00:01:28.529] LOG -- att_db.c.615: ATT_READ_BY_TYPE_REQUEST: from 0007 to 0009, type:
[00:01:28.529] LOG -- 0x03, 0x28,
[00:01:28.529] ACL => 40 00 1B 00 17 00 04 00 09 15 08 00 02 09 00 FB 34 9B 5F 80 00 00 80 00 10 00 00 12 FF 00 00
[00:01:28.530] CMD => 35 0C 05 01 40 00 01 00
[00:01:28.558] ACL <= 40 20 0B 00 07 00 04 00 08 09 00 09 00 03 28
[00:01:28.559] LOG -- att_db.c.615: ATT_READ_BY_TYPE_REQUEST: from 0009 to 0009, type:
[00:01:28.559] LOG -- 0x03, 0x28,
[00:01:28.559] ACL => 40 00 09 00 05 00 04 00 01 08 09 00 0A
[00:01:28.560] CMD => 35 0C 05 01 40 00 01 00
[00:01:28.561] EVT <= 13 05 01 40 00 02 00
[00:01:28.589] EVT <= 3E 0B 06 40 00 18 00 28 00 00 00 F4 01
hciHanldeEventPacket: le subevent=6
[00:01:28.589] CMD => 20 20 0E 40 00 18 00 28 00 00 00 F4 01 00 00 00 00
[00:01:28.593] EVT <= 0E 06 01 20 20 00 40 00
[00:01:28.716] EVT <= 13 05 01 40 00 01 00
[00:01:28.766] EVT <= 3E 0A 03 00 40 00 18 00 00 00 F4 01
hciHanldeEventPacket: le subevent=3
[00:01:28.976] EVT <= 3E 0B 07 40 00 FB 00 48 08 1B 00 48 08
hciHanldeEventPacket: le subevent=7
[00:01:29.036] EVT <= 3E 0B 07 40 00 FB 00 48 08 1B 00 48 01
hciHanldeEventPacket: le subevent=7
[00:01:29.336] EVT <= 3E 0B 07 40 00 FB 00 48 08 1B 00 48 08
hciHanldeEventPacket: le subevent=7
[00:01:30.236] EVT <= 3E 0B 07 40 00 FB 00 48 08 1B 00 48 01
hciHanldeEventPacket: le subevent=7
[00:01:31.976] EVT <= 3E 0B 07 40 00 FB 00 48 08 1B 00 48 08
hciHanldeEventPacket: le subevent=7
[00:01:32.036] EVT <= 3E 0B 07 40 00 FB 00 48 08 1B 00 48 01
hciHanldeEventPacket: le subevent=7
[00:01:33.896] EVT <= 3E 0B 07 40 00 FB 00 48 08 1B 00 48 08
hciHanldeEventPacket: le subevent=7
[00:01:34.526] EVT <= 3E 0B 07 40 00 FB 00 48 08 1B 00 48 01
hciHanldeEventPacket: le subevent=7
[00:01:35.456] EVT <= 3E 0B 07 40 00 FB 00 48 08 1B 00 48 08
hciHanldeEventPacket: le subevent=7
[00:01:35.576] ACL <= 40 20 0B 00 07 00 06 00 01 04 00 2D 10 0F 0F
[00:01:35.576] CMD => 35 0C 05 01 40 00 01 00
[00:01:35.577] LOG -- sm.c.2451: sm: connection 0x0040 locked setup context as responder, state 32
[00:01:35.577] LOG -- sm.c.2887: sm_run: state 32
[00:01:35.577] LOG -- btstack_tlv_flash_bank.c.408: Found tag '4254440f' at position 260
[00:01:35.577] LOG -- le_device_db_tlv.c.338: LE Device DB encryption for 15, ediv x0000, keysize 16, authenticated 0, authorized 0, secure connection 1
[00:01:35.578] LOG -- sm.c.3023: pairing request but LTK available
[00:01:35.578] LOG -- btstack_tlv_flash_bank.c.408: Found tag '4254440f' at position 260
sm_packet_handler: packet_type 4
sm_packet_handler: event_type 214
Bonding information exists for addr type 0, identity addr 5C:33:7B:D2:CF:62 -> re-encryption started
[00:01:35.578] LOG -- btstack_tlv_flash_bank.c.408: Found tag '4254440f' at position 260
sm_packet_handler: packet_type 4
sm_packet_handler: event_type 215
Re-encryption failed, bonding information missing

Assuming remote lost bonding information
Deleting local bonding information to allow for new pairing...
[00:01:35.579] LOG -- btstack_tlv_flash_bank.c.408: Found tag '4254440f' at position 260
[00:01:35.580] LOG -- btstack_tlv_flash_bank.c.360: Erase tag '4254440f' at position 260
[00:01:35.581] LOG -- sm.c.1206: our  address 2C:CF:67:B8:8D:6A type 0
[00:01:35.581] LOG -- sm.c.1207: peer address 5C:33:7B:D2:CF:62 type 0
[00:01:35.581] LOG -- sm.c.860: Secure pairing: 1
[00:01:35.581] LOG -- sm.c.911: sm_setup_tk: master io cap: 4, slave io cap: 3 -> method 0
[00:01:35.581] LOG -- sm.c.1260: SMP: generation method 0
[00:01:35.582] ACL => 40 00 0B 00 07 00 06 00 02 03 00 09 10 02 02
[00:01:35.582] LOG -- sm.c.2887: sm_run: state 50
[00:01:35.583] CMD => 2A 20 00
sm_packet_handler: packet_type 4
sm_packet_handler: event_type 212
Pairing started
[00:01:35.584] LOG -- att_server.c.441: SM Pairing started
[00:01:35.584] LOG -- att_server.c.1129: Clear CCC values of remote 5C:33:7B:D2:CF:62, le device id 15
sm_packet_handler: packet_type 4
sm_packet_handler: event_type 200
Just Works requested
[00:01:35.585] EVT <= 0E 05 01 2A 20 00 7E
[00:01:35.585] LOG -- sm.c.2887: sm_run: state 50
[00:01:35.586] CMD => 29 20 00
[00:01:35.587] EVT <= 0E 04 01 29 20 00
[00:01:35.588] LOG -- sm.c.2887: sm_run: state 50
[00:01:35.588] CMD => 27 20 27 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 C4 88 3E 3A D8 CF 62 44 21 79 0C 31 ED C5 78 D6
[00:01:35.590] EVT <= 0E 04 01 27 20 00
[00:01:35.591] LOG -- sm.c.2887: sm_run: state 50
[00:01:35.636] ACL <= 40 20 1B 00 41 00 06 00 0C 8A 05 DE AB 2C FB 10 A2 A6 8A 6B 60 99 11 E3 0F A5 20 19 C5 CA EA
[00:01:35.637] CMD => 35 0C 05 01 40 00 01 00
[00:01:35.637] LOG -- sm.c.2887: sm_run: state 50
[00:01:35.638] ACL <= 40 10 1B 00 A8 B9 56 3C A9 6B 64 14 EF 01 65 16 BD 51 B9 9E 5E 38 9E 0A 0E 24 00 FC 0B 47 AF
[00:01:35.639] CMD => 35 0C 05 01 40 00 01 00
[00:01:35.639] LOG -- sm.c.2887: sm_run: state 50
[00:01:35.640] ACL <= 40 10 0F 00 E7 BB 13 9E F9 32 EC E4 C1 32 38 06 35 FA 85
[00:01:35.703] LOG -- btstack_crypto.c.596: dhkey
[00:01:35.703] LOG -- 0x00, 0x01, 0x11, 0x73, 0x5E, 0xA5, 0x15, 0x77, 0x94, 0xC0, 0x7A, 0x49, 0x29, 0x75, 0xB2, 0x15,
[00:01:35.703] LOG -- 0xFD, 0xF1, 0xF3, 0x6A, 0x63, 0x25, 0xB2, 0x17, 0x16, 0x1F, 0x6D, 0x9C, 0xE2, 0x21, 0x50, 0xBF,
[00:01:35.703] LOG -- sm.c.1990: dhkey
[00:01:35.703] LOG -- 0x00, 0x01, 0x11, 0x73, 0x5E, 0xA5, 0x15, 0x77, 0x94, 0xC0, 0x7A, 0x49, 0x29, 0x75, 0xB2, 0x15,
[00:01:35.704] LOG -- 0xFD, 0xF1, 0xF3, 0x6A, 0x63, 0x25, 0xB2, 0x17, 0x16, 0x1F, 0x6D, 0x9C, 0xE2, 0x21, 0x50, 0xBF,
[00:01:35.704] LOG -- sm.c.4433: public key received, generation method 0
[00:01:35.704] CMD => 35 0C 05 01 40 00 01 00
[00:01:35.705] LOG -- sm.c.2887: sm_run: state 49
[00:01:35.705] ACL => 40 00 45 00 41 00 06 00 0C FC 0F 7E 1C C3 B1 CA 81 4A E0 39 37 5C A2 E4 C0 DA F3 57 5E D8 D7 4A D1 D8 EB 1F 5B F3 24 71 7C 8F ED 3C F8 56 A9 A6 88 D0 CF B1 2E 2D 7A 12 DA B0 65 CE 32 9A A9 83 23 0D 69 C5 5B EB 0C C3 E1
[00:01:35.706] LOG -- sm.c.2887: sm_run: state 51
[00:01:35.707] CMD => 18 20 00
[00:01:35.708] EVT <= 0E 0C 01 18 20 00 34 89 05 C1 F6 6E 57 D3
[00:01:35.709] LOG -- sm.c.2887: sm_run: state 51
[00:01:35.709] CMD => 18 20 00
[00:01:35.710] EVT <= 0E 0C 01 18 20 00 AC DC 80 21 A1 EF F4 B7
[00:01:35.711] LOG -- sm.c.2887: sm_run: state 51
[00:01:35.712] LOG -- sm.c.2887: sm_run: state 52
[00:01:35.712] LOG -- sm.c.1815: f4 key
[00:01:35.713] LOG -- 0x34, 0x89, 0x05, 0xC1, 0xF6, 0x6E, 0x57, 0xD3, 0xAC, 0xDC, 0x80, 0x21, 0xA1, 0xEF, 0xF4, 0xB7,
[00:01:35.713] LOG -- sm.c.1817: f4 message
[00:01:35.713] LOG -- 0x7C, 0x71, 0x24, 0xF3, 0x5B, 0x1F, 0xEB, 0xD8, 0xD1, 0x4A, 0xD7, 0xD8, 0x5E, 0x57, 0xF3, 0xDA,
[00:01:35.713] LOG -- 0xC0, 0xE4, 0xA2, 0x5C, 0x37, 0x39, 0xE0, 0x4A, 0x81, 0xCA, 0xB1, 0xC3, 0x1C, 0x7E, 0x0F, 0xFC,
[00:01:35.713] LOG -- 0x01, 0xEF, 0x14, 0x64, 0x6B, 0xA9, 0x3C, 0x56, 0xB9, 0xA8, 0xEA, 0xCA, 0xC5, 0x19, 0x20, 0xA5,
[00:01:35.713] LOG -- 0x0F, 0xE3, 0x11, 0x99, 0x60, 0x6B, 0x8A, 0xA6, 0xA2, 0x10, 0xFB, 0x2C, 0xAB, 0xDE, 0x05, 0x8A,
[00:01:35.714] LOG -- 0x00,
[00:01:35.715] LOG -- sm.c.1685: sm_sc_cmac_done:
[00:01:35.715] LOG -- 0xD8, 0x91, 0x2C, 0x81, 0x2A, 0xCA, 0x4C, 0x3D, 0xD7, 0xCE, 0x09, 0xAF, 0x87, 0x3E, 0x07, 0x2F,
[00:01:35.717] LOG -- sm.c.2887: sm_run: state 54
[00:01:35.717] ACL => 40 00 15 00 11 00 06 00 03 2F 07 3E 87 AF 09 CE D7 3D 4C CA 2A 81 2C 91 D8
[00:01:35.718] LOG -- sm.c.2887: sm_run: state 59
[00:01:35.727] EVT <= 13 05 01 40 00 02 00
[00:01:35.727] LOG -- sm.c.2887: sm_run: state 59
[00:01:35.756] ACL <= 40 20 15 00 11 00 06 00 04 7B AD 3C E2 E6 0B C3 F1 A8 CF CD D6 DD 93 28 5E
[00:01:35.756] LOG -- sm.c.4700: SM_SC_W4_PAIRING_RANDOM, responder: 1, just works: 1, passkey used 0, passkey entry 0
[00:01:35.757] CMD => 35 0C 05 01 40 00 01 00
[00:01:35.757] LOG -- sm.c.2887: sm_run: state 58
[00:01:35.757] LOG -- sm.c.2673: stk method 0, bit num: 0
[00:01:35.758] LOG -- sm.c.2684: SM_SC_SEND_PAIRING_RANDOM B
[00:01:35.758] LOG -- sm.c.2691: SM_SC_SEND_PAIRING_RANDOM B2
[00:01:35.758] LOG -- sm.c.1969: sm_sc_prepare_dhkey_check, DHKEY calculated 1
[00:01:35.758] ACL => 40 00 15 00 11 00 06 00 04 B7 F4 EF A1 21 80 DC AC D3 57 6E F6 C1 05 89 34
[00:01:35.759] LOG -- sm.c.2887: sm_run: state 63
[00:01:35.759] LOG -- sm.c.1829: f5_calculate_salt
[00:01:35.760] LOG -- sm.c.1685: sm_sc_cmac_done:
[00:01:35.760] LOG -- 0x00, 0xF6, 0x3E, 0x72, 0xC8, 0x71, 0x53, 0xC4, 0x2B, 0xEE, 0x49, 0x52, 0x17, 0x31, 0xDD, 0xA3,
[00:01:35.761] LOG -- sm.c.2887: sm_run: state 65
[00:01:35.761] LOG -- sm.c.1849: f5 key
[00:01:35.761] LOG -- 0x00, 0xF6, 0x3E, 0x72, 0xC8, 0x71, 0x53, 0xC4, 0x2B, 0xEE, 0x49, 0x52, 0x17, 0x31, 0xDD, 0xA3,
[00:01:35.761] LOG -- sm.c.1851: f5 message for MacKey
[00:01:35.761] LOG -- 0x00, 0x62, 0x74, 0x6C, 0x65, 0x5E, 0x28, 0x93, 0xDD, 0xD6, 0xCD, 0xCF, 0xA8, 0xF1, 0xC3, 0x0B,
[00:01:35.761] LOG -- 0xE6, 0xE2, 0x3C, 0xAD, 0x7B, 0x34, 0x89, 0x05, 0xC1, 0xF6, 0x6E, 0x57, 0xD3, 0xAC, 0xDC, 0x80,
[00:01:35.762] LOG -- 0x21, 0xA1, 0xEF, 0xF4, 0xB7, 0x00, 0x5C, 0x33, 0x7B, 0xD2, 0xCF, 0x62, 0x00, 0x2C, 0xCF, 0x67,
[00:01:35.762] LOG -- 0xB8, 0x8D, 0x6A, 0x01, 0x00,
[00:01:35.763] LOG -- sm.c.1685: sm_sc_cmac_done:
[00:01:35.763] LOG -- 0x1F, 0x3F, 0xEC, 0x00, 0x10, 0xBB, 0x9D, 0x7C, 0x2C, 0xE1, 0xC7, 0x61, 0x86, 0x95, 0x88, 0xB0,
[00:01:35.765] LOG -- sm.c.2887: sm_run: state 67
[00:01:35.765] LOG -- sm.c.1877: f5 key
[00:01:35.765] LOG -- 0x00, 0xF6, 0x3E, 0x72, 0xC8, 0x71, 0x53, 0xC4, 0x2B, 0xEE, 0x49, 0x52, 0x17, 0x31, 0xDD, 0xA3,
[00:01:35.765] LOG -- sm.c.1879: f5 message for LTK
[00:01:35.765] LOG -- 0x01, 0x62, 0x74, 0x6C, 0x65, 0x5E, 0x28, 0x93, 0xDD, 0xD6, 0xCD, 0xCF, 0xA8, 0xF1, 0xC3, 0x0B,
[00:01:35.765] LOG -- 0xE6, 0xE2, 0x3C, 0xAD, 0x7B, 0x34, 0x89, 0x05, 0xC1, 0xF6, 0x6E, 0x57, 0xD3, 0xAC, 0xDC, 0x80,
[00:01:35.765] LOG -- 0x21, 0xA1, 0xEF, 0xF4, 0xB7, 0x00, 0x5C, 0x33, 0x7B, 0xD2, 0xCF, 0x62, 0x00, 0x2C, 0xCF, 0x67,
[00:01:35.766] LOG -- 0xB8, 0x8D, 0x6A, 0x01, 0x00,
[00:01:35.766] LOG -- sm.c.1685: sm_sc_cmac_done:
[00:01:35.767] LOG -- 0xDD, 0x4E, 0x30, 0x9A, 0x0C, 0x53, 0x96, 0xA2, 0x03, 0x03, 0xAB, 0x25, 0x03, 0x08, 0x40, 0xBF,
[00:01:35.768] LOG -- sm.c.2887: sm_run: state 69
[00:01:35.769] LOG -- sm.c.1900: f6 key
[00:01:35.769] LOG -- 0x1F, 0x3F, 0xEC, 0x00, 0x10, 0xBB, 0x9D, 0x7C, 0x2C, 0xE1, 0xC7, 0x61, 0x86, 0x95, 0x88, 0xB0,
[00:01:35.769] LOG -- sm.c.1902: f6 message
[00:01:35.769] LOG -- 0x34, 0x89, 0x05, 0xC1, 0xF6, 0x6E, 0x57, 0xD3, 0xAC, 0xDC, 0x80, 0x21, 0xA1, 0xEF, 0xF4, 0xB7,
[00:01:35.769] LOG -- 0x5E, 0x28, 0x93, 0xDD, 0xD6, 0xCD, 0xCF, 0xA8, 0xF1, 0xC3, 0x0B, 0xE6, 0xE2, 0x3C, 0xAD, 0x7B,
[00:01:35.769] LOG -- 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00,
[00:01:35.770] LOG -- 0x09, 0x00, 0x03, 0x00, 0x2C, 0xCF, 0x67, 0xB8, 0x8D, 0x6A, 0x00, 0x5C, 0x33, 0x7B, 0xD2, 0xCF,
[00:01:35.770] LOG -- 0x62,
[00:01:35.770] LOG -- sm.c.1685: sm_sc_cmac_done:
[00:01:35.771] LOG -- 0xB6, 0xDF, 0x91, 0x3B, 0xF9, 0x48, 0xF9, 0xAF, 0x32, 0xB4, 0x99, 0xC9, 0xE7, 0xF8, 0xA9, 0x8F,
[00:01:35.772] LOG -- sm.c.2887: sm_run: state 75
[00:01:35.816] EVT <= 13 05 01 40 00 02 00
[00:01:35.816] LOG -- sm.c.2887: sm_run: state 75
[00:01:36.086] EVT <= 3E 0B 07 40 00 FB 00 48 08 1B 00 48 01
[00:01:36.086] LOG -- sm.c.2887: sm_run: state 75
hciHanldeEventPacket: le subevent=7
[00:01:36.686] EVT <= 3E 0B 07 40 00 FB 00 48 08 1B 00 48 08
[00:01:36.686] LOG -- sm.c.2887: sm_run: state 75
hciHanldeEventPacket: le subevent=7
[00:01:37.346] EVT <= 3E 0B 07 40 00 FB 00 48 08 1B 00 48 01
[00:01:37.346] LOG -- sm.c.2887: sm_run: state 75
hciHanldeEventPacket: le subevent=7
[00:01:37.646] ACL <= 40 20 15 00 11 00 06 00 0D 15 F6 90 84 3A 42 BD A5 D1 15 BA F8 CC 7D 63 97
[00:01:37.646] CMD => 35 0C 05 01 40 00 01 00
[00:01:37.647] LOG -- sm.c.2887: sm_run: state 71
[00:01:37.647] LOG -- sm.c.1900: f6 key
[00:01:37.647] LOG -- 0x1F, 0x3F, 0xEC, 0x00, 0x10, 0xBB, 0x9D, 0x7C, 0x2C, 0xE1, 0xC7, 0x61, 0x86, 0x95, 0x88, 0xB0,
[00:01:37.648] LOG -- sm.c.1902: f6 message
[00:01:37.648] LOG -- 0x5E, 0x28, 0x93, 0xDD, 0xD6, 0xCD, 0xCF, 0xA8, 0xF1, 0xC3, 0x0B, 0xE6, 0xE2, 0x3C, 0xAD, 0x7B,
[00:01:37.648] LOG -- 0x34, 0x89, 0x05, 0xC1, 0xF6, 0x6E, 0x57, 0xD3, 0xAC, 0xDC, 0x80, 0x21, 0xA1, 0xEF, 0xF4, 0xB7,
[00:01:37.648] LOG -- 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00,
[00:01:37.648] LOG -- 0x2D, 0x00, 0x04, 0x00, 0x5C, 0x33, 0x7B, 0xD2, 0xCF, 0x62, 0x00, 0x2C, 0xCF, 0x67, 0xB8, 0x8D,
[00:01:37.648] LOG -- 0x6A,
[00:01:37.649] LOG -- sm.c.1685: sm_sc_cmac_done:
[00:01:37.649] LOG -- 0xCA, 0x38, 0x72, 0x0F, 0x15, 0x42, 0x38, 0xF8, 0x9E, 0x9D, 0xFB, 0x4E, 0x90, 0xCC, 0xC8, 0xAD,
[00:01:37.651] ACL => 40 00 06 00 02 00 06 00 05 0B
[00:01:37.652] LOG -- sm.c.2887: sm_run: state 26
sm_packet_handler: packet_type 4
sm_packet_handler: event_type 213
Pairing failed, authentication failure with reason = 11
[00:01:37.653] LOG -- sm.c.1106: sm: connection 0x40 released setup context
[00:01:37.653] LOG -- sm.c.5119: sm: generate new ec key
[00:01:37.653] LOG -- btstack_crypto.c.948: start ecc random
[00:01:37.653] CMD => 18 20 00
[00:01:37.654] EVT <= 0E 0C 01 18 20 00 6D 77 24 EB A7 BC 27 BC
[00:01:37.655] LOG -- btstack_crypto.c.961: more ecc random
[00:01:37.655] CMD => 18 20 00
[00:01:37.656] EVT <= 0E 0C 01 18 20 00 A0 C3 86 FC 1A 0D 58 2F
[00:01:37.657] LOG -- btstack_crypto.c.961: more ecc random
[00:01:37.657] CMD => 18 20 00
[00:01:37.658] EVT <= 0E 0C 01 18 20 00 41 5E DA 0F D7 F0 B1 67
[00:01:37.659] LOG -- btstack_crypto.c.961: more ecc random
[00:01:37.659] CMD => 18 20 00
[00:01:37.660] EVT <= 0E 0C 01 18 20 00 86 C7 FE 2F D8 0B 56 4B
[00:01:37.661] LOG -- btstack_crypto.c.961: more ecc random
[00:01:37.661] CMD => 18 20 00
[00:01:37.662] EVT <= 0E 0C 01 18 20 00 92 DB 86 7E 9A 3D 4D 15
[00:01:37.662] LOG -- btstack_crypto.c.961: more ecc random
[00:01:37.663] CMD => 18 20 00
[00:01:37.664] EVT <= 0E 0C 01 18 20 00 47 FC A9 D2 E6 B2 EB 57
[00:01:37.664] LOG -- btstack_crypto.c.961: more ecc random
[00:01:37.664] CMD => 18 20 00
[00:01:37.666] EVT <= 0E 0C 01 18 20 00 12 1C D7 6A D3 50 09 0A
[00:01:37.666] LOG -- btstack_crypto.c.961: more ecc random
[00:01:37.666] CMD => 18 20 00
[00:01:37.668] EVT <= 0E 0C 01 18 20 00 02 9A 75 2E 0E 26 EF 2D
[00:01:37.668] LOG -- btstack_crypto.c.530: set uECC RNG for initial key generation with 64 random bytes
[00:01:37.669] LOG -- btstack_crypto.c.503: sm_generate_f_rng: size 32 - offset 0
[00:01:37.731] LOG -- btstack_crypto.c.493: Elliptic curve: X
[00:01:37.731] LOG -- 0x23, 0x8D, 0x45, 0xA8, 0xAB, 0x75, 0xCE, 0x49, 0x70, 0x1C, 0x8B, 0x20, 0x5B, 0x73, 0xD1, 0xD4,
[00:01:37.732] LOG -- 0x5F, 0xF2, 0xD9, 0xBD, 0x48, 0xFC, 0xFC, 0x10, 0xB4, 0xFA, 0x65, 0xAE, 0x85, 0x60, 0xF0, 0x1E,
[00:01:37.732] LOG -- btstack_crypto.c.495: Elliptic curve: Y
[00:01:37.732] LOG -- 0x75, 0x68, 0xC4, 0x07, 0x5B, 0xD6, 0x95, 0xB8, 0x5B, 0x7D, 0x93, 0x7F, 0xA6, 0xCE, 0x7D, 0x93,
[00:01:37.732] LOG -- 0xF3, 0x7A, 0x6A, 0x7C, 0xB1, 0xEE, 0x16, 0x0A, 0xF5, 0x47, 0x87, 0xCD, 0x54, 0x0F, 0xEF, 0x0A,
[00:01:37.841] EVT <= 13 05 01 40 00 01 00
[00:01:38.516] EVT <= 3E 0B 07 40 00 FB 00 48 08 1B 00 48 08
hciHanldeEventPacket: le subevent=7
[00:01:39.506] EVT <= 3E 0B 07 40 00 FB 00 48 08 1B 00 48 01
hciHanldeEventPacket: le subevent=7
[00:01:40.707] EVT <= 05 04 00 40 00 13
[00:01:40.707] LOG -- hci.c.1667: state 7, role 1, le_con 1
[00:01:40.708] LOG -- hci.c.1673: Num LE Peripheral roles: 0 of 1
[00:01:40.708] LOG -- gatt_client.c.1817: GATT Client: HCI_EVENT_DISCONNECTION_COMPLETE
BLE disconnect, reason 0x13
[00:01:40.708] LOG -- hci.c.1284: Connection closed: handle 0x40, 5C:33:7B:D2:CF:62
[00:01:40.709] LOG -- hci.c.8232: BTSTACK_EVENT_NR_CONNECTIONS_CHANGED 0
[00:01:40.709] CMD => 0A 20 01 01
[00:01:40.710] EVT <= 0E 04 01 0A 20 00

[Brian Reinhold]

Franz,

As I see it (from your description) you have a peripheral which is expecting an encryption request because according to its internal list of bonded centrals it is bonded with this central. However, it did not get an encryption request. It got a pairing request. How your peripheral handles this case is up to you. At least it was when I was programming peripherals on the Nordic Semiconductor nRF51 and nRF52 platforms. One possible response to the pairing request from an address that should be sending an encryption request is to assume the central lost its pairing so you delete those keys that you have for that central and handle the pairing. I know of devices that do that. Other devices will simply disconnect and require that the user manually repair. Other devices send an special error message that describes that situation to the central and then it re-advertises. The central should then attempt to reconnect and repair.

I am not sure about the pico peripheral code. It's been a while since I have worked with the micropython Bluetooth implementation. At the time there was not support for pairing at all and I had to add support for it. But I was developing centrals, not peripherals, so I never updated the peripheral code. I did send an issue about the lack of pairing support and from what you say they have apparently added it.

Brian

[Matthias Ringwald]

Hi Franz

I've converted the HCI Dump into a .pklg to open it in Wirehshark, that's the recommended process, see attached sm-pairing.pklg.

When pairing starts, BTstack realizes that it does have bonding information but the remote side requests a new pairing. It then reports this issue and deletes / ignores the locally stored bonding information.
Then, during the new pairing which uses LE Secure Connections, the devices exchange their public keys, calculate a shared key, chose a random value, use the shared key to encrypt the random value and send this confirm value to the other side. After that, they each send the chosen random key, to allow the remote to verify the calculation. here, your remove device claims that the calculation is wrong.
This is weird as a) you probably didn't have a man-in-the-middle attack ongoing, and b) it works the next time.

I've attached another trace running sm_peripheral.c where I first pair from my iPhone, then delete the pairing on the iPhone and then successfully pair again.

hm.. I just remember some issue with resolvable private addresses which has been fixed, but pico-sdk hasn't updated their BTstack copy in a while.

Could you repeat your test without bonding information, capture the complete log from the beginning:
- start up
- first connection and pairing
- second connection and pairing
and convert it to .pklg and post here?

Best regards
Matthias

> --
> You received this message because you are subscribed to the Google Groups "btstack-dev" group.
> To unsubscribe from this group and stop receiving emails from it, send an email to btstack-dev...@googlegroups.com.
> To view this discussion visit https://groups.google.com/d/msgid/btstack-dev/9137ced1-9dd3-498a-b0e5-6c796e52141an%40googlegroups.com.

[Franz Schnyder]

Hi Matthias

Thanks for the feedback. I attached a complete log (HCI Dump into a .pklg) of the following flow.

- Start with a fresh pico2_w peripheral running BtStack from pico C SDK 2.2.0 (complete flash erased and firmware newly flashed).
- Via an nRF-Connect app on an Android phone

  - Scan and connect to the pico

  - Bond  

  - Disconnect from the pico 

  - Delete the bonding on the phone via nRF-Connect app

  - Connect to the pico
  - Bond => failure

An interesting thing I tried:
I used the same `sm_pairing_peripheral.c` with "LE Secure Connections, Just Works" configured with the latest BtStack on a esp32c6 dev board I have around and did the same flow. This does not have the issue, the second bonding works without an issue. 

Things I want to try next:
I could not yet test it with the esp32c6 and the BtStack version that is included in the Pico SDK as that one states `Currently used for testing: ESP-IDF v4.4 or v5.0` and those I do not yet have installed, and they do not yet support the esp32c6 chip/boards.
I will try to update the BtStack that is used by pico C SDK to the latest release of  BtStack to see if the issue is still there with latest BtStack, not sure how easy such an update will be.

But one insight I already got is that the flow should actually work and yes there is no 'man-in-the-middle attack ongoing'  each time I try this flow :-).  Will post updates if I get some more 'tests' running and hope to be able to find a fix for this for my pico based project.

Thanks and Regards
Franz

You received this message because you are subscribed to a topic in the Google Groups "btstack-dev" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/btstack-dev/_PCnqiR4ERE/unsubscribe.
To unsubscribe from this group and all its topics, send an email to btstack-dev...@googlegroups.com.
To view this discussion visit https://groups.google.com/d/msgid/btstack-dev/4D8D9E72-39F4-4598-8B79-08CE0D02290B%40gmail.com.

[Franz Schnyder]

Hi 

I now updated pico C SDK to use latest BtStack release (v1.8), I only needed to rename `hids_client.c` to `hids_host.c` in some build files. Unfortunately, the issue is still the same. I attached a .pklg of the full flow with BtStack v1.8

Regards 
Franz

[Matthias Ringwald]

Hi Franz

thanks for the log, it confirms my suspicion. The problem is that we have told the Controller to resolve private addresses based on our existing pairing information.
When the phone connects again, it correctly resolves the private address into the identity Address. However, when doing the pairing it would need to use the private address, which the stack hasn't seen, as it was already resolved.

Could you do two more tests and send the log for each of them:
- one that adds ENABLE_LE_ENHANCED_CONNECTION_COMPLETE_EVENT to btstack_config
- one that removes ENABLE_LE_PRIVACY_ADDRESS_RESOLUTION

The second should work, but it would be better to move forward and use the first one.

Cheers
Matthias

> To view this discussion visit https://groups.google.com/d/msgid/btstack-dev/CAFXHxQgqrj8x-8QiwY9AVrXL-rdhR108YFKzYos05vprMooiwA%40mail.gmail.com.
> <full_rebonding_flow_pico2_w_with_bt_stack_v1.8.pklg>

[Franz Schnyder]

Hi Matthias

Adding ENABLE_LE_ENHANCED_CONNECTION_COMPLETE_EVENT solves my problem.
Also removing ENABLE_LE_PRIVACY_ADDRESS_RESOLUTION would solve it.

I attached the logs of both cases if they are of interest.

Thank you so much for your very fast help. What do you think? Should I create a PR against the btstack_config in the pico-examples repository which would add the ENABLE_LE_ENHANCED_CONNECTION_COMPLETE_EVENT?   

Regards
Franz

To view this discussion visit https://groups.google.com/d/msgid/btstack-dev/C53F4811-992E-4636-B11B-448FE9987F47%40gmail.com.

[Matthias Ringwald]

Hi Franz

Thanks for the testing. I'm glad that it was easy to fix after remembering the issue.
Yes, please make a PR and send me the link, so I can "approve it" in a comment.

Cheers
Matthias

> To view this discussion visit https://groups.google.com/d/msgid/btstack-dev/CAFXHxQh4yopj8fP44Zdro331EL7Eco-iry79pq22PyG11B126w%40mail.gmail.com.
> <with_ENABLE_LE_ENHANCED_CONNECTION_COMPLETE_EVENT.pklg><without_ENABLE_LE_PRIVACY_ADDRESS_RESOLUTION.pklg>

[Franz Schnyder]

Hi Matthias

PR => https://github.com/raspberrypi/pico-examples/pull/735 

Regards
Franz

To view this discussion visit https://groups.google.com/d/msgid/btstack-dev/6AB3F2CA-3D01-4883-B287-723B60CE7768%40gmail.com.