ESP8266HTTPclient http.getstring() causing delays since version 2.5.1 #6501

MacSass · 2019-09-10T21:55:02Z

Basic Infos

[x ] I have read the documentation at readthedocs and the issue is not addressed there.
[x ] I have tested that the issue is present in current master branch (aka latest git).
[x ] I have searched the issue tracker for a similar issue.

Platform

Hardware: [ESP-12]
Core Version: [latest git]
Development Env: [Arduino IDE]
Operating System: [Windows]

Settings in IDE

Module: [Nodemcu]
Flash Size: [4MB]
Upload Using: [SERIAL]

Problem Description

I have a fairly simple sketch that uses ESP8266HTTPClient to pull a XML from my AVM Fritz Box router. It downloads a challenge file that is needed in ongoing process to calculate a response and login to the router ...

Since core version 2.5.1 this single HTTP request takes 5000ms longer than with previous versions. In fact the http.getString() is what causes the 5000ms delay. Same code compiled with up to version 2.5.0 the same request only takes about 300ms.

This issue does not apply to all HTTP requests, pulling the same XML from my website, the additional 5000ms time delay is not seen.

Comparing version I found there was a change in honoring the http.timout delay and I suspect that the changes made cause the http.getstring() to wait for the timeout instead of coming back directly after the file has been read.
Honor timeout in HTTPClient #6056

Unfortunately I´m not savy enough to identify the exact issue. Also, as it does not apply to all http requests, I suspect it might only happen if the webserver does not send a standard C string with correct terminating characters.
As said - that is / was no issue up to version 2.5.0

I also tried to reduce the http.timout() to e.g. 1000ms, which reduced the overall time, but still http.getstring always has to wait for the timeout, which was not the case prior to version 2.5.1.

Sample Sketch

#include <ESP8266WiFi.h>
#include <ESP8266HTTPClient.h>

const char* ssid = "mySSID";
const char* password = "myWifiPassword";

HTTPClient http;

void setup() {
  Serial.begin(9600); 
  delay(10);
  if (WiFi.status() == WL_CONNECTED) {
    Serial.print("Already connected... IP address: ");
    Serial.println(WiFi.localIP());    
  } else {
    Serial.print("Connecting to ");
    Serial.println(ssid);
    WiFi.begin(ssid, password);
  
    while (WiFi.status() != WL_CONNECTED) {
      delay(500);
      Serial.print(".");
    } 
  } 
}

void loop() {
  Serial.println("Challenge: " + getSID());   
  delay(60 * 1000);
}

String getSID() {
  unsigned long startMillis;
  startMillis = millis(); 
  //http.setTimeout(1000);
  http.begin("http://fritz.box/login_sid.lua");
  int retCode = http.GET();
  if (retCode != 200) {
    Serial.println("Get Challengd failed! " + String(retCode));
    return "false";
  }
  String result = http.getString();  // <<-- this is taking 5000ms extra since version 2.5.1
  String challenge = result.substring(result.indexOf("<Challenge>") + 11, result.indexOf("<Challenge>") + 19);
  http.end();
  Serial.print("Challenge retrieval took: ");
  Serial.println(millis() - startMillis);
  return challenge;
}

If you require any more information, please let me know.

TD-er · 2019-09-10T22:11:05Z

One of the changes in the PR you linked is the change of waiting for the number of bytes available (old) to number of bytes expected.

So I guess the Fritzbox is giving less than the expected amount of data? (or not fast enough?)

MacSass · 2019-09-10T22:26:22Z

Thanks for the fast feedback - that could well be the case ...
I took a quick look at the header returned with curl, but I did not see any content lenght header provided by the Fritz router at all ...
curl --head http://fritz.box/login_sid.lua HTTP/1.1 200 OK Connection: Keep-Alive Transfer-Encoding: chunked Content-Type: text/xml Keep-Alive: timeout=60, max=300 X-Frame-Options: SAMEORIGIN X-Content-Type-Options: nosniff X-XSS-Protection: 1; mode=block X-Frame-Options: SAMEORIGIN X-XSS-Protection: 1; mode=block X-Content-Type-Options: nosniff

From reading up, it looks like the content lenght header is not used for "chunked transfer encoding" - as the chunks have the lenght in them ....

So this might be the root cause of the issue - is there any way that this might be fixable in the library code, as this was working with no issue up to 2.5.0.

As content lenght header ist not available for chunked transfers, library should somehow be able to handle that. I´m afraid I do not fully understand the code to really understand the impact of the change from bytes available (old) the bytes expected.

TD-er · 2019-09-10T23:43:09Z

Chunked transfer will end with a 0-length chunk.
So must be terminated with something like this:

0\r\n
\r\n

See: developer.mozilla.org/en-US/docs/Web/HTTP/Headers/Transfer-Encoding

MacSass · 2019-09-11T18:50:18Z

Hello, thanks for the info.
I did a network trace of what the Fritz router sends and from what I see it seems to send well formatted chunks:

Currently my suspicion is that the change made from 2.5.0 to 2.5.1 broke the handling of a chunked response when the timout-handling was introduced.

As said - this is just a suspicion and I don´t have enough understanding of the library code to really be able to prove or even fix that ...

I would appreciate your help to verify my suspicion - if there is anything more how I could help with that, please let me know.

Thanks - MacSass

TD-er · 2019-09-11T22:05:17Z

Well, let's see "you" as the more common interpretation :)
I'm also just a user of this library

d-a-v · 2019-09-11T22:18:25Z

What would be helpful is a way to reproduce: an MCVE and an URL

MacSass · 2019-09-11T22:37:29Z

Hi,
I have posted what I considered an MCVE above - is this not a good example?

An URL is a bit harder, as this is from calling up the router internal URL. But anybody having a Fritz box router (which is very popular in Europe at least) should be able to reproduce calling up the URL
http://router-ip/login_sid.lua

I´ll dig around to see if I can find another public URL that uses chunked transfer encoding and will try duplicating with that ...

TD-er · 2019-09-11T22:41:29Z

ESPeasy does serve its web pages (and JSON) as chunked transfer :)

Jeroen88 · 2019-09-12T06:30:47Z

Also jigsaw offers several (very useful!) public test servers including chunked
@MacSass, does this test url reproduce your problem?

d-a-v · 2019-09-12T12:35:13Z

MCVE yes of course sorry, but I have no URL.

Fritz Boxes are essentially on the german market and I can't have one.

I tried jigsaw with emulation on host and it does not work, because data are greater than 64K.
I found another chunk encoded image (http://www.httpwatch.com/httpgallery/chunked/chunkedimage.aspx?0.3596292881389933) from (https://www.httpwatch.com/httpgallery/chunked/) and it works with emulation on host (33K, no 5s delay), but still too large for the esp:

14:30:56.441 -> ---- bytesRead=1024
14:30:56.441 -> :oom(24592)@WString.cpp:183
14:30:56.441 -> :stream2string: memory full (23552->24577)
14:30:56.441 -> [HTTP-Client][writeToStream] short write asked for 1024 but got 0 retry...
14:30:56.474 -> :oom(24592)@WString.cpp:183
14:30:56.474 -> :stream2string: memory full (23552->24577)
14:30:56.474 -> [HTTP-Client][writeToStream] short write asked for 1024 but got 0 failed.
14:30:56.474 -> [HTTP-Client][returnError] error(-10): Stream write error
14:30:56.474 -> [HTTP-Client][returnError] tcp stop
14:30:56.474 -> :close

Looking for another chunk-encoded source before I try to use a local one.

d-a-v · 2019-09-12T12:51:11Z

So I forged an http response with only one chunk and served it with netcat, here is the esp log:

14:49:47.033 -> [HTTP-Client][handleHeaderResponse] RX: 'HTTP/1.1 200 OK'
14:49:47.033 -> [HTTP-Client][handleHeaderResponse] RX: 'Cache-Control: no-cache, no-store'
14:49:47.033 -> [HTTP-Client][handleHeaderResponse] RX: 'Pragma: no-cache'
14:49:47.033 -> [HTTP-Client][handleHeaderResponse] RX: 'Trailer: X-HttpWatch-Sample'
14:49:47.033 -> [HTTP-Client][handleHeaderResponse] RX: 'Transfer-Encoding: chunked'
14:49:47.033 -> [HTTP-Client][handleHeaderResponse] RX: 'Content-Type: image/jpeg; charset=utf-8'
14:49:47.066 -> [HTTP-Client][handleHeaderResponse] RX: 'Expires: -1'
14:49:47.066 -> [HTTP-Client][handleHeaderResponse] RX: 'Server: Microsoft-IIS/10.0'
14:49:47.066 -> [HTTP-Client][handleHeaderResponse] RX: 'X-AspNet-Version: 4.0.30319'
14:49:47.066 -> [HTTP-Client][handleHeaderResponse] RX: 'X-Powered-By: ASP.NET'
14:49:47.066 -> [HTTP-Client][handleHeaderResponse] RX: 'Arr-Disable-Session-Affinity: True'
14:49:47.099 -> [HTTP-Client][handleHeaderResponse] RX: 'Date: Thu, 12 Sep 2019 12:42:49 GMT'
14:49:47.099 -> [HTTP-Client][handleHeaderResponse] RX: ''
14:49:47.099 -> [HTTP-Client][handleHeaderResponse] code: 200
14:49:47.099 -> [HTTP-Client][handleHeaderResponse] Transfer-Encoding: chunked
14:49:47.099 -> ----- chunkheader: '400'
14:49:47.099 -> [HTTP-Client] read chunk len: 1024
14:49:47.099 -> :c 1, 536, 1372
14:49:47.133 -> :c 1, 536, 836
14:49:47.133 -> ---- bytesRead=1024
14:49:47.133 -> [HTTP-Client][writeToStreamDataBlock] end of chunk or data (transferred: 1024).
14:49:47.133 -> ----- chunkheader: '0'
14:49:47.133 -> [HTTP-Client] read chunk len: 0
14:49:47.133 -> [HTTP-Client][end] still data in buffer (2), clean up.
14:49:47.133 -> :c0 1, 300
14:49:47.133 -> [HTTP-Client][end] tcp keep open for reuse
14:49:47.133 -> [HTTP-Client][end] tcp keep open for reuse
14:49:47.166 -> Challenge retrieval took: 187
14:49:47.166 -> :ur 1
14:49:47.166 -> :close
14:49:47.166 -> :del
14:49:47.166 -> Challenge:

"can't reproduce"

d-a-v · 2019-09-12T13:04:13Z

@TD-er

Then please could you try this MCVE with one of your esp as webserver and tell if you observes any timeout ?
(content needs to be smaller than 20K)

ESPeasy does serve its web pages (and JSON) as chunked transfer :)

TD-er · 2019-09-12T14:36:51Z

@d-a-v I was in the middle of some other testing, but you could also install one node of yours with ESPeasy.

Just the regular way of entering WiFi credentials (AP => 192.168.4.1 etc.)
Then you can just load /json on the node (or just about any page) and (almost) all are below 20k in size.

MacSass · 2019-09-12T15:58:11Z

Hello, thanks folks for helping me with this.
I did enable HTTPClient debugging on the sketch above but my output seems to look a bit different:

18:34:51.366 -> SDK:2.2.1(cfd48f3)/Core:2.5.2=20502000/lwIP:STABLE-2_1_2_RELEASE/glue:1.1-7-g82abda3/BearSSL:a143020
18:34:51.460 -> Connecting to WIFISSID
18:34:51.553 -> scandone
18:34:52.069 -> .....scandone
18:34:55.491 -> state: 0 -> 2 (b0)
18:34:55.491 -> .state: 2 -> 3 (0)
18:34:55.538 -> state: 3 -> 5 (10)
18:34:55.538 -> add 0
18:34:55.538 -> aid 4
18:34:55.538 -> cnt 
18:34:55.538 -> 
18:34:55.538 -> connected with WIFISSID, channel 13
18:34:55.585 -> dhcp client start...
18:34:56.007 -> ............ip:192.168.1.36,mask:255.255.255.0,gw:192.168.1.1
18:35:02.008 -> .[HTTP-Client][begin] url: http://fritz.box/login_sid.lua
18:35:02.054 -> [HTTP-Client][begin] host: fritz.box port: 80 url: /login_sid.lua
18:35:02.101 -> [HTTP-Client][sendRequest] type: 'GET' redirCount: 0
18:35:02.148 -> [HTTP-Client] connected to fritz.box:80
18:35:02.195 -> [HTTP-Client] sending request header
18:35:02.242 -> -----
18:35:02.242 -> GET /login_sid.lua HTTP/1.1
18:35:02.289 -> Host: fritz.box
18:35:02.289 -> User-Agent: ESP8266HTTPClient
18:35:02.336 -> Connection: close
18:35:02.336 -> Accept-Encoding: identity;q=1,chunked;q=0.1,*;q=0
18:35:02.429 -> 
18:35:02.429 -> -----
18:35:02.570 -> [HTTP-Client][handleHeaderResponse] RX: 'HTTP/1.1 200 OK'
18:35:02.617 -> [HTTP-Client][handleHeaderResponse] RX: 'Connection: close'
18:35:02.711 -> [HTTP-Client][handleHeaderResponse] RX: 'Content-Type: text/xml'
18:35:02.758 -> [HTTP-Client][handleHeaderResponse] RX: 'X-Frame-Options: SAMEORIGIN'
18:35:02.851 -> [HTTP-Client][handleHeaderResponse] RX: 'X-Content-Type-Options: nosniff'
18:35:02.898 -> [HTTP-Client][handleHeaderResponse] RX: 'X-XSS-Protection: 1; mode=block'
18:35:02.992 -> [HTTP-Client][handleHeaderResponse] RX: 'X-Frame-Options: SAMEORIGIN'
18:35:03.086 -> [HTTP-Client][handleHeaderResponse] RX: 'X-XSS-Protection: 1; mode=block'
18:35:03.133 -> [HTTP-Client][handleHeaderResponse] RX: 'X-Content-Type-Options: nosniff'
18:35:03.226 -> [HTTP-Client][handleHeaderResponse] RX: ''
18:35:03.273 -> [HTTP-Client][handleHeaderResponse] code: 200
18:35:05.477 -> pm open,type:2 0
18:35:08.196 -> [HTTP-Client][writeToStreamDataBlock] connection closed or file end (written: 165).
18:35:08.289 -> [HTTP-Client][end] tcp is closed
18:35:08.289 -> [HTTP-Client][end] tcp is closed
18:35:08.336 -> Challenge retrieval took: 6249
18:35:08.383 -> Challenge: 83f16d38

One thing I find strange - but might be a lack of my understanding:
I don´t see the "chunked transfer header" here, that I saw in the network trace when I pulled the URL via Firefox, so maybe I should make sure I do another network trace that actually reflects the ESP pulling the URL from the router - just to make sure this does not make a difference.

The http.getString() is what is actually causing the 5 second delay since version 2.5.1. as you can see here (not sure wha the pm open,type:2 0 means):

18:35:03.273 -> [HTTP-Client][handleHeaderResponse] code: 200
18:35:05.477 -> pm open,type:2 0
18:35:08.196 -> [HTTP-Client][writeToStreamDataBlock] connection closed or file end (written: 165).
18:35:08.289 -> [HTTP-Client][end] tcp is closed

Thanks again for your help and hanging in here with me with your valuable time.

Regards - MacSass

MacSass · 2019-09-12T16:33:37Z

Here is the network trace from where the ESP actually requests the URL from the router - it looks a bit different from my previous network trace, where I pulled the URL with Firefox (it was just to see how the router responds) - I hope this did not create more confusion, than it did good:

I´m not totally sure if this is still a chunked response at all as I don´t see the respective header.
Fact still is: As soon as I move from 2.5.0 to 2.5.1 I get the 5 second delay for the HTTP Client
http.getString(). The http.getString() is what is causing the delay ...

d-a-v · 2019-09-12T16:38:44Z

From your esp log above, you are not using git master (Core:2.5.2=20502000).
Can you try with git master ?

timestamps is an option that can be enabled on the arduino serial console window.

MacSass · 2019-09-12T16:45:40Z

Found the timestamp :-) and updated the debug output.

I installed the latest version via boardmanager in arduino ide (2.5.2) now - see updated debug output above - is that OK? Or do I need to manually install from git?

Thanks - MacSass

d-a-v · 2019-09-12T16:57:15Z

I could not reproduce with latest git, so it is better if you can give a try with it.

MacSass · 2019-09-12T17:02:15Z

@d-a-v :
Sorry is this is a stupid question: The latest git means I have to download from github manually and install into arduino ide manually?

Isn´t arduino boardmanager pulling the latest master version? It shows 2.5.2 now in my debug output (see above) - or should it show something different?

18:34:51.366 -> SDK:2.2.1(cfd48f3)/Core:2.5.2=20502000/lwIP:STABLE-2_1_2_RELEASE/glue:1.1-7-g82abda3/BearSSL:a143020

d-a-v · 2019-09-12T17:09:10Z

Git version installation is on the main page: https://github.com/esp8266/Arduino#quick-links
(it's manual)

Jeroen88 · 2019-09-12T19:33:06Z

From your debug information:

18:35:03.273 -> [HTTP-Client][handleHeaderResponse] code: 200

You can tell that your code passes this line. However, it does not reach this line. This is because the router does not send a 'Content-Length' header, so _size == 0. The client can not tell the size of the data it is getting.

The server does not send a 'Transfer-Encoding: chunked' header neither, and, as far as I can see, the data is not chunked, so this is correct. If it would be chunked, the client could determine the end of the data because every chunk has a size header. Since the data is not chunked, it can not determine the end of the data stream.

The combination of the missing of both headers leads to the failure, because the while loop 2 lines above this line, in combination with the if(len>0) evaluating to 'false', causes the else part to be executed. The else is here and just waits for the timeout.

My observations are:

Although I am not sure, the combination of no 'Content-Length' header and no 'Transfer-Encoding: chunked' may be not allowed. Fact is that the ESP8266Client can't handle it
Maybe it would be better to exit ::handleHeaderResponse() directly (possibly with a warning log) instead of waiting for the timeout. This will leave data unread from the server (like it does now). I do not know if this harms
I think having the client continue in this situation is not a good idea. Since the end of the stream can not be determined, the best the client can do is exit on a time out, but with the data read made available, e.g. through ::getString(). Since I think this situation is erroneous we should not put effort into this

devyte · 2019-09-12T21:58:32Z

AFAICT from w3.org and a quick look at the RFC2616 there, having neither header is not specified behavior, i.e.: either Content-Length must be present, or Transfer-Encoding: chunked must be present. If both are present, Content-Length must be ignored. I don't see mention of neither being present, hence unspecified.
I suspect that our current logic is to behave as chunked if Content-Length is missing, which agrees with the code analysis in the previous comment. Since there is no 0-length terminator chunk, you hit the timeout.
I'm closing this because I agree with @Jeroen88 : your router's headers are unspecified behavior.
I'll reopen if the analysis is proven wrong.

MacSass · 2019-09-15T22:08:26Z

Hello,
I follow your reasoning and agree that from what I have presented so far it looks like the right conclusion.
I think I need to dig a bit deeper to understand what is going on, as I get well formed chunked response from the router when I call up the URL from Firefox or using curl ...
Also I would really suprised if the router return bad formed response, as usually AVM Fritz is pretty good in what they are doing ... but of course it can still be on their side.

I will do some more investigation and in case I come to the conclusion we still have an issue in the code, I´ll do a re-open. Until then I can always go back to 2.5.0 version, which works perfectly for me.

Thanks for your time - hope to have some more details and a better undestanding of what is going on soon.

Regards - MacSass

MacSass · 2019-12-08T22:01:13Z

Hello,
unfortunately I did not have the time to dig deeper into the issue, but I´m happy to report that this has been fixed as of 2.6.0.
With 2.6.0 and up, I´m getting the nice short response times again like with version prior to 2.5.1, only 2.5.1 and 2.5.2 are causing the issue.
As said - I did not have the time to follow the changes or dig deeper into the root cause - just wanted to state that as 2.6.0 everything is great again ...

Thanks - MacSass

hojnorek · 2021-12-29T13:39:09Z

The workaround for this is to set timeout to 1 just before getString.

d-a-v · 2021-12-29T16:22:50Z

@hojnorek this is a long-time-closed issue.
If you still get problems, please open a new issue with details and mcve.

d-a-v self-assigned this Sep 11, 2019

devyte closed this as completed Sep 12, 2019

Jeroen88 mentioned this issue Sep 24, 2019

Handle HTTP Response with no content-length header espressif/arduino-esp32#3254

Closed

esp8266 locked as resolved and limited conversation to collaborators Dec 29, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

ESP8266HTTPclient http.getstring() causing delays since version 2.5.1 #6501

ESP8266HTTPclient http.getstring() causing delays since version 2.5.1 #6501

MacSass commented Sep 10, 2019

TD-er commented Sep 10, 2019

MacSass commented Sep 10, 2019 •

edited

Loading

TD-er commented Sep 10, 2019

MacSass commented Sep 11, 2019 •

edited

Loading

TD-er commented Sep 11, 2019

d-a-v commented Sep 11, 2019

MacSass commented Sep 11, 2019

TD-er commented Sep 11, 2019

Jeroen88 commented Sep 12, 2019 •

edited

Loading

d-a-v commented Sep 12, 2019 •

edited

Loading

d-a-v commented Sep 12, 2019

d-a-v commented Sep 12, 2019

TD-er commented Sep 12, 2019

MacSass commented Sep 12, 2019 •

edited

Loading

MacSass commented Sep 12, 2019

d-a-v commented Sep 12, 2019

MacSass commented Sep 12, 2019

d-a-v commented Sep 12, 2019

MacSass commented Sep 12, 2019

d-a-v commented Sep 12, 2019

Jeroen88 commented Sep 12, 2019

devyte commented Sep 12, 2019 •

edited

Loading

MacSass commented Sep 15, 2019

MacSass commented Dec 8, 2019

hojnorek commented Dec 29, 2021

d-a-v commented Dec 29, 2021

ESP8266HTTPclient http.getstring() causing delays since version 2.5.1 #6501

ESP8266HTTPclient http.getstring() causing delays since version 2.5.1 #6501

Comments

MacSass commented Sep 10, 2019

Basic Infos

Platform

Settings in IDE

Problem Description

Sample Sketch

TD-er commented Sep 10, 2019

MacSass commented Sep 10, 2019 • edited Loading

TD-er commented Sep 10, 2019

MacSass commented Sep 11, 2019 • edited Loading

TD-er commented Sep 11, 2019

d-a-v commented Sep 11, 2019

MacSass commented Sep 11, 2019

TD-er commented Sep 11, 2019

Jeroen88 commented Sep 12, 2019 • edited Loading

d-a-v commented Sep 12, 2019 • edited Loading

d-a-v commented Sep 12, 2019

d-a-v commented Sep 12, 2019

TD-er commented Sep 12, 2019

MacSass commented Sep 12, 2019 • edited Loading

MacSass commented Sep 12, 2019

d-a-v commented Sep 12, 2019

MacSass commented Sep 12, 2019

d-a-v commented Sep 12, 2019

MacSass commented Sep 12, 2019

d-a-v commented Sep 12, 2019

Jeroen88 commented Sep 12, 2019

devyte commented Sep 12, 2019 • edited Loading

MacSass commented Sep 15, 2019

MacSass commented Dec 8, 2019

hojnorek commented Dec 29, 2021

d-a-v commented Dec 29, 2021

MacSass commented Sep 10, 2019 •

edited

Loading

MacSass commented Sep 11, 2019 •

edited

Loading

Jeroen88 commented Sep 12, 2019 •

edited

Loading

d-a-v commented Sep 12, 2019 •

edited

Loading

MacSass commented Sep 12, 2019 •

edited

Loading

devyte commented Sep 12, 2019 •

edited

Loading