[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