BlueZ "Pin or Key missing" occurred even though it has already been paired

Question

I'm developing a BLE peripheral device based on linux(bluez 5.48) and QT app for a gatt service. I'm also developing an Android phone's app for connecting the device.

My problem is on second connection(#3) as below procedure,

1. Device starts advertising -> Android app scan it and connect -> Android app try to write to an characteristic which have authentication security -> insufficient authentication occurred and pincode entry popped up on the phone -> Enter pincode and pairing success and the writing of the characteristic is OK.
2. Disconnect
3. Device starts advertising -> Android app scan it and connect -> Android app try to write to an characteristic which have authentication security -> insufficient authentication occurred and pincode entry popped up on the phone ????????????

I found "pin or key missing" error in the device's log. It seems my device recognizes the phone as a new device because of the phone's random MAC address. Any idea or solution for this problem?

Ps:The bluez device set to DisplayOnly

Thanks, Calvin

---

I added the device's log of above test sequence. Why is "Removing temporary device..." happening?

=============== first connection and pairing with my android test app: connect -> bonded -> disconnect from app =========

Dec 17 07:35:38 bluetoothd[368]: ../bluez-5.50/src/agent.c:agent_ref() 0xfd1000: ref=1

Dec 17 07:35:38 bluetoothd[368]: ../bluez-5.50/src/agent.c:register_agent() agent :1.49

Dec 17 07:35:38 bluetoothd[368]: ../bluez-5.50/src/agent.c:unregister_agent() agent :1.49

Dec 17 07:35:38 bluetoothd[368]: ../bluez-5.50/src/agent.c:agent_disconnect() Agent :1.49 disconnected

Dec 17 07:35:38 bluetoothd[368]: ../bluez-5.50/src/agent.c:agent_destroy() agent :1.49

Dec 17 07:35:38 bluetoothd[368]: ../bluez-5.50/src/agent.c:agent_unref() 0xfd1000: ref=0

Dec 17 07:35:38 bluetoothd[368]: ../bluez-5.50/src/agent.c:agent_ref() 0xfd1000: ref=1

Dec 17 07:35:38 bluetoothd[368]: ../bluez-5.50/src/agent.c:register_agent() agent :1.49

Dec 17 07:35:38 bluetoothd[368]: ../bluez-5.50/src/agent.c:add_default_agent() Default agent set to :1.49 /org/bluez/agent

Dec 17 07:35:46 bluetoothd[368]: ../bluez-5.50/src/adapter.c:connected_callback() hci0 device 5C:CB:99:7F:77:02 connected eir_len 0

Dec 17 07:35:47 bluetoothd[368]: ../bluez-5.50/src/adapter.c:user_passkey_notify_callback() hci0 5C:CB:99:7F:77:02

Dec 17 07:35:47 bluetoothd[368]: ../bluez-5.50/src/adapter.c:user_passkey_notify_callback() passkey 859060 entered 0

Dec 17 07:35:47 bluetoothd[368]: ../bluez-5.50/src/device.c:new_auth() Requesting agent authentication for 5C:CB:99:7F:77:02

Dec 17 07:35:47 bluetoothd[368]: ../bluez-5.50/src/agent.c:agent_ref() 0xfd1000: ref=2

Dec 17 07:35:56 bluetoothd[368]: ../bluez-5.50/src/adapter.c:new_irk_callback() hci0 new IRK for 5C:CB:99:7F:77:02 RPA 00:00:00:00:00:00

Dec 17 07:35:56 bluetoothd[368]: ../bluez-5.50/src/adapter.c:new_csrk_callback() hci0 new CSRK for 5C:CB:99:7F:77:02 type 3

Dec 17 07:35:56 bluetoothd[368]: ../bluez-5.50/src/adapter.c:new_csrk_callback() hci0 new CSRK for 5C:CB:99:7F:77:02 type 2

Dec 17 07:35:56 bluetoothd[368]: ../bluez-5.50/src/adapter.c:new_long_term_key_callback() hci0 new LTK for 5C:CB:99:7F:77:02 type 1 enc_size 16

Dec 17 07:35:56 bluetoothd[368]: ../bluez-5.50/src/device.c:device_set_bonded()

Dec 17 07:35:56 bluetoothd[368]: ../bluez-5.50/src/device.c:device_bonding_complete() bonding (nil) status 0x00

Dec 17 07:35:56 bluetoothd[368]: ../bluez-5.50/src/agent.c:agent_unref() 0xfd1000: ref=1

Dec 17 07:35:56 bluetoothd[368]: ../bluez-5.50/src/adapter.c:resume_discovery()

Dec 17 07:35:56 bluetoothd[368]: ../bluez-5.50/src/adapter.c:new_long_term_key_callback() hci0 new LTK for 5C:CB:99:7F:77:02 type 1 enc_size 16

Dec 17 07:35:56 bluetoothd[368]: ../bluez-5.50/src/device.c:device_set_bonded()

Dec 17 07:35:56 bluetoothd[368]: ../bluez-5.50/src/device.c:device_bonding_complete() bonding (nil) status 0x00

Dec 17 07:35:56 bluetoothd[368]: ../bluez-5.50/src/adapter.c:resume_discovery()

Dec 17 07:36:15 bluetoothd[368]: ../bluez-5.50/src/adapter.c:dev_disconnected() Device 5C:CB:99:7F:77:02 disconnected, reason 3

Dec 17 07:36:15 bluetoothd[368]: ../bluez-5.50/src/adapter.c:adapter_remove_connection() Dec 17 07:36:15 bluetoothd[368]: ../bluez-5.50/plugins/policy.c:disconnect_cb() reason 3

Dec 17 07:36:15 bluetoothd[368]: ../bluez-5.50/src/adapter.c:bonding_attempt_complete() hci0 bdaddr 5C:CB:99:7F:77:02 type 1 status 0xe

Dec 17 07:36:15 bluetoothd[368]: ../bluez-5.50/src/device.c:device_bonding_complete() bonding (nil) status 0x0e

Dec 17 07:36:15 bluetoothd[368]: ../bluez-5.50/src/device.c:device_bonding_failed() status 14

Dec 17 07:36:15 bluetoothd[368]: ../bluez-5.50/src/adapter.c:resume_discovery()

Dec 17 07:36:36 bluetoothd[368]: ../bluez-5.50/src/agent.c:agent_disconnect() Agent :1.49 disconnected

Dec 17 07:36:36 bluetoothd[368]: ../bluez-5.50/src/agent.c:remove_default_agent() Default agent cleared

Dec 17 07:36:36 bluetoothd[368]: ../bluez-5.50/src/agent.c:agent_destroy() agent :1.49

Dec 17 07:36:36 bluetoothd[368]: ../bluez-5.50/src/agent.c:agent_unref() 0xfd1000: ref=0

Dec 17 07:36:37 bluetoothd[368]: ../bluez-5.50/src/agent.c:agent_ref() 0xfd2808: ref=1

Dec 17 07:36:37 bluetoothd[368]: ../bluez-5.50/src/agent.c:register_agent() agent :1.51

Dec 17 07:36:37 bluetoothd[368]: ../bluez-5.50/src/agent.c:unregister_agent() agent :1.51

Dec 17 07:36:37 bluetoothd[368]: ../bluez-5.50/src/agent.c:agent_disconnect() Agent :1.51 disconnected

Dec 17 07:36:37 bluetoothd[368]: ../bluez-5.50/src/agent.c:agent_destroy() agent :1.51

Dec 17 07:36:37 bluetoothd[368]: ../bluez-5.50/src/agent.c:agent_unref() 0xfd2808: ref=0

============= second connection : this device unpaired unintentionally from the app system as soon as connected ===================================

Dec 17 07:36:37 bluetoothd[368]: ../bluez-5.50/src/agent.c:agent_ref() 0xfd2808: ref=1

Dec 17 07:36:37 bluetoothd[368]: ../bluez-5.50/src/agent.c:register_agent() agent :1.51

Dec 17 07:36:37 bluetoothd[368]: ../bluez-5.50/src/agent.c:add_default_agent() Default agent set to :1.51 /org/bluez/agent

Dec 17 07:36:42 bluetoothd[368]: ../bluez-5.50/src/adapter.c:connected_callback() hci0 device 4D:EE:4F:F1:6F:FD connected eir_len 0

Dec 17 07:36:42 bluetoothd[368]: ../bluez-5.50/src/device.c:device_create() dst 4D:EE:4F:F1:6F:FD

Dec 17 07:36:42 bluetoothd[368]: ../bluez-5.50/src/device.c:device_new() address 4D:EE:4F:F1:6F:FD

Dec 17 07:36:42 bluetoothd[368]: ../bluez-5.50/src/device.c:device_new() Creating device /org/bluez/hci0/dev_4D_EE_4F_F1_6F_FD

Dec 17 07:36:43 bluetoothd[368]: ../bluez-5.50/src/adapter.c:dev_disconnected() Device 4D:EE:4F:F1:6F:FD disconnected, reason 3

Dec 17 07:36:43 bluetoothd[368]: ../bluez-5.50/src/adapter.c:adapter_remove_connection()

Dec 17 07:36:43 bluetoothd[368]: ../bluez-5.50/src/adapter.c:adapter_remove_connection() Removing temporary device /org/bluez/hci0/dev_4D_EE_4F_F1_6F_FD

Dec 17 07:36:43 bluetoothd[368]: ../bluez-5.50/src/device.c:device_remove() Removing device /org/bluez/hci0/dev_4D_EE_4F_F1_6F_FD

Dec 17 07:36:43 bluetoothd[368]: ../bluez-5.50/src/device.c:btd_device_unref() Freeing device /org/bluez/hci0/dev_4D_EE_4F_F1_6F_FD

Dec 17 07:36:43 bluetoothd[368]: ../bluez-5.50/src/device.c:device_free() 0xff3058

Dec 17 07:36:43 bluetoothd[368]: ../bluez-5.50/plugins/policy.c:disconnect_cb() reason 3

Dec 17 07:36:43 bluetoothd[368]: ../bluez-5.50/src/adapter.c:bonding_attempt_complete() hci0 bdaddr 4D:EE:4F:F1:6F:FD type 2 status 0xe

Dec 17 07:36:43 bluetoothd[368]: ../bluez-5.50/src/adapter.c:resume_discovery()

Answer 1

Update:

While resolving the issue within Direct-BT, I was able to resolve the semantics about the master (== central == initiator) field of BlueZ/Kernel mgmt-api's Load Long Term Keys Command and New Long Term Key Event.

BlueZ interprets this flag's role as follows:

• Adapter role slave/responder (GATT server)
  • 1 = master/initiator (GATT client); 0 = slave/responder (GATT server)
• Adapter role master/initiator (GATT client)
  • 0 = master/initiator (GATT client); 1 = slave/responder (GATT server)

After resolving this issue, we got no more pin or key missing error when uploading the previously received and stored legacy LTK.

Note: Using secure connections (SC), the DH negotiated key is the same for both communication partner and no more transported between them.

Hope this helps a little.

+++

I experience this for 'pre-paired' devices using legacy security (no SC) on kernel >= 5.15 as well so far.

HCI event caught:

[opcode HCI_ENC_CHANGED, devID 0x0000, address=C0:26:DA:01:DA:B1, addressType BDADDR_LE_PUBLIC, status PIN_OR_KEY_MISSING, enabled 0x00, data[size 0, data ], tsz 15]

Not sure yet whether this is a BlueZ regression or mine within Direct-BT https://jausoft.com/cgit/direct_bt.git/about/ - but pre-pairing works on Debian 11, kernel 5.10 w/ same BLE server peripheral.

Interesting is that HCI_ERROR_PIN_OR_KEY_MISSING 0x06 is only READ and not set in git-linux-stable 5.16 or bluetooth-next Linux kernel.

The previously set encryption status via uploaded keys on the client/master was:

  Setup:
  - SC 0
  - IOCap conn NO_INPUT_NO_OUTPUT, user NO_INPUT_NO_OUTPUT, auto UNSET
  - Level conn ENC_ONLY, user ENC_ONLY
  Initiator (master) Set:
  - OOB   OOB_AUTH_DATA_NOT_PRESENT
  - Auth  [No bonding, No MITM, Legacy, No keypresses]
  - IOCap NO_INPUT_NO_OUTPUT
  - EncSz 0
  - Keys  [ENC_KEY, ID_KEY, SIGN_KEY] / [ENC_KEY, ID_KEY, SIGN_KEY]
    - LTK[props [], enc_size 16, ediv 01b3, rand 5feb93388bc72e70, ltk 8dd48069ede576283d0954998e310c29, valid 1]
    - LK[resp 0, type COMBI, key 00000000000000000000000000000000, plen 0]
    - IRK[props [], irk 2b50a1db3fb6719e95d1919adb2fee2d]
    - CSRK[props [], csrk 3c465201878e78a8c4ad47b4f418e5e0]
  - IdAdr [00:00:00:00:00:00, BDADDR_UNDEFINED]
  Responder (slave) Set:
  - OOB   OOB_AUTH_DATA_NOT_PRESENT
  - Auth  [No bonding, No MITM, Legacy, No keypresses]
  - IOCap NO_INPUT_NO_OUTPUT
  - EncSz 0
  - Keys  [ENC_KEY, SIGN_KEY] / [ENC_KEY, SIGN_KEY]
    - LTK[props [RESPONDER], enc_size 16, ediv 1640, rand 12ff85c7fe7367d4, ltk c63a9d774b0bafc0d0ddb322e2ce2b5d, valid 1]
    - LK[resp 0, type COMBI, key 00000000000000000000000000000000, plen 0]
    - IRK[props [], irk 00000000000000000000000000000000]
    - CSRK[props [RESPONDER], csrk 7dfa0dd991c98762474c4fe1124c1eca]
  - IdAdr [00:00:00:00:00:00, BDADDR_UNDEFINED] ]