espressif / esp-idf

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

WiFi AP max stations already connected #2357

Closed michprev closed 6 years ago

michprev commented 6 years ago

Environment

Problem Description

I am unable to connect to ESP AP with my laptop with error message wifi: max stations already connected to ap! <station>e8:2a:44:6f:60:01, AID = 0 (e8:2a:44:6f:60:01 is MAC of my laptop) while Android phone connects without a problem (f4:f5:db:c4:c8:7d MAC of Android phone).

First I have been using

wifi_config_t wifi_config;
wifi_config.ap.authmode = WIFI_AUTH_WPA_WPA2_PSK;
wifi_config.ap.beacon_interval = 100;
wifi_config.ap.channel = 7;
wifi_config.ap.max_connection = 1;

Then I changed wifi_config.ap.max_connection to 4 but the problem still persisted => resetting the chip did not help. After running make erase_flash and reflashing the app the problem disappeared.

Debug Logs

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:2
load:0x3fff0018,len:4
load:0x3fff001c,len:5824
ho 0 tail 12 room 4
load:0x40078000,len:9020
load:0x40080000,len:6120
0x40080000: _iram_start at /home/michal/git/esp-idf/components/freertos/xtensa_vectors.S:1687

entry 0x40080334
0x40080334: _KernelExceptionVector at ??:?

I (30) boot: ESP-IDF v3.1-rc1-149-g22da5f6de-dirty 2nd stage bootloader
I (30) boot: compile time 00:04:12
I (31) boot: Enabling RNG early entropy source...
I (37) boot: SPI Speed      : 40MHz
I (41) boot: SPI Mode       : DIO
I (45) boot: SPI Flash Size : 4MB
I (49) boot: Partition Table:
I (52) boot: ## Label            Usage          Type ST Offset   Length
I (60) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (67) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (75) boot:  2 factory          factory app      00 00 00010000 00100000
I (82) boot:  3 coredump         Unknown data     01 03 00110000 0001e000
I (90) boot:  4 log_storage      unknown          40 40 0012e000 00200000
I (97) boot: End of partition table
I (101) esp_image: segment 0: paddr=0x00010020 vaddr=0x3f400020 size=0x19f34 (106292) map
I (148) esp_image: segment 1: paddr=0x00029f5c vaddr=0x3ffb0000 size=0x034dc ( 13532) load
I (153) esp_image: segment 2: paddr=0x0002d440 vaddr=0x3ffb34dc size=0x00000 (     0) load
I (154) esp_image: segment 3: paddr=0x0002d448 vaddr=0x40080000 size=0x00400 (  1024) load
0x40080000: _iram_start at /home/michal/git/esp-idf/components/freertos/xtensa_vectors.S:1687

I (164) esp_image: segment 4: paddr=0x0002d850 vaddr=0x40080400 size=0x027c0 ( 10176) load
I (176) esp_image: segment 5: paddr=0x00030018 vaddr=0x400d0018 size=0x70230 (459312) map
0x400d0018: _stext at ??:?

I (342) esp_image: segment 6: paddr=0x000a0250 vaddr=0x40082bc0 size=0x0f684 ( 63108) load
0x40082bc0: esp_log_write at /home/michal/git/esp-idf/components/log/log.c:121

I (368) esp_image: segment 7: paddr=0x000af8dc vaddr=0x400c0000 size=0x00000 (     0) load
I (369) esp_image: segment 8: paddr=0x000af8e4 vaddr=0x50000000 size=0x00000 (     0) load
I (386) boot: Loaded app from partition at offset 0x10000
I (386) boot: Disabling RNG early entropy source...
I (387) cpu_start: Pro cpu up.
I (390) cpu_start: Starting app cpu, entry point is 0x400810a4
0x400810a4: call_start_cpu1 at /home/michal/git/esp-idf/components/esp32/cpu_start.c:225

I (0) cpu_start: App cpu up.
I (401) heap_init: Initializing. RAM available for dynamic allocation:
D (408) heap_init: New heap initialised at 0x3ffae6e0
I (413) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM
D (419) heap_init: New heap initialised at 0x3ffb9f80
I (424) heap_init: At 3FFB9F80 len 00026080 (152 KiB): DRAM
I (430) heap_init: At 3FFE0440 len 00003BC0 (14 KiB): D/IRAM
I (437) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
D (443) heap_init: New heap initialised at 0x40092244
I (448) heap_init: At 40092244 len 0000DDBC (55 KiB): IRAM
I (454) cpu_start: Pro cpu start user code
D (467) clk: RTC_SLOW_CLK calibration value: 3630157
D (28) intr_alloc: Connected src 46 to int 2 (cpu 0)
D (29) intr_alloc: Connected src 57 to int 3 (cpu 0)
D (29) intr_alloc: Connected src 24 to int 9 (cpu 0)
I (34) cpu_start: Starting scheduler on PRO CPU.
D (0) intr_alloc: Connected src 25 to int 2 (cpu 1)
I (4) cpu_start: Starting scheduler on APP CPU.
D (58) heap_init: New heap initialised at 0x3ffe0440
D (64) heap_init: New heap initialised at 0x3ffe4350
D (69) nvs: nvs_flash_init_custom partition=nvs start=9 count=6
D (92) intr_alloc: Connected src 22 to int 23 (cpu 1)
I (1092) gpio: GPIO[2]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 
I (1092) gpio: GPIO[33]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 
D (1100) intr_alloc: Connected src 49 to int 12 (cpu 0)
D (1105) spi: SPI1 use gpio matrix.
D (1109) intr_alloc: Connected src 30 to int 12 (cpu 0)
D (1114) spi_master: eff: 1000, limit: 26666k(/2), 0 dummy, -1 delay
D (1120) spi_master: SPI1: New device added to CS0, effective clock: 1000kHz
I (1127) gpio: GPIO[13]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 
D (1137) spi_master: eff: 1000, limit: 26666k(/2), 0 dummy, -1 delay
D (1143) spi_master: SPI1: New device added to CS0, effective clock: 1000kHz
I (1150) gpio: GPIO[13]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 
D (1160) spi_master: eff: 1000, limit: 26666k(/2), 0 dummy, -1 delay
D (1166) spi_master: SPI1: New device added to CS0, effective clock: 1000kHz
I (1173) gpio: GPIO[17]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 
I (1182) gpio: GPIO[5]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 
I (1192) gpio: GPIO[16]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 
I (1201) gpio: GPIO[18]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 
D (1211) spi: SPI1 use gpio matrix.
D (1214) intr_alloc: Connected src 30 to int 12 (cpu 0)
D (1219) spi_master: eff: 1000, limit: 26666k(/2), 0 dummy, -1 delay
D (1226) spi_master: SPI1: New device added to CS0, effective clock: 1000kHz
I (1233) gpio: GPIO[4]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:1 
D (1444) nvs: nvs_open_from_partition misc 1
D (1444) nvs: nvs_get_str_or_blob log
I (1445) wifi: wifi driver task: 3ffc3418, prio:23, stack:3584, core=0
I (1447) wifi: wifi firmware version: 54ef8ed
I (1451) wifi: config NVS flash: enabled
I (1455) wifi: config nano formating: disabled
I (1459) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
I (1469) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
D (1479) nvs: nvs_open_from_partition nvs.net80211 1
D (1484) nvs: nvs_get opmode 1
D (1487) nvs: nvs_get_str_or_blob sta.ssid
D (1491) nvs: nvs_get_str_or_blob sta.mac
D (1495) nvs: nvs_get sta.authmode 1
D (1499) nvs: nvs_get_str_or_blob sta.pswd
D (1503) nvs: nvs_get_str_or_blob sta.pmk
D (1507) nvs: nvs_get sta.chan 1
D (1510) nvs: nvs_get auto.conn 1
D (1514) nvs: nvs_get bssid.set 1
D (1517) nvs: nvs_get_str_or_blob sta.bssid
D (1521) nvs: nvs_get sta.lis_intval 2
D (1525) nvs: nvs_get sta.phym 1
D (1528) nvs: nvs_get sta.phybw 1
D (1532) nvs: nvs_get_str_or_blob sta.apsw
D (1536) nvs: nvs_get_str_or_blob sta.apinfo
D (1542) nvs: nvs_get sta.scan_method 1
D (1544) nvs: nvs_get sta.sort_method 1
D (1548) nvs: nvs_get sta.minrssi 1
D (1552) nvs: nvs_get sta.minauth 1
D (1555) nvs: nvs_get_str_or_blob ap.ssid
D (1560) nvs: nvs_get_str_or_blob ap.mac
D (1563) nvs: nvs_get_str_or_blob ap.passwd
D (1568) nvs: nvs_get_str_or_blob ap.pmk
D (1572) nvs: nvs_get ap.chan 1
D (1575) nvs: nvs_get ap.authmode 1
D (1578) nvs: nvs_get ap.hidden 1
D (1582) nvs: nvs_get ap.max.conn 1
D (1585) nvs: nvs_get bcn.interval 2
D (1589) nvs: nvs_get ap.phym 1
D (1592) nvs: nvs_get ap.phybw 1
D (1595) nvs: nvs_get ap.sndchan 1
D (1599) nvs: nvs_get lorate 1
D (1602) nvs: nvs_set_blob sta.mac 6
D (1607) nvs: nvs_set_blob ap.mac 6
I (1610) wifi: Init dynamic tx buffer num: 32
I (1613) wifi: Init data frame dynamic rx buffer num: 32
I (1618) wifi: Init management frame dynamic rx buffer num: 32
I (1624) wifi: Init static rx buffer size: 1600
I (1628) wifi: Init static rx buffer num: 10
I (1632) wifi: Init dynamic rx buffer num: 32
D (1637) nvs: nvs_set_blob ap.ssid 36
D (1641) nvs: nvs_set_blob ap.passwd 65
D (1645) nvs: nvs_set ap.authmode 1 4
D (1648) nvs: nvs_set ap.chan 1 7
D (1651) nvs: nvs_set ap.hidden 1 0
D (1655) nvs: nvs_set ap.max.conn 1 4
D (1659) nvs: nvs_set bcn.interval 2 100
D (2319) nvs: nvs_set_blob ap.pmk 32
D (2321) RTC_MODULE: Wi-Fi takes adc2 lock.
D (2321) phy_init: loading PHY init data from application binary
D (2322) nvs: nvs_open_from_partition phy 0
D (2327) nvs: nvs_get cal_version 4
D (2330) nvs: nvs_get_str_or_blob cal_mac
D (2335) nvs: nvs_get_str_or_blob cal_data
D (2342) nvs: nvs_close 3
I (2398) phy: phy_version: 3960, 5211945, Jul 18 2018, 10:40:07, 0, 0
I (2399) wifi: mode : softAP (30:ae:a4:0a:c2:4d)
D (2403) event: SYSTEM_EVENT_AP_START
D (2405) tcpip_adapter: dhcp server start:(ip: 192.168.4.1, mask: 255.255.255.0, gw: 192.168.4.1)
I (34626) wifi: max stations already connected to ap! <station>e8:2a:44:6f:60:01, AID = 0
I (47158) wifi: n:7 0, o:7 0, ap:7 1, sta:255 255, prof:7
I (47159) wifi: station: f4:f5:db:c4:c8:7d join, AID=1, bgn, 20
D (47163) event: SYSTEM_EVENT_AP_STACONNECTED, mac:f4:f5:db:c4:c8:7d, aid:1
I (47540) tcpip_adapter: softAP assign IP to station,IP is: 192.168.4.2
D (47541) event: SYSTEM_EVENT_AP_STAIPASSIGNED
I (51994) wifi: station: f4:f5:db:c4:c8:7d leave, AID = 1
I (51995) wifi: n:7 0, o:7 0, ap:7 1, sta:255 255, prof:7
D (51995) event: SYSTEM_EVENT_AP_STADISCONNECTED, mac:f4:f5:db:c4:c8:7d, aid:1
I (71058) wifi: max stations already connected to ap! <station>e8:2a:44:6f:60:01, AID = 0
I (80602) wifi: max stations already connected to ap! <station>e8:2a:44:6f:60:01, AID = 0
I (86626) wifi: max stations already connected to ap! <station>e8:2a:44:6f:60:01, AID = 0
I (95948) wifi: n:7 0, o:7 0, ap:7 1, sta:255 255, prof:7
I (95949) wifi: station: f4:f5:db:c4:c8:7d join, AID=1, bgn, 20
D (95951) event: SYSTEM_EVENT_AP_STACONNECTED, mac:f4:f5:db:c4:c8:7d, aid:1
I (96463) tcpip_adapter: softAP assign IP to station,IP is: 192.168.4.2
D (96464) event: SYSTEM_EVENT_AP_STAIPASSIGNED
I (100600) wifi: station: f4:f5:db:c4:c8:7d leave, AID = 1
I (100601) wifi: n:7 0, o:7 0, ap:7 1, sta:255 255, prof:7
D (100601) event: SYSTEM_EVENT_AP_STADISCONNECTED, mac:f4:f5:db:c4:c8:7d, aid:1
I (172692) wifi: max stations already connected to ap! <station>e8:2a:44:6f:60:01, AID = 0
I (182638) wifi: max stations already connected to ap! <station>e8:2a:44:6f:60:01, AID = 0
I (200028) wifi: n:7 0, o:7 0, ap:7 1, sta:255 255, prof:7
I (200029) wifi: station: f4:f5:db:c4:c8:7d join, AID=1, bgn, 20
D (200031) event: SYSTEM_EVENT_AP_STACONNECTED, mac:f4:f5:db:c4:c8:7d, aid:1
I (200409) tcpip_adapter: softAP assign IP to station,IP is: 192.168.4.2
D (200410) event: SYSTEM_EVENT_AP_STAIPASSIGNED
I (203071) wifi: station: f4:f5:db:c4:c8:7d leave, AID = 1
I (203072) wifi: n:7 0, o:7 0, ap:7 1, sta:255 255, prof:7
D (203073) event: SYSTEM_EVENT_AP_STADISCONNECTED, mac:f4:f5:db:c4:c8:7d, aid:1
negativekelvin commented 6 years ago

If you are not going to set all values you should wifi_config_t wifi_config = { 0 };

What happens if you reboot does (1582) nvs: nvs_get ap.max.conn 1 change to 4

stickbreaker commented 6 years ago

as @negativekelvin says, the error message:

I (172692) wifi: max stations already connected to ap! e8:2a:44:6f:60:01, AID = 0

is telling the truth.

You have Wifi AP configured for only 1 connection. and your cellphone is first in line.

Chuck.

negativekelvin commented 6 years ago

No it is definitely weird because "max stations" comes at 34s but SYSTEM_EVENT_AP_STACONNECTED does not come until 47s. Then even after SYSTEM_EVENT_AP_STADISCONNECTED there is no free slot. You should check esp_wifi_ap_get_sta_list().

michprev commented 6 years ago

If you are not going to set all values you should wifi_config_t wifi_config = { 0 };

Whoops, I did not post the whole code.

    wifi_config_t wifi_config;
    wifi_config.ap.authmode = WIFI_AUTH_WPA_WPA2_PSK;
    wifi_config.ap.beacon_interval = 100;
    wifi_config.ap.channel = 7;
    wifi_config.ap.max_connection = 4;

    std::strcpy((char *) wifi_config.ap.password, CONFIG_FLYHERO_WIFI_WPA2_PASSPHRASE);
    std::strcpy((char *) wifi_config.ap.ssid, CONFIG_FLYHERO_WIFI_SSID);
    wifi_config.ap.ssid_hidden = !CONFIG_FLYHERO_WIFI_SSID_VISIBLE;
    wifi_config.ap.ssid_len = 0;

You should check esp_wifi_ap_get_sta_list()

I have modified the app to print num of stations every 500 ms. WIth the same app I managed to connect with my phone and tablet without a problem (num of stations 2).

I (2556) wifi: mode : softAP (30:ae:a4:0a:c2:4d)
D (2560) event: SYSTEM_EVENT_AP_START
V (2560) event: enter default callback
V (2562) tcpip_adapter: check: local, if=1 fn=0x40137ff0
0x40137ff0: tcpip_adapter_start_api at /home/michal/git/esp-idf/components/tcpip_adapter/tcpip_adapter_lwip.c:1082

D (2569) tcpip_adapter: dhcp server start:(ip: 192.168.4.1, mask: 255.255.255.0, gw: 192.168.4.1)
V (2576) tcpip_adapter: call api in lwip: ret=0x0, give sem
V (2582) tcpip_adapter: check: remote, if=1 fn=0x40137ff0
0x40137ff0: tcpip_adapter_start_api at /home/michal/git/esp-idf/components/tcpip_adapter/tcpip_adapter_lwip.c:1082

V (2588) event: exit default callback
num of stations 0
num of stations 0
num of stations 0
num of stations 0
num of stations 0
num of stations 0
num of stations 0
num of stations 0
num of stations 0
num of stations 0
num of stations 0
num of stations 0
num of stations 0
num of stations 0
num of stations 1
num of stations 1
num of stations 1
num of stations 1
num of stations 1
num of stations 1
num of stations 1
num of stations 1
num of stations 1
num of stations 1
I (28274) wifi: max stations already connected to ap! <station>e8:2a:44:6f:60:01, AID = 0
num of stations 0
num of stations 0
num of stations 0
num of stations 0
num of stations 0
num of stations 0
num of stations 0
num of stations 0
num of stations 0
num of stations 1
num of stations 1
num of stations 1
num of stations 1
num of stations 1
num of stations 1
num of stations 1
num of stations 1
num of stations 1
num of stations 1
I (37819) wifi: max stations already connected to ap! <station>e8:2a:44:6f:60:01, AID = 0
num of stations 0
num of stations 0
num of stations 0
num of stations 0
num of stations 0
num of stations 0
num of stations 0
num of stations 0
num of stations 0
num of stations 0
num of stations 1
num of stations 1
I (43665) wifi: max stations already connected to ap! <station>e8:2a:44:6f:60:01, AID = 0
num of stations 0
num of stations 0
num of stations 0
num of stations 0
num of stations 0
num of stations 0
num of stations 0
num of stations 0
num of stations 0
num of stations 0
num of stations 0

EDIT: The problem does not exist on the same laptop on Win 10. Also erasing ESP flash does not help anymore.

This appeared in my dmesg log after unsuccessfull connection to ESP:

[  805.521802] wlp3s0: authenticate with 30:ae:a4:0a:c2:4d
[  805.551588] wlp3s0: send auth to 30:ae:a4:0a:c2:4d (try 1/3)
[  805.553497] wlp3s0: authenticated
[  807.004842] wlp3s0: aborting authentication with 30:ae:a4:0a:c2:4d by local choice (Reason: 3=DEAUTH_LEAVING)

I would say that I have problems with my Qualcomm Atheros QCA9377 driver but I don't quite understand why ESP claims that max stations are already connected.

negativekelvin commented 6 years ago

Set your log level to debug

michprev commented 6 years ago

Set your log level to debug

On ESP? I have set it to verbose.

negativekelvin commented 6 years ago

Oh ok sorry. That is weird that num of stations 1 without any events. Something your WiFi driver on Debian is doing that confuses esp32, not sure which has the bug.

negativekelvin commented 6 years ago

https://unix.stackexchange.com/questions/386925/aborting-authentication-by-local-choice-reason-3-deauth-leaving-when-trying

michprev commented 6 years ago

Reinstalling Network Manager on my system made this issue appear less often. I strongly believe that the problem is on my system rather than on ESP.