Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Open
RosiersRobin opened this issue Apr 11, 2022 · 16 comments
Open
Labels
Area: BT&Wifi BT & Wifi related issues Resolution: Awaiting response Waiting for response of author Status: Needs investigation We need to do some research before taking next steps on this issue

Comments

@RosiersRobin
Copy link

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.
@RosiersRobin RosiersRobin added the Status: Awaiting triage Issue is waiting for triage label Apr 11, 2022
@vlastahajek
Copy link
Contributor

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

@VojtechBartoska VojtechBartoska added the Area: BT&Wifi BT & Wifi related issues label Apr 12, 2022
@VojtechBartoska
Copy link
Collaborator

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

@VojtechBartoska VojtechBartoska added Resolution: Awaiting response Waiting for response of author and removed Status: Awaiting triage Issue is waiting for triage labels Apr 12, 2022
@RosiersRobin
Copy link
Author

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
Copy link
Author

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

@TD-er
Copy link
Contributor

TD-er commented Apr 14, 2022

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 VojtechBartoska added the Status: Needs investigation We need to do some research before taking next steps on this issue label Apr 14, 2022
@VojtechBartoska
Copy link
Collaborator

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

@podaen
Copy link

podaen commented May 10, 2022

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

@RosiersRobin
Copy link
Author

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
Copy link
Contributor

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
Copy link
Contributor

TD-er commented Aug 23, 2022

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:

void HTTPClient::end(void)
{
disconnect(false);
clear();
}
/**
* disconnect
* close the TCP socket
*/
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();
}
if(_reuse && _canReuse) {
log_d("tcp keep open for reuse");
} else {
log_d("tcp stop");
_client->stop();
if(!preserveClient) {
_client = nullptr;
#ifdef HTTPCLIENT_1_1_COMPATIBLE
if(_tcpDeprecated) {
_transportTraits.reset(nullptr);
_tcpDeprecated.reset(nullptr);
}
#endif
}
}
} else {
log_d("tcp is closed\n");
}
}

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.

if(_reuse && _canReuse) {
log_d("tcp keep open for reuse");
} else {
log_d("tcp stop");
_client->stop();
if(!preserveClient) {
_client = nullptr;
#ifdef HTTPCLIENT_1_1_COMPATIBLE
if(_tcpDeprecated) {
_transportTraits.reset(nullptr);
_tcpDeprecated.reset(nullptr);
}
#endif
}
}

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
Copy link

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)

@podaen
Copy link

podaen commented Feb 3, 2023

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:

void HTTPClient::end(void)
{
disconnect(false);
clear();
}
/**
* disconnect
* close the TCP socket
*/
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();
}
if(_reuse && _canReuse) {
log_d("tcp keep open for reuse");
} else {
log_d("tcp stop");
_client->stop();
if(!preserveClient) {
_client = nullptr;
#ifdef HTTPCLIENT_1_1_COMPATIBLE
if(_tcpDeprecated) {
_transportTraits.reset(nullptr);
_tcpDeprecated.reset(nullptr);
}
#endif
}
}
} else {
log_d("tcp is closed\n");
}
}

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.

if(_reuse && _canReuse) {
log_d("tcp keep open for reuse");
} else {
log_d("tcp stop");
_client->stop();
if(!preserveClient) {
_client = nullptr;
#ifdef HTTPCLIENT_1_1_COMPATIBLE
if(_tcpDeprecated) {
_transportTraits.reset(nullptr);
_tcpDeprecated.reset(nullptr);
}
#endif
}
}

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
Copy link

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
Copy link
Collaborator

@RosiersRobin Can this issue be closed?

@RosiersRobin
Copy link
Author

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

@ArnieO
Copy link

ArnieO commented Jan 10, 2024

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: #3387 (comment)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Area: BT&Wifi BT & Wifi related issues Resolution: Awaiting response Waiting for response of author Status: Needs investigation We need to do some research before taking next steps on this issue
Projects
Development

No branches or pull requests

9 participants