BLE SMP OTA. Image upload command no response

[Jon_RLG]

Im currently working on BLE SMP DFU on Nordic52840DK (Connect SDK v2.7.0) based on this example:

https://github.com/hellesvik-nordic/samples_for_nrf_connect_sdk/tree/main/bootloader_samples/client_smp/smp_client_ble

the server side is using the smp_svr example.

Im able to connect and send echo commands. The echo response is received.

Unfortunately, when im sending the image response command, no response is received and the upload process is stuck.. I debugged both commands on the smp_svr and saw that the image command is valid and both times the line 

    rc = bt_gatt_notify_cb(conn, &notify_param);

is executed. But as mentioned, only the echo response is received.

Here is the Log fo the smp central after sending the image upload command:

[00:00:08.909,515] <dbg> bt_att: bt_att_sent: chan 0x20009a80

--- 34 messages dropped ---

[00:00:08.909,545] <dbg> bt_att: chan_rebegin_att_timeout: chan 0x20009a80 chan->req 0x2000d160

[00:00:08.909,576] <dbg> bt_conn: bt_conn_prepare_events:

--- 79 messages dropped ---

[00:00:08.937,316] <dbg> bt_conn: do_send_frag: conn 0x200023c8 buf 0x2000c42c len 27 flags 0x01

[00:00:08.937,347] <dbg> bt_hci_core: bt_send: buf 0x2000c42c len 31 type 2

[00:00:08.937,377] <dbg> bt_sdc_hci_driver: hci_driver_send:

[00:00:08.937,408] <dbg> bt_sdc_hci_driver: acl_handle:

[00:00:08.937,438] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0

[00:00:08.937,469] <dbg> bt_conn: send_buf: last frag

[00:00:08.937,500] <dbg> bt_conn: do_send_frag: conn 0x200023c8 buf 0x2000d0b8 len 6 flags 0x03

--- 13 messages dropped ---

[00:00:08.937,835] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events

[00:00:08.937,866] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue

[00:00:08.937,896] <dbg> bt_hci_core: rx_work_handler: buf 0x2000bd6c type 3 len 9

[00:00:08.937,927] <dbg> bt_hci_core: hci_acl: buf 0x2000bd6c

[00:00:08.937,957] <dbg> bt_hci_core: hci_acl: handle 0 len 5 flags 2

--- 3 messages dropped ---

[00:00:08.985,504] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x2000bf50 len 7

[00:00:08.985,534] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1

[00:00:08.985,534] <dbg> bt_hci_core: hci_num_completed_packets: handle 0 count 1

[00:00:08.985,565] <dbg> bt_conn: bt_conn_ref: handle 0 ref 3 -> 4

[00:00:08.985,595] <dbg> bt_conn: bt_conn_unref: handle 0 ref 4 -> 3

[00:00:08.985,961] <dbg> bt_sdc_hci_driver: event_packet_process: Event (0x13) len 5

[00:00:08.986,022] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x2000bf50 len 7

[00:00:08.986,053] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1

[00:00:08.986,053] <dbg> bt_hci_core: hci_num_completed_packets: handle 0 count 1

[00:00:08.986,114] <dbg> bt_conn: bt_conn_ref: handle 0 ref 3 -> 4

[00:00:08.986,145] <dbg> bt_conn: bt_conn_unref: handle 0 ref 4 -> 3

[00:00:08.986,480] <dbg> bt_sdc_hci_driver: event_packet_process: Event (0x13) len 5

[00:00:08.986,511] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x2000bf50 len 7

[00:00:08.986,541] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1

[00:00:08.986,572] <dbg> bt_hci_core: hci_num_completed_packets: handle 0 count 1

[00:00:08.986,602] <dbg> bt_conn: bt_conn_ref: handle 0 ref 3 -> 4

[00:00:08.986,602] <dbg> bt_conn: bt_conn_unref: handle 0 ref 4 -> 3

[00:00:09.035,461] <dbg> bt_sdc_hci_driver: data_packet_process: Data: handle (0x00), PB(2), BC(0), len(16)

[00:00:09.035,461] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x2000bd50 len 20

[00:00:09.036,041] <dbg> bt_sdc_hci_driver: data_packet_process: Data: handle (0x00), PB(2), BC(0), len(23)

[00:00:09.036,071] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x2000bd88 len 27

Furthermore the notify_param on the smp_svr for the respone: 

And here is the same Logging after sending the sucessfully echo command:

[00:00:08.026,367] <dbg> bt_att: bt_att_sent: chan 0x20009a80

--- 33 messages dropped ---

[00:00:08.041,595] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1

--- 35 messages dropped ---

[00:00:08.041,809] <dbg> bt_hci_core: hci_num_completed_packets: handle 0 count 1

[00:00:08.041,809] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3

--- 73 messages dropped ---

[00:00:08.094,970] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events

[00:00:08.095,092] <dbg> bt_hci_core: bt_hci_cmd_send_sync: rsp 0x2000bffc opcode 0x2013 len 0

[00:00:08.095,245] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2

--- 3 messages dropped ---

[00:00:08.095,550] <dbg> bt_hci_core: hci_acl: handle 0 len 24 flags 2

[00:00:08.095,581] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3

[00:00:08.095,672] <dbg> bt_conn: wait_for_tx_work: conn 0x200023c8

[00:00:08.095,703] <dbg> bt_conn: tx_notify: conn 0x200023c8

[00:00:08.095,916] <dbg> bt_conn: wait_for_tx_work: done

[00:00:08.095,947] <dbg> bt_conn: bt_conn_recv: handle 0 len 24 flags 02

[00:00:08.096,008] <dbg> bt_conn: bt_acl_recv: First, len 24 final 20

[00:00:08.096,038] <dbg> bt_conn: bt_acl_recv: Successfully parsed 24 byte L2CAP packet

[00:00:08.096,191] <dbg> bt_l2cap: bt_l2cap_recv: Packet for CID 4 len 20

[00:00:08.096,221] <dbg> bt_l2cap: l2cap_chan_recv: chan 0x20009a84 len 20

[00:00:08.096,252] <dbg> bt_att: bt_att_recv: Received ATT chan 0x20009a80 code 0x1b len 19

[00:00:08.096,343] <dbg> bt_att: att_notify: chan 0x20009a80 handle 0x0012

[00:00:08.096,374] <dbg> bt_gatt: bt_gatt_notification: handle 0x0012 length 17

[00:00:08.096,527] <dbg> dfu_smp: notify_process: DFU SMP Response received!

DFU SMP Response received![00:00:08.096,588] <dbg> dfu_smp: notify_process: DFU SMP starting callback

Echo response part received, size: 17.

Total response received - decoding

{_"r": "Lore"}

[00:00:08.097,015] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2

[00:00:08.140,777] <dbg> bt_sdc_hci_driver: event_packet_process: Event (0x13) len 5

[00:00:08.141,052] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x2000bf50 len 7

[00:00:08.141,082] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1

[00:00:08.141,082] <dbg> bt_hci_core: hci_num_completed_packets: handle 0 count 1

[00:00:08.141,113] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3

[00:00:08.141,204] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2

[00:00:08.440,887] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x03), len (10)

[00:00:08.440,917] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x2000bd50 len 12

[00:00:08.441,101] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue

[00:00:08.441,101] <dbg> bt_hci_core: rx_work_handler: buf 0x2000bd50 type 1 len 12

[00:00:08.441,223] <dbg> bt_hci_core: hci_event: event 0x3e

[00:00:08.441,253] <dbg> bt_hci_core: hci_le_meta_event: subevent 0x03

[00:00:08.441,253] <dbg> bt_hci_core: le_conn_update_complete: status 0x00, handle 0

[00:00:08.441,375] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3

[00:00:08.441,375] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2

And the notify_params:

[Menon]

Hello,

I went through the logs you shared, and I noticed the "no controller bufs" messages. I suspect that this issue could be due to a limited number of available buffers or insufficient buffer size. Please search for CONFIG_BT_BUF in the Kconfig reference. Also, refer to this thread where my colleague is discussing a similar issue.

Kind Regards,

Abhijith

[Jon_RLG]

Hello,

thanks for your response. I have checked the CONFIG_BT_BUF and was able to get rid of the "no controller bufs" messages.

Unfortunately, the issue still exists.

Here is the Log from the smp ble client after sending the image upload cmd:

Payload legnth is: 99Sending upload cmd![00:00:08.689,483] <dbg> bt_gatt: gatt_write_ccc: handle 0x0013 value 0x0001
[00:00:08.689,514] <dbg> bt_att: bt_att_req_alloc: req 0x2000f9a0
[00:00:08.689,514] <dbg> bt_conn: bt_conn_create_pdu_timeout: Timeout discarded. No blocking in syswq.
[00:00:08.689,544] <dbg> bt_att: bt_att_req_send: conn 0x200047d0 req 0x2000f9a0
[00:00:08.689,575] <dbg> bt_att: bt_att_chan_req_send: req 0x2000f9a0
[00:00:08.689,605] <dbg> bt_att: chan_req_send: chan 0x2000c2c0 req 0x2000f9a0 len 5
[00:00:08.689,605] <dbg> bt_att: bt_att_chan_send: chan 0x2000c2c0 flags 1 code 0x12
[00:00:08.689,636] <dbg> bt_att: chan_send: code 0x12
[00:00:08.689,666] <dbg> bt_l2cap: bt_l2cap_send_cb: conn 0x200047d0 cid 4 len 5
[00:00:08.689,666] <dbg> bt_conn: bt_conn_send_cb: conn handle 0 buf len 9 cb 0 user_data 0
[00:00:08.689,727] <dbg> bt_conn: bt_conn_create_pdu_timeout: Timeout discarded. No blocking in syswq.
[00:00:08.689,758] <dbg> bt_gatt: bt_gatt_write_without_response_cb: handle 0x0012 length 107
[00:00:08.689,788] <dbg> bt_att: bt_att_chan_send: chan 0x2000c2c0 flags 1 code 0x52
[00:00:08.689,819] <dbg> bt_att: chan_send: code 0x52
[00:00:08.689,849] <dbg> bt_l2cap: bt_l2cap_send_cb: conn 0x200047d0 cid 4 len 110
[00:00:08.689,880] <dbg> bt_conn: bt_conn_send_cb: conn handle 0 buf len 114 cb 0 user_data 0
[00:00:08.689,910] <dbg> bt_hci_core: process_events: count 3
[00:00:08.689,941] <dbg> bt_hci_core: process_events: ev->state 0
[00:00:08.689,941] <dbg> bt_hci_core: process_events: ev->state 0
[00:00:08.689,971] <dbg> bt_hci_core: process_events: ev->state 4
[00:00:08.690,002] <dbg> bt_conn: bt_conn_process_tx: conn 0x200047d0
[00:00:08.690,002] <dbg> bt_conn: send_buf: conn 0x200047d0 buf 0x2000f918 len 9
[00:00:08.690,032] <dbg> bt_conn: send_buf: send single
[00:00:08.690,032] <dbg> bt_conn: do_send_frag: conn 0x200047d0 buf 0x2000f918 len 9 flags 0x02
[00:00:08.690,063] <dbg> bt_hci_core: bt_send: buf 0x2000f918 len 13 type 2
[00:00:08.690,093] <dbg> bt_sdc_hci_driver: hci_driver_send: 
[00:00:08.690,093] <dbg> bt_sdc_hci_driver: acl_handle: 
[00:00:08.690,124] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
[00:00:08.690,155] <dbg> bt_att: att_tx_destroy: 0x2000f918
[00:00:08.690,185] <dbg> bt_att: att_on_sent_cb: opcode 0x12
[00:00:08.690,185] <dbg> bt_att: att_on_sent_cb: UATT bearer, calling att_sent
[00:00:08.690,216] <dbg> bt_att: att_sent: conn 0x200047d0 chan 0x2000c2c4
[00:00:08.690,246] <dbg> bt_att: bt_att_sent: chan 0x2000c2c0
[00:00:08.690,277] <dbg> bt_att: chan_rebegin_att_timeout: chan 0x2000c2c0 chan->req 0x2000f9a0
[00:00:08.690,307] <dbg> bt_conn: bt_conn_prepare_events: 
[00:00:08.690,338] <dbg> bt_conn: conn_prepare_events: Adding conn 0x200047d0 to poll list
[00:00:08.690,368] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:00:08.690,368] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
[00:00:08.690,399] <dbg> bt_hci_core: process_events: count 3
[00:00:08.690,429] <dbg> bt_hci_core: process_events: ev->state 0
[00:00:08.690,429] <dbg> bt_hci_core: process_events: ev->state 0
[00:00:08.690,460] <dbg> bt_hci_core: process_events: ev->state 4
[00:00:08.690,460] <dbg> bt_conn: bt_conn_process_tx: conn 0x200047d0
[00:00:08.690,490] <dbg> bt_conn: send_buf: conn 0x200047d0 buf 0x2000f8f8 len 114
[00:00:08.690,521] <dbg> bt_conn: send_buf: send single
[00:00:08.690,521] <dbg> bt_conn: do_send_frag: conn 0x200047d0 buf 0x2000f8f8 len 114 flags 0x02
[00:00:08.690,551] <dbg> bt_hci_core: bt_send: buf 0x2000f8f8 len 118 type 2
[00:00:08.690,582] <dbg> bt_sdc_hci_driver: hci_driver_send: 
[00:00:08.690,582] <dbg> bt_sdc_hci_driver: acl_handle: 
[00:00:08.690,612] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
[00:00:08.690,643] <dbg> bt_att: att_tx_destroy: 0x2000f8f8
[00:00:08.690,673] <dbg> bt_att: att_on_sent_cb: opcode 0x52
[00:00:08.690,704] <dbg> bt_att: att_on_sent_cb: UATT bearer, calling att_sent
[00:00:08.690,704] <dbg> bt_att: att_sent: conn 0x200047d0 chan 0x2000c2c4
[00:00:08.690,734] <dbg> bt_att: bt_att_sent: chan 0x2000c2c0
[00:00:08.690,734] <dbg> bt_att: chan_req_notif_sent: chan 0x2000c2c0 CID 0x0004
[00:00:08.690,795] <dbg> bt_conn: bt_conn_prepare_events: 
[00:00:08.690,795] <dbg> bt_conn: conn_prepare_events: Adding conn 0x200047d0 to poll list
[00:00:08.690,826] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:00:08.690,826] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
[00:00:08.712,677] <dbg> bt_sdc_hci_driver: event_packet_process: Event (0x13) len 5
[00:00:08.712,707] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x2000e790 len 7
[00:00:08.712,707] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1
[00:00:08.712,738] <dbg> bt_hci_core: hci_num_completed_packets: handle 0 count 1
[00:00:08.712,738] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:00:08.712,768] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:08.713,623] <dbg> bt_sdc_hci_driver: event_packet_process: Event (0x13) len 5
[00:00:08.713,653] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x2000e790 len 7
[00:00:08.713,653] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1
[00:00:08.713,684] <dbg> bt_hci_core: hci_num_completed_packets: handle 0 count 1
[00:00:08.713,714] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:00:08.713,714] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:08.713,806] <dbg> bt_sdc_hci_driver: data_packet_process: Data: handle (0x00), PB(2), BC(0), len(5)
[00:00:08.713,806] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x2000e590 len 9
[00:00:08.713,897] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
[00:00:08.713,928] <dbg> bt_hci_core: rx_work_handler: buf 0x2000e590 type 3 len 9
[00:00:08.713,928] <dbg> bt_hci_core: hci_acl: buf 0x2000e590
[00:00:08.713,958] <dbg> bt_hci_core: hci_acl: handle 0 len 5 flags 2
[00:00:08.713,958] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:00:08.713,989] <dbg> bt_conn: wait_for_tx_work: conn 0x200047d0
[00:00:08.762,695] <dbg> bt_sdc_hci_driver: data_packet_process: Data: handle (0x00), PB(2), BC(0), len(16)
[00:00:08.762,725] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x2000e5ac len 20
[00:00:08.763,275] <dbg> bt_sdc_hci_driver: data_packet_process: Data: handle (0x00), PB(2), BC(0), len(23)
[00:00:08.763,275] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x2000e5c8 len 27

Furthermore im sharing my prj.conf if that helps:

#
# Copyright (c) 2019 Nordic Semiconductor ASA
#
# SPDX-License-Identifier: LicenseRef-Nordic-5-Clause
#
CONFIG_BT=y
CONFIG_BT_DEBUG_LOG=y
CONFIG_BT_CENTRAL=y
CONFIG_BT_SMP=y
CONFIG_BT_GATT_CLIENT=y
CONFIG_BT_GATT_DM=y
CONFIG_HEAP_MEM_POOL_SIZE=2048
CONFIG_BT_DFU_SMP=y

CONFIG_BT_L2CAP_TX_MTU=498
CONFIG_BT_BUF_ACL_RX_SIZE=502
CONFIG_BT_BUF_ACL_TX_SIZE=502
CONFIG_BT_CTLR_DATA_LENGTH_MAX=251

CONFIG_UART_ASYNC_API=y

CONFIG_BT_SCAN=y
CONFIG_BT_SCAN_FILTER_ENABLE=y
CONFIG_BT_SCAN_UUID_CNT=1

CONFIG_ZCBOR=y
CONFIG_ZCBOR_STOP_ON_ERROR=y

CONFIG_DK_LIBRARY=y

CONFIG_DEBUG_OPTIMIZATIONS=y

CONFIG_FLASH=y

CONFIG_BOOTLOADER_MCUBOOT=y
CONFIG_MCUMGR=y
CONFIG_MCUMGR_TRANSPORT_UART=y
CONFIG_MCUMGR_GRP_IMG=y

# CONFIG_MCUMGR_TRANSPORT_UART dependencies
CONFIG_BASE64=y

# CONFIG_MCUMGR_GRP_IMG dependencies
CONFIG_FLASH=y
CONFIG_IMG_MANAGER=y

# CONFIG_IMG_MANAGER dependencies
CONFIG_STREAM_FLASH=y

# CONFIG_MCUMGR dependencies
CONFIG_NET_BUF=y
CONFIG_ZCBOR=y

# Required for CONFIG_IMG_MANAGER
CONFIG_FLASH_MAP=y

#Logging
CONFIG_LOG_BUFFER_SIZE=10240 
CONFIG_BT_SMP_LOG_LEVEL_DBG=y
CONFIG_BT_DFU_SMP_LOG_LEVEL_DBG=y
CONFIG_BT_LOG_LEVEL_DBG=y
CONFIG_BT_GATT_LOG_LEVEL_DBG=y

Thanks!