WiFi disconnections (IDFGH-204)

[rojer]

Sometimes we get wifi disconnects in our tests, after which it is unable to reconnect:

first connection is successful:

I (2660) wifi: n:10 0, o:1 0, ap:255 255, sta:10 0, prof:1
I (3510) wifi: state: init -> auth (b0)
I (3510) wifi: state: auth -> assoc (0)
mongoose_poll        New heap free LWM: 68160
I (3520) wifi: state: assoc -> run (10)
I (3570) wifi: connected with Cesanta, channel 10
mgos_net_on_change_c WiFi STA: connected
mgos_event_trigger   ev NET2 triggered 3 handlers
I (4250) event: sta ip: 192.168.1.22, mask: 255.255.255.0, gw: 192.168.1.1

but after a few seconds it disconnects and never recovers:

I (6530) wifi: pm start, type:0

mgos_sntp_retry      SNTP next query in 4200 ms
I (11480) wifi: bcn_timout,ap_probe_send_start
mgos_sntp_retry      SNTP next query in 8769 ms
I (13990) wifi: ap_probe_send over, resett wifi status to disassoc
I (13990) wifi: state: run -> init (1)
I (14000) wifi: n:10 0, o:10 0, ap:255 255, sta:10 0, prof:1
I (14000) wifi: pm stop, total sleep time: 0/7471504

esp32_wifi_ev        Disconnected from Cesanta, reason: 200
mgos_net_on_change_c WiFi STA: disconnected
mgos_event_trigger   ev NET0 triggered 3 handlers
mgos_net_on_change_c WiFi STA: connecting
mgos_event_trigger   ev NET1 triggered 3 handlers
mg_resolve_async_eh  Failed to resolve 'time.google.com', server 192.168.1.1
mgos_sntp_ev         SNTP sent query to 0.0.0.0
mgos_sntp_ev         SNTP close
esp32_wifi_ev        Disconnected from Cesanta, reason: 201
mgos_net_on_change_c WiFi STA: disconnected
mgos_event_trigger   ev NET0 triggered 3 handlers
mgos_net_on_change_c WiFi STA: connecting
mgos_event_trigger   ev NET1 triggered 3 handlers
esp32_wifi_ev        Disconnected from Cesanta, reason: 201
mgos_net_on_change_c WiFi STA: disconnected
mgos_event_trigger   ev NET0 triggered 3 handlers
mgos_net_on_change_c WiFi STA: connecting
mgos_event_trigger   ev NET1 triggered 3 handlers
W (19710) wifi: alloc eb len=76 type=2 fail

W (19710) wifi: m f probe req l=0

W (19830) wifi: alloc eb len=76 type=2 fail

W (19840) wifi: m f probe req l=0

W (19960) wifi: alloc eb len=76 type=2 fail

W (19970) wifi: m f probe req l=0

W (20090) wifi: alloc eb len=76 type=2 fail

W (20090) wifi: m f probe req l=0

mgos_sntp_query      SNTP query to time.google.com
mgos_sntp_retry      SNTP next query in 16328 ms
mg_resolve_async_eh  Failed to resolve 'time.google.com', server 192.168.1.1
mgos_sntp_ev         SNTP sent query to 0.0.0.0
mgos_sntp_ev         SNTP close
esp32_wifi_ev        Disconnected from Cesanta, reason: 201
W (21310) wifi: alloc eb len=76 type=2 fail

W (21310) wifi: m f probe req l=0

mgos_net_on_change_c WiFi STA: disconnected
mgos_event_trigger   ev NET0 triggered 3 handlers
mgos_net_on_change_c WiFi STA: connecting
mgos_event_trigger   ev NET1 triggered 3 handlers
W (21440) wifi: alloc eb len=76 type=2 fail

W (21440) wifi: m f probe req l=0

W (21570) wifi: alloc eb len=76 type=2 fail

W (21570) wifi: m f probe req l=0

W (21690) wifi: alloc eb len=76 type=2 fail

W (21700) wifi: m f probe req l=0

W (21820) wifi: alloc eb len=76 type=2 fail

W (21830) wifi: m f probe req l=0

W (21950) wifi: alloc eb len=76 type=2 fail

W (21950) wifi: m f probe req l=0

W (22080) wifi: alloc eb len=76 type=2 fail
...

[TimXia]

@rojer How often did it happen? Could you provide a demo to reproduce it?

[rojer]

unfortunately, it only happens very infrequently and i cannot reproduce it at will. we have automated tests and sometimes one of them just fails with these messages in the log.

[TimXia]

@rojer Did you call esp_wifi_stop() in your code?

[rojer]

@TimXia no, this disconnection was not intentional

[TimXia]

@rojer Could you provide a demo which can reproduce the issue? We can not reproduece it in our test.

[PaladinEng]

I'm having this issue as well, but for me it's very consistent.
Here's the code:

main.txt

[TimXia]

@PaladinEng What is the commit ID of IDF you use? How often did it happen?

[PaladinEng]

The commit ID is: bd26045
It's happened to me pretty much every time I compile and flash. However, occassionally, it will run fine once, then the issue will resume.
I think the issue is related to this line:
xEventGroupClearBits(wifi_event_group, CONNECTED_BIT);
But I'm still testing that hypothesis.

[PaladinEng]

OK, the behavior is unrelated to
'xEventGroupClearBits(wifi_event_group, CONNECTED_BIT);'
And on many runs, I can't get an IP.

This code is basically identical to the template and the simple wifi example, so it really should be working.

[rojer]

@TimXia as i said, i cannot really reproduce it at will. it happens with the same code that works most of the time. my only hope was that the alloc error message will be enough for you to figure out what's going on. what i can say is that it's not heap memory shortage, there's plenty of heap available.

@PaladinEng can you confirm that you see alloc eb ... fail messages as well?

[TimXia]

@rojer It's hard to debug with the alloc error message. What's the commit ID of your IDF?

[rojer]

@TimXia yeah, i see that. sorry, i don't really have much to offer as additional help except that it happens sometimes, on different tests we run, on different devices, and i see these messages in the logs. we use a fork of IDF, currently based on 8478823 . there are a few patches on top of it but they are not related (the branch is here).

[rojer]

@TimXia maybe you can add printing some additional debug info when this alloc failure happens? i would then post new logs when it happens. we usually stay pretty close to IDF master, so it shouldn't take that long.

[PaladinEng]

@rojer I cannot confirm that I see the alloc eb ... fail message. So we might not be having the exact same issue.

@TimXia
Here's my most recent output log.
output.txt

[TimXia]

@rojer Sorry, we can not reproduce the issue. If you can provide a demo which can reproduce the issue, it will be much helpful.

[TimXia]

@PaladinEng Is the router that you try to connect to is far away from your device? Does it fail all the time if you continue to try to connect to the router again and again(at least 10 times)?

[PaladinEng]

@TimXia the wifi router is only 10 feet away from the device, and sufficiently strong that I'm able to get a useful signal with most devices more than 100 feet away, through a brick wall.

I've just power-cycled my router and modem, erased the flash, and made a clean flash, and let the program run. It usually connects correctly the first time the program runs. I've tested this three times in a row, and successfully connected each time.

I'm currently letting the program run to see how long it will stay connected. I will provide a log of the output.

Typically, if I kill the program and re-flash, it will not connect without also power cycling the wifi router. Additionally, even with a successful connection, it eventually disconnects and never successfully reconnects. After I finish the current run, I'll run a long-duration (hour or more) test to capture that output as well.

[PaladinEng]

@TimXia So, I just let the program run for a few hours. It stayed connected, but no packets were exchanged. I immediately reflashed and re-ran the program. This time, rather surprisingly, it eventually reconnected. I've attached both the output log and the wireshark capture in the hopes there is something useful there.

output-eventual success.txt

packetcapture.pcapng.zip

[PaladinEng]

@TimXia any progress on this? Anything I can do to assist?

[comcomservices]

I'm having the exact same problem, from what I can understand the device is running out of memory and allocation of a buffer is failing.. It seems that memory consumption in the latest 3.x idf release is substantially higher than earlier versions and may be responsible..

W (80194131) wifi: m f probe req l=0

I (80194251) wifi: n:1 1, o:1 0, ap:255 255, sta:1 1, prof:1
I (80194253) wifi: state: init -> auth (b0)
W (80194254) wifi: alloc eb len=32 type=3 fail, heap:2562344

[rojer]

i should note as well that the firmware this happens on is "fatter" than other firmware we test (it includes JS engine).
but we're still nowhere close to exhausting the heap.

[comcomservices]

Still having the same problem but like you pointed out, the heap still has lots of memory and checking the max available block allocation size there should still be no reason for an allocation failure..

V (23524382) event: exit default callback
I (23524386) WIFI: Trying to connect to ESP_09C6F5 with p=
W (23524393) wifi: alloc eb len=76 type=2 fail, heap:2861488

W (23524397) wifi: m f probe req l=0

I (23524522) wifi: n:1 1, o:1 0, ap:255 255, sta:1 1, prof:1
I (23524525) wifi: state: init -> auth (b0)
W (23524526) wifi: alloc eb len=32 type=3 fail, heap:2861496

W (23524527) wifi: m f auth

D (23524696) phy_common: phy_mii_check_link_status(UP)
I (23525420) DS2482: No Device detected
E (23525422) DS2482: One Wire Reset Failed..
E (23525422) DS2482: no 1-Wire slaves found
I (23525427) DS2482: No Device detected
I (23525530) wifi: state: auth -> init (2)
I (23525532) wifi: n:1 0, o:1 1, ap:255 255, sta:1 1, prof:1
D (23525534) event: SYSTEM_EVENT_STA_DISCONNECTED, ssid:Com Com Services, ssid_len:16, bssid:4c:5e:0c:b5:44:cd, reason:2
V (23525540) event: enter default callback
V (23525545) tcpip_adapter: check: local, if=0 fn=0x400f1908
0x400f1908: tcpip_adapter_down_api at /home/jon/Programming/flexsc2/esp-idf/components/tcpip_adapter/tcpip_adapter_lwip.c:1124


D (23525550) tcpip_adapter: if0 start ip lost tmr: enter
D (23525556) tcpip_adapter: if0 start ip lost tmr: no need start because netif=0x3ffdd518 interval=0 ip=35dc10ac
V (23525566) tcpip_adapter: call api in lwip: ret=0x0, give sem
V (23525572) tcpip_adapter: check: remote, if=0 fn=0x400f1908
0x400f1908: tcpip_adapter_down_api at /home/jon/Programming/flexsc2/esp-idf/components/tcpip_adapter/tcpip_adapter_lwip.c:1124


V (23525578) event: exit default callback
I (23525582) WIFI: Trying to connect to ESP_09C6F5 with p=
W (23525590) wifi: alloc eb len=76 type=2 fail, heap:2861488

W (23525594) wifi: m f probe req l=0

I (23525718) wifi: n:1 1, o:1 0, ap:255 255, sta:1 1, prof:1
I (23525721) wifi: state: init -> auth (b0)
W (23525723) wifi: alloc eb len=32 type=3 fail, heap:2861496

W (23525723) wifi: m f auth

I (23526234) FEEDS: Taking Measurement, Current Measurements Count = 204, max=16785
I (23526236) MAIN: 800406 adc samples... 7622 sps

Notice how each time it's trying to connect to 'ESP_09C6F5'... Should be connecting to Com Com Services..

This is printed in the STA_DISCONNECTED event..

case SYSTEM_EVENT_STA_DISCONNECTED:

        ESP_LOGI(WIFI_TAG, "Trying to connect to %s with p=%s",wifi_config.sta.ssid,wifi_config.sta.password);

An additional note is that the ethernet interface quits working aswell at the same time, even if we set the IF_ETH interface as the default interface.

If anyone has anything to add it would be very appreciated, @rojer, did you figure out anything?

[rojer]

@comcomservices nope, still happens every now and then.

[comcomservices]

It's absolutely killing us! We've spent the past week trying to get to the bottom of it with no luck.. Basically we're at the point where we automatically reboot our device every 40m but there's no way we can release a product until this is resolved. Let us know if any of you guys found out anything related to it and why some people are afflicted by it and not others..

[PaladinEng]

@TimXia or anyone, got any idea what the issue is? Could it be a setting on the router?

[GiulianoPortaro]

I had a similar problem and I resolved it without changing the promiscuous mode. If you put "false" in this mode you not able to capture the packets in the air and after (i don't know the number) few packets the esp32 in station mode disables the connection with the AP and crash (impossible to reboot); if you don't leave the promiscouse mode this will not happening.

[comcomservices]

@GiulianoPortaro, would you mind elaborating a little bit more on what you did? How is it different from the ESP examples / documentation?

esp_wifi_get_promiscuous(&proMode); returns false so it seems promiscuous mode is already disabled..

[GiulianoPortaro]

Well, I doing a project where sniffing packet in a specific channel and after 1 minute I block the promiscuous mode (esp_wifi_set_promiscuous(false);) to synchronize timer of the ESP32 (with a sntp cluster, protocol UDP) and to send the packets at one server (with socket library); after I do all, I enable the promiscuous mode (same command with true) to continue a sniffing packets. This is all correct but after 1 minutes or 40 minutes (the interval is not deterministic) i obtain the same issues discussed here. I read on the web, don't remember where, that the ESP32 in station mode close the connection with the AP if don't receive probe packet after one time (that is configurable, in ms with a maximum threshold, in the wifi_config_t struct) close the connection but after this event it is impossible to reconnect or reboot (i tried to insert a esp_reboot, or esp_wifi_stop, command in the handler event function but don't have effect, rather it has caused other problem). The only soluction that I found, after many test, is: not disable never the promiscuous mode. I think, but i not sure, that this problem maybe resolved, also, if reconfigure the wifi struct in AP+STA before handle other task.

[TimXia]

@rojer @comcomservices Could you provide a demo that can reproduce this issue? We can not reproduce it with our test code. Or could you descript the detail of your project, e.g. the WiFi mode do you use, promiscuous mode enabled or not, the more the better. It's better to provide a demo, it will help us to solve the problem.

[TimXia]

@PaladinEng Your problem is different from others. Please erase the flash before downloading bin files to the device, and then use the latest IDF code to test.

[satishIoT]

Me too facing wifi disconnect issue now and then and had posted complete log in
#1750
and awaiting for the response. We have planned our product on esp32-wroom but this issue is killing us from taking steps towards production .

[fisherman6v6]

Hi @GiulianoPortaro my project is very similar to yours and I've the same issues. Have you resolved the disconnection problem after disable promiscuous mode? I tried almost everything but nothing seems to work and the only solution seems to maintain the promiscuous mode active for all the time.

[GiulianoPortaro]

@fisherman6v6 The ESP32 has a factory defect, or a design choice depends on the point of view, which prevents you from activating the station mode (including wifi connect) + the promiscuous mode and then deactivating the promiscuous mode. In fact if you do this the device will stop working. If you are trying to capture packets for a period of time DO NOT DEACTIVATE the promiscuous mode but enter the code you want to perform in that time frame in a higher priority handler: in this way the ESP32 will not disable the WiFi connection and will not block ; moreover, there is a similar problem in pairing bluetooth with Wifi

For example:

void app_main(void) {
        // Print on serial error or information about status
	esp_log_level_set("*", ESP_LOG_DEBUG);

	// Boot flash memory
	nvs_flash_init();

	// Wi-Fi configuration
	wifi_setup();  // declare a function that start the connection (esp_wifi_init, esp_wifi_set_country et etc)

	// ...

	// Callback on function when capture one packet
	ESP_ERROR_CHECK(esp_wifi_set_promiscuous_rx_cb(&wifi_sniffer_packet_handler));

	// Sniffer mode on
	ESP_ERROR_CHECK(esp_wifi_set_promiscuous(true));

	// Set channel
	ESP_ERROR_CHECK(esp_wifi_set_channel(channel, WIFI_SECOND_CHAN_NONE));

	// Loop (Exectued all Timer second and block the capture of packets)
	while (true) {
		vTaskDelay(TIMER / portTICK_PERIOD_MS);

		//esp_wifi_set_promiscuous(false); ---> this cause the problem on code

               // What you want do after TIMER ms

		//esp_wifi_set_promiscuous(true); ---> this cause the problem on code
    }
}

[TimXia]

@fisherman6v6 @GiulianoPortaro Yes, it's better not to call esp_wifi_set_channel when ESP32 is connected with AP. In fact, this API is just designed for sniffer mode. It can be referenced in the API document.

[figueiredoAF]

Hello,

Any solution in this issue? I am having the same problem.

I'm running the BLE and Wifi at the same time, after ~15min I get the following problem:

I (619521) wifi: ap_probe_send over, resett wifi status to disassoc
I (619521) wifi: state: run -> init (1)
W (619521) wifi: alloc eb len=28 type=3 fail

W (619521) wifi: m f disassoc

I (619531) wifi: pm stop, total sleep time: 0/7506507

I (619531) wifi: n:2 0, o:2 1, ap:255 255, sta:2 1, prof:1

After this, the ESP32 reboots.

[negativekelvin]

@figueiredoAF #2184

[snahmad]

I am getting similar error
wifi: alloc eb len=192 type=2 fail

I am using WIFI with external RAM.

Internal Heap free: 41120
Heap free: 4195984:4233744

Plenty of external ram and some internal RAM.

Does in default settings WIFI only uses internal ram.

[davctv]

Hi, I would like to report my issue on WiFi disconnection and "wifi" task got stuck

`I (3518155) wifi: bcn_timout,ap_probe_send_start
I (3520658) wifi: ap_probe_send over, resett wifi status to disassoc
I (3520658) wifi: state: run -> init (100)
I (3520659) wifi: pm stop, total sleep time: 823348942 us / 1733716302 us

I (3520664) wifi: n:7 0, o:7 2, ap:255 255, sta:7 2, prof:1
Task watchdog got triggered. The following tasks did not reset the watchdog in time:

IDLE (CPU 0)
Tasks currently running:
CPU 0: wifi
CPU 1: IDLE
Task watchdog got triggered. The following tasks did not reset the watchdog in time:
IDLE (CPU 0)
Tasks currently running:
CPU 0: wifi
CPU 1: IDLE`

Before getting the "bcn_timout,ap_probe_send_start" the available heap was around 47200bytes.
I'm using ESP32-WROOM-32 with esp-idf v3.1

git rev-parse HEAD 22da5f6de9ff3657fa7613fc06ad2eca1d1fe14a

`git submodule
8bf852db77c360eebfa4b800754fdb90e29ea43e components/aws_iot/aws-iot-device-sdk-embedded-C (v2.1.1-39-g8bf852d)

00e64bfb47a596c6d375ab7b89ec2733c66da2be components/bt/lib (remotes/origin/release/v3.1)

6468887a12666f88b8704d797fc176cd4f40ee4c components/coap/libcoap (v4.1.1-401-g6468887)

1373c2075a9524437cbb4bdfd8576dedb77c68a2 components/esp32/lib (remotes/origin/release/v3.1-25-g1373c20)

fd8c25d2160505fb9d5abbe56f85116a136afb05 components/esptool_py/esptool (v2.4.1-5-gfd8c25d)

7cc52f60356909b3dd260304c7c50c0693699353 components/json/cJSON (v1.7.1)

70170c28c844a4786e75efc626e1aeebc93caebc components/libsodium/libsodium (1.0.12)

b9ada3067587aaccb37c33d41733bb82496c6342 components/mbedtls/mbedtls (mbedtls-2.9.0-641-gb9ada306)

d037ec89546fad14b5c4d5456c2e23a71e554966 components/micro-ecc/micro-ecc (v1.0)

3bcc416e13cc790e2fb45fcfe9111d38609c5032 components/nghttp/nghttp2 (v1.24.0)

f5e26c4e933189593a71c6b82cda381a7b21e41c components/spiffs/spiffs (0.2-221-gf5e26c4)`

I have also noticed that this could happen also when "esp_wifi_stop" API is called.

[snahmad]

now I keep internal ram usage under control. WIFI needs at least 50k internal ram free available. seems to me good so far.

[davctv]

Hello @snahmad,

WIFI needs at least 50k internal ram free available

Where did you get this limit? From docs or from tests. I also noticed that RAM usage is critical..but esp32 itself is quite "limited" (respect to others modules) in RAM size.

Thanks

[ghost]

I have started to get this issue as well :-( Started after i updated esp-idf.
EDIT: Hold fire.. I have an obvious memory leak that was introduced at the same time... Will update after 24 hours of run time success.

[Alvin1Zhang]

@rojer Thanks for reporting the issue. Feel free to reopen if the issue still exists. Thanks.

[alexander-sorokin]

@TimXia or anyone, got any idea what the issue is? Could it be a setting on the router?

99.9%

Try changing your router.

I have spent few days debugging.
Changed to wolfssl from mbedTLS. That helped a little bit, but code still crashes or webpage loads up to 5 minutes.

Then I had to move to another place and... I was surprised! Everything works just perfect!
I tried with mobile hotspot and few other routers. The problem was my router - Sagemcom Fast 5280 with hardware version 1.0 and software version SGAC110226_prod.

Similar behavior exists with both wolfssl from mbedTLS. It is definitely some sort of bug, but where?

Usually my app leaves around 160000 bytes of free heap, but after loading webpage thru my home router it has only 1208 bytes.

[hassandraga]

I was having the same issue, using the latest SDK (v4.4-dev-2977-gdd491ee851-dirty) and implementation of esp_wifi_set_promiscuous(true) solve the issue.

[MartinTJDK]

@hassandraga Is it correct, that ENABLING "promiscuous mode" will forward more packages for processing, right? Is that feature enabled as default, since it makes a difference for you, when DISABLING it?

Do not understand me wrong. I am just curious. And trying to figure out instability in SDKV4 (4.3.1) related to Wi-Fi connectivity.
I am seeing the following console output: "W (57074904) wifi:m f probe req l=0".
I have reduces all buffers in SDK to minimum allowed size to increase amount of free internal RAM...

[MaxwellAlan]

Hi @hassandraga @MartinTJDK
Could you provide some more details(full logs, wireless sniffer etc) for your issue, and if you still face these issues, welcome to open new github issue.
Thanks.