"Error: sending the request failed" trying to perform OTA DFU with nRF Connect app

[tonyh]

I am on nRF Connect 2.5.0 SDK. I am trying to add OTA DFU support to my custom board using the MCUBoot bootloader, and everything appears normal when I look at the characteristic table but when trying to upload to the device using the nRF Connect app on iOS, the app appears to slowly upload the firmware (displaying low upload speed ~0.5kbps) then after a few minutes gives me "Error: sending the request failed". My board has no UART connection and I have been using RTT logging using the J-link on an nrf52DK; from what I have seen MCUboot logging with RTT is not reliable, and I have not been able to get it to work either. 

My procedure: 

1. Build and flash MCUboot and app onto the custom board with an nrf52DK.

2. Change my app and build the new app.

3. use nRF Connect app to try to upload 'app_update.bin' to device in upgrade mode "test and confirm". The procedure always fails before completing.

Here is my bootlaoder config in my prj.conf:

 

# Bootloader Configuration
#==================================
CONFIG_BOOTLOADER_MCUBOOT=y
CONFIG_NCS_SAMPLE_MCUMGR_BT_OTA_DFU=y
CONFIG_MCUBOOT_BOOTLOADER_MODE_SWAP_WITHOUT_SCRATCH=y
CONFIG_MCUBOOT_BOOTLOADER_NO_DOWNGRADE=n
CONFIG_IMG_MANAGER=y
CONFIG_PARTITION_MANAGER_ENABLED=y

# Enable most core commands.
CONFIG_MCUMGR_GRP_IMG=y
CONFIG_MCUMGR_GRP_OS=y

# Enable mcumgr.
CONFIG_MCUMGR=y
CONFIG_MCUMGR_TRANSPORT_BT=y
CONFIG_MCUMGR_TRANSPORT_BT_AUTHEN=n

# Some command handlers require a large stack.
CONFIG_SYSTEM_WORKQUEUE_STACK_SIZE=3072

CONFIG_MCUBOOT_UTIL_LOG_LEVEL_INF=y 

# LOGGING Configuration
#==================================
CONFIG_LOG=y
CONFIG_USE_SEGGER_RTT=y
CONFIG_LOG_MODE_IMMEDIATE=y 
CONFIG_LOG_MODE_MINIMAL=n
CONFIG_LOG_BACKEND_RTT=y
CONFIG_LOG_BACKEND_FORMAT_TIMESTAMP=y
CONFIG_THREAD_NAME=y
CONFIG_RESET_ON_FATAL_ERROR=n
CONFIG_INIT_STACKS=y
CONFIG_THREAD_ANALYZER=y

#==================================
# Bluetooth Configuration
#==================================
CONFIG_BT=y
CONFIG_BT_NUS=y
CONFIG_BT_SMP=n
CONFIG_BT_PERIPHERAL=y
CONFIG_BT_THROUGHPUT=y
CONFIG_BT_DEVICE_NAME="test"
CONFIG_BT_DEVICE_APPEARANCE=832

CONFIG_BT_PRIVACY=n
CONFIG_BT_MAX_CONN=1

CONFIG_BT_CTLR_PHY_2M=y
CONFIG_BT_AUTO_PHY_UPDATE=y

CONFIG_BT_BUF_ACL_TX_COUNT=20
CONFIG_BT_L2CAP_TX_MTU=247
CONFIG_BT_BUF_ACL_TX_SIZE=251
CONFIG_BT_CTLR_DATA_LENGTH_MAX=251
CONFIG_BT_BUF_ACL_RX_SIZE=251
CONFIG_BT_AUTO_DATA_LEN_UPDATE=y

CONFIG_BT_CTLR_TX_PWR_DYNAMIC_CONTROL=y
CONFIG_BT_ATT_PREPARE_COUNT=2

Here is my child_image/mcuboot.conf: 

CONFIG_BOOT_SIGNATURE_TYPE_ECDSA_P256=y

#this is an absolute path, change it yourself
CONFIG_BOOT_SIGNATURE_KEY_FILE="C:/Vitalmark/keys/private.pem"

#reduce mcuboot partition size
CONFIG_PM_PARTITION_SIZE_MCUBOOT=0x10000

# Disable UART Console and enable the RTT console
CONFIG_UART_CONSOLE=n
CONFIG_RTT_CONSOLE=y
CONFIG_USE_SEGGER_RTT=y

# Config logger
CONFIG_LOG_BACKEND_RTT=y
CONFIG_LOG_BACKEND_UART=n

CONFIG_MULTITHREADING=y

and I have also statically defined the flash partitions in pm_static.yml based on the first automatically partitioned build:

app:
  address: 0x10200
  end_address: 0x48000
  region: flash_primary
  size: 0x37e00
mcuboot:
  address: 0x0
  end_address: 0x10000
  placement:
    before:
    - mcuboot_primary
  region: flash_primary
  size: 0x10000
mcuboot_pad:
  address: 0x10000
  end_address: 0x10200
  placement:
    align:
      start: 0x1000
    before:
    - mcuboot_primary_app
  region: flash_primary
  size: 0x200
mcuboot_primary:
  address: 0x10000
  end_address: 0x48000
  orig_span: &id001
  - app
  - mcuboot_pad
  region: flash_primary
  sharers: 0x1
  size: 0x38000
  span: *id001
mcuboot_primary_app:
  address: 0x10200
  end_address: 0x48000
  orig_span: &id002
  - app
  region: flash_primary
  size: 0x37e00
  span: *id002
mcuboot_secondary:
  address: 0x48000
  end_address: 0x80000
  placement:
    after:
    - mcuboot_primary
    align:
      start: 0x1000
    align_next: 0x1000
  region: flash_primary
  share_size:
  - mcuboot_primary
  size: 0x38000
sram_primary:
  address: 0x20000000
  end_address: 0x20010000
  region: sram_primary
  size: 0x10000

Here is the log from the nrf connect app: 

Scanner On.
Device Scanned.
Device Appearance switched from Generic to UART.
Connected.
Discovered Nordic UART Service, 0483DADD-6C9D-6CA9-5D41-03AD4FFF4ABB, and SMP Service Services.
Discovered Characteristics UART TX Characteristic and UART RX Characteristic for Service Nordic UART Service.
Discovered Characteristics 1524 for Service 0483DADD-6C9D-6CA9-5D41-03AD4FFF4ABB.
Discovered Characteristics SMP Characteristic for Service SMP Service.
Discovered Client Characteristic Configuration for Characteristic UART TX Characteristic
Characteristic UART RX Characteristic has no Descriptors.
Characteristic 1524 has no Descriptors.
Device Appearance switched from UART to McuMgrDFU.
Discovered Client Characteristic Configuration for Characteristic SMP Characteristic
Found valid Firmware in file:///var/mobile/Containers/Data/Application/4D4197EB-C6BC-4ECA-861F-10957E6527CB/Library/Caches/app_updateAF08E5E7-D04E-4537-986B-CAA02FF5CA2D-95620-00001C3F1CF8B74E.bin for Device DFU McuMgr.
Central Manager ready
Peripheral connected
Device ready
LIST Command Performed with Success.
Upgrade started with 1 image(s) using 'Test and Confirm' mode
Firmware Upgrade Started.
State changed from none to requestMcuMgrParameters
Peripheral connected
Device ready
Mcu Manager parameters received (4 x 2475)
State changed from requestMcuMgrParameters to bootloaderInfo
Bootloader info received (mode: Swap without scratch)
State changed from bootloaderInfo to validate
Image List response: Header: {"version": "1", "op": "1", "flags": 0, "length": 134, "group": 1, "seqNum": 129, "commandId": 0}, Payload: {"splitStatus" : 0, "images" : {{"confirmed" : true, "bootable" : true, "pending" : false, "slot" : 0, "active" : true, "version" : "0.0.1", "permanent" : false, "hash" : 0xC3ED37EE6691E2DAF0070AEF8FC5C2EE5651FAE20D6EEE2CDC8C40E2720025B7}}}
Scheduling upload (hash: 0x468347114A3BAEB15B0D72C5D64286A195190BF76D65F3A5C87DAD409B5A5A8A) for image 0 (slot: 1)
State changed from validate to upload
Retry 1 for seq: 132
Retry 1 for seq: 133
Retry 1 for seq: 139
Retry 1 for seq: 144
Retry 1 for seq: 145
Retry 1 for seq: 146
Retry 2 for seq: 144
Retry 1 for seq: 148
Retry 1 for seq: 149
Retry 1 for seq: 150
Retry 2 for seq: 148
Retry 1 for seq: 155
Retry 1 for seq: 156
Scanner Off.
Retry 2 for seq: 156
Retry 1 for seq: 164
Retry 1 for seq: 165
Retry 1 for seq: 173
Retry 1 for seq: 174
Retry 1 for seq: 175
Retry 2 for seq: 173
Retry 1 for seq: 184
Retry 1 for seq: 185
Retry 1 for seq: 186
Retry 2 for seq: 185
Retry 1 for seq: 194
Retry 1 for seq: 195
Retry 1 for seq: 202
Retry 1 for seq: 203
Retry 1 for seq: 204
Retry 1 for seq: 205
Retry 1 for seq: 210
Retry 1 for seq: 215
Retry 1 for seq: 216
Retry 1 for seq: 217
Retry 1 for seq: 218
Retry 2 for seq: 218
Retry 1 for seq: 233
Retry 1 for seq: 234
Retry 1 for seq: 235
Retry 2 for seq: 233
Retry 1 for seq: 245
Retry 2 for seq: 245
Retry 1 for seq: 6
Retry 1 for seq: 7
Retry 1 for seq: 8
Retry 2 for seq: 8
Retry 1 for seq: 21
Retry 1 for seq: 26
Retry 1 for seq: 32
Retry 2 for seq: 32
Retry 1 for seq: 48
Retry 1 for seq: 49
Retry 1 for seq: 50
Retry 2 for seq: 48
Retry 2 for seq: 50
Retry 1 for seq: 58
Retry 2 for seq: 58
Retry 1 for seq: 77
Retry 1 for seq: 78
Retry 1 for seq: 79
Retry 2 for seq: 77
Retry 1 for seq: 89
Retry 1 for seq: 98
Retry 1 for seq: 99
Retry 2 for seq: 89
Retry 3 for seq: 89
Request (SMPv2, group: image, seq: 89, command: upload) failed: Sending the request failed.
Sending the request failed.
Upload cancelled due to error: sendFailed
Image upload is not in progress
Image upload is not in progress
Image upload is not in progress
Image upload is not in progress
Image upload is not in progress
Image upload is not in progress
Image upload is not in progress
Image upload is not in progress
Image upload is not in progress
Image upload is not in progress
Image upload is not in progress
Image upload is not in progress
Image upload is not in progress
Image upload is not in progress
Image upload is not in progress
Image upload is not in progress
Image upload is not in progress
Image upload is not in progress
DFU failed: Sending the request failed.
DFU Failed with Error: Sending the request failed.

I am fairly certain it is not a connection issue, since I never had any issues with the old NordicDFU on the nrf5 SDK using the exact same board. Since I don't have a UART port for MCUBoot logging I'm not sure how I can diagnose this issue. Any help would be much appreciated

[Amanda Hsieh]

Hi, 

but when trying to upload to the device using the nRF Connect app on iOS

Could you try with https://www.nordicsemi.com/Products/Development-tools/nrf-connect-device-manager?

Regards,
Amanda H. 

[tonyh]

Hello Amanda, 

Thanks for your reply. I was able to successfully upload the image, confirm it, and reset the device. However, it was very slow (it took around 15 minutes). Is there any reason for this? 

Tony

[Amanda Hsieh]

Hi, 

Hope this post  DFU upload speed through BT SMP is slow can help. 

-Amanda H. 

[tonyh]

Hello,

As you can see from my mcuboot.conf, I have already enabled NCS_SAMPLE_MCUMGR_BT_OTA_DFU_SPEEDUP, but I have had to lower some of the BT buffer sizes as I am at 99% RAM utilization. Is there anything else I can do to increase the upload speed? In my main application I am able to achieve around 10kB/s no problem while when uploading the image I'm getting average 0.19kB/s, so I don't believe the buffer sizes are the issue. 

Thank you for your help.

Tony

[Amanda Hsieh]

Hi Tony, 

What iOS are you using?

Could you provide the nRF Sniffer log? Please capture the log before the connection. 

-Amanda H.

[tonyh]

Hello,

I am using an iphone 12 pro max on iOS 16.6. Here is the trace: nrf_device_manager_dfu.pcapng

and here is the wireshark log: 

INFO: Log started at Wed Jan 31 13:32:32 2024
INFO: Extcap version 4.2
INFO: Opening serial port COM5
INFO: closing UART
INFO: Opening serial port COM5
INFO: args: ()
INFO: kwargs: {'callbacks': [('*', <bound method Notifier.passOnNotification of <Sniffer(Thread-3, initial)>>)]}
INFO: board ID: 5
INFO: Sniffer created
INFO: Software version: 4.1.1
INFO: sniffer started
INFO: starting scan
INFO: Scan flags: 0b11
INFO: Sent TK to sniffer: [0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]
INFO: scanning started
INFO: follow_device: [b'205', b' 148', b' 145', b' 142', b' 124', b' 238', b' 1']
INFO: Sniffing device 0 - """"
INFO: Follow flags: 0b0
INFO: Firmware version 4.1.1
INFO: Firmware timestamp 450871608 reference: Jan 31 2024 13:32:32.990599 Pacific Standard Time
INFO: Following cd:94:91:8e:7c:ee  random 
INFO: defaults written
INFO: control loop

. 

I uploaded the image, confirmed it, and then reset the device from the app. 
I'm not able to capture the log of the device since I'm using the DK as the sniffer. 

Thanks for your help,

Tony

[Amanda Hsieh]

Could you also provide .config file under build/zephyr? Thanks. 

[tonyh]

Here it is: https://www.dropbox.com/scl/fi/lg96m31n3239frze208n7/.config?rlkey=qqdyaadl4zt86ndgfy6qkdqph&dl=0

And here is the .config file from build/mcuboot/zephyr too: https://www.dropbox.com/scl/fi/u9zvk69pca5opkzbc0jdc/.config?rlkey=n232modltr486056wne19zyz6&dl=0

[Amanda Hsieh]

Could you try to set CONFIG_BT_L2CAP_TX_MTU=498 to see if it can help or not?

You can check by build/zephyr/.config and the sniffer log to see if the MTU is set and updated to 498. 

[tonyh]

Unfortunately as I mentioned earlier I am at 99.89% RAM utilization, the maximum MTU size I can increase it to is 251 before I cannot build anymore, and there seems to be no change in the speed at 251.