NO_AP_FOUND_IN_AUTHMODE_THRESHOLD while threshold's condition is respected (IDFGH-12863)

evoon commented 5 months ago

Answers checklist.

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

IDF version.

v5.2.1

Espressif SoC revision.

ESP32-C6 v0.0

Operating System used.

Windows

How did you build your project?

VS Code IDE

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

None

Development Kit.

ESP32-C6-WROOM-1

Power Supply used.

USB

What is the expected behavior?

I expect the ESP32 STA to connect to the AP, as the STA threshold is set to WIFI_AUTH_WPA2 and the AP's authmode is set to >WPA2.

What is the actual behavior?

I am getting NO_AP_FOUND_IN_AUTHMODE_THRESHOLD, while the authmode.threshold in the STA is greater than AP's one. No matter what threshold i put in authmode.threshold, the only AP configuration that it will connect to is WPA3

Steps to reproduce.

Set station config's authmode.threshold to anything/don't set it
Connect to a wifi network with a security inferior to WPA3

Debug Logs.

SCAN RESULT : SSID=TestReseau, AUTHMODE=3

I (241251) http_server: POST /connect.json
I (241261) http_server: ssid: TestReseau, password: Password1!
I (241261) wifi_manager: MESSAGE: ORDER_CONNECT_STA
I (241271) wifi_manager: wifi_sta_config: ssid:TestReseau password:Password1!
I (241281) wifi_manager: wifi_sta_config: sta_authmode 3
I (241291) wifi_manager: wifi_sta_config: RM enabled 1
I (241291) wifi_manager: wifi_sta_config: BTM enabled 1
I (241301) wifi_manager: wifi_sta_config: MBO enabled 1
I (241311) wifi_manager: wifi_sta_config: FT enabled 1
I (241311) wifi_manager: wifi_sta_config: OWE enabled 1
I (241321) wifi_manager: wifi_sta_config: PMF capable enabled 1
I (241331) wifi_manager: wifi_sta_config: PMF required enabled 0
I (241341) wifi_manager: wifi_sta_config: transition_disable enabled 0
I (244171) wifi_manager: WIFI_EVENT_STA_DISCONNECTED
I (244171) wifi_manager: MESSAGE: EVENT_STA_DISCONNECTED with Reason code: 211
I (244181) wifi_manager: MESSAGE: EVENT_STA_DISCONNECTED with rssi: -128
I (244181) wifi_manager: Set STA IP String to: 0.0.0.0



### More Information.

I have tried setting OWE to 1 in the STA config, and also setting transition_disable to 1 in the STA config.
Ultimately, the STA will only connect to the AP if the security of the AP is set to WPA3

vik-gokhale commented 5 months ago

Hi @evoon Could you please enable WIFI debug print and share the log?

CONFIG_WPA_DEBUG_PRINT=y CONFIG_MBEDTLS_DEBUG=y CONFIG_MBEDTLS_DEBUG_LEVEL_VERBOSE=y CONFIG_MBEDTLS_DEBUG_LEVEL=4 CONFIG_LOG_DEFAULT_LEVEL_DEBUG=y CONFIG_LOG_DEFAULT_LEVEL=4

evoon commented 5 months ago

Hello, thanks for your help, the objective of the code is wifi provisioning through a http page, here is the log with your config (i removed the scanning wifi network loop in the middle for more clarity) :

PS C:\Users\User\Desktop\STAGE\Projets\esp\softap_prov> set IDF_PATH=C:\Users\User\esp\v5.2.1\esp-idf
PS C:\Users\User\Desktop\STAGE\Projets\esp\softap_prov> C:\Users\User\.espressif\python_env\idf5.2_py3.11_env\Scripts\python.exe C:\Users\User\esp\v5.2.1\esp-idf\tools\idf_monitor.py -p COM4 -b 115200 --toolchain-prefix riscv32-esp-elf- --target esp32c6 c:\Users\User\Desktop\STAGE\Projets\esp\softap_prov\build\softap_prov.elf
--- WARNING: GDB cannot open serial ports accessed as COMx
--- Using \\.\COM4 instead...
--- esp-idf-monitor 1.4.0 on \\.\COM4 115200 ---
--- Quit: Ctrl+] | Menu: Ctrl+T | Help: Ctrl+T followed by Ctrl+H ---
ESP-ROM:esp32c6-20220919
Build:Sep 19 2022
rst:0x15 (USB_UART_HPSYS),boot:0x7d (SPI_FAST_FLASH_BOOT)
Saved PC:0x408053b4
0x408053b4: rv_utils_wait_for_intr at C:/Users/User/esp/v5.2/esp-idf/components/riscv/include/riscv/rv_utils.h:52
 (inlined by) esp_cpu_wait_for_intr at C:/Users/User/esp/v5.2/esp-idf/components/esp_hw_support/cpu.c:143        

SPIWP:0xee
mode:DIO, clock div:2
load:0x40875720,len:0x1804
load:0x4086c410,len:0xde0
load:0x4086e610,len:0x2e04
entry 0x4086c41a
I (23) boot: ESP-IDF v5.2 2nd stage bootloader
I (23) boot: compile time May 22 2024 09:41:27
I (24) boot: chip revision: v0.0
I (26) boot.esp32c6: SPI Speed      : 80MHz
I (30) boot.esp32c6: SPI Mode       : DIO
I (35) boot.esp32c6: SPI Flash Size : 2MB
I (40) boot: Enabling RNG early entropy source...
I (45) boot: Partition Table:
I (49) boot: ## Label            Usage          Type ST Offset   Length
I (56) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (64) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (71) boot:  2 factory          factory app      00 00 00010000 00100000
I (79) boot: End of partition table
I (83) esp_image: segment 0: paddr=00010020 vaddr=420a8020 size=30c10h (199696) map
I (132) esp_image: segment 1: paddr=00040c38 vaddr=40800000 size=073e0h ( 29664) load
I (140) esp_image: segment 2: paddr=00048020 vaddr=42000020 size=a75b4h (685492) map
I (291) esp_image: segment 3: paddr=000ef5dc vaddr=408073e0 size=0e544h ( 58692) load
I (305) esp_image: segment 4: paddr=000fdb28 vaddr=40815930 size=0363ch ( 13884) load
I (314) boot: Loaded app from partition at offset 0x10000
I (315) boot: Disabling RNG early entropy source...
I (526) cpu_start: Unicore app
D (526) cpu_start: Pro cpu up
D (535) clk: RTC_SLOW_CLK calibration value: 3715277
W (540) clk: esp_perip_clk_init() has not been implemented yet
I (546) cpu_start: Pro cpu start user code
I (547) cpu_start: cpu freq: 160000000 Hz
I (547) cpu_start: Application information:
I (550) cpu_start: Project name:     softap_prov
I (555) cpu_start: App version:      1
I (559) cpu_start: Compile time:     May 22 2024 09:41:46
I (565) cpu_start: ELF file SHA256:  3c4ba5414...
I (571) cpu_start: ESP-IDF:          v5.2
I (575) cpu_start: Min chip rev:     v0.0
I (580) cpu_start: Max chip rev:     v0.99 
I (585) cpu_start: Chip rev:         v0.0
D (590) memory_layout: Checking 5 reserved memory ranges:
D (595) memory_layout: Reserved memory range 0x40800000 - 0x40815930
0x40800000: _vector_table at ??:?

D (602) memory_layout: Reserved memory range 0x40815930 - 0x4081e370
D (608) memory_layout: Reserved memory range 0x4087f564 - 0x40880000
D (614) memory_layout: Reserved memory range 0x50000000 - 0x50000000
D (621) memory_layout: Reserved memory range 0x50003fe8 - 0x50004000
D (627) memory_layout: Building list of available memory regions:
D (633) memory_layout: Available memory region 0x4081e370 - 0x40820000
D (640) memory_layout: Available memory region 0x40820000 - 0x40840000
D (647) memory_layout: Available memory region 0x40840000 - 0x40860000
D (653) memory_layout: Available memory region 0x40860000 - 0x4087c610
D (660) memory_layout: Available memory region 0x4087c610 - 0x4087f564
D (666) memory_layout: Available memory region 0x50000000 - 0x50003fe8
I (673) heap_init: Initializing. RAM available for dynamic allocation:
D (680) heap_init: New heap initialised at 0x4081e370
I (685) heap_init: At 4081E370 len 0005E2A0 (376 KiB): RAM
I (691) heap_init: At 4087C610 len 00002F54 (11 KiB): RAM
D (698) heap_init: New heap initialised at 0x50000000
I (703) heap_init: At 50000000 len 00003FE8 (15 KiB): RTCRAM
D (709) intr_alloc: Connected src 15 to int 2 (cpu 0)
D (715) spi_flash: trying chip: generic
I (718) spi_flash: detected chip: generic
I (723) spi_flash: flash io: dio
W (727) spi_flash: Detected size(8192k) larger than the size in the binary image header(2048k). Using the size in the binary image header.      
D (740) cpu_start: calling init function: 0x4209a922
0x4209a922: _GLOBAL__sub_I__ZN9__gnu_cxx9__freeresEv at /builds/idf/crosstool-NG/.build/HOST-x86_64-w64-mingw32/riscv32-esp-elf/src/gcc/libstdc++-v3/libsupc++/eh_alloc.cc:462

D (745) cpu_start: calling init function: 0x4209a29c
0x4209a29c: _GLOBAL__sub_I__ZN17__eh_globals_init7_S_initE at /builds/idf/crosstool-NG/.build/HOST-x86_64-w64-mingw32/riscv32-esp-elf/build/build-cc-gcc-final/riscv32-esp-elf/rv32imac_zicsr_zifencei/ilp32/no-rtti/libstdc++-v3/include/riscv32-esp-elf/bits/gthr-default.h:708
 (inlined by) __eh_globals_init::__eh_globals_init() at /builds/idf/crosstool-NG/.build/HOST-x86_64-w64-mingw32/riscv32-esp-elf/src/gcc/libstdc++-v3/libsupc++/eh_globals.cc:105
 (inlined by) __static_initialization_and_destruction_0 at /builds/idf/crosstool-NG/.build/HOST-x86_64-w64-mingw32/riscv32-esp-elf/src/gcc/libstdc++-v3/libsupc++/eh_globals.cc:126
 (inlined by) _GLOBAL__sub_I__ZN17__eh_globals_init7_S_initE at /builds/idf/crosstool-NG/.build/HOST-x86_64-w64-mingw32/riscv32-esp-elf/src/gcc/libstdc++-v3/libsupc++/eh_globals.cc:162

D (750) cpu_start: calling init function: 0x4204cb96
0x4204cb96: s_set_default_wifi_log_level at C:/Users/User/esp/v5.2/esp-idf/components/esp_wifi/src/wifi_init.c:77

D (755) cpu_start: calling init function: 0x4080649e
0x4080649e: enable_timer_group0_for_calibration at C:/Users/User/esp/v5.2/esp-idf/components/esp_hw_support/port/esp32c6/rtc_time.c:273

D (760) cpu_start: calling init function: 0x420031f6
0x420031f6: esp_crypto_dpa_protection_startup at C:/Users/User/esp/v5.2/esp-idf/components/esp_hw_support/esp_dpa_protection.c:21

D (765) cpu_start: calling init function: 0x4200002a
0x4200002a: esp_app_format_init_elf_sha256 at C:/Users/User/esp/v5.2/esp-idf/components/esp_app_format/esp_app_desc.c:69

D (770) cpu_start: calling init function: 0x42007488 on core: 0
0x42007488: __esp_system_init_fn_esp_timer_startup_init at C:/Users/User/esp/v5.2/esp-idf/components/esp_timer/src/esp_timer.c:578

D (776) intr_alloc: Connected src 59 to int 9 (cpu 0)
D (781) cpu_start: calling init function: 0x42001866 on core: 0
0x42001866: __esp_system_init_fn_esp_hw_stack_guard_init at C:/Users/User/esp/v5.2/esp-idf/components/esp_system/hw_stack_guard.c:15

D (787) cpu_start: calling init function: 0x42002fc2 on core: 0
0x42002fc2: __esp_system_init_fn_esp_sleep_startup_init at C:/Users/User/esp/v5.2/esp-idf/components/esp_hw_support/sleep_gpio.c:189

I (793) sleep: Configure to isolate all GPIO pins in sleep state
I (800) sleep: Enable automatic switching of GPIO sleep configuration
D (807) cpu_start: calling init function: 0x420013e2 on core: 0
0x420013e2: __esp_system_init_fn_init_components0 at C:/Users/User/esp/v5.2/esp-idf/components/esp_system/startup.c:480

I (813) coexist: coex firmware version: 77cd7f8
I (818) coexist: coexist rom version 5b8dcfa
D (823) intr_alloc: Connected src 22 to int 10 (cpu 0)
D (828) app_start: Starting scheduler on CPU0
D (833) intr_alloc: Connected src 57 to int 11 (cpu 0)
I (833) main_task: Started on CPU0
D (833) heap_init: New heap initialised at 0x4087c610
D (833) intr_alloc: Connected src 53 to int 12 (cpu 0)
I (843) main_task: Calling app_main()
D (853) esp_netif_lwip: LwIP stack has been initialized
D (853) esp_netif_lwip: esp-netif has been successfully initialized
I (863) wifi_manager: Set STA IP String to: 0.0.0.0
D (863) esp_netif_lwip: esp-netif has been successfully initialized
D (873) event: running task for loop 0x4082605c
D (873) event: created task for loop 0x4082605c
D (883) event: created event loop 0x4082605c
D (883) esp_netif_lwip: check: remote, if=0x40825bec fn=0x42033dee
0x42033dee: esp_netif_new_api at C:/Users/User/esp/v5.2/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:690

D (893) esp_netif_objects: esp_netif_add_to_list_unsafe netif added successfully (total netifs: 1)
D (903) esp_netif_lwip: call api in lwip: ret=0x0, give sem
D (903) esp_netif_lwip: check: remote, if=0x40825bec fn=0x42033dee
0x42033dee: esp_netif_new_api at C:/Users/User/esp/v5.2/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:690

D (913) esp_netif_objects: esp_netif_add_to_list_unsafe netif added successfully (total netifs: 2)
D (923) esp_netif_lwip: call api in lwip: ret=0x0, give sem
I (923) pp: pp rom version: 5b8dcfa
I (933) net80211: net80211 rom version: 5b8dcfa
D (933) nvs: nvs_open_from_partition misc 1
I (943) main_task: Returned from app_main()
D (953) efuse: In EFUSE_BLK1__DATA1_REG is used 8 bits starting with 8 bit
D (953) efuse: In EFUSE_BLK1__DATA1_REG is used 8 bits starting with 0 bit
D (963) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 24 bit
D (963) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 16 bit
D (973) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 8 bit
D (983) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 0 bit
D (983) nvs: nvs_open_from_partition nvs.net80211 1
D (993) nvs: nvs_get opmode 1
D (993) nvs: nvs_get_str_or_blob sta.ssid
D (1003) nvs: nvs_get sta.authmode 1
D (1003) nvs: nvs_get_str_or_blob sta.pswd
D (1003) nvs: nvs_get_str_or_blob sta.pmk
D (1013) nvs: nvs_get sta.chan 1
D (1013) nvs: nvs_get auto.conn 1
D (1013) nvs: nvs_get bssid.set 1
D (1023) nvs: nvs_get_str_or_blob sta.bssid
D (1023) nvs: nvs_get sta.lis_intval 2
D (1033) nvs: nvs_get sta.phym 1
D (1033) nvs: nvs_get sta.phybw 1
D (1033) nvs: nvs_get_str_or_blob sta.apsw
D (1043) nvs: nvs_get_str_or_blob sta.apinfo
D (1043) nvs: nvs_get sta.scan_method 1
D (1043) nvs: nvs_get sta.sort_method 1
D (1053) nvs: nvs_get sta.minrssi 1
D (1053) nvs: nvs_get sta.minauth 1
D (1063) nvs: nvs_get sta.pmf_e 1
D (1063) nvs: nvs_get sta.pmf_r 1
D (1063) nvs: nvs_get sta.btm_e 1
D (1073) nvs: nvs_get sta.rrm_e 1
D (1073) nvs: nvs_get sta.mbo_e 1
D (1073) nvs: nvs_get_str_or_blob ap.ssid
D (1083) nvs: nvs_get_str_or_blob ap.passwd
D (1083) nvs: nvs_get_str_or_blob ap.pmk
D (1083) nvs: nvs_get ap.chan 1
D (1093) nvs: nvs_get ap.authmode 1
D (1093) nvs: nvs_get ap.hidden 1
D (1093) nvs: nvs_get ap.max.conn 1
D (1103) nvs: nvs_get bcn.interval 2
D (1103) nvs: nvs_get ap.phym 1
D (1113) nvs: nvs_get ap.phybw 1
D (1113) nvs: nvs_get ap.sndchan 1
D (1113) nvs: nvs_get ap.pmf_e 1
D (1123) nvs: nvs_get ap.pmf_r 1
D (1123) nvs: nvs_get ap.p_cipher 1
D (1123) nvs: nvs_get lorate 1
D (1133) nvs: nvs_get_str_or_blob country
D (1133) nvs: nvs_get ap.ftm_r 1
D (1133) nvs: nvs_get sta.ft 1
D (1143) nvs: nvs_get sta.owe 1
D (1143) nvs: nvs_get sta.trans_d 1
D (1143) nvs: nvs_get sta.sae_h2e 1
D (1153) nvs: nvs_get sta.sae_pk_mode 1
D (1153) nvs: nvs_get sta.bss_retry 1
D (1153) nvs: nvs_get_str_or_blob sta.owe_data
D (1163) nvs: nvs_get sta.he_dcm 1
D (1163) nvs: nvs_get sta.he_dcm_c_tx 1
D (1173) nvs: nvs_get sta.he_dcm_c_rx 1
D (1173) nvs: nvs_get sta.he_mcs9_d 1
D (1173) nvs: nvs_get sta.he_su_b_d 1
D (1183) nvs: nvs_get sta.he_su_b_f_d 1
D (1183) nvs: nvs_get sta.he_mu_b_f_d 1
D (1183) nvs: nvs_get sta.he_cqi_f_d 1
D (1193) nvs: nvs_get_str_or_blob sta.sae_h2e_id
D (1193) nvs: nvs_get ap.sae_h2e 1
D (1203) nvs: nvs_get_str_or_blob ap.pmk_info
D (1203) nvs: nvs_get nan.phym 1
D (1203) nvs: nvs_set ap.sndchan 1 1
I (1213) wifi_init: rx ba win: 6
I (1213) wifi_init: tcpip mbox: 32
I (1223) wifi_init: udp mbox: 6
I (1223) wifi_init: tcp mbox: 6
I (1223) wifi_init: tcp tx win: 5760
I (1233) wifi_init: tcp rx win: 5760
I (1233) wifi_init: tcp mss: 1440
I (1243) wifi_init: WiFi IRAM OP enabled
I (1243) wifi_init: WiFi RX IRAM OP enabled
D (1253) esp_netif_lwip: check: remote, if=0x408272d0 fn=0x420345ce
0x420345ce: esp_netif_dhcps_stop_api at C:/Users/User/esp/v5.2/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:1556

D (1253) esp_netif_lwip: esp_netif_dhcps_stop_api esp_netif:0x408272d0
D (1263) esp_netif_lwip: dhcp server stop successfully
D (1263) esp_netif_lwip: call api in lwip: ret=0x0, give sem
D (1273) esp_netif_lwip: check: remote, if=0x408272d0 fn=0x420349b4
0x420349b4: esp_netif_set_ip_info_api at C:/Users/User/esp/v5.2/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:1804

D (1283) esp_netif_lwip: esp_netif_set_ip_info_api esp_netif:0x408272d0
D (1283) esp_netif_lwip: call api in lwip: ret=0x0, give sem
D (1293) esp_netif_lwip: check: remote, if=0x408272d0 fn=0x42034106
0x42034106: esp_netif_dhcps_start_api at C:/Users/User/esp/v5.2/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:1515

D (1293) esp_netif_lwip: esp_netif_dhcps_start_api esp_netif:0x408272d0
D (1303) esp_netif_lwip: dhcp server re init
D (1313) esp_netif_lwip: call api in lwip: ret=0x0, give sem
D (1313) gdma: new group (0) at 0x408310f8
D (1323) gdma: new pair (0,0) at 0x40831170
D (1323) gdma: new tx channel (0,0) at 0x408310c0
D (1323) gdma: new rx channel (0,0) at 0x40831190
D (1333) gdma: tx channel (0,0), (1:16) bytes aligned, burst enabled
D (1343) gdma: rx channel (0,0), (1:16) bytes aligned, burst disabled
I (1693) phy_init: phy_version 230,c773401,Oct 30 2023,15:07:16
D (1693) phy_init: loading PHY init data from application binary
D (1693) nvs: nvs_open_from_partition phy 0
D (1703) nvs: nvs_get cal_version 4
D (1703) nvs: nvs_get_str_or_blob cal_mac
D (1713) efuse: In EFUSE_BLK1__DATA1_REG is used 8 bits starting with 8 bit
D (1713) efuse: In EFUSE_BLK1__DATA1_REG is used 8 bits starting with 0 bit
D (1723) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 24 bit
D (1733) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 16 bit
D (1733) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 8 bit
D (1743) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 0 bit
D (1753) efuse: In EFUSE_BLK1__DATA1_REG is used 8 bits starting with 24 bit
D (1753) efuse: In EFUSE_BLK1__DATA1_REG is used 8 bits starting with 16 bit
D (1763) nvs: nvs_get_str_or_blob cal_data
D (1773) nvs: nvs_close 3
D (1773) efuse: In EFUSE_BLK1__DATA1_REG is used 8 bits starting with 8 bit
D (1783) efuse: In EFUSE_BLK1__DATA1_REG is used 8 bits starting with 0 bit
D (1783) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 24 bit
D (1793) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 16 bit
D (1803) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 8 bit
D (1803) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 0 bit
D (1813) efuse: In EFUSE_BLK1__DATA1_REG is used 8 bits starting with 24 bit
D (1823) efuse: In EFUSE_BLK1__DATA1_REG is used 8 bits starting with 16 bit
D (1833) temperature_sensor: range changed, change to index 2
D (1873) event: running post WIFI_EVENT:40 with handler 0x4200d294 and context 0x40830f44 on loop 0x4082605c
0x4200d294: wifi_manager_event_handler at C:/Users/User/Desktop/STAGE/Projets/esp/softap_prov/components/esp32-wifi-manager/src/wifi_manager.c:838

D (1873) event: running post WIFI_EVENT:2 with handler 0x4204cefa and context 0x4082717c on loop 0x4082605c
0x4204cefa: wifi_default_action_sta_start at C:/Users/User/esp/v5.2/esp-idf/components/esp_wifi/src/wifi_default.c:71

D (1883) wifi_init_default: wifi_start esp-netif:0x40826f80 event-id2
D (1883) wifi_init_default: WIFI mac address: 40 4c ca 43 6d 38
D (1893) esp_netif_lwip: check: remote, if=0x40826f80 fn=0x42033404
0x42033404: esp_netif_set_mac_api at C:/Users/User/esp/v5.2/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:994

D (1893) esp_netif_lwip: call api in lwip: ret=0x0, give sem
D (1903) esp_netif_handlers: esp_netif action has started with netif0x40826f80 from event_id=2
D (1913) esp_netif_lwip: check: remote, if=0x40826f80 fn=0x4203432e
0x4203432e: esp_netif_start_api at C:/Users/User/esp/v5.2/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:1068

D (1923) esp_netif_lwip: esp_netif_start_api 0x40826f80
D (1923) esp_netif_lwip: esp_netif_get_hostname esp_netif:0x40826f80
D (1933) esp_netif_lwip: check: local, if=0x40826f80 fn=0x420350ea
0x420350ea: esp_netif_update_default_netif_lwip at C:/Users/User/esp/v5.2/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:316

D (1933) esp_netif_lwip: esp_netif_update_default_netif_lwip 0x40826f80
D (1943) esp_netif_lwip: call api in lwip: ret=0x0, give sem
D (1953) event: running post WIFI_EVENT:2 with handler 0x4200d294 and context 0x40830f44 on loop 0x4082605c
0x4200d294: wifi_manager_event_handler at C:/Users/User/Desktop/STAGE/Projets/esp/softap_prov/components/esp32-wifi-manager/src/wifi_manager.c:838

I (1963) wifi_manager: WIFI_EVENT_STA_START
D (1963) httpd: httpd_thread: web server started
D (1963) httpd: httpd_server: doing select maxfd+1 = 56
D (1973) event: no handlers have been registered for event ESP_HTTP_SERVER_EVENT:1 posted to loop 0x4082605c
I (1983) http_server: Registering URI handlers
D (1993) httpd_uri: httpd_register_uri_handler: [0] installed *
D (1993) httpd_uri: httpd_find_uri_handler: [0] = *
D (2003) httpd_uri: httpd_register_uri_handler: [0] exists *
D (2003) httpd_uri: httpd_register_uri_handler: [1] installed *
D (2013) httpd_uri: httpd_find_uri_handler: [0] = *
D (2013) httpd_uri: httpd_find_uri_handler: [1] = *
D (2023) httpd_uri: httpd_register_uri_handler: [0] exists *
D (2023) httpd_uri: httpd_register_uri_handler: [1] exists *
D (2033) httpd_uri: httpd_register_uri_handler: [2] installed *
I (2043) wifi_manager: MESSAGE: ORDER_LOAD_AND_RESTORE_STA
D (2043) nvs: nvs_open_from_partition espwifimgr 0
I (2053) wifi_manager: No saved wifi found on startup. Starting access point.
I (2053) wifi_manager: MESSAGE: ORDER_START_AP
D (2063) event: running post WIFI_EVENT:12 with handler 0x4204cee0 and context 0x4082723c on loop 0x4082605c
0x4204cee0: wifi_default_action_ap_start at C:/Users/User/esp/v5.2/esp-idf/components/esp_wifi/src/wifi_default.c:112

D (2073) wifi_init_default: wifi_start esp-netif:0x408272d0 event-id12
D (2083) wifi_init_default: WIFI mac address: 40 4c ca 43 6d 39
D (2083) esp_netif_lwip: check: remote, if=0x408272d0 fn=0x42033404
0x42033404: esp_netif_set_mac_api at C:/Users/User/esp/v5.2/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:994

D (2093) esp_netif_lwip: call api in lwip: ret=0x0, give sem
D (2093) esp_netif_handlers: esp_netif action has started with netif0x408272d0 from event_id=12
D (2103) esp_netif_lwip: check: remote, if=0x408272d0 fn=0x4203432e
0x4203432e: esp_netif_start_api at C:/Users/User/esp/v5.2/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:1068

D (2113) esp_netif_lwip: esp_netif_start_api 0x408272d0
D (2113) esp_netif_lwip: esp_netif_internal_dhcpc_cb lwip-netif:0x40827354
D (2123) esp_netif_lwip: if0x408272d0 ip unchanged
D (2133) esp_netif_lwip: esp_netif_get_hostname esp_netif:0x408272d0
D (2133) esp_netif_lwip: esp_netif_start_api Setting the lwip netif0x40827354 UP
I (2143) esp_netif_lwip: DHCP server started on interface WIFI_AP_DEF with IP: 10.10.0.1
D (2153) esp_netif_lwip: check: local, if=0x408272d0 fn=0x420350ea
0x420350ea: esp_netif_update_default_netif_lwip at C:/Users/User/esp/v5.2/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:316

D (2153) esp_netif_lwip: esp_netif_update_default_netif_lwip 0x408272d0
D (2163) esp_netif_lwip: call api in lwip: ret=0x0, give sem
D (2173) event: running post WIFI_EVENT:12 with handler 0x4200d294 and context 0x40830f44 on loop 0x4082605c
0x4200d294: wifi_manager_event_handler at C:/Users/User/Desktop/STAGE/Projets/esp/softap_prov/components/esp32-wifi-manager/src/wifi_manager.c:838

I (2183) wifi_manager: WIFI_EVENT_AP_START

[...]

I (44903) http_server: POST /connect.json
D (44913) httpd_txrx: httpd_req_recv: remaining length = 51
D (44913) httpd_txrx: httpd_recv_with_opt: requested length = 51
D (44923) httpd_txrx: httpd_recv_with_opt: pending length = 50
D (44923) httpd_txrx: httpd_recv_with_opt: received length = 51
D (44933) event: running post WIFI_EVENT:1 with handler 0x4200d294 and context 0x40830f44 on loop 0x4082605c
0x4200d294: wifi_manager_event_handler at C:/Users/User/Desktop/STAGE/Projets/esp/softap_prov/components/esp32-wifi-manager/src/wifi_manager.c:838

D (44943) wifi_manager: WIFI_EVENT_SCAN_DONE
D (44943) httpd_txrx: httpd_req_recv: received length = 51
D (44953) event: no handlers have been registered for event ESP_HTTP_SERVER_EVENT:5 posted to loop 0x4082605c
TestReseau, 3
reseau_integration, 3
SETUP, 0
I (44973) http_server: log data received: {"multicast":"239.1.1.1","port":"","protocol":"ax"}
D (44983) nvs: nvs_open_from_partition storage 1
D (44983) nvs: nvs_set_str multicast 239.1.1.1
D (44993) nvs: nvs_set_str port
D (44993) nvs: nvs_set_str protocole ax
D (44993) nvs: nvs_close 4
I (45003) http_server: ssid: TestReseau, password: Password1!
D (45003) http_server: http_server_post_handler: wifi_manager_connect_async() call
D (45013) httpd_txrx: httpd_resp_set_hdr: new header = Cache-Control: no-store, no-cache, must-revalidate, max-age=0
D (45023) httpd_txrx: httpd_resp_set_hdr: new header = Pragma: no-cache
I (45023) wifi_manager: MESSAGE: ORDER_CONNECT_STA
D (45033) httpd_txrx: httpd_send_all: sent = 68
D (45043) nvs: nvs_open_from_partition storage 1
D (45043) nvs: nvs_get_str_or_blob protocole
D (45053) nvs: nvs_get_str_or_blob protocole
D (45053) httpd_txrx: httpd_send_all: sent = 13
D (45063) nvs: nvs_close 5
I (45063) wifi_manager: wifi_manager_fetch_wifi_sta_config: ssid:TestReseau password:Password1!
I (45073) wifi_manager: wifi_manager_fetch_wifi_settings: sta_authmode 3
I (45083) wifi_manager: wifi_manager_fetch_wifi_settings: RM enabled 1
I (45083) wifi_manager: wifi_manager_fetch_wifi_settings: BTM enabled 1
I (45093) wifi_manager: wifi_manager_fetch_wifi_settings: MBO enabled 1
I (45103) wifi_manager: wifi_manager_fetch_wifi_settings: FT enabled 1
I (45103) wifi_manager: wifi_manager_fetch_wifi_settings: OWE enabled 0
I (45113) wifi_manager: wifi_manager_fetch_wifi_settings: PMF capable enabled 1
I (45123) wifi_manager: wifi_manager_fetch_wifi_settings: PMF required enabled 0
I (45133) wifi_manager: wifi_manager_fetch_wifi_settings: transition_disable enabled 0
D (45063) httpd_txrx: httpd_send_all: sent = 2
D (45143) httpd_txrx: httpd_send_all: sent = 46
D (45153) httpd_txrx: httpd_send_all: sent = 2
D (45153) httpd_txrx: httpd_send_all: sent = 6
D (45153) httpd_txrx: httpd_send_all: sent = 2
D (45163) httpd_txrx: httpd_send_all: sent = 8
D (45163) httpd_txrx: httpd_send_all: sent = 2
D (45173) httpd_txrx: httpd_send_all: sent = 2
D (45173) event: no handlers have been registered for event ESP_HTTP_SERVER_EVENT:4 posted to loop 0x4082605c
D (45183) event: no handlers have been registered for event ESP_HTTP_SERVER_EVENT:6 posted to loop 0x4082605c
D (45193) httpd_sess: httpd_sess_process: httpd_req_delete
D (45203) httpd_sess: httpd_sess_process: success
D (45203) httpd: httpd_server: doing select maxfd+1 = 60
D (47163) httpd: httpd_process_session: processing socket 58
D (47163) httpd_sess: httpd_sess_process: httpd_req_new
D (47163) httpd_txrx: httpd_recv_with_opt: requested length = 128
D (47173) httpd_txrx: httpd_recv_with_opt: received length = 128
D (47173) httpd_parse: read_block: received HTTP request block size = 128
D (47183) httpd_parse: cb_url: message begin
D (47193) httpd_parse: cb_url: processing url = /status.json
D (47193) httpd_parse: verify_url: received URI = /status.json
D (47203) httpd_parse: cb_header_field: headers begin
D (47203) httpd_txrx: httpd_unrecv: length = 101
D (47213) httpd_parse: pause_parsing: paused
D (47213) httpd_parse: cb_header_field: processing field = Host
D (47223) httpd_txrx: httpd_recv_with_opt: requested length = 128
D (47223) httpd_txrx: httpd_recv_with_opt: pending length = 101
D (47233) httpd_parse: read_block: received HTTP request block size = 101
D (47243) httpd_parse: continue_parsing: skip pre-parsed data of size = 5
D (47243) httpd_parse: continue_parsing: un-paused
D (47253) httpd_parse: cb_header_value: processing value = 10.10.0.1
D (47253) httpd_parse: cb_header_field: processing field = Connection
D (47263) httpd_parse: cb_header_value: processing value = keep-alive
D (47273) httpd_parse: cb_header_field: processing field = Accept
D (47273) httpd_parse: cb_header_value: processing value = */*
D (47283) httpd_parse: cb_header_field: processing field = User-Agent
D (47293) httpd_parse: cb_header_value: processing value = Mozilla/5.0 (iPhone; CPU iPhone OS 
D (47293) httpd_parse: parse_block: parsed block size = 101
D (47303) httpd_txrx: httpd_recv_with_opt: requested length = 128
D (47313) httpd_txrx: httpd_recv_with_opt: received length = 128
D (47313) httpd_parse: read_block: received HTTP request block size = 128
D (47323) httpd_parse: cb_header_value: processing value = 17_4_1 like Mac OS X) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/17.4.1 Mobile/15E148 Safari/604.1
D (47333) httpd_parse: cb_header_field: processing field = Accept-Language
D (47343) httpd_parse: cb_header_value: processing value = fr-FR
D (47353) httpd_parse: parse_block: parsed block size = 229
D (47353) httpd_txrx: httpd_recv_with_opt: requested length = 128
D (47363) httpd_txrx: httpd_recv_with_opt: received length = 73
D (47363) httpd_parse: read_block: received HTTP request block size = 73
D (47373) httpd_parse: cb_header_value: processing value = ,fr;q=0.9
D (47383) httpd_parse: cb_header_field: processing field = Referer
D (47383) httpd_parse: cb_header_value: processing value = http://10.10.0.1/
D (47393) httpd_parse: cb_header_field: processing field = Accept-Encoding
D (47403) httpd_parse: cb_header_value: processing value = gzip, deflate
D (47403) httpd_parse: cb_headers_complete: bytes read     = 331
D (47413) httpd_parse: cb_headers_complete: content length = 0
D (47423) event: no handlers have been registered for event ESP_HTTP_SERVER_EVENT:3 posted to loop 0x4082605c
D (47433) httpd_parse: pause_parsing: paused
D (47433) httpd_parse: cb_no_body: message complete
D (47443) httpd_parse: httpd_parse_req: parsing complete
D (47443) httpd_uri: httpd_uri: request for /status.json with type 1
D (47453) httpd_uri: httpd_find_uri_handler: [0] = *
D (47453) http_server: GET /status.json
D (47463) httpd_txrx: httpd_resp_set_hdr: new header = Cache-Control: no-store, no-cache, must-revalidate, max-age=0
D (47473) httpd_txrx: httpd_resp_set_hdr: new header = Pragma: no-cache
D (47473) httpd_txrx: httpd_send_all: sent = 68
D (47483) httpd_txrx: httpd_send_all: sent = 13
D (47483) httpd_txrx: httpd_send_all: sent = 2
D (47493) httpd_txrx: httpd_send_all: sent = 46
D (47493) httpd_txrx: httpd_send_all: sent = 2
D (47503) httpd_txrx: httpd_send_all: sent = 6
D (47503) httpd_txrx: httpd_send_all: sent = 2
D (47513) httpd_txrx: httpd_send_all: sent = 8
D (47513) httpd_txrx: httpd_send_all: sent = 2
D (47513) httpd_txrx: httpd_send_all: sent = 2
D (47523) event: no handlers have been registered for event ESP_HTTP_SERVER_EVENT:4 posted to loop 0x4082605c
D (47533) httpd_txrx: httpd_send_all: sent = 3
D (47533) event: no handlers have been registered for event ESP_HTTP_SERVER_EVENT:6 posted to loop 0x4082605c
D (47543) httpd_sess: httpd_sess_process: httpd_req_delete
D (47553) httpd_sess: httpd_sess_process: success
D (47553) httpd: httpd_server: doing select maxfd+1 = 60
D (47973) event: running post WIFI_EVENT:5 with handler 0x4204cf12 and context 0x4082720c on loop 0x4082605c
0x4204cf12: wifi_default_action_sta_disconnected at C:/Users/User/esp/v5.2/esp-idf/components/esp_wifi/src/wifi_default.c:104

D (47973) esp_netif_handlers: esp_netif action disconnected with netif0x40826f80 from event_id=5
D (47973) esp_netif_lwip: check: remote, if=0x40826f80 fn=0x42034c00
0x42034c00: esp_netif_down_api at C:/Users/User/esp/v5.2/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:1673

D (47983) esp_netif_lwip: esp_netif_down_api esp_netif:0x40826f80
D (47993) esp_netif_lwip: esp_netif_start_ip_lost_timer esp_netif:0x40826f80
D (47993) esp_netif_lwip: if0x40826f80 start ip lost tmr: interval=120
D (48003) esp_netif_lwip: check: local, if=0x40826f80 fn=0x420350ea
0x420350ea: esp_netif_update_default_netif_lwip at C:/Users/User/esp/v5.2/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:316

D (48013) esp_netif_lwip: esp_netif_update_default_netif_lwip 0x40826f80
D (48013) esp_netif_lwip: call api in lwip: ret=0x0, give sem
D (48023) event: running post WIFI_EVENT:5 with handler 0x4200d294 and context 0x40830f44 on loop 0x4082605c
0x4200d294: wifi_manager_event_handler at C:/Users/User/Desktop/STAGE/Projets/esp/softap_prov/components/esp32-wifi-manager/src/wifi_manager.c:838

I (48033) wifi_manager: WIFI_EVENT_STA_DISCONNECTED
I (48033) wifi_manager: MESSAGE: EVENT_STA_DISCONNECTED with Reason code: 211
I (48043) wifi_manager: MESSAGE: EVENT_STA_DISCONNECTED with rssi: -128
I (48053) wifi_manager: Set STA IP String to: 0.0.0.0

evoon commented 5 months ago

Problem solved with upgrading to v5.2.1 (still obtaining an error code 202 AUTH_FAIL on the first wifi connexion after boot, but the retry after connects successfully).

espressif / esp-idf