Android hotspot requires restarting for ESP32 to reconnect or fails: auth -> init (200) [solved:update to latest master]

[jcsbanks]

I discovered during application development that an Android hotspot will not be connected to unless it is started after the ESP32, so tested to reproduce with a minimal example:

Using example: esp-idf\examples\wifi\getting_started\station
Board ESP32 MiniKit 1.1 but can try on others

When connecting to a Nokia 8 hotspot (Android 8.1.0), it will only reconnect if the hotspot is restarted after the ESP32 is reset. When connected to other wifi networks, if you reset the ESP32 it will happily reconnect using stored credentials in NVS or credentials in the code, similarly I can switch between these networks at run time without problems.

Below is the dump from two ESP32 restarts. The first time, I start the hotspot after a few failed attempts when it was missing - all as expected. The second time, I just restart the ESP32 and it fails.

SUCCESSFUL CONNECTIONS:
I (12168) wifi: state: init -> auth (b0)
I (12172) wifi: state: auth -> assoc (0)
I (12179) wifi: state: assoc -> run (10)


UNSUCCESSFUL CONNECTIONS:
I (8269) wifi: new:<11,0>, old:<11,0>, ap:<255,255>, sta:<11,0>, prof:1
I (8269) wifi: state: init -> auth (b0)
I (9269) wifi: state: auth -> init (200)
I (9270) wifi: new:<11,0>, old:<11,0>, ap:<255,255>, sta:<11,0>, prof:1
I (9270) wifi station: retry to connect to the AP

Reproduced with second Nokia 8, and also with the SSID with no spaces and with a different password. There are no other options in the Android device except to change from WPA2 PSK to no security, which also does not work.

wifi: state: auth -> init (200) BEACON_TIMEOUT appears to be the issue. Trying to understand whether this is an Android or ESP32 issue, but my users are likely to come across it.

Code: Select all

ets Jun  8 2016 00:22:57

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:6664
load:0x40078000,len:11056
ho 0 tail 12 room 4
load:0x40080400,len:7304
entry 0x40080780
I (30) boot: ESP-IDF v3.3-beta1-44-gda2116f55 2nd stage bootloader
I (30) boot: compile time 22:14:23
I (30) 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 (57) boot: ## Label            Usage          Type ST Offset   Length
I (65) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (72) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (80) boot:  2 factory          factory app      00 00 00010000 00100000
I (87) boot: End of partition table
I (91) esp_image: segment 0: paddr=0x00010020 vaddr=0x3f400020 size=0x1738c ( 95116) map
I (125) esp_image: segment 1: paddr=0x000273b4 vaddr=0x3ff80000 size=0x00000 (     0) load
I (126) esp_image: segment 2: paddr=0x000273bc vaddr=0x3ff80000 size=0x00000 (     0) load
I (132) esp_image: segment 3: paddr=0x000273c4 vaddr=0x3ffb0000 size=0x02cc0 ( 11456) load
I (145) esp_image: segment 4: paddr=0x0002a08c vaddr=0x3ffb2cc0 size=0x00000 (     0) load
I (150) esp_image: segment 5: paddr=0x0002a094 vaddr=0x40080000 size=0x00400 (  1024) load
0x40080000: _WindowOverflow4 at C:/msys32/home/jcsba/esp/esp-idf/components/freertos/xtensa_vectors.S:1685

I (159) esp_image: segment 6: paddr=0x0002a49c vaddr=0x40080400 size=0x05b74 ( 23412) load
I (176) esp_image: segment 7: paddr=0x00030018 vaddr=0x400d0018 size=0x66d34 (421172) map
0x400d0018: _stext at ??:?

I (288) esp_image: segment 8: paddr=0x00096d54 vaddr=0x40085f74 size=0x0b2b4 ( 45748) load
0x40085f74: ppSearchTxQueue at ??:?

I (303) esp_image: segment 9: paddr=0x000a2010 vaddr=0x400c0000 size=0x00000 (     0) load
I (304) esp_image: segment 10: paddr=0x000a2018 vaddr=0x50000000 size=0x00000 (     0) load
I (310) esp_image: segment 11: paddr=0x000a2020 vaddr=0x50000000 size=0x00000 (     0) load
I (329) boot: Loaded app from partition at offset 0x10000
I (329) boot: Disabling RNG early entropy source...
I (331) cpu_start: Pro cpu up.
I (335) cpu_start: Application information:
I (339) cpu_start: Project name:     wifi_station
I (345) cpu_start: App version:
I (349) cpu_start: Compile time:     22:16:16
I (354) cpu_start: Compile date:     Jan  8 2019
I (359) cpu_start: ESP-IDF:          v3.3-beta1-44-gda2116f55
I (366) cpu_start: Starting app cpu, entry point is 0x40081040
0x40081040: call_start_cpu1 at C:/msys32/home/jcsba/esp/esp-idf/components/esp32/cpu_start.c:261

I (0) cpu_start: App cpu up.
I (376) heap_init: Initializing. RAM available for dynamic allocation:
I (383) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM
I (389) heap_init: At 3FFB8C58 len 000273A8 (156 KiB): DRAM
I (396) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (402) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (408) heap_init: At 40091228 len 0000EDD8 (59 KiB): IRAM
I (414) cpu_start: Pro cpu start user code
I (208) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (317) wifi station: ESP_WIFI_MODE_STA
I (320) wifi: wifi driver task: 3ffc02a4, prio:23, stack:3584, core=0
I (320) wifi: wifi firmware version: 328353e
I (321) wifi: config NVS flash: enabled
I (325) wifi: config nano formating: disabled
I (329) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
I (338) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
I (365) wifi: Init dynamic tx buffer num: 32
I (365) wifi: Init data frame dynamic rx buffer num: 32
I (366) wifi: Init management frame dynamic rx buffer num: 32
I (369) wifi: Init static rx buffer size: 1600
I (373) wifi: Init static rx buffer num: 10
I (377) wifi: Init dynamic rx buffer num: 32
W (394) phy_init: failed to load RF calibration data (0x1102), falling back to full calibration
I (547) phy: phy_version: 4000, b6198fa, Sep  3 2018, 15:11:06, 0, 2
I (558) wifi: mode : sta (30:ae:a4:32:d4:90)
I (558) wifi station: wifi_init_sta finished.
I (558) wifi station: connect to ap SSID:Nokia 8 password:[10 char alphanumeric password removed]
I (2966) wifi station: retry to connect to the AP
I (2966) wifi station: connect to the AP fail

I (5373) wifi station: retry to connect to the AP
I (5373) wifi station: connect to the AP fail

I (7779) wifi station: retry to connect to the AP
I (7780) wifi station: connect to the AP fail

I (10186) wifi station: retry to connect to the AP
I (10186) wifi station: connect to the AP fail

I (11511) wifi: new:<11,0>, old:<1,0>, ap:<255,255>, sta:<11,0>, prof:1
I (12168) wifi: state: init -> auth (b0)
I (12172) wifi: state: auth -> assoc (0)
I (12179) wifi: state: assoc -> run (10)
I (12196) wifi: connected with Nokia 8, channel 11, bssid = cc:9f:7a:9d:6a:19
I (12200) wifi: pm start, type: 1

I (12819) event: sta ip: 192.168.43.178, mask: 255.255.255.0, gw: 192.168.43.1
I (12819) wifi station: got ip:192.168.43.178
ets Jun  8 2016 00:22:57

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:6664
load:0x40078000,len:11056
ho 0 tail 12 room 4
load:0x40080400,len:7304
entry 0x40080780
I (30) boot: ESP-IDF v3.3-beta1-44-gda2116f55 2nd stage bootloader
I (30) boot: compile time 22:14:23
I (30) 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 (57) boot: ## Label            Usage          Type ST Offset   Length
I (65) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (72) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (80) boot:  2 factory          factory app      00 00 00010000 00100000
I (87) boot: End of partition table
I (91) esp_image: segment 0: paddr=0x00010020 vaddr=0x3f400020 size=0x1738c ( 95116) map
I (125) esp_image: segment 1: paddr=0x000273b4 vaddr=0x3ff80000 size=0x00000 (     0) load
I (126) esp_image: segment 2: paddr=0x000273bc vaddr=0x3ff80000 size=0x00000 (     0) load
I (132) esp_image: segment 3: paddr=0x000273c4 vaddr=0x3ffb0000 size=0x02cc0 ( 11456) load
I (145) esp_image: segment 4: paddr=0x0002a08c vaddr=0x3ffb2cc0 size=0x00000 (     0) load
I (150) esp_image: segment 5: paddr=0x0002a094 vaddr=0x40080000 size=0x00400 (  1024) load
0x40080000: _WindowOverflow4 at C:/msys32/home/jcsba/esp/esp-idf/components/freertos/xtensa_vectors.S:1685

I (159) esp_image: segment 6: paddr=0x0002a49c vaddr=0x40080400 size=0x05b74 ( 23412) load
I (176) esp_image: segment 7: paddr=0x00030018 vaddr=0x400d0018 size=0x66d34 (421172) map
0x400d0018: _stext at ??:?

I (288) esp_image: segment 8: paddr=0x00096d54 vaddr=0x40085f74 size=0x0b2b4 ( 45748) load
0x40085f74: ppSearchTxQueue at ??:?

I (303) esp_image: segment 9: paddr=0x000a2010 vaddr=0x400c0000 size=0x00000 (     0) load
I (304) esp_image: segment 10: paddr=0x000a2018 vaddr=0x50000000 size=0x00000 (     0) load
I (310) esp_image: segment 11: paddr=0x000a2020 vaddr=0x50000000 size=0x00000 (     0) load
I (329) boot: Loaded app from partition at offset 0x10000
I (329) boot: Disabling RNG early entropy source...
I (331) cpu_start: Pro cpu up.
I (335) cpu_start: Application information:
I (339) cpu_start: Project name:     wifi_station
I (345) cpu_start: App version:
I (349) cpu_start: Compile time:     22:16:16
I (354) cpu_start: Compile date:     Jan  8 2019
I (359) cpu_start: ESP-IDF:          v3.3-beta1-44-gda2116f55
I (366) cpu_start: Starting app cpu, entry point is 0x40081040
0x40081040: call_start_cpu1 at C:/msys32/home/jcsba/esp/esp-idf/components/esp32/cpu_start.c:261

I (0) cpu_start: App cpu up.
I (376) heap_init: Initializing. RAM available for dynamic allocation:
I (383) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM
I (389) heap_init: At 3FFB8C58 len 000273A8 (156 KiB): DRAM
I (395) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (402) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (408) heap_init: At 40091228 len 0000EDD8 (59 KiB): IRAM
I (414) cpu_start: Pro cpu start user code
I (208) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (296) wifi station: ESP_WIFI_MODE_STA
I (297) wifi: wifi driver task: 3ffc03f4, prio:23, stack:3584, core=0
I (298) wifi: wifi firmware version: 328353e
I (300) wifi: config NVS flash: enabled
I (303) wifi: config nano formating: disabled
I (307) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
I (317) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
I (340) wifi: Init dynamic tx buffer num: 32
I (340) wifi: Init data frame dynamic rx buffer num: 32
I (340) wifi: Init management frame dynamic rx buffer num: 32
I (344) wifi: Init static rx buffer size: 1600
I (348) wifi: Init static rx buffer num: 10
I (352) wifi: Init dynamic rx buffer num: 32
I (433) phy: phy_version: 4000, b6198fa, Sep  3 2018, 15:11:06, 0, 0
I (434) wifi: mode : sta (30:ae:a4:32:d4:90)
I (434) wifi station: wifi_init_sta finished.
I (439) wifi station: connect to ap SSID:Nokia 8 password:[10 char alphanumeric password removed]
I (556) wifi: new:<11,0>, old:<1,0>, ap:<255,255>, sta:<11,0>, prof:1
I (1212) wifi: state: init -> auth (b0)
I (2213) wifi: state: auth -> init (200)
I (2213) wifi: new:<11,0>, old:<11,0>, ap:<255,255>, sta:<11,0>, prof:1
I (2214) wifi station: retry to connect to the AP
I (2217) wifi station: connect to the AP fail

I (4620) wifi station: retry to connect to the AP
I (4621) wifi station: connect to the AP fail

I (4741) wifi: new:<11,0>, old:<11,0>, ap:<255,255>, sta:<11,0>, prof:1
I (4741) wifi: state: init -> auth (b0)
I (5741) wifi: state: auth -> init (200)
I (5741) wifi: new:<11,0>, old:<11,0>, ap:<255,255>, sta:<11,0>, prof:1
I (5742) wifi station: retry to connect to the AP
I (5745) wifi station: connect to the AP fail

I (8149) wifi station: retry to connect to the AP
I (8149) wifi station: connect to the AP fail

I (8269) wifi: new:<11,0>, old:<11,0>, ap:<255,255>, sta:<11,0>, prof:1
I (8269) wifi: state: init -> auth (b0)
I (9269) wifi: state: auth -> init (200)
I (9270) wifi: new:<11,0>, old:<11,0>, ap:<255,255>, sta:<11,0>, prof:1
I (9270) wifi station: retry to connect to the AP
I (9274) wifi station: connect to the AP fail

I (11677) wifi station: connect to the AP fail

[jcsbanks]

Enabled some wifi debugging logging:

Code: Select all

I (5526) wifi: ap found, mac=cc:9f:7a:9d:6a:19
I (5530) wifi: bssid=cc:9f:7a:9d:6a:19, LR=0
I (5534) wifi: new_bss=0x3ffb3e90, cur_bss=0x0, new_chan=<6,0>, cur_chan=6
I (5541) wifi: filter: set rx policy=5
I (5544) wifi: new:<6,0>, old:<6,0>, ap:<255,255>, sta:<6,0>, prof:1
I (5550) wifi: connect_op: status=0, auth=5, cipher=3
I (5555) wifi: auth mode is not none
I (5559) wifi: connect_bss: auth=1, reconnect=0
I (5563) wifi: state: init -> auth (b0)
I (5566) wifi: start 1s AUTH timer
I (5569) wifi: clear scan ap list
I (6570) wifi: auth timeout
I (6570) wifi: state: auth -> init (200)
I (6570) wifi: connect step 1 -> 4, status=1, err_time=1
I (6570) wifi: stop beacon/connect timer
I (6573) wifi: reason: auth expire(2)

[brp80000]

Try another device
After updating IDF to 3-1-1 I have problems connecting WIFI devices with Android 6.0.1
Forum dead, need to look for a new device to replace the esp, no one answers

[jcsbanks]

I'm encouraged that there are more posts getting into security and deployment as my project is getting there like so many others, and I am finding your posts thought provoking. I think support is very good, some of these issues are complex.

Certainly I find the hardest bit is getting new APIs to work robustly, nearly always examples and drivers benefit from tweaks until they are really mature, but when they are abstracted fairly heavily and debugging is limited, it can be hard as ESP-IDF is pretty large now.

[liuzhifu]

Hi, I think the problem should happen in following scenario:
1. ESP32 connects to hotspot.
2. ESP32 powers off and has no chance to send deauthorize frame to hotspot to disconnect the WiFi connection.
3. ESP32 fails to connect hotspot because the hotspot thinks the ESP32 is already connected it.

Generally speaking, the AP (including hotspot) has a keep alive timer, the timer value is implementation dependent. It restarts the keep alive time if it receives data packets from the station, it disconnects the WiFi if the keep alive timer expires.

In above scenario, the hotspot doesn't know the ESP32 is left, so it maintains the WiFi connection before the keep alive timer expires. When ESP32 is power on and a reconnect frame (authentication frame) is sent by ESP32. On receiving the authentication frame, different AP may have different strategies:
1. Most APs choose to accept the authentication frame and the station can reconnect to AP immediately
2. Few APs reject the authentication frame and the station can't reconnect to AP until the keep alive timer expires
3. Some APs may have compatibility bugs, they consider the authentication frame as normal data frame and restart the keep alive timer, the station can never be connected if it keep reconnecting.

If your problem is same as the one I'm talking about, we already have enhancement for it, it will be merged into IDF within about 2 weeks.
You can do following test to check it:
1. ESP32 connects to hotspot
2. Power off ESP32
3. Wait for 5~10 minutes, power on ESP32
If ESP32 can connect to hotspot, it means your issue is same as what I'm talking about.

[jcsbanks]

liuzhifu,you are spot on

If I can help to test a fix where this problem is repeatable, I am happy to do so.

[wolsty7]

I'm having the same problem, i'm using a oneplus 6 running android 9, is there anyway to fix the problem in the short term?

[Ritesh]

Enabled some wifi debugging logging:

Code: Select all

I (5526) wifi: ap found, mac=cc:9f:7a:9d:6a:19
I (5530) wifi: bssid=cc:9f:7a:9d:6a:19, LR=0
I (5534) wifi: new_bss=0x3ffb3e90, cur_bss=0x0, new_chan=<6,0>, cur_chan=6
I (5541) wifi: filter: set rx policy=5
I (5544) wifi: new:<6,0>, old:<6,0>, ap:<255,255>, sta:<6,0>, prof:1
I (5550) wifi: connect_op: status=0, auth=5, cipher=3
I (5555) wifi: auth mode is not none
I (5559) wifi: connect_bss: auth=1, reconnect=0
I (5563) wifi: state: init -> auth (b0)
I (5566) wifi: start 1s AUTH timer
I (5569) wifi: clear scan ap list
I (6570) wifi: auth timeout
I (6570) wifi: state: auth -> init (200)
I (6570) wifi: connect step 1 -> 4, status=1, err_time=1
I (6570) wifi: stop beacon/connect timer
I (6573) wifi: reason: auth expire(2)

Hi, Did you enable WiFi debug logs more from wifi header files or any other way?

[Ritesh]

liuzhifu,you are spot on

If I can help to test a fix where this problem is repeatable, I am happy to do so.

Hi,

Would you please describe issue in details like what you are doing and what issue you are facing? also issue has been resolved or still looking for solution?

[jcsbanks]

Ritesh, WiFi debug logging was enabled through menuconfig, sorry not near computer to remember exact name for the next few days.

We are 1 week into the 2 week estimate that liuzhifu provided to wait for a fix, I have not seen anything to test yet.