espressif / arduino-esp32

Arduino core for the ESP32
GNU Lesser General Public License v2.1
13.59k stars 7.41k forks source link

HTTP Client Error 105, and then, Memory Leak when using FreeRTOS #8804

Open josesnchz opened 1 year ago

josesnchz commented 1 year ago

Board

Adafruit ESP32 Feather - HUZZAH32 / ESP32-MINI-1

Device Description

Plain module on breadboard: HUZZAH32, and ESP32-MINI-1 in custom board

Hardware Configuration

Nothing relevant

Version

v2.0.14

IDE Name

Arduino IDE

Operating System

Ubuntu 22.04 with Kernel 5.15.0-87-generic

Flash frequency

80MHz

PSRAM enabled

yes

Upload speed

921600

Description

Using the HTTP Client inside loop does not cause any issues., whereas using it inside a task raises error 105 after the request number 16.
This is due to a bad implementation of the HTTPClient::disconnect method, where the _client stop method is not called if the is released if the _client used is not avaliable or connected, as it can be seen in code. This can be solved by adding a call to _client->stop() in line 408. This causes the client used to close the openned socket, thus allowing to create a new one. Despite fixing that, also, only when running the HTTP client in a task, I see that in each one of the executions of my task, there is memory allocated in the heap that does not get released. Around 200 bytes get used in each one of the requests executed. This issue is similar to #5072, with the difference that the issue mentioned in it is "solved" (if you guys agree, I can make a push request with my changes), but with the additional issue of the memory leak, which I have not found the reason of it.

Sketch

#include <Arduino.h>
#include <HTTPClient.h>
#include <WiFi.h>
#include <freertos/task.h>

const char* wifi_ssid = "ssid";    
const char* wifi_password = "123456789";   // WiFi password
const char* wifi_hostname = "esp32";

bool wifiIsConnected(void){
  return WiFi.status() == WL_CONNECTED;
}

int numberReq = 0;
bool taskRun = false;
void dummyTask(void *pvParameters){

  HTTPClient http;
  http.setReuse(false);
  http.begin("10.42.0.1", 5000, "/api/test");

  Serial.print("After begin Heap Size: ");
  Serial.print(ESP.getHeapSize());
  Serial.print(", free: ");
  Serial.println(ESP.getFreeHeap());

  int code = http.GET();
  String payload = http.getString();
  numberReq ++;
  Serial.print("Number of requests: ");
  Serial.print(numberReq);
  Serial.print("   -------------------------, code ");
  Serial.println(code);

  Serial.print("After get Heap Size: ");
  Serial.print(ESP.getHeapSize());
  Serial.print(", free: ");
  Serial.println(ESP.getFreeHeap());

  http.end();

  Serial.print("After end Heap Size: ");
  Serial.print(ESP.getHeapSize());
  Serial.print(", free: ");
  Serial.println(ESP.getFreeHeap());

  taskRun = false;
  vTaskDelete(NULL); // Delete this task
}

void setup() { 
  TickType_t xLastWakeTime = xTaskGetTickCount();

  // Init serial
  Serial.begin(115200);
  vTaskDelayUntil(&xLastWakeTime, pdMS_TO_TICKS(200));

  // Configure and initialize WiFi
  WiFi.disconnect(true, true); // Deletes old config 
  vTaskDelayUntil(&xLastWakeTime, pdMS_TO_TICKS(200));
  WiFi.mode(WIFI_STA); // Station mode, connect to AP
  WiFi.config(INADDR_NONE, INADDR_NONE, INADDR_NONE, INADDR_NONE, INADDR_NONE); // Use default params 
  WiFi.setAutoConnect(true);
  WiFi.begin(wifi_ssid, wifi_password); // Begin searching for wifi network
  WiFi.setHostname(wifi_hostname); 

  while(!wifiIsConnected()){
    vTaskDelayUntil(&xLastWakeTime, pdMS_TO_TICKS(200));
  }
  Serial.println("------- WiFi Connected");
}

void loop() {
  TickType_t xLastWakeTime = xTaskGetTickCount();
  vTaskDelayUntil(&xLastWakeTime, pdMS_TO_TICKS(200));

  Serial.print("Initial Heap Size: ");
  Serial.print(ESP.getHeapSize());
  Serial.print(", free: ");
  Serial.println(ESP.getFreeHeap());

  if(!taskRun){
    taskRun = true;
    Serial.println("Created Task");
    xTaskCreatePinnedToCore(
      dummyTask,   /* Task Function */
      "dummyTask", /* Task Name. */
      7500,       /* Stack Size */
      NULL,        /* Task Param */
      0,           /* Task Priority */
      NULL, /* Task Handle*/
      1 /* Core 0-1*/
    ); 
    Serial.print("After create task: ");
    Serial.print(ESP.getHeapSize());
    Serial.print(", free: ");
    Serial.println(ESP.getFreeHeap());
  }
}

Debug Message

Initial Heap Size: 320976, free: 218604
Created Task
After create task: 320944, free: 210728
[  4452][D][HTTPClient.cpp:321] begin(): host: 10.42.0.1 port: 5000 uri: /api/live_race/test
After begin Heap Size: 320896, free: 210620
[  4467][D][HTTPClient.cpp:606] sendRequest(): request type: 'GET' redirCount: 0

[  4483][D][HTTPClient.cpp:1178] connect():  connected to 10.42.0.1:5000
[  4503][D][HTTPClient.cpp:1329] handleHeaderResponse(): code: 200
[  4504][D][HTTPClient.cpp:1332] handleHeaderResponse(): size: 29
[  4504][D][HTTPClient.cpp:650] sendRequest(): sendRequest code=200

[  4514][D][WiFiClient.cpp:536] connected(): Disconnected: RES: 0, ERR: 128
[  4517][D][HTTPClient.cpp:1468] writeToStreamDataBlock(): connection closed or file end (written: 29).
[  4540][D][HTTPClient.cpp:416] disconnect(): tcp is closed

Number of requests: 16   -------------------------, code 200
After get Heap Size: 320624, free: 208152

[  4569][D][HTTPClient.cpp:416] disconnect(): tcp is closed

After end Heap Size: 320624, free: 208152
Initial Heap Size: 320736, free: 216260
Created Task
After create task: 320704, free: 208384
[  4652][D][HTTPClient.cpp:321] begin(): host: 10.42.0.1 port: 5000 uri: /api/live_race/test
After begin Heap Size: 320656, free: 208284
[  4667][D][HTTPClient.cpp:606] sendRequest(): request type: 'GET' redirCount: 0

[  4668][E][WiFiClient.cpp:225] connect(): socket: 105
[  4672][D][HTTPClient.cpp:1171] connect(): failed connect to 10.42.0.1:5000
[  4678][W][HTTPClient.cpp:1491] returnError(): error(-1): connection refused
[  4685][W][HTTPClient.cpp:1491] returnError(): error(-4): not connected
Number of requests: 17   -------------------------, code -1
After get Heap Size: 320576, free: 208044

[  4715][D][HTTPClient.cpp:416] disconnect(): tcp is closed

After end Heap Size: 320576, free: 208044
Initial Heap Size: 320672, free: 216100

Other Steps to Reproduce

The problem occurs either in the HUZZAH 32 and my custom board.

I have checked existing issues, online documentation and the Troubleshooting Guide

josesnchz commented 1 year ago

I have been testing the behaviour of this issue a little bit more. Reusing the same HTTPClient to make different request does not cause a memory leak, there might be a problem with the destructor.

me-no-dev commented 1 year ago

@lucasssvaz PTAL

TD-er commented 1 year ago

Looks very much like what I'm seeing. However the memory does get released after 120 sec.

As a test, I have requested a JSON page every second for about 2 minutes and then stopped requesting pages. image Chart is showing free heap on ESP32.

Also on a C3, requested the same JSON page for 90 seconds, then checked again after 120 seconds: image

Memory not freed per call is roughly 160 bytes.

TD-er commented 1 year ago

Hmm reading the original issue again, it seems like this issue is about the WiFi client. I was talking about serving web pages.

Not 100% sure whether it is the same issue.....

me-no-dev commented 1 year ago

memory returning back is normal. Some connections are kept in cache for a bit in case of reconnect, etc.

TD-er commented 1 year ago

memory returning back is normal. Some connections are kept in cache for a bit in case of reconnect, etc.

Is this configurable, as the behavior was different on older IDF versions? (Assuming this is the same issue as reported by the OP, as he didn't report memory is recovered after some time)

me-no-dev commented 1 year ago

This has always been like that. It's part of TCP. Depending on who closes the connection and how, it might be kept in memory for a bit.

josesnchz commented 1 year ago

So what are the methods "setReuse", and "end" in case of the HTTP client or "stop" in case of the Wifi client meant to be used for? Is there any way to free that memory explicitly? If no, maybe there should exist a method to do it.

me-no-dev commented 1 year ago

why? it does not use a lot of memory and it has a limited amount of connections that it will cache. We used to hack this in 8266, but here we have plenty more RAM to stay standard

TD-er commented 1 year ago

It isn't that hard to hit an ESP with 4 requests per second (and serve them too, tried it yesterday) 120 seconds of 4 requests per sec is already about 80k of RAM. On an ESP32-S2, that's more than what's available in free RAM on my test node.

Here the test result I did yesterday on an ESP32 with 4 JSON requests per sec. (from 4 browsers)

image

And 2 minutes later all memory was available again: image

I can easily serve more requests per second.

There is however 1 'strange' thing happening here on the S2. The S2 one doesn't seem to go this 'deep' in keeping sessions like the 'others' do. So I wonder, is there already some limit in place here based on the amount of free memory or something like that?

me-no-dev commented 1 year ago

it is possible that on the 2.x Arduino there could be different settings on the different chips. We have "fixed" this in 3.0.0. Any chance you give the Alpha2 a go?

TD-er commented 1 year ago

@Jason2866 What framework build of yours is using the Alpha2? Is build 1751 already using this? If so, then I could try tomorrow morning.

Edit: If this wasn't a build based on Alpha2, then at least it is some reference for later tests. SDK string (@Jason2866 build 1751 , ESP32 SDK 5.1.1.231024)

C3 hit with about 5.6 JSON requests being handled per second: image

And recovering from this: image

On ESP32 with Ethernet (about 6.5 requests per sec) is the impact less as you only seem to loose about 40k of RAM instead of 125k on the C3:

image

image

On ESP32-S2 the behavior is completely different.

image

ESP32-S3 is showing similar behavior as the S2: (running 8 browser tabs fetching the same JSON every second, still running at time of screenshot) image

Jason2866 commented 1 year ago

The framework is built with latest Arduino and IDF5.1 release branch commits. The memory decrease is not there in Core 2.0.14. It started to behave like @TD-er shows since IDF 5.1 is used. I noticed that in every build from the beginning for Arduino 3.0.0. Since the day i have compiled frameworks for. That was long before the alpha releases. The decrease is too big since it takes too long until it is freed. For Projects which needs a lot of RAM this leads to crashes.

TD-er commented 1 year ago

Just as a comparison, same code built with Core 2.0.14 on ESP32:

image

It clearly stops after about < 20 calls.

Jason2866 commented 1 year ago

it is possible that on the 2.x Arduino there could be different settings on the different chips. We have "fixed" this in 3.0.0. Any chance you give the Alpha2 a go?

What settings are changed, which can introduce this behaviour?

TD-er commented 1 year ago

Ah found the 'lost memory' on the ESP32-S3.... It was using PSRAM, not the internal RAM, as can be seen here: image

I think it was about 8 simultaneous browser tabs requesting the same JSON url every second to get this low on memory usage.

The same on the ESP32-S2 with PSRAM: image

Less concurrent calls to the S2, as it was just about showing the same behavior.

TD-er commented 11 months ago

@Jason2866 made a platform_package for me with some changes to the MSL and FIN wait timeout.

CONFIG_LWIP_TCP_MSL=6000
CONFIG_LWIP_TCP_FIN_WAIT_TIMEOUT=2000

This does make the problem much less of a problem, but I wonder if this is a proper fix or could it have unforeseen side-effects? And still the question remains why it is now becoming a problem?

@s-hadinger rightfully outed his concerns about this suggested change as he still believes there must be something wrong (or changed for unknown reason) causing connections not to be closed when they should.