ESP8266WebServer: Heap-leak and delay on aborted HTTP-requests

[MagnusHelleberg]

Basic Infos

• This issue complies with the issue POLICY doc.
• I have read the documentation at readthedocs and the issue is not addressed there.
• I have tested that the issue is present in current master branch (aka latest git).
• I have searched the issue tracker for a similar issue.
• If there is a stack dump, I have decoded it. (No stack dump)
• I have filled out all fields below.

Platform

• Hardware: ESP8266EX / ESP-12E
• Core Version: 2.4.1
• Development Env: Visual Studio 2017 with vMicro
• Operating System: Windows

Settings in IDE

• Module: ESP8266MOD from AI-Thinker
• Flash Mode: DIO
• Flash Size: 4MB / 1MB
• lwip Variant: v2 lower Memory
• Reset Method: ck
• Flash Frequency: 40Mhz
• CPU Frequency: 160MHz
• Upload Using: OTA

Problem Description

I have an issue with the ESP8266WebServer.
If my HTTP request is completed, everything works perfectly fine.
But if the request gets disrupted / aborted, the webserver seams to run into some kind of timeout or unhandled error.
The next request takes time to get processed (2sec. with Core 2.3.0 even longer >10s) and the free heap gets reduced every time the issue occures by 1032 bytes.

To reconstruct the issue, I wrote a simple example, where a 10KByte picture is requested via the browser.
Press the F5 key extremly fast 2 times in a row, so that the second request is faster issued than the old request is received, then the issue occures.

http://192.168.4.1/abc
Doesn't exist and so the notFound page is displayed, where the FreeHeap is shown.

Here is the .ino and the hex-dump of the picture.
webServer.zip

Hopefully I could clarify my issue.

Best regards,
Magnus.

MCVE Sketch

#include "websites.h"
#include <ESP8266WiFi.h>
#include <ESP8266WebServer.h>
#include <ESP8266HTTPUpdateServer.h>

#define ledGreen_Pin		4
#define ledRed_Pin			5

ESP8266WebServer		webServer(80);
ESP8266HTTPUpdateServer updateServer;
IPAddress				apIP(192, 168, 4, 1);

void setup()
{
	pinMode(ledGreen_Pin, OUTPUT);
	pinMode(ledRed_Pin, OUTPUT);
	digitalWrite(ledGreen_Pin, false);
	digitalWrite(ledRed_Pin, true);

	Serial.begin(115200);

	WiFi.hostname("Test123");
	WiFi.mode(WIFI_AP);
	WiFi.softAP("Test", "12345678");

	// Page not Found Handler
	webServer.onNotFound(allSites_handleUnknown);
	webServer.on("/test.jpg", sendLogo);

	// Setup the otaUpdater and register update functions to webserver
	updateServer.setup(&webServer, "/update");

	webServer.begin();

	digitalWrite(ledGreen_Pin, true);
	digitalWrite(ledRed_Pin, false);
}

void loop()
{
	webServer.handleClient();
}


// Handles all requests from files, which were not registered via webserver.on
void allSites_handleUnknown(void)
{
	String message = "File Not Found\n\n";
	message += "URI..........: ";
	message += webServer.uri();
	message += "\nMethod.....: ";
	message += (webServer.method() == HTTP_GET) ? "GET" : "POST";
	message += "\nArguments..: ";
	message += webServer.args();
	message += "\n";
	for (uint8_t i = 0; i<webServer.args(); i++) {
		message += " " + webServer.argName(i) + ": " + webServer.arg(i) + "\n";
	}
	message += "\n";
	message += "FreeHeap.....: " + String(ESP.getFreeHeap()) + "\n";
	message += "ChipID.......: " + String(ESP.getChipId()) + "\n";
	message += "FlashChipId..: " + String(ESP.getFlashChipId()) + "\n";
	message += "FlashChipSize: " + String(ESP.getFlashChipSize()) + " bytes\n";
	message += "getCycleCount: " + String(ESP.getCycleCount()) + " Cycles\n";
	message += "Milliseconds.: " + String(millis()) + " Milliseconds\n";
	webServer.send(404, "text/plain", message);
}


void sendLogo(void)
{
	webServer.send_P(200, webFiles[0].mime, webFiles[0].content, webFiles[0].len);
}

#ifndef WEBSITES_H_
#define WEBSITES_H_

//
// Website HEX-Dump
//

static const char file_0[] PROGMEM = {
  0xff, 0xd8, 0xff, 0xe0, 0x00, 0x10, 0x4a, 0x46, 0x49, 0x46, 0x00, 0x01,
  0x01, 0x00, 0x00, 0x01, 0x00, 0x01, 0x00, 0x00, 0xff, 0xdb, 0x00, 0x84,
  0x00, 0x09, 0x06, 0x07, 0x13, 0x12, 0x12, 0x15, 0x13, 0x12, 0x13, 0x16,
  0x16, 0x15, 0x17, 0x17, 0x16, 0x15, 0x18, 0x16, 0x17, 0x18, 0x19, 0x16,
  0x17, 0x17, 0x15, 0x15, 0x15, 0x18, 0x17, 0x16, 0x17, 0x18, 0x17, 0x18,
  ...
};

struct t_websitefiles {
  const char* filename;
  const char* mime;
  const unsigned int len;
  const char* content;
} webFiles[] = {
  {
    .filename = "test.jpg",
    .mime = "image/jpeg",
    .len = 10257,
    .content = file_0
  },
};

#endif

Debug Messages

The first request is aborted from the browser and directly requested again.
The second request is delayed.

New client
method: GET url: /test.jpg search: 
headerName: Host
headerValue: 192.168.4.1
headerName: User-Agent
headerValue: Mozilla/5.0 (Windows NT 10.0; WOW64; rv:61.0) Gecko/20100101 Firefox/61.0
headerName: Accept
headerValue: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
headerName: Accept-Language
headerValue: de,en-US;q=0.7,en;q=0.3
headerName: Accept-Encoding
headerValue: gzip, deflate
headerName: Connection
headerValue: keep-alive
headerName: Upgrade-Insecure-Requests
headerValue: 1
headerName: Cache-Control
headerValue: max-age=0
args: 
Request: /test.jpg
 Arguments: 

<Delay of around 2 seconds>

New client
method: GET url: /test.jpg search: 
headerName: Host
headerValue: 192.168.4.1
headerName: User-Agent
headerValue: Mozilla/5.0 (Windows NT 10.0; WOW64; rv:61.0) Gecko/20100101 Firefox/61.0
headerName: Accept
headerValue: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
headerName: Accept-Language
headerValue: de,en-US;q=0.7,en;q=0.3
headerName: Accept-Encoding
headerValue: gzip, deflate
headerName: Connection
headerValue: keep-alive
headerName: Upgrade-Insecure-Requests
headerValue: 1
headerName: Cache-Control
headerValue: max-age=0
args: 
Request: /test.jpg
 Arguments: 

[d-a-v]

Can you please try with latest git version of the core ?
There are known leaks when using 2.4.1 which are fixed in it.

[MagnusHelleberg]

I just downloaded the master from the repository.
But with the newest version, it seems the linker script changed alot and I can't get it running in my IDE.
-- ld.exe: cannot open linker script file ..\ld\eagle.app.v6.common.ld: No such file or directory
The ".ld" is no more, now there are two header files with vTables.
"eagle.app.v6.common.ld.h" and "eagle.app.v6.common.ld.vtables.h"

So I tried copying the new libraries to the old folder (2.4.1) to get the linker use the old script.
It compiles successfully, but it doesn't run on the ESP. (Restarts all the time, maybe false addresses)

[d-a-v]

Are you using the arduino IDE ?

[MagnusHelleberg]

I normaly use Visual Studio with vMicro.

So now I used the Arduino IDE and it runs with the master.
The program seems to run on the ESP, but the issue still occures.

The hole program is faster now, the loading time of the image was reduced from 60ms to 40ms.
And the leak was reduced from 1032 bytes to 976 bytes.

[d-a-v]

OK, I will try to reproduce

[RudyFiero]

I tried this and while the heap goes down initially it does stabilize and even recovers somewhat. I am using a version of git, 2018-05-11.
Clock set at 80MHz

Heap
47856
47536
47368
47288
47120
46864
46952
46696
46696
46696
46696
45960
46528
then it started climbing and has been around
47368
47544
47288
47032
46864
46784
I'm doing multiple hits, stopping, then get the heap so the list is not for every occurrence/pairs.
Transfer time for the image is 35mS typical and 141mS as a maximum. I found that I can go faster with mouse clicks (reload) compared to the F5 key. Not by much though.
47624
47536
47368
47120
47032
It seems to have stabilized at around 47000 for me.

[MagnusHelleberg]

The following picture is the development of my heap.
I hold F5 pressed, until the reload arrow keeps spinning. (around 1-2 secs.)
My download of the master is from the 5. July 2018, 14:16:50.
It keeps dropping, until a heap crash occures and the ESP restarts.

Further more I tested to reduce the heap to 35512 bytes and waited 15 minutes.
The heap remained on exactly the same value and didn't recover. (35512 bytes)

Edit:
I tried different ESP clocks and the lower memory / higher bandwidth options.
The higher bandwidth version is reduced faster, but when the FreeHeap counter reaches ~3000 bytes, I can hold F5 pressed for a long time and it takes some time to trigger the issue again to get a heap crash.

[JonHyeKnudsen]

I don't know if it's related, but I just left a comment with a kind of similar problem on this issue: #4823
I don't even have to send requests to the server to have it exhaust it's heap

[earlephilhower]

@d-a-v implemented some patches to aggressively dispose of tcp per-connection memory structures in 2.4.2. The purpose was to avoid what appeared as a memory leak (but which, given enough idle time, the TCP backend would eventually free). It fixed the same behaviour the original but was seeing.

I've run the sketch given with git head and left my finger on the F5 for quite a while, occasionally checking the reported stats. They are rock solid at 46-47kb free heap, so I think we're good here.