Warnings while flashing OTA, no errors reported, OTA fails

[chromebin]

I am trying to flash an OTA partition on a slave device in the network. The master chops and sends it a firmware, the slave rebuilds it and checks the CRC, then the slave tries to flash it, but fails to do so. The code that updates the OTA is identical to the code used on the master, where it has always worked. The code essentially follows the OTA example, only error-handling is different.

Below is the output from a test program, with some comments inserted. The code is simplified to a minimum: on boot it flashes the firmware. The code causes these info/warnings (see comments in between), but nevertheless completes without error.

I suspected leftover invalid otadata might cause problems, so I have tried to erase the flash using esptool. I have adjusted the partition table to the same effect. I have flashed the firmware using esptool directly, and then all is fine. Summary: I have no clue what is going on. I do not understand what the error-messages (warning really) relate to.

Any help much appreciated!

Code: Select all

// this is the result on a reboot (after boot the code will flash the OTA, again):

rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:2
load:0x3fff0018,len:4
load:0x3fff001c,len:5988
load:0x40078000,len:9800
load:0x40080400,lets Jun  8 2016 00:22:57

rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:2
load:0x3fff0018,len:4
load:0x3fff001c,len:5988
load:0x40078000,len:9800
load:0x40080400,len:6384
entry 0x40080728
I (29) boot: ESP-IDF v3.3-beta1-328-gabea9e4c0 2nd stage bootloader
I (29) boot: compile time 16:14:47
I (29) boot: Enabling RNG early entropy source...
I (35) boot: SPI Speed      : 40MHz
I (39) boot: SPI Mode       : DIO
I (43) boot: SPI Flash Size : 4MB
I (47) boot: Partition Table:
I (51) boot: ## Label            Usage          Type ST Offset   Length
I (58) boot:  0 nvs              WiFi data        01 02 00009000 00004000
I (65) boot:  1 ota_data         OTA data         01 00 0000d000 00002000
I (73) boot:  2 phy_init         RF data          01 01 0000f000 00001000
I (80) boot:  3 factory          factory app      00 00 00010000 000c0000
I (88) boot:  4 ota_0            OTA app          00 10 000d0000 000f0000
I (95) boot:  5 ota_1            OTA app          00 11 001c0000 000f0000
I (103) boot:  6 storage          Unknown data     01 82 002b0000 00100000
I (110) boot:  7 fonts            OTA data         01 00 003b0000 00050000
I (118) boot: End of partition table
E (122) boot: ota data partition invalid, falling back to factory
I (129) esp_image: segment 0: paddr=0x00010020 vaddr=0x3f400020 size=0x1bf98 (11
4584) map
I (178) esp_image: segment 1: paddr=0x0002bfc0 vaddr=0x3ffb0000 size=0x02e50 ( 1
1856) load
I (182) esp_image: segment 2: paddr=0x0002ee18 vaddr=0x40080000 size=0x00400 (
1024) load
0x40080000: _WindowOverflow4 at C:/msys32/home/user/esp/esp-idf/components/freer
tos/xtensa_vectors.S:1779

I (185) esp_image: segment 3: paddr=0x0002f220 vaddr=0x40080400 size=0x00df0 (
3568) load
I (195) esp_image: segment 4: paddr=0x00030018 vaddr=0x400d0018 size=0x751b0 (47
9664) map
0x400d0018: _stext at ??:?

I (368) esp_image: segment 5: paddr=0x000a51d0 vaddr=0x400811f0 size=0x0fef4 ( 6
5268) load
0x400811f0: call_start_cpu0 at C:/msys32/home/user/esp/esp-idf/components/esp32/
cpu_start.c:183 (discriminator 1)

I (404) boot: Loaded app from partition at offset 0x10000
I (404) boot: Disabling RNG early entropy source...
I (405) cpu_start: Pro cpu up.
I (408) cpu_start: Application information:
I (413) cpu_start: Project name:     app-template
I (419) cpu_start: App version:      1
I (423) cpu_start: Compile time:     16:04:45
I (428) cpu_start: Compile date:     Mar  7 2019
I (433) cpu_start: ESP-IDF:          v3.3-beta1-328-gabea9e4c0
I (440) cpu_start: Starting app cpu, entry point is 0x400810fc
0x400810fc: call_start_cpu1 at C:/msys32/home/user/esp/esp-idf/components/esp32/
cpu_start.c:265

I (0) cpu_start: App cpu up.
I (450) heap_init: Initializing. RAM available for dynamic allocation:
I (457) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM
I (463) heap_init: At 3FFC3668 len 0001C998 (114 KiB): DRAM
I (469) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (476) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (482) heap_init: At 400910E4 len 0000EF1C (59 KiB): IRAM
I (488) cpu_start: Pro cpu start user code
I (171) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.



==================OTA==============

Boot partition 0:00 @0x010000
Next partition 0:16 @0x0d0000


// CODE:    esp_err_t error = esp_ota_end(ota_handle);

I (9760) esp_image: segment 0: paddr=0x000d0020 vaddr=0x3f400020 size=0x1bed8 (1
14392) map
I (9824) esp_image: segment 1: paddr=0x000ebf00 vaddr=0x3ffb0000 size=0x02e50 (
11856)
I (9832) esp_image: segment 2: paddr=0x000eed58 vaddr=0x40080000 size=0x00400 (
 1024)
0x40080000: _WindowOverflow4 at C:/msys32/home/user/esp/esp-idf/components/freer
tos/xtensa_vectors.S:1779

I (9834) esp_image: segment 3: paddr=0x000ef160 vaddr=0x40080400 size=0x00eb0 (
 3760)
I (9842) esp_image: segment 4: paddr=0x000f0018 vaddr=0x400d0018 size=0x750cc (4
79436) map
0x400d0018: _stext at ??:?

I (10116) esp_image: segment 5: paddr=0x001650ec vaddr=0x400812b0 size=0x0fe34 (
 65076)
0x400812b0: DPORT_READ_PERI_REG at C:/msys32/home/user/esp/esp-idf/components/so
c/esp32/include/soc/dport_access.h:172 (discriminator 1)
 (inlined by) call_start_cpu0 at C:/msys32/home/user/esp/esp-idf/components/esp3
2/cpu_start.c:213 (discriminator 1)


// CODE: esp_err_t err = esp_ota_set_boot_partition(partition);

I (10918) esp_image: segment 0: paddr=0x000d0020 vaddr=0x3f400020 size=0x1bed8 (
114392) map
I (10984) esp_image: segment 1: paddr=0x000ebf00 vaddr=0x3ffb0000 size=0x02e50 (
 11856)
I (10992) esp_image: segment 2: paddr=0x000eed58 vaddr=0x40080000 size=0x00400 (
  1024)
0x40080000: _WindowOverflow4 at C:/msys32/home/user/esp/esp-idf/components/freer
tos/xtensa_vectors.S:1779

I (10994) esp_image: segment 3: paddr=0x000ef160 vaddr=0x40080400 size=0x00eb0 (
  3760)
I (11002) esp_image: segment 4: paddr=0x000f0018 vaddr=0x400d0018 size=0x750cc (
479436) map
0x400d0018: _stext at ??:?

I (11276) esp_image: segment 5: paddr=0x001650ec vaddr=0x400812b0 size=0x0fe34 (
 65076)
0x400812b0: DPORT_READ_PERI_REG at C:/msys32/home/user/esp/esp-idf/components/so
c/esp32/include/soc/dport_access.h:172 (discriminator 1)
 (inlined by) call_start_cpu0 at C:/msys32/home/user/esp/esp-idf/components/esp3
2/cpu_start.c:213 (discriminator 1)

// no errors!

==================END==============

// SEE TOP TO SEE HOW THE DEVICE BOOTS 

[chromebin]

In other words, what (problem) do the messages below indicate? They occur during both esp_ota_end() and esp_ota_set_boot_partition(), from standard (example) code that works (and is silent) on one device (the network master) and not on another (a network slave).
The problem continues after a `make erase_flash`.

Code: [Select all] [Expand/Collapse]

1. I (9760) esp_image: segment 0: paddr=0x000d0020 vaddr=0x3f400020 size=0x1bed8 (114392) map
2. I (9824) esp_image: segment 1: paddr=0x000ebf00 vaddr=0x3ffb0000 size=0x02e50 (11856)
3. I (9832) esp_image: segment 2: paddr=0x000eed58 vaddr=0x40080000 size=0x00400 ( 1024)
4. 0x40080000: _WindowOverflow4 at C:/msys32/home/user/esp/esp-idf/components/freertos/xtensa_vectors.S:1779
5.  
6. I (9834) esp_image: segment 3: paddr=0x000ef160 vaddr=0x40080400 size=0x00eb0 ( 3760)
7. I (9842) esp_image: segment 4: paddr=0x000f0018 vaddr=0x400d0018 size=0x750cc (479436) map
8. 0x400d0018: _stext at ??:?
9.  
10. I (10116) esp_image: segment 5: paddr=0x001650ec vaddr=0x400812b0 size=0x0fe34 ( 65076)
11. 0x400812b0: DPORT_READ_PERI_REG at C:/msys32/home/user/esp/esp-idf/components/soc/esp32/include/soc/dport_access.h:172 (discriminator 1)
12.  (inlined by) call_start_cpu0 at C:/msys32/home/user/esp/esp-idf/components/esp32/cpu_start.c:213 (discriminator 1)

GeSHi © Codebox Plus Extension

[chromebin]

Houston we have a solution

Take a look at the partition table as reported above:

Code: [Select all] [Expand/Collapse]

1. I (103) boot:  6 storage          Unknown data     01 82 002b0000 00100000
2. I (110) boot:  7 fonts            OTA data         01 00 003b0000 00050000
3. I (118) boot: End of partition table

GeSHi © Codebox Plus Extension

Note that partition 7, which otherwise was fully functional, is of the wrong type and subtype: "OTA data 01".

I replaced the entry in the partition table with "fonts, 0x40, 0, , 0x050000," and now the OTA update works.

The info messages produced continue, but apparently they had nothing to do with the problem. Maybe they occur when the device is in 40MHz SPI mode, whereas the other device runs it at 80Mhz.

Thanks.