[nRF Connect SDK] Pairing failure

[Tim Hwang]

Target nRF52832(nrf52dk_nrf52832)
SDK NCS v2.0.0

original case
(+) [nRF Connect SDK]Force to make pairing(bonding) - Nordic Q&A - Nordic DevZone - Nordic DevZone (nordicsemi.com)

Here is my test step. (Nordic: peripheral role)

1) Nordic begins advertising (custom UUID like peripheral_uart sample)
2) Android app gets predefined bt mac (example 00:16:7F:11:22:36).
There were no BLE scan. and connect to Nordic.

3) Nordic connected and initiate pairing
bt_set_bondable(true);
bt_conn_set_security(conn, BT_SECURITY_L4);

Result
Much of case my Android (MTK) failed to make pairing. (Especially right after android rebooted) 

MTK have told me Nordic should provide solution to resolve this issue.

RTT Viewer
00> Connected secmode 4
00> HS connected
00> HS Connected 00:16:7F:40:1E:D0 (public)
00> D:
00> D: 00:16:7F:40:1E:D0 (public)
00> D: prnd 7d93ec3b4828ce3b4210d054f903653a
00> D: chan 0x20001f54 cid 0x0006
00> D: status 0x8
00> D: chan 0x20001f54 conn 0x20001c90 handle 0 encrypt 0x00 hci status 0x1f
00> Security failed: 00:16:7F:40:1E:D0 (public) level 1 err 9
(Android public mac 00:16:7F:40:1E:D0)

2772.sf650_error_03Nov2022.7z



BTW, Nordic required sniff log for analyzing pairing error. However, I hardly get sniff log.
I can get CONNECT_IND then drops next packets. Do you have any idea?






nrf_sniffer_for_bluetooth_le_4.1.1
wireshark 4.0.1
nRF52DK dev borad
J-Link 6.88a

[Tim Hwang]

00> HS:Advertising successfully started
00> D: 55:A6:42:65:6B:D0 (random)
00> D: No IRK for 55:A6:42:65:6B:D0 (random)
00> D: conn 0x20001c88 handle 0
00> D: chan 0x20001f4c cid 0x0006
00> D: 55:A6:42:65:6B:D0 (random)
00> Connected secmode 4
00> HS connected
00> HS Connected 55:A6:42:65:6B:D0 (random)
00> D: 
00> D: 55:A6:42:65:6B:D0 (random)
00> D: created 0x200029dc for 55:A6:42:65:6B:D0 (random)
00> D: prnd 23a14c89ca6eb11b5c0c56610146bb35
00> Connection parameters updated.
00>  interval: 6, latency: 0, timeout: 500
00> Conn params updated: interval 7 ms, latency 0, timeout: 5000 ms
00> W: Ignoring unexpected request
00> W: Ignoring unexpected request
00> D: chan 0x20001f4c cid 0x0006
00> D: status 0x8
00> D: 55:A6:42:65:6B:D0 (random) (keys 0x0000)
00> D: Deleting key bt/keys/55a642656bd01
00> D: chan 0x20001f4c conn 0x20001c88 handle 0 encrypt 0x00 hci status 0x1f
00> Security failed: 55:A6:42:65:6B:D0 (random) level 1 err 9 
00> D: 55:A6:42:65:6B:D0 (random)
00> D: 00:00:00:00:00:00 (public) (keys 0x0000)
00> D: Deleting key bt/keys/0000000000000
00> D: 55:A6:42:65:6B:D0 (random)
00> D: 55:A6:42:65:6B:D0 (random)
00> Disconnected: 55:A6:42:65:6B:D0 (random) (reason 19) 
00> HS:Advertising successfully started

sniff.7z

sniff log is uploaded as well as rtt log.
Your message will be forwarded to MTK HQ again.

I have no idea what made following error. Can you please find in sniff log?
00> D: chan 0x20001f4c conn 0x20001c88 handle 0 encrypt 0x00 hci status 0x1f

[Hieu]

Hi Tim,

Sorry but I feel confused a bit about your situation here.

original case
[nRF Connect SDK] How to force to wake up (not to go sleep mode) - Nordic Q&A - Nordic DevZone - Nordic DevZone (nordicsemi.com)

I am not sure how that case is related to this current question. Could you please elaborate?

Much of case my Android (MTK) failed to make pairing. (Especially right after android rebooted) 

MTK have told me Nordic should provide solution to resolve this issue.

Does MTK mean MediaTek?

What reasoning did they give to believe Nordic should provide the solution to resolve this issue?

On my end, I attempted to pair using bt_conn_set_security() as you did, and both my Android phone and my Windows PC can bond with the device without any problem.
Pairing at Security Level 4 like you are trying to do also require an out of band verification method. On your RTT log I don't see signs of this happened. What did you do to achieve this?

Tim Hwang said:

I have no idea what made following error. Can you please find in sniff log?
00> D: chan 0x20001f4c conn 0x20001c88 handle 0 encrypt 0x00 hci status 0x1f

That is not an error. It is most likely just a log from smp.c. See sdk-zephyr/smp.c.

Finally, I would like to ask for a few pieces of information to understand the situation better:

What is your current setup?
What module did you enable logging to acquire the RTT log you shared?
Is there a specific sample are you experimenting on?
What SDK version are you on?
These pieces of information help making sense out of the logs you provided.

Best regards,

Hieu

[Tim Hwang]

1. The link was wrong.
[nRF Connect SDK]Force to make pairing(bonding) 

In original case, I did lots of test to know root reason. Now it made us confused.
In this case, I will do test one scenario to make it simple.
Here is NG video and normal operation video clip.
(Android reboot-App launch-connect-failed: NG.mp4, most of time it fails)
then I retry to connect, it will be okay : OKAY.mp4, most of time it succeeds)

2. Does MTK mean MediaTek? Yes

3. What reasoning ...
Because they initiate paring process, but they believe Nordic made timeout error.

4. On my end, I attempted to ...
Of course, you did. We have this issue with MTK.

5. Pairing at Security Level 4 like you are trying to do also require an out of band verification method. On your RTT log I don't see signs of this happened. What did you do to achieve this?
-> I cannot understand "out of band verification method".

6. "chan 0x20001f4c conn 0x20001c88 handle 0 encrypt 0x00 hci status 0x1f"
You though it's normal. But, in smp.c if hci_status is not zero, it is error. (please see hci_err.h)

00> D: conn 0x20001c90 handle 0
00> D: chan 0x20001f54 cid 0x0006
00> D: 00:16:7F:40:1E:D0 (public)
00> Notification has been turned on
00> bt_send_enabled 0 
00> negoDone 0 txEnable 1
00> Connected secmode 4
00> HS connected
00> HS Connected 00:16:7F:40:1E:D0 (public)
00> D: 
00> D: 00:16:7F:40:1E:D0 (public)
00> D: prnd a19413734643c439e2bad8f3f921846a
00> Connection parameters updated.
00>  interval: 6, latency: 0, timeout: 500
00> Conn params updated: interval 7 ms, latency 0, timeout: 5000 ms
00> Connection parameters updated.
00>  interval: 39, latency: 0, timeout: 500
00> Conn params updated: interval 48 ms, latency 0, timeout: 5000 ms
00> D: Received SMP code 0x01 len 6
00> D: 
00> pairing_accept conn: 00:16:7F:40:1E:D0 (public) 
00> io_capability: 4 
00> auth_req: 2d 
00> D: Received SMP code 0x0c len 64
00> D: 
00> D: u d541501fd159ed3e4bd76b7b042c91733dfc7eadb9a01e8c7eef0d3d43b126ec
00> D: v 8d0dd29fd4da1ff910e55ff44e5b686380ce8177005d16ef098fa57f5ecd35c8
00> D: x a19413734643c439e2bad8f3f921846a z 0x0
00> D: res 79124ee59ce77d61a5d284cdd5b357e1
00> D: 0x2000a5ad
00> D: Received SMP code 0x04 len 16
00> D: 
00> D: u 8d0dd29fd4da1ff910e55ff44e5b686380ce8177005d16ef098fa57f5ecd35c8
00> D: v d541501fd159ed3e4bd76b7b042c91733dfc7eadb9a01e8c7eef0d3d43b126ec
00> D: x 3cea4ad0b9d700877bb03726c5cc6b87
00> D: y a19413734643c439e2bad8f3f921846a
00> D: res ec01b336020cb1e5929e2860548e3ca3
00> D: passkey 607779
00> Passkey for 00:16:7F:40:1E:D0 (public): 607779 
00> Press Button 1 to confirm, Button 2 to reject.
00> hs_pair_accept 1
00> Numeric Match, conn 0x20001c90
00> D: Received SMP code 0x0d len 16
00> D: 
00> D: w ea925ab44684d77e5708f05b1f955fe49ad1732bb218016f606d899e8197dfe7
00> D: n1 3cea4ad0b9d700877bb03726c5cc6b87
00> D: n2 a19413734643c439e2bad8f3f921846a
00> D: t f523ab78aa4b5bb443afd804a6e9efa8
00> D: mackey 5e7f9fc30f9c3deee8a4b0b7cd431e0d
00> D: ltk f928202406cbac3dcf53dc240639a032
00> D: w 0d1e43cdb7b0a4e8ee3d9c0fc39f7f5e
00> D: n1 a19413734643c439e2bad8f3f921846a
00> D: n2 3cea4ad0b9d700877bb03726c5cc6b87
00> D: r 00000000000000000000000000000000
00> D: io_cap 01000d
00> D: a1 006415417f1600
00> D: a2 012e1ed387dc42
00> D: res 93a1ff538a2a8802ce3c90ceb014324d
00> D: w 0d1e43cdb7b0a4e8ee3d9c0fc39f7f5e
00> D: n1 3cea4ad0b9d700877bb03726c5cc6b87
00> D: n2 a19413734643c439e2bad8f3f921846a
00> D: r 00000000000000000000000000000000
00> D: io_cap 04002d
00> D: a1 012e1ed387dc42
00> D: a2 006415417f1600
00> D: res a0f3e47af5b51c5892c01ae535d8d1e0
00> D: 
00> D: 00:16:7F:40:1E:D0 (public) (keys 0x0022)
00> D: Deleting key bt/keys/00167f401ed00
00> D: 00:16:7F:40:1E:D0 (public)
00> D: created 0x200029e4 for 00:16:7F:40:1E:D0 (public)
00> D: chan 0x20001f54 conn 0x20001c90 handle 0 encrypt 0x01 hci status 0x00
00> Security changed: 00:16:7F:40:1E:D0 (public) level 4 
00> connect_done secmode(4)
00> D: 00:16:7F:40:1E:D0 (public)
00> param_update_handler 1
00> ## phy(0) dl(0) int(0) mtu(0)
00> reschedule param_work
00> param_update in_pairing(1)
00> negoDone 0 txEnable 1 
00> D: Received SMP code 0x08 len 16
00> D: 
00> D: type 2 00:16:7F:40:1E:D0 (public)
00> D: type 2 00:16:7F:40:1E:D0 (public)
00> D: 00:16:7F:40:1E:D0 (public)
00> D: Received SMP code 0x09 len 7
00> D: identity 00:16:7F:40:1E:D0 (public)
00> D: type 2 00:16:7F:40:1E:D0 (public)
00> D: type 2 00:16:7F:40:1E:D0 (public)
00> D: status 0x0
00> I: SC LTK: 0xf928202406cbac3dcf53dc240639a032
00> D: Stored keys for 00:16:7F:40:1E:D0 (public) (bt/keys/00167f401ed00)
00> Pairing completed: 00:16:7F:40:1E:D0 (public), bonded: 1 
00> param_update_handler 1
00> ## phy(0) dl(0) int(0) mtu(0)
00> reschedule param_work
00> param_update in_pairing(0)
00> Connection parameters update requested (err: 0)
00> Phy update requested
00> MTU exchange pending
00> data_len requested
00> negoDone 0 txEnable 1 
00> LE data len updated: TX (len: 251 time: 2120) RX (len: 247 time: 2120)
00> MTU exchange done. 244
00> D: 00:16:7F:40:1E:D0 (public)
00> Connection parameters updated.
00>  interval: 15, latency: 0, timeout: 400
00> Conn params updated: interval 18 ms, latency 0, timeout: 4000 ms
00> LE PHY updated: TX PHY LE 2M, RX PHY LE 2M
00> param_update_handler 1
00> ## phy(2) dl(251) int(15) mtu(244)
00> negoDone 1 txEnable 1 
00> connect_done secmode(4)

This is the log it paired and connected well. And hci status 0x0
00> D: chan 0x20001f54 conn 0x20001c90 handle 0 encrypt 0x01 hci status 0x00



7. What module did you ...

Fullscreen 2783.prj.conf.txt Download

#
# Copyright (c) 2019 Nordic Semiconductor ASA
#
# SPDX-License-Identifier: LicenseRef-Nordic-5-Clause
#


#
CONFIG_LOG_BUFFER_SIZE=8192
CONFIG_SEGGER_RTT_MODE_BLOCK_IF_FIFO_FULL=y
CONFIG_LOG_BLOCK_IN_THREAD=y
CONFIG_SEGGER_RTT_BUFFER_SIZE_UP=4096
CONFIG_LOG_BLOCK_IN_THREAD_TIMEOUT_MS=-1
CONFIG_BT_DEBUG_LOG=y
CONFIG_BT_DEBUG_SMP=y
CONFIG_BT_LOG_SNIFFER_INFO=y
CONFIG_BT_DEBUG_KEYS=y
CONFIG_BT_DEBUG_CONN=n
#

CONFIG_MCUBOOT_IMAGE_VERSION="1.4.0"
CONFIG_NRFX_UARTE0=y
CONFIG_NCS_SAMPLES_DEFAULTS=y
CONFIG_MAIN_STACK_SIZE=2048
CONFIG_BT=y
CONFIG_BT_DEBUG_LOG=n
CONFIG_BT_MAX_CONN=1
CONFIG_BT_MAX_PAIRED=6
CONFIG_BT_KEYS_OVERWRITE_OLDEST=y
CONFIG_BT_SMP=y
#CONFIG_BT_L2CAP_TX_BUF_COUNT=5
CONFIG_BT_PERIPHERAL=y
CONFIG_BT_DEVICE_NAME="RFRNCS"
CONFIG_BT_DEVICE_NAME_MAX=32
CONFIG_BT_DEVICE_NAME_DYNAMIC=y
#CONFIG_MPU_ALLOW_FLASH_WRITE=y

CONFIG_BT_DEVICE_APPEARANCE=961
#CONFIG_BT_DEVICE_APPEARANCE=833

CONFIG_BT_BAS=n
CONFIG_BT_HIDS=y
CONFIG_BT_HIDS_MAX_CLIENT_COUNT=1
CONFIG_BT_HIDS_DEFAULT_PERM_RW_ENCRYPT=y
CONFIG_BT_GATT_UUID16_POOL_SIZE=40
CONFIG_BT_GATT_CHRC_POOL_SIZE=20

CONFIG_BT_CONN_CTX=y

CONFIG_BT_DIS=n
CONFIG_BT_DIS_PNP=n
#CONFIG_BT_DIS_MANUF="NordicSemiconductor"
#CONFIG_BT_DIS_PNP_VID_SRC=2
#CONFIG_BT_DIS_PNP_VID=0x1915
#CONFIG_BT_DIS_PNP_PID=0xEEEF
#CONFIG_BT_DIS_PNP_VER=0x0100

#CONFIG_SYSTEM_WORKQUEUE_STACK_SIZE=2048

# Enable bonding
CONFIG_BT_SETTINGS=y
CONFIG_FLASH=y
CONFIG_FLASH_PAGE_LAYOUT=y
CONFIG_FLASH_MAP=y
CONFIG_NVS=y
CONFIG_SETTINGS=y

CONFIG_DK_LIBRARY=y

########################################################################

# Boot
#CONFIG_BOOTLOADER_MCUBOOT=y

#From NUS

# Config logger
CONFIG_LOG=y
CONFIG_USE_SEGGER_RTT=y
CONFIG_LOG_BACKEND_RTT=n
CONFIG_LOG_BACKEND_UART=n
CONFIG_RTT_CONSOLE=y

# Enable the NUS service
# CONFIG_BT_NUS=y

# Enable the UART driver
CONFIG_UART_CONSOLE=n
CONFIG_UART_ASYNC_API=n
CONFIG_UART_INTERRUPT_DRIVEN=y

# For HS
CONFIG_BT_CONN_TX_MAX=10
CONFIG_BT_L2CAP_TX_BUF_COUNT=10
CONFIG_BT_L2CAP_TX_MTU=247
CONFIG_BT_BUF_ACL_TX_COUNT=10
CONFIG_BT_BUF_ACL_TX_SIZE=251
CONFIG_BT_BUF_ACL_RX_SIZE=251
#CONFIG_BT_PRIVACY=n
CONFIG_BT_GAP_AUTO_UPDATE_CONN_PARAMS=n
CONFIG_BT_CTLR_DATA_LENGTH_MAX=251
#CONFIG_BT_CONN_PARAM_UPDATE_TIMEOUT=300
CONFIG_BT_CONN_PARAM_UPDATE_TIMEOUT=1000
CONFIG_BT_USER_PHY_UPDATE=y
CONFIG_BT_GATT_CLIENT=y
CONFIG_BT_USER_DATA_LEN_UPDATE=y

CONFIG_RING_BUFFER=y

#Log
# For BT connection debugging(conn.c)
CONFIG_BT_DEBUG_CONN=n

#Boot
CONFIG_BOOTLOADER_MCUBOOT=y

CONFIG_BT_GATT_SERVICE_CHANGED=y

#
CONFIG_BT_SMP_APP_PAIRING_ACCEPT=y

#########################################################################
# FOTA
# Enable mcumgr.
CONFIG_MCUMGR=y

# Enable most core commands.
CONFIG_MCUMGR_CMD_IMG_MGMT=y
CONFIG_MCUMGR_CMD_OS_MGMT=y

# Ensure an MCUboot-compatible binary is generated.
CONFIG_BOOTLOADER_MCUBOOT=y


##################
# Allow for large Bluetooth data packets.
#CONFIG_BT_L2CAP_TX_MTU=252
#CONFIG_BT_BUF_ACL_RX_SIZE=256

# Enable the Bluetooth (unauthenticated) and shell mcumgr transports.
CONFIG_MCUMGR_SMP_BT=y
CONFIG_MCUMGR_SMP_BT_AUTHEN=n

# Some command handlers require a large stack.
CONFIG_SYSTEM_WORKQUEUE_STACK_SIZE=4096
#CONFIG_SYSTEM_WORKQUEUE_STACK_SIZE=2048
#########################################################################

8. Is there a specific sample ...
As I mentioned, I use peripheral_uart with custom UUID. 
I could reproduce this issue with original sample peripheral_uart with
adding two lines when connected.
bt_set_bondable(true);
bt_conn_set_security(conn, BT_SECURITY_L4);

9. What SDK version ..
As I mentioned, I use NCS 2.0.0

-------------------------------------------------------------------------------------
We should provide MTK an air log to show their error. Then we can close this case.
Thanks!

[Tim Hwang]

I review Bluetooth core spec 5.3 regarding LE pairing sequence.

As I mentioned, MTK(Android) connect my project (Nordic), Nordic send security request when connected. (My project requires secure connection).

sf650_error_03Nov2022.pcapng

But Nordic did not send "pairing response" And send "time out error" (7 seconds  later after connected)
Where is from "hci status value 0x1f" ? Is it from MTK?
Can you please explain it? Without it, we cannot go proceed.

00> HS connected
00> HS Connected 00:16:7F:40:1E:D0 (public)
00> D:
00> D: 00:16:7F:40:1E:D0 (public)
00> D: prnd 7d93ec3b4828ce3b4210d054f903653a
00> D: chan 0x20001f54 cid 0x0006
00> D: status 0x8
00> D: chan 0x20001f54 conn 0x20001c90 handle 0 encrypt 0x00 hci status 0x1f
00> Security failed: 00:16:7F:40:1E:D0 (public) level 1 err 9

[Hieu]

Hi Tim,

Tim Hwang said:

5. Pairing at Security Level 4 like you are trying to do also require an out of band verification method. On your RTT log I don't see signs of this happened. What did you do to achieve this?
-> I cannot understand "out of band verification method".

I mean an exchange of passkey or NFC tag scan. Basically, it is a non-BLE channel to show the devices involved that they are talking to the right device, and to prevent MITM attacks.
In your videos, I see you are already using the passkey method.

The passkey check seems to pass very quick in your OKAY video.
But in your NG video it also quite quickly fails.
How do you enter the passkey in your device?

To pinpoint whether the passkey exchange is the problem, could you switch to using Just Works pairing following the steps discussed in this DevZone quesion:  Allow LESC "Just Works" Pairing/Bonding with NRF Connect SDK (Zephyr) after pressing Button 

Please let me know if it works.

Tim Hwang said:

6. "chan 0x20001f4c conn 0x20001c88 handle 0 encrypt 0x00 hci status 0x1f"
You though it's normal. But, in smp.c if hci_status is not zero, it is error. (please see hci_err.h)

Tim Hwang said:

Where is from "hci status value 0x1f" ? Is it from MTK?
Can you please explain it? Without it, we cannot go proceed.

You are right that it is indicative of an error. I'm sorry about missing the bad hci_status.

As you can already see, the error state name is not very descriptive. I will need more time to check on this.
What I can tell you now is that it most likely comes from the internal working of the HCI layer in the nRF device. What triggers the device to go into this state is the part that need more investigation.

Tim Hwang said:

We should provide MTK an air log to show their error. Then we can close this case.

Nothing in the sniffer trace indicates what is wrong yet, unfortunately.

It seems encrypted message of the pairing exchange was not there.

Could you capture one more time following the guide on this page. We need to see the pairing packages if we want to analyze through the sniffer trace.

https://infocenter.nordicsemi.com/index.jsp?topic=%2Fug_sniffer_ble%2FUG%2Fsniffer_ble%2Faction_paired.html

Best regards,

Hieu

[Tim Hwang]

Hello Hieu.

1. NFC
I could reproduce this issue without NFC tagging. Let's discuss later. It is not root reason; I think.

2. Just works (key exchange)
1)We do need authenticated/LE secure connection. let's discuss later as well.
If Key exchange is a matter, we always see this issue. But it is not. What do you think about that?

2) Here is pairing sequence in success case.

Here is failure case.
Nordic sent security request.
MTK sent "Pairing request", but Nordic did not send "Pairing response" 
No "Pairing response", No user confirmation.




3. "hci status value 0x1f"
Let's focus it first. I believe you can give me any explanation.
then I'll forward it to MTK.

[Tim Hwang]

I test again with more log option.

1. Pairing request was received after 5 seconds.

2. RTT log at failure log.

00> [00:01:02.722,015] <dbg> bt_hci_core: bt_recv: buf 0x2000ca88 len 33
00> [00:01:02.722,381] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
00> [00:01:02.722,412] <dbg> bt_hci_core: rx_work_handler: buf 0x2000ca88 type 1 len 33
00> [00:01:02.722,412] <dbg> bt_hci_core: hci_event: event 0x3e
00> [00:01:02.722,442] <dbg> bt_hci_core: hci_le_meta_event: subevent 0x0a
00> [00:01:02.722,869] <dbg> bt_hci_core: bt_hci_le_enh_conn_complete: bt_hci_le_enh_conn_complete status 0x00 handle 0 role 1 peer 47:95:91:6C:DF:D7 (random) peer RPA 00:00:00:00:00:00
00> [00:01:02.723,052] <dbg> bt_hci_core: bt_hci_le_enh_conn_complete: local RPA 00:00:00:00:00:00
00> [00:01:02.723,297] <dbg> bt_keys: bt_keys_find_irk: 47:95:91:6C:DF:D7 (random)
00> [00:01:02.723,541] <dbg> bt_keys: bt_keys_find_irk: No IRK for 47:95:91:6C:DF:D7 (random)
00> [00:01:02.723,602] <dbg> bt_conn: bt_conn_ref: handle 0 ref 1 -> 2
00> [00:01:02.723,632] <dbg> bt_conn: bt_conn_unref: handle 0 ref 2 -> 1
00> [00:01:02.723,663] <dbg> bt_conn: bt_conn_ref: handle 0 ref 1 -> 2
00> [00:01:02.723,724] <dbg> bt_adv: bt_le_adv_resume: Host cannot resume connectable advertising (-12)
00> [00:01:02.723,754] <dbg> bt_conn: bt_conn_set_state: connecting-adv -> connected
00> [00:01:02.723,785] <dbg> bt_l2cap: l2cap_accept: conn 0x20005870 handle 0
00> [00:01:02.723,846] <dbg> bt_l2cap: bt_l2cap_chan_add: conn 0x20005870 chan 0x20006174
00> [00:01:02.723,876] <dbg> bt_l2cap: l2cap_connected: ch 0x20006174 cid 0x0005
00> [00:01:02.723,876] <dbg> bt_smp: bt_smp_accept: bt_smp_accept 5811 conn 0x20005870 handle 0
00> [00:01:02.723,907] <dbg> bt_l2cap: bt_l2cap_chan_add: conn 0x20005870 chan 0x20005b2c
00> [00:01:02.723,907] <dbg> bt_smp: bt_smp_connected: bt_smp_connected: chan 0x20005b2c cid 0x0006
00> [00:01:02.724,029] <dbg> bt_l2cap: bt_l2cap_chan_add: conn 0x20005870 chan 0x2000c124
00> [00:01:02.724,273] <dbg> bt_keys: bt_keys_find_addr: 47:95:91:6C:DF:D7 (random)
00> [00:01:02.724,395] <dbg> bt_smp: smp_send_security_req: smp_send_security_req enter
00> [00:01:02.724,639] <dbg> bt_keys: bt_keys_get_addr: 47:95:91:6C:DF:D7 (random)
00> [00:01:02.724,884] <dbg> bt_keys: bt_keys_get_addr: created 0x20006274 for 47:95:91:6C:DF:D7 (random)
00> [00:01:02.725,006] <dbg> bt_hci_core: process_events: count 2
00> [00:01:02.725,067] <dbg> bt_hci_core: process_events: ev->state 0
00> [00:01:02.725,097] <dbg> bt_hci_core: process_events: ev->state 1
00> [00:01:02.725,128] <dbg> bt_conn: bt_conn_prepare_events: bt_conn_prepare_events
00> [00:01:02.725,189] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20005870 to poll list
00> [00:01:02.725,219] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
00> [00:01:02.725,494] <dbg> bt_smp: smp_init: smp_init prnd c4ab98dceec5db2f0c4f768e84dcd8be
00> [00:01:02.725,585] <dbg> bt_l2cap: bt_l2cap_send_cb: conn 0x20005870 cid 6 len 2
00> [00:01:02.725,616] <dbg> bt_conn: bt_conn_send_cb: conn handle 0 buf len 6 cb (nil) user_data (nil)
00> [00:01:02.725,708] <dbg> bt_smp: smp_send_security_req: smp_send_security_req exit
00> [00:01:02.725,952] <inf> peripheral_uart: ####Connected 47:95:91:6C:DF:D7 (random)
00> [00:01:02.725,952] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
00> [00:01:02.725,982] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x2016 param_len 2
00> [00:01:02.726,043] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x2000cba0
00> [00:01:02.726,074] <dbg> bt_hci_core: bt_hci_cmd_send_sync: buf 0x2000cba0 opcode 0x2016 len 5
00> [00:01:02.726,165] <dbg> bt_hci_core: process_events: count 3
00> [00:01:02.726,165] <dbg> bt_hci_core: process_events: ev->state 4
00> [00:01:02.726,196] <dbg> bt_hci_core: send_cmd: calling net_buf_get
00> [00:01:02.726,196] <dbg> bt_hci_core: send_cmd: calling sem_take_wait
00> [00:01:02.726,226] <dbg> bt_hci_core: send_cmd: Sending command 0x2016 (buf 0x2000cba0) to driver
00> [00:01:02.726,287] <dbg> bt_hci_core: bt_send: buf 0x2000cba0 len 5 type 0
00> [00:01:02.726,348] <dbg> bt_hci_core: process_events: ev->state 0
00> [00:01:02.726,348] <dbg> bt_hci_core: process_events: ev->state 4
00> [00:01:02.726,409] <dbg> bt_conn: bt_conn_process_tx: conn 0x20005870
00> [00:01:02.726,440] <dbg> bt_conn: send_buf: conn 0x20005870 buf 0x2000cbd8 len 6
00> [00:01:02.726,470] <dbg> bt_conn: send_frag: conn 0x20005870 buf 0x2000cbd8 len 6 flags 0x02
00> [00:01:02.726,470] <dbg> bt_hci_core: bt_send: buf 0x2000cbd8 len 10 type 2
00> [00:01:02.726,654] <dbg> bt_hci_core: bt_recv: buf 0x2000cba0 len 6
00> [00:01:02.726,684] <dbg> bt_hci_core: hci_cmd_status: opcode 0x2016
00> [00:01:02.726,684] <dbg> bt_hci_core: hci_cmd_done: opcode 0x2016 status 0x00 buf 0x2000cba0
00> [00:01:02.726,959] <dbg> bt_conn: bt_conn_prepare_events: bt_conn_prepare_events
00> [00:01:02.727,020] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20005870 to poll list
00> [00:01:02.727,050] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
00> [00:01:02.727,081] <dbg> bt_hci_core: bt_hci_cmd_send_sync: rsp 0x2000cba0 opcode 0x2016 len 0
00> [00:01:02.727,142] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x2032 param_len 7
00> [00:01:02.727,172] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x2000cba0
00> [00:01:02.727,203] <dbg> bt_hci_core: bt_hci_cmd_send_sync: buf 0x2000cba0 opcode 0x2032 len 10
00> [00:01:02.727,294] <dbg> bt_hci_core: process_events: count 3
00> [00:01:02.727,325] <dbg> bt_hci_core: process_events: ev->state 4
00> [00:01:02.727,325] <dbg> bt_hci_core: send_cmd: calling net_buf_get
00> [00:01:02.727,386] <dbg> bt_hci_core: send_cmd: calling sem_take_wait
00> [00:01:02.727,416] <dbg> bt_hci_core: send_cmd: Sending command 0x2032 (buf 0x2000cba0) to driver
00> [00:01:02.727,416] <dbg> bt_hci_core: bt_send: buf 0x2000cba0 len 10 type 0
00> [00:01:02.727,539] <dbg> bt_hci_core: process_events: ev->state 0
00> [00:01:02.727,539] <dbg> bt_hci_core: process_events: ev->state 0
00> [00:01:02.727,630] <dbg> bt_hci_core: bt_recv: buf 0x2000cba0 len 6
00> [00:01:02.727,661] <dbg> bt_hci_core: hci_cmd_status: opcode 0x2032
00> [00:01:02.727,661] <dbg> bt_hci_core: hci_cmd_done: opcode 0x2032 status 0x00 buf 0x2000cba0
00> [00:01:02.727,935] <dbg> bt_conn: bt_conn_prepare_events: bt_conn_prepare_events
00> [00:01:02.727,996] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20005870 to poll list
00> [00:01:02.728,027] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
00> [00:01:02.728,057] <dbg> bt_hci_core: bt_hci_cmd_send_sync: rsp 0x2000cba0 opcode 0x2032 len 0
00> [00:01:02.728,149] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
00> [00:01:06.699,066] <dbg> bt_hci_core: bt_recv: buf 0x2000ca18 len 7
00> [00:01:06.699,096] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1
00> [00:01:06.699,127] <dbg> bt_hci_core: hci_num_completed_packets: handle 0 count 1
00> [00:01:06.699,127] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
00> [00:01:06.699,340] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
00> [00:01:06.943,115] <dbg> bt_hci_core: bt_recv: buf 0x2000ca88 len 15
00> [00:01:06.943,389] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
00> [00:01:06.943,450] <dbg> bt_hci_core: rx_work_handler: buf 0x2000ca88 type 3 len 15
00> [00:01:06.943,450] <dbg> bt_hci_core: hci_acl: buf 0x2000ca88
00> [00:01:06.943,481] <dbg> bt_hci_core: hci_acl: handle 0 len 11 flags 2
00> [00:01:06.943,511] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
00> [00:01:06.943,572] <dbg> bt_conn: tx_notify: conn 0x20005870
00> [00:01:06.943,603] <dbg> bt_conn: bt_conn_recv: handle 0 len 11 flags 02
00> [00:01:06.943,603] <dbg> bt_conn: bt_acl_recv: First, len 11 final 7
00> [00:01:06.943,634] <dbg> bt_conn: bt_acl_recv: Successfully parsed 11 byte L
00> [00:01:10.160,369] <dbg> bt_hci_core: bt_recv: buf 0x2000ca88 len 15
00> [00:01:10.160,827] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
00> [00:01:10.160,827] <dbg> bt_hci_core: rx_work_handler: buf 0x2000ca88 type 3 len 15
00> [00:01:10.160,888] <dbg> bt_hci_core: hci_acl: buf 0x2000ca88
00> [00:01:10.160,919] <dbg> bt_hci_core: hci_acl: handle 0 len 11 flags 2
00> [00:01:10.160,919] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
00> [00:01:10.160,949] <dbg> bt_conn: tx_notify: conn 0x20005870
00> [00:01:10.160,949] <dbg> bt_conn: bt_conn_recv: handle 0 len 11 flags 02
00> [00:01:10.161,010] <dbg> bt_conn: bt_acl_recv: First, len 11 final 7
00> [00:01:10.161,041] <dbg> bt_conn: bt_acl_recv: Successfully parsed 11 byte L2CAP packet
00> [00:01:10.161,041] <dbg> bt_l2cap: bt_l2cap_recv: Packet for CID 6 len 7
00> [00:01:10.161,071] <dbg> bt_l2cap: l2cap_chan_recv: chan 0x20005b2c len 7
00> [00:01:10.161,132] <dbg> bt_smp: bt_smp_recv: Received SMP code 0x01 len 6
00> [00:01:10.161,163] <dbg> bt_smp: smp_pairing_req: smp_pairing_req
00> [00:01:10.161,163] <dbg> bt_smp: smp_pairing_req: smp_pairing_req #2
00> [00:01:10.161,193] <dbg> bt_smp: smp_pairing_req: smp_pairing_req #3
00> [00:01:10.161,224] <dbg> bt_smp: smp_pairing_req: smp_pairing_req #4
00> [00:01:10.161,285] <dbg> bt_smp: smp_pairing_req: smp_pairing_req #5
00> [00:01:10.161,285] <dbg> bt_smp: smp_pairing_req: smp_pairing_req #6
00> [00:01:10.161,285] <dbg> bt_smp: smp_pairing_req: smp_pairing_req #7
00> [00:01:10.161,315] <dbg> bt_smp: send_pairing_rsp: send_pairing_rsp enter
00> [00:01:10.161,376] <dbg> bt_l2cap: bt_l2cap_send_cb: conn 0x20005870 cid 6 len 7
00> [00:01:10.161,407] <dbg> bt_conn: bt_conn_send_cb: conn handle 0 buf len 11 cb (nil) user_data (nil)
00> [00:01:10.161,437] <dbg> bt_smp: send_pairing_rsp: send_pairing_rsp exit
00> [00:01:10.161,529] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
00> [00:01:10.161,560] <dbg> bt_hci_core: process_events: count 3
00> [00:01:10.161,560] <dbg> bt_hci_core: process_events: ev->state 0
00> [00:01:10.161,621] <dbg> bt_hci_core: process_events: ev->state 0
00> [00:01:10.161,651] <dbg> bt_hci_core: process_events: ev->state 4
00> [00:01:10.161,651] <dbg> bt_conn: bt_conn_process_tx: conn 0x20005870
00> [00:01:10.161,682] <dbg> bt_conn: send_buf: conn 0x20005870 buf 0x2000cbd8 len 11
00> [00:01:10.161,712] <dbg> bt_conn: send_frag: conn 0x20005870 buf 0x2000cbd8 len 11 flags 0x02
00> [00:01:10.161,773] <dbg> bt_hci_core: bt_send: buf 0x2000cbd8 len 15 type 2
00> [00:01:10.161,865] <dbg> bt_conn: bt_conn_prepare_events: bt_conn_prepare_events
00> [00:01:10.161,895] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20005870 to poll list
00> [00:01:10.161,895] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
00> [00:01:11.915,283] <dbg> bt_hci_core: bt_recv: buf 0x2000ca18 len 7
00> [00:01:11.915,313] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1
00> [00:01:11.915,466] <dbg> bt_hci_core: hci_num_completed_packets: handle 0 count 1
00> [00:01:11.915,496] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
00> [00:01:11.915,527] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
00> [00:01:11.915,771] <dbg> bt_hci_core: bt_recv: buf 0x2000ca88 len 6
00> [00:01:11.915,771] <dbg> bt_hci_core: hci_disconn_complete_prio: hci_disconn_complete_prio status 0x00 handle 0 reason 0x28
00> [00:01:11.915,832] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
00> [00:01:11.915,863] <dbg> bt_conn: bt_conn_set_state: connected -> disconnect-complete
00> [00:01:11.915,893] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
00> [00:01:11.916,137] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
00> [00:01:11.916,229] <dbg> bt_hci_core: rx_work_handler: buf 0x2000ca88 type 1 len 6
00> [00:01:11.916,229] <dbg> bt_hci_core: hci_event: event 0x05
00> [00:01:11.916,259] <dbg> bt_hci_core: hci_disconn_complete: status 0x00 handle 0 reason 0x28
00> [00:01:11.916,259] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
00> [00:01:11.916,320] <dbg> bt_conn: bt_conn_set_state: disconnect-complete -> disconnected
00> [00:01:11.916,351] <dbg> bt_conn: tx_notify: conn 0x20005870
00> [00:01:11.916,381] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
00> [00:01:11.916,473] <dbg> bt_hci_core: process_events: count 3
00> [00:01:11.916,503] <dbg> bt_hci_core: process_events: ev->state 0
00> [00:01:11.916,503] <dbg> bt_hci_core: process_events: ev->state 1
00> [00:01:11.916,503] <dbg> bt_hci_core: process_events: ev->state 0
00> [00:01:11.916,595] <dbg> bt_conn: bt_conn_prepare_events: bt_conn_prepare_events
00> [00:01:11.916,625] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 2 events
00> [00:01:11.916,717] <dbg> bt_conn: deferred_work: conn 0x20005870
00> [00:01:11.916,748] <dbg> bt_l2cap: bt_l2cap_chan_del: conn 0x20005870 chan 0x20006174
00> [00:01:11.916,748] <dbg> bt_l2cap: l2cap_disconnected: ch 0x20006174 cid 0x0005
00> [00:01:11.916,809] <dbg> bt_l2cap: bt_l2cap_chan_del: conn 0x20005870 chan 0x20005b2c
00> [00:01:11.916,839] <dbg> bt_smp: bt_smp_disconnected: bt_smp_disconnected chan 0x20005b2c cid 0x0006
00> [00:01:11.916,839] <dbg> bt_smp: smp_pairing_complete: smp.c 1863 status 0x8
00> [00:01:11.917,083] <dbg> bt_keys: bt_keys_clear: 47:95:91:6C:DF:D7 (random) (keys 0x0000)
00> [00:01:11.917,358] <dbg> bt_keys: bt_keys_clear: Deleting key bt/keys/4795916cdfd71
00> [00:01:11.917,449] <dbg> bt_conn: bt_conn_security_changed: conn.c #1 1986 hci_err(0x1f) bt_security_err(9)
00> [00:01:11.917,480] <dbg> bt_l2cap: bt_l2cap_security_changed: l2cap.c #1 hci_status(1f)
00> [00:01:11.917,510] <dbg> bt_smp: bt_smp_encrypt_change: chan 0x20005b2c conn 0x20005870 handle 0 encrypt 0x00 hci status 0x1f
00> [00:01:11.917,785] <wrn> peripheral_uart: Security failed: 47:95:91:6C:DF:D7 (random) level 1 err 9
00> [00:01:11.918,029] <inf> peripheral_uart: Pairing failed conn: 47:95:91:6C:DF:D7 (random), reason 9
00> [00:01:11.918,273] <dbg> bt_keys: bt_keys_clear: 00:00:00:00:00:00 (public) (keys 0x0000)
00> [00:01:11.918,518] <dbg> bt_keys: bt_keys_clear: Deleting key bt/keys/0000000000000
00> [00:01:11.918,670] <dbg> bt_l2cap: bt_l2cap_chan_del: conn 0x20005870 chan 0x2000c124
00> [00:01:11.919,006] <dbg> bt_keys: bt_keys_find_addr: 47:95:91:6C:DF:D7 (random)
00> [00:01:11.919,250] <dbg> bt_keys: bt_keys_find_addr: 47:95:91:6C:DF:D7 (random)
00> [00:01:11.919,525] <inf> peripheral_uart: Disconnected: 47:95:91:6C:DF:D7 (random) (reason 40)
00> [00:01:11.919,525] <dbg> bt_conn: bt_conn_unref: handle 0 ref 2 -> 1
00> [00:01:11.919,555] <dbg> bt_conn: bt_conn_unref: handle 0 ref 1 -> 0
00> [00:01:11.919,616] <dbg> bt_conn: bt_conn_unref: -bt_le_adv_resume
00> [00:01:11.919,677] <dbg> bt_conn: bt_conn_set_state: disconnected -> connecting-adv
00> [00:01:11.919,677] <dbg> bt_conn: bt_conn_ref: handle 0 ref 1 -> 2
00> [00:01:11.919,738] <dbg> bt_adv: bt_le_adv_resume: Resuming connectable advertising
00> [00:01:11.919,769] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x200a param_len 1
00> [00:01:11.919,799] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x2000cba0
00> [00:01:11.919,799] <dbg> bt_hci_core: bt_hci_cmd_send_sync: buf 0x2000cba0 opcode 0x200a len 4
00> [00:01:11.919,921] <dbg> bt_hci_core: process_events: count 2
00> [00:01:11.919,921] <dbg> bt_hci_core: process_events: ev->state 4
00> [00:01:11.919,982] <dbg> bt_hci_core: send_cmd: calling net_buf_get
00> [00:01:11.920,013] <dbg> bt_hci_core: send_cmd: calling sem_take_wait
00> [00:01:11.920,013] <dbg> bt_hci_core: send_cmd: Sending command 0x200a (buf 0x2000cba0) to driver
00> [00:01:11.920,043] <dbg> bt_hci_core: bt_send: buf 0x2000cba0 len 4 type 0
00> [00:01:11.920,288] <dbg> bt_hci_core: process_events: ev->state 0
00> [00:01:11.920,379] <dbg> bt_hci_core: bt_recv: buf 0x2000cba0 len 6
00> [00:01:11.920,410] <dbg> bt_hci_core: hci_cmd_complete: opcode 0x200a
00> [00:01:11.920,410] <dbg> bt_hci_core: hci_cmd_done: opcode 0x200a status 0x00 buf 0x2000cba0
00> [00:01:11.920,715] <dbg> bt_conn: bt_conn_prepare_events: bt_conn_prepare_events
00> [00:01:11.920,745] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 2 events
00> [00:01:11.920,776] <dbg> bt_hci_core: bt_hci_cmd_send_sync: rsp 0x2000cba0 opcode 0x200a len 1
00> [00:01:11.920,837] <dbg> bt_conn: bt_conn_unref: handle 0 ref 2 -> 1

It seems Pairing response was sent but Android did not receive it.
Can you please review rtt log?

[Hieu]

Hi Tim,

Tim Hwang said:

1. NFC
I could reproduce this issue without NFC tagging. Let's discuss later. It is not root reason; I think.

You misunderstood. I mentioned NFC as an example of an out-of-band (OOB) verification method. NFC should not be the problem here.

Tim Hwang said:

If Key exchange is a matter, we always see this issue. But it is not. What do you think about that?

The problem is exactly that: I don't know what to think about that.

Please take a look back at your videos. What I see are

- Incorrect passkey error message from the "not-good" video.
- Passkey pop-up in the "okay" video
- Very short time between passkey pop-up and the connection is made in the "okay" video. Too short for actual passkey to be entered by a normal human.

The combination of those makes no sense at all.

That is why I hope a sniffer log containing the encrypted pairing packets would help me see what is wrong here.

I might guess that your Android device asks for passkey, but doesn't handle the passkey well, sometime consider "no" passkey as good, sometime doesn't. Without a sniffer, I can't be sure.

Therefore, if possible, please look into getting me that sniffer log with the pairing procedure. Preferably one of a success case, and one of a failure case.

I will look at your RTT log Tue and Wed. Unfortunately, I am partially out of office both days, so my follow-up might be delayed until end of Thursday.

Best regards,

Hieu