search

espressif / arduino-esp32

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

HTTPClient https request works the first time, but fails the second time #6561

Open RosiersRobin opened 2 years ago

RosiersRobin commented 2 years ago

Board

ESP32-Wroom-32UE

Device Description

Plain module un custom hardware with an ETH chip (LAN8720) connected to it, using that chip to cummunicate with internet intead of wifi.

Hardware Configuration

GPIO0 has 50Mhz crystal input for ETH -> disabled on boot, thus device boots

GPIO12 -> crystal power pin GPIO2 -> I2C clock signal GPIO17 -> I2C MDIO

Version

v2.0.2

IDE Name

Arduino IDE

Operating System

Windows 10

Flash frequency

80Mhz

PSRAM enabled

no

Upload speed

921600

Description

I updated from version 1.0.6 to 2.0.2 and changed nothing to the code. The code works still, however, it seems that the HTTPClient is broken since then.

I can do an API call to the server once, but not twice.

I have for example a heartbeat that runs every 5 minutes, the first time it runs just fine, the second time I get a -1 error. While this uses the exact same code...

Sketch

void setup() {
    ... Some other setup code...
    xTaskCreatePinnedToCore(sendHeartBeat, "Send Heartbeat", 20000, NULL, 25, &heartBeatTask, 0);
}

void sendHeartBeat(void *pvParameters) {
    // Heartbeat millis
    unsigned long previousHeartBeatMillis = 0;
    const long heartBeatInterval = 300000; // 5 minutes

    // Send a first heartbeat to let the server know it's alive
    sendHeartBeatApiCall();

    // Infinite loop (runs on another core)
    while (true) {
        unsigned long currentMillis = millis();

        // heartbeat thing
        if (currentMillis - previousHeartBeatMillis >= heartBeatInterval) {

            previousHeartBeatMillis = currentMillis;

            sendHeartBeatApiCall();
        }

        vTaskDelay(1); // to allow for resources to terminate and the task not to crash
    }
}

void sendHeartBeatApiCall() {
    StaticJsonDocument<256> doc;
    doc.clear(); // release the memory
    doc["data"] = "random";
    ... some more json data

    String heartbeatData;
    serializeJson(doc, heartbeatData);

    Serial.println("Sending Heartbeat");

    http.begin("https://my-endpoint.com/path/to/heartbeat");

    http.addHeader("Content-Type", "application/json");

    int responseCode = http.POST(heartbeatData); // just post, Don't care about the response.

    // If the response code was 200, store the current millis.
    if (responseCode == 200) {
        lastHeartbeat = millis();
    }

    Serial.print("ResponseCode from heartbeat: ");
    Serial.println(responseCode);

    // Free resources
    http.end();
}

Debug Message

This is the output (redacted) of a successfull API call;

15:34:26.270 -> Sending Heartbeat
15:34:26.270 -> [ 30759][V][HTTPClient.cpp:247] beginInternal(): url: https://mydomain.com/path/to/api
15:34:26.270 -> [ 30760][W][HTTPClient.cpp:258] beginInternal(): unexpected protocol: https, expected http
15:34:26.270 -> [ 30768][V][HTTPClient.cpp:247] beginInternal(): url: https://mydomain.com/path/to/api
15:34:26.270 -> [ 30776][D][HTTPClient.cpp:298] beginInternal(): protocol: https, host:mydomain.com port: 443 url: /path/to/api
15:34:26.270 -> [ 30787][D][HTTPClient.cpp:595] sendRequest(): request type: 'POST' redirCount: 0
15:34:26.339 -> 
15:34:26.339 -> [ 30794][D][HTTPClient.cpp:1101] connect(): already connected, reusing connection
15:34:26.339 -> [ 30802][V][ssl_client.cpp:351] send_ssl_data(): Writing HTTP request with 257 bytes...
15:34:26.339 -> [ 30810][V][ssl_client.cpp:351] send_ssl_data(): Writing HTTP request with 219 bytes...
15:34:26.408 -> [ 30874][V][HTTPClient.cpp:1234] handleHeaderResponse(): RX: 'HTTP/1.1 200 OK'
15:34:26.408 -> [ 30875][V][HTTPClient.cpp:1234] handleHeaderResponse(): RX: 'Server: nginx'
15:34:26.408 -> [ 30877][V][HTTPClient.cpp:1234] handleHeaderResponse(): RX: 'Content-Type: application/json'
15:34:26.408 -> [ 30885][V][HTTPClient.cpp:1234] handleHeaderResponse(): RX: 'Transfer-Encoding: chunked'
15:34:26.408 -> [ 30893][V][HTTPClient.cpp:1234] handleHeaderResponse(): RX: 'Connection: keep-alive'
15:34:26.408 -> [ 30901][V][HTTPClient.cpp:1234] handleHeaderResponse(): RX: 'Vary: Accept-Encoding'
15:34:26.442 -> [ 30908][V][HTTPClient.cpp:1234] handleHeaderResponse(): RX: 'Cache-Control: no-cache, private'
15:34:26.442 -> [ 30917][V][HTTPClient.cpp:1234] handleHeaderResponse(): RX: 'Date: Mon, 11 Apr 2022 13:34:26 GMT'
15:34:26.442 -> [ 30925][V][HTTPClient.cpp:1234] handleHeaderResponse(): RX: 'Access-Control-Allow-Origin: *'
15:34:26.442 -> [ 30934][V][HTTPClient.cpp:1234] handleHeaderResponse(): RX: 'X-Frame-Options: SAMEORIGIN'
15:34:26.442 -> [ 30942][V][HTTPClient.cpp:1234] handleHeaderResponse(): RX: 'X-XSS-Protection: 1; mode=block'
15:34:26.442 -> [ 30950][V][HTTPClient.cpp:1234] handleHeaderResponse(): RX: 'X-Content-Type-Options: nosniff'
15:34:26.477 -> [ 30958][V][HTTPClient.cpp:1234] handleHeaderResponse(): RX: ''
15:34:26.477 -> [ 30964][D][HTTPClient.cpp:1275] handleHeaderResponse(): code: 200
15:34:26.477 -> [ 30970][D][HTTPClient.cpp:1282] handleHeaderResponse(): Transfer-Encoding: chunked
15:34:26.477 -> [ 30977][D][HTTPClient.cpp:619] sendRequest(): sendRequest code=200
15:34:26.477 -> 
15:34:26.477 -> ResponseCode from heartbeat: 200
15:34:26.477 -> [ 30993][D][HTTPClient.cpp:383] disconnect(): still data in buffer (25), clean up.
15:34:26.477 -> 
15:34:26.477 -> [ 30994][D][HTTPClient.cpp:390] disconnect(): tcp keep open for reuse

This is the output (redacted) of the failed API call;

```cpp
15:38:55.509 -> Sending Heartbeat
15:38:55.509 -> [300001][V][HTTPClient.cpp:247] beginInternal(): url: https://mydomain.com/path/to/api
15:38:55.509 -> [300001][W][HTTPClient.cpp:258] beginInternal(): unexpected protocol: https, expected http
15:38:55.509 -> [300007][V][HTTPClient.cpp:247] beginInternal(): url: https://mydomain.com/path/to/api
15:38:55.509 -> [300016][D][HTTPClient.cpp:298] beginInternal(): protocol: https, host: mydomain.com port: 443 url: /path/to/api
15:38:55.509 -> [300026][D][HTTPClient.cpp:595] sendRequest(): request type: 'POST' redirCount: 0
15:38:55.509 -> 
15:38:55.509 -> [300035][V][ssl_client.cpp:311] stop_ssl_socket(): Cleaning SSL connection.
15:38:55.543 -> [300041][V][ssl_client.cpp:61] start_ssl_client(): Free internal heap before TLS 161764
15:38:55.543 -> [300048][V][ssl_client.cpp:67] start_ssl_client(): Starting socket
15:38:55.610 -> [300084][V][ssl_client.cpp:143] start_ssl_client(): Seeding the random number generator
15:38:55.610 -> [300086][V][ssl_client.cpp:152] start_ssl_client(): Setting up the SSL/TLS structure...
15:38:55.610 -> [300089][I][ssl_client.cpp:173] start_ssl_client(): WARNING: Skipping SSL Verification. INSECURE!
15:38:55.610 -> [300097][V][ssl_client.cpp:244] start_ssl_client(): Setting hostname for TLS session...
15:38:55.610 -> [300105][V][ssl_client.cpp:259] start_ssl_client(): Performing the SSL/TLS handshake...
15:38:55.610 -> [300116][E][WiFiClientSecure.cpp:135] connect(): start_ssl_client: -1
15:38:55.644 -> [300120][V][ssl_client.cpp:311] stop_ssl_socket(): Cleaning SSL connection.
15:38:55.644 -> [300126][D][HTTPClient.cpp:1134] connect(): failed connect to miqey.libaro.io:443
15:38:55.644 -> [300133][W][HTTPClient.cpp:1437] returnError(): error(-1): connection refused
15:38:55.644 -> ResponseCode from heartbeat: -1
15:38:55.644 -> [300150][D][HTTPClient.cpp:405] disconnect(): tcp is closed
15:38:55.644 ->

All outputs were captured via the serial debug monitor setting the core debug level to verbose.



### Other Steps to Reproduce

I already have tried alot here.

Tried to add the CA cert, didn't work,

Used an wificlientsecure with that CA cert, didn't work

`client.setReuse(false);` Didn't work.

The stranges thing here is, I do API calls, but the second time I do the call, it doesn't work.

What I do is like the following;

1. Sync NTP time
2. Register device on https://domain.com/register
3. Connect to AWS IoT using it's own client and certificates
4. Send a heartbeat on https://domain.com/heartbeat
5. Send a heartbeat on https://domain.com/heartbeat --> fails with -1

If I do for example this;

1. Sync NTP time
2. Register device on https://domain.com/register
3. Connect to AWS IoT using it's own client and certificates
4. Send a heartbeat on https://domain.com/heartbeat
5. Send a API call to https://domain2.com/endpoint --> fails with -1
6. Send a heartbeat on https://domain.com/heartbeat --> fails with -1

So I thought, it's somewhere I didn't call `http.end()`, so I went looking, but every `http.begin()` has a `http.end()`.

I'm totally at a loss here now....

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

- [X] I confirm I have checked existing issues, online documentation and Troubleshooting guide.
vlastahajek commented 2 years ago

This seems to be the same issue as #6165. It should work in 2.0.3-rc1

VojtechBartoska commented 2 years ago

Yes, please try to retest it on v2.0.3-rc1.

RosiersRobin commented 2 years ago

Tested it on v2.0.3-rc1, then I have the folloing issue;

First calls work as expectedd (just like above)

Second call fails with error code -2 BUT the thrid call of that same URL works just fine, it then alternates bewteen 200 and -2 of status codes returned.

So;

works doesnt works doesnt works ....

RosiersRobin commented 2 years ago

Update: If I do the call every 5 minutes, it breaks, if I do it every 5 seconds, it works just fine...

TD-er commented 2 years ago

Update: If I do the call every 5 minutes, it breaks, if I do it every 5 seconds, it works just fine...

Can you track the free heap? Have not tested the latest code myself, but the older code had a memory leak in loading the TLS code.

See my (still pending) PR for my own project to include TLS support. https://github.com/letscontrolit/ESPEasy/pull/3788/files These files in particular (especially ESPEasy_ssl_client.h/.cpp) :

These are taken from this lib and adapted to prevent this memory leak as the mbettls context objects are not dealt with properly. The pointers as members are not initialized correctly, thus if you destruct them you will see a crash and if you don't, you will run out of memory.

VojtechBartoska commented 2 years ago

This was added to our Roadmap, we will investigate it further. Thanks for your contribution.

podaen commented 2 years ago

A request would work, it s the content that just not right.

RosiersRobin commented 2 years ago

Update: If I do the call every 5 minutes, it breaks, if I do it every 5 seconds, it works just fine...

Can you track the free heap? Have not tested the latest code myself, but the older code had a memory leak in loading the TLS code.

See my (still pending) PR for my own project to include TLS support. https://github.com/letscontrolit/ESPEasy/pull/3788/files These files in particular (especially ESPEasy_ssl_client.h/.cpp) :

These are taken from this lib and adapted to prevent this memory leak as the mbettls context objects are not dealt with properly. The pointers as members are not initialized correctly, thus if you destruct them you will see a crash and if you don't, you will run out of memory.

Sorry for the late reply.

I have checked memory usage and that didn't seem to be the rpoblem. I even extracted the code into a blank project and tested it the exact same way. Same results.

r-downing commented 2 years ago

Sockets can be reused for multiple requests with HTTP1.1, but 5 minutes is a really long time - is it possible the server is just closing it? You said it works ok at a 5s interval.

"the default connection timeout of Apache httpd 1.3 and 2.0 is as little as 15 seconds and just 5 seconds for Apache httpd 2.2 and above."

If your interval is going to be that long, maybe just move the declaration of the httpclient inside the sendHeartBeatApiCall() function?

TD-er commented 2 years ago

OK, found another issue with the HTTPClient on ESP32. While searching for a related issue, this one came up and it is probably related. If not, I will make a new issue.

Problem is located here: https://github.com/espressif/arduino-esp32/blob/3f69bcfca4225ead422f322e524008408ae5e170/libraries/HTTPClient/src/HTTPClient.cpp#L372-L410

When calling end() the disconnect() call is probably doing nothing since it is likely no longer connected. This results in new calls made using the HTTPClient to not work untill some timeout has occurred or some instance of WiFiClient has made a connection to some other host.

By simply calling stop() on the WiFiClient object, this is no longer an issue.

Not sure if the best fix should be in this HTTPClient::disconnect() function, but I guess it is at least a fix for this problem. However the true problem is probably in the WiFiClient code.

IMHO this code should be executed regardless the connected() state.

https://github.com/espressif/arduino-esp32/blob/3f69bcfca4225ead422f322e524008408ae5e170/libraries/HTTPClient/src/HTTPClient.cpp#L392-L406

But then there should be an extra check on whether _client isn't a nullptr.

So it should probably something like this (untested)

void HTTPClient::disconnect(bool preserveClient)
{
    if(connected()) {
        if(_client->available() > 0) {
            log_d("still data in buffer (%d), clean up.\n", _client->available());
                _client->flush();
        }
    } else {
        log_d("tcp is closed\n");
    }
    if(_reuse && _canReuse) {
        log_d("tcp keep open for reuse");
    } else {
        log_d("tcp stop");
        if (_client != nullptr) _client->stop();
        if(!preserveClient || _client == nullptr) {
            _client = nullptr;
#ifdef HTTPCLIENT_1_1_COMPATIBLE
            if(_tcpDeprecated) {
                _transportTraits.reset(nullptr);
                _tcpDeprecated.reset(nullptr);
            }
#endif
        }
    }
}

N.B. the default for _reuse is true and _canReuse = _reuse; is called when looking at the header response.

hansmbakker commented 1 year ago

I had this problem when a first HTTPS request was made using HTTPClient, and later (in another library) HTTPS requests were made using WifiClientSecure.

The error I got with that was similar to https://github.com/platformio/platform-espressif32/issues/649:

_handle_error(): [send_ssl_data():<line number>]: (-80) UNKNOWN ERROR CODE (0050)
podaen commented 1 year ago

OK, found another issue with the HTTPClient on ESP32. While searching for a related issue, this one came up and it is probably related. If not, I will make a new issue.

Problem is located here:

https://github.com/espressif/arduino-esp32/blob/3f69bcfca4225ead422f322e524008408ae5e170/libraries/HTTPClient/src/HTTPClient.cpp#L372-L410

When calling end() the disconnect() call is probably doing nothing since it is likely no longer connected. This results in new calls made using the HTTPClient to not work untill some timeout has occurred or some instance of WiFiClient has made a connection to some other host.

By simply calling stop() on the WiFiClient object, this is no longer an issue.

Not sure if the best fix should be in this HTTPClient::disconnect() function, but I guess it is at least a fix for this problem. However the true problem is probably in the WiFiClient code.

IMHO this code should be executed regardless the connected() state.

https://github.com/espressif/arduino-esp32/blob/3f69bcfca4225ead422f322e524008408ae5e170/libraries/HTTPClient/src/HTTPClient.cpp#L392-L406

But then there should be an extra check on whether _client isn't a nullptr.

So it should probably something like this (untested)

void HTTPClient::disconnect(bool preserveClient)
{
    if(connected()) {
        if(_client->available() > 0) {
            log_d("still data in buffer (%d), clean up.\n", _client->available());
                _client->flush();
        }
    } else {
        log_d("tcp is closed\n");
    }
    if(_reuse && _canReuse) {
        log_d("tcp keep open for reuse");
    } else {
        log_d("tcp stop");
        if (_client != nullptr) _client->stop();
        if(!preserveClient || _client == nullptr) {
            _client = nullptr;
#ifdef HTTPCLIENT_1_1_COMPATIBLE
            if(_tcpDeprecated) {
                _transportTraits.reset(nullptr);
                _tcpDeprecated.reset(nullptr);
            }
#endif
        }
    }
}

N.B. the default for _reuse is true and _canReuse = _reuse; is called when looking at the header response.

This is corresponding with what I was saying. Good job @TD-er

Tarik2142 commented 1 year ago

I had this problem when a first HTTPS request was made using HTTPClient, and later (in another library) HTTPS requests were made using WifiClientSecure.

The error I got with that was similar to platformio/platform-espressif32#649:

_handle_error(): [send_ssl_data():<line number>]: (-80) UNKNOWN ERROR CODE (0050)

I found that client->println() throws an error (-80) UNKNOWN ERROR CODE (0050) at some point I replaced it with client->print(boundary + "\r\n"); and everything started working

VojtechBartoska commented 10 months ago

@RosiersRobin Can this issue be closed?

RosiersRobin commented 10 months ago

@VojtechBartoska I still have this issue. There seems to be no fix yet for this?

ArnieO commented 9 months ago

Very annoying issue, and I finally found an explanation here. Does anyone have a workaround while waiting for a fix?

This suggested workaround does not work for me: https://github.com/espressif/arduino-esp32/issues/3387#issuecomment-756815055