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

11 views
Skip to first unread message

Franz Schnyder

unread,
Jan 14, 2026, 12:45:14 PM (18 hours ago) Jan 14
to btstack-dev
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

unread,
3:30 AM (3 hours ago) 3:30 AM
to btstack-dev

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
Reply all
Reply to author
Forward
0 new messages