Verify firmware does not work after update.

[zekageri]

Board

ESP32-Wrover-E

Device Description

It is an ESP32-Wrover-E ( 16mb flash and 8mb psram )

Hardware Configuration

ETH,SPI,PSRAM,I2C heavy usage

Version

latest master (checkout manually)

IDE Name

PlatformIO

Operating System

Windows 11

Flash frequency

80mhz

PSRAM enabled

yes

Upload speed

115200

Description

PLATFORM: Espressif 32 (6.0.0) > Espressif ESP-WROVER-KIT
HARDWARE: ESP32 240MHz, 320KB RAM, 4MB Flash
DEBUG: Current (ftdi) On-board (ftdi) External (cmsis-dap, esp-bridge, esp-prog, iot-bus-jtag, jlink, minimodule, olimex-arm-usb-ocd, olimex-arm-usb-ocd-h, olimex-arm-usb-tiny-h, olimex-jtag-tiny, tumpa)
PACKAGES:
 - framework-arduinoespressif32 @ 3.20006.221224 (2.0.6)
 - tool-esptoolpy @ 1.40400.0 (4.4.0)
 - toolchain-xtensa-esp32 @ 8.4.0+2021r2-patch5
LDF: Library Dependency Finder -> https://bit.ly/configure-pio-ldf
LDF Modes: Finder ~ chain, Compatibility ~ soft

I have overwritten the default verifyRollbackLater() function for my own to gain more controll over the firmware rollback process. It was working pretty good so far, but after an update it does not work anymore and i can't load a new firmware via HTTP anymore.

My application called verifyFirmware() after startup at several seconds to ensure the new firmware is not crashing.
If this function never called and the esp crashes, my application rolls back to it's previous state.

How it worked previously:

If ota_state == ESP_OTA_IMG_PENDING_VERIFY then we verified the formware and saved the running address to flash.

Now it's just prints [SYSTEM] - Verifying firmware... and nothing more.
Below is the relevant functions.

Sketch

/*
*   This function is used to overwrite espressif's verifyRollbackLater() function.
*   The espressif's version is returning false, and performing a verify before the
*       app can start.
*/
extern "C" bool verifyRollbackLater(){
    return true;
}

/*
*   Setting the latest partition address value.
*   Used to identify if the current firmware is
*       not the same as the old one for rollback.
*/
void Sys::setLastPartitionAddress(){
    const esp_partition_t *running = esp_ota_get_running_partition();
    config.lastFirmwareAddress = running->address;
}

/*
*   This function is called after startup at FIRMWARE_CHECK_MS time. ( See Sys.h )
*   It will verify the firmware if no crash happens during initializations.
*   If the firmware is not verified and the chip is crashing, it will rollback to
*       a previous stable version.
*/
void Sys::verifyFirmware(){
    if( !shouldCheckFirmware ){ return; }
    if( (millis() - startMS) <= FIRMWARE_CHECK_MS ){ return; }
    shouldCheckFirmware = false;
    if( isDebugOn ){
        debug.print(DEBUG_INFO,"[SYSTEM] - Verifying firmware...\n");
    }
    const esp_partition_t *running = esp_ota_get_running_partition();
    esp_ota_img_states_t ota_state;
    if (esp_ota_get_state_partition(running, &ota_state) == ESP_OK) {
        if (ota_state == ESP_OTA_IMG_PENDING_VERIFY) {
            if (esp_ota_mark_app_valid_cancel_rollback() == ESP_OK) {
                if( isDebugOn ){
                    debug.print(DEBUG_INFO, "[System] - Firmware is stable. Rollback disabled.\n");
                }
                config.isFirmwareValid = true;
                config.currFirmwareAddress = running->address;
                debug.logJson(DEBUG_INFO, "[System] - Firmware verified.");
            } else {
                if( isDebugOn ){
                    debug.print(DEBUG_WARN, "[System] - Failed to disable rollback\n");
                }
                debug.logJson(DEBUG_INFO, "[System] - Failed to disable rollback");
                shouldCheckFirmware = true;
            }
        }
    }else{
        if( isDebugOn ){
            debug.print(DEBUG_ERROR,"[System] - OTA partition has no record in OTA data\n");
        }
    }
}

Debug Message

[SYSTEM] - Firmware upload started.
Update progress: 1%
Guru Meditation Error: Core  1 panic'ed (LoadProhibited). Exception was unhandled.

Core  1 register dump:
PC      : 0x4008bde8  PS      : 0x00060330  A0      : 0x801982c4  A1      : 0x3ffd9b90
A2      : 0x00000001  A3      : 0xfffffffd  A4      : 0x000000ff  A5      : 0x0000ff00
A6      : 0x00ff0000  A7      : 0xff000000  A8      : 0x6469002e  A9      : 0x3ffd9ed0
A10     : 0x3f808694  A11     : 0x00001400  A12     : 0x3f800000  A13     : 0x00000001
A14     : 0x007ba960  A15     : 0x003fffff  SAR     : 0x00000001  EXCCAUSE: 0x0000001c
EXCVADDR: 0x00000001  LBEG    : 0x4008be09  LEND    : 0x4008be19  LCOUNT  : 0xffffffff


Backtrace: 0x4008bde5:0x3ffd9b90 0x401982c1:0x3ffd9ba0 0x4019cec6:0x3ffd9eb0 0x4019ceee:0x3ffd9f50 0x400e4678:0x3ffd9f80 0x400e0d41:0x3ffd9fd0 0x400f0061:0x3ffd9ff0 0x400f015e:0x3ffda020 0x400f0309:0x3ffda040 0x400e1bd2:0x3ffda070 0x400ee481:0x3ffda090 0x401a7455:0x3ffda0f0 0x400e9f82:0x3ffda120 0x400eba91:0x3ffda1a0 0x400ebc55:0x3ffda200 0x4018e1da:0x3ffda220 0x4018e255:0x3ffda250 0x4018e8d6:0x3ffda270

  #0  0x4008bde5:0x3ffd9b90 in strlen at /builds/idf/crosstool-NG/.build/HOST-x86_64-w64-mingw32/xtensa-esp32-elf/src/newlib/newlib/libc/machine/xtensa/strlen.S:43
  #1  0x401982c1:0x3ffd9ba0 in _svfprintf_r at /builds/idf/crosstool-NG/.build/HOST-x86_64-w64-mingw32/xtensa-esp32-elf/src/newlib/newlib/libc/stdio/vfprintf.c:1528
  #2  0x4019cec6:0x3ffd9eb0 in _vsprintf_r at /builds/idf/crosstool-NG/.build/HOST-x86_64-w64-mingw32/xtensa-esp32-elf/src/newlib/newlib/libc/stdio/vsprintf.c:62
  #3  0x4019ceee:0x3ffd9f50 in vsprintf at /builds/idf/crosstool-NG/.build/HOST-x86_64-w64-mingw32/xtensa-esp32-elf/src/newlib/newlib/libc/stdio/vsprintf.c:38
  #4  0x400e4678:0x3ffd9f80 in ServerSystem::sendEvent(char const*, char const*, ...) at src/serverSys/server/serverSys.cpp:113
  #5  0x400e0d41:0x3ffd9fd0 in std::_Function_handler<void (unsigned int, unsigned int), AdminSystem::AdminSystem(AsyncWebServer*)::{lambda(unsigned int, unsigned int)#2}>::_M_invoke(std::_Any_data const&, unsigned int&&, std::_Any_data const&) at src/serverSys/adminSys/adminSys.cpp:68      
      (inlined by) _M_invoke at c:\users\zekag\.platformio\packages\toolchain-xtensa-esp32@8.4.0+2021r2-patch5\xtensa-esp32-elf\include\c++\8.4.0\bits/std_function.h:297
  #6  0x400f0061:0x3ffd9ff0 in std::function<void (unsigned int, unsigned int)>::operator()(unsigned int, unsigned int) const at c:\users\zekag\.platformio\packages\toolchain-xtensa-esp32@8.4.0+2021r2-patch5\xtensa-esp32-elf\include\c++\8.4.0\bits/std_function.h:687
  #7  0x400f015e:0x3ffda020 in UpdateClass::_writeBuffer() at C:/Users/zekag/.platformio/packages/framework-arduinoespressif32/libraries/Update/src/Updater.cpp:231
  #8  0x400f0309:0x3ffda040 in UpdateClass::write(unsigned char*, unsigned int) at C:/Users/zekag/.platformio/packages/framework-arduinoespressif32/libraries/Update/src/Updater.cpp:323
  #9  0x400e1bd2:0x3ffda070 in std::_Function_handler<void (AsyncWebServerRequest*, String const&, unsigned int, unsigned char*, unsigned int, bool), AdminSystem::AdminSystem(AsyncWebServer*)::{lambda(AsyncWebServerRequest*, String const&, unsigned int, unsigned char*, unsigned int, bool)#10}>::_M_invoke(std::_Any_data const&, AsyncWebServerRequest*&&, String const&, unsigned int&&, unsigned char*&&, AsyncWebServerRequest*&&, bool&&) at src/serverSys/adminSys/adminSys.cpp:175
      (inlined by) _M_invoke at c:\users\zekag\.platformio\packages\toolchain-xtensa-esp32@8.4.0+2021r2-patch5\xtensa-esp32-elf\include\c++\8.4.0\bits/std_function.h:297
  #10 0x400ee481:0x3ffda090 in std::function<void (AsyncWebServerRequest*, String const&, unsigned int, unsigned char*, unsigned int, bool)>::operator()(AsyncWebServerRequest*, String const&, unsigned int, unsigned char*, unsigned int, bool) const at c:\users\zekag\.platformio\packages\toolchain-xtensa-esp32@8.4.0+2021r2-patch5\xtensa-esp32-elf\include\c++\8.4.0\bits/std_function.h:687
      (inlined by) AsyncCallbackWebHandler::handleUpload(AsyncWebServerRequest*, String const&, unsigned int, unsigned char*, unsigned int, bool) at lib/ESPAsyncWebServer-yuboxfixes-0xFEEDC0DE64-cleanup/src/WebHandlerImpl.h:140
  #11 0x401a7455:0x3ffda0f0 in AsyncWebServerRequest::_handleUploadByte(unsigned char, bool) at lib/ESPAsyncWebServer-yuboxfixes-0xFEEDC0DE64-cleanup/src/WebRequest.cpp:397
      (inlined by) AsyncWebServerRequest::_handleUploadByte(unsigned char, bool) at lib/ESPAsyncWebServer-yuboxfixes-0xFEEDC0DE64-cleanup/src/WebRequest.cpp:391
  #12 0x400e9f82:0x3ffda120 in AsyncWebServerRequest::_parseMultipartPostByte(unsigned char, bool) at lib/ESPAsyncWebServer-yuboxfixes-0xFEEDC0DE64-cleanup/src/WebRequest.cpp:429 (discriminator 1)
  #13 0x400eba91:0x3ffda1a0 in AsyncWebServerRequest::_onData(void*, unsigned int) at lib/ESPAsyncWebServer-yuboxfixes-0xFEEDC0DE64-cleanup/src/WebRequest.cpp:140 (discriminator 2)
  #14 0x400ebc55:0x3ffda200 in std::_Function_handler<void (void*, AsyncClient*, void*, unsigned int), AsyncWebServerRequest::AsyncWebServerRequest(AsyncWebServer*, AsyncClient*)::{lambda(void*, AsyncClient*, void*, unsigned int)#6}>::_M_invoke(std::_Any_data const&, void*&&, AsyncClient*&&, std::_Any_data const&, unsigned int&&) at lib/ESPAsyncWebServer-yuboxfixes-0xFEEDC0DE64-cleanup/src/WebRequest.cpp:72
      (inlined by) _M_invoke at c:\users\zekag\.platformio\packages\toolchain-xtensa-esp32@8.4.0+2021r2-patch5\xtensa-esp32-elf\include\c++\8.4.0\bits/std_function.h:297
  #15 0x4018e1da:0x3ffda220 in std::function<void (void*, AsyncClient*, void*, unsigned int)>::operator()(void*, AsyncClient*, void*, unsigned int) const at c:\users\zekag\.platformio\packages\toolchain-xtensa-esp32@8.4.0+2021r2-patch5\xtensa-esp32-elf\include\c++\8.4.0\bits/std_function.h:687
      (inlined by) AsyncClient::_recv(tcp_pcb*, pbuf*, signed char) at .pio/libdeps/esp-wrover-kit/AsyncTCP/src/AsyncTCP.cpp:915
  #16 0x4018e255:0x3ffda250 in AsyncClient::_s_recv(void*, tcp_pcb*, pbuf*, signed char) at .pio/libdeps/esp-wrover-kit/AsyncTCP/src/AsyncTCP.cpp:1191
  #17 0x4018e8d6:0x3ffda270 in _async_service_task(void*) at .pio/libdeps/esp-wrover-kit/AsyncTCP/src/AsyncTCP.cpp:159
      (inlined by) _async_service_task at .pio/libdeps/esp-wrover-kit/AsyncTCP/src/AsyncTCP.cpp:194




ELF file SHA256: 9d0b5bbc622b8c59

Rebooting...

Other Steps to Reproduce

This error happens as soon as i want to upload a new firmware via HTTP.
I think the problem is partition related since the firmware verify process does not end.

I have checked existing issues, online documentation and the Troubleshooting Guide

• I confirm I have checked existing issues, online documentation and Troubleshooting guide.

[mrengineer7777]

@zekageri The default partition tables were recently changed to add space for a new debug area. I wonder if the OTA firmware image matches your existing device partitions?

Edit: #7566 Shrunk 'spiffs' and added 'coredump'.

[mrengineer7777]

Your debug message shows a crash not on verify but on the Update.

Looks like the crash in happening in
Updater.cpp:323 write() -> writeBuffer() and
Updater.cpp:231 _writeBuffer() -> _progress_callback()

Are you using a progress callback?

[zekageri]

Edit: #7566 Shrunk 'spiffs' and added 'coredump'.

Wow! Does this mean we can read the crash log from flash finally??

Sorry I think this was my bad. I had a line in the progress callback which printed out the progress but I used %s instead of %d in the print. I think that was the problem. Will test it asap.

The firmware still can't verify tho.

[zekageri]

That solved the firmware update problem but the verify still presist.
I'm gonna open an other issue related to that.
Thank you for your help, i really appreciate it.

The problematic part was that:

/*
*   Setting up a firmware upload progress callback.
*/
Update.onProgress([this](unsigned int progress, unsigned int total){
    int percent = (progress * 100) / total;
    if( percent == latestUpdatePercent ){ return; }
    latestUpdatePercent = percent;
    if(isDebugOn){
        debug.print(
            DEBUG_INFO,
            "Update progress: %d%%\n",
            percent
        );
    }
    serverSys.sendEvent("firmwareUpdate","Percent: %s", percent);
});

changed to

/*
*   Setting up a firmware upload progress callback.
*/
Update.onProgress([this](unsigned int progress, unsigned int total){
    int percent = (progress * 100) / total;
    if( percent == latestUpdatePercent ){ return; }
    latestUpdatePercent = percent;
    if(isDebugOn){
        debug.print(
            DEBUG_INFO,
            "Update progress: %d%%\n",
            percent
        );
    }
    serverSys.sendEvent("firmwareUpdate","Percent: %d", percent);
});

[mrengineer7777]

Wow! Does this mean we can read the crash log from flash finally??

If you use ESPInsights. Haven't played with it. It's been in IDF for a while but was recently added to Arduino level. I get the feeling it's still a work in progress.

[zekageri]

Never heard of it. Thank you i will look into.