search

esp8266 / Arduino

ESP8266 core for Arduino
GNU Lesser General Public License v2.1
16.01k stars 13.33k forks source link

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

Closed MacSass closed 5 years ago

MacSass commented 5 years ago

Basic Infos

Platform

Settings in IDE

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 commented 5 years ago

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 commented 5 years ago

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 commented 5 years ago

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 commented 5 years ago

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: grafik

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 commented 5 years ago

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

d-a-v commented 5 years ago

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

MacSass commented 5 years ago

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 commented 5 years ago

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

Jeroen88 commented 5 years ago

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

d-a-v commented 5 years ago

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 commented 5 years ago

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 commented 5 years ago

@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 commented 5 years ago

@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 commented 5 years ago

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 commented 5 years ago

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:

grafik

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 commented 5 years ago

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 commented 5 years ago

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 commented 5 years ago

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

MacSass commented 5 years ago

@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 commented 5 years ago

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

Jeroen88 commented 5 years ago

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:

devyte commented 5 years ago

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 commented 5 years ago

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 commented 4 years ago

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 commented 2 years ago

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

d-a-v commented 2 years ago

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