ESP32-S2 WPS Example Problem (IDFGH-4852)

[yusufbavas]

Environment

• Development Kit: ESP32-S2 Saola-1
• Kit version v1.2
• Module or chip used: ESP32-S2-WROOM-1
• IDF version v4.2 - v4.3-beta1 - v4.4-dev
• Compiler version xtensa-esp32-elf-gcc.exe (crosstool-NG esp-2020r3) 8.4.0
• Operating System: Windows
• Using an IDE: Visual Studio Code with esp-idf extension
• Power Supply: USB

Problem Description

I face a problem on using WPS connection. I use wps example in github(https://github.com/espressif/esp-idf/tree/master/examples/wifi/wps). Board can find wps connection but it can't connect it. I tried esp-idf v4.2, v4.3-beta1 and v4.4-dev. Both has same issue. What could be the reason of this problem.

Also I create a forum topic, if you want to reply : https://www.esp32.com/viewtopic.php?f=13&t=19696

[sagb2015]

@yusufbavas We have tested the WPS functionality on 4.2 and latest branch and there does not seem to be any problem. Can you help to run the same with supplicant debug logs enabled and provide the console logs?

[Alvin1Zhang]

@yusufbavas Thanks for reporting, would you please help share if any updates for this issue? Thanks.

[yusufbavas]

Sorry for late reply. I still have same problem. I tried latest branch and master branch again but result is same. I upload program in secure mode with --no-stub option. Can it be the reason of this problem?

Here is my console log. I enabled some debug features but I am not fimiliar with esp idf debug options. I can enable or disable some options if you want. Its seems like board get name of the network but it cant get the password. Logs says password is empty.

ESP-ROM:esp32s2-rc4-20191025
Build:Oct 25 2019
rst:0x1 (POWERON),boot:0x8 (SPI_FAST_FLASH_BOOT)
SPIWP:0xee
mode:DIO, clock div:1
load:0x3ffe6100,len:0x8
load:0x3ffe6108,len:0x22e0
load:0x4004c000,len:0xb5c
load:0x40050000,len:0x3334
SHA-256 comparison failed:
Calculated: c0e44b984a7122f885bb3184d8e8b061e44c2ee16287b1d4e60b0a2d6f0e7c4f
Expected: b4f114a6fe54dd6dc1dd3454d0ec2efaa45e9efb7d3f8c6eb495ce5127db1cd4
Attempting to boot anyway...
entry 0x4004c22c
I (68) boot: ESP-IDF v4.3-beta1 2nd stage bootloader
I (68) boot: compile time 15:12:25
D (68) bootloader_flash: mmu set block paddr=0x00000000 (was 0xffffffff)
I (73) boot: chip revision: 0
D (77) boot.esp32s2: magic e9
D (80) boot.esp32s2: segments 04
D (83) boot.esp32s2: spi_mode 02
D (86) boot.esp32s2: spi_speed 0f
D (90) boot.esp32s2: spi_size 02
I (93) boot.esp32s2: SPI Speed      : 80MHz
I (98) boot.esp32s2: SPI Mode       : DIO
I (103) boot.esp32s2: SPI Flash Size : 4MB
D (107) boot: Enabling RTCWDT(9000 ms)
I (111) boot: Enabling RNG early entropy source...
D (117) bootloader_flash: mmu set paddr=00000000 count=1 size=c00 src_addr=8000 src_addr_aligned=0
D (126) boot: mapped partition table 0x8000 at 0x3f008000
D (131) flash_parts: partition table verified, 4 entries
I (137) boot: Partition Table:
I (140) boot: ## Label            Usage          Type ST Offset   Length
D (148) boot: load partition table entry 0x3f008000
D (153) boot: type=1 subtype=2
I (156) boot:  0 nvs              WiFi data        01 02 00009000 00006000
D (163) boot: load partition table entry 0x3f008020
D (168) boot: type=1 subtype=1
I (171) boot:  1 phy_init         RF data          01 01 0000f000 00001000
D (179) boot: load partition table entry 0x3f008040
D (184) boot: type=0 subtype=0
I (187) boot:  2 factory          factory app      00 00 00010000 00100000
I (195) boot: End of partition table
D (199) boot: Trying partition index -1 offs 0x10000 size 0x100000
D (205) esp_image: reading image header @ 0x10000
D (210) bootloader_flash: mmu set block paddr=0x00010000 (was 0xffffffff)
D (217) esp_image: image header: 0xe9 0x06 0x02 0x01 400231f8
V (222) esp_image: loading segment header 0 at offset 0x10018
V (228) esp_image: segment data length 0x189cc data starts 0x10020
V (235) esp_image: segment 0 map_segment 1 segment_data_offs 0x10020 load_addr 0x3f000020
I (243) esp_image: segment 0: paddr=00010020 vaddr=3f000020 size=189cch (100812) map
D (251) esp_image: free data page_count 0x0000003f
D (256) bootloader_flash: mmu set paddr=00010000 count=2 size=189cc src_addr=10020 src_addr_aligned=10000
V (285) esp_image: loading segment header 1 at offset 0x289ec
D (285) bootloader_flash: mmu set block paddr=0x00020000 (was 0xffffffff)
V (286) esp_image: segment data length 0x3f04 data starts 0x289f4
V (293) esp_image: segment 1 map_segment 0 segment_data_offs 0x289f4 load_addr 0x3ffc6520
I (301) esp_image: segment 1: paddr=000289f4 vaddr=3ffc6520 size=03f04h ( 16132) load
D (309) esp_image: free data page_count 0x0000003f
D (314) bootloader_flash: mmu set paddr=00020000 count=1 size=3f04 src_addr=289f4 src_addr_aligned=20000
V (327) esp_image: loading segment header 2 at offset 0x2c8f8
D (330) bootloader_flash: mmu set block paddr=0x00020000 (was 0xffffffff)
V (336) esp_image: segment data length 0x404 data starts 0x2c900
V (343) esp_image: segment 2 map_segment 0 segment_data_offs 0x2c900 load_addr 0x40022000
0x40022000: _WindowOverflow4 at C:/Users/Administrator/esp/esp-idf-v4.3-beta1/esp-idf/components/freertos/port/xtensa/xtensa_vectors.S:1730

I (351) esp_image: segment 2: paddr=0002c900 vaddr=40022000 size=00404h (  1028) load
D (359) esp_image: free data page_count 0x0000003f
D (364) bootloader_flash: mmu set paddr=00020000 count=1 size=404 src_addr=2c900 src_addr_aligned=20000
V (374) esp_image: loading segment header 3 at offset 0x2cd04
D (379) bootloader_flash: mmu set block paddr=0x00020000 (was 0xffffffff)
V (386) esp_image: segment data length 0x330c data starts 0x2cd0c
V (392) esp_image: segment 3 map_segment 0 segment_data_offs 0x2cd0c load_addr 0x40022404
0x40022404: _coredump_iram_start at ??:?

I (401) esp_image: segment 3: paddr=0002cd0c vaddr=40022404 size=0330ch ( 13068) load
D (409) esp_image: free data page_count 0x0000003f
D (414) bootloader_flash: mmu set paddr=00020000 count=2 size=330c src_addr=2cd0c src_addr_aligned=20000
V (427) esp_image: loading segment header 4 at offset 0x30018
D (429) bootloader_flash: mmu set block paddr=0x00030000 (was 0xffffffff)
V (436) esp_image: segment data length 0x73878 data starts 0x30020
V (443) esp_image: segment 4 map_segment 1 segment_data_offs 0x30020 load_addr 0x40080020
0x40080020: _stext at ??:?

I (451) esp_image: segment 4: paddr=00030020 vaddr=40080020 size=73878h (473208) map
D (459) esp_image: free data page_count 0x0000003f
D (464) bootloader_flash: mmu set paddr=00030000 count=8 size=73878 src_addr=30020 src_addr_aligned=30000
V (564) esp_image: loading segment header 5 at offset 0xa3898
D (564) bootloader_flash: mmu set block paddr=0x000a0000 (was 0xffffffff)
V (565) esp_image: segment data length 0x10e10 data starts 0xa38a0
V (571) esp_image: segment 5 map_segment 0 segment_data_offs 0xa38a0 load_addr 0x40025710
0x40025710: spi1_flash_os_check_yield at C:/Users/Administrator/esp/esp-idf-v4.3-beta1/esp-idf/components/spi_flash/spi_flash_os_func_app.c:127 (discriminator 1)

I (580) esp_image: segment 5: paddr=000a38a0 vaddr=40025710 size=10e10h ( 69136) load
D (588) esp_image: free data page_count 0x0000003f
D (593) bootloader_flash: mmu set paddr=000a0000 count=2 size=10e10 src_addr=a38a0 src_addr_aligned=a0000
V (619) esp_image: image start 0x00010000 end of last section 0x000b46b0
D (619) bootloader_flash: mmu set block paddr=0x000b0000 (was 0xffffffff)
D (622) boot: Calculated hash: d09ffcf622f195df4ba03003450e1a318071d801ab17a9b67d2c9362e3dd0b30
D (630) bootloader_flash: mmu set paddr=000b0000 count=1 size=20 src_addr=b46c0 src_addr_aligned=b0000
D (640) bootloader_flash: mmu set paddr=000b0000 count=1 size=20 src_addr=b46c0 src_addr_aligned=b0000
I (660) boot: Loaded app from partition at offset 0x10000
I (660) boot: Disabling RNG early entropy source...
D (661) boot: Mapping segment 0 as DROM
D (665) boot: Mapping segment 4 as IROM
D (669) boot: calling set_cache_and_start_app
D (673) boot: configure drom and irom and start
V (678) boot: d mmu set paddr=00010000 vaddr=3f000000 size=100812 n=2
V (684) boot: rc=0
V (686) boot: i mmu set paddr=00030000 vaddr=40080000 size=473208 n=8
V (693) boot: rc=0
D (695) boot: start: 0x400231f8
0x400231f8: call_start_cpu0 at C:/Users/Administrator/esp/esp-idf-v4.3-beta1/esp-idf/components/esp_system/port/cpu_start.c:254

I (709) cache: Instruction cache        : size 8KB, 4Ways, cache line size 32Byte
I (709) cpu_start: Pro cpu up.
C:/Users/Administrator/esp/esp-idf-v4.3-beta1/esp-idf/components/freertos/queue.c:1441 (xQueueSemaphoreTake)- assert failed!

abort() was called at PC 0x4002af03 on core 0
0x4002af03: xQueueSemaphoreTake at C:/Users/Administrator/esp/esp-idf-v4.3-beta1/esp-idf/components/freertos/queue.c:1441 (discriminator 1)

Backtrace:0x400299ff:0x3fffe070 0x4002a28d:0x3fffe090 0x40030f66:0x3fffe0b0 0x4002af03:0x3fffe120 0x4002fa52:0x3fffe160 0x400f3745:0x3fffe180 0x4002f9e9:0x3fffe1b0 0x40086795:0x3fffe200 0x4008669d:0x3fffe260 0x400f3425:0x3fffe280 0x400822f8:0x3fffe2b0 0x4002324e:0x3fffe300 0x40050fb1:0x3fffe320 0x40051515:0x3fffe370 0x4004c27d:0x3fffe4a0 0x40011371:0x3fffe560 0x4000f788:0x3fffe6f0 0x400072a5:0x3fffe710
0x400299ff: panic_abort at C:/Users/Administrator/esp/esp-idf-v4.3-beta1/esp-idf/components/esp_system/panic.c:356

0x4002a28d: esp_system_abort at C:/Users/Administrator/esp/esp-idf-v4.3-beta1/esp-idf/components/esp_system/system_api.c:112

0x40030f66: abort at C:/Users/Administrator/esp/esp-idf-v4.3-beta1/esp-idf/components/newlib/abort.c:46

0x4002af03: xQueueSemaphoreTake at C:/Users/Administrator/esp/esp-idf-v4.3-beta1/esp-idf/components/freertos/queue.c:1441 (discriminator 1)

0x4002fa52: esp_log_impl_lock_timeout at C:/Users/Administrator/esp/esp-idf-v4.3-beta1/esp-idf/components/log/log_freertos.c:45

0x400f3745: esp_log_writev at C:/Users/Administrator/esp/esp-idf-v4.3-beta1/esp-idf/components/log/log.c:170

0x4002f9e9: esp_log_write at C:/Users/Administrator/esp/esp-idf-v4.3-beta1/esp-idf/components/log/log.c:199

0x40086795: esp_efuse_utility_process at C:/Users/Administrator/esp/esp-idf-v4.3-beta1/esp-idf/components/efuse/src/esp_efuse_utility.c:71 (discriminator 9)

0x4008669d: esp_efuse_read_field_blob at C:/Users/Administrator/esp/esp-idf-v4.3-beta1/esp-idf/components/efuse/src/esp_efuse_api.c:47

0x400f3425: rtc_init at C:/Users/Administrator/esp/esp-idf-v4.3-beta1/esp-idf/components/esp_hw_support/port/esp32s2/rtc_init.c:156

0x400822f8: esp_clk_init at C:/Users/Administrator/esp/esp-idf-v4.3-beta1/esp-idf/components/esp_system/port/soc/esp32s2/clk.c:84

0x4002324e: call_start_cpu0 at C:/Users/Administrator/esp/esp-idf-v4.3-beta1/esp-idf/components/esp_system/port/cpu_start.c:445

ELF file SHA256: 66af5571fe74d094

Rebooting...
ESP-ROM:esp32s2-rc4-20191025
Build:Oct 25 2019
rst:0xc (RTC_SW_CPU_RST),boot:0x8 (SPI_FAST_FLASH_BOOT)
Saved PC:0x40023f3c
0x40023f3c: esp_restart_noos at C:/Users/Administrator/esp/esp-idf-v4.3-beta1/esp-idf/components/esp32s2/system_api_esp32s2.c:109 (discriminator 1)

SPIWP:0xee
mode:DIO, clock div:1
load:0x3ffe6100,len:0x8
load:0x3ffe6108,len:0x22e0
load:0x4004c000,len:0xb5c
load:0x40050000,len:0x3334
SHA-256 comparison failed:
Calculated: c0e44b984a7122f885bb3184d8e8b061e44c2ee16287b1d4e60b0a2d6f0e7c4f
Expected: b4f114a6fe54dd6dc1dd3454d0ec2efaa45e9efb7d3f8c6eb495ce5127db1cd4
Attempting to boot anyway...
entry 0x4004c22c
I (70) boot: ESP-IDF v4.3-beta1 2nd stage bootloader
I (70) boot: compile time 15:12:25
D (70) bootloader_flash: mmu set block paddr=0x00000000 (was 0xffffffff)
I (76) boot: chip revision: 0
D (80) boot.esp32s2: magic e9
D (82) boot.esp32s2: segments 04
D (85) boot.esp32s2: spi_mode 02
D (89) boot.esp32s2: spi_speed 0f
D (92) boot.esp32s2: spi_size 02
I (95) boot.esp32s2: SPI Speed      : 80MHz
I (100) boot.esp32s2: SPI Mode       : DIO
I (105) boot.esp32s2: SPI Flash Size : 4MB
D (110) boot: Enabling RTCWDT(9000 ms)
I (114) boot: Enabling RNG early entropy source...
D (119) bootloader_flash: mmu set paddr=00000000 count=1 size=c00 src_addr=8000 src_addr_aligned=0
D (128) boot: mapped partition table 0x8000 at 0x3f008000
D (134) flash_parts: partition table verified, 4 entries
I (139) boot: Partition Table:
I (143) boot: ## Label            Usage          Type ST Offset   Length
D (150) boot: load partition table entry 0x3f008000
D (155) boot: type=1 subtype=2
I (158) boot:  0 nvs              WiFi data        01 02 00009000 00006000
D (166) boot: load partition table entry 0x3f008020
D (171) boot: type=1 subtype=1
I (174) boot:  1 phy_init         RF data          01 01 0000f000 00001000
D (181) boot: load partition table entry 0x3f008040
D (186) boot: type=0 subtype=0
I (189) boot:  2 factory          factory app      00 00 00010000 00100000
I (197) boot: End of partition table
D (201) boot: Trying partition index -1 offs 0x10000 size 0x100000
D (208) esp_image: reading image header @ 0x10000
D (212) bootloader_flash: mmu set block paddr=0x00010000 (was 0xffffffff)
D (219) esp_image: image header: 0xe9 0x06 0x02 0x01 400231f8
V (225) esp_image: loading segment header 0 at offset 0x10018
V (231) esp_image: segment data length 0x189cc data starts 0x10020
V (237) esp_image: segment 0 map_segment 1 segment_data_offs 0x10020 load_addr 0x3f000020
I (245) esp_image: segment 0: paddr=00010020 vaddr=3f000020 size=189cch (100812) map
D (254) esp_image: free data page_count 0x0000003f
D (259) bootloader_flash: mmu set paddr=00010000 count=2 size=189cc src_addr=10020 src_addr_aligned=10000
V (288) esp_image: loading segment header 1 at offset 0x289ec
D (288) bootloader_flash: mmu set block paddr=0x00020000 (was 0xffffffff)
V (289) esp_image: segment data length 0x3f04 data starts 0x289f4
V (295) esp_image: segment 1 map_segment 0 segment_data_offs 0x289f4 load_addr 0x3ffc6520
I (303) esp_image: segment 1: paddr=000289f4 vaddr=3ffc6520 size=03f04h ( 16132) load
D (312) esp_image: free data page_count 0x0000003f
D (317) bootloader_flash: mmu set paddr=00020000 count=1 size=3f04 src_addr=289f4 src_addr_aligned=20000
V (330) esp_image: loading segment header 2 at offset 0x2c8f8
D (332) bootloader_flash: mmu set block paddr=0x00020000 (was 0xffffffff)
V (339) esp_image: segment data length 0x404 data starts 0x2c900
V (345) esp_image: segment 2 map_segment 0 segment_data_offs 0x2c900 load_addr 0x40022000
0x40022000: _WindowOverflow4 at C:/Users/Administrator/esp/esp-idf-v4.3-beta1/esp-idf/components/freertos/port/xtensa/xtensa_vectors.S:1730

I (353) esp_image: segment 2: paddr=0002c900 vaddr=40022000 size=00404h (  1028) load
D (362) esp_image: free data page_count 0x0000003f
D (367) bootloader_flash: mmu set paddr=00020000 count=1 size=404 src_addr=2c900 src_addr_aligned=20000
V (376) esp_image: loading segment header 3 at offset 0x2cd04
D (382) bootloader_flash: mmu set block paddr=0x00020000 (was 0xffffffff)
V (389) esp_image: segment data length 0x330c data starts 0x2cd0c
V (395) esp_image: segment 3 map_segment 0 segment_data_offs 0x2cd0c load_addr 0x40022404
0x40022404: _coredump_iram_start at ??:?

I (403) esp_image: segment 3: paddr=0002cd0c vaddr=40022404 size=0330ch ( 13068) load
D (412) esp_image: free data page_count 0x0000003f
D (417) bootloader_flash: mmu set paddr=00020000 count=2 size=330c src_addr=2cd0c src_addr_aligned=20000
V (429) esp_image: loading segment header 4 at offset 0x30018
D (432) bootloader_flash: mmu set block paddr=0x00030000 (was 0xffffffff)
V (439) esp_image: segment data length 0x73878 data starts 0x30020
V (445) esp_image: segment 4 map_segment 1 segment_data_offs 0x30020 load_addr 0x40080020
0x40080020: _stext at ??:?

I (453) esp_image: segment 4: paddr=00030020 vaddr=40080020 size=73878h (473208) map
D (462) esp_image: free data page_count 0x0000003f
D (467) bootloader_flash: mmu set paddr=00030000 count=8 size=73878 src_addr=30020 src_addr_aligned=30000
V (566) esp_image: loading segment header 5 at offset 0xa3898
D (566) bootloader_flash: mmu set block paddr=0x000a0000 (was 0xffffffff)
V (568) esp_image: segment data length 0x10e10 data starts 0xa38a0
V (574) esp_image: segment 5 map_segment 0 segment_data_offs 0xa38a0 load_addr 0x40025710
0x40025710: spi1_flash_os_check_yield at C:/Users/Administrator/esp/esp-idf-v4.3-beta1/esp-idf/components/spi_flash/spi_flash_os_func_app.c:127 (discriminator 1)

I (582) esp_image: segment 5: paddr=000a38a0 vaddr=40025710 size=10e10h ( 69136) load
D (591) esp_image: free data page_count 0x0000003f
D (595) bootloader_flash: mmu set paddr=000a0000 count=2 size=10e10 src_addr=a38a0 src_addr_aligned=a0000
V (622) esp_image: image start 0x00010000 end of last section 0x000b46b0
D (622) bootloader_flash: mmu set block paddr=0x000b0000 (was 0xffffffff)
D (624) boot: Calculated hash: d09ffcf622f195df4ba03003450e1a318071d801ab17a9b67d2c9362e3dd0b30
D (633) bootloader_flash: mmu set paddr=000b0000 count=1 size=20 src_addr=b46c0 src_addr_aligned=b0000
D (642) bootloader_flash: mmu set paddr=000b0000 count=1 size=20 src_addr=b46c0 src_addr_aligned=b0000
I (663) boot: Loaded app from partition at offset 0x10000
I (663) boot: Disabling RNG early entropy source...
D (663) boot: Mapping segment 0 as DROM
D (667) boot: Mapping segment 4 as IROM
D (671) boot: calling set_cache_and_start_app
D (676) boot: configure drom and irom and start
V (680) boot: d mmu set paddr=00010000 vaddr=3f000000 size=100812 n=2
V (687) boot: rc=0
V (689) boot: i mmu set paddr=00030000 vaddr=40080000 size=473208 n=8
V (695) boot: rc=0
D (697) boot: start: 0x400231f8
0x400231f8: call_start_cpu0 at C:/Users/Administrator/esp/esp-idf-v4.3-beta1/esp-idf/components/esp_system/port/cpu_start.c:254

I (712) cache: Instruction cache        : size 8KB, 4Ways, cache line size 32Byte
I (712) cpu_start: Pro cpu up.
D (769) clk: RTC_SLOW_CLK calibration value: 6232041
I (775) cpu_start: Pro cpu start user code
I (775) cpu_start: cpu freq: 160000000
I (775) cpu_start: Application information:
I (779) cpu_start: Project name:     wps_example
I (784) cpu_start: App version:      1
I (789) cpu_start: Compile time:     Mar 22 2021 15:12:53
I (795) cpu_start: ELF file SHA256:  66af5571fe74d094...
I (801) cpu_start: ESP-IDF:          v4.3-beta1
V (806) memory_layout: reserved range is 0x3f0189cc - 0x3f0189ec
D (812) memory_layout: Checking 4 reserved memory ranges:
D (818) memory_layout: Reserved memory range 0x3ff9e000 - 0x3ff9e000
D (824) memory_layout: Reserved memory range 0x3ffb2000 - 0x3ffc6520
D (831) memory_layout: Reserved memory range 0x3ffc6520 - 0x3ffced48
D (837) memory_layout: Reserved memory range 0x3ffffa10 - 0x40000000
D (843) memory_layout: Building list of available memory regions:
V (850) memory_layout: Examining memory region 0x3ff9e000 - 0x3ffa0000
D (856) memory_layout: Available memory region 0x3ff9e000 - 0x3ffa0000
V (863) memory_layout: Examining memory region 0x3ffb2000 - 0x3ffb4000
V (869) memory_layout: Region 0x3ffb2000 - 0x3ffb4000 inside of reserved 0x3ffb2000 - 0x3ffc6520
V (878) memory_layout: Examining memory region 0x3ffb4000 - 0x3ffb6000
V (885) memory_layout: Region 0x3ffb4000 - 0x3ffb6000 inside of reserved 0x3ffb2000 - 0x3ffc6520
V (894) memory_layout: Examining memory region 0x3ffb6000 - 0x3ffb8000
V (900) memory_layout: Region 0x3ffb6000 - 0x3ffb8000 inside of reserved 0x3ffb2000 - 0x3ffc6520
V (909) memory_layout: Examining memory region 0x3ffb8000 - 0x3ffbc000
V (916) memory_layout: Region 0x3ffb8000 - 0x3ffbc000 inside of reserved 0x3ffb2000 - 0x3ffc6520
V (925) memory_layout: Examining memory region 0x3ffbc000 - 0x3ffc0000
V (931) memory_layout: Region 0x3ffbc000 - 0x3ffc0000 inside of reserved 0x3ffb2000 - 0x3ffc6520
V (940) memory_layout: Examining memory region 0x3ffc0000 - 0x3ffc4000
V (947) memory_layout: Region 0x3ffc0000 - 0x3ffc4000 inside of reserved 0x3ffb2000 - 0x3ffc6520
V (955) memory_layout: Examining memory region 0x3ffc4000 - 0x3ffc8000
V (962) memory_layout: Start of region 0x3ffc4000 - 0x3ffc8000 overlaps reserved 0x3ffb2000 - 0x3ffc6520
V (972) memory_layout: Region 0x3ffc6520 - 0x3ffc8000 inside of reserved 0x3ffc6520 - 0x3ffced48
V (980) memory_layout: Examining memory region 0x3ffc8000 - 0x3ffcc000
V (987) memory_layout: Region 0x3ffc8000 - 0x3ffcc000 inside of reserved 0x3ffc6520 - 0x3ffced48
V (996) memory_layout: Examining memory region 0x3ffcc000 - 0x3ffd0000
V (1003) memory_layout: Start of region 0x3ffcc000 - 0x3ffd0000 overlaps reserved 0x3ffc6520 - 0x3ffced48
D (1012) memory_layout: Available memory region 0x3ffced48 - 0x3ffd0000
V (1019) memory_layout: Examining memory region 0x3ffd0000 - 0x3ffd4000
D (1026) memory_layout: Available memory region 0x3ffd0000 - 0x3ffd4000
V (1032) memory_layout: Examining memory region 0x3ffd4000 - 0x3ffd8000
D (1039) memory_layout: Available memory region 0x3ffd4000 - 0x3ffd8000
V (1046) memory_layout: Examining memory region 0x3ffd8000 - 0x3ffdc000
D (1052) memory_layout: Available memory region 0x3ffd8000 - 0x3ffdc000
V (1059) memory_layout: Examining memory region 0x3ffdc000 - 0x3ffe0000
D (1066) memory_layout: Available memory region 0x3ffdc000 - 0x3ffe0000
V (1072) memory_layout: Examining memory region 0x3ffe0000 - 0x3ffe4000
D (1079) memory_layout: Available memory region 0x3ffe0000 - 0x3ffe4000
V (1086) memory_layout: Examining memory region 0x3ffe4000 - 0x3ffe8000
D (1092) memory_layout: Available memory region 0x3ffe4000 - 0x3ffe8000
V (1099) memory_layout: Examining memory region 0x3ffe8000 - 0x3ffec000
D (1106) memory_layout: Available memory region 0x3ffe8000 - 0x3ffec000
V (1112) memory_layout: Examining memory region 0x3ffec000 - 0x3fff0000
D (1119) memory_layout: Available memory region 0x3ffec000 - 0x3fff0000
V (1126) memory_layout: Examining memory region 0x3fff0000 - 0x3fff4000
D (1132) memory_layout: Available memory region 0x3fff0000 - 0x3fff4000
V (1139) memory_layout: Examining memory region 0x3fff4000 - 0x3fff8000
D (1146) memory_layout: Available memory region 0x3fff4000 - 0x3fff8000
V (1153) memory_layout: Examining memory region 0x3fff8000 - 0x3fffc000
D (1159) memory_layout: Available memory region 0x3fff8000 - 0x3fffc000
V (1166) memory_layout: Examining memory region 0x3fffc000 - 0x40000000
V (1173) memory_layout: End of region 0x3fffc000 - 0x40000000 overlaps reserved 0x3ffffa10 - 0x40000000
D (1182) memory_layout: Available memory region 0x3fffc000 - 0x3ffffa10
I (1189) heap_init: Initializing. RAM available for dynamic allocation:
D (1196) heap_init: New heap initialised at 0x3ff9e000
I (1201) heap_init: At 3FF9E000 len 00002000 (8 KiB): RTCRAM
D (1208) heap_init: New heap initialised at 0x3ffced48
I (1213) heap_init: At 3FFCED48 len 0002D2B8 (180 KiB): DRAM
I (1219) heap_init: At 3FFFC000 len 00003A10 (14 KiB): DRAM
D (1226) FLASH_HAL: extra_dummy: 0
V (1229) memspi: raw_chip_id: 164020

V (1233) memspi: chip_id: 204016

V (1236) memspi: raw_chip_id: 164020

V (1240) memspi: chip_id: 204016

D (1243) spi_flash: trying chip: issi
D (1247) spi_flash: trying chip: gd
D (1251) spi_flash: trying chip: mxic
D (1255) spi_flash: trying chip: winbond
D (1258) spi_flash: trying chip: boya
D (1262) spi_flash: trying chip: generic
I (1266) spi_flash: detected chip: generic
I (1271) spi_flash: flash io: dio
D (1275) cpu_start: calling init function: 0x400e1898
0x400e1898: _GLOBAL__sub_I___cxa_get_globals_fast at /builds/idf/crosstool-NG/.build/HOST-x86_64-w64-mingw32/xtensa-esp32s2-elf/src/gcc/libstdc++-v3/libsupc++/eh_globals.cc:145

D (1280) cpu_start: calling init function: 0x400e12a8
0x400e12a8: _GLOBAL__sub_I__ZN10__cxxabiv111__terminateEPFvvE at /builds/idf/crosstool-NG/.build/HOST-x86_64-w64-mingw32/xtensa-esp32s2-elf/src/gcc/libstdc++-v3/libsupc++/eh_terminate.cc:125

D (1285) cpu_start: calling init function: 0x400e0fb8
0x400e0fb8: _GLOBAL__sub_I__ZSt7nothrow at /builds/idf/crosstool-NG/.build/HOST-x86_64-w64-mingw32/xtensa-esp32s2-elf/src/gcc/libstdc++-v3/libsupc++/new_handler.cc:71

D (1290) cpu_start: calling init function: 0x400a9454
0x400a9454: adc2_init_code_calibration at C:/Users/Administrator/esp/esp-idf-v4.3-beta1/esp-idf/components/driver/esp32s2/adc2_init_cal.c:28

D (1295) efuse: In EFUSE_BLK2__DATA4_REG is used 3 bits starting with 4 bit
V (1303) ADC: adc_power_acquire: ADC powered on
V (1310) ADC: adc_power_release: ADC powered off
D (1312) ADC: Calib(V1) ADC1 atten=3: 0695
D (1316) cpu_start: calling init function: 0x40094d94
0x40094d94: s_set_default_wifi_log_level at C:/Users/Administrator/esp/esp-idf-v4.3-beta1/esp-idf/components/esp_wifi/src/wifi_init.c:72

D (1321) cpu_start: calling init function: 0x40081ee4
0x40081ee4: esp_ota_init_app_elf_sha256 at C:/Users/Administrator/esp/esp-idf-v4.3-beta1/esp-idf/components/app_update/esp_app_desc.c:76

V (1326) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (1333) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0xE0E
D (1341) intr_alloc: Connected src 73 to int 10 (cpu 0)
V (1346) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (1353) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0x40E
D (1361) intr_alloc: Connected src 28 to int 2 (cpu 0)
I (1366) cpu_start: Starting scheduler on PRO CPU.
D (1372) heap_init: New heap initialised at 0x3fffc000
V (1372) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (1372) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0xE
D (1372) intr_alloc: Connected src 17 to int 3 (cpu 0)
D (1392) partition: Loading the partition table
D (1402) esp_netif_lwip: LwIP stack has been initialized
D (1402) esp_netif_lwip: esp-netif has been successfully initialized
D (1412) event: running task for loop 0x3ffd3278
D (1412) event: created task for loop 0x3ffd3278
D (1422) event: created event loop 0x3ffd3278
V (1422) esp_netif_objects: esp_netif_next_unsafe 0x0
V (1432) esp_netif_objects: esp_netif_next_unsafe 0x0
D (1432) esp_netif_objects: esp_netif_add_to_list 0x3ffd41a0
D (1442) esp_netif_objects: esp_netif_add_to_list netif added successfully (total netifs: 1)
D (1452) nvs: nvs_open_from_partition misc 1
D (1452) nvs: nvs_get_str_or_blob log
I (1462) wifi:wifi driver task: 3ffd67a0, prio:23, stack:6656, core=0
V (1462) esp_adapter: thread sem create: sem=0x3ffd68f8
V (1462) esp_adapter: thread sem get: sem=0x3ffd68f8
I (1472) system_api: Base MAC address is not set
I (1472) system_api: read default base MAC address from EFUSE
D (1482) efuse: In EFUSE_BLK1__DATA1_REG is used 8 bits starting with 8 bit
D (1492) efuse: In EFUSE_BLK1__DATA1_REG is used 8 bits starting with 0 bit
D (1492) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 24 bit
D (1502) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 16 bit
D (1512) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 8 bit
D (1522) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 0 bit
D (1522) nvs: nvs_open_from_partition nvs.net80211 1
D (1532) nvs: nvs_get opmode 1
D (1532) nvs: nvs_get_str_or_blob sta.ssid
D (1542) nvs: nvs_get sta.authmode 1
D (1542) nvs: nvs_get_str_or_blob sta.pswd
D (1542) nvs: nvs_get_str_or_blob sta.pmk
D (1552) nvs: nvs_get sta.chan 1
D (1552) nvs: nvs_get auto.conn 1
D (1552) nvs: nvs_get bssid.set 1
D (1562) nvs: nvs_get_str_or_blob sta.bssid
D (1562) nvs: nvs_get sta.lis_intval 2
D (1572) nvs: nvs_get sta.phym 1
D (1572) nvs: nvs_get sta.phybw 1
D (1572) nvs: nvs_get_str_or_blob sta.apsw
D (1582) nvs: nvs_get_str_or_blob sta.apinfo
D (1582) nvs: nvs_get sta.scan_method 1
D (1582) nvs: nvs_get sta.sort_method 1
D (1592) nvs: nvs_get sta.minrssi 1
D (1592) nvs: nvs_get sta.minauth 1
D (1602) nvs: nvs_get sta.pmf_e 1
D (1602) nvs: nvs_get sta.pmf_r 1
D (1602) nvs: nvs_get sta.btm_e 1
D (1612) nvs: nvs_get sta.rrm_e 1
D (1612) nvs: nvs_get_str_or_blob ap.ssid
D (1612) nvs: nvs_get_str_or_blob ap.passwd
D (1622) nvs: nvs_get_str_or_blob ap.pmk
D (1622) nvs: nvs_get ap.chan 1
D (1622) nvs: nvs_get ap.authmode 1
D (1632) nvs: nvs_get ap.hidden 1
D (1632) nvs: nvs_get ap.max.conn 1
D (1642) nvs: nvs_get bcn.interval 2
D (1642) nvs: nvs_get ap.phym 1
D (1642) nvs: nvs_get ap.phybw 1
D (1652) nvs: nvs_get ap.sndchan 1
D (1652) nvs: nvs_get ap.pmf_e 1
D (1652) nvs: nvs_get ap.pmf_r 1
D (1662) nvs: nvs_get ap.p_cipher 1
D (1662) nvs: nvs_get lorate 1
D (1662) nvs: nvs_get_str_or_blob country
D (1672) nvs: nvs_set ap.sndchan 1 1
I (1672) wifi:wifi firmware version: 6b2834e
I (1672) wifi:wifi certification version: v7.0
I (1682) wifi:config NVS flash: enabled
I (1682) wifi:config nano formating: disabled
I (1692) wifi:Init data frame dynamic rx buffer num: 32
I (1692) wifi:Init management frame dynamic rx buffer num: 32
I (1702) wifi:Init management short buffer num: 32
I (1702) wifi:Init dynamic tx buffer num: 32
I (1702) wifi:Init static rx buffer size: 1600
I (1712) wifi:Init static rx buffer num: 10
I (1712) wifi:Init dynamic rx buffer num: 32
V (1722) esp_adapter: thread sem get: sem=0x3ffd68f8
I (1722) wifi_init: rx ba win: 6
I (1732) wifi_init: tcpip mbox: 32
I (1732) wifi_init: udp mbox: 6
I (1732) wifi_init: tcp mbox: 6
I (1742) wifi_init: tcp tx win: 5744
I (1742) wifi_init: tcp rx win: 5744
I (1752) wifi_init: tcp mss: 1440
I (1752) wifi_init: WiFi IRAM OP enabled
I (1752) wifi_init: WiFi RX IRAM OP enabled
V (1762) esp_adapter: thread sem get: sem=0x3ffd68f8
V (1762) esp_adapter: thread sem get: sem=0x3ffd68f8
D (1772) ADC: Wi-Fi takes adc2 lock.
I (1772) phy_init: phy_version 1300,2887b9c,Dec 16 2020
D (1782) phy_init: loading PHY init data from application binary
D (1932) wifi:filter: set rx policy=0
I (1932) wifi:mode : sta (7c:df:a1:08:df:d2)
I (1932) wifi:enable tsf
D (1932) wifi:filter: set rx policy=1
D (1932) wifi:connect status 0 -> 0
D (1932) event: running post WIFI_EVENT:2 with handler 0x40094ff0 and context 0x3ffd4418 on loop 0x3ffd3278
0x40094ff0: wifi_default_action_sta_start at C:/Users/Administrator/esp/esp-idf-v4.3-beta1/esp-idf/components/esp_wifi/src/wifi_default.c:74

D (1942) wifi_init_default: wifi_start esp-netif:0x3ffd41a0 event-id2
D (1952) wifi_init_default: WIFI mac address: 7c df a1 8 df d2
V (1962) esp_adapter: thread sem create: sem=0x3ffdba00
V (1962) esp_adapter: thread sem get: sem=0x3ffdba00
D (1972) esp_netif_handlers: esp_netif action has started with netif0x3ffd41a0 from event_id=2
D (1972) esp_netif_lwip: check: remote, if=0x3ffd41a0 fn=0x4008bc6c
0x4008bc6c: esp_netif_start_api at C:/Users/Administrator/esp/esp-idf-v4.3-beta1/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:669

D (1982) esp_netif_lwip: esp_netif_start_api 0x3ffd41a0
D (1992) esp_netif_lwip: esp_netif_get_hostname esp_netif:0x3ffd41a0
D (1992) esp_netif_lwip: check: local, if=0x3ffd41a0 fn=0x4008c604
0x4008c604: esp_netif_update_default_netif_lwip at C:/Users/Administrator/esp/esp-idf-v4.3-beta1/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:174

D (2002) esp_netif_lwip: esp_netif_update_default_netif_lwip 0x3ffd41a0
V (2012) esp_netif_objects: esp_netif_next_unsafe 0x0
V (2012) esp_netif_objects: esp_netif_next_unsafe 0x3ffd41a0
V (2022) esp_netif_lwip: esp_netif_is_netif_up esp_netif:0x3ffd41a0
D (2022) esp_netif_lwip: call api in lwip: ret=0x0, give sem
D (2032) event: running post WIFI_EVENT:2 with handler 0x4008636c and context 0x3ffd4d8c on loop 0x3ffd3278
0x4008636c: wifi_event_handler at C:\Users\Administrator\Desktop\ESP32S2\wps-v2\wps\build/../main/wps.c:57

I (2042) example_wps: WIFI_EVENT_STA_START
I (2042) example_wps: start wps...
V (2052) esp_adapter: thread sem create: sem=0x3ffdf0b8
V (2052) esp_adapter: thread sem get: sem=0x3ffdf0b8
V (2062) esp_adapter: thread sem get: sem=0x3ffdf0b8
V (2062) esp_adapter: thread sem get: sem=0x3ffdf0b8
V (2072) esp_adapter: thread sem get: sem=0x3ffdf0b8
V (2072) esp_adapter: thread sem get: sem=0x3ffdf0b8
V (2132) esp_adapter: thread sem get: sem=0x3ffdf0b8
V (2132) esp_adapter: thread sem get: sem=0x3ffdf0b8
D (2132) wifi:Start wifi scan
D (2132) wifi:sta_scan: default parameters, hidden=0, type=active, dur=<0,120>
D (2142) wifi:first chan=1
D (2142) wifi:filter: set rx policy=3
D (2142) wifi:clear scan ap list
D (2142) wifi:start scan: type=0x10f, priority=3, cb=0x4008dd7c, arg=0x3ffcbe70, ss_state=0x1, time=2151834, index=0
0x4008dd7c: wifi_wps_scan_done at C:/Users/Administrator/esp/esp-idf-v4.3-beta1/esp-idf/components/wpa_supplicant/src/esp_supplicant/esp_wps.c:1775

D (2152) wifi:perform scan: ss_state=0x9, chan<1,0>, dur<0,120>
D (2282) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (2282) wifi:perform scan: ss_state=0x9, chan<2,0>, dur<0,120>
D (2402) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (2402) wifi:perform scan: ss_state=0x9, chan<3,0>, dur<0,120>
D (2522) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (2532) wifi:perform scan: ss_state=0x9, chan<4,0>, dur<0,120>
D (2652) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (2652) wifi:perform scan: ss_state=0x9, chan<5,0>, dur<0,120>
D (2772) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (2772) wifi:perform scan: ss_state=0x9, chan<6,0>, dur<0,120>
D (2892) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (2892) wifi:perform scan: ss_state=0x9, chan<7,0>, dur<0,120>
D (3012) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (3012) wifi:perform scan: ss_state=0x9, chan<8,0>, dur<0,120>
D (3132) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (3132) wifi:perform scan: ss_state=0x9, chan<9,0>, dur<0,120>
D (3252) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (3262) wifi:perform scan: ss_state=0x9, chan<10,0>, dur<0,120>
D (3382) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (3382) wifi:perform scan: ss_state=0x9, chan<11,0>, dur<0,120>
D (3502) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (3502) wifi:perform scan: ss_state=0x9, chan<12,0>, dur<360,360>
D (3862) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (3862) wifi:perform scan: ss_state=0x9, chan<13,0>, dur<360,360>
D (4222) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (4222) wifi:filter: set rx policy=4
D (4222) wifi:first chan=1
D (4222) wifi:Start wifi disconnect
D (4222) wifi:connect status 0 -> 0
D (4232) wifi:filter: set rx policy=8
D (4232) wifi:clear blacklist
D (4232) wifi:Start wifi connect
D (4242) wifi:connect status 0 -> 0
D (4242) wifi:connect chan=0
D (4242) wifi:first chan=1
D (4242) wifi:connect status 0 -> 1
D (4252) wifi:filter: set rx policy=3
D (4252) wifi:clear scan ap list
D (4252) wifi:start scan: type=0x50f, priority=2, cb=0x400c4dac, arg=0x0, ss_state=0x1, time=4261512, index=0
0x400c4dac: cnx_start_handoff_cb at ??:?

D (4262) wifi:perform scan: ss_state=0x9, chan<1,0>, dur<0,120>
D (4272) wifi:clear scan ap list
D (4282) wifi:rsn valid: gcipher=3 ucipher=3 akm=5

D (4282) wifi:bssid equal: ss_state=0x7
D (4282) wifi:profile match: ss_state=0x7
D (4282) wifi:scan end: arg=0x0, status=0, ss_state=0x7
D (4292) wifi:find first mathched ssid, scan done
D (4292) wifi:filter: set rx policy=4
D (4302) wifi:first chan=1
D (4302) wifi:handoff_cb: status=0
D (4302) wifi:ap found, mac=80:3f:5d:74:ad:ed
D (4312) wifi:new_bss=0x3ffcd4e0, cur_bss=0x0, new_chan=<1,1>, cur_chan=1
D (4312) wifi:filter: set rx policy=5
I (4322) wifi:new:<1,1>, old:<1,0>, ap:<255,255>, sta:<1,1>, prof:1
D (4322) wifi:connect_op: status=0, auth=5, cipher=3
D (4332) wifi:auth mode is not none
D (4332) wifi:connect_bss: auth=1, reconnect=0
I (4332) wifi:state: init -> auth (b0)
D (4342) wifi:start 1s AUTH timer
D (4342) wifi:clear scan ap list
D (4352) wifi:recv auth: seq=2, status=0
I (4352) wifi:state: auth -> assoc (0)
D (4352) wifi:restart connect 1s timer for assoc
D (4362) wifi:recv assoc: type=0x10
D (4362) wifi:filter: set rx policy=6
I (4362) wifi:state: assoc -> run (10)
D (4372) wifi:start 20s connect timer
D (4392) wifi:wps handle eapol succeed
D (4452) wifi:wps handle eapol succeed
D (5092) wifi:wps handle eapol succeed
V (5102) esp_adapter: thread sem get: sem=0x3ffdf0b8
D (5102) event: running post WIFI_EVENT:8 with handler 0x4008636c and context 0x3ffd4d8c on loop 0x3ffd3278
0x4008636c: wifi_event_handler at C:\Users\Administrator\Desktop\ESP32S2\wps-v2\wps\build/../main/wps.c:57

I (5102) example_wps: WIFI_EVENT_STA_WPS_ER_FAILED
V (5112) esp_adapter: thread sem get: sem=0x3ffdba00
V (5112) esp_adapter: thread sem get: sem=0x3ffdf0b8
V (5122) esp_adapter: thread sem get: sem=0x3ffdf0b8
V (5122) esp_adapter: thread sem get: sem=0x3ffdf0b8
V (5132) esp_adapter: thread sem get: sem=0x3ffdf0b8
V (5132) esp_adapter: thread sem get: sem=0x3ffdba00
D (5142) wifi:Start wifi disconnect
I (5142) wifi:state: run -> init (0)
D (5142) wifi:connect status 1 -> 6
D (5152) wifi:stop beacon/connect timer, send diassoc(8)
D (5152) wifi:sta leave
D (5152) wifi:stop CSA timer
D (5162) wifi:remove 80:3f:5d:74:ad:ed from rc list
I (5162) wifi:new:<1,0>, old:<1,1>, ap:<255,255>, sta:<1,1>, prof:1
D (5172) wifi:filter: set rx policy=8
D (5172) wifi:Send disconnect event, reason=8, AP number=0
D (5182) wifi:connect status 6 -> 0
D (5182) wifi:filter: set rx policy=8
V (5182) esp_adapter: thread sem get: sem=0x3ffdba00
V (5192) esp_adapter: thread sem create: sem=0x3ffd68f8
V (5192) esp_adapter: thread sem get: sem=0x3ffd68f8
V (5202) esp_adapter: thread sem get: sem=0x3ffd68f8
V (5202) esp_adapter: thread sem get: sem=0x3ffd68f8
V (5212) esp_adapter: thread sem get: sem=0x3ffd68f8
V (5212) esp_adapter: thread sem get: sem=0x3ffd68f8
V (5272) esp_adapter: thread sem get: sem=0x3ffd68f8
D (5272) event: running post WIFI_EVENT:5 with handler 0x40095008 and context 0x3ffd44a8 on loop 0x3ffd3278
0x40095008: wifi_default_action_sta_disconnected at C:/Users/Administrator/esp/esp-idf-v4.3-beta1/esp-idf/components/esp_wifi/src/wifi_default.c:107

D (5272) esp_netif_handlers: esp_netif action disconnected with netif0x3ffd41a0 from event_id=5
D (5282) esp_netif_lwip: check: remote, if=0x3ffd41a0 fn=0x4008beac
0x4008beac: esp_netif_down_api at C:/Users/Administrator/esp/esp-idf-v4.3-beta1/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:1226

D (5292) esp_netif_lwip: esp_netif_down_api esp_netif:0x3ffd41a0
D (5292) esp_netif_lwip: esp_netif_start_ip_lost_timer esp_netif:0x3ffd41a0
D (5302) esp_netif_lwip: if0x3ffd41a0 start ip lost tmr: no need start because netif=0x3ffd4220 interval=120 ip=0
D (5312) esp_netif_lwip: check: local, if=0x3ffd41a0 fn=0x4008c604
0x4008c604: esp_netif_update_default_netif_lwip at C:/Users/Administrator/esp/esp-idf-v4.3-beta1/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:174

D (5322) esp_netif_lwip: esp_netif_update_default_netif_lwip 0x3ffd41a0
V (5322) esp_netif_objects: esp_netif_next_unsafe 0x0
V (5332) esp_netif_lwip: esp_netif_is_netif_up esp_netif:0x3ffd41a0
V (5342) esp_netif_objects: esp_netif_next_unsafe 0x3ffd41a0
D (5342) esp_netif_lwip: call api in lwip: ret=0x0, give sem
D (5352) event: running post WIFI_EVENT:5 with handler 0x4008636c and context 0x3ffd4d8c on loop 0x3ffd3278
0x4008636c: wifi_event_handler at C:\Users\Administrator\Desktop\ESP32S2\wps-v2\wps\build/../main/wps.c:57

I (5362) example_wps: WIFI_EVENT_STA_DISCONNECTED
V (5362) esp_adapter: thread sem get: sem=0x3ffdba00
D (5372) wifi:Start wifi connect
D (5372) wifi:connect status 0 -> 0
D (5372) wifi:connect chan=0
D (5382) wifi:first chan=1
D (5382) wifi:connect status 0 -> 1
D (5382) wifi:filter: set rx policy=3
D (5382) wifi:clear scan ap list
D (5392) wifi:start scan: type=0x50f, priority=2, cb=0x400c4dac, arg=0x0, ss_state=0x1, time=5394910, index=0
0x400c4dac: cnx_start_handoff_cb at ??:?

D (5402) wifi:perform scan: ss_state=0x9, chan<1,0>, dur<0,120>
V (5402) esp_adapter: thread sem get: sem=0x3ffd68f8
D (5412) wifi:Start wifi scan
W (5412) wifi:sta_scan: STA is connecting, scan are not allowed!
D (5422) wifi:rsn valid: gcipher=3 ucipher=3 akm=5

D (5422) wifi:receive encrypted ap, but password is empty
D (5472) wifi:rsn valid: gcipher=3 ucipher=3 akm=5

D (5472) wifi:receive encrypted ap, but password is empty
D (5522) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (5522) wifi:perform scan: ss_state=0x9, chan<2,0>, dur<0,120>
D (5652) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (5652) wifi:perform scan: ss_state=0x9, chan<3,0>, dur<0,120>
D (5772) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (5772) wifi:perform scan: ss_state=0x9, chan<4,0>, dur<0,120>
D (5892) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (5892) wifi:perform scan: ss_state=0x9, chan<5,0>, dur<0,120>
D (6012) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (6012) wifi:perform scan: ss_state=0x9, chan<6,0>, dur<0,120>
D (6132) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (6132) wifi:perform scan: ss_state=0x9, chan<7,0>, dur<0,120>
D (6252) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (6252) wifi:perform scan: ss_state=0x9, chan<8,0>, dur<0,120>
D (6382) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (6382) wifi:perform scan: ss_state=0x9, chan<9,0>, dur<0,120>
D (6502) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (6502) wifi:perform scan: ss_state=0x9, chan<10,0>, dur<0,120>
D (6622) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (6622) wifi:perform scan: ss_state=0x9, chan<11,0>, dur<0,120>
D (6742) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (6742) wifi:perform scan: ss_state=0x9, chan<12,0>, dur<360,360>
D (7102) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (7102) wifi:perform scan: ss_state=0x9, chan<13,0>, dur<360,360>
D (7462) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (7462) wifi:filter: set rx policy=4
D (7462) wifi:first chan=1
D (7472) wifi:handoff_cb: status=0
D (7472) wifi:clear rc list
D (7472) wifi:clear blacklist
D (7472) wifi:send disconnect event
D (7482) wifi:connect status 1 -> 3
D (7482) wifi:disable connect timer
D (7482) wifi:clear scan ap list
D (7482) event: running post WIFI_EVENT:5 with handler 0x40095008 and context 0x3ffd44a8 on loop 0x3ffd3278
0x40095008: wifi_default_action_sta_disconnected at C:/Users/Administrator/esp/esp-idf-v4.3-beta1/esp-idf/components/esp_wifi/src/wifi_default.c:107

D (7492) esp_netif_handlers: esp_netif action disconnected with netif0x3ffd41a0 from event_id=5
D (7502) esp_netif_lwip: check: remote, if=0x3ffd41a0 fn=0x4008beac
0x4008beac: esp_netif_down_api at C:/Users/Administrator/esp/esp-idf-v4.3-beta1/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:1226

D (7512) esp_netif_lwip: esp_netif_down_api esp_netif:0x3ffd41a0
D (7522) esp_netif_lwip: esp_netif_start_ip_lost_timer esp_netif:0x3ffd41a0
D (7522) esp_netif_lwip: if0x3ffd41a0 start ip lost tmr: no need start because netif=0x3ffd4220 interval=120 ip=0
D (7532) esp_netif_lwip: check: local, if=0x3ffd41a0 fn=0x4008c604
0x4008c604: esp_netif_update_default_netif_lwip at C:/Users/Administrator/esp/esp-idf-v4.3-beta1/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:174

D (7542) esp_netif_lwip: esp_netif_update_default_netif_lwip 0x3ffd41a0
V (7552) esp_netif_objects: esp_netif_next_unsafe 0x0
V (7552) esp_netif_lwip: esp_netif_is_netif_up esp_netif:0x3ffd41a0
V (7562) esp_netif_objects: esp_netif_next_unsafe 0x3ffd41a0
D (7562) esp_netif_lwip: call api in lwip: ret=0x0, give sem
D (7572) event: running post WIFI_EVENT:5 with handler 0x4008636c and context 0x3ffd4d8c on loop 0x3ffd3278
0x4008636c: wifi_event_handler at C:\Users\Administrator\Desktop\ESP32S2\wps-v2\wps\build/../main/wps.c:57

I (7582) example_wps: WIFI_EVENT_STA_DISCONNECTED
V (7582) esp_adapter: thread sem get: sem=0x3ffdba00
D (7592) wifi:Start wifi connect
D (7592) wifi:connect status 3 -> 0
D (7602) wifi:connect chan=0
D (7602) wifi:first chan=1
D (7602) wifi:connect status 0 -> 1
D (7602) wifi:filter: set rx policy=3
D (7612) wifi:clear scan ap list
D (7612) wifi:start scan: type=0x50f, priority=2, cb=0x400c4dac, arg=0x0, ss_state=0x1, time=7617295, index=0
0x400c4dac: cnx_start_handoff_cb at ??:?

D (7622) wifi:perform scan: ss_state=0x9, chan<1,0>, dur<0,120>
D (7632) wifi:rsn valid: gcipher=3 ucipher=3 akm=5

D (7632) wifi:receive encrypted ap, but password is empty
D (7642) wifi:rsn valid: gcipher=3 ucipher=3 akm=5

D (7642) wifi:receive encrypted ap, but password is empty
D (7732) wifi:rsn valid: gcipher=3 ucipher=3 akm=5

D (7732) wifi:receive encrypted ap, but password is empty
D (7752) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (7752) wifi:perform scan: ss_state=0x9, chan<2,0>, dur<0,120>
D (7872) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (7872) wifi:perform scan: ss_state=0x9, chan<3,0>, dur<0,120>
D (7992) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (7992) wifi:perform scan: ss_state=0x9, chan<4,0>, dur<0,120>
D (8112) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (8112) wifi:perform scan: ss_state=0x9, chan<5,0>, dur<0,120>
D (8232) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (8232) wifi:perform scan: ss_state=0x9, chan<6,0>, dur<0,120>
D (8352) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (8362) wifi:perform scan: ss_state=0x9, chan<7,0>, dur<0,120>
D (8482) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (8482) wifi:perform scan: ss_state=0x9, chan<8,0>, dur<0,120>
D (8602) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (8602) wifi:perform scan: ss_state=0x9, chan<9,0>, dur<0,120>
D (8722) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (8722) wifi:perform scan: ss_state=0x9, chan<10,0>, dur<0,120>
D (8842) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (8842) wifi:perform scan: ss_state=0x9, chan<11,0>, dur<0,120>
D (8962) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (8962) wifi:perform scan: ss_state=0x9, chan<12,0>, dur<360,360>
D (9322) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (9322) wifi:perform scan: ss_state=0x9, chan<13,0>, dur<360,360>
D (9692) wifi:scan end: arg=0x0, status=0, ss_state=0x3
D (9692) wifi:filter: set rx policy=4
D (9692) wifi:first chan=1
D (9692) wifi:handoff_cb: status=0
D (9692) wifi:clear rc list
D (9692) wifi:clear blacklist
D (9692) wifi:send disconnect event
D (9702) wifi:connect status 1 -> 3
D (9702) wifi:disable connect timer
D (9702) wifi:clear scan ap list
D (9712) event: running post WIFI_EVENT:5 with handler 0x40095008 and context 0x3ffd44a8 on loop 0x3ffd3278
0x40095008: wifi_default_action_sta_disconnected at C:/Users/Administrator/esp/esp-idf-v4.3-beta1/esp-idf/components/esp_wifi/src/wifi_default.c:107

D (9722) esp_netif_handlers: esp_netif action disconnected with netif0x3ffd41a0 from event_id=5
D (9732) esp_netif_lwip: check: remote, if=0x3ffd41a0 fn=0x4008beac
0x4008beac: esp_netif_down_api at C:/Users/Administrator/esp/esp-idf-v4.3-beta1/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:1226

D (9732) esp_netif_lwip: esp_netif_down_api esp_netif:0x3ffd41a0
D (9742) esp_netif_lwip: esp_netif_start_ip_lost_timer esp_netif:0x3ffd41a0
D (9752) esp_netif_lwip: if0x3ffd41a0 start ip lost tmr: no need start because netif=0x3ffd4220 interval=120 ip=0
D (9762) esp_netif_lwip: check: local, if=0x3ffd41a0 fn=0x4008c604
0x4008c604: esp_netif_update_default_netif_lwip at C:/Users/Administrator/esp/esp-idf-v4.3-beta1/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:174

D (9762) esp_netif_lwip: esp_netif_update_default_netif_lwip 0x3ffd41a0
V (9772) esp_netif_objects: esp_netif_next_unsafe 0x0
V (9772) esp_netif_lwip: esp_netif_is_netif_up esp_netif:0x3ffd41a0
V (9782) esp_netif_objects: esp_netif_next_unsafe 0x3ffd41a0
D (9792) esp_netif_lwip: call api in lwip: ret=0x0, give sem
D (9792) event: running post WIFI_EVENT:5 with handler 0x4008636c and context 0x3ffd4d8c on loop 0x3ffd3278
0x4008636c: wifi_event_handler at C:\Users\Administrator\Desktop\ESP32S2\wps-v2\wps\build/../main/wps.c:57

I (9802) example_wps: WIFI_EVENT_STA_DISCONNECTED
I (9812) example_wps: Failed to connect!

[nishanth-radja]

@yusufbavas 1.Can you also pls share the AP model and configuration of the AP which you are using for the WPS connection. 2.Also Pls share the wireless sniffer capture during the failure of the wps connection. 3.Can you pls send me the SDK config of the example.

[AxelLin]

@yusufbavas Please check if v4.3 branch works or not. I'm wondering if this is related to https://github.com/espressif/esp-idf/issues/8087 The fix is in v4.3 and v4.4 branches now, but not yet in v4.2 branch.

[nishanth-radja]

@yusufbavas, As AxelLin suggested pls try on 4.3 branch,

From the logs shared looks like the wps handshake failed during the building of M1 packet. "D (4392) wifi:wps handle eapol succeed D (4452) wifi:wps handle eapol succeed D (5092) wifi:wps handle eapol succeed V (5102) esp_adapter: thread sem get: sem=0x3ffdf0b8 D (5102) event: running post WIFI_EVENT:8 with handler 0x4008636c and context 0x3ffd4d8c on loop 0x3ffd3278 0x4008636c: wifi_event_handler at C:\Users\Administrator\Desktop\ESP32S2\wps-v2\wps\build/../main/wps.c:57

I (5102) example_wps: WIFI_EVENT_STA_WPS_ER_FAILED"

We are supposed to have "wps handle eapol succeed" 8 times for a successful wps session.Sniffer capture will help.

[AxelLin]

@yusufbavas The WPS fix is in v4.2 branch now: eb90d9bf18957927316443fc93c59ce7e049edfe eec9d6db94693aa5024986a2a97e7ed422b51c9d Any update regarding this issue? If it still does not work, please capture sniffer log.

[Alvin1Zhang]

Thanks for reporting, will close due to short of feedback, feel free to reopen with more updates. Thanks.