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,

Could you test the smp_server using the nRF Connect mobile app on a phone? This will help narrow down the issue and quickly identify if the problem is with your client implementation or the server setup. If the mobile app successfully communicates with the server and completes an image upload or other SMP commands, it suggests that the server is working as expected and that the issue may be on the client side.

Kind regards,
Abhijith

[Jon_RLG]

Hi,

The image upload on the smp_server with the nrF Connect mobile app works as expected. So it seems like the issue is on the Client side.

[Menon]

Hello,

Is the issue related to the connection parameters associated with the smp_client, such as MTU size, connection interval, timeout, and other BLE settings? You could try increasing the MTU size on both the client and server sides to allow for larger data transfers in a single packet.

It might be helpful to check this Developer Academy course for instructions on how to do this.

Kind Regards,

Abhijith