Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

simple_ota_example fails after upgrade to idf v5.1.2 from v 5.1.1 (IDFGH-12486) #13497

Closed
3 tasks done
ghoti57 opened this issue Mar 29, 2024 · 6 comments
Closed
3 tasks done

simple_ota_example fails after upgrade to idf v5.1.2 from v 5.1.1 (IDFGH-12486) #13497

ghoti57 opened this issue Mar 29, 2024 · 6 comments
Assignees
@hmalpani
Labels
Resolution: NA Issue resolution is unavailable Status: Done Issue is done internally Type: Bug bugs in IDF

Comments

@ghoti57
Copy link

ghoti57 commented Mar 29, 2024 •
edited
Loading

Answers checklist.

  • I have read the documentation ESP-IDF Programming Guide and the issue is not addressed there.
  • I have updated my IDF branch (master or release) to the latest version and checked that the issue is present there.
  • I have searched the issue tracker for a similar issue and not found a similar issue.

IDF version.

v5.1.2

Espressif SoC revision.

esp32-s3

Operating System used.

Windows

How did you build your project?

Command line with idf.py

If you are using Windows, please specify command line type.

CMD

Development Kit.

Custom Board based on esp32-s3 WROOM-1 N16R8

Power Supply used.

USB

What is the expected behavior?

Perform OTA update from github

What is the actual behavior?

Fails with following output

`I (7475) wifi:<ba-add>idx:1 (ifx:0, 9c:a2:f4:43:a2:2c), tid:0, ssn:0, winSize:64
I (8445) esp-x509-crt-bundle: Certificate validated
I (9685) esp-x509-crt-bundle: Certificate validated
W (10425) HTTP_CLIENT: This request requires authentication, but does not provide header information for that
W (10555) HTTP_CLIENT: This request requires authentication, but does not provide header information for that
W (10675) HTTP_CLIENT: This request requires authentication, but does not provide header information for that
W (10795) HTTP_CLIENT: This request requires authentication, but does not provide header information for that
W (10915) HTTP_CLIENT: This request requires authentication, but does not provide header information for that
W (11045) HTTP_CLIENT: This request requires authentication, but does not provide header information for that
W (11165) HTTP_CLIENT: This request requires authentication, but does not provide header information for that
W (11285) HTTP_CLIENT: This request requires authentication, but does not provide header information for that
W (11415) HTTP_CLIENT: This request requires authentication, but does not provide header information for that
W (11535) HTTP_CLIENT: This request requires authentication, but does not provide header information for that
E (11655) esp_https_ota: Reached max_authorization_retries (401)
E (11655) esp_https_ota: Failed to establish HTTP connection
E (11665) simple_ota_example: Firmware upgrade failed

Steps to reproduce.

  1. Download simple_ota_example
  2. edit simple_ota_example.c to increase buffer_size_tx
    esp_http_client_config_t config = {
        .url = CONFIG_EXAMPLE_FIRMWARE_UPGRADE_URL,
#ifdef CONFIG_EXAMPLE_USE_CERT_BUNDLE
        .crt_bundle_attach = esp_crt_bundle_attach,
#else
        .cert_pem = (char *)server_cert_pem_start,
#endif /* CONFIG_EXAMPLE_USE_CERT_BUNDLE */
        .event_handler = _http_event_handler,
        .keep_alive_enable = true,
#ifdef CONFIG_EXAMPLE_FIRMWARE_UPGRADE_BIND_IF
        .if_name = &ifr,
#endif
		.buffer_size_tx=2048
    };
  1. Edit sdkconfig.defaults
# Minimum FLASH size
CONFIG_ESPTOOLPY_FLASHSIZE_8MB=y
CONFIG_PARTITION_TABLE_CUSTOM=y
CONFIG_PARTITION_TABLE_CUSTOM_FILENAME="partitions.csv"

# Use Built in USB CDC Serial
CONFIG_ESP_CONSOLE_USB_SERIAL_JTAG=y
CONFIG_ESP_CONSOLE_SECONDARY_NONE=y
CONFIG_ESP_CONSOLE_UART_NUM=-1

# Certificate bundle configuration
CONFIG_MBEDTLS_CERTIFICATE_BUNDLE_DEFAULT_CMN=y
  1. Edit Kconfig.projbuild to specify upgrade URL
    config EXAMPLE_FIRMWARE_UPGRADE_URL
        string "firmware upgrade url endpoint"
        default "https://github.com/IndaloTech/ramses_esp/releases/latest/download/ramses_esp.bin"
        help
            URL of server which hosts the firmware
            image.

  1. idf.py set-target esp32-s3

  2. idf.py menuconfig to configure wifi

  3. using idf 5.1.1
    idf.py -p COMxx fullclean build flash monitor

  4. using idf 5.1.2
    idf.py -p COMxx fullclean build flash monitor

Debug Logs.

with idf 5.1.1

I (0) cpu_start: App cpu up.
I (336) cpu_start: Pro cpu start user code
I (336) cpu_start: cpu freq: 160000000 Hz
I (336) cpu_start: Application information:
I (336) cpu_start: Project name:     simple_ota
I (337) cpu_start: App version:      1
I (337) cpu_start: Compile time:     Mar 29 2024 19:52:48
I (337) cpu_start: ELF file SHA256:  258afdcbf4821ee8...
I (337) cpu_start: ESP-IDF:          v5.1.1-dirty
I (338) cpu_start: Min chip rev:     v0.0
I (338) cpu_start: Max chip rev:     v0.99
I (338) cpu_start: Chip rev:         v0.2
I (338) heap_init: Initializing. RAM available for dynamic allocation:
I (339) heap_init: At 3FC9EFC0 len 0004A750 (297 KiB): DRAM
I (339) heap_init: At 3FCE9710 len 00005724 (21 KiB): STACK/DRAM
I (339) heap_init: At 3FCF0000 len 00008000 (32 KiB): DRAM
I (340) heap_init: At 600FE010 len 00001FD8 (7 KiB): RTCRAM
I (341) spi_flash: detected chip: generic
I (341) spi_flash: flash io: dio
W (341) spi_flash: Detected size(16384k) larger than the size in the binary image header(8192k). Using the size in the binary image header.
I (342) sleep: Configure to isolate all GPIO pins in sleep state
I (343) sleep: Enable automatic switching of GPIO sleep configuration
I (343) app_start: Starting scheduler on CPU0
I (344) app_start: Starting scheduler on CPU1
I (344) main_task: Started on CPU0
I (354) main_task: Calling app_main()
I (354) simple_ota_example: OTA example app_main start
I (374) simple_ota_example: SHA-256 for bootloader:  09003fc745b1a570f318150503aeb0811994f7099ff7a1a14b0b158a2138114a
I (454) simple_ota_example: SHA-256 for current firmware:  7660391af76ed85212430f82a59f29879498765c495da6eadf07697e7739ceb7
I (454) example_connect: Start example_connect.
I (454) pp: pp rom version: e7ae62f
I (454) net80211: net80211 rom version: e7ae62f
I (464) wifi:wifi driver task: 3fca8ea8, prio:23, stack:6656, core=0
I (474) wifi:wifi firmware version: ce9244d
I (474) wifi:wifi certification version: v7.0
I (474) wifi:config NVS flash: enabled
I (474) wifi:config nano formating: disabled
I (474) wifi:Init data frame dynamic rx buffer num: 32
I (474) wifi:Init management frame dynamic rx buffer num: 32
I (474) wifi:Init management short buffer num: 32
I (474) wifi:Init dynamic tx buffer num: 32
I (474) wifi:Init static tx FG buffer num: 2
I (474) wifi:Init static rx buffer size: 1600
I (474) wifi:Init static rx buffer num: 10
I (474) wifi:Init dynamic rx buffer num: 32
I (474) wifi_init: rx ba win: 6
I (474) wifi_init: tcpip mbox: 32
I (474) wifi_init: udp mbox: 6
I (474) wifi_init: tcp mbox: 6
I (474) wifi_init: tcp tx win: 5744
I (474) wifi_init: tcp rx win: 5744
I (474) wifi_init: tcp mss: 1440
I (474) wifi_init: WiFi IRAM OP enabled
I (474) wifi_init: WiFi RX IRAM OP enabled
I (474) phy_init: phy_version 601,98f2a71,Jun 29 2023,09:58:12
I (514) wifi:mode : sta (48:27:e2:ff:77:d0)
I (514) wifi:enable tsf
I (514) example_connect: Connecting to MyNetwork...
I (524) example_connect: Waiting for IP(s)
I (2924) wifi:new:<11,0>, old:<1,0>, ap:<255,255>, sta:<11,0>, prof:1
I (2924) wifi:state: init -> auth (b0)
I (3644) wifi:state: auth -> assoc (0)
I (3654) wifi:state: assoc -> run (10)
I (3664) wifi:connected with MyNetwork, aid = 1, channel 11, BW20, bssid = 9c:a2:f4:7d:30:0a
I (3664) wifi:security: WPA3-SAE, phy: bgn, rssi: -54
I (3664) wifi:pm start, type: 1

I (3674) wifi:set rx beacon pti, rx_bcn_pti: 0, bcn_timeout: 25000, mt_pti: 0, mt_time: 10000
I (3724) wifi:AP's beacon interval = 102400 us, DTIM period = 1
I (4174) wifi:<ba-add>idx:0 (ifx:0, 9c:a2:f4:7d:30:0a), tid:6, ssn:2, winSize:64
I (5174) esp_netif_handlers: example_netif_sta ip: 192.168.240.9, mask: 255.255.255.0, gw: 192.168.240.254
I (5174) example_connect: Got IPv4 event: Interface "example_netif_sta" address: 192.168.240.9
I (5454) example_connect: Got IPv6 event: Interface "example_netif_sta" address: fe80:0000:0000:0000:4a27:e2ff:feff:77d0, type: ESP_IP6_ADDR_IS_LINK_LOCAL
I (5454) example_common: Connected to example_netif_sta
I (5454) example_common: - IPv4 address: 192.168.240.9,
I (5454) example_common: - IPv6 address: fe80:0000:0000:0000:4a27:e2ff:feff:77d0, type: ESP_IP6_ADDR_IS_LINK_LOCAL
I (5454) wifi:Set ps type: 0, coexist: 0

I (5454) simple_ota_example: Starting OTA example task
I (5454) simple_ota_example: Attempting to download update from https://github.com/IndaloTech/ramses_esp/releases/latest/download/ramses_esp.bin
I (5454) main_task: Returned from app_main()
I (5464) wifi:<ba-add>idx:1 (ifx:0, 9c:a2:f4:7d:30:0a), tid:0, ssn:0, winSize:64
I (6404) esp-x509-crt-bundle: Certificate validated
I (7604) esp-x509-crt-bundle: Certificate validated
I (8494) esp_https_ota: Starting OTA...
I (8494) esp_https_ota: Writing to partition subtype 16 at offset 0x210000
I (22784) esp_image: segment 0: paddr=00210020 vaddr=3c0b0020 size=3cd60h (249184) map
I (22814) esp_image: segment 1: paddr=0024cd88 vaddr=3fc99400 size=03290h ( 12944)
I (22824) esp_image: segment 2: paddr=00250020 vaddr=42000020 size=af504h (718084) map
I (22914) esp_image: segment 3: paddr=002ff52c vaddr=3fc9c690 size=0156ch (  5484)
I (22924) esp_image: segment 4: paddr=00300aa0 vaddr=40374000 size=15374h ( 86900)
I (22934) esp_image: segment 0: paddr=00210020 vaddr=3c0b0020 size=3cd60h (249184) map
I (22974) esp_image: segment 1: paddr=0024cd88 vaddr=3fc99400 size=03290h ( 12944)
I (22974) esp_image: segment 2: paddr=00250020 vaddr=42000020 size=af504h (718084) map
I (23074) esp_image: segment 3: paddr=002ff52c vaddr=3fc9c690 size=0156ch (  5484)
I (23074) esp_image: segment 4: paddr=00300aa0 vaddr=40374000 size=15374h ( 86900)
I (23094) simple_ota_example: OTA Succeed, Rebooting...

with idf 5.1.2

0x40375450: call_start_cpu1 at C:/Espressif/frameworks/esp-idf-v5.1.2/components/esp_system/port/cpu_start.c:157

I (0) cpu_start: App cpu up.
I (337) cpu_start: Pro cpu start user code
I (337) cpu_start: cpu freq: 160000000 Hz
I (337) cpu_start: Application information:
I (337) cpu_start: Project name:     simple_ota
I (338) cpu_start: App version:      1
I (338) cpu_start: Compile time:     Mar 29 2024 19:03:43
I (338) cpu_start: ELF file SHA256:  0ce252131841b74b...
I (338) cpu_start: ESP-IDF:          v5.1.2-dirty
I (339) cpu_start: Min chip rev:     v0.0
I (339) cpu_start: Max chip rev:     v0.99
I (339) cpu_start: Chip rev:         v0.2
I (339) heap_init: Initializing. RAM available for dynamic allocation:
I (340) heap_init: At 3FC9EDA0 len 0004A970 (298 KiB): DRAM
I (340) heap_init: At 3FCE9710 len 00005724 (21 KiB): STACK/DRAM
I (340) heap_init: At 3FCF0000 len 00008000 (32 KiB): DRAM
I (341) heap_init: At 600FE010 len 00001FD8 (7 KiB): RTCRAM
I (342) spi_flash: detected chip: generic
I (342) spi_flash: flash io: dio
W (342) spi_flash: Detected size(16384k) larger than the size in the binary image header(8192k). Using the size in the binary image header.
I (343) sleep: Configure to isolate all GPIO pins in sleep state
I (344) sleep: Enable automatic switching of GPIO sleep configuration
I (344) app_start: Starting scheduler on CPU0
I (345) app_start: Starting scheduler on CPU1
I (345) main_task: Started on CPU0
I (355) main_task: Calling app_main()
I (355) simple_ota_example: OTA example app_main start
I (385) simple_ota_example: SHA-256 for bootloader:  a446492e62b9d9f0947b22a836a3d21efcdeb09ed6dd1883bb15b3ef435a4cae
I (465) simple_ota_example: SHA-256 for current firmware:  c03b829a95bebcb69708dd18463a5bdbb88a1fbc82fecf1fb41bd016fcd1f8ab
I (465) example_connect: Start example_connect.
I (465) pp: pp rom version: e7ae62f
I (465) net80211: net80211 rom version: e7ae62f
I (475) wifi:wifi driver task: 3fca8c04, prio:23, stack:6656, core=0
I (485) wifi:wifi firmware version: 91b9630
I (485) wifi:wifi certification version: v7.0
I (485) wifi:config NVS flash: enabled
I (485) wifi:config nano formating: disabled
I (485) wifi:Init data frame dynamic rx buffer num: 32
I (485) wifi:Init static rx mgmt buffer num: 5
I (485) wifi:Init management short buffer num: 32
I (485) wifi:Init dynamic tx buffer num: 32
I (485) wifi:Init static tx FG buffer num: 2
I (485) wifi:Init static rx buffer size: 1600
I (485) wifi:Init static rx buffer num: 10
I (485) wifi:Init dynamic rx buffer num: 32
I (485) wifi_init: rx ba win: 6
I (485) wifi_init: tcpip mbox: 32
I (485) wifi_init: udp mbox: 6
I (485) wifi_init: tcp mbox: 6
I (485) wifi_init: tcp tx win: 5744
I (485) wifi_init: tcp rx win: 5744
I (485) wifi_init: tcp mss: 1440
I (485) wifi_init: WiFi IRAM OP enabled
I (485) wifi_init: WiFi RX IRAM OP enabled
I (495) phy_init: phy_version 620,ec7ec30,Sep  5 2023,13:49:13
I (535) wifi:mode : sta (48:27:e2:ff:77:d0)
I (535) wifi:enable tsf
I (535) example_connect: Connecting to MyNetwork...
I (535) example_connect: Waiting for IP(s)
I (2945) wifi:new:<11,0>, old:<1,0>, ap:<255,255>, sta:<11,0>, prof:1
I (2945) wifi:state: init -> auth (b0)
I (3705) wifi:state: auth -> assoc (0)
I (3705) wifi:Association refused temporarily, comeback time 1000 (TUs)
I (4735) wifi:state: assoc -> assoc (0)
I (4735) wifi:state: assoc -> init (6c0)
I (4745) wifi:new:<11,0>, old:<11,0>, ap:<255,255>, sta:<11,0>, prof:1
I (4745) wifi:new:<1,0>, old:<11,0>, ap:<255,255>, sta:<1,0>, prof:1
I (4745) wifi:state: init -> auth (b0)
I (5505) wifi:state: auth -> assoc (0)
I (5515) wifi:state: assoc -> run (10)
I (5535) wifi:connected with MyNetwork, aid = 1, channel 1, BW20, bssid = 9c:a2:f4:43:a2:2c
I (5535) wifi:security: WPA3-SAE, phy: bgn, rssi: -82
I (5535) wifi:pm start, type: 1

I (5535) wifi:set rx beacon pti, rx_bcn_pti: 0, bcn_timeout: 25000, mt_pti: 0, mt_time: 10000
I (5545) wifi:<ba-add>idx:0 (ifx:0, 9c:a2:f4:43:a2:2c), tid:6, ssn:2, winSize:64
I (5545) wifi:AP's beacon interval = 102400 us, DTIM period = 1
I (6535) esp_netif_handlers: example_netif_sta ip: 192.168.240.9, mask: 255.255.255.0, gw: 192.168.240.254
I (6535) example_connect: Got IPv4 event: Interface "example_netif_sta" address: 192.168.240.9
I (7465) example_connect: Got IPv6 event: Interface "example_netif_sta" address: fe80:0000:0000:0000:4a27:e2ff:feff:77d0, type: ESP_IP6_ADDR_IS_LINK_LOCAL
I (7465) example_common: Connected to example_netif_sta
I (7465) example_common: - IPv4 address: 192.168.240.9,
I (7465) example_common: - IPv6 address: fe80:0000:0000:0000:4a27:e2ff:feff:77d0, type: ESP_IP6_ADDR_IS_LINK_LOCAL
I (7465) wifi:Set ps type: 0, coexist: 0

I (7465) simple_ota_example: Starting OTA example task
I (7465) simple_ota_example: Attempting to download update from https://github.com/IndaloTech/ramses_esp/releases/latest/download/ramses_esp.bin
I (7465) main_task: Returned from app_main()
I (7475) wifi:<ba-add>idx:1 (ifx:0, 9c:a2:f4:43:a2:2c), tid:0, ssn:0, winSize:64
I (8445) esp-x509-crt-bundle: Certificate validated
I (9685) esp-x509-crt-bundle: Certificate validated
W (10425) HTTP_CLIENT: This request requires authentication, but does not provide header information for that
W (10555) HTTP_CLIENT: This request requires authentication, but does not provide header information for that
W (10675) HTTP_CLIENT: This request requires authentication, but does not provide header information for that
W (10795) HTTP_CLIENT: This request requires authentication, but does not provide header information for that
W (10915) HTTP_CLIENT: This request requires authentication, but does not provide header information for that
W (11045) HTTP_CLIENT: This request requires authentication, but does not provide header information for that
W (11165) HTTP_CLIENT: This request requires authentication, but does not provide header information for that
W (11285) HTTP_CLIENT: This request requires authentication, but does not provide header information for that
W (11415) HTTP_CLIENT: This request requires authentication, but does not provide header information for that
W (11535) HTTP_CLIENT: This request requires authentication, but does not provide header information for that
E (11655) esp_https_ota: Reached max_authorization_retries (401)
E (11655) esp_https_ota: Failed to establish HTTP connection
E (11665) simple_ota_example: Firmware upgrade failed

```### More Information.

Is this linked to update of mbedTLS to v 3.5
Problem still exists in idf v5.2
@ghoti57 ghoti57 added the Type: Bug bugs in IDF label Mar 29, 2024
@espressif-bot espressif-bot added the Status: Opened Issue is new label Mar 29, 2024
@github-actions github-actions bot changed the title simple_ota_example fails after upgrade to idf v5.1.2 from v 5.1.1 simple_ota_example fails after upgrade to idf v5.1.2 from v 5.1.1 (IDFGH-12486) Mar 29, 2024
@espressif-bot espressif-bot added Status: In Progress Work is in progress and removed Status: Opened Issue is new labels Apr 1, 2024
@hmalpani
Copy link
Contributor

hmalpani commented Apr 1, 2024

Hello @ghoti57
Can you try reverting the commit: 9525da0 and let me know if that helps you resolve the issue.
Use command git revert 9525da090800d84e9a4eaf801cf44b940622ed78

@espressif-bot espressif-bot added Status: Done Issue is done internally Resolution: NA Issue resolution is unavailable and removed Status: In Progress Work is in progress labels Apr 1, 2024
@ghoti57
Copy link
Author

ghoti57 commented Apr 1, 2024

Hi, reverting that commit allows the OTA to work in 5.1.2

How do I progress to 5.2.1 which exhibits the same problem?

@hmalpani
Copy link
Contributor

hmalpani commented Apr 1, 2024 •
edited
Loading

Hello @ghoti57
We have fixed the issue in release/v5.2 as well. The fix should be available on GitHub soon. Until then, you can try to revert 04ac8e4 on v5.2.1.

@ghoti57
Copy link
Author

ghoti57 commented Apr 2, 2024

Reverting that commit also resolves the problem for me in v5.2.1

Do you know when the fix is likely to appear in the release branches?

@hmalpani
Copy link
Contributor

hmalpani commented Apr 2, 2024

We have backported the fix to release branches as well. The fix should be available soon.

@ghoti57
Copy link
Author

ghoti57 commented Apr 2, 2024 •
edited
Loading

thanks

@ghoti57 ghoti57 closed this as completed Apr 2, 2024
espressif-bot pushed a commit that referenced this issue Apr 3, 2024
@hmalpani
Revert "fix(esp_http_client): Call event_handler after header value i…
8d494a8 
…s received"

This reverts commit 04ac8e4.

Fixes #13497
Fixes #13097
espressif-bot pushed a commit that referenced this issue Apr 4, 2024
@hmalpani
Revert "fix(esp_http_client): Call event_handler after header value i…
2814b5a 
…s received"

This reverts commit 04ac8e4.

When `http_on_header_event` is called, event_handler is invoked and
then the current header key and header value are freed. In the previous
approach, `http_on_header_event` was called from `http_on_header_value`,
but it lead to an issue where if the value is received in multiple chunks,
then the current header key and value were freed and thus header was not
processed correctly which might result in connection issues. Calling
`http_on_heaher_event` from `http_on_header_field` ensures that the current
header field and value are processed properly

Fixes #13497
Fixes #13097
espressif-bot pushed a commit that referenced this issue Apr 12, 2024
@hmalpani
Revert "fix(esp_http_client): Call event_handler after header value i…
1451ec3 
…s received"

This reverts commit 04ac8e4.

Fixes #13497
Fixes #13097
espressif-bot pushed a commit that referenced this issue Apr 17, 2024
@hmalpani
Revert "fix(esp_http_client): Call event_handler after header value i…
9c092a3 
…s received"

This reverts commit 04ac8e4.

Fixes #13497
Fixes #13097
espressif-bot pushed a commit that referenced this issue Apr 17, 2024
@hmalpani
Revert "fix(esp_http_client): Call event_handler after header value i…
ce225df 
…s received"

This reverts commit 04ac8e4.

Fixes #13497
Fixes #13097
@ghoti57 ghoti57 mentioned this issue Apr 27, 2024
Open
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@hmalpani hmalpani

Labels
Resolution: NA Issue resolution is unavailable Status: Done Issue is done internally Type: Bug bugs in IDF
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@ghoti57 @espressif-bot @hmalpani