Application service UUID gone after secure OTA DFU

[SK]

Hello, 

I am using nRF52832 on SES v4.12 with SDK v15.3 and SD v6.1.1 on a custom board.

Background: 

I want to perform OTA DFU and with that i have two services enabled (secure dfu buttonless and NUS). I was facing OTA DFU issue in which i was getting CRC does not match error. This has been resolved here - https://devzone.nordicsemi.com/f/nordic-q-a/55653/dfu-crc-does-not-match-error

So, i have been able to perform OTA update. 

The package that i created includes BL+SD+APP. 

Problem: 

Once i perform the update and connect again, i only see one service, which is Secure DFU service and the other which is the main application service ID (NUS) is gone. I looked in the forum and found this -https://devzone.nordicsemi.com/f/nordic-q-a/39982/after-ota-dfu-bootloader-application-gone

But i do not quite fully understand as to what is to be done here. Could you please highlight on what is required for a proper DFU process? From what i understand from the post and infocenter that it is still a single update, so BL+SD+APP merged together should work fine internally. 

EDIT:

Zip created has only application hex in it. BL+SD+APP is programmed directly using nrfjprog. 

Please let me know if you require more information. 

Thanks a lot!

-SK

[Aleksander Nowakowski]

After successful dfu the new application should be started. The services available after an update depend on what you have in it. If there's only Secure dfu service, than it's either the buttonless service (check characteristic name in nRF Connect for Android) which means that your have flashed an app without NUS, or you're still in bootloader mode, that is the app has been rejected by the new bootloader do for some reason. The old app has been removed, a specially if SD's major version has changed, to make space for dual bank.

In nRF Connect it may also be that another tab opened, with the bootloader address. Just close it and use the tab with your old device name. You may also clear cache, select Refresh services in the menu after connecting to your device.

[SK]

I migrated the SDK from 14.2 to 15.3. In v14.2, this DFU process worked fine. That means i have both the services running after DFU process and yes, there was another tab that opened with the bootloader address. 

But with 15.3, i donot see such a thing. SD major is still 132 that i am using with v6.1.1. 

I ran nrfjprog --eraseall before programming the module with merged hex (BL+SD+APP) and then did a reset. Till here, application runs fine. I can see both the services on the nRF Connect. It is only when i try to update the application (creating a package) via OTA DFU, that i see the problem. When i try to connect, i see only Secure DFU service and not the other one. Not sure whats going on :(  

[Aleksander Nowakowski]

Ideally, the app, after started after successful DFU, should send SC indication, just like the bootloader is sending when switched from app to bootloader mode. On Android you may force clear the cache, like nRF Connect does, but if you want to support iOS as well, there's no such API, not even hidden, so working SC is a must when working with bonded DFU.

The errors 133 happen often, yes. The DFU lib does what it can to try to avoid them, tries many times sometimes, but, a specially on older Android devices and when the device is bonded, the 133 error is common. What phone are you testing on?

If you have sniffer (for example this one: https://www.nordicsemi.com/Software-and-tools/Development-Tools/nRF-Sniffer-for-Bluetooth-LE) you may try to find out what's causing this 133 error. Usually it means that there was a packet lost, packet collision, some packets came too early or too late, or, when device is bonded, perhaps something with the encryption. Try putting phone and device close to each other to avoid interference, sometimes disabling wi-fi also helps, as I read in the Internet. 133 is a generic error when "something else" happens, so it may be almost anything.

The 133 around 5 sec after connection attempt seems like the Connect Request was missed by the device and it continued to advertise instead. Retries should increase the chance of success.

[SK]

Aleksander Nowakowski said:

What phone are you testing on?

I am testing on samsung S9+ currently.

Aleksander Nowakowski said:

133 is a generic error when "something else" happens, so it may be almost anything

That's comforting to know :D 

Yes, i will try it out by sniffing the packets and see if i can get somewhere with this error. 

SK said:

Would you know anything about this issue? https://devzone.nordicsemi.com/f/nordic-q-a/36346/a-problem-on-buttonless-dfu-bonding-valid

This is what Hung said in the link i shared above

"I think we found the root cause of the issue. When you set the MTU to something else not the default that the iPhone set when connected, the nrf_ble_gatt.c will try to request sd_ble_gattc_exchange_mtu_request() immediately right after CONNECTED event."

. Would you know if it is corrected in v15.3? or is it still an issue? 

[Hung Bui]

@SK: The issue regarding the MTU request is fixed in SDK v16.0 but not on SDK v15.3 you may want to follow my suggestion in the case. 

[SK]

Okay sure, will do. In that case, you say putting in a timer to delay the MTU exchange? When should the timer expire? Could you tell me more on the details, please.  

[Hung Bui]

The main reason to delay MTU exchange was to wait for the phone to do that. (so that we have larger MTU ATT). I would say give it 1-2 second. 

Regarding the issue of having sd_ble_gatts_service_changed() and sd_ble_gattc_exchange_mtu_request() at the same time, you can check if the error is NRF_ERROR_INVALID_STATE the application can retry after a certain time (let's say 1 second) . 

[SK]

Hi Hung Bui

Sorry, i had to move to some other tasks. I tried to do as you suggested, but i am getting error on the sd_ble_gattc_exchange_mtu_request() --> unknown error code 

Would you know why would that be? I have added timer as below.

    if (p_link->att_mtu_desired > p_link->att_mtu_effective)
    {
        NRF_LOG_DEBUG("Requesting to update ATT MTU to %u bytes on connection 0x%x.",
                      p_link->att_mtu_desired, conn_handle);
        create_mtu_request_timer();
        app_timer_start(mtu_request_delay_timer, APP_TIMER_TICKS(1000), NULL);
    }

Rest of the code i have moved in the handler:

static void request_delay_handler(void *p_context)
{
  ret_code_t err_code;
  nrf_ble_gatt_t * p_gatt = (nrf_ble_gatt_t *)p_context;
  ble_evt_t const * p_ble_evt;
  uint16_t  conn_handle = p_ble_evt->evt.common_evt.conn_handle;
  nrf_ble_gatt_link_t * p_link      = &p_gatt->links[conn_handle];
    err_code = sd_ble_gattc_exchange_mtu_request(conn_handle, p_link->att_mtu_desired);

    if (err_code == NRF_SUCCESS)
    {
        p_link->att_mtu_exchange_requested = true;
    }
    else if (err_code == NRF_ERROR_BUSY)
    {
        p_link->att_mtu_exchange_pending = true;
        NRF_LOG_DEBUG("sd_ble_gattc_exchange_mtu_request()"
                      " on connection 0x%x returned busy, will retry.", conn_handle);
    }
    else
    {
        NRF_LOG_ERROR("sd_ble_gattc_exchange_mtu_request() returned %s.",
                      nrf_strerror_get(err_code));
    }  
}

Once i connect, i get this error: 

<error> nrf_ble_gatt: sd_ble_gattc_exchange_mtu_request() returned Unknown error code.

[SK]

Okay, got it what i was doing wrong there! 

will continue to check on the DFU procedure now. 

[SK]

Okay, tried doing OTA DFU. Still not working. 

Error 0x85 - GATT Error. Before this happens, device resets. 

[SK]

logs from the bootloader as i try to do DFU

<debug> app: In nrf_bootloader_init

<debug> nrf_dfu_settings: Calling nrf_dfu_settings_init()...

<debug> nrf_dfu_flash: Initializing nrf_fstorage_nvmc backend.

<debug> nrf_dfu_settings: Using settings page.

<debug> nrf_dfu_settings: Copying forbidden parts from backup page.

<debug> nrf_dfu_settings: Destination settings are identical to source, write not needed. Skipping.

<info> nrf_dfu_settings: Backing up settings page to address 0x7E000.

<debug> nrf_dfu_settings: Destination settings are identical to source, write not needed. Skipping.

<debug> app: Enter nrf_bootloader_fw_activate

<info> app: No firmware to activate.

<debug> app: App is valid

<info> nrf_dfu_settings: Backing up settings page to address 0x7E000.

<debug> nrf_dfu_settings: Destination settings are identical to source, write not needed. Skipping.

<debug> app: Running nrf_bootloader_app_start with address: 0x00001000

<debug> app: Disabling interrupts. NVIC->ICER[0]: 0x0

<debug> app: In nrf_bootloader_init

<debug> nrf_dfu_settings: Calling nrf_dfu_settings_init()...

<debug> nrf_dfu_flash: Initializing nrf_fstorage_nvmc backend.

<debug> nrf_dfu_settings: Using settings page.

<debug> nrf_dfu_settings: Copying forbidden parts from backup page.

<debug> nrf_dfu_settings: Destination settings are identical to source, write not needed. Skipping.

<info> nrf_dfu_settings: Backing up settings page to address 0x7E000.

<debug> nrf_dfu_settings: Destination settings are identical to source, write not needed. Skipping.

<debug> app: Enter nrf_bootloader_fw_activate

<info> app: No firmware to activate.

<debug> app: App is valid

<info> nrf_dfu_settings: Backing up settings page to address 0x7E000.

<debug> nrf_dfu_settings: Destination settings are identical to source, write not needed. Skipping.

<debug> app: Running nrf_bootloader_app_start with address: 0x00001000

<debug> app: Disabling interrupts. NVIC->ICER[0]: 0x0

<debug> app: In nrf_bootloader_init

<debug> nrf_dfu_settings: Calling nrf_dfu_settings_init()...

<debug> nrf_dfu_flash: Initializing nrf_fstorage_nvmc backend.

<debug> nrf_dfu_settings: Using settings page.

<debug> nrf_dfu_settings: Copying forbidden parts from backup page.

<debug> nrf_dfu_settings: Destination settings are identical to source, write not needed. Skipping.

<info> nrf_dfu_settings: Backing up settings page to address 0x7E000.

<debug> nrf_dfu_settings: Writing settings...

<debug> nrf_dfu_settings: Erasing old settings at: 0x0007E000

<debug> nrf_dfu_flash: nrf_fstorage_erase(addr=0x0x0007E000, len=1 pages), queue usage: 0

<debug> nrf_dfu_flash: Flash erase success: addr=0x0007E000, pending 0

<debug> nrf_dfu_flash: nrf_fstorage_write(addr=0x0007E000, src=0x20005DE4, len=896 bytes), queue usage: 1

<debug> nrf_dfu_flash: Flash write success: addr=0x0007E000, pending 0

<debug> app: Enter nrf_bootloader_fw_activate

<info> app: No firmware to activate.

<debug> app: App is valid

<debug> app: DFU mode requested via GPREGRET.

<info> nrf_bootloader_wdt: WDT is not enabled

<debug> app: in weak nrf_dfu_init_user

<debug> app: timer_stop (0x200057D8)

<debug> app: timer_activate (0x200057D8)

<info> app: Entering DFU mode.

<debug> app: Initializing transports (found: 1)

<debug> nrf_dfu_ble: Initializing BLE DFU transport

<debug> nrf_dfu_ble: Setting up vector table: 0x00072000

<debug> nrf_dfu_ble: Enabling SoftDevice.

<debug> nrf_dfu_ble: Configuring BLE stack.

<debug> nrf_dfu_ble: Enabling the BLE stack.

<debug> nrf_dfu_ble: Copying peer data

<debug> nrf_dfu_ble: Using default advertising name

<debug> nrf_dfu_ble: Advertising...

<debug> nrf_dfu_ble: BLE DFU transport initialized.

<debug> nrf_dfu_flash: Initializing nrf_fstorage_sd backend.

<debug> app: Enter main loop

<debug> nrf_dfu_ble: Connected

<debug> nrf_dfu_ble: Received BLE_GAP_EVT_CONN_PARAM_UPDATE

<debug> nrf_dfu_ble: max_conn_interval: 12

<debug> nrf_dfu_ble: min_conn_interval: 12

<debug> nrf_dfu_ble: slave_latency: 0

<debug> nrf_dfu_ble: conn_sup_timeout: 600

<debug> nrf_dfu_ble: Received BLE_GAP_EVT_SEC_INFO_REQUEST

<debug> nrf_dfu_ble: Sending Service Changed indication

<debug> nrf_dfu_ble: Finished handling conn sec update

<debug> nrf_dfu_ble: Received BLE_GAP_EVT_CONN_PARAM_UPDATE

<debug> nrf_dfu_ble: max_conn_interval: 6

<debug> nrf_dfu_ble: min_conn_interval: 6

<debug> nrf_dfu_ble: slave_latency: 0

<debug> nrf_dfu_ble: conn_sup_timeout: 500

<debug> nrf_dfu_ble: Received BLE_GAP_EVT_CONN_PARAM_UPDATE

<debug> nrf_dfu_ble: max_conn_interval: 12

<debug> nrf_dfu_ble: min_conn_interval: 12

<debug> nrf_dfu_ble: slave_latency: 0

<debug> nrf_dfu_ble: conn_sup_timeout: 600

<debug> nrf_dfu_ble: Received BLE_GATTS_EVT_EXCHANGE_MTU_REQUEST (request: 517, reply: 247).

<debug> nrf_dfu_ble: Received BLE_GAP_EVT_DATA_LENGTH_UPDATE_REQUEST.

<debug> nrf_dfu_ble: Received BLE_GAP_EVT_DATA_LENGTH_UPDATE (251, max_rx_time 2120).

<debug> app: In nrf_bootloader_init

<debug> nrf_dfu_settings: Calling nrf_dfu_settings_init()...

<debug> nrf_dfu_flash: Initializing nrf_fstorage_nvmc backend.

<debug> nrf_dfu_settings: Using settings page.

<debug> nrf_dfu_settings: Copying forbidden parts from backup page.

<debug> nrf_dfu_settings: Destination settings are identical to source, write not needed. Skipping.

<info> nrf_dfu_settings: Backing up settings page to address 0x7E000.

<debug> nrf_dfu_settings: Destination settings are identical to source, write not needed. Skipping.

<debug> app: Enter nrf_bootloader_fw_activate

<info> app: No firmware to activate.

<debug> app: App is valid

<debug> nrf_dfu_settings_svci: Erasing settings page additional data.

<info> nrf_dfu_settings: Backing up settings page to address 0x7E000.

<debug> nrf_dfu_settings: Writing settings...

<debug> nrf_dfu_settings: Erasing old settings at: 0x0007E000

<debug> nrf_dfu_flash: nrf_fstorage_erase(addr=0x0x0007E000, len=1 pages), queue usage: 0

<debug> nrf_dfu_flash: Flash erase success: addr=0x0007E000, pending 0

<debug> nrf_dfu_flash: nrf_fstorage_write(addr=0x0007E000, src=0x20005DE4, len=896 bytes), queue usage: 1

<debug> nrf_dfu_flash: Flash write success: addr=0x0007E000, pending 0

<debug> app: Running nrf_bootloader_app_start with address: 0x00001000

<debug> app: Disabling interrupts. NVIC->ICER[0]: 0x0

[SK]

Okay so i noticed that for the previous SDK 14.2 i used inactivity timer value as 10000. 

Increasing the value to 120000 as was default, i did not see any GATT error while doing OTA DFU.