esp-idf
esp-idf copied to clipboard
espressif
Network requests failing occasionally when connected to bridged network (IDFGH-12630)
Answers checklist.
- [X] I have read the documentation ESP-IDF Programming Guide and the issue is not addressed there.
- [X] I have updated my IDF branch (master or release) to the latest version and checked that the issue is present there.
- [X] I have searched the issue tracker for a similar issue and not found a similar issue.
IDF version.
v5.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
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:
@mhdong @MaxwellAlan
Any feedback about this issue? (The label shows "In Progress" but seems no response for a long period, is there anyone working on this issue?)
I sometimes got below error after device boot and successfully joined an AP:
E (21970) esp-tls: [sock=48] select() timeout E (21971) esp-tls: Failed to open new connection E (21971) transport_base: Failed to open a new connection
Below is the debug log:
tcp_connect to port 8121 tcp_slowtmr: processing active pcb tcp_slowtmr: processing active pcb tcp_slowtmr: polling application tcp_slowtmr: processing active pcb tcp_slowtmr: processing active pcb tcp_slowtmr: polling application tcp_slowtmr: processing active pcb tcp_slowtmr: processing active pcb tcp_slowtmr: polling application tcp_slowtmr: processing active pcb tcp_slowtmr: processing active pcb tcp_slowtmr: polling application tcp_slowtmr: processing active pcb tcp_slowtmr: processing active pcb tcp_slowtmr: polling application tcp_slowtmr: processing active pcb tcp_slowtmr: processing active pcb tcp_slowtmr: polling application tcp_slowtmr: processing active pcb tcp_slowtmr: processing active pcb tcp_slowtmr: polling application tcp_slowtmr: processing active pcb tcp_slowtmr: processing active pcb tcp_slowtmr: polling application tcp_slowtmr: processing active pcb tcp_slowtmr: processing active pcb tcp_slowtmr: polling application tcp_slowtmr: processing active pcb tcp_slowtmr: processing active pcb tcp_slowtmr: polling application tcp_slowtmr: processing active pcb tcp_slowtmr: processing active pcb tcp_slowtmr: polling application tcp_slowtmr: processing active pcb tcp_slowtmr: processing active pcb tcp_slowtmr: polling application tcp_slowtmr: processing active pcb tcp_slowtmr: processing active pcb tcp_slowtmr: polling application tcp_slowtmr: processing active pcb tcp_slowtmr: processing active pcb tcp_slowtmr: polling application tcp_slowtmr: processing active pcb tcp_slowtmr: processing active pcb tcp_slowtmr: polling application E (22215) esp-tls: [sock=48] select() timeout tcp_close: closing in State: SYN_SENT tcp_pcb_purge tcp_pcb_purge: data left on ->unacked E (22217) esp-tls: Failed to open new connection E (22222) transport_base: Failed to open a new connection E (22229) HTTP_CLIENT: Connection failed, sock < 0 W (22239) Re-try uploading data, ret=28674, errno=119 (Connection already in progress)
I (22249) TLS_MGR: ca_sel=0 tcp_connect to port 8121 tcp_slowtmr: processing active pcb tcp_slowtmr: processing active pcb tcp_slowtmr: polling application tcp_slowtmr: processing active pcb tcp_slowtmr: processing active pcb tcp_slowtmr: polling application tcp_slowtmr: processing active pcb tcp_slowtmr: processing active pcb tcp_slowtmr: polling application tcp_slowtmr: processing active pcb tcp_slowtmr: processing active pcb tcp_slowtmr: polling application tcp_slowtmr: processing active pcb tcp_slowtmr: processing active pcb tcp_slowtmr: polling application tcp_slowtmr: processing active pcb tcp_slowtmr: processing active pcb tcp_slowtmr: polling application tcp_slowtmr: processing active pcb tcp_slowtmr: processing active pcb tcp_slowtmr: polling application tcp_slowtmr: processing active pcb tcp_slowtmr: processing active pcb tcp_slowtmr: polling application tcp_slowtmr: processing active pcb tcp_slowtmr: processing active pcb tcp_slowtmr: polling application tcp_slowtmr: processing active pcb tcp_slowtmr: processing active pcb tcp_slowtmr: polling application tcp_slowtmr: processing active pcb tcp_slowtmr: processing active pcb tcp_slowtmr: polling application tcp_slowtmr: processing active pcb tcp_slowtmr: processing active pcb tcp_slowtmr: polling application tcp_slowtmr: processing active pcb tcp_slowtmr: processing active pcb tcp_slowtmr: polling application tcp_slowtmr: processing active pcb tcp_slowtmr: processing active pcb tcp_slowtmr: polling application tcp_slowtmr: processing active pcb tcp_slowtmr: processing active pcb tcp_slowtmr: polling application E (37257) esp-tls: [sock=48] select() timeout tcp_close: closing in State: SYN_SENT tcp_pcb_purge tcp_pcb_purge: data left on ->unacked E (37259) esp-tls: Failed to open new connection E (37264) transport_base: Failed to open a new connection E (37271) HTTP_CLIENT: Connection failed, sock < 0
I compare the OK and FAILURE casess:
The OK case: lwip_socket(PF_INET, SOCK_STREAM, 0) = 48 lwip_connect(48, addr=125.228.203.199 port=8121) tcp_connect to port 8121 lwip_connect(48) failed, err=-5 lwip_select(49, 0x0, 0x3fca9690, 0x0, tvsec=15 tvusec=0) lwip_selscan: fd=48 ready for writing lwip_select: nready=1 lwip_getsockopt(48, SOL_SOCKET, SO_ERROR) = 0 I (7103) mbedtls: ssl_tls.c:4606 => handshake
The failure case: lwip_socket(PF_INET, SOCK_STREAM, 0) = 48 lwip_connect(48, addr=125.228.203.199 port=8121) tcp_connect to port 8121 lwip_connect(48) failed, err=-5 lwip_select(49, 0x0, 0x3fca9690, 0x0, tvsec=15 tvusec=0) tcp_slowtmr: processing active pcb tcp_slowtmr: processing active pcb tcp_slowtmr: polling application ... It never reach "ready for writing". lwip_select: timeout expired
And when this issue happened, https://github.com/espressif/esp-lwip/blob/2.1.2-esp/src/api/sockets.c#L1934 it cannot reach ready for writing because sendevent is 0.
@david-cermak @ESP-YJM Can you help to take a look, thanks.
@AxelLin For the failure issue, it seems the device send TCP SYN and not receive SYN +ACK and reach the max retries. It maybe the device send SYN failure in wifi or wifi not receive SYN + ACK. You can simply disabled WIFI AMPDU TX and RX to test. Or you can capture the air packet to check whether the server response the SYN + ACK.
@ESP-YJM Now I confirm I can reproduce this issue only when CONFIG_ESP_WIFI_AMPDU_TX_ENABLED=y. Test with v5.2.2-457-g3883a17f54
@AxelLin Could you please try the release/v5.2 branch?
I'm using release/v5.2 branch $ git describe v5.2.2-457-g3883a17f54
@AxelLin Ok, I have asked WIFI colleagues to check it.
FYI, below is the log with verbose build:
lwip_connect(48, addr=125.228.203.199 port=8121) V (12516) wifi:tx process: alloc static tx buf, pb=0x3c120378 l=58 hdr=0 data=58 lwip_connect(48) failed, err=-5 lwip_select(49, 0x0, 0x3fca8af0, 0x0, tvsec=15 tvusec=0) V (13170) wifi:tx process: alloc static tx buf, pb=0x3c1203dc l=42 hdr=0 data=42 V (13765) wifi:tx process: alloc static tx buf, pb=0x3c120378 l=58 hdr=0 data=58 V (15265) wifi:tx process: alloc static tx buf, pb=0x3c120378 l=58 hdr=0 data=58 V (16765) wifi:tx process: alloc static tx buf, pb=0x3c120378 l=58 hdr=0 data=58 V (18265) wifi:tx process: alloc static tx buf, pb=0x3c120378 l=58 hdr=0 data=58 V (19765) wifi:tx process: alloc static tx buf, pb=0x3c120378 l=58 hdr=0 data=58 V (21265) wifi:tx process: alloc static tx buf, pb=0x3c120378 l=58 hdr=0 data=58 V (22765) wifi:tx process: alloc static tx buf, pb=0x3c120378 l=58 hdr=0 data=58 V (24265) wifi:tx process: alloc static tx buf, pb=0x3c120378 l=58 hdr=0 data=58 V (25765) wifi:tx process: alloc static tx buf, pb=0x3c120378 l=58 hdr=0 data=58 V (27265) wifi:tx process: alloc static tx buf, pb=0x3c120378 l=58 hdr=0 data=58 lwip_select: timeout expired E (27554) esp-tls: [sock=48] select() timeout lwip_close(48) E (27555) esp-tls: Failed to open new connection E (27557) transport_base: Failed to open a new connection E (27563) HTTP_CLIENT: Connection failed, sock < 0
@AxelLin Ok, I have asked WIFI colleagues to check it.
But there is no update at all even after waiting for 3 Months.
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
hi @AxelLin I'm very sorry for the delayed response. I’m using the example (https://github.com/espressif/esp-idf/tree/master/examples/protocols/sntp), no issues were found during testing.
D (30972) wifi:eb is dhcp or dns sport = 53698, dport = 53 Multiple logs showing dport = 53 for DNS indicate DNS failures. Possible reasons include an incorrect NTP server name or the NTP server being offline. The cause of the issue can be verified using packet capture or ping NTP server.
Thanks for reporting, will close due to short of feedback, feel free to reopen with more updates. Thanks for using our Espressif product!
