ATT assertion fail when subscribing to characteristic using nRF9160 as central

[Fredrik]

Hi,

I'm writing a central application for the nRF9160 DK. The central connects to an nRF52832 peripheral and subscribes to a characteristic whose CCCD handle and value handle is known prior to connecting. It does not perform service discovery. In the connected callback, where the BLE examples normally perform service discovery, I perform a call to bt_gatt_subscribe like this:

    static struct bt_gatt_subscribe_params param = {
        .notify       = on_notification_received,
        .value        = BT_GATT_CCC_NOTIFY,
        .ccc_handle   = 0x002E,
        .value_handle = 0x002D
    };
    
    int err = bt_gatt_subscribe(conn, &param);
    if (err) {
        printk("Subscribe failed (err %d)\n", err);
    }

In the peripheral, I see the central connecting and subscribing without issues. Shortly after writing the CCCD, The nRF9160 fails an assert:

[00:00:06.259,887] <dbg> bt_att.bt_att_accept: conn 0x200209c0 handle 0
[00:00:06.267,120] <dbg> bt_att.bt_att_connected: chan 0x20020b14 cid 0x0004
[00:00:06.281,982] <dbg> bt_att.bt_att_req_send: conn 0x200209c0 req 0x20036fcc
[00:00:07.457,641] <dbg> bt_att.att_send_req: req 0x20036fcc
[00:00:07.471,984] <dbg> bt_att.bt_att_req_send: conn 0x200209c0 req 0x20036fcc
[00:00:07.480,438] <dbg> bt_att.bt_att_recv: Received ATT code 0x02 len 2
[00:00:07.487,792] <dbg> bt_att.att_mtu_req: Client MTU 185
[00:00:07.493,927] <dbg> bt_att.att_mtu_req: Server MTU 23
[00:00:07.499,969] <dbg> bt_att.att_mtu_req: Negotiated MTU 23
[00:00:07.562,042] <dbg> bt_att.att_req_sent: conn 0x200209c0 att 0x20020b14 att->req 0x20036fcc
[00:00:07.571,411] <dbg> bt_att.att_pdu_sent: conn 0x200209c0 att 0x20020b14
[00:00:07.611,907] <dbg> bt_att.att_rsp_sent: conn 0x200209c0 att 0x20020b14
[00:00:07.619,537] <dbg> bt_att.att_pdu_sent: conn 0x200209c0 att 0x20020b14
[00:00:07.627,319] <dbg> bt_att.bt_att_recv: Received ATT code 0x13 len 0
[00:00:07.634,674] <dbg> bt_att.att_handle_write_rsp: 
[00:00:07.640,350] <dbg> bt_att.att_handle_rsp: err 0x00 len 0: 
[00:00:07.646,942] <dbg> bt_att.att_req_destroy: req 0x20036fcc
[00:00:07.653,411] <dbg> bt_att.att_process: 
ASSERTION FAIL [req->func] @ <zephyr sdk>/subsys/bluetooth/host/att.c:301
[00:00:06.108,734] <err> os: r0/a1:  0x00000004  r1/a2:  0x0000012d  r2/a3:  0x00000001
[00:00:06.117,584] <err> os: r3/a4:  0x00011069 r12/ip:  0x000003e8 r14/lr:  0x00016991
[00:00:06.126,434] <err> os:  xpsr:  0x61000000
[00:00:06.131,774] <err> os: s[0]:  0x00000000  s[1]:  0x00000000  s[2]:  0x00000000  s[3]:  0x00000000
[00:00:06.142,150] <err> os: s[4]:  0x00000000  s[5]:  0x00000000  s[6]:  0x00000000  s[7]:  0x00000000
[00:00:06.152,526] <err> os: s[8]:  0x00000000  s[9]:  0x00000000  s[10]:  0x00000000  s[11]:  0x00000000
[00:00:06.163,116] <err> os: s[12]:  0x00000000  s[13]:  0x00000000  s[14]:  0x00000000  s[15]:  0x00000000
[00:00:06.173,858] <err> os: fpscr:  0x00000000
[00:00:06.179,260] <err> os: Faulting instruction address (r15/pc): 0x0002ee10
[00:00:06.187,316] <err> os: >>> ZEPHYR FATAL ERROR 4: Kernel panic
[00:00:06.194,396] <err> os: Current thread: 0x20026884 (unknown)
[00:00:06.201,293] <err> os: Halting system

When stepping through the code, I see that att_send_req() is called twice, and __ASSERT_NO_MSG(req->func) fails the second time around. This is the call stack just before the assert fails:

att_send_req@0x00016974 (<zephyr sdk>/subsys/bluetooth/host/att.c:301)
att_process@0x00016b06 (<zephyr sdk>/subsys/bluetooth/host/att.c:335)
att_handle_rsp@0x00016b06 (<zephyr sdk>/subsys/bluetooth/host/att.c:379)
bt_att_recv@0x00017470 (<zephyr sdk>/subsys/bluetooth/host/att.c:1979)
l2cap_chan_recv@0x0002fc58 (<zephyr sdk>/subsys/bluetooth/host/l2cap.c:1664)
l2cap_rx_process@0x0002fc58 (<zephyr sdk>/subsys/bluetooth/host/l2cap.c:274)
z_work_q_main@0x0002ea94 (<zephyr sdk>/lib/os/work_q.c:32)
z_thread_entry@0x0002ea5c (<zephyr sdk>/lib/os/thread_entry.c:29)
z_thread_entry@0x0002ea5c (<zephyr sdk>/lib/os/thread_entry.c:29)
??@0xe8040000 (Unknown Source:0)

This is my prj.conf for those interested:

CONFIG_NEWLIB_LIBC=y
CONFIG_ASSERT=y
CONFIG_REBOOT=y
CONFIG_LOG=y
CONFIG_LOG_IMMEDIATE=y
CONFIG_HW_STACK_PROTECTION=y
CONFIG_STACK_SENTINEL=y

# Network
CONFIG_NETWORKING=y
CONFIG_NET_NATIVE=n
CONFIG_NET_SOCKETS=y
CONFIG_NET_SOCKETS_OFFLOAD=y
CONFIG_NET_SOCKETS_POSIX_NAMES=y
CONFIG_SNTP=y
CONFIG_SNTP_LOG_LEVEL_DBG=n
CONFIG_NET_LOG=n

# LTE link control
CONFIG_LTE_LINK_CONTROL=y
CONFIG_LTE_LINK_CONTROL_LOG_LEVEL_DBG=n

# LTE network configuration
CONFIG_LTE_AUTO_INIT_AND_CONNECT=n
CONFIG_LTE_NETWORK_USE_FALLBACK=y
CONFIG_LTE_NETWORK_TIMEOUT=120

# AT stuff
CONFIG_AT_HOST_LIBRARY=y
CONFIG_AT_CMD=y
CONFIG_AT_CMD_LOG_LEVEL_DBG=n

# Modem info
CONFIG_MODEM_INFO=n

# BSD library
CONFIG_BSD_LIBRARY=y

# Disable Modem traces, since we need UART1 for HCI
CONFIG_BSD_LIBRARY_TRACE_ENABLED=n

# Enable Bluetooth stack, libraries and UART
CONFIG_BT=y
CONFIG_BT_H4=y
CONFIG_BT_WAIT_NOP=y
CONFIG_BT_CENTRAL=y
CONFIG_BT_GATT_CLIENT=y
CONFIG_BT_GATT_DM=y
CONFIG_BT_SCAN=y
CONFIG_BT_SCAN_FILTER_ENABLE=y
CONFIG_BT_SCAN_UUID_CNT=1
CONFIG_UART_2_NRF_UARTE=y
CONFIG_UART_2_NRF_FLOW_CONTROL=y
CONFIG_UART_INTERRUPT_DRIVEN=y
CONFIG_BT_RX_STACK_SIZE=16384
CONFIG_BT_HCI_TX_STACK_SIZE=16384
CONFIG_BT_DEBUG_LOG=y
CONFIG_BT_DEBUG_ATT=y

# Heap and stacks
CONFIG_HEAP_MEM_POOL_SIZE=16384
CONFIG_MAIN_STACK_SIZE=16384

I posted this on the Zephyr slack channel and was suggested to post here as well, in case this is an issue that has been fixed in Zephyr master but not in Nordic's fork. I'm on NCS v2.0.99-ncs1. I know this is a strange use-case (subscribing without service discovery), but I don't see any reason it would not work. The same procedure works on the nRF SDK v15.0.0.

EDIT: If i perform service discovery after connecting and subscribe from the discovery_completed callback using the same hard-coded handles, the assert does not fail.

Any help is appreciated!

[Simon]

Could you upload the code? Then I can try to reproduce the issue and get to the bottom of it. I can make the ticket private if you would like to?

You may experience delayed answers since huge parts of the support team are on vacation. Most of the staff will be back 2 of January, and you'll get help then.

Best regards,

Simon

[Fredrik]

Hi Simon,

I'm attaching an altered version of my nRF9160 code that works with the HRS example from nRF SDK v15.2 on PCA10040. If you look in the file "project_stripped/src/ble.c", I've declared a boolean called "do_discover". When set to true, the nRF9160 performs service discovery and then subscribes to hard-coded ccc_handle and value_handle (which match the handles I'm getting on my PCA10040). This should work on your end as well. When "do_discover" is false, the nRF9160 tries to subscribe inside the connected callback and fails the assertion.

Flashing a PCA10040 with the HRS sample code from SDK v15.2 and running the attached code on an nRF9160 should work, however you may need to change the hard-coded values for it to work on your end. Also, I'm using west directly on Ubuntu 18.04 for building and flashing (no SES project unfortunately), but hopefully that's not an issue.

Thanks for your help!

4628.project_stripped.zip

[Simon]

I took a look at and tested your code, and was not able to get to the bottom of it, unfortunately. I think you will get better help on the Zephyr slack channel since you will get in touch with the developers that have written the BLE software.

We don't give support for Zephyr running on nRF52 at the moment, and I am sorry for not telling you this earlier.

Best regards,

Simon

[Fredrik]

Alright, thanks. I'll ask on the zephyr slack again and post here if the problem is resolved.

[Simon]

That sound like a good idea

[Fredrik]

The Zephyr ATT was apparently rewritten a while ago, and it seems the changes made it into fw-nrfconnect-nrf v1.2.0-rc1 released just now. With the new changes, this issue has vanished!

I can finally close this thread