espressif / esp-idf

Espressif IoT Development Framework. Official development framework for Espressif SoCs.
Apache License 2.0
12.91k stars 7.09k forks source link

Network requests failing occasionally when connected to bridged network (IDFGH-12630) #13628

Open swidget opened 2 months ago

swidget commented 2 months ago

Answers checklist.

IDF version.

v5.3-dev-3225-g5a40bb8746

Espressif SoC revision.

ESP32-S3

Operating System used.

Windows

How did you build your project?

Command line with CMake

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

CMD

Development Kit.

Custom Board

Power Supply used.

External 5V

What is the expected behavior?

I expected the device to remain connected to WiFi without issue when connected to a bridged network.

What is the actual behavior?

The device will occasionally fail to perform network requests (without receiving a WiFi Disconnect event), once it begins to fail making requests, this will continue for about 15 minutes until a WiFi disconnect occurs, at which point it will perform a reconnect and begin to operate as normal. This is occuring using the http_request example. The issue also results in pinging the default gateway to fail, but UDP broadcast packets are still sent out to the network. This issue does not occur on all networks, it does occur on one of my networks in bridged mode.

Steps to reproduce.

Setup the example to connect to the router in bridged mode, then let the http_request to run until issue occurs.

Debug Logs.

SPIWP:0xee
mode:DIO, clock div:1
load:0x3fce2810,len:0x178c
load:0x403c8700,len:0x4
load:0x403c8704,len:0xcb8
load:0x403cb700,len:0x2d9c
entry 0x403c8914
I (26) boot: ESP-IDF v5.3-dev-3225-g5a40bb8746-dirty 2nd stage bootloader
I (27) boot: compile time Apr 11 2024 12:44:51
I (28) boot: Multicore bootloader
I (32) boot: chip revision: v0.2
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 (55) 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=3c090020 size=26ca0h (158880) map
I (130) esp_image: segment 1: paddr=00036cc8 vaddr=3fc98b00 size=047e4h ( 18404) load
I (134) esp_image: segment 2: paddr=0003b4b4 vaddr=40374000 size=04b64h ( 19300) load
I (140) esp_image: segment 3: paddr=00040020 vaddr=42000020 size=85d00h (548096) map
I (242) esp_image: segment 4: paddr=000c5d28 vaddr=40378b64 size=0fef8h ( 65272) load
I (265) boot: Loaded app from partition at offset 0x10000
I (266) boot: Disabling RNG early entropy source...
I (277) cpu_start: Multicore app
D (277) cpu_start: Pro cpu up
D (278) cpu_start: Starting app cpu, entry point is 0x40375340
0x40375340: call_start_cpu1 at /home/thunder/build/last_sdk/esp-idf/components/esp_system/port/cpu_start.c:194

D (0) cpu_start: App cpu up
D (288) clk: RTC_SLOW_CLK calibration value: 3576256
D (299) cpu_start: calling init function: 0x420023b0 on core: 0
0x420023b0: __esp_system_init_fn_init_efuse_check at /home/thunder/build/last_sdk/esp-idf/components/efuse/src/esp_efuse_startup.c:31

D (299) cpu_start: calling init function: 0x42002858 on core: 0
0x42002858: __esp_system_init_fn_init_show_cpu_freq at /home/thunder/build/last_sdk/esp-idf/components/esp_system/startup_funcs.c:58

I (299) cpu_start: Pro cpu start user code
I (304) cpu_start: cpu freq: 160000000 Hz
D (309) cpu_start: calling init function: 0x420022e0 on core: 0
0x420022e0: __esp_system_init_fn_init_show_app_info at /home/thunder/build/last_sdk/esp-idf/components/esp_app_format/esp_app_desc.c:104

I (315) app_init: Application information:
I (319) app_init: Project name:     http_request
I (325) app_init: App version:      v5.3-dev-3225-g5a40bb8746-dirty
I (332) app_init: Compile time:     Apr 11 2024 12:44:48
I (338) app_init: ELF file SHA256:  8afaff026...
I (343) app_init: ESP-IDF:          v5.3-dev-3225-g5a40bb8746-dirty
D (350) cpu_start: calling init function: 0x420023c4 on core: 0
0x420023c4: __esp_system_init_fn_init_efuse_show_app_info at /home/thunder/build/last_sdk/esp-idf/components/efuse/src/esp_efuse_startup.c:41

I (356) efuse_init: Min chip rev:     v0.0
I (361) efuse_init: Max chip rev:     v0.99
I (366) efuse_init: Chip rev:         v0.2
D (370) cpu_start: calling init function: 0x4200445c on core: 0
0x4200445c: __esp_system_init_fn_init_heap at /home/thunder/build/last_sdk/esp-idf/components/heap/heap_caps_init.c:25

D (376) memory_layout: Checking 6 reserved memory ranges:
D (382) memory_layout: Reserved memory range 0x3fc84000 - 0x3fc98b00
D (388) memory_layout: Reserved memory range 0x3fc98b00 - 0x3fca1298
D (395) memory_layout: Reserved memory range 0x3fceee34 - 0x3fcf0000
D (401) memory_layout: Reserved memory range 0x40374000 - 0x40388b00
0x40374000: _WindowOverflow4 at /home/thunder/build/last_sdk/esp-idf/components/xtensa/xtensa_vectors.S:2027

D (408) memory_layout: Reserved memory range 0x600fe000 - 0x600fe100
D (414) memory_layout: Reserved memory range 0x600fffe8 - 0x60100000
D (420) memory_layout: Building list of available memory regions:
D (427) memory_layout: Available memory region 0x3fca1298 - 0x3fcb0000
D (433) memory_layout: Available memory region 0x3fcb0000 - 0x3fcc0000
D (440) memory_layout: Available memory region 0x3fcc0000 - 0x3fcd0000
D (446) memory_layout: Available memory region 0x3fcd0000 - 0x3fce0000
D (453) memory_layout: Available memory region 0x3fce0000 - 0x3fce9710
D (460) memory_layout: Available memory region 0x3fce9710 - 0x3fceee34
D (466) memory_layout: Available memory region 0x3fcf0000 - 0x3fcf8000
D (473) memory_layout: Available memory region 0x600fe100 - 0x600fffe8
I (479) heap_init: Initializing. RAM available for dynamic allocation:
D (487) heap_init: New heap initialised at 0x3fca1298
I (492) heap_init: At 3FCA1298 len 00048478 (289 KiB): RAM
I (498) heap_init: At 3FCE9710 len 00005724 (21 KiB): RAM
D (504) heap_init: New heap initialised at 0x3fcf0000
I (509) heap_init: At 3FCF0000 len 00008000 (32 KiB): DRAM
D (515) heap_init: New heap initialised at 0x600fe100
I (520) heap_init: At 600FE100 len 00001EE8 (7 KiB): RTCRAM
D (527) cpu_start: calling init function: 0x42007ae8 on core: 0
0x42007ae8: __esp_system_init_fn_esp_timer_init_nonos at /home/thunder/build/last_sdk/esp-idf/components/esp_timer/src/esp_timer_init.c:28

D (533) cpu_start: calling init function: 0x420072e4 on core: 0
0x420072e4: __esp_system_init_fn_init_newlib at /home/thunder/build/last_sdk/esp-idf/components/newlib/newlib_init.c:162

D (539) cpu_start: calling init function: 0x420028a4 on core: 0
0x420028a4: __esp_system_init_fn_init_brownout at /home/thunder/build/last_sdk/esp-idf/components/esp_system/startup_funcs.c:67

D (545) intr_alloc: Connected src 39 to int 1 (cpu 0)
D (550) cpu_start: calling init function: 0x420028b0 on core: 0
0x420028b0: __esp_system_init_fn_init_newlib_time at /home/thunder/build/last_sdk/esp-idf/components/esp_system/startup_funcs.c:81

D (556) cpu_start: calling init function: 0x42008be0 on core: 0
0x42008be0: __esp_system_init_fn_init_vfs_uart at /home/thunder/build/last_sdk/esp-idf/components/esp_driver_uart/src/uart_vfs.c:1080

D (562) cpu_start: calling init function: 0x420098fc on core: 0
0x420098fc: __esp_system_init_fn_init_vfs_usj_sec at /home/thunder/build/last_sdk/esp-idf/components/esp_driver_usb_serial_jtag/src/usb_serial_jtag_vfs.c:404

D (568) cpu_start: calling init function: 0x42009b1c on core: 0
0x42009b1c: __esp_system_init_fn_init_vfs_console at /home/thunder/build/last_sdk/esp-idf/components/esp_vfs_console/vfs_console.c:218

D (574) cpu_start: calling init function: 0x4200734c on core: 0
0x4200734c: __esp_system_init_fn_init_newlib_stdio at /home/thunder/build/last_sdk/esp-idf/components/newlib/newlib_init.c:207

D (580) cpu_start: calling init function: 0x42007774 on core: 0
0x42007774: __esp_system_init_fn_init_pthread at /home/thunder/build/last_sdk/esp-idf/components/pthread/pthread.c:76

D (586) cpu_start: calling init function: 0x420028bc on core: 0
0x420028bc: __esp_system_init_fn_init_flash at /home/thunder/build/last_sdk/esp-idf/components/esp_system/startup_funcs.c:88

D (592) spi_flash: trying chip: issi
D (595) spi_flash: trying chip: gd
I (599) spi_flash: detected chip: gd
I (603) spi_flash: flash io: dio
W (607) spi_flash: Detected size(8192k) larger than the size in the binary image header(2048k). Using the size in the binary image header.
D (620) cpu_start: calling init function: 0x42002460 on core: 0
0x42002460: __esp_system_init_fn_init_efuse at /home/thunder/build/last_sdk/esp-idf/components/efuse/src/esp_efuse_startup.c:137

D (626) cpu_start: calling init function: 0x42068b7c
0x42068b7c: _GLOBAL__sub_I__ZN9__gnu_cxx9__freeresEv at /builds/idf/crosstool-NG/.build/xtensa-esp-elf/src/gcc/libstdc++-v3/libsupc++/eh_alloc.cc:462

D (631) C++ init: Setting C++ exception emergency pool to 0.
D (637) cpu_start: calling init function: 0x4206864c
0x4206864c: _GLOBAL__sub_I__ZN17__eh_globals_init7_S_initE at /builds/idf/crosstool-NG/.build/xtensa-esp-elf/src/gcc/libstdc++-v3/libsupc++/eh_globals.cc:162

D (642) cpu_start: calling init function: 0x42028928
0x42028928: s_set_default_wifi_log_level at /home/thunder/build/last_sdk/esp-idf/components/esp_wifi/src/wifi_init.c:89

D (647) cpu_start: calling init function: 0x4037bcd0
0x4037bcd0: enable_timer_group0_for_calibration at /home/thunder/build/last_sdk/esp-idf/components/esp_hw_support/port/esp32s3/rtc_time.c:199

D (652) cpu_start: calling init function: 0x42003c38
0x42003c38: esp_ipc_init at /home/thunder/build/last_sdk/esp-idf/components/esp_system/esp_ipc.c:113

D (657) cpu_start: calling init function: 0x42002e4c
0x42002e4c: esp_reset_reason_init at /home/thunder/build/last_sdk/esp-idf/components/esp_system/port/soc/esp32s3/reset_reason.c:63

D (662) cpu_start: calling init function: 0x42052c34 on core: 0
0x42052c34: __esp_system_init_fn_esp_timer_init_os at /home/thunder/build/last_sdk/esp-idf/components/esp_timer/src/esp_timer.c:587

D (668) intr_alloc: Connected src 59 to int 2 (cpu 0)
D (673) cpu_start: calling init function: 0x420052a4 on core: 0
0x420052a4: __esp_system_init_fn_esp_sleep_startup_init at /home/thunder/build/last_sdk/esp-idf/components/esp_hw_support/sleep_gpio.c:185

I (679) sleep: Configure to isolate all GPIO pins in sleep state
I (686) sleep: Enable automatic switching of GPIO sleep configuration
D (693) cpu_start: calling init function: 0x420028e4 on core: 0
0x420028e4: __esp_system_init_fn_init_apb_dma at /home/thunder/build/last_sdk/esp-idf/components/esp_system/startup_funcs.c:125

D (699) cpu_start: calling init function: 0x4200950c on core: 0
0x4200950c: __esp_system_init_fn_usb_serial_jtag_conn_status_init at /home/thunder/build/last_sdk/esp-idf/components/esp_driver_usb_serial_jtag/src/usb_serial_jtag_connection_monitor.c:75

D (705) cpu_start: calling init function: 0x420028f0 on core: 0
0x420028f0: __esp_system_init_fn_init_disable_rtc_wdt at /home/thunder/build/last_sdk/esp-idf/components/esp_system/startup_funcs.c:143

D (711) intr_alloc: Connected src 79 to int 3 (cpu 0)
D (716) app_start: Starting scheduler on CPU0
D (720) intr_alloc: Connected src 57 to int 5 (cpu 0)
D (720) intr_alloc: Connected src 80 to int 0 (cpu 1)
D (730) app_start: Starting scheduler on CPU1
D (730) intr_alloc: Connected src 58 to int 1 (cpu 1)
I (720) main_task: Started on CPU0
D (740) heap_init: New heap initialised at 0x3fce9710
D (740) intr_alloc: Connected src 52 to int 8 (cpu 0)
I (750) main_task: Calling app_main()
D (770) esp_netif_lwip: LwIP stack has been initialized
D (770) esp_netif_lwip: esp-netif has been successfully initialized
D (780) event: running task for loop 0x3fca7cf8
D (780) event: created task for loop 0x3fca7cf8
D (780) event: created event loop 0x3fca7cf8
I (790) example_connect: Start example_connect.
I (790) pp: pp rom version: e7ae62f
I (800) net80211: net80211 rom version: e7ae62f
D (800) nvs: nvs_open_from_partition misc 1
I (820) wifi:wifi driver task: 3fcab29c, prio:23, stack:6656, core=0
D (820) efuse: In EFUSE_BLK1__DATA1_REG is used 8 bits starting with 8 bit
D (820) efuse: In EFUSE_BLK1__DATA1_REG is used 8 bits starting with 0 bit
D (830) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 24 bit
D (830) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 16 bit
D (840) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 8 bit
D (850) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 0 bit
D (860) nvs: nvs_open_from_partition nvs.net80211 1
D (860) nvs: nvs_get opmode 1
D (860) nvs: nvs_get_str_or_blob sta.ssid
D (870) nvs: nvs_get sta.authmode 1
D (870) nvs: nvs_get_str_or_blob sta.pswd
D (880) nvs: nvs_get_str_or_blob sta.pmk
D (880) nvs: nvs_get sta.chan 1
D (880) nvs: nvs_get auto.conn 1
D (890) nvs: nvs_get bssid.set 1
D (890) nvs: nvs_get_str_or_blob sta.bssid
D (890) nvs: nvs_get sta.lis_intval 2
D (900) nvs: nvs_get sta.phym 1
D (900) nvs: nvs_get sta.phybw 1
D (900) nvs: nvs_get_str_or_blob sta.apsw
D (910) nvs: nvs_get_str_or_blob sta.apinfo
D (910) nvs: nvs_get sta.scan_method 1
D (920) nvs: nvs_get sta.sort_method 1
D (920) nvs: nvs_get sta.minrssi 1
D (920) nvs: nvs_get sta.minauth 1
D (930) nvs: nvs_get sta.pmf_e 1
D (930) nvs: nvs_get sta.pmf_r 1
D (930) nvs: nvs_get sta.btm_e 1
D (940) nvs: nvs_get sta.rrm_e 1
D (940) nvs: nvs_get sta.mbo_e 1
D (940) nvs: nvs_get_str_or_blob ap.ssid
D (950) nvs: nvs_get_str_or_blob ap.passwd
D (950) nvs: nvs_get_str_or_blob ap.pmk
D (950) nvs: nvs_get ap.chan 1
D (960) nvs: nvs_get ap.authmode 1
D (960) nvs: nvs_get ap.hidden 1
D (960) nvs: nvs_get ap.max.conn 1
D (970) nvs: nvs_get bcn.interval 2
D (970) nvs: nvs_get ap.phym 1
D (970) nvs: nvs_get ap.phybw 1
D (980) nvs: nvs_get ap.sndchan 1
D (980) nvs: nvs_get ap.pmf_e 1
D (980) nvs: nvs_get ap.pmf_r 1
D (990) nvs: nvs_get ap.p_cipher 1
D (990) nvs: nvs_get lorate 1
D (990) nvs: nvs_get_str_or_blob country
D (1000) nvs: nvs_get ap.ftm_r 1
D (1000) nvs: nvs_get sta.ft 1
D (1000) nvs: nvs_get sta.owe 1
D (1010) nvs: nvs_get sta.trans_d 1
D (1010) nvs: nvs_get sta.sae_h2e 1
D (1010) nvs: nvs_get sta.sae_pk_mode 1
D (1020) nvs: nvs_get sta.bss_retry 1
D (1020) nvs: nvs_get_str_or_blob sta.owe_data
D (1030) nvs: nvs_get sta.he_dcm 1
D (1030) nvs: nvs_get sta.he_dcm_c_tx 1
D (1030) nvs: nvs_get sta.he_dcm_c_rx 1
D (1040) nvs: nvs_get sta.he_mcs9_d 1
D (1040) nvs: nvs_get sta.he_su_b_d 1
D (1050) nvs: nvs_get sta.he_su_b_f_d 1
D (1050) nvs: nvs_get sta.he_mu_b_f_d 1
D (1050) nvs: nvs_get sta.he_cqi_f_d 1
D (1060) nvs: nvs_get_str_or_blob sta.sae_h2e_id
D (1060) nvs: nvs_get ap.sae_h2e 1
D (1070) nvs: nvs_get_str_or_blob ap.pmk_info
D (1070) nvs: nvs_get nan.phym 1
D (1070) nvs: nvs_set ap.sndchan 1 1
I (1080) wifi:wifi firmware version: a209922
I (1080) wifi:wifi certification version: v7.0
I (1090) wifi:config NVS flash: enabled
I (1090) wifi:config nano formating: disabled
I (1090) wifi:Init data frame dynamic rx buffer num: 32
I (1100) wifi:Init static rx mgmt buffer num: 5
I (1100) wifi:Init management short buffer num: 32
I (1110) wifi:Init dynamic tx buffer num: 32
I (1110) wifi:Init static tx FG buffer num: 2
I (1110) wifi:Init static rx buffer size: 1600
I (1120) wifi:Init static rx buffer num: 10
I (1120) wifi:Init dynamic rx buffer num: 32
I (1130) wifi_init: rx ba win: 6
I (1130) wifi_init: accept mbox: 6
I (1130) wifi_init: tcpip mbox: 32
I (1140) wifi_init: udp mbox: 6
I (1140) wifi_init: tcp mbox: 6
I (1150) wifi_init: tcp tx win: 5760
I (1150) wifi_init: tcp rx win: 5760
I (1150) wifi_init: tcp mss: 1440
I (1160) wifi_init: WiFi IRAM OP enabled
I (1160) wifi_init: WiFi RX IRAM OP enabled
D (1170) esp_netif_lwip: check: remote, if=0x3fca4ca0 fn=0x42026544
0x42026544: esp_netif_new_api at /home/thunder/build/last_sdk/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:689

D (1170) esp_netif_objects: esp_netif_add_to_list_unsafe netif added successfully (total netifs: 1)
D (1180) esp_netif_lwip: call api in lwip: ret=0x0, give sem
I (1190) phy_init: phy_version 640,cd64a1a,Jan 24 2024,17:28:12
D (1200) phy_init: loading PHY init data from application binary
D (1200) nvs: nvs_open_from_partition phy 0
D (1210) nvs: nvs_get cal_version 4
D (1210) nvs: nvs_get_str_or_blob cal_mac
D (1210) efuse: In EFUSE_BLK1__DATA1_REG is used 8 bits starting with 8 bit
D (1220) efuse: In EFUSE_BLK1__DATA1_REG is used 8 bits starting with 0 bit
D (1230) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 24 bit
D (1230) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 16 bit
D (1240) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 8 bit
D (1250) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 0 bit
D (1260) nvs: nvs_get_str_or_blob cal_data
D (1260) nvs: nvs_close 3
D (1260) efuse: In EFUSE_BLK1__DATA1_REG is used 8 bits starting with 8 bit
D (1270) efuse: In EFUSE_BLK1__DATA1_REG is used 8 bits starting with 0 bit
D (1280) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 24 bit
D (1280) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 16 bit
D (1290) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 8 bit
D (1300) efuse: In EFUSE_BLK1__DATA0_REG is used 8 bits starting with 0 bit
D (1320) temperature_sensor: range changed, change to index 2
D (1330) wifi:filter: set rx policy=0
I (1330) wifi:mode : sta (dc:54:75:d8:6c:28)
I (1340) wifi:enable tsf
D (1340) wifi:filter: set rx policy=1
D (1340) wifi:connect status 0 -> 0
D (1340) event: no handlers have been registered for event WIFI_EVENT:40 posted to loop 0x3fca7cf8
D (1350) event: running post WIFI_EVENT:2 with handler 0x42028b94 and context 0x3fcb1768 on loop 0x3fca7cf8
0x42028b94: wifi_default_action_sta_start at /home/thunder/build/last_sdk/esp-idf/components/esp_wifi/src/wifi_default.c:72

D (1360) wifi_init_default: wifi_start esp-netif:0x3fcb1574 event-id2
D (1360) wifi_init_default: WIFI mac address: dc 54 75 d8 6c 28
D (1370) esp_netif_lwip: check: remote, if=0x3fcb1574 fn=0x42025f44
0x42025f44: esp_netif_set_mac_api at /home/thunder/build/last_sdk/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:992

D (1380) esp_netif_lwip: call api in lwip: ret=0x0, give sem
D (1380) esp_netif_handlers: esp_netif action has started with netif0x3fcb1574 from event_id=2
D (1390) esp_netif_lwip: check: remote, if=0x3fcb1574 fn=0x420267fc
0x420267fc: esp_netif_start_api at /home/thunder/build/last_sdk/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:1067

D (1400) esp_netif_lwip: esp_netif_start_api 0x3fcb1574
D (1400) esp_netif_lwip: esp_netif_get_hostname esp_netif:0x3fcb1574
D (1410) esp_netif_lwip: check: local, if=0x3fcb1574 fn=0x42026f6c
0x42026f6c: esp_netif_update_default_netif_lwip at /home/thunder/build/last_sdk/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:316

D (1420) esp_netif_lwip: esp_netif_update_default_netif_lwip 0x3fcb1574
D (1420) esp_netif_lwip: call api in lwip: ret=0x0, give sem
I (1430) example_connect: Connecting to XXXXX...
D (1430) wifi:clear blacklist
D (1440) wifi:Start wifi connect
D (1440) wifi:connect status 0 -> 0
D (1440) wifi:connect chan=0
D (1450) wifi:first chan=8
D (1450) wifi:connect status 0 -> 1
D (1450) wifi:filter: set rx policy=3
D (1450) wifi:clear scan ap list
D (1460) wifi:start scan: type=0x50f, priority=2, cb=0x4204616c, arg=0x0, ss_state=0x1, time=1463065, index=0
0x4204616c: cnx_start_handoff_cb at ??:?

D (1470) wifi:perform scan: ss_state=0x9, chan<8,0>, dur<0,120>
I (1470) example_connect: Waiting for IP(s)
D (1480) wifi:rsn valid: gcipher=1 ucipher=3 akm=5 mac=00:26:5a:cc:71:13
D (1480) wifi:profile match: ss_state=0x7
D (1520) wifi:rsn valid: gcipher=1 ucipher=3 akm=5 mac=00:26:5a:cc:71:13
D (1520) wifi:set max rate: from <rate=130, phy=3, sig=0> to <rate=144, phy=3 sig=0>
D (1530) wifi:sig_b=0, sig_g=0, sig_n=0, max_b=22, max_g=108, max_n=144
D (1530) wifi:profile match: ss_state=0x7
D (1590) wifi:scan end: arg=0x0, status=0, ss_state=0x7
D (1590) wifi:perform scan: ss_state=0xd, chan<1,0>, dur<0,120>
D (1710) wifi:scan end: arg=0x0, status=0, ss_state=0x7
D (1720) wifi:perform scan: ss_state=0xd, chan<2,0>, dur<0,120>
D (1840) wifi:scan end: arg=0x0, status=0, ss_state=0x7
D (1840) wifi:perform scan: ss_state=0xd, chan<3,0>, dur<0,120>
D (1960) wifi:scan end: arg=0x0, status=0, ss_state=0x7
D (1960) wifi:perform scan: ss_state=0xd, chan<4,0>, dur<0,120>
D (2080) wifi:scan end: arg=0x0, status=0, ss_state=0x7
D (2080) wifi:perform scan: ss_state=0xd, chan<5,0>, dur<0,120>
D (2220) wifi:scan end: arg=0x0, status=0, ss_state=0x7
D (2220) wifi:perform scan: ss_state=0xd, chan<6,0>, dur<0,120>
D (2340) wifi:scan end: arg=0x0, status=0, ss_state=0x7
D (2340) wifi:perform scan: ss_state=0xd, chan<7,0>, dur<0,120>
D (2470) wifi:scan end: arg=0x0, status=0, ss_state=0x7
D (2470) wifi:perform scan: ss_state=0xd, chan<9,0>, dur<0,120>
D (2590) wifi:scan end: arg=0x0, status=0, ss_state=0x7
D (2590) wifi:perform scan: ss_state=0xd, chan<10,0>, dur<0,120>
D (2710) wifi:scan end: arg=0x0, status=0, ss_state=0x7
D (2710) wifi:perform scan: ss_state=0xd, chan<11,0>, dur<0,120>
D (2830) wifi:scan end: arg=0x0, status=0, ss_state=0x7
D (2830) wifi:perform scan: ss_state=0xd, chan<12,0>, dur<360,360>
D (3190) wifi:scan end: arg=0x0, status=0, ss_state=0x7
D (3190) wifi:perform scan: ss_state=0xd, chan<13,0>, dur<360,360>
D (3550) wifi:scan end: arg=0x0, status=0, ss_state=0x7
D (3550) wifi:perform scan: ss_state=0xd, chan<14,0>, dur<360,360>
D (3920) wifi:scan end: arg=0x0, status=0, ss_state=0x7
D (3920) wifi:filter: set rx policy=4
D (3920) wifi:first chan=1
D (3920) wifi:handoff_cb: status=0
D (3920) wifi:ap found, mac=00:26:5a:cc:71:13
D (3920) gdma: new group (0) at 0x3fcb2204
D (3930) gdma: new pair (0,0) at 0x3fcb228c
D (3930) gdma: new tx channel (0,0) at 0x3fcb21ac
D (3940) gdma: new rx channel (0,0) at 0x3fcb22ac
D (3940) gdma: tx channel (0,0), (1:16) bytes aligned, burst enabled
D (3950) gdma: rx channel (0,0), (1:16) bytes aligned, burst disabled
D (4430) wifi:going for connection with bssid=00:26:5a:cc:71:13
D (4430) wifi:new_bss=0x3fc9f750, cur_bss=0x0, new_chan=<8,0>, cur_chan=1
D (4430) wifi:filter: set rx policy=5
I (4430) wifi:new:<8,0>, old:<1,0>, ap:<255,255>, sta:<8,0>, prof:1
D (4440) wifi:connect_op: status=0, auth=5, cipher=3
D (4440) wifi:auth mode is not none
D (4440) wifi:connect_bss: auth=1, reconnect=0
I (4450) wifi:state: init -> auth (b0)
D (4450) wifi:start 1s AUTH timer
D (4460) wifi:clear scan ap list
D (4460) event: no handlers have been registered for event WIFI_EVENT:40 posted to loop 0x3fca7cf8
D (4460) wifi:recv auth: seq=2, status=0
I (4470) wifi:state: auth -> assoc (0)
D (4480) wifi:restart connect 1s timer for assoc
D (4480) wifi:recv assoc: type=0x10
D (4480) wifi:filter: set rx policy=6
I (4490) wifi:state: assoc -> run (10)
D (4490) wifi:start 10s connect timer for 4 way handshake
D (4500) intr_alloc: Connected src 77 to int 9 (cpu 0)
I (4500) wifi:connected with XXXXX, aid = 1, channel 8, BW20, bssid = 00:26:5a:cc:71:13
I (4510) wifi:security: WPA2-PSK, phy: bgn, rssi: -44
D (4510) wifi:remove all except 00:26:5a:cc:71:13 from rc list
D (4520) wifi:clear blacklist
D (4520) wifi:filter: set rx policy=7
I (4520) wifi:pm start, type: 1

I (4530) wifi:dp: 1, bi: 102400, li: 3, scale listen interval from 307200 us to 307200 us
I (4530) wifi:set rx beacon pti, rx_bcn_pti: 0, bcn_timeout: 25000, mt_pti: 0, mt_time: 10000
D (4540) wifi:Send sta connected event
D (4550) wifi:connect status 1 -> 5
D (4550) wifi:obss scan is disabled
D (4550) wifi:start obss scan: obss scan is stopped
D (4560) event: running post WIFI_EVENT:4 with handler 0x42028bc4 and context 0x3fcb17c8 on loop 0x3fca7cf8
0x42028bc4: wifi_default_action_sta_connected at /home/thunder/build/last_sdk/esp-idf/components/esp_wifi/src/wifi_default.c:86

D (4570) esp_netif_handlers: esp_netif action connected with netif0x3fcb1574 from event_id=4
D (4580) esp_netif_lwip: check: remote, if=0x3fcb1574 fn=0x42026bb0
0x42026bb0: esp_netif_up_api at /home/thunder/build/last_sdk/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:1646

D (4580) esp_netif_lwip: esp_netif_up_api esp_netif:0x3fcb1574
D (4590) esp_netif_lwip: check: local, if=0x3fcb1574 fn=0x42026f6c
0x42026f6c: esp_netif_update_default_netif_lwip at /home/thunder/build/last_sdk/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:316

D (4590) esp_netif_lwip: esp_netif_update_default_netif_lwip 0x3fcb1574
I (4600) wifi:D (4600) esp_netif_lwip: call api in lwip: ret=0x0, give sem
AP's beacon interval = 102400 us, DTIM period = 1
D (4610) esp_netif_lwip: check: remote, if=0x3fcb1574 fn=0x42026a70
0x42026a70: esp_netif_dhcpc_start_api at /home/thunder/build/last_sdk/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:1438

D (4620) esp_netif_lwip: esp_netif_dhcpc_start_api esp_netif:0x3fcb1574
D (4630) esp_netif_lwip: esp_netif_start_ip_lost_timer esp_netif:0x3fcb1574
D (4630) esp_netif_lwip: if0x3fcb1574 start ip lost tmr: interval=120
D (4640) esp_netif_lwip: starting dhcp client
D (4640) wifi:D (4640) esp_netif_lwip: call api in lwip: ret=0x0, give sem
eb is dhcp or dns sport = 68, dport = 67
D (4650) event: running post WIFI_EVENT:4 with handler 0x4207da8c and context 0x3fcb20d0 on loop 0x3fca7cf8
0x4207da8c: example_handler_on_wifi_connect at /home/thunder/build/last_sdk/esp-idf/examples/common_components/protocol_examples_common/wifi_connect.c:90

D (4660) wifi:eb is dhcp or dns sport = 68, dport = 67
D (5640) esp_netif_lwip: esp_netif_internal_dhcpc_cb lwip-netif:0x3fcb15e8
D (5640) esp_netif_lwip: if0x3fcb1574 ip changed=1
D (5640) event: running post IP_EVENT:0 with handler 0x420289f0 and context 0x3fcb189c on loop 0x3fca7cf8
0x420289f0: wifi_default_action_sta_got_ip at /home/thunder/build/last_sdk/esp-idf/components/esp_wifi/src/wifi_default.c:128

D (5650) wifi_init_default: Got IP wifi default handler entered
D (5650) esp_netif_handlers: esp_netif action got_ip with netif0x3fcb1574 from event_id=0
I (5660) esp_netif_handlers: example_netif_sta ip: 192.168.2.65, mask: 255.255.255.0, gw: 192.168.2.1
D (5670) event: running post IP_EVENT:0 with handler 0x4200ab0c and context 0x3fcb20b0 on loop 0x3fca7cf8
0x4200ab0c: example_handler_on_sta_got_ip at /home/thunder/build/last_sdk/esp-idf/examples/common_components/protocol_examples_common/wifi_connect.c:98

I (5680) example_connect: Got IPv4 event: Interface "example_netif_sta" address: 192.168.2.65
D (5690) esp_netif_lwip: check: remote, if=0x4200aa3c fn=0x4207e67c
0x4200aa3c: print_all_ips_tcpip at /home/thunder/build/last_sdk/esp-idf/examples/common_components/protocol_examples_common/connect.c:57
0x4207e67c: tcpip_exec_api at /home/thunder/build/last_sdk/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:679

I (5700) example_common: Connected to example_netif_sta
D (5700) esp_netif_lwip: esp_netif_get_ip_info esp_netif:0x3fcb1574
I (5710) example_common: - IPv4 address: 192.168.2.65,
D (5710) esp_netif_lwip: call api in lwip: ret=0x0, give sem
I (5720) main_task: Returned from app_main()
D (5720) wifi:eb is dhcp or dns sport = 26679, dport = 53
I (5730) example: DNS lookup succeeded. IP=3.66.72.53
I (5740) example: ... allocated socket
I (5930) example: ... connected
I (5930) example: ... socket send success
I (5930) example: ... set socket receiving timeout success
HTTP/1.1 301 Moved Permanently
content-length: 0
location: https://dragons.icu:80/
connection: close

I (6350) example: ... done reading from socket. Last read return=0 errno=128.
I (6350) example: 10...
I (7350) example: 9...
I (8350) example: 8...
I (9350) example: 7...
I (10350) example: 6...
I (11350) example: 5...
I (12350) example: 4...
I (13350) example: 3...
I (14350) example: 2...
I (15350) example: 1...
I (16350) example: 0...
I (17350) example: Starting again!
I (17350) example: DNS lookup succeeded. IP=3.66.72.53
I (17350) example: ... allocated socket
I (17500) example: ... connected
I (17500) example: ... socket send success
I (17500) example: ... set socket receiving timeout success
HTTP/1.1 301 Moved Permanently
content-length: 0
location: https://dragons.icu:80/
connection: close

I (17930) example: ... done reading from socket. Last read return=0 errno=128.
I (17930) example: 10...
I (18930) example: 9...
I (19930) example: 8...
I (20930) example: 7...
I (21930) example: 6...
I (22930) example: 5...
I (23930) example: 4...
I (24930) example: 3...
I (25930) example: 2...
I (26930) example: 1...
I (27930) example: 0...
I (28930) example: Starting again!
I (28930) example: DNS lookup succeeded. IP=3.66.72.53
I (28930) example: ... allocated socket
I (29070) example: ... connected
I (29070) example: ... socket send success
I (29070) example: ... set socket receiving timeout success
HTTP/1.1 301 Moved Permanently
content-length: 0
location: https://dragons.icu:80/
connection: close

...

I (377460) example: ... done reading from socket. Last read return=0 errno=128.
I (377470) example: 10...
I (378470) example: 9...
I (379470) example: 8...
I (380470) example: 7...
I (381470) example: 6...
I (382470) example: 5...
I (383470) example: 4...
I (384470) example: 3...
I (385470) example: 2...
I (386470) example: 1...
I (387470) example: 0...
I (388470) example: Starting again!
I (388470) example: DNS lookup succeeded. IP=3.66.72.53
I (388470) example: ... allocated socket
I (388610) example: ... connected
I (388610) example: ... socket send success
I (388610) example: ... set socket receiving timeout success
HTTP/1.1 301 Moved Permanently
content-length: 0
location: https://dragons.icu:80/
connection: close

I (389350) example: ... done reading from socket. Last read return=0 errno=128.
I (389350) example: 10...
I (390350) example: 9...
I (391350) example: 8...
I (392350) example: 7...
I (393350) example: 6...
I (394350) example: 5...
I (395350) example: 4...
I (395780) wifi:<ba-add>idx:0 (ifx:0, 00:26:5a:cc:71:13), tid:0, ssn:378, winSize:64
I (396350) example: 3...
I (397350) example: 2...
I (398350) example: 1...
I (399350) example: 0...
I (400350) example: Starting again!
I (400350) example: DNS lookup succeeded. IP=3.66.72.53
I (400350) example: ... allocated socket
I (400490) example: ... connected
I (400490) example: ... socket send success
I (400490) example: ... set socket receiving timeout success
HTTP/1.1 301 Moved Permanently
content-length: 0
location: https://dragons.icu:80/
connection: close

I (400800) example: ... done reading from socket. Last read return=0 errno=128.
I (400800) example: 10...
I (401800) example: 9...
I (402800) example: 8...
I (403800) example: 7...
I (404800) example: 6...
I (405800) example: 5...
I (406800) example: 4...
I (407800) example: 3...
I (408800) example: 2...
I (409800) example: 1...
I (410800) example: 0...
I (411800) example: Starting again!
I (411800) example: DNS lookup succeeded. IP=3.66.72.53
I (411800) example: ... allocated socket
E (430300) example: ... socket connect failed errno=113
I (434300) example: DNS lookup succeeded. IP=3.66.72.53
I (434300) example: ... allocated socket
I (434400) example: ... connected
I (434400) example: ... socket send success
I (434400) example: ... set socket receiving timeout success
HTTP/1.1 301 Moved Permanently
content-length: 0
location: https://dragons.icu:80/
connection: close

I (434720) example: ... done reading from socket. Last read return=0 errno=128.
I (434720) example: 10...
I (435720) example: 9...
I (436720) example: 8...
I (437720) example: 7...
I (438720) example: 6...
I (439720) example: 5...
I (440720) example: 4...
I (441720) example: 3...
I (442720) example: 2...
I (443720) example: 1...
I (444720) example: 0...
I (445720) example: Starting again!
I (445720) example: DNS lookup succeeded. IP=3.66.72.53
I (445720) example: ... allocated socket
E (463970) example: ... socket connect failed errno=113
I (467970) example: DNS lookup succeeded. IP=3.66.72.53
I (467970) example: ... allocated socket
E (486470) example: ... socket connect failed errno=113
D (490470) wifi:eb is dhcp or dns sport = 65348, dport = 53
D (491470) wifi:eb is dhcp or dns sport = 65348, dport = 53
D (492470) wifi:eb is dhcp or dns sport = 65348, dport = 53
D (494470) wifi:eb is dhcp or dns sport = 65348, dport = 53
D (497470) wifi:eb is dhcp or dns sport = 65348, dport = 53
D (498470) wifi:eb is dhcp or dns sport = 65348, dport = 53
D (499470) wifi:eb is dhcp or dns sport = 65348, dport = 53
D (501470) wifi:eb is dhcp or dns sport = 65348, dport = 53
E (504470) example: DNS lookup failed err=202 res=0x0
D (505470) wifi:eb is dhcp or dns sport = 24858, dport = 53
D (506470) wifi:eb is dhcp or dns sport = 24858, dport = 53
D (507470) wifi:eb is dhcp or dns sport = 24858, dport = 53
D (509470) wifi:eb is dhcp or dns sport = 24858, dport = 53
D (512470) wifi:eb is dhcp or dns sport = 24858, dport = 53
D (513470) wifi:eb is dhcp or dns sport = 24858, dport = 53
D (514470) wifi:eb is dhcp or dns sport = 24858, dport = 53
D (516470) wifi:eb is dhcp or dns sport = 24858, dport = 53
E (519470) example: DNS lookup failed err=202 res=0x0
D (520470) wifi:eb is dhcp or dns sport = 15530, dport = 53
D (521470) wifi:eb is dhcp or dns sport = 15530, dport = 53
D (522470) wifi:eb is dhcp or dns sport = 15530, dport = 53
D (524470) wifi:eb is dhcp or dns sport = 15530, dport = 53
D (527470) wifi:eb is dhcp or dns sport = 15530, dport = 53
D (528470) wifi:eb is dhcp or dns sport = 15530, dport = 53
D (529470) wifi:eb is dhcp or dns sport = 15530, dport = 53
D (531470) wifi:eb is dhcp or dns sport = 15530, dport = 53
E (534470) example: DNS lookup failed err=202 res=0x0
D (535470) wifi:eb is dhcp or dns sport = 58749, dport = 53
D (536470) wifi:eb is dhcp or dns sport = 58749, dport = 53
D (537470) wifi:eb is dhcp or dns sport = 58749, dport = 53
D (539470) wifi:eb is dhcp or dns sport = 58749, dport = 53
D (542470) wifi:eb is dhcp or dns sport = 58749, dport = 53
D (543470) wifi:eb is dhcp or dns sport = 58749, dport = 53
D (544470) wifi:eb is dhcp or dns sport = 58749, dport = 53
D (546470) wifi:eb is dhcp or dns sport = 58749, dport = 53
E (549470) example: DNS lookup failed err=202 res=0x0
D (550470) wifi:eb is dhcp or dns sport = 47881, dport = 53
D (551470) wifi:eb is dhcp or dns sport = 47881, dport = 53
D (552470) wifi:eb is dhcp or dns sport = 47881, dport = 53
D (554470) wifi:eb is dhcp or dns sport = 47881, dport = 53
D (557470) wifi:eb is dhcp or dns sport = 47881, dport = 53
D (558470) wifi:eb is dhcp or dns sport = 47881, dport = 53
D (559480) wifi:eb is dhcp or dns sport = 47881, dport = 53
D (561480) wifi:eb is dhcp or dns sport = 47881, dport = 53
E (564480) example: DNS lookup failed err=202 res=0x0
D (565480) wifi:eb is dhcp or dns sport = 12002, dport = 53
D (566480) wifi:eb is dhcp or dns sport = 12002, dport = 53
D (567480) wifi:eb is dhcp or dns sport = 12002, dport = 53
D (569480) wifi:eb is dhcp or dns sport = 12002, dport = 53
D (572480) wifi:eb is dhcp or dns sport = 12002, dport = 53
D (573480) wifi:eb is dhcp or dns sport = 12002, dport = 53
D (574480) wifi:eb is dhcp or dns sport = 12002, dport = 53
D (576480) wifi:eb is dhcp or dns sport = 12002, dport = 53
E (579480) example: DNS lookup failed err=202 res=0x0
D (580480) wifi:eb is dhcp or dns sport = 20549, dport = 53
D (581480) wifi:eb is dhcp or dns sport = 20549, dport = 53
D (582480) wifi:eb is dhcp or dns sport = 20549, dport = 53
D (584480) wifi:eb is dhcp or dns sport = 20549, dport = 53
D (587480) wifi:eb is dhcp or dns sport = 20549, dport = 53
D (588480) wifi:eb is dhcp or dns sport = 20549, dport = 53
D (589480) wifi:eb is dhcp or dns sport = 20549, dport = 53
D (591480) wifi:eb is dhcp or dns sport = 20549, dport = 53
E (594480) example: DNS lookup failed err=202 res=0x0
D (595480) wifi:eb is dhcp or dns sport = 61044, dport = 53
D (596480) wifi:eb is dhcp or dns sport = 61044, dport = 53
D (597480) wifi:eb is dhcp or dns sport = 61044, dport = 53
D (599480) wifi:eb is dhcp or dns sport = 61044, dport = 53
D (602480) wifi:eb is dhcp or dns sport = 61044, dport = 53
D (603480) wifi:eb is dhcp or dns sport = 61044, dport = 53
D (604480) wifi:eb is dhcp or dns sport = 61044, dport = 53
D (606480) wifi:eb is dhcp or dns sport = 61044, dport = 53
E (609480) example: DNS lookup failed err=202 res=0x0
D (610480) wifi:eb is dhcp or dns sport = 40915, dport = 53
D (611480) wifi:eb is dhcp or dns sport = 40915, dport = 53
D (612480) wifi:eb is dhcp or dns sport = 40915, dport = 53
D (614480) wifi:eb is dhcp or dns sport = 40915, dport = 53
D (617480) wifi:eb is dhcp or dns sport = 40915, dport = 53
D (618480) wifi:eb is dhcp or dns sport = 40915, dport = 53
D (619480) wifi:eb is dhcp or dns sport = 40915, dport = 53
D (621480) wifi:eb is dhcp or dns sport = 40915, dport = 53
E (624480) example: DNS lookup failed err=202 res=0x0
D (625480) wifi:eb is dhcp or dns sport = 23061, dport = 53
D (626480) wifi:eb is dhcp or dns sport = 23061, dport = 53
D (627480) wifi:eb is dhcp or dns sport = 23061, dport = 53
D (629480) wifi:eb is dhcp or dns sport = 23061, dport = 53
D (632480) wifi:eb is dhcp or dns sport = 23061, dport = 53
D (633480) wifi:eb is dhcp or dns sport = 23061, dport = 53
D (634480) wifi:eb is dhcp or dns sport = 23061, dport = 53
D (636480) wifi:eb is dhcp or dns sport = 23061, dport = 53
E (639480) example: DNS lookup failed err=202 res=0x0
D (640480) wifi:eb is dhcp or dns sport = 16423, dport = 53
D (641480) wifi:eb is dhcp or dns sport = 16423, dport = 53
D (642480) wifi:eb is dhcp or dns sport = 16423, dport = 53
D (644480) wifi:eb is dhcp or dns sport = 16423, dport = 53
D (647480) wifi:eb is dhcp or dns sport = 16423, dport = 53
D (648480) wifi:eb is dhcp or dns sport = 16423, dport = 53
D (649480) wifi:eb is dhcp or dns sport = 16423, dport = 53
D (651480) wifi:eb is dhcp or dns sport = 16423, dport = 53
E (654480) example: DNS lookup failed err=202 res=0x0

...

E (1719480) example: DNS lookup failed err=202 res=0x0
D (1720480) wifi:eb is dhcp or dns sport = 41306, dport = 53
D (1721480) wifi:eb is dhcp or dns sport = 41306, dport = 53
D (1722480) wifi:eb is dhcp or dns sport = 41306, dport = 53
D (1724480) wifi:eb is dhcp or dns sport = 41306, dport = 53
D (1727480) wifi:eb is dhcp or dns sport = 41306, dport = 53
D (1728480) wifi:eb is dhcp or dns sport = 41306, dport = 53
D (1729480) wifi:eb is dhcp or dns sport = 41306, dport = 53
D (1731480) wifi:eb is dhcp or dns sport = 41306, dport = 53
E (1734480) example: DNS lookup failed err=202 res=0x0
D (1734720) wifi:recv deauth, reason=0x9
I (1734720) wifi:state: run -> init (9c0)
D (1734720) wifi:stop beacon and connect timers
D (1734720) wifi:recv deauth/disassoc
D (1734730) wifi:connect status 5 -> 4
D (1734730) wifi:sta leave
I (1734740) wifi:pm stop, total sleep time: 871170556 us / 1730209683 us

D (1734740) wifi:stop CSA timer
I (1734740) wifi:<ba-del>idx:0, tid:0
D (1734740) wifi:remove 00:26:5a:cc:71:13 from rc list
I (1734750) wifi:new:<8,0>, old:<8,0>, ap:<255,255>, sta:<8,0>, prof:1
D (1734750) wifi:filter: set rx policy=8
D (1734760) wifi:Send disconnect event, reason=9, AP number=0
D (1734760) event: running post WIFI_EVENT:5 with handler 0x42028bac and context 0x3fcb17f8 on loop 0x3fca7cf8
0x42028bac: wifi_default_action_sta_disconnected at /home/thunder/build/last_sdk/esp-idf/components/esp_wifi/src/wifi_default.c:105

D (1734770) esp_netif_handlers: esp_netif action disconnected with netif0x3fcb1574 from event_id=5
D (1734780) esp_netif_lwip: check: remote, if=0x3fcb1574 fn=0x42026c00
0x42026c00: esp_netif_down_api at /home/thunder/build/last_sdk/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:1672

D (1734790) esp_netif_lwip: esp_netif_down_api esp_netif:0x3fcb1574
D (1734790) esp_netif_lwip: esp_netif_internal_dhcpc_cb lwip-netif:0x3fcb15e8
D (1734800) esp_netif_lwip: esp_netif_start_ip_lost_timer esp_netif:0x3fcb1574
D (1734810) esp_netif_lwip: if0x3fcb1574 start ip lost tmr: interval=120
D (1734820) esp_netif_lwip: esp_netif_start_ip_lost_timer esp_netif:0x3fcb1574
D (1734820) esp_netif_lwip: if0x3fcb1574 start ip lost tmr: already started
D (1734830) esp_netif_lwip: check: local, if=0x3fcb1574 fn=0x42026f6c
0x42026f6c: esp_netif_update_default_netif_lwip at /home/thunder/build/last_sdk/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:316

D (1734840) esp_netif_lwip: esp_netif_update_default_netif_lwip 0x3fcb1574
D (1734840) esp_netif_lwip: call api in lwip: ret=0x0, give sem
D (1734850) event: running post WIFI_EVENT:5 with handler 0x4200ab9c and context 0x3fcb18e4 on loop 0x3fca7cf8
0x4200ab9c: example_handler_on_wifi_disconnect at /home/thunder/build/last_sdk/esp-idf/examples/common_components/protocol_examples_common/wifi_connect.c:65

I (1734860) example_connect: Wi-Fi disconnected, trying to reconnect...
D (1734870) wifi:Start wifi connect
D (1734870) wifi:connect status 4 -> 0
D (1734870) wifi:connect chan=0
D (1734880) wifi:first chan=8
D (1734880) wifi:connect status 0 -> 1
D (1734880) wifi:filter: set rx policy=3
D (1734890) wifi:clear scan ap list
D (1734890) wifi:start scan: type=0x50f, priority=2, cb=0x4204616c, arg=0x0, ss_state=0x1, time=1734895192, index=0
0x4204616c: cnx_start_handoff_cb at ??:?

D (1734900) wifi:perform scan: ss_state=0x9, chan<8,0>, dur<0,120>
D (1734910) wifi:rsn valid: gcipher=1 ucipher=3 akm=5 mac=00:26:5a:cc:71:13
D (1734910) wifi:profile match: ss_state=0x7
D (1734920) wifi:rsn valid: gcipher=1 ucipher=3 akm=5 mac=00:26:5a:cc:71:13
D (1734920) wifi:set max rate: from <rate=130, phy=3, sig=0> to <rate=144, phy=3 sig=0>
D (1734930) wifi:sig_b=0, sig_g=0, sig_n=0, max_b=22, max_g=108, max_n=144
D (1734940) wifi:profile match: ss_state=0x7
D (1734990) wifi:rsn valid: gcipher=1 ucipher=3 akm=5 mac=00:26:5a:cc:71:13
D (1735000) wifi:profile match: ss_state=0x7
D (1735030) wifi:scan end: arg=0x0, status=0, ss_state=0x7
D (1735030) wifi:perform scan: ss_state=0xd, chan<1,0>, dur<0,120>
D (1735150) wifi:scan end: arg=0x0, status=0, ss_state=0x7
D (1735150) wifi:perform scan: ss_state=0xd, chan<2,0>, dur<0,120>
D (1735270) wifi:scan end: arg=0x0, status=0, ss_state=0x7
D (1735270) wifi:perform scan: ss_state=0xd, chan<3,0>, dur<0,120>
D (1735390) wifi:scan end: arg=0x0, status=0, ss_state=0x7
D (1735390) wifi:perform scan: ss_state=0xd, chan<4,0>, dur<0,120>
D (1735510) wifi:scan end: arg=0x0, status=0, ss_state=0x7
D (1735510) wifi:perform scan: ss_state=0xd, chan<5,0>, dur<0,120>
D (1735630) wifi:scan end: arg=0x0, status=0, ss_state=0x7
D (1735640) wifi:perform scan: ss_state=0xd, chan<6,0>, dur<0,120>
D (1735760) wifi:scan end: arg=0x0, status=0, ss_state=0x7
D (1735760) wifi:perform scan: ss_state=0xd, chan<7,0>, dur<0,120>
D (1735880) wifi:scan end: arg=0x0, status=0, ss_state=0x7
D (1735880) wifi:perform scan: ss_state=0xd, chan<9,0>, dur<0,120>
D (1736000) wifi:scan end: arg=0x0, status=0, ss_state=0x7
D (1736000) wifi:perform scan: ss_state=0xd, chan<10,0>, dur<0,120>
D (1736120) wifi:scan end: arg=0x0, status=0, ss_state=0x7
D (1736120) wifi:perform scan: ss_state=0xd, chan<11,0>, dur<0,120>
D (1736240) wifi:scan end: arg=0x0, status=0, ss_state=0x7
D (1736240) wifi:perform scan: ss_state=0xd, chan<12,0>, dur<360,360>
D (1736600) wifi:scan end: arg=0x0, status=0, ss_state=0x7
D (1736610) wifi:perform scan: ss_state=0xd, chan<13,0>, dur<360,360>
D (1736970) wifi:scan end: arg=0x0, status=0, ss_state=0x7
D (1736970) wifi:perform scan: ss_state=0xd, chan<14,0>, dur<360,360>
D (1737330) wifi:scan end: arg=0x0, status=0, ss_state=0x7
D (1737330) wifi:filter: set rx policy=4
D (1737330) wifi:first chan=1
D (1737330) wifi:handoff_cb: status=0
D (1737350) wifi:ap found, mac=00:26:5a:cc:71:13
D (1737350) wifi:going for connection with bssid=00:26:5a:cc:71:13
D (1737350) wifi:new_bss=0x3fc9f750, cur_bss=0x0, new_chan=<8,0>, cur_chan=8
D (1737350) wifi:filter: set rx policy=5
I (1737360) wifi:new:<8,0>, old:<8,0>, ap:<255,255>, sta:<8,0>, prof:1
D (1737360) wifi:connect_op: status=0, auth=5, cipher=3
D (1737370) wifi:auth mode is not none
D (1737370) wifi:connect_bss: auth=1, reconnect=0
I (1737370) wifi:state: init -> auth (b0)
D (1737380) wifi:start 1s AUTH timer
D (1737380) wifi:clear scan ap list
D (1737390) wifi:recv auth: seq=2, status=0
I (1737390) wifi:state: auth -> assoc (0)
D (1737390) wifi:restart connect 1s timer for assoc
D (1737400) wifi:recv assoc: type=0x10
D (1737400) wifi:filter: set rx policy=6
I (1737400) wifi:state: assoc -> run (10)
D (1737410) wifi:start 10s connect timer for 4 way handshake
I (1737420) wifi:connected with XXXXX, aid = 1, channel 8, BW20, bssid = 00:26:5a:cc:71:13
I (1737420) wifi:security: WPA2-PSK, phy: bgn, rssi: -45
D (1737430) wifi:remove all except 00:26:5a:cc:71:13 from rc list
D (1737430) wifi:clear blacklist
D (1737440) wifi:filter: set rx policy=7
I (1737440) wifi:pm start, type: 1

I (1737440) wifi:set rx beacon pti, rx_bcn_pti: 0, bcn_timeout: 25000, mt_pti: 0, mt_time: 10000
D (1737450) wifi:Send sta connected event
D (1737450) wifi:connect status 1 -> 5
D (1737460) wifi:obss scan is disabled
D (1737460) wifi:start obss scan: obss scan is stopped
I (1737470) wifi:AP's beacon interval = 102400 us, DTIM period = 1
D (1737470) event: running post WIFI_EVENT:4 with handler 0x42028bc4 and context 0x3fcb17c8 on loop 0x3fca7cf8
0x42028bc4: wifi_default_action_sta_connected at /home/thunder/build/last_sdk/esp-idf/components/esp_wifi/src/wifi_default.c:86

D (1737480) esp_netif_handlers: esp_netif action connected with netif0x3fcb1574 from event_id=4
D (1737490) esp_netif_lwip: check: remote, if=0x3fcb1574 fn=0x42026bb0
0x42026bb0: esp_netif_up_api at /home/thunder/build/last_sdk/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:1646

D (1737500) esp_netif_lwip: esp_netif_up_api esp_netif:0x3fcb1574
D (1737500) esp_netif_lwip: check: local, if=0x3fcb1574 fn=0x42026f6c
0x42026f6c: esp_netif_update_default_netif_lwip at /home/thunder/build/last_sdk/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:316

D (1737510) esp_netif_lwip: esp_netif_update_default_netif_lwip 0x3fcb1574
D (1737520) esp_netif_lwip: call api in lwip: ret=0x0, give sem
D (1737520) esp_netif_lwip: check: remote, if=0x3fcb1574 fn=0x42026a70
0x42026a70: esp_netif_dhcpc_start_api at /home/thunder/build/last_sdk/esp-idf/components/esp_netif/lwip/esp_netif_lwip.c:1438

D (1737530) esp_netif_lwip: esp_netif_dhcpc_start_api esp_netif:0x3fcb1574
D (1737540) esp_netif_lwip: esp_netif_start_ip_lost_timer esp_netif:0x3fcb1574
D (1737540) esp_netif_lwip: if0x3fcb1574 start ip lost tmr: already started
D (1737550) esp_netif_lwip: starting dhcp client
D (1737560) wifi:D (1737560) esp_netif_lwip: call api in lwip: ret=0x0, give sem
eb is dhcp or dns sport = 68, dport = 67
D (1737570) event: running post WIFI_EVENT:4 with handler 0x4207da8c and context 0x3fcb20d0 on loop 0x3fca7cf8
0x4207da8c: example_handler_on_wifi_connect at /home/thunder/build/last_sdk/esp-idf/examples/common_components/protocol_examples_common/wifi_connect.c:90

D (1738060) wifi:eb is dhcp or dns sport = 68, dport = 67
D (1738680) wifi:eb is dhcp or dns sport = 68, dport = 67
D (1739560) esp_netif_lwip: esp_netif_internal_dhcpc_cb lwip-netif:0x3fcb15e8
D (1739560) esp_netif_lwip: if0x3fcb1574 ip changed=0
D (1739560) event: running post IP_EVENT:0 with handler 0x420289f0 and context 0x3fcb189c on loop 0x3fca7cf8
0x420289f0: wifi_default_action_sta_got_ip at /home/thunder/build/last_sdk/esp-idf/components/esp_wifi/src/wifi_default.c:128

D (1739570) wifi_init_default: Got IP wifi default handler entered
D (1739570) esp_netif_handlers: esp_netif action got_ip with netif0x3fcb1574 from event_id=0
I (1739580) esp_netif_handlers: example_netif_sta ip: 192.168.2.65, mask: 255.255.255.0, gw: 192.168.2.1
D (1739590) event: running post IP_EVENT:0 with handler 0x4200ab0c and context 0x3fcb20b0 on loop 0x3fca7cf8
0x4200ab0c: example_handler_on_sta_got_ip at /home/thunder/build/last_sdk/esp-idf/examples/common_components/protocol_examples_common/wifi_connect.c:98

I (1739600) example_connect: Got IPv4 event: Interface "example_netif_sta" address: 192.168.2.65
D (1742480) wifi:eb is dhcp or dns sport = 27296, dport = 53
I (1742770) example: DNS lookup succeeded. IP=3.66.72.53
I (1742770) example: ... allocated socket
I (1744110) example: ... connected
I (1744110) example: ... socket send success
I (1744110) example: ... set socket receiving timeout success
HTTP/1.1 301 Moved Permanently
content-length: 0
location: https://dragons.icu:80/
connection: close

I (1744540) example: ... done reading from socket. Last read return=0 errno=128.
I (1744550) example: 10...
I (1745550) example: 9...
I (1746550) example: 8...
I (1747550) example: 7...
I (1748550) example: 6...
I (1749550) example: 5...
I (1750550) example: 4...
I (1751550) example: 3...
I (1752550) example: 2...
I (1753550) example: 1...
I (1754550) example: 0...
I (1755550) example: Starting again!
I (1755550) example: DNS lookup succeeded. IP=3.66.72.53
I (1755550) example: ... allocated socket
I (1755680) example: ... connected
I (1755680) example: ... socket send success
I (1755680) example: ... set socket receiving timeout success
HTTP/1.1 301 Moved Permanently
content-length: 0
location: https://dragons.icu:80/
connection: close

More Information.

No response

AxelLin commented 1 month ago

Is there any progress about this issue?

I have similar issue. (using v5.2.1-537-g9cf323d4c6) Sometimes, the esp32s3 device joined an AP and got IP, but then the ntp sync fails:

I (8964) wifi:idx:0 (ifx:0, 18:a6:f7:ab:ca:66), tid:0, ssn:415, winSize:64 D (9705) wifi:eb is dhcp or dns sport = 31009, dport = 53 D (9961) wifi:eb is dhcp or dns sport = 31009, dport = 53 D (10961) wifi:eb is dhcp or dns sport = 31009, dport = 53 D (12961) wifi:eb is dhcp or dns sport = 31009, dport = 53 D (15961) wifi:eb is dhcp or dns sport = 21502, dport = 53 D (15963) wifi:eb is dhcp or dns sport = 21502, dport = 53 D (30972) wifi:eb is dhcp or dns sport = 53698, dport = 53 E (38961) Fail to sync NTP time