Pairing as Central fails instantly (ESP32-S3)

[nullstalgia]

I have a device that requires the Central to be paired for a certain characteristic to actually send Notifications when subscribing.

However, the entire process of attempting to pair with set_bondable(true) and request_security fails in under a second.

I turned on trace-level defmt logs, and also enabled printing the inner l2cap data (I was surprised the reason for Pairing Failed isn't shown otherwise).

The reason 0x08 seems to just be Unspecified.

Luckily I'm able to probe the device's serial port for logs, and I have examples of successful pairing with Android and Linux->BlueZ, and the unsuccessful attempt with trouble.

• Unsuccessful, with trouble

I 00192381 BLE: GAP event CONNECTED
I 00192381 BLE: Connected
I 00192381 BLE: Master address: ff:e4:05:1b:8f:ff [private] # <- the ESP
I 00192381 BLE: Device address: d8:c4:97:07:00:46 [public]  # <- target device
I 00192381 BLE: Connected connection interval: [15.00 15.00] ms, sl=0, st=4500ms, initial
I 00192383 BLE: State transition begin:
I 00192383 BLE:     State (now): INITIALIZED
I 00192383 BLE:           Event: CONNECTED
I 00192398 BLE:          Status: OK
I 00192400 BLE: State transition end; new state: CONNECTION_PAIRING_IN_PROGRESS; changed: yes
I 00192400 BLE: GAP event ADV_COMPLETED
I 00192400 BLE: Stopped advertising
I 00192400 SYS: StateButtonAdv exit
I 00192400 SYS: StateConnActive entry
I 00192409 BLE: GAP event PAIR_REQ # <- pair req recieved
I 00192409 BLE: State transition begin:
I 00192409 BLE:     State (now): CONNECTION_PAIRING_IN_PROGRESS
I 00192409 BLE:           Event: PAIR_REQ
I 00192409 BLE:          Status: OK
I 00192409 BLE: State transition end; new state: CONNECTION_PAIRING_IN_PROGRESS; changed: no
I 00192409 BLE: GAP event PAIR_COMPLETED 
I 00192409 BLE: State transition begin: 
I 00192409 BLE:     State (now): CONNECTION_PAIRING_IN_PROGRESS
I 00192411 BLE:           Event: PAIR_COMPLETED
I 00192415 BLE:          Status: ERROR # <- failed
I 00192417 BLE: Connecting device that was NOT paired/bonded already
I 00192417 BLE: due to seeing a pair request event; skipping device lookup.
I 00192420 BLE: State transition end; new state: CONNECTION_PAIRING_IN_PROGRESS; changed: no
I 00192439 BLE: GAP event DISCONNECTED
I 00192439 BLE: Disconnected, reason: REMOTE_USER_TERM_CON 0x13
I 00192439 BLE: State transition begin:
I 00192439 BLE:     State (now): CONNECTION_PAIRING_IN_PROGRESS
I 00192441 BLE:           Event: DISCONNECTED
I 00192441 BLE:          Status: OK
I 00192441 BLE: State transition end; new state: DISCONNECTED; changed: yes
W 00192441 SYS: Unexpected disconnect

• Successful, Linux->BlueZ

I 04248089 BLE: GAP event CONNECTED
I 04248089 BLE: Connected
I 04248089 BLE: Master address: xx:xx:xx:xx:xx:xx [public]
I 04248089 BLE: Device address: d8:c4:97:07:00:46 [public]
I 04248089 BLE: Connected connection interval: [45.00 45.00] ms, sl=0, st=420ms, initial
I 04248091 BLE: State transition begin:
I 04248091 BLE:     State (now): DISCONNECTED
I 04248091 BLE:           Event: CONNECTED
I 04248091 BLE:          Status: OK
I 04248091 BLE: State transition end; new state: CONNECTION_PAIRING_IN_PROGRESS; changed: yes
I 04248098 BLE: GAP event ADV_COMPLETED
I 04248100 BLE: Stopped advertising
I 04248100 SYS: StateTimedAdvUser exit
I 04248100 SYS: StateConnActive entry
I 04248202 BLE: GAP event PAIR_REQ # <- pair req recieved
I 04248202 BLE: State transition begin:
I 04248202 BLE:     State (now): CONNECTION_PAIRING_IN_PROGRESS
I 04248204 BLE:           Event: PAIR_REQ
I 04248204 BLE:          Status: OK
I 04248204 BLE: State transition end; new state: CONNECTION_PAIRING_IN_PROGRESS; changed: no
I 04248797 BLE: GAP event UNKNOWN
I 04248797 BLE: GAP event SEC_LEVEL_CHANGED
I 04248799 BLE: Security level changed to 2
I 04248799 BLE: State transition begin:
I 04248799 BLE:     State (now): CONNECTION_PAIRING_IN_PROGRESS
I 04248799 BLE:           Event: SEC_LEVEL_CHANGED
I 04248799 BLE:          Status: OK
I 04248799 BLE: Connecting device that was NOT paired/bonded already
I 04248799 BLE: due to seeing a pair request event; skipping device lookup.
I 04248799 BLE: State transition end; new state: CONNECTION_PAIRING_IN_PROGRESS; changed: no
I 04248808 BLE: GAP event PAIR_COMPLETED
I 04248808 BLE: State transition begin:
I 04248808 BLE:     State (now): CONNECTION_PAIRING_IN_PROGRESS
I 04248808 BLE:           Event: PAIR_COMPLETED
I 04248808 BLE:          Status: OK
I 04248808 BLE: Connection was in progress; but now is ready
I 04248808 BLE: =================== FULLY CONNECTED ===================

• Successful, Android

I 00374697 BLE: GAP event CONNECTED
I 00374697 BLE: Connected
I 00374697 BLE: Master address: xx:xx:xx:xx:xx:xx [private]
I 00374697 BLE: Device address: d8:c4:97:07:00:46 [public]
I 00374697 BLE: Connected connection interval: [45.00 45.00] ms, sl=0, st=5000ms, initial
I 00374699 BLE: State transition begin:
I 00374699 BLE:     State (now): DISCONNECTED
I 00374699 BLE:           Event: CONNECTED
I 00374699 BLE:          Status: OK
I 00374699 BLE: State transition end; new state: CONNECTION_PAIRING_IN_PROGRESS; changed: yes
I 00374703 BLE: GAP event ADV_COMPLETED
I 00374710 BLE: Stopped advertising
I 00374712 SYS: StateTimedAdvUser exit
I 00374712 SYS: StateConnActive entry
I 00374948 BLE: GAP event CONN_PARAM_UPDATE_REQ
I 00374948 BLE: Master requested connection interval: [7.50 7.50] ms, sl=0, st=5000ms, accepted
I 00375447 BLE: GAP event CONN_PARAM_UPDATED
I 00375447 BLE: Updated connection interval: [7.50 7.50] ms, sl=0, st=5000ms, master
I 00375844 BLE: GAP event CONN_PARAM_UPDATE_REQ
I 00375846 BLE: Master requested connection interval: [45.00 45.00] ms, sl=0, st=5000ms, accepted
I 00375942 BLE: GAP event CONN_PARAM_UPDATED
I 00375942 BLE: Updated connection interval: [45.00 45.00] ms, sl=0, st=5000ms, master
I 00382599 BLE: GAP event PAIR_REQ # <- pair req recieved
I 00382601 BLE: State transition begin:
I 00382601 BLE:     State (now): CONNECTION_PAIRING_IN_PROGRESS
I 00382601 BLE:           Event: PAIR_REQ
I 00382601 BLE:          Status: OK
I 00382601 BLE: State transition end; new state: CONNECTION_PAIRING_IN_PROGRESS; changed: no
I 00387823 BLE: GAP event ADDRESS_RESOLVED
I 00387825 BLE: GAP event SEC_LEVEL_CHANGED
I 00387825 BLE: Security level changed to 2
I 00387825 BLE: State transition begin:
I 00387825 BLE:     State (now): CONNECTION_PAIRING_IN_PROGRESS
I 00387825 BLE:           Event: SEC_LEVEL_CHANGED
I 00387825 BLE:          Status: OK
I 00387825 BLE: Connecting device that was NOT paired/bonded already
I 00387825 BLE: due to seeing a pair request event; skipping device lookup.
I 00387825 BLE: State transition end; new state: CONNECTION_PAIRING_IN_PROGRESS; changed: no
I 00387831 BLE: GAP event PAIR_COMPLETED
I 00387833 BLE: State transition begin:
I 00387833 BLE:     State (now): CONNECTION_PAIRING_IN_PROGRESS
I 00387833 BLE:           Event: PAIR_COMPLETED
I 00387833 BLE:          Status: OK
I 00387833 BLE: Connection was in progress; but now is ready
I 00387833 BLE: =================== FULLY CONNECTED ===================

(i tried so many languages for the log blocks until i found one that looked nice, thanks yml)

Edit: Oh, not doing set_bondable first does show the reason? Odd. Oh wait that's an entirely different response, but still a failure.

[nullstalgia]

Ah, it looks like I might be another victim of #439. Tis a shame, I hope someone with the knowledge and time can get that in when possible.