nrf51 dfu via nrfToolbox or nrfConnect crashes on dfu upload Huawei p30 lite

[Robin P]

Hello!

I am having issues dfu from the huawei p30 lite. with nrf51. Tried with nrf connect and nrf toolbox.

Dfu progress stops at 2-3% when uploading.

Error Remote dfu error OPERATION_FAILED.

Gatt conn timeout.

Log bellow

nRF Connect, 2019-05-24

Pacelog (C8:3F:A7:C9:6F:34)

V 15:04:59.343 Connecting to C8:3F:A7:C9:6F:34...

D 15:04:59.343 gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, preferred PHY = LE 1M)

D 15:04:59.630 [Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED

D 15:04:59.658 [Callback] Connection state changed with status: 0 and new state: CONNECTED (2)

I 15:04:59.658 Connected to C8:3F:A7:C9:6F:34

V 15:04:59.669 Discovering services...

D 15:04:59.669 gatt.discoverServices()

I 15:05:00.070 Connection parameters updated (interval: 30.0ms, latency: 0, timeout: 4000ms)

I 15:05:00.316 Connection parameters updated (interval: 7.5ms, latency: 0, timeout: 5000ms)

D 15:05:00.491 [Callback] Services discovered with status: 0

I 15:05:00.491 Services discovered

V 15:05:00.523 Generic Access (0x1800)

- Device Name [R W] (0x2A00)

- Appearance [R] (0x2A01)

- Peripheral Preferred Connection Parameters [R] (0x2A04)

Generic Attribute (0x1801)

- Service Changed [I] (0x2A05)

Client Characteristic Configuration (0x2902)

Device Firmware Update Service (00001530-1212-efde-1523-785feabcd123)

- DFU Packet [WNR] (00001532-1212-efde-1523-785feabcd123)

- DFU Control Point [N W] (00001531-1212-efde-1523-785feabcd123)

Client Characteristic Configuration (0x2902)

- DFU Version [R] (00001534-1212-efde-1523-785feabcd123)

D 15:05:00.523 gatt.setCharacteristicNotification(00002a05-0000-1000-8000-00805f9b34fb, true)

I 15:05:00.554 Connection parameters updated (interval: 15.0ms, latency: 0, timeout: 4000ms)

I 15:05:00.899 Connection parameters updated (interval: 15.0ms, latency: 0, timeout: 4000ms)

V 15:05:22.905 [DFU] DFU service started

V 15:05:22.905 [DFU] Opening file...

I 15:05:23.230 [DFU] Firmware file opened successfully

V 15:05:23.230 [DFU] Connecting to DFU target...

D 15:05:23.231 [DFU] gatt = device.connectGatt(autoConnect = false)

I 15:05:23.243 [DFU] Connected to C8:3F:A7:C9:6F:34

V 15:05:23.243 [DFU] Discovering services...

D 15:05:23.243 [DFU] gatt.discoverServices()

I 15:05:23.250 [DFU] Services discovered

D 15:05:23.272 [DFU] wait(1000)

V 15:05:24.258 [DFU] Reading DFU version number...

D 15:05:24.259 [DFU] gatt.readCharacteristic(00001534-1212-efde-1523-785feabcd123)

I 15:05:24.406 [DFU] Read Response received from 00001534-1212-efde-1523-785feabcd123, value (0x): 08-00

A 15:05:24.406 [DFU] Version number read: 0.8

D 15:05:24.410 [DFU] wait(1000)

V 15:05:25.411 [DFU] Enabling notifications for 00001531-1212-efde-1523-785feabcd123

D 15:05:25.411 [DFU] gatt.setCharacteristicNotification(00001531-1212-efde-1523-785feabcd123, true)

D 15:05:25.417 [DFU] gatt.writeDescriptor(00002902-0000-1000-8000-00805f9b34fb, value=0x01-00)

I 15:05:25.443 [DFU] Data written to descr.00001531-1212-efde-1523-785feabcd123, value (0x): 01-00

V 15:05:25.443 [DFU] Notifications enabled for 00001531-1212-efde-1523-785feabcd123

A 15:05:25.444 [DFU] Notifications enabled

D 15:05:25.444 [DFU] wait(1000)

V 15:05:26.491 [DFU] Writing to characteristic 00001531-1212-efde-1523-785feabcd123

D 15:05:26.491 [DFU] gatt.writeCharacteristic(00001531-1212-efde-1523-785feabcd123)

I 15:05:26.491 [DFU] Data written to 00001531-1212-efde-1523-785feabcd123, value (0x): 01-04

A 15:05:26.491 [DFU] DFU Start sent (Op Code = 1, Upload Mode = 4)

V 15:05:26.491 [DFU] Writing to characteristic 00001532-1212-efde-1523-785feabcd123

D 15:05:26.491 [DFU] gatt.writeCharacteristic(00001532-1212-efde-1523-785feabcd123)

I 15:05:26.491 [DFU] Data written to 00001532-1212-efde-1523-785feabcd123, value (0x): 00-00-00-00-00-00-00-00-68-C0-00-00

A 15:05:26.491 [DFU] Firmware image size sent (0b, 0b, 49256b)

I 15:05:30.213 [DFU] Notification received from 00001531-1212-efde-1523-785feabcd123, value (0x): 10-01-01

A 15:05:30.214 [DFU] Response received (Op Code = 1 Status = 1)

A 15:05:30.214 [DFU] Writing Initialize DFU Parameters...

V 15:05:30.214 [DFU] Writing to characteristic 00001531-1212-efde-1523-785feabcd123

D 15:05:30.214 [DFU] gatt.writeCharacteristic(00001531-1212-efde-1523-785feabcd123)

I 15:05:30.241 [DFU] Data written to 00001531-1212-efde-1523-785feabcd123, value (0x): 02-00

V 15:05:30.242 [DFU] Writing to characteristic 00001532-1212-efde-1523-785feabcd123

D 15:05:30.242 [DFU] gatt.writeCharacteristic(00001532-1212-efde-1523-785feabcd123)

I 15:05:30.246 [DFU] Data written to 00001532-1212-efde-1523-785feabcd123, value (0x): FF-FF-FF-FF-FF-FF-FF-FF-01-00-FE-FF-67-1A

V 15:05:30.247 [DFU] Writing to characteristic 00001531-1212-efde-1523-785feabcd123

D 15:05:30.247 [DFU] gatt.writeCharacteristic(00001531-1212-efde-1523-785feabcd123)

I 15:05:30.301 [DFU] Data written to 00001531-1212-efde-1523-785feabcd123, value (0x): 02-01

A 15:05:30.302 [DFU] Initialize DFU Parameters completed

I 15:05:30.303 [DFU] Notification received from 00001531-1212-efde-1523-785feabcd123, value (0x): 10-02-01

A 15:05:30.304 [DFU] Response received (Op Code = 2, Status = 1)

V 15:05:30.307 [DFU] Writing to characteristic 00001531-1212-efde-1523-785feabcd123

D 15:05:30.307 [DFU] gatt.writeCharacteristic(00001531-1212-efde-1523-785feabcd123)

I 15:05:30.345 [DFU] Data written to 00001531-1212-efde-1523-785feabcd123, value (0x): 03

A 15:05:30.346 [DFU] Receive Firmware Image request sent

A 15:05:30.386 [DFU] Uploading firmware...

V 15:05:30.386 [DFU] Sending firmware to characteristic 00001532-1212-efde-1523-785feabcd123...

I 15:05:30.590 [DFU] Notification received from 00001531-1212-efde-1523-785feabcd123, value (0x): 10-03-06

A 15:05:30.591 [DFU] Response received (Op Code = 3, Status = 6)

E 15:05:30.593 [DFU] Remote DFU error: OPERATION FAILED

V 15:05:30.594 [DFU] Writing to characteristic 00001531-1212-efde-1523-785feabcd123

D 15:05:30.594 [DFU] gatt.writeCharacteristic(00001531-1212-efde-1523-785feabcd123)

D 15:05:34.637 [Callback] Connection state changed with status: 8 and new state: DISCONNECTED (0)

E 15:05:34.638 Error 8 (0x8): GATT CONN TIMEOUT

I 15:05:34.638 Disconnected

A 15:05:34.667 [DFU] Reset request sent

V 15:05:34.667 [DFU] Disconnecting...

D 15:05:34.668 [DFU] gatt.disconnect()

I 15:05:34.707 [DFU] Disconnected

D 15:05:34.707 [DFU] gatt.refresh() (hidden)

D 15:05:34.707 [DFU] gatt.close()

D 15:05:34.707 [DFU] wait(600)

D 15:05:34.707 [Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED

D 15:05:34.730 [DFU] [Broadcast] Action received: android.bluetooth.device.action.ACL_DISCONNECTED

D 15:05:35.302 gatt.close()

D 15:05:35.307 wait(200)

V 15:05:35.509 Connecting to C8:3F:A7:C9:6F:34...

D 15:05:35.509 gatt = device.connectGatt(autoConnect = false, TRANSPORT_LE, preferred PHY = LE 1M)

D 15:05:35.708 [Callback] Connection state changed with status: 0 and new state: CONNECTED (2)

I 15:05:35.708 Connected to C8:3F:A7:C9:6F:34

V 15:05:35.745 Discovering services...

D 15:05:35.745 gatt.discoverServices()

D 15:05:35.756 [Broadcast] Action received: android.bluetooth.device.action.ACL_CONNECTED

I 15:05:36.175 Connection parameters updated (interval: 30.0ms, latency: 0, timeout: 4000ms)

I 15:05:36.420 Connection parameters updated (interval: 7.5ms, latency: 0, timeout: 5000ms)

D 15:05:36.620 [Callback] Services discovered with status: 0

I 15:05:36.620 Services discovered

V 15:05:36.648 Generic Access (0x1800)

- Device Name [R W] (0x2A00)

- Appearance [R] (0x2A01)

- Peripheral Preferred Connection Parameters [R] (0x2A04)

Generic Attribute (0x1801)

- Service Changed [I] (0x2A05)

Client Characteristic Configuration (0x2902)

Device Firmware Update Service (00001530-1212-efde-1523-785feabcd123)

- DFU Packet [WNR] (00001532-1212-efde-1523-785feabcd123)

- DFU Control Point [N W] (00001531-1212-efde-1523-785feabcd123)

Client Characteristic Configuration (0x2902)

- DFU Version [R] (00001534-1212-efde-1523-785feabcd123)

D 15:05:36.649 gatt.setCharacteristicNotification(00002a05-0000-1000-8000-00805f9b34fb, true)

I 15:05:36.683 Connection parameters updated (interval: 15.0ms, latency: 0, timeout: 4000ms)

I 15:05:37.014 Connection parameters updated (interval: 15.0ms, latency: 0, timeout: 4000ms)

[Robin P]

We tried debugging the bootloader, And the error we get is error code 4 NO_MEM before it throws the OPERATION_FAILED. 

However if I set request MTU in app, the DFU succeeds.

[bjorn-spockeli]

Which function is returning NO_MEM? Which MTU are you requesting?

[Robin P]

static void app_data_process(ble_dfu_t * p_dfu, ble_dfu_evt_t * p_evt)

{

    uint32_t err_code;

 

    if ((p_evt->evt.ble_dfu_pkt_write.len & (sizeof(uint32_t) - 1)) != 0)

    {

        // Data length is not a multiple of 4 (word size).

        err_code = ble_dfu_response_send(p_dfu,

                                         BLE_DFU_RECEIVE_APP_PROCEDURE,

                                         BLE_DFU_RESP_VAL_NOT_SUPPORTED);

        APP_ERROR_CHECK(err_code);

        return;

    }

 

    uint32_t length = p_evt->evt.ble_dfu_pkt_write.len;

 

    err_code = hci_mem_pool_rx_produce(length, (void **) &mp_rx_buffer);

    if (err_code != NRF_SUCCESS)

    {

        dfu_error_notify(p_dfu, err_code);

        return;

    }

 

    uint8_t * p_data_packet = p_evt->evt.ble_dfu_pkt_write.p_data;

   

    memcpy(mp_rx_buffer, p_data_packet, length);

 

    err_code = hci_mem_pool_rx_data_size_set(length);

    if (err_code != NRF_SUCCESS)

    {

        dfu_error_notify(p_dfu, err_code);

        return;

    }

 

    err_code = hci_mem_pool_rx_extract(&mp_rx_buffer, &length);

    if (err_code != NRF_SUCCESS)

    {

        dfu_error_notify(p_dfu, err_code);

        return;

    }

 

    dfu_update_packet_t dfu_pkt;

 

    dfu_pkt.packet_type                      = DATA_PACKET;

    dfu_pkt.params.data_packet.packet_length = length / sizeof(uint32_t);

    dfu_pkt.params.data_packet.p_data_packet = (uint32_t *)mp_rx_buffer;

 

    err_code = dfu_data_pkt_handle(&dfu_pkt); // här genereras felet

 

    if (err_code == NRF_SUCCESS)

    {

        m_num_of_firmware_bytes_rcvd += p_evt->evt.ble_dfu_pkt_write.len;

 

        // All the expected firmware data has been received and processed successfully.

        // Response will be sent when flash operation for final packet is completed.

        mp_final_packet = mp_rx_buffer;

    }

    else if (err_code == NRF_ERROR_INVALID_LENGTH)

    {

        // Firmware data packet was handled successfully. And more firmware data is expected.

        m_num_of_firmware_bytes_rcvd += p_evt->evt.ble_dfu_pkt_write.len;

 

        // Check if a packet receipt notification is needed to be sent.

        if (m_pkt_rcpt_notif_enabled)

        {

            // Decrement the counter for the number firmware packets needed for sending the

            // next packet receipt notification.

            m_pkt_notif_target_cnt--;

 

            if (m_pkt_notif_target_cnt == 0)

            {

                err_code = ble_dfu_pkts_rcpt_notify(p_dfu, m_num_of_firmware_bytes_rcvd);

                APP_ERROR_CHECK(err_code);

 

                // Reset the counter for the number of firmware packets.

                m_pkt_notif_target_cnt = m_pkt_notif_target;

            }

       }

    }

    else

    {

        uint32_t hci_error = hci_mem_pool_rx_consume(mp_rx_buffer);

        if (hci_error != NRF_SUCCESS)

        {

            dfu_error_notify(p_dfu, hci_error);

        }

 

        dfu_error_notify(p_dfu, err_code);

    }

}

Fault is generated at: err_code = dfu_data_pkt_handle(&dfu_pkt)

Then in function: nrf_err_code_translate we have error code 4 going in, but there is no handler for error code 4 so it returns default: BLE_DFU_RESP_VAL_OPER_FAILED

Mtu: In Android application -> settings -> connectivity -> Auto request maximum MTU. This enabled makes dfu succeed

[bjorn-spockeli]

Hmm, 

error code 4 is NRF_ERROR_NO_MEM. Digging down in the functions called internally in dfu_data_pkt_handle() it looks like this error code is coming from 

dfu_data_pkt_handle()->pstorage_store->cmd_queue_enqueue 

due to the queue count reaching the PSTORAGE_CMD_QUEUE_SIZE limit. 

static uint32_t cmd_queue_enqueue(uint8_t             opcode,
                                  pstorage_handle_t * p_storage_addr,
                                  uint8_t           * p_data_addr,
                                  pstorage_size_t     size,
                                  pstorage_size_t     offset)
{
    uint32_t retval;

    if (m_cmd_queue.count != PSTORAGE_CMD_QUEUE_SIZE)
    {
        uint8_t write_index = m_cmd_queue.rp + m_cmd_queue.count;

        if (write_index >= PSTORAGE_CMD_QUEUE_SIZE)
        {
            write_index -= PSTORAGE_CMD_QUEUE_SIZE;
        }

        m_cmd_queue.cmd[write_index].op_code      = opcode;
        m_cmd_queue.cmd[write_index].p_data_addr  = p_data_addr;
        m_cmd_queue.cmd[write_index].storage_addr = (*p_storage_addr);
        m_cmd_queue.cmd[write_index].size         = size;
        m_cmd_queue.cmd[write_index].offset       = offset;
        retval                                    = NRF_SUCCESS;
        if (m_cmd_queue.flash_access == false)
        {
            retval = cmd_process();
            if (retval == NRF_ERROR_BUSY)
            {
                // In case of busy error code, it is possible to attempt to access flash.
                retval = NRF_SUCCESS;
            }
        }
        m_cmd_queue.count++;
    }
    else
    {
        retval = NRF_ERROR_NO_MEM;
    }

    return retval;
}

The PSTORAGE_CMD_QUEUE_SIZE is configurable so you could try to increase it. It is defined to 10 by default in pstorage_platform.h

However, it is odd that requesting a larger MTU size appears to resolve the issue. Would you be able to capture a sniffer trace of the on air packets using our nRF Sniffer v2?  

https://www.nordicsemi.com/Software-and-Tools/Development-Tools/nRF-Sniffer

Best regards

Bjørn