Esp-idf: WiFi hangs when trying to connect. (IDFGH-1160)

[arossoinsite]

Environment

• Development Kit: none
• Module or chip used: ESP32-WROOM-32U
• IDF version: v3.1.3-2-g0d825c6e7
• Build System: Make
• Compiler version: 1.22.0-80-g6c4433a
• Operating System: Linux
• Power Supply: external 5V

Problem Description

After reset or connection lost, WiFi is unable to connect and hangs in an unknown state or falls into a connect/disconnect loop.

Expected Behavior

On system reset or disconnect event, and after calling esp_wifi_connect(), the module should always connect to the AP.

Actual Behavior

Sometimes, on system reset or disconnect event, and after calling esp_wifi_connect(), the module does not connect to the AP and eithers hangs or falls into a connect/disconnect loop.

Debug Logs

Logs when it hangs

rst:0xc (SW_CPU_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:1
load:0x3fff0018,len:4
load:0x3fff001c,len:6156
load:0x40078000,len:8588
ho 0 tail 12 room 4
load:0x40080000,len:6544
entry 0x40080330
I (31) boot: ESP-IDF v3.1.3-2-g0d825c6e7 2nd stage bootloader
I (31) boot: compile time 11:23:13
I (31) boot: Enabling RNG early entropy source...
I (36) qio_mode: Enabling default flash chip QIO
I (42) boot: SPI Speed      : 80MHz
I (46) boot: SPI Mode       : QIO
I (50) boot: SPI Flash Size : 4MB
I (54) boot: Partition Table:
I (58) boot: ## Label            Usage          Type ST Offset   Length
I (65) boot:  0 nvs              WiFi data        01 02 00009000 00010000
I (72) boot:  1 otadata          OTA data         01 00 00019000 00002000
I (80) boot:  2 phy_init         RF data          01 01 0001b000 00001000
I (87) boot:  3 ota_0            OTA app          00 10 00020000 00150000
I (95) boot:  4 ota_1            OTA app          00 11 00170000 00150000
I (102) boot:  5 certs            unknown          fe 00 002c0000 00001000
I (110) boot:  6 apinfo           unknown          fe 00 002c1000 00001000
I (117) boot: End of partition table
I (122) esp_image: segment 0: paddr=0x00170020 vaddr=0x3f400020 size=0x3285c (206940) map
I (185) esp_image: segment 1: paddr=0x001a2884 vaddr=0x3ffb0000 size=0x02f98 ( 12184) load
I (188) esp_image: segment 2: paddr=0x001a5824 vaddr=0x40080000 size=0x00400 (  1024) load
I (192) esp_image: segment 3: paddr=0x001a5c2c vaddr=0x40080400 size=0x0a3e4 ( 41956) load
I (213) esp_image: segment 4: paddr=0x001b0018 vaddr=0x400d0018 size=0x996d8 (628440) map
I (377) esp_image: segment 5: paddr=0x002496f8 vaddr=0x4008a7e4 size=0x06a58 ( 27224) load
I (396) boot: Loaded app from partition at offset 0x170000
I (396) boot: Disabling RNG early entropy source...
I (396) cpu_start: Pro cpu up.
I (400) cpu_start: Starting app cpu, entry point is 0x400812b8
I (391) cpu_start: App cpu up.
I (411) heap_init: Initializing. RAM available for dynamic allocation:
I (417) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM
I (423) heap_init: At 3FFC16A8 len 0001E958 (122 KiB): DRAM
I (430) heap_init: At 3FFE0440 len 00003BC0 (14 KiB): D/IRAM
I (436) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (442) heap_init: At 4009123C len 0000EDC4 (59 KiB): IRAM
I (449) cpu_start: Pro cpu start user code
I (18) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (58) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
I (68) emac: emac start !!!

I (78) emac: emac reset done
I (88) emac: emac start success !!!
I (88) wifi: wifi driver task: 3ffd0a80, prio:23, stack:3584, core=0
I (88) wifi: wifi firmware version: 71d6725
I (88) wifi: config NVS flash: disabled
I (88) wifi: config nano formating: disabled
I (98) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
I (108) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
I (118) wifi: Init dynamic tx buffer num: 32
I (118) wifi: Init data frame dynamic rx buffer num: 32
I (118) wifi: Init management frame dynamic rx buffer num: 32
I (128) wifi: Init static rx buffer size: 1600
I (128) wifi: Init static rx buffer num: 10
I (138) wifi: Init dynamic rx buffer num: 32
I (138) wifi: Set ps type: 0

I (148) Intelligence: Loading certs ok.
I (148) Intelligence: Intelligence config ok.
I (378) phy: phy_version: 4008, c9ae59f, Jan 25 2019, 16:54:06, 0, 2
I (378) wifi: mode : sta (24:0a:c4:16:29:ac)
I (378) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
I (388) Wi-Fi: wifi_set_static_ip() ok.
I (398) Wi-Fi: wifi_set_dns_server() ok.
I (398) Wi-Fi: wifi_set_dns_server() ok.
I (408) Wi-Fi: wifi_set_dns_server() ok.
I (408) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
I (528) wifi: n:1 0, o:1 0, ap:255 255, sta:1 0, prof:1
I (1098) wifi: state: init -> auth (b0)
I (1098) wifi: state: auth -> assoc (0)
I (1098) wifi: state: assoc -> init (9c0)
I (1098) wifi: n:1 0, o:1 0, ap:255 255, sta:1 0, prof:1

Logs when it goes into connect/disconnect loop.

rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:1
load:0x3fff0018,len:4
load:0x3fff001c,len:6156
load:0x40078000,len:8588
ho 0 tail 12 room 4
load:0x40080000,len:6544
0x40080000: _iram_start at /home/arosso/esp/esp-idf/components/freertos/xtensa_vectors.S:1779

entry 0x40080330
0x40080330: _KernelExceptionVector at ??:?

I (30) boot: ESP-IDF v3.1.3-2-g796b6fff8 2nd stage bootloader
I (30) boot: compile time 15:07:37
I (30) boot: Enabling RNG early entropy source...
I (36) qio_mode: Enabling default flash chip QIO
I (41) boot: SPI Speed      : 80MHz
I (45) boot: SPI Mode       : QIO
I (49) boot: SPI Flash Size : 4MB
I (53) boot: Partition Table:
I (57) boot: ## Label            Usage          Type ST Offset   Length
I (64) boot:  0 nvs              WiFi data        01 02 00009000 00010000
I (72) boot:  1 otadata          OTA data         01 00 00019000 00002000
I (79) boot:  2 phy_init         RF data          01 01 0001b000 00001000
I (86) boot:  3 ota_0            OTA app          00 10 00020000 00150000
I (94) boot:  4 ota_1            OTA app          00 11 00170000 00150000
I (101) boot:  5 certs            unknown          fe 00 002c0000 00001000
I (109) boot:  6 apinfo           unknown          fe 00 002c1000 00001000
I (117) boot: End of partition table
I (121) boot: No factory image, trying OTA 0
I (126) esp_image: segment 0: paddr=0x00020020 vaddr=0x3f400020 size=0x31224 (201252) map
I (187) esp_image: segment 1: paddr=0x0005124c vaddr=0x3ffb0000 size=0x02f98 ( 12184) load
I (191) esp_image: segment 2: paddr=0x000541ec vaddr=0x40080000 size=0x00400 (  1024) load
0x40080000: _iram_start at /home/arosso/esp/esp-idf/components/freertos/xtensa_vectors.S:1779

I (194) esp_image: segment 3: paddr=0x000545f4 vaddr=0x40080400 size=0x0ba1c ( 47644) load
I (217) esp_image: segment 4: paddr=0x00060018 vaddr=0x400d0018 size=0x9891c (624924) map
0x400d0018: _stext at ??:?

I (381) esp_image: segment 5: paddr=0x000f893c vaddr=0x4008be1c size=0x05420 ( 21536) load
0x4008be1c: prvInitialiseNewTask at /home/arosso/esp/esp-idf/components/freertos/tasks.c:4832

I (397) boot: Loaded app from partition at offset 0x20000
I (398) boot: Disabling RNG early entropy source...
I (398) cpu_start: Pro cpu up.
I (402) cpu_start: Starting app cpu, entry point is 0x400812b8
0x400812b8: call_start_cpu1 at /home/arosso/esp/esp-idf/components/esp32/cpu_start.c:232

I (0) cpu_start: App cpu up.
I (412) heap_init: Initializing. RAM available for dynamic allocation:
I (419) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM
I (425) heap_init: At 3FFC16A8 len 0001E958 (122 KiB): DRAM
I (431) heap_init: At 3FFE0440 len 00003BC0 (14 KiB): D/IRAM
I (437) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (444) heap_init: At 4009123C len 0000EDC4 (59 KiB): IRAM
I (450) cpu_start: Pro cpu start user code
I (20) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (200) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
I (210) emac: emac start !!!

I (220) emac: emac reset done
I (230) emac: emac start success !!!
I (230) wifi: wifi driver task: 3ffd0a80, prio:23, stack:3584, core=0
I (230) wifi: wifi firmware version: 71d6725
I (230) wifi: config NVS flash: disabled
I (230) wifi: config nano formating: disabled
I (240) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
I (250) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
I (260) wifi: Init dynamic tx buffer num: 32
I (260) wifi: Init data frame dynamic rx buffer num: 32
I (260) wifi: Init management frame dynamic rx buffer num: 32
I (270) wifi: Init static rx buffer size: 1600
I (270) wifi: Init static rx buffer num: 10
I (280) wifi: Init dynamic rx buffer num: 32
I (280) wifi: Set ps type: 0

I (290) Intelligence: Loading certs ok.
I (290) Intelligence: Intelligence config ok.
I (520) phy: phy_version: 4008, c9ae59f, Jan 25 2019, 16:54:06, 0, 2
I (520) wifi: mode : sta (24:0a:c4:17:1b:a8)
I (520) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
I (520) Wi-Fi: wifi_set_static_ip() ok.
I (530) Wi-Fi: wifi_set_dns_server() ok.
I (540) Wi-Fi: wifi_set_dns_server() ok.
I (540) Wi-Fi: wifi_set_dns_server() ok.
I (540) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
I (790) wifi: n:2 0, o:1 0, ap:255 255, sta:2 0, prof:1
I (1350) wifi: state: init -> auth (b0)
I (2350) wifi: state: auth -> init (200)
I (2350) wifi: n:2 0, o:2 0, ap:255 255, sta:2 0, prof:1
W (2350) WIFI EVENT: Wi-Fi Reason: AUTH_EXPIRE (2)
I (2350) Network Manager: Connection attempt: 1
I (2840) wifi: n:4 0, o:2 0, ap:255 255, sta:4 0, prof:1
I (2840) wifi: state: init -> auth (b0)
I (2860) wifi: state: auth -> init (8a0)
I (2860) wifi: n:4 0, o:4 0, ap:255 255, sta:4 0, prof:1
W (2860) WIFI EVENT: Wi-Fi Reason: AUTH_FAIL (202)
I (2870) Network Manager: Connection attempt: 2
W (5280) WIFI EVENT: Wi-Fi Reason: NO_AP_FOUND (201)
I (5280) Network Manager: Connection attempt: 3
I (5400) wifi: n:4 0, o:4 0, ap:255 255, sta:4 0, prof:1
I (5400) wifi: state: init -> auth (b0)
I (6400) wifi: state: auth -> init (200)
I (6400) wifi: n:4 0, o:4 0, ap:255 255, sta:4 0, prof:1
W (6400) WIFI EVENT: Wi-Fi Reason: AUTH_EXPIRE (2)
I (6400) Network Manager: Connection attempt: 4
I (6770) wifi: n:2 0, o:4 0, ap:255 255, sta:2 0, prof:1
I (6770) wifi: state: init -> auth (b0)
I (7770) wifi: state: auth -> init (200)
I (7770) wifi: n:2 0, o:2 0, ap:255 255, sta:2 0, prof:1
W (7770) WIFI EVENT: Wi-Fi Reason: AUTH_EXPIRE (2)
I (7770) Network Manager: Connection attempt: 5
W (10190) WIFI EVENT: Wi-Fi Reason: NO_AP_FOUND (201)
I (10190) Network Manager: Connection attempt: 6
I (10310) wifi: n:2 0, o:2 0, ap:255 255, sta:2 0, prof:1
I (10310) wifi: state: init -> auth (b0)
I (11310) wifi: state: auth -> init (200)
I (11310) wifi: n:2 0, o:2 0, ap:255 255, sta:2 0, prof:1
W (11310) WIFI EVENT: Wi-Fi Reason: AUTH_EXPIRE (2)
I (11310) Network Manager: Connection attempt: 7
I (11800) wifi: n:4 0, o:2 0, ap:255 255, sta:4 0, prof:1
I (11800) wifi: state: init -> auth (b0)
I (12800) wifi: state: auth -> init (200)
I (12800) wifi: n:4 0, o:4 0, ap:255 255, sta:4 0, prof:1
W (12800) WIFI EVENT: Wi-Fi Reason: AUTH_EXPIRE (2)
I (12800) Network Manager: Connection attempt: 8
W (15210) WIFI EVENT: Wi-Fi Reason: NO_AP_FOUND (201)
I (15210) Network Manager: Connection attempt: 9
I (15580) wifi: n:2 0, o:4 0, ap:255 255, sta:2 0, prof:1
I (15580) wifi: state: init -> auth (b0)
I (16580) wifi: state: auth -> init (200)
I (16580) wifi: n:2 0, o:2 0, ap:255 255, sta:2 0, prof:1
W (16580) WIFI EVENT: Wi-Fi Reason: AUTH_EXPIRE (2)
I (16580) Network Manager: Connection attempt: 10
I (17070) wifi: n:4 0, o:2 0, ap:255 255, sta:4 0, prof:1
I (17070) wifi: state: init -> auth (b0)
I (18070) wifi: state: auth -> init (200)
I (18070) wifi: n:4 0, o:4 0, ap:255 255, sta:4 0, prof:1
W (18070) WIFI EVENT: Wi-Fi Reason: AUTH_EXPIRE (2)
I (18070) Network Manager: Connection attempt: 11
W (20490) WIFI EVENT: Wi-Fi Reason: NO_AP_FOUND (201)
I (20490) Network Manager: Connection attempt: 12
I (20610) wifi: n:4 0, o:4 0, ap:255 255, sta:4 0, prof:1
I (20610) wifi: state: init -> auth (b0)
I (21610) wifi: state: auth -> init (200)
I (21610) wifi: n:4 0, o:4 0, ap:255 255, sta:4 0, prof:1
W (21610) WIFI EVENT: Wi-Fi Reason: AUTH_EXPIRE (2)
I (21610) Network Manager: Connection attempt: 13
I (21980) wifi: n:2 0, o:4 0, ap:255 255, sta:2 0, prof:1
I (21980) wifi: state: init -> auth (b0)
I (22980) wifi: state: auth -> init (200)
I (22980) wifi: n:2 0, o:2 0, ap:255 255, sta:2 0, prof:1
W (22980) WIFI EVENT: Wi-Fi Reason: AUTH_EXPIRE (2)
I (22980) Network Manager: Connection attempt: 14
W (25390) WIFI EVENT: Wi-Fi Reason: NO_AP_FOUND (201)
I (25390) Network Manager: Connection attempt: 15
I (25510) wifi: n:2 0, o:2 0, ap:255 255, sta:2 0, prof:1
I (25510) wifi: state: init -> auth (b0)
I (26520) wifi: state: auth -> init (200)
I (26520) wifi: n:2 0, o:2 0, ap:255 255, sta:2 0, prof:1
W (26520) WIFI EVENT: Wi-Fi Reason: AUTH_EXPIRE (2)
I (26520) Network Manager: Connection attempt: 16
I (27010) wifi: n:4 0, o:2 0, ap:255 255, sta:4 0, prof:1
I (27010) wifi: state: init -> auth (b0)
I (28010) wifi: state: auth -> init (200)
I (28010) wifi: n:4 0, o:4 0, ap:255 255, sta:4 0, prof:1
W (28010) WIFI EVENT: Wi-Fi Reason: AUTH_EXPIRE (2)
I (28010) Network Manager: Connection attempt: 17
W (30420) WIFI EVENT: Wi-Fi Reason: NO_AP_FOUND (201)
I (30420) Network Manager: Connection attempt: 18
I (30540) wifi: n:4 0, o:4 0, ap:255 255, sta:4 0, prof:1
I (30540) wifi: state: init -> auth (b0)
I (31540) wifi: state: auth -> init (200)
I (31540) wifi: n:4 0, o:4 0, ap:255 255, sta:4 0, prof:1
W (31540) WIFI EVENT: Wi-Fi Reason: AUTH_EXPIRE (2)
I (31550) Network Manager: Connection attempt: 19
I (31910) wifi: n:2 0, o:4 0, ap:255 255, sta:2 0, prof:1
I (31920) wifi: state: init -> auth (b0)
I (32920) wifi: state: auth -> init (200)
I (32920) wifi: n:2 0, o:2 0, ap:255 255, sta:2 0, prof:1
W (32920) WIFI EVENT: Wi-Fi Reason: AUTH_EXPIRE (2)
I (32920) Network Manager: Connection attempt: 20

Logs when it connects succesfully

rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:1
load:0x3fff0018,len:4
load:0x3fff001c,len:6156
load:0x40078000,len:8588
ho 0 tail 12 room 4
load:0x40080000,len:6544
0x40080000: _iram_start at /home/arosso/esp/esp-idf/components/freertos/xtensa_vectors.S:1779

entry 0x40080330
0x40080330: _KernelExceptionVector at ??:?

I (30) boot: ESP-IDF v3.1.3-2-g796b6fff8 2nd stage bootloader
I (30) boot: compile time 15:07:37
I (30) boot: Enabling RNG early entropy source...
I (36) qio_mode: Enabling default flash chip QIO
I (41) boot: SPI Speed      : 80MHz
I (45) boot: SPI Mode       : QIO
I (49) boot: SPI Flash Size : 4MB
I (53) boot: Partition Table:
I (57) boot: ## Label            Usage          Type ST Offset   Length
I (64) boot:  0 nvs              WiFi data        01 02 00009000 00010000
I (71) boot:  1 otadata          OTA data         01 00 00019000 00002000
I (79) boot:  2 phy_init         RF data          01 01 0001b000 00001000
I (86) boot:  3 ota_0            OTA app          00 10 00020000 00150000
I (94) boot:  4 ota_1            OTA app          00 11 00170000 00150000
I (101) boot:  5 certs            unknown          fe 00 002c0000 00001000
I (109) boot:  6 apinfo           unknown          fe 00 002c1000 00001000
I (117) boot: End of partition table
I (121) boot: No factory image, trying OTA 0
I (126) esp_image: segment 0: paddr=0x00020020 vaddr=0x3f400020 size=0x31224 (201252) map
I (187) esp_image: segment 1: paddr=0x0005124c vaddr=0x3ffb0000 size=0x02f98 ( 12184) load
I (191) esp_image: segment 2: paddr=0x000541ec vaddr=0x40080000 size=0x00400 (  1024) load
0x40080000: _iram_start at /home/arosso/esp/esp-idf/components/freertos/xtensa_vectors.S:1779

I (194) esp_image: segment 3: paddr=0x000545f4 vaddr=0x40080400 size=0x0ba1c ( 47644) load
I (217) esp_image: segment 4: paddr=0x00060018 vaddr=0x400d0018 size=0x9891c (624924) map
0x400d0018: _stext at ??:?

I (381) esp_image: segment 5: paddr=0x000f893c vaddr=0x4008be1c size=0x05420 ( 21536) load
0x4008be1c: prvInitialiseNewTask at /home/arosso/esp/esp-idf/components/freertos/tasks.c:4832

I (397) boot: Loaded app from partition at offset 0x20000
I (397) boot: Disabling RNG early entropy source...
I (398) cpu_start: Pro cpu up.
I (401) cpu_start: Starting app cpu, entry point is 0x400812b8
0x400812b8: call_start_cpu1 at /home/arosso/esp/esp-idf/components/esp32/cpu_start.c:232

I (0) cpu_start: App cpu up.
I (412) heap_init: Initializing. RAM available for dynamic allocation:
I (419) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM
I (425) heap_init: At 3FFC16A8 len 0001E958 (122 KiB): DRAM
I (431) heap_init: At 3FFE0440 len 00003BC0 (14 KiB): D/IRAM
I (437) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (444) heap_init: At 4009123C len 0000EDC4 (59 KiB): IRAM
I (450) cpu_start: Pro cpu start user code
I (20) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (200) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
I (210) emac: emac start !!!

I (220) emac: emac reset done
I (230) emac: emac start success !!!
I (230) wifi: wifi driver task: 3ffd0a80, prio:23, stack:3584, core=0
I (230) wifi: wifi firmware version: 71d6725
I (230) wifi: config NVS flash: disabled
I (230) wifi: config nano formating: disabled
I (240) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
I (250) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
I (260) wifi: Init dynamic tx buffer num: 32
I (260) wifi: Init data frame dynamic rx buffer num: 32
I (260) wifi: Init management frame dynamic rx buffer num: 32
I (270) wifi: Init static rx buffer size: 1600
I (270) wifi: Init static rx buffer num: 10
I (280) wifi: Init dynamic rx buffer num: 32
I (280) wifi: Set ps type: 0

I (290) Intelligence: Loading certs ok.
I (290) Intelligence: Intelligence config ok.
I (490) phy: phy_version: 4008, c9ae59f, Jan 25 2019, 16:54:06, 0, 2
I (490) wifi: mode : sta (24:0a:c4:17:1b:a8)
I (500) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
I (500) Wi-Fi: wifi_set_static_ip() ok.
I (510) Wi-Fi: wifi_set_dns_server() ok.
I (510) Wi-Fi: wifi_set_dns_server() ok.
I (520) Wi-Fi: wifi_set_dns_server() ok.
I (520) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
I (760) wifi: n:2 0, o:1 0, ap:255 255, sta:2 0, prof:1
I (1330) wifi: state: init -> auth (b0)
I (1330) wifi: state: auth -> assoc (0)
I (1340) wifi: state: assoc -> run (10)
I (1360) wifi: connected with insite2.4, channel 2
I (1360) wifi: pm start, type: 0

I (1360) Network Manager: Waiting IP...
I (1360) event: sta ip: 192.168.1.218, mask: 255.255.255.0, gw: 192.168.1.254
I (1360) Network Manager: Got IP!

[negativekelvin]

It looks like it is trying to connect on different channels 1,2,4. What is your AP setup?

[arossoinsite]

Well, the place where the ESP's are is a little big, so, there are various AP's configured on different channels, that probably explains why it tries to connect on different channels. With this in mind, it makes me think that the ESP cannot decide which AP to connect to, but why, and how do you know which channel it is trying to connect?

[DietmarHoch]

same problem with one AP, see the log. nothing happens after last line...

I (0) cpu_start: App cpu up.
I (384) heap_init: Initializing. RAM available for dynamic allocation:
I (391) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM
I (397) heap_init: At 3FFB8EA0 len 00027160 (156 KiB): DRAM
I (403) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (409) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (416) heap_init: At 4008FCC4 len 0001033C (64 KiB): IRAM
I (422) cpu_start: Pro cpu start user code
I (104) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (172) wifi: wifi driver task: 3ffc080c, prio:23, stack:3584, core=0
I (172) wifi: wifi firmware version: 7c00966
I (172) wifi: config NVS flash: enabled
I (182) wifi: config nano formating: disabled
I (182) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
I (192) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
I (232) wifi: Init dynamic tx buffer num: 32
I (232) wifi: Init data frame dynamic rx buffer num: 32
I (232) wifi: Init management frame dynamic rx buffer num: 32
I (242) wifi: Init management short buffer num: 32
I (242) wifi: Init static rx buffer size: 1600
I (242) wifi: Init static rx buffer num: 10
I (252) wifi: Init dynamic rx buffer num: 32
I (362) phy: phy_version: 4100, 2a5dd04, Jan 23 2019, 21:00:07, 0, 0
I (362) wifi: mode : sta (30:ae:a4:fe:08:d8)
I (362) wifi station: wifi_init_sta finished.
I (372) wifi station: connect to ap SSID:xxxxxxxxxxx password:xxxxxxxxxxx
I (492) wifi: new:<6,0>, old:<1,0>, ap:<255,255>, sta:<6,0>, prof:1
I (492) wifi: state: init -> auth (b0)
I (492) wifi: state: auth -> init (8a0)
I (492) wifi: new:<6,0>, old:<6,0>, ap:<255,255>, sta:<6,0>, prof:1

[camiloperezv]

I have a similar issue using 3.1.3 release. The device neither get the IP from router nor send a disconnection event or any event

[DietmarHoch]

any updates???
Issue is very important for my project...

[negativekelvin]

I (1098) wifi: state: assoc -> init (9c0)
I (32920) wifi: state: auth -> init (200)
I (492) wifi: state: auth -> init (8a0)

It would help to know what these codes mean @liuzfesp

[liuzfesp]

Hi @zhangyanjiaoesp please help.

[zhangyanjiaoesp]

@DietmarHoch Which IDF version do you use? Please tell me the version and commit ID

[zhangyanjiaoesp]

I have a similar issue using 3.1.3 release. The device neither get the IP from router nor send a disconnection event or any event

@camiloperezv Do you have mulit APs with the same ssid also?

[camiloperezv]

@zhangyanjiaoesp Yes, I have at least 3 AP with the same SSID but they are in different channels because they are set to AUTO

[DietmarHoch]

@zhangyanjiaoesp
i am on the master branch
v4.0-dev-584-g3bf56cdd1-dirty

[zhangyanjiaoesp]

@DietmarHoch Please use the wifi lib to test, I think it can resolve your peoblem.
GH3474_master.zip

[zhangyanjiaoesp]

@arossoinsite Please check your IDF commit ID, I can't find v3.1.3-2-g0d825c6e7. And I find there are two commit ID in your log: v3.1.3-2-g0d825c6e7, v3.1.3-2-g796b6fff8. Both of them can't be found.

[arossoinsite]

@zhangyanjiaoesp IDF commit is v3.1.2-99-gcf5dbadf4, but we add the MQTT client as a local commit, so that's why the commit I gave previously is different.

[DietmarHoch]

@DietmarHoch Please use the wifi lib to test, I think it can resolve your peoblem.
GH3474_master.zip

tried out this fix, 50 connects without a problem so far, I think this fix my problem.
could you please include this in the master branch and give me an update when done?

here are a trace with a possible reconnect after fail:

_LED init
STA start
I (535) wifi: new:<6,0>, old:<1,0>, ap:<255,255>, sta:<6,0>, prof:1
I (535) wifi: state: init -> auth (b0)
I (545) wifi: state: auth -> init (8a0)
I (545) wifi: new:<6,0>, old:<6,0>, ap:<255,255>, sta:<6,0>, prof:1
I (545) wifi: new:<6,0>, old:<6,0>, ap:<255,255>, sta:<6,0>, prof:1
I (555) wifi: state: init -> auth (b0)
I (555) wifi: state: auth -> init (8a0)
I (555) wifi: new:<6,0>, old:<6,0>, ap:<255,255>, sta:<6,0>, prof:1
STA disconnected
STA disconnected
I (2745) wifi: new:<6,0>, old:<6,0>, ap:<255,255>, sta:<6,0>, prof:1
I (2745) wifi: state: init -> auth (b0)
I (2745) wifi: state: auth -> assoc (0)
I (2755) wifi: state: assoc -> run (10)
I (2795) wifi: connected with home-sweet-home, channel 6, bssid = e0:28:6d:76:30:fc
I (2795) wifi: pm start, type: 1

I (3745) tcpip_adapter: sta ip: 192.168.178.29, mask: 255.255.255.0, gw: 192.168.178.1
WiFI ready_

[zhangyanjiaoesp]

@DietmarHoch

could you please include this in the master branch and give me an update when done?

We will merge it into the master, and give you update later.

[zhangyanjiaoesp]

@arossoinsite

@zhangyanjiaoesp IDF commit is v3.1.2-99-gcf5dbadf4, but we add the MQTT client as a local commit, so that's why the commit I gave previously is different.

Please use the wifi lib to test, thanks.
GH3474_v3.1.zip

[arossoinsite]

@zhangyanjiaoesp I wil try and tell you if it works fine in a couple of days.

[arossoinsite]

@igrr @zhangyanjiaoesp Do you know if these is fixed on release 3.2? If not, it is possible to have these bugfix for that release?

[zhangyanjiaoesp]

@igrr @zhangyanjiaoesp Do you know if these is fixed on release 3.2? If not, it is possible to have these bugfix for that release?

@arossoinsite Can this bugfix solve your problem? This bugfix has been merged into master and release/v3.3, and it will be merged into v3.2 and v3.1 later.
By the way, you found this problem while testing another problem(https://github.com/espressif/esp-idf/issues/3323), Will the original problem still occur with the wifi lib I provided ?

[arossoinsite]

@zhangyanjiaoesp I've just released a new firmware for the products with the lib provided, I'm watching how it behaves. The problems arise about once a week, so probably at the end of this week I will have some news.

[zhangyanjiaoesp]

@arossoinsite Do you have any updates?

[arossoinsite]

@zhangyanjiaoesp Almost two weeks have passed and only today one board has dropped out, but for now I don't know why.

[arossoinsite]

@zhangyanjiaoesp It seems the issue is gone, about 3 weeks without problems. The only board that disconnected was because it's power supply failed.

[camiloperezv]

Yeah, my issue is gone too, thanks a lot.

[q7777777hk]

I am experiencing same problem in 3.3
After the last line, nothing happened after the last line. No IP from router nor any disconnection event

I (680333) wifi: new:<1,0>, old:<1,0>, ap:<255,255>, sta:<1,0>, prof:1
I (680333) wifi: state: init -> auth (b0)
I (680333) wifi: state: auth -> assoc (0)
I (680333) wifi: state: assoc -> run (10)
I (680353) wifi: connected with xxxxxxx, channel 1, HT20, bssid = 0a:8d:db:6e:f8:20
I (680483) wifi: pm start, type: 1
I (680493) STA: Connected

Any idea ?

[arossoinsite]

In our project we implement a kind of sentinel task, independent of Wi-Fi and system event loop tasks, that receives event notifications from the Wi-Fi event handler to reset a timer, if the timer expires, the system reboot, but if receives the got IP event, stops the timer. If a disconnect or lost IP event arrives, the timer is enabled again.

[q7777777hk]

In our project we implement a kind of sentinel task, independent of Wi-Fi and system event loop tasks, that receives event notifications from the Wi-Fi event handler to reset a timer, if the timer expires, the system reboot, but if receives the got IP event, stops the timer. If a disconnect or lost IP event arrives, the timer is enabled again.

Problem is I got no event at all after the "STA: Connected", no got IP, no disconnect, nor lost IP

[zhangyanjiaoesp]

@q7777777hk
Thanks for reporting the issue. Would you please help provide more details as suggested in the issue template? Information like elf, sdk configuration, backtrace, log outputs, commit ID, hardware and etc. would help us debug further. Thanks.

[q7777777hk]

@q7777777hk
Thanks for reporting the issue. Would you please help provide more details as suggested in the issue template? Information like elf, sdk configuration, backtrace, log outputs, commit ID, hardware and etc. would help us debug further. Thanks.

Thanks for reminding, below is the detail information

My hardware is : ESP32-WROOM-32D
SDK configuration
https://drive.google.com/file/d/12vQOLFqxpMnvkQzHrierQmvmu_v82tqy/view?usp=sharing
Log output
https://drive.google.com/file/d/1Ddr5w6kQ5V1MqmbIw6pQj9G0W--PychH/view?usp=sharing
Commit log
https://drive.google.com/file/d/1JV0FZ-H5SRCXtP2MvcWFt8SCtepdkx3B/view?usp=sharing

I am using 2 routers, firstly my ESP32 connects to "MYNET". This router is always ok.
Then I switch the wifi connection to my 2nd router "ABC_Devices" (Meraki MR42). It can connect but it never return IP not disconnection event. Tried a number of time but same situation

(Sorry I cannot provide the elf file, as it contains too much information of my customer)

[zhangyanjiaoesp]

Are MYNET and ABC_Devices the two routers ssid? Both of them are Meraki MR42?

[zhangyanjiaoesp]

What are the encryption methods of the two routers?

[negativekelvin]

@q7777777hk are you sure this isn't just dhcp problem? Have you tried disabling CONFIG_LWIP_DHCP_DOES_ARP_CHECK?

[q7777777hk]

@zhangyanjiaoesp

Are MYNET and ABC_Devices the two routers ssid? Both of them are Meraki MR42?

Yes, MYNET and ABC_Devices the two routers ssid. Only ABC_Devices is Meraki MR42
Both use WPA2-PSK[AES]

[q7777777hk]

@negativekelvin are you sure this isn't just dhcp problem? Have you tried disabling CONFIG_LWIP_DHCP_DOES_ARP_CHECK?

I have read other post, "CONFIG_LWIP_DHCP_DOES_ARP_CHECK" affects the Reserved DHCP.
But my router has not reserved any ip for my ESP32
And you can see from my log, ESP32 even cannot get IP address from ABC_Devices for the 1st connection attempt

[zhangyanjiaoesp]

@q7777777hk Can you provide some packet captures when this issue happens.

[negativekelvin]

@q7777777hk did you try with CONFIG_LWIP_DHCP_DOES_ARP_CHECK disabled? It is affected by other things besides reserved addresses.

[q7777777hk]

@negativekelvin , I will disable this in our next release, but since this problem is found in customer environment, I need to wait for their reply to get the result

[q7777777hk]

@zhangyanjiaoesp , not possible to do so, as this problem is found in customer environment. They will not help us to capture packets