WiFiClient issuing no Timeout using client.readStringUntil()

[artua]

Platform

• Hardware: [ESP-12]
• Core Version: [8ae0746]
• Development Env: [Arduino IDE]
• Operating System: [MacOS]

Settings in IDE

• Module: [Generic ESP8266 Module]
• Flash Mode: [qio]
• Flash Size: [4MB/1MB]
• lwip Variant: [v2 Lower Memory]
• Reset Method: [nodemcu]
• Flash Frequency: [40Mhz]
• CPU Frequency: [160MHz]
• Upload Using: [SERIAL]
• Upload Speed: [115200]

Problem Description

No Timeout implemented using client.readStringUntil()
Tested with WiFiClient, WiFiClientSecure, BearSSL::WiFiClientSecure

MCVE Sketch

#include <ESP8266WiFi.h>
#include <WiFiClientSecure.h>
#include <WiFiClient.h>

   WiFiClient client;

const int API_TIMEOUT = 1500;
struct Result {
  int code;
  String content;
};
  Result res;
struct Timings {
  int count;
  int conn;
  int req;
  int head;
  int body;
  int stop;
  int htout;
  int btout;
};

Timings t;

String line;
int myWdt;

const char* host = "el-sag.com";
const char* url = "/wm/tout.cgi";
const int httpsPort = 80;
long init_ms;
String data = "{}";
bool TOUT;
  int c_len;
  char c_buf[512];
  int bytes;

void setup() {
init_ms = millis();
  Serial.begin(74880);
  Serial.print("Connecting to Wifi");
  WiFi.begin();
  while (WiFi.status() != WL_CONNECTED) { Serial.print("."); delay(200); }
  Serial.println();
  logger("Free HEAP: " + String(ESP.getFreeHeap()));
  
}

void loop() {
  t.count++;
  myWdt = millis();

  client.setTimeout(API_TIMEOUT);
  logger("Client Secure started " + String(millis() - myWdt) + " ms");
  logger("Free HEAP: " + String(ESP.getFreeHeap()));
  logger("connecting to " + String(host));
  t.conn += millis() - myWdt;
  myWdt = millis();
  if (!client.connect(host, httpsPort)) {
    logger("Connection failed " + String(millis() - myWdt) + " ms");
    res.code = 0; res.content = F("connection failed");
    return; // 1 = connection failed
  }
  logger("Free HEAP: " + String(ESP.getFreeHeap()));
  t.conn += millis() - myWdt;
  logger("Connected " + String(millis() - myWdt) + " ms");
  myWdt = millis();
  
  logger("Free HEAP: " + String(ESP.getFreeHeap()));
  logger("requesting URL: " + String(url) + " with data: " + String(data));
  myWdt = millis();
  
  
  client.print(String("POST ") + url + " HTTP/1.0\r\n" +
               "Host: " + host + "\r\n"
               + "Content-Type: application/json\r\n"
               + "Content-Length: " + data.length() + "\r\n\r\n"
               + data);

  t.req += millis() - myWdt;
  logger("Request sent " + String(millis() - myWdt) + " ms");
  logger("Free HEAP: " + String(ESP.getFreeHeap()));
  client.setTimeout(API_TIMEOUT);
  
  myWdt = millis();
  TOUT=1;
  while (client.connected()) {
    line = client.readStringUntil('\n');
    if (line.startsWith("HTTP/1.")) {
      res.code = line.substring(9, 12).toInt();
      logger("Got HTTP code " + String(res.code));
    }
    if (line.startsWith("Content-Length: ")) {
      c_len = line.substring(15).toInt();
      logger("Got Content-length: " + String(c_len));
    }
    if (line == "\r") {
      t.head += millis() - myWdt;
      logger("Headers received " + String(millis() - myWdt) + " ms");
      logger("Free HEAP: " + String(ESP.getFreeHeap()));
      TOUT=0;
      break;
    }
  }
  if(TOUT) { 
    t.htout++;
    logger("\n*** Timeout receiving headers. Connected: " + String(client.connected()));
    return;
  }
  
  myWdt = millis();
  if (client.available()) {
    TOUT=1;
    //res.content += String(client.read());
    bytes = client.readBytes(c_buf, c_len);
    c_buf[c_len] = '\0';
    TOUT=0;
  }
  if(TOUT) { 
    t.btout++;
    logger("\n*** Timeout receiving body. Connected: " + String(client.connected()));
    return;
  }
  res.content = String(c_buf);
  logger("Result length: " + String(res.content.length()) + " | " + String(bytes));
  t.body += millis() - myWdt;
  logger("Content received " + String(millis() - myWdt) + " ms");
  logger("Free HEAP: " + String(ESP.getFreeHeap()));
  myWdt = millis();
  client.stop();
  t.stop += millis() - myWdt;
  logger("Client stop " + String(millis() - myWdt) + " ms");
  logger("Free HEAP: " + String(ESP.getFreeHeap()));
  logger("\n*** Result: " + res.content);
  logger(String("Cycles: ") + t.count + " Head TOUTs: " + t.htout + " Body TOUTs: " + t.btout + "\nConn ave: " + t.conn/t.count 
  + "\nReq ave: " + t.req/t.count + "\nHead ave: " + t.head/t.count 
  + "\nBody ave: " + t.body/t.count + "\nStop ave: " + t.stop/t.count + "\nOverall ave: " + (t.conn+t.req+t.head+t.body+t.stop)/t.count);
//  logger("Session size: " + String(sizeof(session)));
}

void printTS() {
  long ts = millis() - init_ms;
  int m = ts / 60000;
  int s = (ts) / 1000 - m * 60;
  int ms = ts - m * 60000 - s * 1000;
  Serial.printf("%02d:%02d:%03d ", m, s, ms);
}

void logger(String str) {
  printTS();
  Serial.println(str);
}

Debug Messages

SDK:3.0.0-dev(c0f7b44)/Core:2.4.2-96-g8ae0746e/lwIP:2.1.0(STABLE-2_1_0_RELEASE/glue:arduino-2.4.2-13-g80224f0)/BearSSL:f55a6ad
Connecting to Wifiscandone
.scandone
state: 0 -> 2 (b0)
state: 2 -> 3 (0)
state: 3 -> 5 (10)
add 0
aid 4
cnt 

connected with Welcome, channel 11
dhcp client start...
.ip:192.168.3.128,mask:255.255.255.0,gw:192.168.3.200

00:00:408 Free HEAP: 49352
00:00:408 Client Secure started 0 ms
00:00:408 Free HEAP: 49352
00:00:409 connecting to el-sag.com
00:00:594 Free HEAP: 48928
00:00:595 Connected 185 ms
00:00:595 Free HEAP: 48928
00:00:595 requesting URL: /wm/tout.cgi with data: {}
00:00:597 Request sent 1 ms
00:00:600 Free HEAP: 48232
pm open,type:2 0
00:12:362 Got HTTP code 200
00:12:368 Headers received 11765 ms
00:12:368 Free HEAP: 47984
00:12:369 Result length: 0 | 0
00:12:369 Content received 0 ms
00:12:370 Free HEAP: 47984
00:12:374 Client stop 1 ms
00:12:376 Free HEAP: 48056
00:12:380 
*** Result: 
00:12:384 Cycles: 1 Head TOUTs: 0 Body TOUTs: 0
Conn ave: 186
Req ave: 1
Head ave: 11765
Body ave: 0
Stop ave: 1
Overall ave: 11953

[Jeroen88]

Some time ago I was evaluating timeouts too. If I remember correctly, the client timeout does not take into account the time it takes to connect to the server. So the gap between 00:00:600 and (a little before) 00:12:362 is not affected by the client timeout. The following readStringUntil's are affected by the timeout, set to 1500 ms in your code. But the full read out completes in less than this time, so no timeout is triggered.

[artua]

Really? :) More than 11000ms to receive the headers (delay set on server) so the readStringUntil never timeouts!!

…

On Fri, Nov 2, 2018 at 3:05 PM Jeroen88 ***@***.***> wrote: Some time ago I was evaluating timeouts too. If I remember correctly, the client timeout does not take into account the time it takes to connect to the server. So the gap between 00:00:600 and (a little before) 00:12:362 is not affected by the client timeout. The following readStringUntil's are affected by the timeout, set to 1500 ms in your code. But the full read out completes in less than this time, so no timeout is triggered. — You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub <#5304 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AGV_3dj13CdlG1sz3Gm9UnaUOJCEINQ-ks5urEMKgaJpZM4YG-Nc> .

[Jeroen88]

Yes really, and because all data you request from your server fits in one tcp buffer, everything including the HTTP Code 200 and everything else is already downloaded to the ESP8266. So all your code does effectively is transfering bytes from the TCP buffer to your data types. This is of course very fast!
If you try BearSSL, it sets the timeout internally to 15,000 ms. In this case, if I recall correctly, you can not bypass this timeout (that is passed to Stream where it is used by readStringUnilt()), so it is always 15,000 ms.

[artua]

You are absolutely wrong. I set 10000ms delay on server, before it sends data, and set timeout 1500ms. There is no timeout at all. So it's definitely a bug here. My sketch incorrectly deals with HTTP message content (which delayed on server for another 10000ms), but it's another talk. Maybe I should remove these lines later.

…

On Sat, Nov 3, 2018 at 3:32 PM Jeroen88 ***@***.***> wrote: Yes really, and because all data you request from your server fits in one tcp buffer, everything including the HTTP Code 200 and everything else is already downloaded to the ESP8266. So all your code does effectively is transfering bytes from the TCP buffer to your data types. This is of course very fast! If you try BearSSL, it set the timeout internally to 15,000 ms. Then if I recall correctly, you can not bypass this timeout (that is passed to Stream where it is used by readStringUnilt()). — You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub <#5304 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AGV_3TQYYQsBQZo22rvnII0ciDijjH7aks5urZrOgaJpZM4YG-Nc> .

[Jeroen88]

Saying I am absolutely wrong is not very motivating to help you.

Change the readBytes() in your sketch to read a lot more than you send (don't forget to increase the buffer size if needed) and I bet you get your timeout.

[artua]

I’m not saying about readBytes now. Look at readStringUntil. It never timeouts. Try it now. The delay on server set back to 10 seconds before sending headers.

…

On Sat, Nov 3, 2018 at 6:49 PM Jeroen88 ***@***.***> wrote: Saying I am absolutely wrong is not very motivating to help you. Change the readBytes() in your sketch to read a lot more than you send (don't forget to increase the buffer size if needed) and I bet you get your timeout. — You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub <#5304 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AGV_3b70zNXOJyC_SMxdCmuP4wLc0nUBks5urcktgaJpZM4YG-Nc> .

[Jeroen88]

readBytes() and readStringUntil() use the same primitive function in Client:: You can get your timeout also if you readBytesUntil() a character that is never send, e.g. '\01'

[artua]

Sure. But please see the timeout wich never occurs in readStringUntil in my code. You can try it now, I’ve set back the delay on server.

…

On Sat, Nov 3, 2018 at 7:07 PM Jeroen88 ***@***.***> wrote: readBytes() and readStringUntil() use the same primitive function in Client:: You can get your timeout also if you readBytesUntil() a character that is never send, e.g. '\01' — You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub <#5304 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AGV_3cj4LuIiJfq5QcH1Rg7B1WvaizTUks5urc1ZgaJpZM4YG-Nc> .

[Jeroen88]

I have no time to check your code. Of you are really interested follow the timeout from HTTPClient to WiFiClient to Client to Stream.
Maybe your server starts sending after it finishes the full request. I tried to explain you the ESP8266 side. You should debug the code on the ESP side, as I explained, by trying to readStringUntil a character never send. Once you have the timeout you can try to understand why

[artua]

But the problem on the ESP side. I told you, the server set up to provide a delay in response. And the timeout never occurs.

…

On Sat, Nov 3, 2018 at 7:48 PM Jeroen88 ***@***.***> wrote: I have no time to check your code. Of you are really interested follow the timeout from HTTPClient to WiFiClient to Client to Stream. Maybe your server starts sending after it finishes the full request. I tried to explain you the ESP8266 side. You should debug the code on the ESP side, as I explained, by trying to readStringUntil a character never send. Once you have the timeout you can try to understand why — You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub <#5304 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AGV_3VQMC_d_CeCfOUJWZRf3ULB7_u3Eks5urdbLgaJpZM4YG-Nc> .

[Jeroen88]

Well good luck then

[artua]

For me it’s not a problem as of now. I rewritten the code using plain client.read() issuing timeouts by my own code. But the rest of community will benefit if the problem will be resolved. Can you please copy/paste and run my code? Maybe the problem on the (my) hardware side?

…

On Sat, Nov 3, 2018 at 7:53 PM Jeroen88 ***@***.***> wrote: Well good luck then — You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub <#5304 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AGV_3UIVgkO_vIEVJQsDFI6axEmod-PQks5urdf7gaJpZM4YG-Nc> .

[Jeroen88]

You assume a bug that is not there, the timeout is working correctly after a connection is established

[artua]

Please read it once again. The timeout is set for 1.5 seconds in the code. The server starts sending data after 10 seconds. The overal time reading the headers from the time of client connected is 12 seconds. Read it again. 12 seconds vs 1.5 seconds. The time to connect is not included. Once again. 1.5 seconds timeout set in code. 12 seconds to read == NO TIMEOUT

…

On Sat, Nov 3, 2018 at 8:15 PM Jeroen88 ***@***.***> wrote: You assume a bug that is not there, the timeout is working correctly after a connection is established — You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub <#5304 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AGV_3fXGGhfSo0JK27cphkhq8bkGyFsPks5urd08gaJpZM4YG-Nc> .