Skip to content
New issue

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

Sign up for GitHub

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

Already on GitHub? Sign in to your account

Jump to bottom

ESP32S3 WIFI join AP failure (IDFGH-13577) #14465

Closed
3 tasks done
beanjs opened this issue Aug 30, 2024 · 37 comments
Closed
3 tasks done

ESP32S3 WIFI join AP failure (IDFGH-13577) #14465

beanjs opened this issue Aug 30, 2024 · 37 comments
Assignees
@zhangyanjiaoesp
Labels
Resolution: Done Issue is done internally Status: Done Issue is done internally Type: Bug bugs in IDF

Comments

@beanjs
Copy link

beanjs commented Aug 30, 2024

Answers checklist.

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

IDF version.

v5.4-dev-2596-g6e5414b6c4

Espressif SoC revision.

ESP32S3

Operating System used.

macOS

How did you build your project?

Command line with idf.py

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

CMD

Development Kit.

ESP32S3-WROOM-1

Power Supply used.

USB

What is the expected behavior?

Join AP should work.

What is the actual behavior?

Failed to join the AP. The log indicates that the verification timed out.

Steps to reproduce.

using wifi/getting_started example
Uploading sdkconfig.zip…

Debug Logs.

I (23) boot: ESP-IDF v5.4-dev-2596-g6e5414b6c4 2nd stage bootloader
I (23) boot: compile time Aug 30 2024 13:16:25
I (24) boot: Multicore bootloader
I (28) boot: chip revision: v0.2
I (31) boot: efuse block revision: v1.3
I (36) boot.esp32s3: Boot SPI Speed : 80MHz
I (41) boot.esp32s3: SPI Mode       : DIO
I (45) boot.esp32s3: SPI Flash Size : 2MB
I (50) boot: Enabling RNG early entropy source...
I (56) boot: Partition Table:
I (59) boot: ## Label            Usage          Type ST Offset   Length
I (66) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (74) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (81) boot:  2 factory          factory app      00 00 00010000 00100000
I (89) boot: End of partition table
I (93) esp_image: segment 0: paddr=00010020 vaddr=3c080020 size=240ech (147692) map
I (128) esp_image: segment 1: paddr=00034114 vaddr=3fc99a00 size=04b18h ( 19224) load
I (132) esp_image: segment 2: paddr=00038c34 vaddr=40374000 size=073e4h ( 29668) load
I (140) esp_image: segment 3: paddr=00040020 vaddr=42000020 size=79b50h (498512) map
I (230) esp_image: segment 4: paddr=000b9b78 vaddr=4037b3e4 size=0e5e4h ( 58852) load
I (257) boot: Loaded app from partition at offset 0x10000
I (257) boot: Disabling RNG early entropy source...
V (269) mmap: after coalescing, 1 regions are left
I (269) cpu_start: Multicore app
D (269) cpu_start: Pro cpu up
D (269) cpu_start: Starting app cpu, entry point is 0x40375398
D (0) cpu_start: App cpu up
V CACHE_ERR: illegal error intr clr & ena mask is: 0x3f
V CA H28E) c c:re 1 SLccesLK error inton clr & ena 4ma20mis: 0x1f
V CACHE_ERR: illegal error intr clr & ena mask is: 0x3f
V CACHE_ERR: core 0 access error intr clr & ena mask is: 0x1f
D (301) cpu_start: calling init function: 0x420018d4 on core: 0
D (306) cpu_start: calling init function: 0x42001d74 on core: 0
I (312) cpu_start: Pro cpu start user code
I (316) cpu_start: cpu freq: 160000000 Hz
D (321) cpu_start: calling init function: 0x42001804 on core: 0
I (327) app_init: Application information:
I (332) app_init: Project name:     wifi_station
I (337) app_init: App version:      v5.4-dev-2596-g6e5414b6c4
I (343) app_init: Compile time:     Aug 30 2024 13:16:14
I (349) app_init: ELF file SHA256:  3adfb2c14...
I (355) app_init: ESP-IDF:          v5.4-dev-2596-g6e5414b6c4
D (361) cpu_start: calling init function: 0x420018e8 on core: 0
I (367) efuse_init: Min chip rev:     v0.0
I (372) efuse_init: Max chip rev:     v0.99 
I (377) efuse_init: Chip rev:         v0.2
D (382) cpu_start: calling init function: 0x42003dd4 on core: 0
V (388) memory_layout: reserved range is 0x3c0a4034 - 0x3c0a405c
D (394) memory_layout: Checking 6 reserved memory ranges:
D (399) memory_layout: Reserved memory range 0x3fc84000 - 0x3fc99a00
D (406) memory_layout: Reserved memory range 0x3fc99a00 - 0x3fca20b8
D (412) memory_layout: Reserved memory range 0x3fceee34 - 0x3fcf0000
D (418) memory_layout: Reserved memory range 0x40374000 - 0x40389a00
D (425) memory_layout: Reserved memory range 0x600fe000 - 0x600fe100
D (431) memory_layout: Reserved memory range 0x600fffe8 - 0x60100000
D (438) memory_layout: Building list of available memory regions:
V (444) memory_layout: Examining memory region 0x3fc88000 - 0x3fc90000
V (451) memory_layout: Region 0x3fc88000 - 0x3fc90000 inside of reserved 0x3fc84000 - 0x3fc99a00
V (459) memory_layout: Examining memory region 0x3fc90000 - 0x3fca0000
V (466) memory_layout: Start of region 0x3fc90000 - 0x3fca0000 overlaps reserved 0x3fc84000 - 0x3fc99a00
V (476) memory_layout: Region 0x3fc99a00 - 0x3fca0000 inside of reserved 0x3fc99a00 - 0x3fca20b8
V (484) memory_layout: Examining memory region 0x3fca0000 - 0x3fcb0000
V (491) memory_layout: Start of region 0x3fca0000 - 0x3fcb0000 overlaps reserved 0x3fc99a00 - 0x3fca20b8
D (501) memory_layout: Available memory region 0x3fca20b8 - 0x3fcb0000
V (507) memory_layout: Examining memory region 0x3fcb0000 - 0x3fcc0000
D (514) memory_layout: Available memory region 0x3fcb0000 - 0x3fcc0000
V (520) memory_layout: Examining memory region 0x3fcc0000 - 0x3fcd0000
D (527) memory_layout: Available memory region 0x3fcc0000 - 0x3fcd0000
V (533) memory_layout: Examining memory region 0x3fcd0000 - 0x3fce0000
D (540) memory_layout: Available memory region 0x3fcd0000 - 0x3fce0000
V (547) memory_layout: Examining memory region 0x3fce0000 - 0x3fce9710
D (553) memory_layout: Available memory region 0x3fce0000 - 0x3fce9710
V (560) memory_layout: Examining memory region 0x3fce9710 - 0x3fcf0000
V (566) memory_layout: End of region 0x3fce9710 - 0x3fcf0000 overlaps reserved 0x3fceee34 - 0x3fcf0000
D (576) memory_layout: Available memory region 0x3fce9710 - 0x3fceee34
V (582) memory_layout: Examining memory region 0x3fcf0000 - 0x3fcf8000
D (589) memory_layout: Available memory region 0x3fcf0000 - 0x3fcf8000
V (596) memory_layout: Examining memory region 0x600fe000 - 0x60100000
V (602) memory_layout: Start of region 0x600fe000 - 0x60100000 overlaps reserved 0x600fe000 - 0x600fe100
V (612) memory_layout: End of region 0x600fe100 - 0x60100000 overlaps reserved 0x600fffe8 - 0x60100000
D (621) memory_layout: Available memory region 0x600fe100 - 0x600fffe8
I (628) heap_init: Initializing. RAM available for dynamic allocation:
D (635) heap_init: New heap initialised at 0x3fca20b8
I (640) heap_init: At 3FCA20B8 len 00047658 (285 KiB): RAM
I (646) heap_init: At 3FCE9710 len 00005724 (21 KiB): RAM
D (652) heap_init: New heap initialised at 0x3fcf0000
I (657) heap_init: At 3FCF0000 len 00008000 (32 KiB): DRAM
D (664) heap_init: New heap initialised at 0x600fe100
I (669) heap_init: At 600FE100 len 00001EE8 (7 KiB): RTCRAM
D (675) cpu_start: calling init function: 0x42007444 on core: 0
D (681) cpu_start: calling init function: 0x42006ea0 on core: 0
D (687) cpu_start: calling init function: 0x42001dc0 on core: 0
V (693) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (699) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0x40E
D (708) intr_alloc: Connected src 39 to int 1 (cpu 0)
D (713) cpu_start: calling init function: 0x42001dcc on core: 0
D (719) cpu_start: calling init function: 0x42008554 on core: 0
D (725) cpu_start: calling init function: 0x420092c0 on core: 0
D (731) cpu_start: calling init function: 0x4200a3a4 on core: 0
D (737) cpu_start: calling init function: 0x420094e4 on core: 0
D (743) cpu_start: calling init function: 0x42006f08 on core: 0
D (749) cpu_start: calling init function: 0x42001dd8 on core: 0
V (755) memspi: raw_chip_id: 1840EF

V (758) memspi: chip_id: EF4018

V (762) memspi: raw_chip_id: 1840EF

V (765) memspi: chip_id: EF4018

D (769) spi_flash: trying chip: issi
D (772) spi_flash: trying chip: gd
D (776) spi_flash: trying chip: mxic
D (779) spi_flash: trying chip: winbond
I (783) spi_flash: detected chip: winbond
I (788) spi_flash: flash io: dio
W (792) spi_flash: Detected size(16384k) larger than the size in the binary image header(2048k). Using the size in the binary image header.
D (805) cpu_start: calling init function: 0x42001984 on core: 0
D (811) cpu_start: calling init function: 0x4205d3b8
D (816) cpu_start: calling init function: 0x42013710
D (821) cpu_start: calling init function: 0x4037c030
D (826) cpu_start: calling init function: 0x42003190
D (832) cpu_start: calling init function: 0x42002374
D (837) cpu_start: calling init function: 0x4203fd28 on core: 0
V (842) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (849) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0xC02
D (857) intr_alloc: Connected src 59 to int 2 (cpu 0)
D (862) cpu_start: calling init function: 0x42071fac on core: 0
D (868) cpu_start: calling init function: 0x42004e60 on core: 0
I (874) sleep_gpio: Configure to isolate all GPIO pins in sleep state
I (881) sleep_gpio: Enable automatic switching of GPIO sleep configuration
D (889) cpu_start: calling init function: 0x42001e00 on core: 0
D (895) cpu_start: calling init function: 0x42008eac on core: 0
D (901) cpu_start: calling init function: 0x42001e0c on core: 0
V (907) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (913) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0x40E
D (921) intr_alloc: Connected src 79 to int 3 (cpu 0)
D (926) app_start: Starting scheduler on CPU0
V (931) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (931) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0x402
D (931) intr_alloc: Connected src 57 to int 5 (cpu 0)
V (931) intr_alloc: esp_intr_alloc_intrstatus (cpu 1): checking args
V (941) intr_alloc: esp_intr_alloc_intrstatus (cpu 1): Args okay. Resulting flags 0x40E
D (941) intr_alloc: Connected src 80 to int 0 (cpu 1)
D (951) app_start: Starting scheduler on CPU1
V (951) intr_alloc: esp_intr_alloc_intrstatus (cpu 1): checking args
V (961) intr_alloc: esp_intr_alloc_intrstatus (cpu 1): Args okay. Resulting flags 0x402
D (971) intr_alloc: Connected src 58 to int 1 (cpu 1)
I (931) main_task: Started on CPU0
D (981) heap_init: New heap initialised at 0x3fce9710
V (981) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): checking args
V (991) intr_alloc: esp_intr_alloc_intrstatus (cpu 0): Args okay. Resulting flags 0xE
D (1001) intr_alloc: Connected src 52 to int 8 (cpu 0)
I (1001) main_task: Calling app_main()
V (1011) partition: Loading the partition table
V (1011) mmap: actual_mapped_len is 0x10000
V (1021) calculated md5: 0x3fca5c58   f4 ad 4f 45 38 56 4b 5d  74 35 b6 2c 75 b6 95 24  |..OE8VK]t5.,u..$|
V (1031) stored md5: 0x3c0b8070   f4 ad 4f 45 38 56 4b 5d  74 35 b6 2c 75 b6 95 24  |..OE8VK]t5.,u..$|
V (1041) partition: Partition table MD5 verified
I (1061) wifi station: ESP_WIFI_MODE_STA
D (1061) esp_netif_lwip: LwIP stack has been initialized
D (1061) esp_netif_lwip: esp-netif has been successfully initialized
D (1071) event: running task for loop 0x3fca8b38
D (1071) event: created task for loop 0x3fca8b38
D (1081) event: created event loop 0x3fca8b38
D (1081) esp_netif_lwip: check: remote, if=0x3fca5bd0 fn=0x42011144
V (1091) esp_netif_objects: esp_netif_add_to_list_unsafe 0x3fca9a60
D (1091) esp_netif_objects: esp_netif_add_to_list_unsafe netif added successfully (total netifs: 1)
D (1101) esp_netif_lwip: call api in lwip: ret=0x0, give sem
I (1111) pp: pp rom version: e7ae62f
I (1111) net80211: net80211 rom version: e7ae62f
D (1121) nvs: nvs_open_from_partition misc 1
I (1131) wifi:wifi driver task: 3fcac3d4, prio:23, stack:6656, core=0
V (1131) esp_adapter: thread sem create: sem=0x3fcac52c
V (1131) esp_adapter: thread sem get: sem=0x3fcac52c
D (1141) efuse: BLK1 REG1 [8-15], len=8 bits
D (1141) efuse: BLK1 REG1 [0-7], len=8 bits
D (1151) efuse: BLK1 REG0 [24-31], len=8 bits
D (1151) efuse: BLK1 REG0 [16-23], len=8 bits
D (1161) efuse: BLK1 REG0 [8-15], len=8 bits
D (1161) efuse: BLK1 REG0 [0-7], len=8 bits
D (1161) nvs: nvs_open_from_partition nvs.net80211 1
D (1171) nvs: nvs_get opmode 1
D (1171) nvs: nvs_get_str_or_blob sta.ssid
D (1181) nvs: nvs_get sta.authmode 1
D (1181) nvs: nvs_get_str_or_blob sta.pswd
D (1191) nvs: nvs_get_str_or_blob sta.pmk
D (1191) nvs: nvs_get sta.chan 1
D (1191) nvs: nvs_get auto.conn 1
D (1201) nvs: nvs_get bssid.set 1
D (1201) nvs: nvs_get_str_or_blob sta.bssid
D (1201) nvs: nvs_get sta.lis_intval 2
D (1211) nvs: nvs_get sta.phym 1
D (1211) nvs: nvs_get sta.phybw 1
D (1211) nvs: nvs_get_str_or_blob sta.apsw
D (1221) nvs: nvs_get_str_or_blob sta.apinfo
D (1221) nvs: nvs_get sta.scan_method 1
D (1231) nvs: nvs_get sta.sort_method 1
D (1231) nvs: nvs_get sta.minrssi 1
D (1231) nvs: nvs_get sta.minauth 1
D (1241) nvs: nvs_get sta.pmf_e 1
D (1241) nvs: nvs_get sta.pmf_r 1
D (1241) nvs: nvs_get sta.btm_e 1
D (1251) nvs: nvs_get sta.rrm_e 1
D (1251) nvs: nvs_get sta.mbo_e 1
D (1251) nvs: nvs_get_str_or_blob ap.ssid
D (1261) nvs: nvs_get_str_or_blob ap.passwd
D (1261) nvs: nvs_get_str_or_blob ap.pmk
D (1271) nvs: nvs_get ap.chan 1
D (1271) nvs: nvs_get ap.authmode 1
D (1271) nvs: nvs_get ap.hidden 1
D (1281) nvs: nvs_get ap.max.conn 1
D (1281) nvs: nvs_get bcn.interval 2
D (1281) nvs: nvs_get ap.phym 1
D (1291) nvs: nvs_get ap.phybw 1
D (1291) nvs: nvs_get ap.sndchan 1
D (1291) nvs: nvs_get ap.pmf_e 1
D (1301) nvs: nvs_get ap.pmf_r 1
D (1301) nvs: nvs_get ap.p_cipher 1
D (1301) nvs: nvs_get lorate 1
D (1311) nvs: nvs_get_str_or_blob country
D (1311) nvs: nvs_get ap.ftm_r 1
D (1311) nvs: nvs_get sta.ft 1
D (1321) nvs: nvs_get sta.owe 1
D (1321) nvs: nvs_get sta.trans_d 1
D (1321) nvs: nvs_get sta.sae_h2e 1
D (1331) nvs: nvs_get sta.sae_pk_mode 1
D (1331) nvs: nvs_get sta.bss_retry 1
D (1341) nvs: nvs_get_str_or_blob sta.owe_data
D (1341) nvs: nvs_get sta.he_dcm 1
D (1341) nvs: nvs_get sta.he_dcm_c_tx 1
D (1351) nvs: nvs_get sta.he_dcm_c_rx 1
D (1351) nvs: nvs_get sta.he_mcs9_d 1
D (1361) nvs: nvs_get sta.he_su_b_d 1
D (1361) nvs: nvs_get sta.he_su_b_f_d 1
D (1361) nvs: nvs_get sta.he_mu_b_f_d 1
D (1371) nvs: nvs_get sta.he_cqi_f_d 1
D (1371) nvs: nvs_get_str_or_blob sta.sae_h2e_id
D (1381) nvs: nvs_get ap.sae_h2e 1
D (1381) nvs: nvs_get_str_or_blob ap.pmk_info
D (1381) nvs: nvs_get nan.phym 1
D (1391) nvs: nvs_get sta.pwr_reset 1
D (1391) nvs: nvs_get band_mode 1
D (1391) nvs: nvs_get sta.phym5g 1
D (1401) nvs: nvs_get ap.phym5g 1
D (1401) nvs: nvs_get sta.phybw5g 1
D (1401) nvs: nvs_get ap.phybw5g 1
D (1411) nvs: nvs_get ap.sndchan5g 1
D (1411) nvs: nvs_get ap.chan5g 1
D (1411) nvs: nvs_get ap.chanisset 1
D (1421) nvs: nvs_get ap.chan5gisset 1
D (1421) nvs: nvs_set ap.sndchan 1 1
I (1431) wifi:wifi firmware version: fa211df
I (1431) wifi:wifi certification version: v7.0
I (1431) wifi:config NVS flash: enabled
I (1441) wifi:config nano formatting: disabled
I (1441) wifi:Init data frame dynamic rx buffer num: 32
I (1451) wifi:Init static rx mgmt buffer num: 5
I (1451) wifi:Init management short buffer num: 32
I (1451) wifi:Init dynamic tx buffer num: 32
I (1461) wifi:Init static tx FG buffer num: 2
I (1461) wifi:Init static rx buffer size: 1600
I (1471) wifi:Init static rx buffer num: 10
I (1471) wifi:Init dynamic rx buffer num: 32
D (1481) wifi:Reset scan defaults in ms : min,max,passive,chan_dwell :(0,120,360,30)
V (1481) wifi:hint=255, act_dur=<0,120>, pas_dur=360, nchans=14 history_num=0
V (1491) esp_adapter: thread sem get: sem=0x3fcac52c
I (1491) wifi_init: rx ba win: 6
I (1501) wifi_init: accept mbox: 6
I (1501) wifi_init: tcpip mbox: 32
I (1511) wifi_init: udp mbox: 6
I (1511) wifi_init: tcp mbox: 6
I (1511) wifi_init: tcp tx win: 5760
I (1521) wifi_init: tcp rx win: 5760
I (1521) wifi_init: tcp mss: 1440
I (1531) wifi_init: WiFi IRAM OP enabled
I (1531) wifi_init: WiFi RX IRAM OP enabled
V (1541) esp_adapter: thread sem get: sem=0x3fcac52c
D (1541) nvs: nvs_get opmode 1
V (1541) esp_adapter: thread sem get: sem=0x3fcac52c
D (1551) wifi:clear blacklist
D (1551) nvs: nvs_get_str_or_blob sta.ssid
D (1561) nvs: nvs_get sta.pmf_e 1
V (1561) esp_adapter: thread sem get: sem=0x3fcac52c
I (1561) phy_init: phy_version 680,a6008b2,Jun  4 2024,16:41:10
D (1571) phy_init: loading PHY init data from application binary
D (1581) nvs: nvs_open_from_partition phy 0
D (1581) nvs: nvs_get cal_version 4
V (1591) phy_init: phy_get_rf_cal_version: 680
D (1591) nvs: nvs_get_str_or_blob cal_mac
D (1591) efuse: BLK1 REG1 [8-15], len=8 bits
D (1601) efuse: BLK1 REG1 [0-7], len=8 bits
D (1601) efuse: BLK1 REG0 [24-31], len=8 bits
D (1611) efuse: BLK1 REG0 [16-23], len=8 bits
D (1611) efuse: BLK1 REG0 [8-15], len=8 bits
D (1621) efuse: BLK1 REG0 [0-7], len=8 bits
D (1621) nvs: nvs_get_str_or_blob cal_data
D (1631) nvs: nvs_close 3
D (1631) efuse: BLK1 REG1 [8-15], len=8 bits
D (1631) efuse: BLK1 REG1 [0-7], len=8 bits
D (1631) efuse: BLK1 REG0 [24-31], len=8 bits
D (1641) efuse: BLK1 REG0 [16-23], len=8 bits
D (1641) efuse: BLK1 REG0 [8-15], len=8 bits
D (1651) efuse: BLK1 REG0 [0-7], len=8 bits
D (1671) temperature_sensor: range changed, change to index 2
W (1691) phy_init: saving new calibration data because of checksum failure, mode(0)
D (1691) nvs: nvs_open_from_partition phy 1
D (1691) nvs: nvs_set_blob cal_data 1904
D (1721) efuse: BLK1 REG1 [8-15], len=8 bits
D (1721) efuse: BLK1 REG1 [0-7], len=8 bits
D (1721) efuse: BLK1 REG0 [24-31], len=8 bits
D (1721) efuse: BLK1 REG0 [16-23], len=8 bits
D (1721) efuse: BLK1 REG0 [8-15], len=8 bits
D (1731) efuse: BLK1 REG0 [0-7], len=8 bits
D (1731) nvs: nvs_set_blob cal_mac 6
V (1741) phy_init: phy_get_rf_cal_version: 680
D (1741) nvs: nvs_set cal_version 4 680
D (1741) nvs: nvs_close 4
V (1751) wifi:ht20 freq=2412, chan=1
D (1751) wifi:filter: set rx policy=0
I (1751) wifi:mode : sta (ec:da:3b:5b:71:1c)
I (1761) wifi:enable tsf
D (1761) wifi:filter: set rx policy=1
D (1761) wifi:connect status 0 -> 0
D (1771) event: running post WIFI_EVENT:43 with handler 0x4200a3b0 and context 0x3fcb28b0 on loop 0x3fca8b38
D (1781) event: running post WIFI_EVENT:2 with handler 0x420139b8 and context 0x3fca9c64 on loop 0x3fca8b38
D (1791) wifi_init_default: wifi_start esp-netif:0x3fca9a60 event-id2
D (1791) wifi_init_default: WIFI mac address: ec da 3b 5b 71 1c
V (1801) esp_adapter: thread sem create: sem=0x3fcb2f3c
V (1801) esp_adapter: thread sem get: sem=0x3fcb2f3c
D (1811) esp_netif_lwip: check: remote, if=0x3fca9a60 fn=0x420108f8
D (1811) esp_netif_lwip: call api in lwip: ret=0x0, give sem
I (1811) wifi station: wifi_init_sta finished.
D (1821) esp_netif_handlers: esp_netif action has started with netif0x3fca9a60 from event_id=2
D (1831) esp_netif_lwip: check: remote, if=0x3fca9a60 fn=0x42011360
D (1841) esp_netif_lwip: esp_netif_start_api 0x3fca9a60
D (1851) esp_netif_lwip: esp_netif_get_hostname esp_netif:0x3fca9a60
D (1851) esp_netif_lwip: call api in lwip: ret=0x0, give sem
D (1861) event: running post WIFI_EVENT:2 with handler 0x4200a3b0 and context 0x3fcb28b0 on loop 0x3fca8b38
V (1871) esp_adapter: thread sem get: sem=0x3fcb2f3c
D (1871) wifi:Start wifi connect
D (1881) wifi:connect status 0 -> 0
D (1881) wifi:connect chan=0
V (1881) wifi:nvs=0, ssid=myssid, channel=255
V (1891) wifi:nvs=1, ssid=WY216, channel=255
V (1891) wifi:ssid=WY216 match nvs 1, channel=255
D (1891) wifi:first chan=1
D (1901) wifi:connect status 0 -> 1
D (1901) wifi:filter: set rx policy=3
D (1901) wifi:clear scan ap list
D (1911) wifi:start scan: type=0x50f, priority=2, cb=0x42032d08, arg=0x0, ss_state=0x1, time=1927050, index=0
V (1921) wifi:inter_channel_timeout: arg=0x0, ss_state=0x1
D (1921) wifi:perform scan: ss_state=0x9, chan<1,0>, dur<0,120>
V (1931) wifi:change: chan<1,0>, dur<0,120>
V (1931) wifi:enter start op, arg=0x3fc9f7fa
V (1931) wifi:scan operation: state=0x3, chan<1,0>, arg=0x3fc9f7fa, status=0
V (1941) wifi:scan specific ssid=WY216
V (1951) wifi:start max timer
D (2071) wifi:scan end: arg=0x3fc9f7fa, status=0, ss_state=0x3
D (2071) wifi:perform scan: ss_state=0x9, chan<2,0>, dur<0,120>
V (2071) wifi:change: chan<2,0>, dur<0,120>
V (2071) wifi:ht20 freq=2417, chan=2
V (2081) wifi:enter start op, arg=0x3fc9f7fa
V (2081) wifi:scan operation: state=0x3, chan<2,0>, arg=0x3fc9f7fa, status=0
V (2091) wifi:scan specific ssid=WY216
V (2091) wifi:start max timer
D (2211) wifi:scan end: arg=0x3fc9f7fa, status=0, ss_state=0x3
D (2211) wifi:perform scan: ss_state=0x9, chan<3,0>, dur<0,120>
V (2211) wifi:change: chan<3,0>, dur<0,120>
V (2221) wifi:ht20 freq=2422, chan=3
V (2221) wifi:enter start op, arg=0x3fc9f7fa
V (2221) wifi:scan operation: state=0x3, chan<3,0>, arg=0x3fc9f7fa, status=0
V (2231) wifi:scan specific ssid=WY216
V (2231) wifi:start max timer
D (2361) wifi:scan end: arg=0x3fc9f7fa, status=0, ss_state=0x3
D (2361) wifi:perform scan: ss_state=0x9, chan<4,0>, dur<0,120>
V (2361) wifi:change: chan<4,0>, dur<0,120>
V (2361) wifi:ht20 freq=2427, chan=4
V (2371) wifi:enter start op, arg=0x3fc9f7fa
V (2371) wifi:scan operation: state=0x3, chan<4,0>, arg=0x3fc9f7fa, status=0
V (2381) wifi:scan specific ssid=WY216
V (2381) wifi:start max timer
D (2501) wifi:scan end: arg=0x3fc9f7fa, status=0, ss_state=0x3
D (2501) wifi:perform scan: ss_state=0x9, chan<5,0>, dur<0,120>
V (2501) wifi:change: chan<5,0>, dur<0,120>
V (2511) wifi:ht20 freq=2432, chan=5
V (2511) wifi:enter start op, arg=0x3fc9f7fa
V (2511) wifi:scan operation: state=0x3, chan<5,0>, arg=0x3fc9f7fa, status=0
V (2521) wifi:scan specific ssid=WY216
V (2521) wifi:start max timer
D (2651) wifi:scan end: arg=0x3fc9f7fa, status=0, ss_state=0x3
D (2651) wifi:perform scan: ss_state=0x9, chan<6,0>, dur<0,120>
V (2651) wifi:change: chan<6,0>, dur<0,120>
V (2651) wifi:ht20 freq=2437, chan=6
V (2651) wifi:enter start op, arg=0x3fc9f7fa
V (2661) wifi:scan operation: state=0x3, chan<6,0>, arg=0x3fc9f7fa, status=0
V (2671) wifi:scan specific ssid=WY216
V (2671) wifi:start max timer
D (2791) wifi:scan end: arg=0x3fc9f7fa, status=0, ss_state=0x3
D (2791) wifi:perform scan: ss_state=0x9, chan<7,0>, dur<0,120>
V (2791) wifi:change: chan<7,0>, dur<0,120>
V (2801) wifi:ht20 freq=2442, chan=7
V (2801) wifi:enter start op, arg=0x3fc9f7fa
V (2801) wifi:scan operation: state=0x3, chan<7,0>, arg=0x3fc9f7fa, status=0
V (2811) wifi:scan specific ssid=WY216
V (2811) wifi:start max timer
D (2941) wifi:scan end: arg=0x3fc9f7fa, status=0, ss_state=0x3
D (2941) wifi:perform scan: ss_state=0x9, chan<8,0>, dur<0,120>
V (2941) wifi:change: chan<8,0>, dur<0,120>
V (2941) wifi:ht20 freq=2447, chan=8
V (2941) wifi:enter start op, arg=0x3fc9f7fa
V (2951) wifi:scan operation: state=0x3, chan<8,0>, arg=0x3fc9f7fa, status=0
V (2951) wifi:scan specific ssid=WY216
V (2961) wifi:start max timer
D (3081) wifi:scan end: arg=0x3fc9f7fa, status=0, ss_state=0x3
D (3081) wifi:perform scan: ss_state=0x9, chan<9,0>, dur<0,120>
V (3081) wifi:change: chan<9,0>, dur<0,120>
V (3091) wifi:ht20 freq=2452, chan=9
V (3091) wifi:enter start op, arg=0x3fc9f7fa
V (3091) wifi:scan operation: state=0x3, chan<9,0>, arg=0x3fc9f7fa, status=0
V (3101) wifi:scan specific ssid=WY216
V (3101) wifi:start max timer
D (3231) wifi:scan end: arg=0x3fc9f7fa, status=0, ss_state=0x3
D (3231) wifi:perform scan: ss_state=0x9, chan<10,0>, dur<0,120>
V (3231) wifi:change: chan<10,0>, dur<0,120>
V (3231) wifi:ht20 freq=2457, chan=10
V (3231) wifi:enter start op, arg=0x3fc9f7fa
V (3241) wifi:scan operation: state=0x3, chan<10,0>, arg=0x3fc9f7fa, status=0
V (3241) wifi:scan specific ssid=WY216
V (3251) wifi:start max timer
D (3371) wifi:scan end: arg=0x3fc9f7fa, status=0, ss_state=0x3
D (3371) wifi:perform scan: ss_state=0x9, chan<11,0>, dur<0,120>
V (3371) wifi:change: chan<11,0>, dur<0,120>
V (3371) wifi:ht20 freq=2462, chan=11
V (3381) wifi:enter start op, arg=0x3fc9f7fa
V (3381) wifi:scan operation: state=0x3, chan<11,0>, arg=0x3fc9f7fa, status=0
V (3391) wifi:scan specific ssid=WY216
V (3391) wifi:start max timer
D (3441) wifi:rsn valid: gcipher=3 ucipher=3 akm=5 mac=5c:27:d4:98:c9:8e
V (3441) wifi:updated connection retries to 0
D (3441) wifi:profile match: ss_state=0x7
V (3441) wifi:scan histroy table is not full yet, add
V (3451) wifi:add ssid=WY216, chan=11 to scan history
D (3451) wifi:scan end: arg=0x3fc9f7fa, status=0, ss_state=0x7
D (3461) wifi:find first mathched ssid, scan done
V (3461) wifi:back home chan=<1,0>, current chan=<11,0>
V (3471) wifi:ht20 freq=2412, chan=1
D (3471) wifi:filter: set rx policy=4
D (3481) wifi:first chan=1
V (3481) wifi:scan_done: arg=0x0, status=0, cur_time=3500151, scan_id=128, scan state=0
V (3491) wifi:call scan_done cb, arg=0x0
D (3491) wifi:handoff_cb: status=0
V (3491) wifi:best bss has set.
D (3501) wifi:ap found, mac=5c:27:d4:98:c9:8e
V (3501) wifi:bssid=5c:27:d4:98:c9:8e, LR=0
D (3501) wifi:going for connection with bssid=5c:27:d4:98:c9:8e
D (3511) wifi:new_bss=0x3fc9fc60, cur_bss=0x0, new_chan=<11,0>, cur_chan=1
D (3521) wifi:filter: set rx policy=5
I (3521) wifi:new:<11,0>, old:<1,0>, ap:<255,255>, sta:<11,0>, prof:1, snd_ch_cfg:0x0
V (3531) wifi:ht20 freq=2462, chan=11
D (3531) wifi:connect_op: status=0, auth=5, cipher=3 
D (3541) wifi:auth mode is not none
D (3541) wifi:connect_bss: auth=1, reconnect=0
I (3541) wifi:state: init -> auth (0xb0)
D (3551) nvs: nvs_get sta.pwr_reset 1
D (3551) nvs: nvs_set sta.pwr_reset 1 1
D (3551) event: running post WIFI_EVENT:43 with handler 0x4200a3b0 and context 0x3fcb28b0 on loop 0x3fca8b38
D (3561) wifi:start 1s AUTH timer
D (3571) wifi:clear scan ap list
D (4571) wifi:auth timeout
I (4571) wifi:state: auth -> init (0x200)
D (4571) nvs: nvs_get sta.pwr_reset 1
D (4571) nvs: nvs_set sta.pwr_reset 1 0
D (4581) wifi:stop beacon and connect timers
D (4581) wifi:connect status 1 -> 4
D (4581) wifi:reason: auth expire(2)
D (4581) wifi:add bssid 5c:27:d4:98:c9:8e to blacklist, cnt=0
D (4591) wifi:stop CSA timer
D (4591) wifi:connect status 4 -> 0
V (4591) wifi:bss connection retry cnt=0
D (4601) wifi:remove 5c:27:d4:98:c9:8e from rc list
I (4601) wifi:new:<11,0>, old:<11,0>, ap:<255,255>, sta:<11,0>, prof:1, snd_ch_cfg:0x0
D (4611) wifi:filter: set rx policy=8
D (4611) wifi:Send disconnect event, reason=2, AP number=0
D (4621) event: running post WIFI_EVENT:5 with handler 0x42013828 and context 0x3fca9cf4 on loop 0x3fca8b38
D (4631) esp_netif_handlers: esp_netif action disconnected with netif0x3fca9a60 from event_id=5
D (4631) esp_netif_lwip: check: remote, if=0x3fca9a60 fn=0x42011614
D (4641) esp_netif_lwip: esp_netif_down_api esp_netif:0x3fca9a60
D (4651) esp_netif_lwip: esp_netif_start_ip_lost_timer esp_netif:0x3fca9a60
D (4651) esp_netif_lwip: if0x3fca9a60 start ip lost tmr: interval=120
D (4661) esp_netif_lwip: check: local, if=0x3fca9a60 fn=0x420119f8
D (4671) esp_netif_lwip: esp_netif_update_default_netif_lwip 0x3fca9a60
V (4671) esp_netif_objects: esp_netif_next_unsafe 0x0
V (4681) esp_netif_lwip: esp_netif_is_netif_up esp_netif:0x3fca9a60
V (4691) esp_netif_objects: esp_netif_next_unsafe 0x3fca9a60
D (4691) esp_netif_lwip: call api in lwip: ret=0x0, give sem
D (4701) event: running post WIFI_EVENT:5 with handler 0x4200a3b0 and context 0x3fcb28b0 on loop 0x3fca8b38
V (4711) esp_adapter: thread sem get: sem=0x3fcb2f3c
D (4711) wifi:Start wifi connect
D (4711) wifi:connect status 0 -> 0
D (4721) wifi:connect chan=0
V (4721) wifi:history=0, ssid=WY216, channel=11
V (4721) wifi:ssid=WY216 match history 0, channel=11
D (4731) wifi:first chan=11
D (4731) wifi:connect status 0 -> 1
D (4731) wifi:filter: set rx policy=3
D (4741) wifi:clear scan ap list
D (4741) wifi:start scan: type=0x50f, priority=2, cb=0x42032d08, arg=0x0, ss_state=0x1, time=4765761, index=0
V (4751) wifi:inter_channel_timeout: arg=0x0, ss_state=0x1
D (4761) wifi:perform scan: ss_state=0x9, chan<11,0>, dur<0,120>
V (4761) wifi:change: chan<11,0>, dur<0,120>
V (4771) wifi:enter start op, arg=0x3fc9f7fa
V (4771) wifi:scan operation: state=0x3, chan<11,0>, arg=0x3fc9f7fa, status=0
V (4781) wifi:scan specific ssid=WY216
V (4781) wifi:start max timer
D (4781) wifi:rsn valid: gcipher=3 ucipher=3 akm=5 mac=5c:27:d4:98:c9:8e
D (4791) wifi:find the 5c:27:d4:98:c9:8e in blacklist.

I (4791) wifi station: retry to connect to the AP
I (4801) wifi station: connect to the AP fail
D (4871) wifi:rsn valid: gcipher=3 ucipher=3 akm=5 mac=5c:27:d4:98:c9:8e
D (4871) wifi:find the 5c:27:d4:98:c9:8e in blacklist.

D (4901) wifi:scan end: arg=0x3fc9f7fa, status=0, ss_state=0x3
D (4901) wifi:perform scan: ss_state=0x9, chan<1,0>, dur<0,120>
V (4901) wifi:change: chan<1,0>, dur<0,120>
V (4911) wifi:ht20 freq=2412, chan=1
V (4911) wifi:enter start op, arg=0x3fc9f7fa
V (4911) wifi:scan operation: state=0x3, chan<1,0>, arg=0x3fc9f7fa, status=0
V (4921) wifi:scan specific ssid=WY216
V (4921) wifi:start max timer
D (5051) wifi:scan end: arg=0x3fc9f7fa, status=0, ss_state=0x3
D (5051) wifi:perform scan: ss_state=0x9, chan<2,0>, dur<0,120>
V (5051) wifi:change: chan<2,0>, dur<0,120>
V (5051) wifi:ht20 freq=2417, chan=2
V (5061) wifi:enter start op, arg=0x3fc9f7fa
V (5061) wifi:scan operation: state=0x3, chan<2,0>, arg=0x3fc9f7fa, status=0
V (5071) wifi:scan specific ssid=WY216
V (5071) wifi:start max timer
D (5191) wifi:scan end: arg=0x3fc9f7fa, status=0, ss_state=0x3
D (5191) wifi:perform scan: ss_state=0x9, chan<3,0>, dur<0,120>
V (5191) wifi:change: chan<3,0>, dur<0,120>
V (5201) wifi:ht20 freq=2422, chan=3
V (5201) wifi:enter start op, arg=0x3fc9f7fa
V (5201) wifi:scan operation: state=0x3, chan<3,0>, arg=0x3fc9f7fa, status=0
V (5211) wifi:scan specific ssid=WY216
V (5211) wifi:start max timer
D (5341) wifi:scan end: arg=0x3fc9f7fa, status=0, ss_state=0x3
D (5341) wifi:perform scan: ss_state=0x9, chan<4,0>, dur<0,120>
V (5341) wifi:change: chan<4,0>, dur<0,120>
V (5341) wifi:ht20 freq=2427, chan=4
V (5341) wifi:enter start op, arg=0x3fc9f7fa
V (5351) wifi:scan operation: state=0x3, chan<4,0>, arg=0x3fc9f7fa, status=0
V (5361) wifi:scan specific ssid=WY216
V (5361) wifi:start max timer
D (5481) wifi:scan end: arg=0x3fc9f7fa, status=0, ss_state=0x3
D (5481) wifi:perform scan: ss_state=0x9, chan<5,0>, dur<0,120>
V (5481) wifi:change: chan<5,0>, dur<0,120>
V (5491) wifi:ht20 freq=2432, chan=5
V (5491) wifi:enter start op, arg=0x3fc9f7fa
V (5491) wifi:scan operation: state=0x3, chan<5,0>, arg=0x3fc9f7fa, status=0
V (5501) wifi:scan specific ssid=WY216
V (5501) wifi:start max timer
D (5631) wifi:scan end: arg=0x3fc9f7fa, status=0, ss_state=0x3
D (5631) wifi:perform scan: ss_state=0x9, chan<6,0>, dur<0,120>
V (5631) wifi:change: chan<6,0>, dur<0,120>
V (5631) wifi:ht20 freq=2437, chan=6
V (5631) wifi:enter start op, arg=0x3fc9f7fa
V (5641) wifi:scan operation: state=0x3, chan<6,0>, arg=0x3fc9f7fa, status=0
V (5641) wifi:scan specific ssid=WY216
V (5651) wifi:start max timer
D (5771) wifi:scan end: arg=0x3fc9f7fa, status=0, ss_state=0x3
D (5771) wifi:perform scan: ss_state=0x9, chan<7,0>, dur<0,120>
V (5771) wifi:change: chan<7,0>, dur<0,120>
V (5781) wifi:ht20 freq=2442, chan=7
V (5781) wifi:enter start op, arg=0x3fc9f7fa
V (5781) wifi:scan operation: state=0x3, chan<7,0>, arg=0x3fc9f7fa, status=0
V (5791) wifi:scan specific ssid=WY216
V (5791) wifi:start max timer
D (5921) wifi:scan end: arg=0x3fc9f7fa, status=0, ss_state=0x3
D (5921) wifi:perform scan: ss_state=0x9, chan<8,0>, dur<0,120>
V (5921) wifi:change: chan<8,0>, dur<0,120>
V (5921) wifi:ht20 freq=2447, chan=8
V (5921) wifi:enter start op, arg=0x3fc9f7fa
V (5931) wifi:scan operation: state=0x3, chan<8,0>, arg=0x3fc9f7fa, status=0
V (5931) wifi:scan specific ssid=WY216
V (5941) wifi:start max timer
D (6061) wifi:scan end: arg=0x3fc9f7fa, status=0, ss_state=0x3
D (6061) wifi:perform scan: ss_state=0x9, chan<9,0>, dur<0,120>
V (6061) wifi:change: chan<9,0>, dur<0,120>
V (6061) wifi:ht20 freq=2452, chan=9
V (6071) wifi:enter start op, arg=0x3fc9f7fa
V (6071) wifi:scan operation: state=0x3, chan<9,0>, arg=0x3fc9f7fa, status=0
V (6081) wifi:scan specific ssid=WY216
V (6081) wifi:start max timer
D (6201) wifi:scan end: arg=0x3fc9f7fa, status=0, ss_state=0x3
D (6211) wifi:perform scan: ss_state=0x9, chan<10,0>, dur<0,120>
V (6211) wifi:change: chan<10,0>, dur<0,120>
V (6211) wifi:ht20 freq=2457, chan=10
V (6211) wifi:enter start op, arg=0x3fc9f7fa
V (6221) wifi:scan operation: state=0x3, chan<10,0>, arg=0x3fc9f7fa, status=0
V (6221) wifi:scan specific ssid=WY216
V (6231) wifi:start max timer
D (6351) wifi:scan end: arg=0x3fc9f7fa, status=0, ss_state=0x3
D (6351) wifi:perform scan: ss_state=0x9, chan<12,0>, dur<360,360>
V (6351) wifi:change: chan<12,0>, dur<360,360>
V (6351) wifi:ht20 freq=2467, chan=12
V (6361) wifi:enter start op, arg=0x3fc9f7fa
V (6361) wifi:scan operation: state=0x3, chan<12,0>, arg=0x3fc9f7fa, status=0
V (6371) wifi:passive scan, listen only
V (6371) wifi:start max timer
D (6741) wifi:scan end: arg=0x3fc9f7fa, status=0, ss_state=0x3
D (6741) wifi:perform scan: ss_state=0x9, chan<13,0>, dur<360,360>
V (6741) wifi:change: chan<13,0>, dur<360,360>
V (6741) wifi:ht20 freq=2472, chan=13
V (6741) wifi:enter start op, arg=0x3fc9f7fa
V (6751) wifi:scan operation: state=0x3, chan<13,0>, arg=0x3fc9f7fa, status=0
V (6751) wifi:passive scan, listen only
V (6761) wifi:start max timer
D (7121) wifi:scan end: arg=0x3fc9f7fa, status=0, ss_state=0x3
D (7121) wifi:perform scan: ss_state=0x9, chan<14,0>, dur<360,360>
V (7121) wifi:change: chan<14,0>, dur<360,360>
V (7131) wifi:ht20 freq=2484, chan=14
V (7131) wifi:enter start op, arg=0x3fc9f7fa
V (7131) wifi:scan operation: state=0x3, chan<14,0>, arg=0x3fc9f7fa, status=0
V (7141) wifi:passive scan, listen only
V (7141) wifi:start max timer
D (7511) wifi:scan end: arg=0x3fc9f7fa, status=0, ss_state=0x3
V (7511) wifi:back home chan=<11,0>, current chan=<14,0>
V (7511) wifi:ht20 freq=2462, chan=11
D (7511) wifi:filter: set rx policy=4
D (7511) wifi:first chan=1
V (7521) wifi:scan_done: arg=0x0, status=0, cur_time=7540437, scan_id=128, scan state=0
V (7521) wifi:call scan_done cb, arg=0x0
D (7531) wifi:handoff_cb: status=0
V (7531) wifi:there is only one ap in blacklist now, release it!
D (7541) wifi:clear blacklist
D (7541) wifi:clear rc list
D (7541) wifi:clear blacklist
D (7541) wifi:Send disconnect event, reason=205
D (7551) wifi:connect status 1 -> 3
D (7551) wifi:disable connect timer
D (7551) wifi:clear scan ap list
D (7561) event: running post WIFI_EVENT:5 with handler 0x42013828 and context 0x3fca9cf4 on loop 0x3fca8b38
D (7571) esp_netif_handlers: esp_netif action disconnected with netif0x3fca9a60 from event_id=5
D (7581) esp_netif_lwip: check: remote, if=0x3fca9a60 fn=0x42011614
D (7581) esp_netif_lwip: esp_netif_down_api esp_netif:0x3fca9a60
D (7591) esp_netif_lwip: esp_netif_start_ip_lost_timer esp_netif:0x3fca9a60
D (7591) esp_netif_lwip: if0x3fca9a60 start ip lost tmr: already started
D (7601) esp_netif_lwip: check: local, if=0x3fca9a60 fn=0x420119f8
D (7611) esp_netif_lwip: esp_netif_update_default_netif_lwip 0x3fca9a60
V (7611) esp_netif_objects: esp_netif_next_unsafe 0x0
V (7621) esp_netif_lwip: esp_netif_is_netif_up esp_netif:0x3fca9a60
V (7631) esp_netif_objects: esp_netif_next_unsafe 0x3fca9a60
D (7631) esp_netif_lwip: call api in lwip: ret=0x0, give sem
D (7641) event: running post WIFI_EVENT:5 with handler 0x4200a3b0 and context 0x3fcb28b0 on loop 0x3fca8b38
V (7651) esp_adapter: thread sem get: sem=0x3fcb2f3c
D (7651) wifi:Start wifi connect
D (7661) wifi:connect status 3 -> 0
D (7661) wifi:connect chan=0
V (7661) wifi:history=0, ssid=WY216, channel=11
V (7671) wifi:ssid=WY216 match history 0, channel=11
D (7671) wifi:first chan=11
D (7671) wifi:connect status 0 -> 1
D (7681) wifi:filter: set rx policy=3
D (7681) wifi:clear scan ap list
D (7681) wifi:start scan: type=0x50f, priority=2, cb=0x42032d08, arg=0x0, ss_state=0x1, time=7707449, index=0
V (7691) wifi:inter_channel_timeout: arg=0x0, ss_state=0x1
D (7701) wifi:perform scan: ss_state=0x9, chan<11,0>, dur<0,120>
V (7701) wifi:change: chan<11,0>, dur<0,120>
V (7711) wifi:enter start op, arg=0x3fc9f7fa
V (7711) wifi:scan operation: state=0x3, chan<11,0>, arg=0x3fc9f7fa, status=0
V (7721) wifi:scan specific ssid=WY216
V (7721) wifi:start max timer
I (7721) wifi station: retry to connect to the AP
I (7731) wifi station: connect to the AP fail
D (7741) wifi:rsn valid: gcipher=3 ucipher=3 akm=5 mac=5c:27:d4:98:c9:8e
V (7741) wifi:updated connection retries to 0
D (7751) wifi:profile match: ss_state=0x7
V (7751) wifi:update scan history ssid=WY216, channel=11
D (7751) wifi:scan end: arg=0x3fc9f7fa, status=0, ss_state=0x7
D (7761) wifi:find first mathched ssid, scan done
V (7761) wifi:back home chan=<11,0>, current chan=<11,0>
D (7771) wifi:filter: set rx policy=4
D (7771) wifi:first chan=1
V (7771) wifi:scan_done: arg=0x0, status=0, cur_time=7799596, scan_id=128, scan state=0
V (7781) wifi:call scan_done cb, arg=0x0
D (7791) wifi:handoff_cb: status=0
V (7791) wifi:best bss has set.
D (7791) wifi:ap found, mac=5c:27:d4:98:c9:8e
V (7801) wifi:bssid=5c:27:d4:98:c9:8e, LR=0
D (7801) wifi:going for connection with bssid=5c:27:d4:98:c9:8e
D (7811) wifi:new_bss=0x3fc9fc60, cur_bss=0x0, new_chan=<11,0>, cur_chan=11
D (7811) wifi:filter: set rx policy=5
I (7821) wifi:new:<11,0>, old:<11,0>, ap:<255,255>, sta:<11,0>, prof:1, snd_ch_cfg:0x0
D (7821) wifi:connect_op: status=0, auth=5, cipher=3 
D (7831) wifi:auth mode is not none
D (7831) wifi:connect_bss: auth=1, reconnect=0
I (7841) wifi:state: init -> auth (0xb0)
D (7841) nvs: nvs_get sta.pwr_reset 1
D (7841) nvs: nvs_set sta.pwr_reset 1 1
D (7861) wifi:start 1s AUTH timer
D (7861) wifi:clear scan ap list
D (8861) wifi:auth timeout
I (8861) wifi:state: auth -> init (0x200)
D (8861) nvs: nvs_get sta.pwr_reset 1
D (8861) nvs: nvs_set sta.pwr_reset 1 0
D (8871) wifi:stop beacon and connect timers
D (8871) wifi:connect status 1 -> 4
D (8871) wifi:reason: auth expire(2)
D (8871) wifi:add bssid 5c:27:d4:98:c9:8e to blacklist, cnt=0
D (8881) wifi:stop CSA timer
D (8881) wifi:connect status 4 -> 0
V (8881) wifi:bss connection retry cnt=0
D (8891) wifi:remove 5c:27:d4:98:c9:8e from rc list
I (8891) wifi:new:<11,0>, old:<11,0>, ap:<255,255>, sta:<11,0>, prof:1, snd_ch_cfg:0x0
D (8901) wifi:filter: set rx policy=8
D (8901) wifi:Send disconnect event, reason=2, AP number=0
D (8911) event: running post WIFI_EVENT:5 with handler 0x42013828 and context 0x3fca9cf4 on loop 0x3fca8b38
D (8921) esp_netif_handlers: esp_netif action disconnected with netif0x3fca9a60 from event_id=5
D (8921) esp_netif_lwip: check: remote, if=0x3fca9a60 fn=0x42011614
D (8931) esp_netif_lwip: esp_netif_down_api esp_netif:0x3fca9a60
D (8941) esp_netif_lwip: esp_netif_start_ip_lost_timer esp_netif:0x3fca9a60
D (8941) esp_netif_lwip: if0x3fca9a60 start ip lost tmr: already started
D (8951) esp_netif_lwip: check: local, if=0x3fca9a60 fn=0x420119f8
D (8961) esp_netif_lwip: esp_netif_update_default_netif_lwip 0x3fca9a60
V (8961) esp_netif_objects: esp_netif_next_unsafe 0x0
V (8971) esp_netif_lwip: esp_netif_is_netif_up esp_netif:0x3fca9a60
V (8981) esp_netif_objects: esp_netif_next_unsafe 0x3fca9a60
D (8981) esp_netif_lwip: call api in lwip: ret=0x0, give sem
D (8991) event: running post WIFI_EVENT:5 with handler 0x4200a3b0 and context 0x3fcb28b0 on loop 0x3fca8b38
V (9001) esp_adapter: thread sem get: sem=0x3fcb2f3c
D (9001) wifi:Start wifi connect
D (9001) wifi:connect status 0 -> 0
D (9011) wifi:connect chan=0
V (9011) wifi:history=0, ssid=WY216, channel=11
V (9011) wifi:ssid=WY216 match history 0, channel=11
D (9021) wifi:first chan=11
D (9021) wifi:connect status 0 -> 1
D (9021) wifi:filter: set rx policy=3
D (9031) wifi:clear scan ap list
D (9031) wifi:start scan: type=0x50f, priority=2, cb=0x42032d08, arg=0x0, ss_state=0x1, time=9057974, index=0
V (9041) wifi:inter_channel_timeout: arg=0x0, ss_state=0x1
D (9051) wifi:perform scan: ss_state=0x9, chan<11,0>, dur<0,120>
V (9051) wifi:change: chan<11,0>, dur<0,120>
V (9061) wifi:enter start op, arg=0x3fc9f7fa
V (9061) wifi:scan operation: state=0x3, chan<11,0>, arg=0x3fc9f7fa, status=0
V (9071) wifi:scan specific ssid=WY216
V (9071) wifi:start max timer
D (9071) wifi:rsn valid: gcipher=3 ucipher=3 akm=5 mac=5c:27:d4:98:c9:8e
D (9081) wifi:find the 5c:27:d4:98:c9:8e in blacklist.

I (9081) wifi station: retry to connect to the AP
I (9091) wifi station: connect to the AP fail
D (9181) wifi:rsn valid: gcipher=3 ucipher=3 akm=5 mac=5c:27:d4:98:c9:8e
D (9181) wifi:find the 5c:27:d4:98:c9:8e in blacklist.

D (9191) wifi:scan end: arg=0x3fc9f7fa, status=0, ss_state=0x3
D (9191) wifi:perform scan: ss_state=0x9, chan<1,0>, dur<0,120>
V (9191) wifi:change: chan<1,0>, dur<0,120>
V (9201) wifi:ht20 freq=2412, chan=1
V (9201) wifi:enter start op, arg=0x3fc9f7fa
V (9201) wifi:scan operation: state=0x3, chan<1,0>, arg=0x3fc9f7fa, status=0
V (9211) wifi:scan specific ssid=WY216
V (9211) wifi:start max timer
D (9341) wifi:scan end: arg=0x3fc9f7fa, status=0, ss_state=0x3
D (9341) wifi:perform scan: ss_state=0x9, chan<2,0>, dur<0,120>
V (9341) wifi:change: chan<2,0>, dur<0,120>
V (9341) wifi:ht20 freq=2417, chan=2
V (9351) wifi:enter start op, arg=0x3fc9f7fa
V (9351) wifi:scan operation: state=0x3, chan<2,0>, arg=0x3fc9f7fa, status=0
V (9361) wifi:scan specific ssid=WY216
V (9361) wifi:start max timer
D (9481) wifi:scan end: arg=0x3fc9f7fa, status=0, ss_state=0x3
D (9481) wifi:perform scan: ss_state=0x9, chan<3,0>, dur<0,120>
V (9481) wifi:change: chan<3,0>, dur<0,120>
V (9491) wifi:ht20 freq=2422, chan=3
V (9491) wifi:enter start op, arg=0x3fc9f7fa
V (9491) wifi:scan operation: state=0x3, chan<3,0>, arg=0x3fc9f7fa, status=0
V (9501) wifi:scan specific ssid=WY216
V (9501) wifi:start max timer
D (9631) wifi:scan end: arg=0x3fc9f7fa, status=0, ss_state=0x3
D (9631) wifi:perform scan: ss_state=0x9, chan<4,0>, dur<0,120>
V (9631) wifi:change: chan<4,0>, dur<0,120>
V (9631) wifi:ht20 freq=2427, chan=4
V (9631) wifi:enter start op, arg=0x3fc9f7fa
V (9641) wifi:scan operation: state=0x3, chan<4,0>, arg=0x3fc9f7fa, status=0
V (9651) wifi:scan specific ssid=WY216
V (9651) wifi:start max timer
D (9771) wifi:scan end: arg=0x3fc9f7fa, status=0, ss_state=0x3
D (9771) wifi:perform scan: ss_state=0x9, chan<5,0>, dur<0,120>
V (9771) wifi:change: chan<5,0>, dur<0,120>
V (9781) wifi:ht20 freq=2432, chan=5
V (9781) wifi:enter start op, arg=0x3fc9f7fa
V (9781) wifi:scan operation: state=0x3, chan<5,0>, arg=0x3fc9f7fa, status=0
V (9791) wifi:scan specific ssid=WY216
V (9791) wifi:start max timer

More Information.

No response
@beanjs beanjs added the Type: Bug bugs in IDF label Aug 30, 2024
@beanjs
Copy link
Author

beanjs commented Aug 30, 2024

sdkconfig.zip

@github-actions github-actions bot changed the title ESP32S3 WIFI join AP failure ESP32S3 WIFI join AP failure (IDFGH-13577) Aug 30, 2024
@espressif-bot espressif-bot added the Status: Opened Issue is new label Aug 30, 2024
@beanjs
Copy link
Author

beanjs commented Sep 2, 2024

smartconfig can receive configuration information，but join AP always failure

I (43155) smartconfig: TYPE: AIRKISS
I (43155) smartconfig: T|PHONE MAC: ea:34:b4:16:69:7f
I (43155) smartconfig: T|AP MAC:5c:27:d4:98:c9:8e
I (43156) smartconfig: Found channel on 11-0. Start to get ssid and password...
I (45910) smartconfig: T|pswd: wy12345678
I (45910) smartconfig: T|ssid: WY216
I (45910) wifi:ic_disable_sniffer
W (00:01:06.733) WIFI: ssid:WY216 password:wy12345678
W (45916) wifi:Password length matches WPA2 standards, authmode threshold changes from OPEN to WPA2
I (47505) wifi:new:<11,0>, old:<11,0>, ap:<255,255>, sta:<11,0>, prof:1, snd_ch_cfg:0x0
I (47505) wifi:state: init -> auth (0xb0)
I (48506) wifi:state: auth -> init (0x200)
I (48509) wifi:new:<11,0>, old:<11,0>, ap:<255,255>, sta:<11,0>, prof:1, snd_ch_cfg:0x0
I (50973) wifi:new:<11,0>, old:<11,0>, ap:<255,255>, sta:<11,0>, prof:1, snd_ch_cfg:0x0
I (50974) wifi:state: init -> auth (0xb0)
I (51976) wifi:state: auth -> init (0x200)
I (51978) wifi:new:<11,0>, old:<11,0>, ap:<255,255>, sta:<11,0>, prof:1, snd_ch_cfg:0x0
I (00:01:13.427) WL: total: 9428(KB)  free: 9428(KB) pst: 100

@zhangyanjiaoesp
Copy link
Collaborator

@beanjs It seems the ESP32S3 send auth packet, but doesn't receive the auth packet from AP. Is there any special about your AP？Is your AP a router or a hotspot？Can you provide a packet capture using Wireshark?

@espressif-bot espressif-bot added Status: In Progress Work is in progress and removed Status: Opened Issue is new labels Sep 4, 2024
@beanjs
Copy link
Author

beanjs commented Sep 5, 2024

请问怎么使用Wireshark进行抓包？

@zhangyanjiaoesp
Copy link
Collaborator

@beanjs you can refer this link https://docs.espressif.com/projects/esp-idf/zh_CN/latest/esp32/api-guides/wireshark-user-guide.html#wireshark

@beanjs
Copy link
Author

beanjs commented Sep 5, 2024

你发的这个教程连接，感觉里面没什么干货啊。就是简单的软件使用，就我现在的问题也没有具体的抓包方法和查找问题的方法。另外这个问题是出现在谋几个模块上，有的模块又是没有问题的。所以我感觉这个不是路由器的问题吧。

@zhangyanjiaoesp
Copy link
Collaborator

就是简单的软件使用，就我现在的问题也没有具体的抓包方法和查找问题的方法。

在过滤条件里面设置 AP 的 mac 地址和 STA 的 mac 地址，设置正确的 channel，抓包就可以了。如下图，显示了 STA 连接 AP 的过程：
image (5)
抓包保存后，当去掉过滤条件之后会显示 mac ACK 的抓包，表示收到了对方的包。
image (6)

这个问题是出现在谋几个模块上，有的模块又是没有问题的

这个情况你之前并没有说明，如果是这样的话，可能是模块的问题，不过还是可以抓包确认一下。

@beanjs
Copy link
Author

beanjs commented Sep 5, 2024

Authentication数据包就没有发出，这个是不是说明芯片坏了？但是我刚才测试了芯片的AP模式，这个模式又是工作正常的，就是STA模式在连接AP的时候，没有发送Authentication数据包。不过smartconfig又能接收到手机发出的AP配置信息。

@beanjs
Copy link
Author

beanjs commented Sep 5, 2024

2024-09-05_11.12.10.257.pcap.zip

@beanjs
Copy link
Author

beanjs commented Sep 5, 2024

@zhangyanjiaoesp 您好，我大概理清楚原因了。会不会是SDK里面对Authentication的发送进行了某种判断，然后因为没有打不到某个条件导致没有发出Authentication数据包，从而导致了wifi:start 1s AUTH timer超时从而触发了WIFI_EVENT_STA_DISCONNECTED事件

@zhangyanjiaoesp
Copy link
Collaborator

wifi:start 1s AUTH timer 这个timer 是在 auth 发送了之后才启动的。station example 会默认重连5次，5 次都连接不成功吗？

@beanjs
Copy link
Author

beanjs commented Sep 5, 2024 •
edited
Loading

都不成功呢，每次都是因为wifi:start 1s AUTH timer超时引起WIFI_EVENT_STA_DISCONNECTED 事件。

D (7861) wifi:start 1s AUTH timer
D (7861) wifi:clear scan ap list
D (8861) wifi:auth timeout
I (8861) wifi:state: auth -> init (0x200)

@zhangyanjiaoesp
Copy link
Collaborator

2024-09-05_11.12.10.257.pcap.zip
会不会是这个抓包里面没有抓到auth 包？你的 STA 的 mac 地址是多少？

@beanjs
Copy link
Author

beanjs commented Sep 5, 2024

这个抓包是能抓到Authentication数据包的，发出来的这个是有问题那个模块的抓包文件。另外正常的模块是可以抓到Authentication包的，验证过程和你发给我那个图片的差不多。我就没有发了，我现在另外给你抓个正常模块的包。

2024-09-05_15.08.39.900.pcap.zip

@zhangyanjiaoesp
Copy link
Collaborator

你用 release/v5.3 的分支测试一下？

@beanjs
Copy link
Author

beanjs commented Sep 5, 2024 •
edited
Loading

也还是一样的，我拉取的是最新的代码，也就是合并5.3.1的。

I (24443) wifi:new:<11,0>, old:<11,0>, ap:<255,255>, sta:<11,0>, prof:1, snd_ch_cfg:0x0
D (24451) wifi:connect_op: status=0, auth=5, cipher=3 
D (24455) wifi:auth mode is not none
D (24459) wifi:connect_bss: auth=1, reconnect=0
I (24463) wifi:state: init -> auth (0xb0)
D (24469) wifi:start 1s AUTH timer
D (24470) wifi:clear scan ap list
D (25470) wifi:auth timeout
I (25470) wifi:state: auth -> init (0x200)
D (25473) wifi:stop beacon and connect timers
D (25473) wifi:connect status 1 -> 4
D (25473) wifi:reason: auth expire(2)

0x420b0b00: cnx_start_handoff_cb at ??:?

@zhangyanjiaoesp
Copy link
Collaborator

这个抓包是能抓到Authentication数据包的，发出来的这个是有问题那个模块的抓包文件。另外正常的模块是可以抓到Authentication包的，验证过程和你发给我那个图片的差不多。我就没有发了，我现在另外给你抓个正常模块的包。

2024-09-05_15.08.39.900.pcap.zip

这个抓包是有问题的还是没问题的？ STA 的MAC 地址是多少？我过滤抓包看一下

@zhangyanjiaoesp
Copy link
Collaborator

也还是一样的，我拉取的是最新的代码，也就是合并5.3.1的。

I (24443) wifi:new:<11,0>, old:<11,0>, ap:<255,255>, sta:<11,0>, prof:1, snd_ch_cfg:0x0
D (24451) wifi:connect_op: status=0, auth=5, cipher=3 
D (24455) wifi:auth mode is not none
D (24459) wifi:connect_bss: auth=1, reconnect=0
I (24463) wifi:state: init -> auth (0xb0)
D (24469) wifi:start 1s AUTH timer
D (24470) wifi:clear scan ap list
D (25470) wifi:auth timeout
I (25470) wifi:state: auth -> init (0x200)
D (25473) wifi:stop beacon and connect timers
D (25473) wifi:connect status 1 -> 4
D (25473) wifi:reason: auth expire(2)

0x420b0b00: cnx_start_handoff_cb at ??:?

5.3分支和 master 分支还是有区别的，如果 5.3 也连不上，可能和分支没什么关系。

@beanjs
Copy link
Author

beanjs commented Sep 5, 2024

这个是正常模块的抓包数据，你查找Authentication就可以了。

001

@zhangyanjiaoesp
Copy link
Collaborator

这个抓包是能抓到Authentication数据包的，发出来的这个是有问题那个模块的抓包文件。另外正常的模块是可以抓到Authentication包的，验证过程和你发给我那个图片的差不多。我就没有发了，我现在另外给你抓个正常模块的包。
2024-09-05_15.08.39.900.pcap.zip

这个抓包是有问题的还是没问题的？ STA 的MAC 地址是多少？我过滤抓包看一下

@beanjs 失败的设备的 MAC 地址是多少？要查看一下其他包，看是不是有其他包影响了。

@beanjs
Copy link
Author

beanjs commented Sep 5, 2024

@zhangyanjiaoesp 失败设备的MAC是ec:da:3b:5b:71:20。现在我们是单独弄了个无线路由器来测试的，这个路由器只无线设备只连接了手机和ESP32S3模块，手机是用来使用airkiss进行配网的。

@zhangyanjiaoesp
Copy link
Collaborator

image

设置过滤条件之后一个包都没有，看起来STA 时候的TX模块坏了，建议你换其他 ESP32S3 模块吧。

@beanjs
Copy link
Author

beanjs commented Sep 5, 2024

STA和AP的时候使用的不是相同的TX和RX模块么？现在这个模块的AP模式是正常的。另外就是如果TX模块不正常的话smartconfig应该是不能正确接收配网信息的吧？

@zhangyanjiaoesp
Copy link
Collaborator

zhangyanjiaoesp commented Sep 5, 2024 •
edited
Loading

smartconfig 是通过sniffer 模式接收配网信息的， 收包的时候不需要 TX

@zhangyanjiaoesp
Copy link
Collaborator

STA和AP的时候使用的不是相同的TX和RX模块么？现在这个模块的AP模式是正常的

AP 模式的时候能正常接收外面 STA 的连接？那你把设备设置成 STA+softAP 模式，再连接路由器试试？

@zhangyanjiaoesp
Copy link
Collaborator

@beanjs 有什么进展吗？

@beanjs
Copy link
Author

beanjs commented Sep 9, 2024

@zhangyanjiaoesp 还是一样的问题，我现在是越来越蒙了。蓝牙是正常的，softAP是正常的，就STA不正常，我也是醉了。

@zhangyanjiaoesp
Copy link
Collaborator

那你把设备设置成 STA+softAP 模式，再连接路由器试试？

@beanjs 这样试过吗？

@beanjs
Copy link
Author

beanjs commented Sep 10, 2024

那你把设备设置成 STA+softAP 模式，再连接路由器试试？

@beanjs 这样试过吗？

@zhangyanjiaoesp 试过来的，这个模式下面STA还是有问题，但是softAP没有问题，我现在真的懵逼了。

@zhangyanjiaoesp
Copy link
Collaborator

作为softAP被其他设备成功连接的 log 能上传一下吗？sdkconfig 能上传一下吗？

@beanjs
Copy link
Author

beanjs commented Sep 11, 2024

@zhangyanjiaoesp 可以，我先把手上的事情弄一下，这几天都在研究这个事情，项目进度都慢下来了。弄完就抓日志给你。

@zhangyanjiaoesp
Copy link
Collaborator

好的，建议切换信道测试一下，连接其他信道的AP 测试一下。

@beanjs
Copy link
Author

beanjs commented Sep 23, 2024

@zhangyanjiaoesp 你看看会不会是这个引起的，我把射频功率调整到+21db以后就容易出现这个问题。恢复到+9db以后，发生这个问题的几率就变小了。另外在+21db的程序运行以后在切换成+9db的时候，问题依旧。

@zhangyanjiaoesp
Copy link
Collaborator

@beanjs 你的意思是调用 esp_wifi_set_max_tx_power(power) 设置 power 值为 21 或者 9 ?

@AxelLin
Copy link
Contributor

AxelLin commented Nov 7, 2024

@beanjs
How is the status of this issue now?
Can you answer #14465 (comment) ?

@beanjs
Copy link
Author

beanjs commented Nov 7, 2024

@AxelLin Already switched to esp32c3 chip

@zhangyanjiaoesp
Copy link
Collaborator

@beanjs Can we close this issue?

@beanjs beanjs closed this as completed Dec 19, 2024
@espressif-bot espressif-bot added Status: Done Issue is done internally Resolution: Done Issue is done internally and removed Status: In Progress Work is in progress labels Dec 19, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@zhangyanjiaoesp zhangyanjiaoesp

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

No branches or pull requests
5 participants
@AxelLin @MaxwellAlan @beanjs @zhangyanjiaoesp @espressif-bot