ESP32-S3 Simple OTA Example takes too long to update

boesmu
Posts: 1
Joined: Tue Dec 06, 2022 1:52 pm

ESP32-S3 Simple OTA Example takes too long to update

Postby boesmu » Tue Dec 06, 2022 3:36 pm

Environment:
  • Operating system: Arch Linux x86_64
  • Kernel: 6.0.10-arch2-1
  • ESP-IDF version (git describe): v4.4.3 (recently updated from v4.4.2)
  • xtensa-esp32-elf-gcc --version: xtensa-esp32-elf-gcc (crosstool-NG esp-2021r2-patch5) 8.4.0
  • Board: ESP32-S3-DevKitC-1
  • openssl version: OpenSSL 3.0.7 1 Nov 2022 (Library: OpenSSL 3.0.7 1 Nov 2022)
I am following the instructions for flashing the simple_ota_example. Also, I have compiled the Blink Example and I am serving the blink.bin through the openssl s_server.
I am using a partitions.csv with the following content for both the simple_ota_example and the blink_example:

Code: Select all

nvs, data, nvs, 0x9000, 0x4000
otadata, data, ota, 0xd000, 0x2000
phy_init, data, phy, 0xf000, 0x1000
factory, app, factory, 0x10000, 1M
ota_0, app, ota_0, , 1M
ota_1, app, ota_1, , 1M
After doing idf.py flash monitor in the simple_ota_example it gets stuck in the following log:

Code: Select all

I (6843) esp_https_ota: Writing to partition subtype 16 at offset 0x110000
Finally, after capturing some packages with Wireshark, I figure out that the transmission of the binary is done properly but the connection remains open with keep_alive packages. As soon as I close the openssl s_server the update in the ESP32 is triggered. I have tried disabling the keep_alive option in the simple_ota_example code with no change in the behavior.

If I do not manually close the server, the OTA update never happens. Well, that is not entirely true, I left the ESP32 alone for a while (more than 1 hour) and at the end someone (ESP32 or Server) gave up on mantaining the connection open and the update happened. Here the logs:

Note: the logs are from v4.4.2 but same happens with v4.4.3.

Code: Select all

--- idf_monitor on /dev/ttyACM0 115200 ---
--- Quit: Ctrl+] | Menu: Ctrl+T | Help: Ctrl+T followed by Ctrl+H ---
ESP-ROM:esp32s3-20210327
Build:Mar 27 2021
rst:0x15 (USB_UART_CHIP_RESET),boot:0x8 (SPI_FAST_FLASH_BOOT)
Saved PC:0x400490d5
SPIWP:0xee
mode:DIO, clock div:1
load:0x3fce3808,len:0x1650
load:0x403c9700,len:0xbb8
load:0x403cc700,len:0x2f88
entry 0x403c9954
I (24) boot: ESP-IDF v4.4.2 2nd stage bootloader
I (24) boot: compile time 11:04:01
I (25) boot: chip revision: 0
I (26) boot.esp32s3: Boot SPI Speed : 80MHz
I (31) boot.esp32s3: SPI Mode       : DIO
I (36) boot.esp32s3: SPI Flash Size : 4MB
I (40) boot: Enabling RNG early entropy source...
I (46) boot: Partition Table:
I (49) boot: ## Label            Usage          Type ST Offset   Length
I (57) boot:  0 nvs              WiFi data        01 02 00009000 00004000
I (64) boot:  1 otadata          OTA data         01 00 0000d000 00002000
I (72) boot:  2 phy_init         RF data          01 01 0000f000 00001000
I (79) boot:  3 factory          factory app      00 00 00010000 00100000
I (87) boot:  4 ota_0            OTA app          00 10 00110000 00100000
I (94) boot:  5 ota_1            OTA app          00 11 00210000 00100000
I (101) boot: End of partition table
I (106) boot: Defaulting to factory image
I (110) esp_image: segment 0: paddr=00010020 vaddr=3c090020 size=1b10ch (110860) map
I (139) esp_image: segment 1: paddr=0002b134 vaddr=3fc95260 size=04184h ( 16772) load
I (143) esp_image: segment 2: paddr=0002f2c0 vaddr=40374000 size=00d58h (  3416) load
I (145) esp_image: segment 3: paddr=00030020 vaddr=42000020 size=8a9a8h (567720) map
I (255) esp_image: segment 4: paddr=000ba9d0 vaddr=40374d58 size=10500h ( 66816) load
I (270) esp_image: segment 5: paddr=000caed8 vaddr=50000000 size=00010h (    16) load
I (277) boot: Loaded app from partition at offset 0x10000
I (278) boot: Disabling RNG early entropy source...
I (290) cpu_start: Pro cpu up.
I (290) cpu_start: Starting app cpu, entry point is 0x403751ec
0x403751ec: call_start_cpu1 at /home/steven/esp/esp-idf/components/esp_system/port/cpu_start.c:160

I (0) cpu_start: App cpu up.
I (304) cpu_start: Pro cpu start user code
I (304) cpu_start: cpu freq: 160000000
I (304) cpu_start: Application information:
I (307) cpu_start: Project name:     simple_ota
I (312) cpu_start: App version:      1
I (317) cpu_start: Compile time:     Dec  5 2022 11:03:48
I (323) cpu_start: ELF file SHA256:  c5aced6756fa8da1...
I (329) cpu_start: ESP-IDF:          v4.4.2
I (334) heap_init: Initializing. RAM available for dynamic allocation:
I (341) heap_init: At 3FC9CFD0 len 00043030 (268 KiB): D/IRAM
I (347) heap_init: At 3FCE0000 len 0000EE34 (59 KiB): STACK/DRAM
I (354) heap_init: At 3FCF0000 len 00008000 (32 KiB): DRAM
I (360) heap_init: At 600FE000 len 00002000 (8 KiB): RTCRAM
I (367) spi_flash: detected chip: gd
I (371) spi_flash: flash io: dio
W (375) spi_flash: Detected size(8192k) larger than the size in the binary image header(4096k). Using the size in the binary image header.
I (388) sleep: Configure to isolate all GPIO pins in sleep state
I (395) sleep: Enable automatic switching of GPIO sleep configuration
I (402) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (443) simple_ota_example: SHA-256 for bootloader:  8a3d678e51b7d46a2ff0c0b50352e399fb487b7c9b3029012d0ac98e0f0ffb0a
I (503) simple_ota_example: SHA-256 for current firmware:  31184a28bf6630c3c90010f6b7b495d206ffb5ba2ddc987f55ad10016b2f81be
I (503) pp: pp rom version: e7ae62f
I (513) net80211: net80211 rom version: e7ae62f
I (523) wifi:wifi driver task: 3fce5610, prio:23, stack:6656, core=0
I (523) system_api: Base MAC address is not set
I (523) system_api: read default base MAC address from EFUSE
I (533) wifi:wifi firmware version: eeaa27d
I (533) wifi:wifi certification version: v7.0
I (543) wifi:config NVS flash: enabled
I (543) wifi:config nano formating: disabled
I (543) wifi:Init data frame dynamic rx buffer num: 32
I (553) wifi:Init management frame dynamic rx buffer num: 32
I (553) wifi:Init management short buffer num: 32
I (563) wifi:Init dynamic tx buffer num: 32
I (563) wifi:Init static tx FG buffer num: 2
I (573) wifi:Init static rx buffer size: 1600
I (573) wifi:Init static rx buffer num: 10
I (573) wifi:Init dynamic rx buffer num: 32
I (583) wifi_init: rx ba win: 6
I (583) wifi_init: tcpip mbox: 32
I (593) wifi_init: udp mbox: 6
I (593) wifi_init: tcp mbox: 6
I (593) wifi_init: tcp tx win: 5744
I (603) wifi_init: tcp rx win: 5744
I (603) wifi_init: tcp mss: 1440
I (613) wifi_init: WiFi IRAM OP enabled
I (613) wifi_init: WiFi RX IRAM OP enabled
I (623) example_connect: Connecting to A-Sus-Router...
I (623) phy_init: phy_version 503,13653eb,Jun  1 2022,17:47:08
W (633) phy_init: failed to load RF calibration data (0x1102), falling back to full calibration
I (683) wifi:mode : sta (84:f7:03:c0:74:0c)
I (693) wifi:enable tsf
I (693) example_connect: Waiting for IP(s)
I (3103) wifi:new:<1,0>, old:<1,0>, ap:<255,255>, sta:<1,0>, prof:1
I (4063) wifi:state: init -> auth (b0)
I (4073) wifi:state: auth -> assoc (0)
I (4113) wifi:state: assoc -> run (10)
W (4133) wifi:<ba-add>idx:0 (ifx:0, f0:2f:74:99:7f:50), tid:0, ssn:0, winSize:64
I (4193) wifi:connected with A-Sus-Router, aid = 1, channel 1, BW20, bssid = f0:2f:74:99:7f:50
I (4193) wifi:security: WPA2-PSK, phy: bgn, rssi: -29
I (4193) wifi:pm start, type: 1

I (4203) wifi:set rx beacon pti, rx_bcn_pti: 0, bcn_timeout: 0, mt_pti: 25000, mt_time: 10000
I (4283) wifi:BcnInt:102400, DTIM:3
I (5003) esp_netif_handlers: example_connect: sta ip: 192.168.1.228, mask: 255.255.255.0, gw: 192.168.1.1
I (5003) example_connect: Got IPv4 event: Interface "example_connect: sta" address: 192.168.1.228
I (5503) example_connect: Got IPv6 event: Interface "example_connect: sta" address: fe80:0000:0000:0000:86f7:03ff:fec0:740c, type: ESP_IP6_ADDR_IS_LINK_LOCAL
I (5503) example_connect: Connected to example_connect: sta
I (5513) example_connect: - IPv4 address: 192.168.1.228
I (5513) example_connect: - IPv6 address: fe80:0000:0000:0000:86f7:03ff:fec0:740c, type: ESP_IP6_ADDR_IS_LINK_LOCAL
I (5523) wifi:Set ps type: 0

I (5533) simple_ota_example: Starting OTA example
I (6843) HTTP_CLIENT: Body received in fetch header state, 0x3fcedead, 467
I (6843) esp_https_ota: Starting OTA...
I (6843) esp_https_ota: Writing to partition subtype 16 at offset 0x110000
I (4420603) esp_image: segment 0: paddr=00110020 vaddr=3c020020 size=08920h ( 35104) map
I (4420603) esp_image: segment 1: paddr=00118948 vaddr=3fc91b70 size=02718h ( 10008)
I (4420613) esp_image: segment 2: paddr=0011b068 vaddr=40374000 size=04fb0h ( 20400)
I (4420623) esp_image: segment 3: paddr=00120020 vaddr=42000020 size=18aa0h (101024) map
I (4420643) esp_image: segment 4: paddr=00138ac8 vaddr=40378fb0 size=08bbch ( 35772)
I (4420643) esp_image: segment 5: paddr=0014168c vaddr=50000000 size=00010h (    16)
I (4420653) esp_image: segment 0: paddr=00110020 vaddr=3c020020 size=08920h ( 35104) map
I (4420663) esp_image: segment 1: paddr=00118948 vaddr=3fc91b70 size=02718h ( 10008)
I (4420663) esp_image: segment 2: paddr=0011b068 vaddr=40374000 size=04fb0h ( 20400)
I (4420673) esp_image: segment 3: paddr=00120020 vaddr=42000020 size=18aa0h (101024) map
I (4420693) esp_image: segment 4: paddr=00138ac8 vaddr=40378fb0 size=08bbch ( 35772)
I (4420703) esp_image: segment 5: paddr=0014168c vaddr=50000000 size=00010h (    16)
I (4420743) wifi:state: run -> init (0)
I (4420743) wifi:pm stop, total sleep time: 881697 us / 4416541038 us

W (4420743) wifi:<ba-del>idx
I (4420743) wifi:new:<1,0>, old:<1,0>, ap:<255,255>, sta:<1,0>, prof:1
I (4420923) wifi:flush txq
I (4420923) wifi:stop sw txq
I (4420923) wifi:lmac stop hw txq
I (4420923) wifi:Deinit lldesc rx mblock:10
ESP-ROM:esp32s3-20210327
Build:Mar 27 2021
rst:0xc (RTC_SW_CPU_RST),boot:0x8 (SPI_FAST_FLASH_BOOT)
Saved PC:0x403757a4
0x403757a4: esp_restart_noos at /home/steven/esp/esp-idf/components/esp_system/port/soc/esp32s3/system_internal.c:143 (discriminator 1)

SPIWP:0xee
mode:DIO, clock div:1
load:0x3fce3808,len:0x1650
load:0x403c9700,len:0xbb8
load:0x403cc700,len:0x2f88
entry 0x403c9954
I (24) boot: ESP-IDF v4.4.2 2nd stage bootloader
I (24) boot: compile time 11:04:01
I (24) boot: chip revision: 0
I (26) boot.esp32s3: Boot SPI Speed : 80MHz
I (30) boot.esp32s3: SPI Mode       : DIO
I (35) boot.esp32s3: SPI Flash Size : 4MB
I (40) boot: Enabling RNG early entropy source...
I (45) boot: Partition Table:
I (49) boot: ## Label            Usage          Type ST Offset   Length
I (56) boot:  0 nvs              WiFi data        01 02 00009000 00004000
I (64) boot:  1 otadata          OTA data         01 00 0000d000 00002000
I (71) boot:  2 phy_init         RF data          01 01 0000f000 00001000
I (79) boot:  3 factory          factory app      00 00 00010000 00100000
I (86) boot:  4 ota_0            OTA app          00 10 00110000 00100000
I (93) boot:  5 ota_1            OTA app          00 11 00210000 00100000
I (101) boot: End of partition table
I (105) esp_image: segment 0: paddr=00110020 vaddr=3c020020 size=08920h ( 35104) map
I (120) esp_image: segment 1: paddr=00118948 vaddr=3fc91b70 size=02718h ( 10008) load
I (124) esp_image: segment 2: paddr=0011b068 vaddr=40374000 size=04fb0h ( 20400) load
I (135) esp_image: segment 3: paddr=00120020 vaddr=42000020 size=18aa0h (101024) map
I (157) esp_image: segment 4: paddr=00138ac8 vaddr=40378fb0 size=08bbch ( 35772) load
I (166) esp_image: segment 5: paddr=0014168c vaddr=50000000 size=00010h (    16) load
I (171) boot: Loaded app from partition at offset 0x110000
I (172) boot: Disabling RNG early entropy source...
I (186) cpu_start: Pro cpu up.
I (186) cpu_start: Starting app cpu, entry point is 0x403751c4
0x403751c4: esp_ota_get_app_elf_sha256 at /home/steven/esp/esp-idf/components/app_update/esp_app_desc.c:96 (discriminator 1)

I (169) cpu_start: App cpu up.
I (200) cpu_start: Pro cpu start user code
I (200) cpu_start: cpu freq: 160000000
I (200) cpu_start: Application information:
I (203) cpu_start: Project name:     blink
I (208) cpu_start: App version:      1
I (212) cpu_start: Compile time:     Dec  5 2022 11:18:30
I (218) cpu_start: ELF file SHA256:  62d201966031a229...
I (224) cpu_start: ESP-IDF:          v4.4.2
I (229) heap_init: Initializing. RAM available for dynamic allocation:
I (236) heap_init: At 3FC94CB0 len 0004B350 (300 KiB): D/IRAM
I (243) heap_init: At 3FCE0000 len 0000EE34 (59 KiB): STACK/DRAM
I (250) heap_init: At 3FCF0000 len 00008000 (32 KiB): DRAM
I (256) heap_init: At 600FE000 len 00002000 (8 KiB): RTCRAM
I (262) spi_flash: detected chip: gd
I (266) spi_flash: flash io: dio
W (270) spi_flash: Detected size(8192k) larger than the size in the binary image header(4096k). Using the size in the binary image header.
I (284) sleep: Configure to isolate all GPIO pins in sleep state
I (290) sleep: Enable automatic switching of GPIO sleep configuration
I (298) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (318) example: Example configured to blink addressable LED!
I (318) example: Turning the LED OFF!
I (1328) example: Turning the LED ON!
I (2328) example: Turning the LED OFF!
I (3328) example: Turning the LED ON!
I (4328) example: Turning the LED OFF!
I (5328) example: Turning the LED ON!
I (6328) example: Turning the LED OFF!
I (7328) example: Turning the LED ON!
Thanks for your help. I hope you can help me to bring some light to this issue.

Who is online

Users browsing this forum: No registered users and 15 guests