4G personal hotspot native OTA fail, blocked at esp_http_client_read() (IDFGH-13740)

[zheyuejiang12]

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.

v4.0.4

Espressif SoC revision.

ESP32-D0WD (revision 1)

Operating System used.

Linux

How did you build your project?

Command line with Make

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

None

Development Kit.

custom board

Power Supply used.

External 3.3V

What is the expected behavior?

4G personal hotspot OTA successfully

What is the actual behavior?

4G personal hotspot native OTA fail, blocked at esp_http_client_read()

Steps to reproduce.

1. idf v4.0.4
2. make native ota example
3. connect 4G personal hotspot
4. ota fail
   ...

Debug Logs.

st: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:12
load:0x3fff0028,len:7268
load:0x40078000,len:15744
ho 0 tail 12 room 4
load:0x40080400,len:3844
entry 0x400806b0
I (79) boot: Chip Revision: 1
I (80) boot_comm: chip revision: 1, min. bootloader chip revision: 0
W (132) rtc_clk_init: Potentially bogus XTAL frequency: 35 MHz, guessing 40 MHz
I (53) boot: ESP-IDF v4.0.4-dirty 2nd stage bootloader
I (53) boot: compile time 09:20:24
I (53) boot: Enabling RNG early entropy source...
I (58) boot: SPI Speed      : 40MHz
I (62) boot: SPI Mode       : DIO
I (66) boot: SPI Flash Size : 4MB
I (70) boot: Partition Table:
I (74) boot: ## Label            Usage          Type ST Offset   Length
I (81) boot:  0 nvs              WiFi data        01 02 00009000 00004000
I (89) boot:  1 otadata          OTA data         01 00 0000d000 00002000
I (96) boot:  2 phy_init         RF data          01 01 0000f000 00001000
I (104) boot:  3 factory          factory app      00 00 00010000 00100000
I (111) boot:  4 ota_0            OTA app          00 10 00110000 00100000
I (119) boot:  5 ota_1            OTA app          00 11 00210000 00100000
I (126) boot: End of partition table
I (131) boot: Defaulting to factory image
I (135) boot_comm: chip revision: 1, min. application chip revision: 0
I (142) esp_image: segment 0: paddr=0x00010020 vaddr=0x3f400020 size=0x20d64 (134500) map
I (199) esp_image: segment 1: paddr=0x00030d8c vaddr=0x3ffb0000 size=0x03754 ( 14164) load
I (205) esp_image: segment 2: paddr=0x000344e8 vaddr=0x40080000 size=0x00400 (  1024) load
0x40080000: _WindowOverflow4 at /home/zheyuejiang/esp/esp-idf/components/freertos/xtensa_vectors.S:1778

I (206) esp_image: segment 3: paddr=0x000348f0 vaddr=0x40080400 size=0x0b720 ( 46880) load
I (234) esp_image: segment 4: paddr=0x00040018 vaddr=0x400d0018 size=0x8dfc8 (581576) map
0x400d0018: _stext at ??:?

I (441) esp_image: segment 5: paddr=0x000cdfe8 vaddr=0x4008bb20 size=0x09bdc ( 39900) load
0x4008bb20: multi_heap_realloc_impl at /home/zheyuejiang/esp/esp-idf/components/heap/multi_heap.c:576

I (471) boot: Loaded app from partition at offset 0x10000
I (471) boot: Disabling RNG early entropy source...
I (471) cpu_start: Pro cpu up.
I (475) cpu_start: Application information:
I (480) cpu_start: Project name:     native_ota
I (485) cpu_start: App version:      1
I (489) cpu_start: Compile time:     Sep 19 2024 09:20:19
I (496) cpu_start: ELF file SHA256:  5a744ca633ee61c6...
I (501) cpu_start: ESP-IDF:          v4.0.4-dirty
I (507) cpu_start: Starting app cpu, entry point is 0x40081284
0x40081284: call_start_cpu1 at /home/zheyuejiang/esp/esp-idf/components/esp32/cpu_start.c:273

I (0) cpu_start: App cpu up.
V (517) memory_layout: reserved range is 0x3f420d5c - 0x3f420d84
D (523) memory_layout: Checking 7 reserved memory ranges:
D (528) memory_layout: Reserved memory range 0x3ffae000 - 0x3ffae6e0
D (535) memory_layout: Reserved memory range 0x3ffb0000 - 0x3ffb8ab8
D (541) memory_layout: Reserved memory range 0x3ffe0000 - 0x3ffe0440
D (548) memory_layout: Reserved memory range 0x3ffe3f20 - 0x3ffe4350
D (554) memory_layout: Reserved memory range 0x40070000 - 0x40078000
D (561) memory_layout: Reserved memory range 0x40078000 - 0x40080000
0x40080000: _WindowOverflow4 at /home/zheyuejiang/esp/esp-idf/components/freertos/xtensa_vectors.S:1778

D (567) memory_layout: Reserved memory range 0x40080000 - 0x400956fc
0x40080000: _WindowOverflow4 at /home/zheyuejiang/esp/esp-idf/components/freertos/xtensa_vectors.S:1778

D (573) memory_layout: Building list of available memory regions:
V (580) memory_layout: Examining memory region 0x3ffae000 - 0x3ffb0000
V (586) memory_layout: Start of region 0x3ffae000 - 0x3ffb0000 overlaps reserved 0x3ffae000 - 0x3ffae6e0
D (596) memory_layout: Available memory region 0x3ffae6e0 - 0x3ffb0000
V (602) memory_layout: Examining memory region 0x3ffb0000 - 0x3ffb8000
V (609) memory_layout: Region 0x3ffb0000 - 0x3ffb8000 inside of reserved 0x3ffb0000 - 0x3ffb8ab8
V (618) memory_layout: Examining memory region 0x3ffb8000 - 0x3ffc0000
V (624) memory_layout: Start of region 0x3ffb8000 - 0x3ffc0000 overlaps reserved 0x3ffb0000 - 0x3ffb8ab8
D (634) memory_layout: Available memory region 0x3ffb8ab8 - 0x3ffc0000
V (641) memory_layout: Examining memory region 0x3ffc0000 - 0x3ffc2000
D (647) memory_layout: Available memory region 0x3ffc0000 - 0x3ffc2000
V (654) memory_layout: Examining memory region 0x3ffc2000 - 0x3ffc4000
D (660) memory_layout: Available memory region 0x3ffc2000 - 0x3ffc4000
V (667) memory_layout: Examining memory region 0x3ffc4000 - 0x3ffc6000
D (674) memory_layout: Available memory region 0x3ffc4000 - 0x3ffc6000
V (680) memory_layout: Examining memory region 0x3ffc6000 - 0x3ffc8000
D (687) memory_layout: Available memory region 0x3ffc6000 - 0x3ffc8000
V (693) memory_layout: Examining memory region 0x3ffc8000 - 0x3ffca000
D (700) memory_layout: Available memory region 0x3ffc8000 - 0x3ffca000
V (707) memory_layout: Examining memory region 0x3ffca000 - 0x3ffcc000
D (713) memory_layout: Available memory region 0x3ffca000 - 0x3ffcc000
V (720) memory_layout: Examining memory region 0x3ffcc000 - 0x3ffce000
D (726) memory_layout: Available memory region 0x3ffcc000 - 0x3ffce000
V (733) memory_layout: Examining memory region 0x3ffce000 - 0x3ffd0000
D (740) memory_layout: Available memory region 0x3ffce000 - 0x3ffd0000
V (746) memory_layout: Examining memory region 0x3ffd0000 - 0x3ffd2000
D (753) memory_layout: Available memory region 0x3ffd0000 - 0x3ffd2000
V (759) memory_layout: Examining memory region 0x3ffd2000 - 0x3ffd4000
D (766) memory_layout: Available memory region 0x3ffd2000 - 0x3ffd4000
V (772) memory_layout: Examining memory region 0x3ffd4000 - 0x3ffd6000
D (779) memory_layout: Available memory region 0x3ffd4000 - 0x3ffd6000
V (786) memory_layout: Examining memory region 0x3ffd6000 - 0x3ffd8000
D (792) memory_layout: Available memory region 0x3ffd6000 - 0x3ffd8000
V (799) memory_layout: Examining memory region 0x3ffd8000 - 0x3ffda000
D (805) memory_layout: Available memory region 0x3ffd8000 - 0x3ffda000
V (812) memory_layout: Examining memory region 0x3ffda000 - 0x3ffdc000
D (819) memory_layout: Available memory region 0x3ffda000 - 0x3ffdc000
V (825) memory_layout: Examining memory region 0x3ffdc000 - 0x3ffde000
D (832) memory_layout: Available memory region 0x3ffdc000 - 0x3ffde000
V (838) memory_layout: Examining memory region 0x3ffde000 - 0x3ffe0000
D (845) memory_layout: Available memory region 0x3ffde000 - 0x3ffe0000
V (852) memory_layout: Examining memory region 0x3ffe0000 - 0x3ffe4000
V (858) memory_layout: Start of region 0x3ffe0000 - 0x3ffe4000 overlaps reserved 0x3ffe0000 - 0x3ffe0440
V (868) memory_layout: End of region 0x3ffe0440 - 0x3ffe4000 overlaps reserved 0x3ffe3f20 - 0x3ffe4350
D (877) memory_layout: Available memory region 0x3ffe0440 - 0x3ffe3f20
V (884) memory_layout: Examining memory region 0x3ffe4000 - 0x3ffe8000
V (890) memory_layout: Start of region 0x3ffe4000 - 0x3ffe8000 overlaps reserved 0x3ffe3f20 - 0x3ffe4350
D (900) memory_layout: Available memory region 0x3ffe4350 - 0x3ffe8000
V (907) memory_layout: Examining memory region 0x3ffe8000 - 0x3fff0000
D (913) memory_layout: Available memory region 0x3ffe8000 - 0x3fff0000
V (920) memory_layout: Examining memory region 0x3fff0000 - 0x3fff8000
D (926) memory_layout: Available memory region 0x3fff0000 - 0x3fff8000
V (933) memory_layout: Examining memory region 0x3fff8000 - 0x3fffc000
D (940) memory_layout: Available memory region 0x3fff8000 - 0x3fffc000
V (946) memory_layout: Examining memory region 0x3fffc000 - 0x40000000
D (953) memory_layout: Available memory region 0x3fffc000 - 0x40000000
V (959) memory_layout: Examining memory region 0x40070000 - 0x40078000
V (966) memory_layout: Region 0x40070000 - 0x40078000 inside of reserved 0x40070000 - 0x40078000
V (975) memory_layout: Examining memory region 0x40078000 - 0x40080000
0x40080000: _WindowOverflow4 at /home/zheyuejiang/esp/esp-idf/components/freertos/xtensa_vectors.S:1778

V (981) memory_layout: Region 0x40078000 - 0x40080000 inside of reserved 0x40078000 - 0x40080000
0x40080000: _WindowOverflow4 at /home/zheyuejiang/esp/esp-idf/components/freertos/xtensa_vectors.S:1778

0x40080000: _WindowOverflow4 at /home/zheyuejiang/esp/esp-idf/components/freertos/xtensa_vectors.S:1778

V (990) memory_layout: Examining memory region 0x40080000 - 0x40082000
0x40080000: _WindowOverflow4 at /home/zheyuejiang/esp/esp-idf/components/freertos/xtensa_vectors.S:1778

0x40082000: _xt_user_exc at /home/zheyuejiang/esp/esp-idf/components/freertos/xtensa_vectors.S:660

V (997) memory_layout: Region 0x40080000 - 0x40082000 inside of reserved 0x40080000 - 0x400956fc
0x40080000: _WindowOverflow4 at /home/zheyuejiang/esp/esp-idf/components/freertos/xtensa_vectors.S:1778

0x40082000: _xt_user_exc at /home/zheyuejiang/esp/esp-idf/components/freertos/xtensa_vectors.S:660

0x40080000: _WindowOverflow4 at /home/zheyuejiang/esp/esp-idf/components/freertos/xtensa_vectors.S:1778

V (1006) memory_layout: Examining memory region 0x40082000 - 0x40084000
0x40082000: _xt_user_exc at /home/zheyuejiang/esp/esp-idf/components/freertos/xtensa_vectors.S:660

0x40084000: main_flash_region_protected at /home/zheyuejiang/esp/esp-idf/components/spi_flash/spi_flash_os_func_app.c:100

V (1012) memory_layout: Region 0x40082000 - 0x40084000 inside of reserved 0x40080000 - 0x400956fc
0x40082000: _xt_user_exc at /home/zheyuejiang/esp/esp-idf/components/freertos/xtensa_vectors.S:660

0x40084000: main_flash_region_protected at /home/zheyuejiang/esp/esp-idf/components/spi_flash/spi_flash_os_func_app.c:100

0x40080000: _WindowOverflow4 at /home/zheyuejiang/esp/esp-idf/components/freertos/xtensa_vectors.S:1778

V (1021) memory_layout: Examining memory region 0x40084000 - 0x40086000
0x40084000: main_flash_region_protected at /home/zheyuejiang/esp/esp-idf/components/spi_flash/spi_flash_os_func_app.c:100

0x40086000: i2c_write_master at /home/cff/gittree/chip7.1_phy/chip_7.1/board_code/app_test/pp/phy/phy_chip_v7_ana.c:130 (discriminator 1)

V (1028) memory_layout: Region 0x40084000 - 0x40086000 inside of reserved 0x40080000 - 0x400956fc
0x40084000: main_flash_region_protected at /home/zheyuejiang/esp/esp-idf/components/spi_flash/spi_flash_os_func_app.c:100

0x40086000: i2c_write_master at /home/cff/gittree/chip7.1_phy/chip_7.1/board_code/app_test/pp/phy/phy_chip_v7_ana.c:130 (discriminator 1)

0x40080000: _WindowOverflow4 at /home/zheyuejiang/esp/esp-idf/components/freertos/xtensa_vectors.S:1778

V (1037) memory_layout: Examining memory region 0x40086000 - 0x40088000
0x40086000: i2c_write_master at /home/cff/gittree/chip7.1_phy/chip_7.1/board_code/app_test/pp/phy/phy_chip_v7_ana.c:130 (discriminator 1)

0x40088000: prvReceiveGeneric at /home/zheyuejiang/esp/esp-idf/components/esp_ringbuf/ringbuf.c:769

V (1044) memory_layout: Region 0x40086000 - 0x40088000 inside of reserved 0x40080000 - 0x400956fc
0x40086000: i2c_write_master at /home/cff/gittree/chip7.1_phy/chip_7.1/board_code/app_test/pp/phy/phy_chip_v7_ana.c:130 (discriminator 1)

0x40088000: prvReceiveGeneric at /home/zheyuejiang/esp/esp-idf/components/esp_ringbuf/ringbuf.c:769

0x40080000: _WindowOverflow4 at /home/zheyuejiang/esp/esp-idf/components/freertos/xtensa_vectors.S:1778

V (1053) memory_layout: Examining memory region 0x40088000 - 0x4008a000
0x40088000: prvReceiveGeneric at /home/zheyuejiang/esp/esp-idf/components/esp_ringbuf/ringbuf.c:769

0x4008a000: xPortGetCoreID at /home/zheyuejiang/esp/esp-idf/components/freertos/include/freertos/portable.h:211
 (inlined by) vTaskEnterCritical at /home/zheyuejiang/esp/esp-idf/components/freertos/tasks.c:4206

V (1059) memory_layout: Region 0x40088000 - 0x4008a000 inside of reserved 0x40080000 - 0x400956fc
0x40088000: prvReceiveGeneric at /home/zheyuejiang/esp/esp-idf/components/esp_ringbuf/ringbuf.c:769

0x4008a000: xPortGetCoreID at /home/zheyuejiang/esp/esp-idf/components/freertos/include/freertos/portable.h:211
 (inlined by) vTaskEnterCritical at /home/zheyuejiang/esp/esp-idf/components/freertos/tasks.c:4206

0x40080000: _WindowOverflow4 at /home/zheyuejiang/esp/esp-idf/components/freertos/xtensa_vectors.S:1778

V (1068) memory_layout: Examining memory region 0x4008a000 - 0x4008c000
0x4008a000: xPortGetCoreID at /home/zheyuejiang/esp/esp-idf/components/freertos/include/freertos/portable.h:211
 (inlined by) vTaskEnterCritical at /home/zheyuejiang/esp/esp-idf/components/freertos/tasks.c:4206

0x4008c000: ieee80211_output_process at ??:?

V (1075) memory_layout: Region 0x4008a000 - 0x4008c000 inside of reserved 0x40080000 - 0x400956fc
0x4008a000: xPortGetCoreID at /home/zheyuejiang/esp/esp-idf/components/freertos/include/freertos/portable.h:211
 (inlined by) vTaskEnterCritical at /home/zheyuejiang/esp/esp-idf/components/freertos/tasks.c:4206

0x4008c000: ieee80211_output_process at ??:?

0x40080000: _WindowOverflow4 at /home/zheyuejiang/esp/esp-idf/components/freertos/xtensa_vectors.S:1778

V (1084) memory_layout: Examining memory region 0x4008c000 - 0x4008e000
0x4008c000: ieee80211_output_process at ??:?

0x4008e000: sta_input at ??:?

V (1090) memory_layout: Region 0x4008c000 - 0x4008e000 inside of reserved 0x40080000 - 0x400956fc
0x4008c000: ieee80211_output_process at ??:?

0x4008e000: sta_input at ??:?

0x40080000: _WindowOverflow4 at /home/zheyuejiang/esp/esp-idf/components/freertos/xtensa_vectors.S:1778

V (1099) memory_layout: Examining memory region 0x4008e000 - 0x4009000x4008e000: sta_input at ??:?

00
V (1106) memory_layout: Region 0x4008e000 - 0x40090000 inside of reserved 0x40080000 - 0x400956fc
0x4008e000: sta_input at ??:?

0x40090000: ppResortTxAMPDU at ??:?

0x40080000: _WindowOverflow4 at /home/zheyuejiang/esp/esp-idf/components/freertos/xtensa_vectors.S:1778

V (1115) memory_layout: Examining memory region 0x40090000 - 0x40092000
0x40090000: ppResortTxAMPDU at ??:?

0x40092000: ppRxPkt at ??:?

V (1122) memory_layout: Region 0x40090000 - 0x40092000 inside of reserved 0x40080000 - 0x400956fc
0x40090000: ppResortTxAMPDU at ??:?

0x40092000: ppRxPkt at ??:?

0x40080000: _WindowOverflow4 at /home/zheyuejiang/esp/esp-idf/components/freertos/xtensa_vectors.S:1778

V (1131) memory_layout: Examining memory region 0x40092000 - 0x40094000
0x40092000: ppRxPkt at ??:?

0x40094000: rtc_clk_cal_internal at /home/zheyuejiang/esp/esp-idf/components/soc/esp32/rtc_time.c:48

V (1137) memory_layout: Region 0x40092000 - 0x40094000 inside of reserved 0x40080000 - 0x400956fc
0x40092000: ppRxPkt at ??:?

0x40094000: rtc_clk_cal_internal at /home/zheyuejiang/esp/esp-idf/components/soc/esp32/rtc_time.c:48

0x40080000: _WindowOverflow4 at /home/zheyuejiang/esp/esp-idf/components/freertos/xtensa_vectors.S:1778

V (1146) memory_layout: Examining memory region 0x40094000 - 0x40096000
0x40094000: rtc_clk_cal_internal at /home/zheyuejiang/esp/esp-idf/components/soc/esp32/rtc_time.c:48

V (1153) memory_layout: Start of region 0x40094000 - 0x40096000 overlaps reserved 0x40080000 - 0x400956fc
0x40094000: rtc_clk_cal_internal at /home/zheyuejiang/esp/esp-idf/components/soc/esp32/rtc_time.c:48

0x40080000: _WindowOverflow4 at /home/zheyuejiang/esp/esp-idf/components/freertos/xtensa_vectors.S:1778

D (1163) memory_layout: Available memory region 0x400956fc - 0x40096000
V (1169) memory_layout: Examining memory region 0x40096000 - 0x40098000
D (1176) memory_layout: Available memory region 0x40096000 - 0x40098000
V (1183) memory_layout: Examining memory region 0x40098000 - 0x4009a000
D (1189) memory_layout: Available memory region 0x40098000 - 0x4009a000
V (1196) memory_layout: Examining memory region 0x4009a000 - 0x4009c000
D (1203) memory_layout: Available memory region 0x4009a000 - 0x4009c000
V (1209) memory_layout: Examining memory region 0x4009c000 - 0x4009e000
D (1216) memory_layout: Available memory region 0x4009c000 - 0x4009e000
V (1223) memory_layout: Examining memory region 0x4009e000 - 0x400a0000
D (1229) memory_layout: Available memory region 0x4009e000 - 0x400a0000
I (1236) heap_init: Initializing. RAM available for dynamic allocation:
D (1243) heap_init: New heap initialised at 0x3ffae6e0
I (1249) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM
D (1255) heap_init: New heap initialised at 0x3ffb8ab8
I (1260) heap_init: At 3FFB8AB8 len 00027548 (157 KiB): DRAM
I (1266) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (1273) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
D (1279) heap_init: New heap initialised at 0x400956fc
I (1284) heap_init: At 400956FC len 0000A904 (42 KiB): IRAM
I (1291) cpu_start: Pro cpu start user code
D (1303) clk: RTC_SLOW_CLK calibration value: 3388352
V (1312) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (1312) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0xE
D (1318) intr_alloc: Connected src 46 to int 2 (cpu 0)
V (1323) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (1329) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0xC0E
D (1337) intr_alloc: Connected src 57 to int 3 (cpu 0)
V (1343) esp_dbg_stubs: esp_dbg_stubs_init stubs 3ffb3fcc
V (1349) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (1354) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0x40E
D (1363) intr_alloc: Connected src 24 to int 9 (cpu 0)
D (1368) FLASH_HAL: extra_dummy: 1
V (1371) memspi: raw_chip_id: 16405E

V (1375) memspi: chip_id: 5E4016

V (1379) memspi: raw_chip_id: 16405E

V (1382) memspi: chip_id: 5E4016

D (1386) spi_flash: trying chip: issi
D (1390) spi_flash: trying chip: gd
D (1393) spi_flash: trying chip: generic
I (1397) spi_flash: detected chip: generic
I (1402) spi_flash: flash io: dio
I (1406) cpu_start: Starting scheduler on PRO CPU.
V (0) intr_alloc: esp_intr_alloc_intrstatus (cpu 1): checking args
V (0) intr_alloc: esp_intr_alloc_intrstatus (cpu 1): Args okay. Resulting flags 0x40E
D (10) intr_alloc: Connected src 25 to int 2 (cpu 1)
I (10) cpu_start: Starting scheduler on APP CPU.
D (1456) heap_init: New heap initialised at 0x3ffe0440
D (1456) heap_init: New heap initialised at 0x3ffe4350
V (1466) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (1466) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0xE
D (1466) intr_alloc: Connected src 16 to int 12 (cpu 0)
I (1486) native_ota_example: SHA-256 for the partition table: : d1c0e9d02fa9d26cd2e1984e7b5dd20157204f501ddc83ce82229e5f3175ee8b
D (1496) esp_image: reading image header @ 0x1000
D (1506) esp_image: image header: 0xe9 0x05 0x02 0x02 400806b0
I (1506) boot_comm: chip revision: 1, min. application chip revision: 0
V (1516) esp_image: loading segment header 0 at offset 0x1018
V (1526) esp_image: segment data length 0x4 data starts 0x1020
V (1526) esp_image: segment 0 map_segment 0 segment_data_offs 0x1020 load_addr 0x3fff0018
D (1536) esp_image: free data page_count 0x0000003d
V (1546) esp_image: loading segment header 1 at offset 0x1024
V (1546) esp_image: segment data length 0xc data starts 0x102c
V (1556) esp_image: segment 1 map_segment 0 segment_data_offs 0x102c load_addr 0x3fff001c
D (1556) esp_image: free data page_count 0x0000003d
V (1566) esp_image: loading segment header 2 at offset 0x1038
V (1576) esp_image: segment data length 0x1c64 data starts 0x1040
V (1576) esp_image: segment 2 map_segment 0 segment_data_offs 0x1040 load_addr 0x3fff0028
D (1586) esp_image: free data page_count 0x0000003d
V (1596) esp_image: loading segment header 3 at offset 0x2ca4
V (1596) esp_image: segment data length 0x3d80 data starts 0x2cac
V (1606) esp_image: segment 3 map_segment 0 segment_data_offs 0x2cac load_addr 0x40078000
D (1616) esp_image: free data page_count 0x0000003d
V (1626) esp_image: loading segment header 4 at offset 0x6a2c
V (1626) esp_image: segment data length 0xf04 data starts 0x6a34
V (1626) esp_image: segment 4 map_segment 0 segment_data_offs 0x6a34 load_addr 0x40080400
D (1636) esp_image: free data page_count 0x0000003d
V (1646) esp_image: image start 0x00001000 end of last section 0x00007938
I (1646) native_ota_example: SHA-256 for bootloader: : d227c71b5f8f19cc44f42cc9e825aa276361b05d57510fcf561177217cc1450f
D (1656) partition: Loading the partition table
V (1666) calculated md5: 0x3ffbdf28   bf 25 82 2c 0f a6 d8 64  1b d9 30 25 1e 06 b4 c4  |.%.,...d..0%....|
V (1676) stored md5: 0x3f4380d0   bf 25 82 2c 0f a6 d8 64  1b d9 30 25 1e 06 b4 c4  |.%.,...d..0%....|
D (1686) partition: Partition table MD5 verified
D (1686) esp_image: reading image header @ 0x10000
D (1696) esp_image: image header: 0xe9 0x06 0x02 0x02 400812d8
I (1696) boot_comm: chip revision: 1, min. application chip revision: 0
V (1706) esp_image: loading segment header 0 at offset 0x10018
V (1716) esp_image: segment data length 0x20d64 data starts 0x10020
V (1716) esp_image: segment 0 map_segment 1 segment_data_offs 0x10020 load_addr 0x3f400020
D (1726) esp_image: free data page_count 0x0000003d
V (1776) esp_image: loading segment header 1 at offset 0x30d84
V (1776) esp_image: segment data length 0x3754 data starts 0x30d8c
V (1776) esp_image: segment 1 map_segment 0 segment_data_offs 0x30d8c load_addr 0x3ffb0000
D (1786) esp_image: free data page_count 0x0000003d
V (1796) esp_image: loading segment header 2 at offset 0x344e0
V (1796) esp_image: segment data length 0x400 data starts 0x344e8
V (1806) esp_image: segment 2 map_segment 0 segment_data_offs 0x344e8 load_addr 0x40080000
0x40080000: _WindowOverflow4 at /home/zheyuejiang/esp/esp-idf/components/freertos/xtensa_vectors.S:1778

D (1816) esp_image: free data page_count 0x0000003d
V (1816) esp_image: loading segment header 3 at offset 0x348e8
V (1826) esp_image: segment data length 0xb720 data starts 0x348f0
V (1826) esp_image: segment 3 map_segment 0 segment_data_offs 0x348f0 load_addr 0x40080400
D (1836) esp_image: free data page_count 0x0000003d
V (1856) esp_image: loading segment header 4 at offset 0x40010
V (1856) esp_image: segment data length 0x8dfc8 data starts 0x40018
V (1856) esp_image: segment 4 map_segment 1 segment_data_offs 0x40018 load_addr 0x400d0018
0x400d0018: _stext at ??:?

D (1866) esp_image: free data page_count 0x0000003d
V (2066) esp_image: loading segment header 5 at offset 0xcdfe0
V (2066) esp_image: segment data length 0x9bdc data starts 0xcdfe8
V (2066) esp_image: segment 5 map_segment 0 segment_data_offs 0xcdfe8 load_addr 0x4008bb20
0x4008bb20: multi_heap_realloc_impl at /home/zheyuejiang/esp/esp-idf/components/heap/multi_heap.c:576

D (2076) esp_image: free data page_count 0x0000003d
V (2096) esp_image: image start 0x00010000 end of last section 0x000d7bc4
D (2096) esp_image: Calculated hash: dbc17ff8f1961f127c2f28fb1c95f437ba58263136a0c3c46c851ab595981880
I (2106) native_ota_example: SHA-256 for current firmware: : dbc17ff8f1961f127c2f28fb1c95f437ba58263136a0c3c46c851ab595981880
D (2116) nvs: nvs_flash_init_custom partition=nvs start=9 count=4
D (2156) event: running task for loop 0x3ffc2998
D (2156) event: created task for loop 0x3ffc2998
D (2156) event: created event loop 0x3ffc2998
D (2156) nvs: nvs_open_from_partition misc 1
D (2156) nvs: nvs_get_str_or_blob log
I (2176) wifi:wifi driver task: 3ffc72a8, prio:23, stack:6656, core=0
V (2176) esp_adapter: thread sem create: sem=0x3ffbccec
V (2176) esp_adapter: thread sem get: sem=0x3ffbccec
I (2186) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
D (2186) efuse: coding scheme 0
D (2196) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 8 bit
D (2196) efuse: coding scheme 0
D (2206) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 0 bit
D (2216) efuse: coding scheme 0
D (2216) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 24 bit
D (2226) efuse: coding scheme 0
D (2226) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 16 bit
D (2236) efuse: coding scheme 0
D (2236) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 8 bit
D (2246) efuse: coding scheme 0
D (2246) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 0 bit
D (2256) efuse: coding scheme 0
D (2256) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 16 bit
I (2266) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
D (2276) efuse: coding scheme 0
D (2276) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 8 bit
D (2286) efuse: coding scheme 0
D (2286) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 0 bit
D (2296) efuse: coding scheme 0
D (2296) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 24 bit
D (2306) efuse: coding scheme 0
D (2306) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 16 bit
D (2316) efuse: coding scheme 0
D (2316) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 8 bit
D (2326) efuse: coding scheme 0
D (2326) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 0 bit
D (2336) efuse: coding scheme 0
D (2336) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 16 bit
D (2346) nvs: nvs_open_from_partition nvs.net80211 1
D (2346) nvs: nvs_get opmode 1
D (2356) nvs: nvs_get_str_or_blob sta.ssid
D (2356) nvs: nvs_get_str_or_blob sta.mac
D (2366) nvs: nvs_get sta.authmode 1
D (2366) nvs: nvs_get_str_or_blob sta.pswd
D (2366) nvs: nvs_get_str_or_blob sta.pmk
D (2376) nvs: nvs_get sta.chan 1
D (2376) nvs: nvs_get auto.conn 1
D (2376) nvs: nvs_get bssid.set 1
D (2386) nvs: nvs_get_str_or_blob sta.bssid
D (2386) nvs: nvs_get sta.lis_intval 2
D (2386) nvs: nvs_get sta.phym 1
D (2396) nvs: nvs_get sta.phybw 1
D (2396) nvs: nvs_get_str_or_blob sta.apsw
D (2406) nvs: nvs_get_str_or_blob sta.apinfo
D (2406) nvs: nvs_get sta.scan_method 1
D (2406) nvs: nvs_get sta.sort_method 1
D (2416) nvs: nvs_get sta.minrssi 1
D (2416) nvs: nvs_get sta.minauth 1
D (2426) nvs: nvs_get sta.pmf_e 1
D (2426) nvs: nvs_get sta.pmf_r 1
D (2426) nvs: nvs_get_str_or_blob ap.ssid
D (2436) nvs: nvs_get_str_or_blob ap.mac
D (2436) nvs: nvs_get_str_or_blob ap.passwd
D (2436) nvs: nvs_get_str_or_blob ap.pmk
D (2446) nvs: nvs_get ap.chan 1
D (2446) nvs: nvs_get ap.authmode 1
D (2446) nvs: nvs_get ap.hidden 1
D (2456) nvs: nvs_get ap.max.conn 1
D (2456) nvs: nvs_get bcn.interval 2
D (2466) nvs: nvs_get ap.phym 1
D (2466) nvs: nvs_get ap.phybw 1
D (2466) nvs: nvs_get ap.sndchan 1
D (2476) nvs: nvs_get ap.pmf_e 1
D (2476) nvs: nvs_get ap.pmf_r 1
D (2476) nvs: nvs_get lorate 1
D (2486) nvs: nvs_set ap.sndchan 1 1
D (2486) nvs: nvs_set_blob sta.mac 6
D (2486) nvs: nvs_set_blob ap.mac 6
I (2496) wifi:wifi firmware version: e58bf82
I (2496) wifi:config NVS flash: enabled
I (2496) wifi:config nano formating: disabled
I (2506) wifi:Init data frame dynamic rx buffer num: 64
I (2506) wifi:Init management frame dynamic rx buffer num: 64
I (2516) wifi:Init management short buffer num: 32
I (2516) wifi:Init dynamic tx buffer num: 32
I (2526) wifi:Init static rx buffer size: 1600
I (2526) wifi:Init static rx buffer num: 16
I (2526) wifi:Init dynamic rx buffer num: 64
V (2536) esp_adapter: thread sem get: sem=0x3ffbccec
I (2536) wifi_init: rx ba win: 16
I (2546) wifi_init: tcpip mbox: 32
I (2546) wifi_init: udp mbox: 6
I (2556) wifi_init: tcp mbox: 6
I (2556) wifi_init: tcp tx win: 5600
I (2556) wifi_init: tcp rx win: 5600
I (2566) wifi_init: tcp mss: 1400
I (2566) wifi_init: WiFi IRAM OP enabled
I (2576) wifi_init: WiFi RX IRAM OP enabled
I (2576) example_connect: Connecting to 1234...
V (2586) esp_adapter: thread sem get: sem=0x3ffbccec
V (2586) esp_adapter: thread sem get: sem=0x3ffbccec
D (2596) wifi:clear blacklist
V (2596) esp_adapter: thread sem get: sem=0x3ffbccec
D (2596) RTC_MODULE: Wi-Fi takes adc2 lock.
I (2606) phy_init: phy_version 4660,0162888,Dec 23 2020
D (2606) phy_init: loading PHY init data from application binary
D (2616) nvs: nvs_open_from_partition phy 0
D (2616) nvs: nvs_get cal_version 4
V (2626) phy_init: phy_get_rf_cal_version: 4660

D (2626) nvs: nvs_get_str_or_blob cal_mac
D (2636) efuse: coding scheme 0
D (2636) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 8 bit
D (2646) efuse: coding scheme 0
D (2646) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 0 bit
D (2656) efuse: coding scheme 0
D (2656) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 24 bit
D (2666) efuse: coding scheme 0
D (2666) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 16 bit
D (2676) efuse: coding scheme 0
D (2676) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 8 bit
D (2686) efuse: coding scheme 0
D (2686) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 0 bit
D (2696) efuse: coding scheme 0
D (2696) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 16 bit
D (2706) nvs: nvs_get_str_or_blob cal_data
D (2716) nvs: nvs_close 3
D (2716) efuse: coding scheme 0
D (2716) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 8 bit
D (2726) efuse: coding scheme 0
D (2726) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 0 bit
D (2736) efuse: coding scheme 0
D (2736) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 24 bit
D (2746) efuse: coding scheme 0
D (2746) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 16 bit
D (2756) efuse: coding scheme 0
D (2756) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 8 bit
D (2766) efuse: coding scheme 0
D (2766) efuse: In EFUSE_BLK0__DATA1_REG is used 8 bits starting with 0 bit
D (2776) efuse: coding scheme 0
D (2776) efuse: In EFUSE_BLK0__DATA2_REG is used 8 bits starting with 16 bit
V (2876) wifi:ht20 freq=2412, chan=1
D (2886) wifi:filter: set rx policy=0
I (2886) wifi:mode : sta (34:94:54:a0:3a:08)
D (2886) wifi:filter: set rx policy=1
D (2886) wifi:connect status 0 -> 0
D (2886) system_event: SYSTEM_EVENT_STA_START
D (2896) event: running post WIFI_EVENT:2 with handler 0x4013866c on loop 0x3ffc2998
0x4013866c: handle_sta_start at /home/zheyuejiang/esp/esp-idf/components/tcpip_adapter/event_handlers.c:141

V (2896) esp_adapter: thread sem create: sem=0x3ffce56c
V (2906) esp_adapter: thread sem get: sem=0x3ffce56c
V (2906) esp_adapter: thread sem get: sem=0x3ffbccec
V (2906) tcpip_adapter: check: local, if=0 fn=0x400e5e74
0x400e5e74: tcpip_adapter_start_api at /home/zheyuejiang/esp/esp-idf/components/tcpip_adapter/tcpip_adapter_lwip.c:270


V (2916) tcpip_adapter: call api in lwip: ret=0x0, give sem
V (2926) tcpip_adapter: check: remote, if=0 fn=0x400e5e74
0x400e5e74: tcpip_adapter_start_api at /home/zheyuejiang/esp/esp-idf/components/tcpip_adapter/tcpip_adapter_lwip.c:270


D (2936) wifi:Start wifi connect
D (2936) wifi:connect status 0 -> 0
D (2936) wifi:connect chan=0
V (2936) wifi:nvs=0, ssid=1234, channel=9
V (2946) wifi:ssid=1234 match nvs 0, channel=9
D (2946) wifi:first chan=9
D (2946) wifi:connect status 0 -> 1
D (2956) wifi:filter: set rx policy=3
D (2956) wifi:clear scan ap list
D (2956) wifi:start scan: type=0x50f, priority=2, cb=0x40106ed8, arg=0x0, ss_state=0x1, time=80200, index=0
0x40106ed8: cnx_start_handoff_cb at ??:?

V (2966) wifi:inter_channel_timeout: arg=0x0, ss_state=0x1
D (2976) wifi:perform scan: ss_state=0x9, chan<9,0>, dur<0,120>
V (2976) wifi:change: chan<9,0>, dur<0,120>
V (2986) wifi:ht20 freq=2452, chan=9
V (2986) wifi:enter start op, arg=0x3ffb5f74
V (2996) wifi:scan operation: state=0x3, chan<9,0>, arg=0x3ffb5f74, status=0
V (2996) wifi:scan specific ssid=1234
V (3006) wifi:start max timer
D (3126) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (3126) wifi:perform scan: ss_state=0x9, chan<1,0>, dur<0,120>
V (3126) wifi:change: chan<1,0>, dur<0,120>
V (3126) wifi:ht20 freq=2412, chan=1
V (3136) wifi:enter start op, arg=0x3ffb5f74
V (3136) wifi:scan operation: state=0x3, chan<1,0>, arg=0x3ffb5f74, status=0
V (3146) wifi:scan specific ssid=1234
V (3146) wifi:start max timer
D (3266) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (3266) wifi:perform scan: ss_state=0x9, chan<2,0>, dur<0,120>
V (3266) wifi:change: chan<2,0>, dur<0,120>
V (3276) wifi:ht20 freq=2417, chan=2
V (3276) wifi:enter start op, arg=0x3ffb5f74
V (3276) wifi:scan operation: state=0x3, chan<2,0>, arg=0x3ffb5f74, status=0
V (3286) wifi:scan specific ssid=1234
V (3286) wifi:start max timer
D (3416) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (3416) wifi:perform scan: ss_state=0x9, chan<3,0>, dur<0,120>
V (3416) wifi:change: chan<3,0>, dur<0,120>
V (3416) wifi:ht20 freq=2422, chan=3
V (3416) wifi:enter start op, arg=0x3ffb5f74
V (3426) wifi:scan operation: state=0x3, chan<3,0>, arg=0x3ffb5f74, status=0
V (3426) wifi:scan specific ssid=1234
V (3436) wifi:start max timer
D (3556) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (3556) wifi:perform scan: ss_state=0x9, chan<4,0>, dur<0,120>
V (3556) wifi:change: chan<4,0>, dur<0,120>
V (3556) wifi:ht20 freq=2427, chan=4
V (3566) wifi:enter start op, arg=0x3ffb5f74
V (3566) wifi:scan operation: state=0x3, chan<4,0>, arg=0x3ffb5f74, status=0
V (3576) wifi:scan specific ssid=1234
V (3576) wifi:start max timer
D (3696) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (3696) wifi:perform scan: ss_state=0x9, chan<5,0>, dur<0,120>
V (3696) wifi:change: chan<5,0>, dur<0,120>
V (3706) wifi:ht20 freq=2432, chan=5
V (3706) wifi:enter start op, arg=0x3ffb5f74
V (3716) wifi:scan operation: state=0x3, chan<5,0>, arg=0x3ffb5f74, status=0
V (3716) wifi:scan specific ssid=1234
V (3726) wifi:start max timer
D (3846) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (3846) wifi:perform scan: ss_state=0x9, chan<6,0>, dur<0,120>
V (3846) wifi:change: chan<6,0>, dur<0,120>
V (3846) wifi:ht20 freq=2437, chan=6
V (3856) wifi:enter start op, arg=0x3ffb5f74
V (3856) wifi:scan operation: state=0x3, chan<6,0>, arg=0x3ffb5f74, status=0
V (3866) wifi:scan specific ssid=1234
V (3866) wifi:start max timer
D (3866) wifi:rsn valid: gcipher=3 ucipher=3 akm=5

D (3876) wifi:profile match: ss_state=0x7
V (3876) wifi:scan histroy table is not full yet, add
V (3886) wifi:add ssid=1234, chan=6 to scan history
D (3906) wifi:rsn valid: gcipher=3 ucipher=3 akm=5

D (3906) wifi:set max rate: from <rate=130, phy=3, sig=0> to <rate=144, phy=3 sig=0>
D (3906) wifi:sig_b=0, sig_g=0, sig_n=0, max_b=22, max_g=108, max_n=144
D (3916) wifi:profile match: ss_state=0x7
V (3916) wifi:update scan history ssid=1234, channel=6
D (3966) wifi:rsn valid: gcipher=3 ucipher=3 akm=5

D (3966) wifi:profile match: ss_state=0x7
V (3966) wifi:update scan history ssid=1234, channel=6
D (3986) wifi:scan end: arg=0x0, status=0, ss_state=0x7
D (3986) wifi:perform scan: ss_state=0xd, chan<7,0>, dur<0,120>
V (3986) wifi:change: chan<7,0>, dur<0,120>
V (3996) wifi:ht20 freq=2442, chan=7
V (3996) wifi:enter start op, arg=0x3ffb5f74
V (3996) wifi:scan operation: state=0x7, chan<7,0>, arg=0x3ffb5f74, status=0
V (4006) wifi:scan specific ssid=1234
V (4006) wifi:start max timer
D (4136) wifi:scan end: arg=0x0, status=0, ss_state=0x7
D (4136) wifi:perform scan: ss_state=0xd, chan<8,0>, dur<0,120>
V (4136) wifi:change: chan<8,0>, dur<0,120>
V (4136) wifi:ht20 freq=2447, chan=8
V (4136) wifi:enter start op, arg=0x3ffb5f74
V (4146) wifi:scan operation: state=0x7, chan<8,0>, arg=0x3ffb5f74, status=0
V (4146) wifi:scan specific ssid=1234
V (4156) wifi:start max timer
D (4276) wifi:scan end: arg=0x0, status=0, ss_state=0x7
D (4276) wifi:perform scan: ss_state=0xd, chan<10,0>, dur<0,120>
V (4276) wifi:change: chan<10,0>, dur<0,120>
V (4276) wifi:ht20 freq=2457, chan=10
V (4286) wifi:enter start op, arg=0x3ffb5f74
V (4286) wifi:scan operation: state=0x7, chan<10,0>, arg=0x3ffb5f74, status=0
V (4296) wifi:scan specific ssid=1234
V (4296) wifi:start max timer
D (4416) wifi:scan end: arg=0x0, status=0, ss_state=0x7
D (4416) wifi:perform scan: ss_state=0xd, chan<11,0>, dur<0,120>
V (4416) wifi:change: chan<11,0>, dur<0,120>
V (4426) wifi:ht20 freq=2462, chan=11
V (4426) wifi:enter start op, arg=0x3ffb5f74
V (4426) wifi:scan operation: state=0x7, chan<11,0>, arg=0x3ffb5f74, status=0
V (4436) wifi:scan specific ssid=1234
V (4446) wifi:start max timer
D (4566) wifi:scan end: arg=0x0, status=0, ss_state=0x7
D (4566) wifi:perform scan: ss_state=0xd, chan<12,0>, dur<360,360>
V (4566) wifi:change: chan<12,0>, dur<360,360>
V (4566) wifi:ht20 freq=2467, chan=12
V (4576) wifi:enter start op, arg=0x3ffb5f74
V (4576) wifi:scan operation: state=0x7, chan<12,0>, arg=0x3ffb5f74, status=0
V (4586) wifi:passive scan, listen only
V (4586) wifi:start max timer
D (4946) wifi:scan end: arg=0x0, status=0, ss_state=0x7
D (4946) wifi:perform scan: ss_state=0xd, chan<13,0>, dur<360,360>
V (4946) wifi:change: chan<13,0>, dur<360,360>
V (4956) wifi:ht20 freq=2472, chan=13
V (4956) wifi:enter start op, arg=0x3ffb5f74
V (4956) wifi:scan operation: state=0x7, chan<13,0>, arg=0x3ffb5f74, status=0
V (4966) wifi:passive scan, listen only
V (4966) wifi:start max timer
D (5336) wifi:scan end: arg=0x0, status=0, ss_state=0x7
V (5336) wifi:back home chan=<1,0>, current chan=<13,0>
V (5336) wifi:ht20 freq=2412, chan=1
D (5336) wifi:filter: set rx policy=4
D (5336) wifi:first chan=1
V (5346) wifi:scan_done: arg=0x0, status=0, cur_time=2461648, scan_id=128, scan state=0
V (5346) wifi:call scan_done cb, arg=0x0
D (5356) wifi:handoff_cb: status=0
V (5356) wifi:best bss has set.
D (5356) wifi:ap found, mac=22:64:35:0a:78:28
V (5366) wifi:bssid=22:64:35:0a:78:28, LR=0
D (5366) wifi:new_bss=0x3ffb4a70, cur_bss=0x0, new_chan=<6,0>, cur_chan=1
D (5376) wifi:filter: set rx policy=5
I (5376) wifi:new:<6,0>, old:<1,0>, ap:<255,255>, sta:<6,0>, prof:1
V (5386) wifi:ht20 freq=2437, chan=6
D (5386) wifi:connect_op: status=0, auth=5, cipher=3 
D (5386) wifi:auth mode is not none
D (6366) wifi:connect_bss: auth=1, reconnect=0
I (6366) wifi:state: init -> auth (b0)
D (6366) wifi:start 1s AUTH timer
D (6366) wifi:clear scan ap list
D (6376) wifi:rsn valid: gcipher=3 ucipher=3 akm=5

D (6376) wifi:rsn valid: gcipher=3 ucipher=3 akm=5

D (6376) wifi:rsn valid: gcipher=3 ucipher=3 akm=5

D (6386) wifi:rsn valid: gcipher=3 ucipher=3 akm=5

D (6386) wifi:rsn valid: gcipher=3 ucipher=3 akm=5

D (6396) wifi:rsn valid: gcipher=3 ucipher=3 akm=5

D (6396) wifi:rsn valid: gcipher=3 ucipher=3 akm=5

D (6406) wifi:rsn valid: gcipher=3 ucipher=3 akm=5

D (6406) wifi:rsn valid: gcipher=3 ucipher=3 akm=5

D (6416) wifi:recv auth: seq=2, status=0
I (6416) wifi:state: auth -> assoc (0)
D (6426) wifi:restart connect 1s timer for assoc
D (6426) wifi:rsn valid: gcipher=3 ucipher=3 akm=5

D (6426) wifi:recv assoc: type=0x10
D (6436) wifi:filter: set rx policy=6
I (6436) wifi:state: assoc -> run (10)
D (6436) wifi:start 10s connect timer for 4 way handshake
V (6466) wifi:wpa_psk start
V (6466) wifi:wpa_psk handle succeed
V (6476) wifi:wpa_psk start
V (6476) wifi:wpa_psk handle succeed
I (6476) wifi:connected with 1234, aid = 1, channel 6, BW20, bssid = 22:64:35:0a:78:28
I (6476) wifi:security: WPA2-PSK, phy: bgn, rssi: -34
D (6476) wifi:remove all except 22:64:35:0a:78:28 from rc list
D (6486) wifi:clear blacklist
D (6486) wifi:filter: set rx policy=7
I (6486) wifi:pm start, type: 1

D (6496) wifi:Send sta connected event
D (6496) system_event: SYSTEM_EVENT_STA_CONNECTED, ssid:1234, ssid_len:4, bssid:22:64:35:0a:78:28, channel:6, authmode:3
D (6506) wifi:connect status 1 -> 5
D (6516) wifi:obss scan is disabled
D (6516) wifi:start obss scan: obss scan is stopped
D (6516) event: running post WIFI_EVENT:4 with handler 0x40138560 on loop 0x3ffc2998
0x40138560: handle_sta_connected at /home/zheyuejiang/esp/esp-idf/components/tcpip_adapter/event_handlers.c:157

I (6526) wifi:AP's beacon interval = 102400 us, DTIM period = 1
V (6536) esp_adapter: thread sem get: sem=0x3ffce56c
V (6536) tcpip_adapter: check: local, if=0 fn=0x400e63f4
0x400e63f4: tcpip_adapter_up_api at /home/zheyuejiang/esp/esp-idf/components/tcpip_adapter/tcpip_adapter_lwip.c:339


V (6546) tcpip_adapter: call api in lwip: ret=0x0, give sem
V (6546) tcpip_adapter: check: remote, if=0 fn=0x400e63f4
0x400e63f4: tcpip_adapter_up_api at /home/zheyuejiang/esp/esp-idf/components/tcpip_adapter/tcpip_adapter_lwip.c:339


V (6556) tcpip_adapter: check: local, if=0 fn=0x400e69a0
0x400e69a0: tcpip_adapter_dhcpc_start_api at /home/zheyuejiang/esp/esp-idf/components/tcpip_adapter/tcpip_adapter_lwip.c:1119


D (6556) tcpip_adapter: dhcp client init ip/mask/gw to all-0
D (6566) tcpip_adapter: if0 start ip lost tmr: enter
D (6576) tcpip_adapter: if0 start ip lost tmr: no need start because netif=0x3ffce5d0 interval=120 ip=0
D (6586) tcpip_adapter: dhcp client start successfully
V (6586) tcpip_adapter: call api in lwip: ret=0x0, give sem
V (6596) tcpip_adapter: check: remote, if=0 fn=0x400e69a0
0x400e69a0: tcpip_adapter_dhcpc_start_api at /home/zheyuejiang/esp/esp-idf/components/tcpip_adapter/tcpip_adapter_lwip.c:1119


D (6596) event: running post WIFI_EVENT:4 with handler 0x400e4b90 on loop 0x3ffc2998
0x400e4b90: on_wifi_connect at /home/zheyuejiang/esp/esp-idf/examples/common_components/protocol_examples_common/connect.c:112

V (6606) tcpip_adapter: check: local, if=0 fn=0x400e6788
0x400e6788: tcpip_adapter_create_ip6_linklocal_api at /home/zheyuejiang/esp/esp-idf/components/tcpip_adapter/tcpip_adapter_lwip.c:557


V (6606) tcpip_adapter: call api in lwip: ret=0x0, give sem
V (6616) tcpip_adapter: check: remote, if=0 fn=0x400e6788
0x400e6788: tcpip_adapter_create_ip6_linklocal_api at /home/zheyuejiang/esp/esp-idf/components/tcpip_adapter/tcpip_adapter_lwip.c:557


V (6736) wifi:sta recv dup seq=0 tid=6, discard
D (7656) tcpip_adapter: if0 dhcpc cb
D (7656) tcpip_adapter: if0 ip changed=1
D (7656) system_event: SYSTEM_EVENT_STA_GOT_IP, ip:172.20.10.2, mask:255.255.255.240, gw:172.20.10.1
D (7656) event: running post IP_EVENT:0 with handler 0x40138384 on loop 0x3ffc2998
0x40138384: handle_sta_got_ip at /home/zheyuejiang/esp/esp-idf/components/tcpip_adapter/event_handlers.c:101

I (7666) tcpip_adapter: sta ip: 172.20.10.2, mask: 255.255.255.240, gw: 172.20.10.1
D (7676) event: running post IP_EVENT:0 with handler 0x400e4b60 on loop 0x3ffc2998
0x400e4b60: on_got_ip at /home/zheyuejiang/esp/esp-idf/examples/common_components/protocol_examples_common/connect.c:52

D (8156) system_event: SYSTEM_EVENT_AP_STA_GOT_IP6 address fe80:0000:0000:0000:3694:54ff:fea0:3a08
D (8156) event: running post IP_EVENT:3 with handler 0x400e4b40 on loop 0x3ffc2998
0x400e4b40: on_got_ipv6 at /home/zheyuejiang/esp/esp-idf/examples/common_components/protocol_examples_common/connect.c:62

I (8156) example_connect: Connected to 1234
I (8166) example_connect: IPv4 address: 172.20.10.2
I (8166) example_connect: IPv6 address: fe80:0000:0000:0000:3694:54ff:fea0:3a08
V (8176) esp_adapter: thread sem get: sem=0x3ffbccec
I (8186) wifi:Set ps type: 0

I (8186) native_ota_example: Starting OTA example
D (8196) esp_ota_ops: found ota app max = 2
D (8196) esp_ota_ops: finding factory app...
I (8196) native_ota_example: Running partition type 0 subtype 0 (offset 0x00010000)
D (8206) HTTP_CLIENT: Begin connect to: http://yat-smart.oss-cn-shanghai.aliyuncs.com:80
D (8446) TRANS_TCP: Enable TCP keep alive. idle: 5, interval: 5, count: 3
D (8446) TRANS_TCP: [sock=54],connecting to server IP:139.196.119.65,Port:80...
D (8506) HTTP_CLIENT: Write header[3]: GET /ota/test/yat_esp32_7fc7dd.bin HTTP/1.1
User-Agent: ESP32 HTTP Client/1.0
Host: yat-smart.oss-cn-shanghai.aliyuncs.com
Content-Length: 0


D (8606) HTTP_CLIENT: on_message_begin
D (8606) HTTP_CLIENT: HEADER=Server:AliyunOSS
D (8606) HTTP_CLIENT: HEADER=Date:Thu, 19 Sep 2024 01:23:01 GMT
D (8606) HTTP_CLIENT: HEADER=Content-Type:application/octet-stream
D (8616) HTTP_CLIENT: HEADER=Content-Length:1097760
D (8616) HTTP_CLIENT: HEADER=Connection:keep-alive
D (8626) HTTP_CLIENT: HEADER=x-oss-request-id:66EB7CF50D39F73839A5CD44
D (8626) HTTP_CLIENT: HEADER=Accept-Ranges:bytes
D (8636) HTTP_CLIENT: HEADER=ETag:"5C033BFB56AE0E2FD738B3C97F1A50BF"
D (8636) HTTP_CLIENT: HEADER=Last-Modified:Mon, 09 Sep 2024 07:15:10 GMT
D (8646) HTTP_CLIENT: HEADER=x-oss-object-type:Normal
D (8656) HTTP_CLIENT: HEADER=x-oss-hash-crc64ecma:4782135042889504910
D (8656) HTTP_CLIENT: HEADER=x-oss-storage-class:Standard
D (8666) HTTP_CLIENT: HEADER=Content-Disposition:attachment
D (8666) HTTP_CLIENT: HEADER=Content-MD5:XAM7+1auDi/XOLPJfxpQvw==
D (8676) HTTP_CLIENT: HEADER=x-oss-server-time:31
D (8676) HTTP_CLIENT: http_on_headers_complete, status=200, offset=514, nread=514
D (8686) HTTP_CLIENT: http_on_body 510
D (8686) HTTP_CLIENT: content_length = 1097760
I (8696) native_ota_example: Writing to partition subtype 16 at offset 0x110000
D (8706) HTTP_CLIENT: is_data_remain=1, is_chunked=0, content_length=1097760
D (8716) HTTP_CLIENT: need_read=514, byte_to_read=512, rlen=512, ridx=510
D (8716) HTTP_CLIENT: http_on_body 512
D (8726) HTTP_CLIENT: is_data_remain=1, is_chunked=0, content_length=1097760
D (8726) HTTP_CLIENT: need_read=2, byte_to_read=2, rlen=2, ridx=1022
D (8736) HTTP_CLIENT: http_on_body 2
I (8736) native_ota_example: New firmware version: 1.8-70-g32ba94c-dirty
I (8746) native_ota_example: Running firmware version: 1
D (8756) esp_ota_ops: Invalid otadata[-1]
I (12596) native_ota_example: esp_ota_begin succeeded
D (12596) native_ota_example: Written image length 1024
D (12596) HTTP_CLIENT: is_data_remain=1, is_chunked=0, content_length=1097760
D (12606) HTTP_CLIENT: need_read=1024, byte_to_read=512, rlen=512, ridx=0
D (12606) HTTP_CLIENT: http_on_body 512
D (12606) HTTP_CLIENT: is_data_remain=1, is_chunked=0, content_length=1097760
D (12616) HTTP_CLIENT: need_read=512, byte_to_read=512, rlen=512, ridx=512
D (12626) HTTP_CLIENT: http_on_body 512
D (12626) native_ota_example: Written image length 2048
D (12636) HTTP_CLIENT: is_data_remain=1, is_chunked=0, content_length=1097760
D (12636) HTTP_CLIENT: need_read=1024, byte_to_read=512, rlen=512, ridx=0
D (12646) HTTP_CLIENT: http_on_body 512
D (12646) HTTP_CLIENT: is_data_remain=1, is_chunked=0, content_length=1097760
D (12656) HTTP_CLIENT: need_read=512, byte_to_read=512, rlen=512, ridx=512
D (12666) HTTP_CLIENT: http_on_body 512
D (12676) native_ota_example: Written image length 3072
D (12676) HTTP_CLIENT: is_data_remain=1, is_chunked=0, content_length=1097760
D (12686) HTTP_CLIENT: need_read=1024, byte_to_read=512, rlen=512, ridx=0
D (12686) HTTP_CLIENT: http_on_body 512
D (12696) HTTP_CLIENT: is_data_remain=1, is_chunked=0, content_length=1097760
D (12696) HTTP_CLIENT: need_read=512, byte_to_read=512, rlen=512, ridx=512
D (12706) HTTP_CLIENT: http_on_body 512
D (12716) native_ota_example: Written image length 4096
D (12716) HTTP_CLIENT: is_data_remain=1, is_chunked=0, content_length=1097760
D (12726) HTTP_CLIENT: need_read=1024, byte_to_read=512, rlen=512, ridx=0
D (12726) HTTP_CLIENT: http_on_body 512
D (12736) HTTP_CLIENT: is_data_remain=1, is_chunked=0, content_length=1097760
D (12746) HTTP_CLIENT: need_read=512, byte_to_read=512, rlen=512, ridx=512
D (12746) HTTP_CLIENT: http_on_body 512
D (12756) native_ota_example: Written image length 5120
D (12756) HTTP_CLIENT: is_data_remain=1, is_chunked=0, content_length=1097760
D (12766) HTTP_CLIENT: need_read=1024, byte_to_read=512, rlen=512, ridx=0
D (12766) HTTP_CLIENT: http_on_body 512
D (12776) HTTP_CLIENT: is_data_remain=1, is_chunked=0, content_length=1097760
D (12786) HTTP_CLIENT: need_read=512, byte_to_read=512, rlen=512, ridx=512
D (12786) HTTP_CLIENT: http_on_body 512
D (12796) native_ota_example: Written image length 6144
D (12796) HTTP_CLIENT: is_data_remain=1, is_chunked=0, content_length=1097760
D (12806) HTTP_CLIENT: need_read=1024, byte_to_read=512, rlen=512, ridx=0
D (12816) HTTP_CLIENT: http_on_body 512
D (12816) HTTP_CLIENT: is_data_remain=1, is_chunked=0, content_length=1097760
D (12826) HTTP_CLIENT: need_read=512, byte_to_read=512, rlen=512, ridx=512
D (12826) HTTP_CLIENT: http_on_body 512
D (12836) native_ota_example: Written image length 7168
D (12836) HTTP_CLIENT: is_data_remain=1, is_chunked=0, content_length=1097760
D (12846) HTTP_CLIENT: need_read=1024, byte_to_read=512, rlen=512, ridx=0
D (12856) HTTP_CLIENT: http_on_body 512
D (12856) HTTP_CLIENT: is_data_remain=1, is_chunked=0, content_length=1097760
D (12866) HTTP_CLIENT: need_read=512, byte_to_read=512, rlen=480, ridx=512
D (12876) HTTP_CLIENT: http_on_body 480
D (12876) HTTP_CLIENT: is_data_remain=1, is_chunked=0, content_length=1097760
D (22886) HTTP_CLIENT: need_read=32, byte_to_read=32, rlen=0, ridx=992
D (22886) native_ota_example: Written image length 8160
D (22886) HTTP_CLIENT: is_data_remain=1, is_chunked=0, content_length=1097760
D (32886) HTTP_CLIENT: need_read=1024, byte_to_read=512, rlen=0, ridx=0
D (32886) HTTP_CLIENT: Data processed 8160 != Data specified in content length 1097760
D (32886) HTTP_CLIENT: is_data_remain=1, is_chunked=0, content_length=1097760

More Information.

sdkconfig.txt

[nileshkale123]

Hello @zheyuejiang12,

Could you please check the connection status and speed? I also recommend upgrading to the latest IDF version, as support for IDF 4.0.4 has reached End-of-Life (EOL).

[zheyuejiang12]

@nileshkale123

status and speed is OK, I can definitely confirm this

Because the current project is being developed on version 4.0.4, there is currently no idea of switching branches, which may cause instability and a lot of workload. Does this issue exist on the current version 4.0.4, what is the reason for it, and is there a solution?

[nileshkale123]

Hello @zheyuejiang12,

You can test it in the latest IDF using the simple_ota_example with the appropriate configuration.

Feel free to reach out if you encounter any issues.

[nileshkale123]

I am closing this issue as this support for IDF 4.0.4 is EOL.