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,

The sample you are following is based on an older version of the nRF Connect SDK and hasn't been updated to match the latest NCS changes. I recommend taking our Developer Academy course for guidance on adding BLE DFU support to your application.

I'm a bit confused by your mention of the Echo command. Are you using both smp_client and smp_server? If so, which device is running the smp_client? If not, which device holds the firmware image that is uploaded to the smp_server?

When you mentioned "Echo," did you mean a simple test to verify that communication between the two devices is working correctly?

Could you please use the insert tab to paste the entire log here? It will be easier for me to review.

Kind Regards,
Abhijith

[Jon_RLG]

Hello,

Yes, i am using a smp Client and a smp server on 2 different DK. The client is trying to update the server over ble. The firmware is stored on the client.

The mentioned Developer Academy is great but is mainly focusing on the receiving side. I find it hard to find any other informations on how to perform a DFU from one DK to another. Especially over BLE.

Following the mentioned course and setting up an peripheral with  CONFIG_NCS_SAMPLE_MCUMGR_BT_OTA_DFU, im getting the same issue.

You are right! The mentioned echo command is only to verify if the communication is working. Here is the link to the mcumgr echo command: https://docs.nordicsemi.com/bundle/ncs-2.7.0/page/zephyr/services/device_mgmt/smp_groups/smp_group_0.html

I´m sorry for the bad format. Here are the log files again.

Mcumgr Echo Command:

Echo test: 1
[00:00:10.380,645] <dbg> bt_gatt: gatt_write_ccc: handle 0x0019 value 0x0001
[00:00:10.380,676] <dbg> bt_att: bt_att_req_alloc: req 0x2000e3a0
[00:00:10.380,706] <dbg> bt_conn: bt_conn_create_pdu_timeout: Timeout discarded. No blocking in syswq.
[00:00:10.380,706] <dbg> bt_att: bt_att_req_send: conn 0x200047d0 req 0x2000e3a0
[00:00:10.380,737] <dbg> bt_att: bt_att_chan_req_send: req 0x2000e3a0
[00:00:10.380,767] <dbg> bt_att: chan_req_send: chan 0x2000be00 req 0x2000e3a0 len 5
[00:00:10.380,767] <dbg> bt_att: bt_att_chan_send: chan 0x2000be00 flags 1 code 0x12
[00:00:10.380,798] <dbg> bt_att: chan_send: code 0x12
[00:00:10.380,798] <dbg> bt_l2cap: bt_l2cap_send_cb: conn 0x200047d0 cid 4 len 5
[00:00:10.380,828] <dbg> bt_conn: bt_conn_send_cb: conn handle 0 buf len 9 cb 0 user_data 0
[00:00:10.380,889] <dbg> bt_conn: bt_conn_create_pdu_timeout: Timeout discarded. No blocking in syswq.
[00:00:10.380,920] <dbg> bt_gatt: bt_gatt_write_without_response_cb: handle 0x0018 length 17
[00:00:10.380,950] <dbg> bt_att: bt_att_chan_send: chan 0x2000be00 flags 1 code 0x52
[00:00:10.380,950] <dbg> bt_att: chan_send: code 0x52
[00:00:10.380,981] <dbg> bt_l2cap: bt_l2cap_send_cb: conn 0x200047d0 cid 4 len 20
[00:00:10.380,981] <dbg> bt_conn: bt_conn_send_cb: conn handle 0 buf len 24 cb 0 user_data 0
[00:00:10.381,072] <dbg> bt_hci_core: process_events: count 3
[00:00:10.381,072] <dbg> bt_hci_core: process_events: ev->state 0
[00:00:10.381,103] <dbg> bt_hci_core: process_events: ev->state 0
[00:00:10.381,103] <dbg> bt_hci_core: process_events: ev->state 4
[00:00:10.381,134] <dbg> bt_conn: bt_conn_process_tx: conn 0x200047d0
[00:00:10.381,134] <dbg> bt_conn: send_buf: conn 0x200047d0 buf 0x2000e318 len 9
[00:00:10.381,164] <dbg> bt_conn: send_buf: send single
[00:00:10.381,195] <dbg> bt_conn: do_send_frag: conn 0x200047d0 buf 0x2000e318 len 9 flags 0x02
[00:00:10.381,195] <dbg> bt_hci_core: bt_send: buf 0x2000e318 len 13 type 2
[00:00:10.381,225] <dbg> bt_sdc_hci_driver: hci_driver_send: 
[00:00:10.381,225] <dbg> bt_sdc_hci_driver: acl_handle: 
[00:00:10.381,256] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
[00:00:10.381,286] <dbg> bt_att: att_tx_destroy: 0x2000e318
[00:00:10.381,317] <dbg> bt_att: att_on_sent_cb: opcode 0x12
[00:00:10.381,317] <dbg> bt_att: att_on_sent_cb: UATT bearer, calling att_sent
[00:00:10.381,347] <dbg> bt_att: att_sent: conn 0x200047d0 chan 0x2000be04
[00:00:10.381,347] <dbg> bt_att: bt_att_sent: chan 0x2000be00
[00:00:10.381,378] <dbg> bt_att: chan_rebegin_att_timeout: chan 0x2000be00 chan->req 0x2000e3a0
[00:00:10.381,408] <dbg> bt_conn: bt_conn_prepare_events: 
[00:00:10.381,439] <dbg> bt_conn: conn_prepare_events: Adding conn 0x200047d0 to poll list
[00:00:10.381,439] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:00:10.381,469] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
[00:00:10.381,500] <dbg> bt_hci_core: process_events: count 3
[00:00:10.381,500] <dbg> bt_hci_core: process_events: ev->state 0
[00:00:10.381,530] <dbg> bt_hci_core: process_events: ev->state 0
[00:00:10.381,530] <dbg> bt_hci_core: process_events: ev->state 4
[00:00:10.381,561] <dbg> bt_conn: bt_conn_process_tx: conn 0x200047d0
[00:00:10.381,561] <dbg> bt_conn: send_buf: conn 0x200047d0 buf 0x2000e2f8 len 24
[00:00:10.381,591] <dbg> bt_conn: send_buf: send single
[00:00:10.381,622] <dbg> bt_conn: do_send_frag: conn 0x200047d0 buf 0x2000e2f8 len 24 flags 0x02
[00:00:10.381,622] <dbg> bt_hci_core: bt_send: buf 0x2000e2f8 len 28 type 2
[00:00:10.381,652] <dbg> bt_sdc_hci_driver: hci_driver_send: 
[00:00:10.381,652] <dbg> bt_sdc_hci_driver: acl_handle: 
[00:00:10.381,683] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
[00:00:10.381,713] <dbg> bt_att: att_tx_destroy: 0x2000e2f8
[00:00:10.381,744] <dbg> bt_att: att_on_sent_cb: opcode 0x52
[00:00:10.381,744] <dbg> bt_att: att_on_sent_cb: UATT bearer, calling att_sent
[00:00:10.381,774] <dbg> bt_att: att_sent: conn 0x200047d0 chan 0x2000be04
[00:00:10.381,774] <dbg> bt_att: bt_att_sent: chan 0x2000be00
[00:00:10.381,805] <dbg> bt_att: chan_req_notif_sent: chan 0x2000be00 CID 0x0004
[00:00:10.381,835] <dbg> bt_conn: bt_conn_prepare_events: 
[00:00:10.381,835] <dbg> bt_conn: conn_prepare_events: Adding conn 0x200047d0 to poll list
[00:00:10.381,866] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:00:10.381,896] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
[00:00:10.389,312] <dbg> bt_sdc_hci_driver: event_packet_process: Event (0x13) len 5
[00:00:10.389,343] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x2000d934 len 7
[00:00:10.389,373] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1
[00:00:10.389,373] <dbg> bt_hci_core: hci_num_completed_packets: handle 0 count 1
[00:00:10.389,404] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:00:10.389,404] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:10.389,892] <dbg> bt_sdc_hci_driver: event_packet_process: Event (0x13) len 5
[00:00:10.389,923] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x2000d934 len 7
[00:00:10.389,953] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1
[00:00:10.389,953] <dbg> bt_hci_core: hci_num_completed_packets: handle 0 count 1
[00:00:10.389,984] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:00:10.390,014] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:10.390,075] <dbg> bt_sdc_hci_driver: data_packet_process: Data: handle (0x00), PB(2), BC(0), len(5)
[00:00:10.390,106] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x2000d734 len 9
[00:00:10.390,167] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
[00:00:10.390,197] <dbg> bt_hci_core: rx_work_handler: buf 0x2000d734 type 3 len 9
[00:00:10.390,228] <dbg> bt_hci_core: hci_acl: buf 0x2000d734
[00:00:10.390,228] <dbg> bt_hci_core: hci_acl: handle 0 len 5 flags 2
[00:00:10.390,258] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:00:10.390,258] <dbg> bt_conn: wait_for_tx_work: conn 0x200047d0
[00:00:10.390,319] <dbg> bt_conn: tx_notify: conn 0x200047d0
[00:00:10.390,350] <dbg> bt_conn: wait_for_tx_work: done
[00:00:10.390,380] <dbg> bt_conn: bt_conn_recv: handle 0 len 5 flags 02
[00:00:10.390,411] <dbg> bt_conn: bt_acl_recv: First, len 5 final 1
[00:00:10.390,411] <dbg> bt_conn: bt_acl_recv: Successfully parsed 5 byte L2CAP packet
[00:00:10.390,441] <dbg> bt_l2cap: bt_l2cap_recv: Packet for CID 4 len 1
[00:00:10.390,441] <dbg> bt_l2cap: l2cap_chan_recv: chan 0x2000be04 len 1
[00:00:10.390,472] <dbg> bt_att: bt_att_recv: Received ATT chan 0x2000be00 code 0x13 len 0
[00:00:10.390,502] <dbg> bt_att: att_handle_write_rsp: 
[00:00:10.390,533] <dbg> bt_att: att_handle_rsp: chan 0x2000be00 err 0 len 0: 
[00:00:10.390,563] <dbg> bt_att: bt_att_req_free: req 0x2000e3a0
[00:00:10.390,563] <dbg> bt_gatt: gatt_write_ccc_rsp: err 0
[00:00:10.390,594] <dbg> bt_gatt: att_err_from_int: 0
[00:00:10.390,625] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:10.439,361] <dbg> bt_sdc_hci_driver: data_packet_process: Data: handle (0x00), PB(2), BC(0), len(16)
[00:00:10.439,361] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x2000d734 len 20
[00:00:10.439,483] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
[00:00:10.439,514] <dbg> bt_hci_core: rx_work_handler: buf 0x2000d734 type 3 len 20
[00:00:10.439,514] <dbg> bt_hci_core: hci_acl: buf 0x2000d734
[00:00:10.439,544] <dbg> bt_hci_core: hci_acl: handle 0 len 16 flags 2
[00:00:10.439,544] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:00:10.439,575] <dbg> bt_conn: wait_for_tx_work: conn 0x200047d0
[00:00:10.439,605] <dbg> bt_conn: tx_notify: conn 0x200047d0
[00:00:10.439,666] <dbg> bt_conn: wait_for_tx_work: done
[00:00:10.439,697] <dbg> bt_conn: bt_conn_recv: handle 0 len 16 flags 02
[00:00:10.439,697] <dbg> bt_conn: bt_acl_recv: First, len 16 final 12
[00:00:10.439,849] <dbg> bt_conn: bt_acl_recv: Successfully parsed 16 byte L2CAP packet
[00:00:10.439,880] <dbg> bt_l2cap: bt_l2cap_recv: Packet for CID 5 len 12
[00:00:10.439,880] <dbg> bt_l2cap: l2cap_chan_recv: chan 0x200068b8 len 12
[00:00:10.439,910] <dbg> bt_l2cap: l2cap_recv: Signaling code 0x12 ident 7 len 8
[00:00:10.439,941] <dbg> bt_l2cap: le_conn_param_update_req: min 0x0006 max 0x0009 latency: 0x0000 timeout: 0x002a
[00:00:10.439,971] <dbg> bt_l2cap: bt_l2cap_send_cb: conn 0x200047d0 cid 5 len 6
[00:00:10.439,971] <dbg> bt_conn: bt_conn_send_cb: conn handle 0 buf len 10 cb 0 user_data 0
[00:00:10.440,002] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x2013 param_len 14
[00:00:10.440,032] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x2000d9e0
[00:00:10.440,063] <dbg> bt_hci_core: bt_hci_cmd_send_sync: buf 0x2000d9e0 opcode 0x2013 len 17
[00:00:10.440,155] <dbg> bt_sdc_hci_driver: data_packet_process: Data: handle (0x00), PB(2), BC(0), len(24)
[00:00:10.440,185] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x2000d750 len 28
[00:00:10.440,246] <dbg> bt_hci_core: process_events: count 3
[00:00:10.440,277] <dbg> bt_hci_core: process_events: ev->state 4
[00:00:10.440,277] <dbg> bt_hci_core: send_cmd: calling net_buf_get
[00:00:10.440,307] <dbg> bt_hci_core: send_cmd: calling sem_take_wait
[00:00:10.440,307] <dbg> bt_hci_core: send_cmd: Sending command 0x2013 (buf 0x2000d9e0) to driver
[00:00:10.440,338] <dbg> bt_hci_core: bt_send: buf 0x2000d9e0 len 17 type 0
[00:00:10.440,338] <dbg> bt_sdc_hci_driver: hci_driver_send: 
[00:00:10.440,368] <dbg> bt_sdc_hci_driver: cmd_handle: 
[00:00:10.440,399] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
[00:00:10.440,429] <dbg> bt_hci_core: process_events: ev->state 0
[00:00:10.440,429] <dbg> bt_hci_core: process_events: ev->state 4
[00:00:10.440,460] <dbg> bt_conn: bt_conn_process_tx: conn 0x200047d0
[00:00:10.440,460] <dbg> bt_conn: send_buf: conn 0x200047d0 buf 0x2000df80 len 10
[00:00:10.440,490] <dbg> bt_conn: send_buf: send single
[00:00:10.440,521] <dbg> bt_conn: do_send_frag: conn 0x200047d0 buf 0x2000df80 len 10 flags 0x02
[00:00:10.440,521] <dbg> bt_hci_core: bt_send: buf 0x2000df80 len 14 type 2
[00:00:10.440,551] <dbg> bt_sdc_hci_driver: hci_driver_send: 
[00:00:10.440,551] <dbg> bt_sdc_hci_driver: acl_handle: 
[00:00:10.440,582] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
[00:00:10.440,643] <dbg> bt_sdc_hci_driver: event_packet_process: Command Status (0x2013) status: 0x00
[00:00:10.440,673] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x2000d76c len 6
[00:00:10.440,673] <dbg> bt_hci_core: hci_cmd_status: opcode 0x2013
[00:00:10.440,704] <dbg> bt_hci_core: hci_cmd_done: opcode 0x2013 status 0x00 buf 0x2000d76c
[00:00:10.440,795] <dbg> bt_conn: bt_conn_prepare_events: 
[00:00:10.440,826] <dbg> bt_conn: conn_prepare_events: Adding conn 0x200047d0 to poll list
[00:00:10.440,826] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:00:10.440,856] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
[00:00:10.440,887] <dbg> bt_hci_core: bt_hci_cmd_send_sync: rsp 0x2000d9e0 opcode 0x2013 len 0
[00:00:10.440,917] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:10.440,948] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
[00:00:10.440,979] <dbg> bt_hci_core: rx_work_handler: buf 0x2000d750 type 3 len 28
[00:00:10.440,979] <dbg> bt_hci_core: hci_acl: buf 0x2000d750
[00:00:10.441,009] <dbg> bt_hci_core: hci_acl: handle 0 len 24 flags 2
[00:00:10.441,009] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:00:10.441,040] <dbg> bt_conn: wait_for_tx_work: conn 0x200047d0
[00:00:10.441,070] <dbg> bt_conn: tx_notify: conn 0x200047d0
[00:00:10.441,131] <dbg> bt_conn: wait_for_tx_work: done
[00:00:10.441,162] <dbg> bt_conn: bt_conn_recv: handle 0 len 24 flags 02
[00:00:10.441,162] <dbg> bt_conn: bt_acl_recv: First, len 24 final 20
[00:00:10.441,192] <dbg> bt_conn: bt_acl_recv: Successfully parsed 24 byte L2CAP packet
[00:00:10.441,192] <dbg> bt_l2cap: bt_l2cap_recv: Packet for CID 4 len 20
[00:00:10.441,223] <dbg> bt_l2cap: l2cap_chan_recv: chan 0x2000be04 len 20
[00:00:10.441,223] <dbg> bt_att: bt_att_recv: Received ATT chan 0x2000be00 code 0x1b len 19
[00:00:10.441,253] <dbg> bt_att: att_notify: chan 0x2000be00 handle 0x0018
[00:00:10.441,284] <dbg> bt_gatt: bt_gatt_notification: handle 0x0018 length 17
[00:00:10.441,284] <dbg> dfu_smp: notify_process: DFU SMP Response received!
DFU SMP Response received![00:00:10.441,345] <dbg> dfu_smp: notify_process: DFU SMP starting callback
Echo response part received, size: 17.
Total response received - decoding
{_"r": "Lore"}
[00:00:10.441,497] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:10.489,379] <dbg> bt_sdc_hci_driver: event_packet_process: Event (0x13) len 5
[00:00:10.489,410] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x2000d934 len 7
[00:00:10.489,440] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1
[00:00:10.489,471] <dbg> bt_hci_core: hci_num_completed_packets: handle 0 count 1
[00:00:10.489,471] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:00:10.489,501] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:10.789,367] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x03), len (10)
[00:00:10.789,398] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x2000d750 len 12
[00:00:10.789,459] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
[00:00:10.789,489] <dbg> bt_hci_core: rx_work_handler: buf 0x2000d750 type 1 len 12
[00:00:10.789,489] <dbg> bt_hci_core: hci_event: event 0x3e
[00:00:10.789,520] <dbg> bt_hci_core: hci_le_meta_event: subevent 0x03
[00:00:10.789,550] <dbg> bt_hci_core: le_conn_update_complete: status 0x00, handle 0
[00:00:10.789,550] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:00:10.789,581] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:15.395,690] <dbg> bt_sdc_hci_driver: data_packet_process: Data: handle (0x00), PB(2), BC(0), len(16)
[00:00:15.395,721] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x2000d750 len 20
[00:00:15.395,812] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
[00:00:15.395,812] <dbg> bt_hci_core: rx_work_handler: buf 0x2000d750 type 3 len 20
[00:00:15.395,843] <dbg> bt_hci_core: hci_acl: buf 0x2000d750
[00:00:15.395,843] <dbg> bt_hci_core: hci_acl: handle 0 len 16 flags 2
[00:00:15.395,874] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:00:15.395,904] <dbg> bt_conn: wait_for_tx_work: conn 0x200047d0
[00:00:15.395,935] <dbg> bt_conn: tx_notify: conn 0x200047d0
[00:00:15.395,996] <dbg> bt_conn: wait_for_tx_work: done
[00:00:15.396,026] <dbg> bt_conn: bt_conn_recv: handle 0 len 16 flags 02
[00:00:15.396,026] <dbg> bt_conn: bt_acl_recv: First, len 16 final 12
[00:00:15.396,057] <dbg> bt_conn: bt_acl_recv: Successfully parsed 16 byte L2CAP packet
[00:00:15.396,057] <dbg> bt_l2cap: bt_l2cap_recv: Packet for CID 5 len 12
[00:00:15.396,087] <dbg> bt_l2cap: l2cap_chan_recv: chan 0x200068b8 len 12
[00:00:15.396,087] <dbg> bt_l2cap: l2cap_recv: Signaling code 0x12 ident 8 len 8
[00:00:15.396,118] <dbg> bt_l2cap: le_conn_param_update_req: min 0x0018 max 0x0028 latency: 0x0000 timeout: 0x002a
[00:00:15.396,148] <dbg> bt_l2cap: bt_l2cap_send_cb: conn 0x200047d0 cid 5 len 6
[00:00:15.396,179] <dbg> bt_conn: bt_conn_send_cb: conn handle 0 buf len 10 cb 0 user_data 0
[00:00:15.396,209] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x2013 param_len 14
[00:00:15.396,209] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x2000d9e0
[00:00:15.396,240] <dbg> bt_hci_core: bt_hci_cmd_send_sync: buf 0x2000d9e0 opcode 0x2013 len 17
[00:00:15.396,301] <dbg> bt_hci_core: process_events: count 3
[00:00:15.396,331] <dbg> bt_hci_core: process_events: ev->state 4
[00:00:15.396,331] <dbg> bt_hci_core: send_cmd: calling net_buf_get
[00:00:15.396,362] <dbg> bt_hci_core: send_cmd: calling sem_take_wait
[00:00:15.396,362] <dbg> bt_hci_core: send_cmd: Sending command 0x2013 (buf 0x2000d9e0) to driver
[00:00:15.396,392] <dbg> bt_hci_core: bt_send: buf 0x2000d9e0 len 17 type 0
[00:00:15.396,392] <dbg> bt_sdc_hci_driver: hci_driver_send: 
[00:00:15.396,423] <dbg> bt_sdc_hci_driver: cmd_handle: 
[00:00:15.396,453] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
[00:00:15.396,484] <dbg> bt_hci_core: process_events: ev->state 0
[00:00:15.396,484] <dbg> bt_hci_core: process_events: ev->state 4
[00:00:15.396,514] <dbg> bt_conn: bt_conn_process_tx: conn 0x200047d0
[00:00:15.396,514] <dbg> bt_conn: send_buf: conn 0x200047d0 buf 0x2000df80 len 10
[00:00:15.396,545] <dbg> bt_conn: send_buf: send single
[00:00:15.396,575] <dbg> bt_conn: do_send_frag: conn 0x200047d0 buf 0x2000df80 len 10 flags 0x02
[00:00:15.396,575] <dbg> bt_hci_core: bt_send: buf 0x2000df80 len 14 type 2
[00:00:15.396,606] <dbg> bt_sdc_hci_driver: hci_driver_send: 
[00:00:15.396,606] <dbg> bt_sdc_hci_driver: acl_handle: 
[00:00:15.396,636] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
[00:00:15.396,697] <dbg> bt_sdc_hci_driver: event_packet_process: Command Status (0x2013) status: 0x00
[00:00:15.396,728] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x2000d734 len 6
[00:00:15.396,728] <dbg> bt_hci_core: hci_cmd_status: opcode 0x2013
[00:00:15.396,759] <dbg> bt_hci_core: hci_cmd_done: opcode 0x2013 status 0x00 buf 0x2000d734
[00:00:15.396,850] <dbg> bt_conn: bt_conn_prepare_events: 
[00:00:15.396,881] <dbg> bt_conn: conn_prepare_events: Adding conn 0x200047d0 to poll list
[00:00:15.396,881] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:00:15.396,911] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
[00:00:15.396,942] <dbg> bt_hci_core: bt_hci_cmd_send_sync: rsp 0x2000d9e0 opcode 0x2013 len 0
[00:00:15.396,972] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:15.406,890] <dbg> bt_sdc_hci_driver: event_packet_process: Event (0x13) len 5
[00:00:15.406,921] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x2000d934 len 7
[00:00:15.406,951] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1
[00:00:15.406,951] <dbg> bt_hci_core: hci_num_completed_packets: handle 0 count 1
[00:00:15.406,982] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:00:15.407,012] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:15.474,365] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x03), len (10)
[00:00:15.474,395] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x2000d750 len 12
[00:00:15.474,456] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
[00:00:15.474,487] <dbg> bt_hci_core: rx_work_handler: buf 0x2000d750 type 1 len 12
[00:00:15.474,517] <dbg> bt_hci_core: hci_event: event 0x3e
[00:00:15.474,517] <dbg> bt_hci_core: hci_le_meta_event: subevent 0x03
[00:00:15.474,548] <dbg> bt_hci_core: le_conn_update_complete: status 0x00, handle 0
[00:00:15.474,548] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:00:15.474,578] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2

Image upload Command:

Payload legnth is: 199Sending upload cmd![00:02:03.632,720] <dbg> bt_conn: bt_conn_create_pdu_timeout: Timeout discarded. No blocking in syswq.
[00:02:03.632,751] <dbg> bt_gatt: bt_gatt_write_without_response_cb: handle 0x0018 length 207
[00:02:03.632,781] <dbg> bt_att: bt_att_chan_send: chan 0x2000be00 flags 1 code 0x52
[00:02:03.632,812] <dbg> bt_att: chan_send: code 0x52
[00:02:03.632,812] <dbg> bt_l2cap: bt_l2cap_send_cb: conn 0x200047d0 cid 4 len 210
[00:02:03.632,843] <dbg> bt_conn: bt_conn_send_cb: conn handle 0 buf len 214 cb 0 user_data 0
[00:02:03.632,904] <dbg> bt_hci_core: process_events: count 3
[00:02:03.632,904] <dbg> bt_hci_core: process_events: ev->state 0
[00:02:03.632,934] <dbg> bt_hci_core: process_events: ev->state 0
[00:02:03.632,934] <dbg> bt_hci_core: process_events: ev->state 4
[00:02:03.632,965] <dbg> bt_conn: bt_conn_process_tx: conn 0x200047d0
[00:02:03.632,965] <dbg> bt_conn: send_buf: conn 0x200047d0 buf 0x2000e2f8 len 214
[00:02:03.632,995] <dbg> bt_conn: send_buf: start fragmenting
[00:02:03.633,026] <dbg> bt_conn: do_send_frag: conn 0x200047d0 buf 0x2000dc24 len 27 flags 0x00
[00:02:03.633,056] <dbg> bt_hci_core: bt_send: buf 0x2000dc24 len 31 type 2
[00:02:03.633,056] <dbg> bt_sdc_hci_driver: hci_driver_send: 
[00:02:03.633,087] <dbg> bt_sdc_hci_driver: acl_handle: 
[00:02:03.633,117] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
[00:02:03.633,148] <dbg> bt_conn: do_send_frag: conn 0x200047d0 buf 0x2000dc24 len 27 flags 0x01
[00:02:03.633,178] <dbg> bt_hci_core: bt_send: buf 0x2000dc24 len 31 type 2
[00:02:03.633,178] <dbg> bt_sdc_hci_driver: hci_driver_send: 
[00:02:03.633,209] <dbg> bt_sdc_hci_driver: acl_handle: 
[00:02:03.633,239] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
[00:02:03.633,270] <dbg> bt_conn: do_send_frag: conn 0x200047d0 buf 0x2000dc24 len 27 flags 0x01
[00:02:03.633,300] <dbg> bt_hci_core: bt_send: buf 0x2000dc24 len 31 type 2
[00:02:03.633,300] <dbg> bt_sdc_hci_driver: hci_driver_send: 
[00:02:03.633,331] <dbg> bt_sdc_hci_driver: acl_handle: 
[00:02:03.633,361] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
[00:02:03.633,392] <dbg> bt_conn: send_frag: no controller bufs
[00:02:03.633,392] <dbg> bt_conn: send_buf: 0x2000e2f8 failed, mark as existing frag
[00:02:03.633,422] <dbg> bt_conn: bt_conn_prepare_events: 
[00:02:03.633,453] <dbg> bt_conn: conn_prepare_events: Adding conn 0x200047d0 to poll list
[00:02:03.633,483] <dbg> bt_conn: conn_prepare_events: wait on ctlr buffers
[00:02:03.633,483] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
[00:02:03.635,620] <dbg> bt_sdc_hci_driver: event_packet_process: Event (0x13) len 5
[00:02:03.635,650] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x2000d934 len 7
[00:02:03.635,681] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1
[00:02:03.635,681] <dbg> bt_hci_core: hci_num_completed_packets: handle 0 count 1
[00:02:03.635,711] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:02:03.635,742] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:02:03.635,864] <dbg> bt_hci_core: process_events: count 3
[00:02:03.635,864] <dbg> bt_hci_core: process_events: ev->state 0
[00:02:03.635,894] <dbg> bt_hci_core: process_events: ev->state 0
[00:02:03.635,894] <dbg> bt_hci_core: process_events: ev->state 2
[00:02:03.635,925] <dbg> bt_conn: bt_conn_prepare_events: 
[00:02:03.635,955] <dbg> bt_conn: conn_prepare_events: Adding conn 0x200047d0 to poll list
[00:02:03.635,955] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:02:03.635,986] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
[00:02:03.636,077] <dbg> bt_hci_core: process_events: count 3
[00:02:03.636,077] <dbg> bt_hci_core: process_events: ev->state 0
[00:02:03.636,108] <dbg> bt_hci_core: process_events: ev->state 0
[00:02:03.636,108] <dbg> bt_hci_core: process_events: ev->state 4
[00:02:03.636,138] <dbg> bt_conn: bt_conn_process_tx: conn 0x200047d0
[00:02:03.636,138] <dbg> bt_conn: send_buf: conn 0x200047d0 buf 0x2000e2f8 len 133
[00:02:03.636,169] <dbg> bt_conn: send_buf: start fragmenting
[00:02:03.636,199] <dbg> bt_conn: do_send_frag: conn 0x200047d0 buf 0x2000dc24 len 27 flags 0x01
[00:02:03.636,230] <dbg> bt_hci_core: bt_send: buf 0x2000dc24 len 31 type 2
[00:02:03.636,230] <dbg> bt_sdc_hci_driver: hci_driver_send: 
[00:02:03.636,260] <dbg> bt_sdc_hci_driver: acl_handle: 
[00:02:03.636,291] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
[00:02:03.636,322] <dbg> bt_conn: send_frag: no controller bufs
[00:02:03.636,352] <dbg> bt_conn: send_buf: 0x2000e2f8 failed, mark as existing frag
[00:02:03.636,444] <dbg> bt_sdc_hci_driver: event_packet_process: Event (0x13) len 5
[00:02:03.636,474] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x2000d934 len 7
[00:02:03.636,474] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1
[00:02:03.636,505] <dbg> bt_hci_core: hci_num_completed_packets: handle 0 count 1
[00:02:03.636,657] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:02:03.636,688] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:02:03.636,749] <dbg> bt_sdc_hci_driver: event_packet_process: Event (0x13) len 5
[00:02:03.636,779] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x2000d934 len 7
[00:02:03.636,810] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1
[00:02:03.636,810] <dbg> bt_hci_core: hci_num_completed_packets: handle 0 count 1
[00:02:03.636,840] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:02:03.636,871] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:02:03.636,932] <dbg> bt_conn: bt_conn_prepare_events: 
[00:02:03.636,962] <dbg> bt_conn: conn_prepare_events: Adding conn 0x200047d0 to poll list
[00:02:03.636,962] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:02:03.636,993] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
[00:02:03.637,023] <dbg> bt_hci_core: process_events: count 3
[00:02:03.637,023] <dbg> bt_hci_core: process_events: ev->state 0
[00:02:03.637,054] <dbg> bt_hci_core: process_events: ev->state 0
[00:02:03.637,054] <dbg> bt_hci_core: process_events: ev->state 4
[00:02:03.637,084] <dbg> bt_conn: bt_conn_process_tx: conn 0x200047d0
[00:02:03.637,115] <dbg> bt_conn: send_buf: conn 0x200047d0 buf 0x2000e2f8 len 106
[00:02:03.637,115] <dbg> bt_conn: send_buf: start fragmenting
[00:02:03.637,145] <dbg> bt_conn: do_send_frag: conn 0x200047d0 buf 0x2000dc24 len 27 flags 0x01
[00:02:03.637,176] <dbg> bt_hci_core: bt_send: buf 0x2000dc24 len 31 type 2
[00:02:03.637,176] <dbg> bt_sdc_hci_driver: hci_driver_send: 
[00:02:03.637,207] <dbg> bt_sdc_hci_driver: acl_handle: 
[00:02:03.637,237] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
[00:02:03.637,268] <dbg> bt_conn: do_send_frag: conn 0x200047d0 buf 0x2000dc24 len 27 flags 0x01
[00:02:03.637,298] <dbg> bt_hci_core: bt_send: buf 0x2000dc24 len 31 type 2
[00:02:03.637,298] <dbg> bt_sdc_hci_driver: hci_driver_send: 
[00:02:03.637,329] <dbg> bt_sdc_hci_driver: acl_handle: 
[00:02:03.637,359] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
[00:02:03.637,390] <dbg> bt_conn: send_frag: no controller bufs
[00:02:03.637,390] <dbg> bt_conn: send_buf: 0x2000e2f8 failed, mark as existing frag
[00:02:03.637,451] <dbg> bt_conn: bt_conn_prepare_events: 
[00:02:03.637,451] <dbg> bt_conn: conn_prepare_events: Adding conn 0x200047d0 to poll list
[00:02:03.637,481] <dbg> bt_conn: conn_prepare_events: wait on ctlr buffers
[00:02:03.637,481] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
[00:02:03.685,638] <dbg> bt_sdc_hci_driver: event_packet_process: Event (0x13) len 5
[00:02:03.685,668] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x2000d934 len 7
[00:02:03.685,668] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1
[00:02:03.685,699] <dbg> bt_hci_core: hci_num_completed_packets: handle 0 count 1
[00:02:03.685,699] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:02:03.685,729] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:02:03.685,852] <dbg> bt_hci_core: process_events: count 3
[00:02:03.685,882] <dbg> bt_hci_core: process_events: ev->state 0
[00:02:03.685,882] <dbg> bt_hci_core: process_events: ev->state 0
[00:02:03.685,913] <dbg> bt_hci_core: process_events: ev->state 2
[00:02:03.685,943] <dbg> bt_conn: bt_conn_prepare_events: 
[00:02:03.685,943] <dbg> bt_conn: conn_prepare_events: Adding conn 0x200047d0 to poll list
[00:02:03.685,974] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:02:03.685,974] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
[00:02:03.686,065] <dbg> bt_hci_core: process_events: count 3
[00:02:03.686,096] <dbg> bt_hci_core: process_events: ev->state 0
[00:02:03.686,096] <dbg> bt_hci_core: process_events: ev->state 0
[00:02:03.686,126] <dbg> bt_hci_core: process_events: ev->state 4
[00:02:03.686,126] <dbg> bt_conn: bt_conn_process_tx: conn 0x200047d0
[00:02:03.686,157] <dbg> bt_conn: send_buf: conn 0x200047d0 buf 0x2000e2f8 len 52
[00:02:03.686,157] <dbg> bt_conn: send_buf: start fragmenting
[00:02:03.686,187] <dbg> bt_conn: do_send_frag: conn 0x200047d0 buf 0x2000dc24 len 27 flags 0x01
[00:02:03.686,218] <dbg> bt_hci_core: bt_send: buf 0x2000dc24 len 31 type 2
[00:02:03.686,218] <dbg> bt_sdc_hci_driver: hci_driver_send: 
[00:02:03.686,248] <dbg> bt_sdc_hci_driver: acl_handle: 
[00:02:03.686,279] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
[00:02:03.686,309] <dbg> bt_conn: send_buf: last frag
[00:02:03.686,309] <dbg> bt_conn: send_frag: no controller bufs
[00:02:03.686,431] <dbg> bt_sdc_hci_driver: event_packet_process: Event (0x13) len 5
[00:02:03.686,462] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x2000d934 len 7
[00:02:03.686,462] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1
[00:02:03.686,492] <dbg> bt_hci_core: hci_num_completed_packets: handle 0 count 1
[00:02:03.686,492] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:02:03.686,645] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:02:03.686,737] <dbg> bt_sdc_hci_driver: event_packet_process: Event (0x13) len 5
[00:02:03.686,767] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x2000d934 len 7
[00:02:03.686,798] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1
[00:02:03.686,798] <dbg> bt_hci_core: hci_num_completed_packets: handle 0 count 1
[00:02:03.686,828] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:02:03.686,859] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:02:03.686,920] <dbg> bt_conn: bt_conn_prepare_events: 
[00:02:03.686,950] <dbg> bt_conn: conn_prepare_events: Adding conn 0x200047d0 to poll list
[00:02:03.686,950] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:02:03.686,981] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
[00:02:03.687,011] <dbg> bt_hci_core: process_events: count 3
[00:02:03.687,011] <dbg> bt_hci_core: process_events: ev->state 0
[00:02:03.687,042] <dbg> bt_hci_core: process_events: ev->state 0
[00:02:03.687,042] <dbg> bt_hci_core: process_events: ev->state 4
[00:02:03.687,072] <dbg> bt_conn: bt_conn_process_tx: conn 0x200047d0
[00:02:03.687,072] <dbg> bt_conn: send_buf: conn 0x200047d0 buf 0x2000e2f8 len 25
[00:02:03.687,103] <dbg> bt_conn: send_buf: start fragmenting
[00:02:03.687,103] <dbg> bt_conn: send_buf: last frag
[00:02:03.687,133] <dbg> bt_conn: do_send_frag: conn 0x200047d0 buf 0x2000e2f8 len 25 flags 0x03
[00:02:03.687,164] <dbg> bt_hci_core: bt_send: buf 0x2000e2f8 len 29 type 2
[00:02:03.687,164] <dbg> bt_sdc_hci_driver: hci_driver_send: 
[00:02:03.687,194] <dbg> bt_sdc_hci_driver: acl_handle: 
[00:02:03.687,225] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
[00:02:03.687,225] <dbg> bt_att: att_tx_destroy: 0x2000e2f8
[00:02:03.687,255] <dbg> bt_att: att_on_sent_cb: opcode 0x52
[00:02:03.687,286] <dbg> bt_att: att_on_sent_cb: UATT bearer, calling att_sent
[00:02:03.687,286] <dbg> bt_att: att_sent: conn 0x200047d0 chan 0x2000be04
[00:02:03.687,316] <dbg> bt_att: bt_att_sent: chan 0x2000be00
[00:02:03.687,316] <dbg> bt_att: chan_req_notif_sent: chan 0x2000be00 CID 0x0004
[00:02:03.687,347] <dbg> bt_conn: bt_conn_prepare_events: 
[00:02:03.687,377] <dbg> bt_conn: conn_prepare_events: Adding conn 0x200047d0 to poll list
[00:02:03.687,377] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:02:03.687,408] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
[00:02:03.735,626] <dbg> bt_sdc_hci_driver: event_packet_process: Event (0x13) len 5
[00:02:03.735,656] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x2000d934 len 7
[00:02:03.735,687] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1
[00:02:03.735,687] <dbg> bt_hci_core: hci_num_completed_packets: handle 0 count 1
[00:02:03.735,717] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:02:03.735,748] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:02:03.736,206] <dbg> bt_sdc_hci_driver: event_packet_process: Event (0x13) len 5
[00:02:03.736,236] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x2000d934 len 7
[00:02:03.736,236] <dbg> bt_hci_core: hci_num_completed_packets: num_handles 1
[00:02:03.736,267] <dbg> bt_hci_core: hci_num_completed_packets: handle 0 count 1
[00:02:03.736,297] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:02:03.736,297] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:02:03.785,614] <dbg> bt_sdc_hci_driver: data_packet_process: Data: handle (0x00), PB(2), BC(0), len(16)
[00:02:03.785,614] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x2000d750 len 20
[00:02:03.785,736] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
[00:02:03.785,766] <dbg> bt_hci_core: rx_work_handler: buf 0x2000d750 type 3 len 20
[00:02:03.785,766] <dbg> bt_hci_core: hci_acl: buf 0x2000d750
[00:02:03.785,797] <dbg> bt_hci_core: hci_acl: handle 0 len 16 flags 2
[00:02:03.785,797] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:02:03.785,827] <dbg> bt_conn: wait_for_tx_work: conn 0x200047d0
[00:02:03.786,163] <dbg> bt_sdc_hci_driver: data_packet_process: Data: handle (0x00), PB(2), BC(0), len(23)
[00:02:03.786,193] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x2000d734 len 27
[00:02:08.785,675] <dbg> bt_sdc_hci_driver: data_packet_process: Data: handle (0x00), PB(2), BC(0), len(16)
[00:02:08.785,736] <dbg> bt_hci_core: bt_recv_unsafe: buf 0x2000d76c len 20

Please let me know if you need any other informations.

Thanks.

[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!

[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