WiFi with automatic light sleep

[maleadt]

Hi all,

I was trying out the wifi/powersave example from the ESP-IDF master branch, but am running into a problem where I get disconnected after a while (seconds to minutes) without being able to reconnect. Boot log ending with the disconnect events:

Code: Select all

]
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:5752
load:0x40078000,len:7684
load:0x40080000,len:7392
0x40080000: _iram_start at /home/tim/Projects/2018/ESP32/sdk/components/freertos/xtensa_vectors.S:1685

entry 0x4008039c
0x4008039c: _UserExceptionVector at ??:?

I (28) boot: ESP-IDF v3.2-dev-57-ge75628b4 2nd stage bootloader
I (28) boot: compile time 21:00:01
I (28) boot: Enabling RNG early entropy source...
I (34) boot: SPI Speed      : 40MHz
I (38) boot: SPI Mode       : DIO
I (42) boot: SPI Flash Size : 4MB
I (46) boot: Partition Table:
I (50) boot: ## Label            Usage          Type ST Offset   Length
I (57) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (65) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (72) boot:  2 factory          factory app      00 00 00010000 00100000
I (80) boot: End of partition table
I (84) esp_image: segment 0: paddr=0x00010020 vaddr=0x3f400020 size=0x13964 ( 80228) map
I (121) esp_image: segment 1: paddr=0x0002398c vaddr=0x3ffb0000 size=0x03a5c ( 14940) load
I (127) esp_image: segment 2: paddr=0x000273f0 vaddr=0x3ffb3a5c size=0x00000 (     0) load
I (127) esp_image: segment 3: paddr=0x000273f8 vaddr=0x40080000 size=0x00400 (  1024) load
0x40080000: _iram_start at /home/tim/Projects/2018/ESP32/sdk/components/freertos/xtensa_vectors.S:1685

I (137) esp_image: segment 4: paddr=0x00027800 vaddr=0x40080400 size=0x08810 ( 34832) load
I (160) esp_image: segment 5: paddr=0x00030018 vaddr=0x400d0018 size=0x66f58 (421720) map
0x400d0018: _stext at ??:?

I (308) esp_image: segment 6: paddr=0x00096f78 vaddr=0x40088c10 size=0x08ac4 ( 35524) load
0x40088c10: rcGetSched at ??:?

I (323) esp_image: segment 7: paddr=0x0009fa44 vaddr=0x400c0000 size=0x00064 (   100) load
I (323) esp_image: segment 8: paddr=0x0009fab0 vaddr=0x50000000 size=0x00000 (     0) load
I (340) boot: Loaded app from partition at offset 0x10000
I (340) boot: Disabling RNG early entropy source...
I (341) cpu_start: Pro cpu up.
I (345) cpu_start: Starting app cpu, entry point is 0x4008114c
0x4008114c: call_start_cpu1 at /home/tim/Projects/2018/ESP32/sdk/components/esp32/cpu_start.c:225

I (0) cpu_start: App cpu up.
I (355) heap_init: Initializing. RAM available for dynamic allocation:
I (362) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM
I (368) heap_init: At 3FFBA100 len 00025F00 (151 KiB): DRAM
I (374) heap_init: At 3FFE0440 len 00003BC0 (14 KiB): D/IRAM
I (381) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (387) heap_init: At 400916D4 len 0000E92C (58 KiB): IRAM
I (393) cpu_start: Pro cpu start user code
I (412) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (414) application: application starting up
I (414) application: free memory: 269480 bytes
I (414) application: IDF version: v3.2-dev-57-ge75628b4
I (464) pm_esp32: Frequency switching config: CPU_MAX: 80, APB_MAX: 80, APB_MIN: XTAL, Light sleep: ENABLED
I (474) wifi: wifi driver task: 3ffc16f4, prio:23, stack:4096, core=0
I (474) wifi: wifi firmware version: a7a46e9
I (474) wifi: config NVS flash: enabled
I (474) wifi: config nano formating: disabled
I (484) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
I (494) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
I (534) wifi: Init dynamic tx buffer num: 32
I (534) wifi: Init data frame dynamic rx buffer num: 32
I (534) wifi: Init management frame dynamic rx buffer num: 32
I (534) wifi: Init static rx buffer size: 1600
I (534) wifi: Init static rx buffer num: 10
I (544) wifi: Init dynamic rx buffer num: 32
I (594) wifi: Set ps type: 2

I (674) phy: phy_version: 3910, c0c45a3, May 21 2018, 18:07:06, 0, 0
I (674) wifi: mode : sta (b4:e6:2d:b1:aa:21)
I (674) application: waiting for WiFi connection
I (674) application: SYSTEM_EVENT_STA_START
I (804) wifi: n:6 0, o:1 0, ap:255 255, sta:6 0, prof:1
I (2764) wifi: state: init -> auth (b0)
I (2774) wifi: state: auth -> assoc (0)
I (2784) wifi: state: assoc -> run (10)
I (2804) wifi: connected with Planet Internet, channel 6
I (2814) wifi: pm start, type: 2

I (5094) event: sta ip: 192.168.0.143, mask: 255.255.255.0, gw: 192.168.0.1
I (5094) application: SYSTEM_EVENT_STA_GOT_IP
I (5094) application: got IPv4 address 192.168.0.143
I (5104) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
I (13004) wifi: bcn_timout,ap_probe_send_start
I (15514) wifi: ap_probe_send over, resett wifi status to disassoc
I (15514) wifi: state: run -> init (1)
I (15514) wifi: pm stop, total sleep time: 3284901 us / 12429939 us

I (15514) wifi: n:6 0, o:6 0, ap:255 255, sta:6 0, prof:1
I (15524) application: SYSTEM_EVENT_STA_DISCONNECTED
I (17954) application: SYSTEM_EVENT_STA_DISCONNECTED
I (20364) application: SYSTEM_EVENT_STA_DISCONNECTED
I (22784) application: SYSTEM_EVENT_STA_DISCONNECTED
I (25204) application: SYSTEM_EVENT_STA_DISCONNECTED
I (27624) application: SYSTEM_EVENT_STA_DISCONNECTED
I (30034) application: SYSTEM_EVENT_STA_DISCONNECTED
I (32454) application: SYSTEM_EVENT_STA_DISCONNECTED

Upon SYSTEM_EVENT_STA_DISCONNECTED, my wifi event handler should call esp_wifi_connect (which succeeds) but doesn't manage to reconnect (something that _does_ work if not using automatic light sleep, tested by forcing a disconnect). Disabling the automatic light sleep makes the example work, ie. other PM features (DFS from 40mhz-80mhz, esp_wifi_set_ps(WIFI_PS_MAX_MODEM)) do seem to work.

I'm new to ESP32 development, so I'm not sure how to debug this. Automatic light sleep looks like a new feature, so maybe it's just unstable? Although I couldn't find other issues to confirm that.

[hassan789]

1. can you post the disconnect reason? "event->event_info.disconnected.reason"
2. What RSSI are you at when this happens?

[maleadt]

Initial disconnect reason is 200, subsequent "disconnects" have reason 201. RSSI is around 75 (-66 dBm according to AP).

Code: Select all

I (534) wifi: Init dynamic tx buffer num: 32
I (534) wifi: Init data frame dynamic rx buffer num: 32
I (534) wifi: Init management frame dynamic rx buffer num: 32
I (534) wifi: Init static rx buffer size: 1600
I (534) wifi: Init static rx buffer num: 10
I (544) wifi: Init dynamic rx buffer num: 32
I (594) wifi: Set ps type: 2

I (664) phy: phy_version: 3910, c0c45a3, May 21 2018, 18:07:06, 0, 0
I (674) wifi: mode : sta (b4:e6:2d:b1:aa:21)
I (674) application: waiting for WiFi connection
I (674) application: SYSTEM_EVENT_STA_START
I (804) wifi: n:6 0, o:1 0, ap:255 255, sta:6 0, prof:1
I (2764) wifi: state: init -> auth (b0)
I (2774) wifi: state: auth -> assoc (0)
I (2794) wifi: state: assoc -> run (10)
I (2804) wifi: connected with Planet Internet, channel 6
I (2814) wifi: pm start, type: 2

I (7784) event: sta ip: 192.168.0.143, mask: 255.255.255.0, gw: 192.168.0.1
I (7784) application: SYSTEM_EVENT_STA_GOT_IP
I (7784) application: got IPv4 address 192.168.0.143
I (7794) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
I (8804) application: WiFi RSSI: -75
I (9804) application: WiFi RSSI: -73
...
I (49074) wifi: bcn_timout,ap_probe_send_start
I (50024) application: WiFi RSSI: -75
I (51024) application: WiFi RSSI: -75
I (51584) wifi: ap_probe_send over, resett wifi status to disassoc
I (51584) wifi: state: run -> init (1)
I (51584) wifi: pm stop, total sleep time: 34481106 us / 45676218 us

I (51584) wifi: n:6 0, o:6 0, ap:255 255, sta:6 0, prof:1
I (51594) application: SYSTEM_EVENT_STA_DISCONNECTED
I (51594) application: disconnect reason 200
W (52024) wifi: Haven't to connect to a suitable AP now!
W (53024) wifi: Haven't to connect to a suitable AP now!
W (54024) wifi: Haven't to connect to a suitable AP now!
I (54024) application: SYSTEM_EVENT_STA_DISCONNECTED
I (54024) application: disconnect reason 201
W (55024) wifi: Haven't to connect to a suitable AP now!
W (56024) wifi: Haven't to connect to a suitable AP now!
I (56444) application: SYSTEM_EVENT_STA_DISCONNECTED
I (56444) application: disconnect reason 201
W (57024) wifi: Haven't to connect to a suitable AP now!
W (58024) wifi: Haven't to connect to a suitable AP now!
I (58864) application: SYSTEM_EVENT_STA_DISCONNECTED
I (58864) application: disconnect reason 201
W (59024) wifi: Haven't to connect to a suitable AP now!
W (60024) wifi: Haven't to connect to a suitable AP now!
W (61024) wifi: Haven't to connect to a suitable AP now!

[hassan789]

looks like you are getting a beacon timeout from the AP. Issue seems to be with your AP.
more details here: https://esp-idf.readthedocs.io/en/v3.1- ... eason-code

You can try these things:
1. check to make sure the beacon TIM interval is 100ms on your router/AP
2. Try a different router/AP
3. put the ESP in promiscuous mode and see what the TIM, and beacon interval manually.

[maleadt]

What about the subsequent NO_AP_FOUND errors? I'm using Ubiquiti hardware, beacon interval is set to 100ms already. I'll try to verify in promiscuous mode.

[swtih1997]

Has anyone made on progress on this? I am having the same issue and it is driving my crazy. I have updated to the latest IDF release v3.0.2 with the same performance.

[hassan789]

Just an idea,
is your ssid broadcast set to 1mbps mode? if not, I have had some issues.. if you can't tell from your router, you can check via wireshark wifi adapter OR you can put the ESP in promiscuous mode and inspect the packet.

[maleadt]

1mbps beacons are pretty common, right? Anyway, I bumped them to 6mbps, but that didn't change anything:

Code: Select all

I (739) phy: phy_version: 3960, 5211945, Jul 18 2018, 10:40:07, 0, 0
I (739) wifi: mode : sta (b4:e6:2d:b1:aa:21)
I (749) application: waiting for WiFi connection
I (749) application: SYSTEM_EVENT_STA_START
I (879) wifi: n:6 0, o:1 0, ap:255 255, sta:6 0, prof:1
I (2839) wifi: state: init -> auth (b0)
I (2849) wifi: state: auth -> assoc (0)
I (2859) wifi: state: assoc -> run (10)
I (2879) wifi: connected with Planet Internet, channel 6
I (2889) wifi: pm start, type: 2

I (2889) application: SYSTEM_EVENT_STA_CONNECTED
I (4589) event: sta ip: 192.168.0.143, mask: 255.255.255.0, gw: 192.168.0.1
I (4589) application: SYSTEM_EVENT_STA_GOT_IP
I (4589) application: got IPv4 address 192.168.0.143
I (4599) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
I (391399) wifi: bcn_timout,ap_probe_send_start
I (393909) wifi: ap_probe_send over, resett wifi status to disassoc
I (393909) wifi: state: run -> init (100)
I (393909) wifi: pm stop, total sleep time: 337756038 us / 357807209 us

I (393909) wifi: n:6 0, o:6 0, ap:255 255, sta:6 0, prof:1
I (393919) application: SYSTEM_EVENT_STA_DISCONNECTED (reason 200)
W (395339) wifi: Haven't to connect to a suitable AP now!
I (396339) application: SYSTEM_EVENT_STA_DISCONNECTED (reason 201)
I (398749) application: SYSTEM_EVENT_STA_DISCONNECTED (reason 201)
W (400339) wifi: Haven't to connect to a suitable AP now!
I (401169) application: SYSTEM_EVENT_STA_DISCONNECTED (reason 201)
I (403579) application: SYSTEM_EVENT_STA_DISCONNECTED (reason 201)
W (405339) wifi: Haven't to connect to a suitable AP now!
I (405999) application: SYSTEM_EVENT_STA_DISCONNECTED (reason 201)

Notice the failure to reconnect. This looks like more than just a disconnect after a missed beacon? Sometimes (once every 25 attempts), the connection attempt gets a little further, but never ends up succeeding:

Code: Select all

I (497709) application: SYSTEM_EVENT_STA_DISCONNECTED (reason 201)
I (499039) wifi: n:11 0, o:11 0, ap:255 255, sta:11 0, prof:1
I (499039) wifi: state: init -> auth (b0)
I (500049) wifi: state: auth -> init (200)
I (500049) wifi: n:11 0, o:11 0, ap:255 255, sta:11 0, prof:1
I (500049) application: SYSTEM_EVENT_STA_DISCONNECTED (reason 2)
W (500339) wifi: Haven't to connect to a suitable AP now!
I (502469) application: SYSTEM_EVENT_STA_DISCONNECTED (reason 201)

[hassan789]

Can you confirm your APs TIM interval?

[maleadt]

Yes, beacons are coming in at 100ms intervals, but upon closer inspection the ESP's loss of connectivity coincides with a ~4s gap without beacons. So this looks like a legitimate AP issue indeed.
Nonetheless, it works without automatic sleep, and I can't seem to reconnect either. My event handler is pretty simple, taking from the examples, calling esp_wifi_connect() upon disconnect. Am I doing something wrong?

Code: Select all

static esp_err_t wifi_event_handler(void *ctx, system_event_t *event) {
    switch (event->event_id) {
    case SYSTEM_EVENT_STA_START:
        ESP_LOGI(TAG, "SYSTEM_EVENT_STA_START");
        ESP_ERROR_CHECK(
            tcpip_adapter_set_hostname(TCPIP_ADAPTER_IF_STA, HOSTNAME));
        ESP_ERROR_CHECK(esp_wifi_connect());
        break;
    case SYSTEM_EVENT_STA_CONNECTED:
        ESP_LOGI(TAG, "SYSTEM_EVENT_STA_CONNECTED (channel %d)",
                 event->event_info.connected.channel);
        break;
    case SYSTEM_EVENT_STA_GOT_IP:
        ESP_LOGI(TAG, "SYSTEM_EVENT_STA_GOT_IP");
        ESP_LOGI(TAG, "got IPv4 address %s",
                 ip4addr_ntoa(&event->event_info.got_ip.ip_info.ip));
        xEventGroupSetBits(wifi_event_group, WIFI_CONNECTED_BIT);
        break;
    case SYSTEM_EVENT_STA_DISCONNECTED:
        ESP_LOGI(TAG, "SYSTEM_EVENT_STA_DISCONNECTED (reason %d)",
                 event->event_info.disconnected.reason);
        ESP_ERROR_CHECK(esp_wifi_connect());
        xEventGroupClearBits(wifi_event_group, WIFI_CONNECTED_BIT);
        break;
    default:
        break;
    }
    return ESP_OK;
}

Tried to do the reconnect from another thread, as mentioned in https://github.com/espressif/esp-idf/is ... -311626685, but that didn't help.