BearSSL::WiFiClientSecure not working the same way axTLS did

[artua]

Platform

• Hardware: [ESP-12]
• Core Version: [Mon May 14 20:46:47 2018 -0700]
• Development Env: [Arduino IDE]
• Operating System: [MacOS]

Settings in IDE

• Module: [Generic ESP8266 Module]
• Flash Mode: [qio]
• Flash Size: [4MB]
• lwip Variant: [v2 Lower Memory|Higher Bandwidth]
• Reset Method: [nodemcu]
• Flash Frequency: [40Mhz]
• CPU Frequency: [80Mhz]
• Upload Using: [SERIAL]
• Upload Speed: [115200]

Problem Description

BearSSL::WiFiClientSecure does not connect. No debug messages at all (debug tls+ssl+http client). My custom logs attached.

MCVE Sketch

#include <WiFiClientSecure.h>

void setup() {
 BearSSL::WiFiClientSecure client;
 if (!client.connect(host, httpsPort)) {
    res.code = 0; res.content = F("connection failed");
    return (res); // 1 = connection failed
  }
}

void loop() {

}

Debug Messages

00:01:374 Free HEAP: 36264
00:01:375 Client Secure started 1 ms
00:01:375 Free HEAP: 31704
00:01:376 connecting to api.monitec.systems
00:01:969 Connection failed 593 ms
00:01:973 Request failed. Reason: (0) connection failed

[earlephilhower]

Please check the examples. You have not set any CAs, nor have you asked it to be insecure (i.e. SSL connect but w/o checking certificates). client.setInsecure() will do the latter, before any connection.

Added #4739 to track adding some debug output beyond the GetLastError API.

[artua]

Thanks, I already found client.setInsecure().
But it still won't work and I can't get any debug output.

Debug Messages

0:01:284 connecting to api2.monitec.systems
00:02:235 Free HEAP: 10456
00:02:236 Connected 952 ms
00:02:237 fingerprint doesn't match
00:02:238 Certificate checked 1 ms
00:02:239 Free HEAP: 10456
00:02:240 requesting URL: /api/data with data: {"....."}
00:02:309 Request sent 14 ms
00:02:310 Free HEAP: 8840
00:07:312 Result length: 0 

MCVE Sketch (logger lines removed)

BearSSL::WiFiClientSecure client;
  client.setInsecure();
  client.setTimeout(API_TIMEOUT);
  client.connect(host, httpsPort);
  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);
  client.setTimeout(API_TIMEOUT);
  while (client.connected()) {
    String line = client.readStringUntil('\n');
    if (line.startsWith("HTTP/1.")) {
      res.code = line.substring(9, 12).toInt();
    }
    if (line.startsWith("Content-Length: ")) {
      c_len = line.substring(15).toInt();
    }
    if (line == "\r") {
      break;
    }
  }
  if (client.available()) {
    bytes = client.readBytes(c_buf, c_len);
    c_buf[c_len] = '\0';
  }
  res.content = String(c_buf);
  client.stop();
  return (res);
}

[earlephilhower]

@artua, can you please give a full sketch example that doesn't work and can be publicly accessible? I'm not able to reproduce it with my own testing...

[artua]

Hello @earlephilhower

Here is quick sketch for you to quickly compare two clients and debug output for both.
Just comment bearssl client and uncomment axtls client if you wish to compare.

Maybe timeout is hardcoded or setTimeout() not working?

Also please note it takes almost 500ms more for BearSSL to connect. It's huge for tiny battery-powered devices.

Sketch

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

const int API_TIMEOUT = 8000;
struct Result {
  int code;
  String content;
};
  Result res;

String line;
int myWdt;
const char* host = "el-sag.com";
const char* url = "/bearssl.txt";
const int httpsPort = 443;
long init_ms;
String data = "{}";
bool TOUT;
  int c_len;
  char c_buf[512];
  int bytes;

void setup() {
  // put your setup code here, to run once:
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() {
  myWdt = millis();
  BearSSL::WiFiClientSecure client;
  client.setInsecure();
  //WiFiClientSecure client;

  client.setTimeout(API_TIMEOUT);
  logger("Client Secure started " + String(millis() - myWdt) + " ms");
  logger("Free HEAP: " + String(ESP.getFreeHeap()));
  logger("connecting to " + String(host));
  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()));
  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);

  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") {
      logger("Headers received " + String(millis() - myWdt) + " ms");
      logger("Free HEAP: " + String(ESP.getFreeHeap()));
      TOUT=0;
      break;
    }
  }
  if(TOUT) { 
    logger("\n*** Timeout receiving headers\n");
    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) { 
    logger("\n*** Timeout receiving body\n" + String());
    return;
  }
  res.content = String(c_buf);
  logger("Result length: " + String(res.content.length()) + " | " + String(bytes));
  logger("Content received " + String(millis() - myWdt) + " ms");
  logger("Free HEAP: " + String(ESP.getFreeHeap()));
  myWdt = millis();
  client.stop();
  logger("Client stop " + String(millis() - myWdt) + " ms");
  logger("Free HEAP: " + String(ESP.getFreeHeap()));
  logger("\n*** Result: " + res.content);
}

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 (BearSSL)

SDK:2.2.1(cfd48f3)/Core:2.4.1-84-g83ab0343/lwIP:2.0.3(STABLE-2_0_3_RELEASE/glue:arduino-2.4.1-7-g2b827f8)
Connecting to Wifiscandone
.scandone
state: 0 -> 2 (b0)
state: 2 -> 3 (0)
state: 3 -> 5 (10)
add 0
aid 2
cnt 

connected with G14, channel 11
dhcp client start...
ip:192.168.3.43,mask:255.255.255.0,gw:192.168.3.200

00:00:205 Free HEAP: 46392
00:00:206 Client Secure started 0 ms
00:00:206 Free HEAP: 41832
00:00:207 connecting to el-sag.com
00:01:593 Free HEAP: 19160
00:01:594 Connected 1387 ms
00:01:595 Free HEAP: 19160
00:01:595 requesting URL: /bearssl.txt with data: {}
00:01:610 Request sent 14 ms
00:01:611 Free HEAP: 17544
00:01:734 Got HTTP code 200
00:01:742 Got Content-length: 21
00:01:745 Headers received 134 ms
00:01:746 Free HEAP: 19096
00:01:747 Result length: 21 | 21
00:01:747 Content received 1 ms
00:01:748 Free HEAP: 19080
00:01:754 Client stop 3 ms
00:01:755 Free HEAP: 41408
00:01:759 
*** Result: {"result":"success"}

00:01:765 Client Secure started 0 ms
00:01:770 Free HEAP: 41720
00:01:774 connecting to el-sag.com
00:03:125 Free HEAP: 19080
00:03:126 Connected 1348 ms
00:03:127 Free HEAP: 19080
00:03:127 requesting URL: /bearssl.txt with data: {}
00:03:142 Request sent 14 ms
00:03:143 Free HEAP: 17464
00:03:262 Got HTTP code 200
00:03:269 Got Content-length: 21
00:03:272 Headers received 129 ms
00:03:273 Free HEAP: 19080
00:03:274 Result length: 21 | 21
00:03:275 Content received 1 ms
00:03:275 Free HEAP: 19080
00:03:281 Client stop 3 ms
00:03:282 Free HEAP: 41408
00:03:286 
*** Result: {"result":"success"}

00:03:292 Client Secure started 0 ms
00:03:297 Free HEAP: 41720
00:03:301 connecting to el-sag.com
00:04:647 Free HEAP: 19080
00:04:648 Connected 1343 ms
00:04:649 Free HEAP: 19080
00:04:649 requesting URL: /bearssl.txt with data: {}
00:04:664 Request sent 13 ms
00:04:664 Free HEAP: 17464
00:04:785 Got HTTP code 200
00:04:793 Got Content-length: 21
00:04:796 Headers received 131 ms
00:04:797 Free HEAP: 19080
00:04:798 Result length: 21 | 21
00:04:798 Content received 1 ms
00:04:799 Free HEAP: 19080
00:04:806 Client stop 3 ms
00:04:806 Free HEAP: 41408
00:04:810 
*** Result: {"result":"success"}

00:04:816 Client Secure started 0 ms
00:04:821 Free HEAP: 41720
00:04:825 connecting to el-sag.com
00:06:175 Free HEAP: 19080
00:06:175 Connected 1346 ms
00:06:176 Free HEAP: 19080
00:06:177 requesting URL: /bearssl.txt with data: {}
00:06:191 Request sent 14 ms
00:06:192 Free HEAP: 17464
00:06:313 Got HTTP code 200
00:06:314 
*** Timeout receiving headers

00:06:315 Client Secure started 0 ms
00:06:316 Free HEAP: 41720
00:06:316 connecting to el-sag.com
00:07:716 Free HEAP: 19080
00:07:717 Connected 1397 ms
00:07:718 Free HEAP: 19080
00:07:719 requesting URL: /bearssl.txt with data: {}
00:07:733 Request sent 14 ms
00:07:734 Free HEAP: 17464
00:07:869 Got HTTP code 200
00:07:869 
*** Timeout receiving headers

00:07:871 Client Secure started 0 ms
00:07:872 Free HEAP: 41720
00:07:872 connecting to el-sag.com
00:09:239 Free HEAP: 19080
00:09:240 Connected 1364 ms
00:09:240 Free HEAP: 19080
00:09:241 requesting URL: /bearssl.txt with data: {}
00:09:256 Request sent 15 ms
00:09:257 Free HEAP: 17464
00:09:382 Got HTTP code 200
00:09:382 
*** Timeout receiving headers

00:09:384 Client Secure started 0 ms
00:09:385 Free HEAP: 41720
00:09:385 connecting to el-sag.com
pm open,type:2 0
00:10:805 Free HEAP: 18560
00:10:806 Connected 1418 ms
00:10:807 Free HEAP: 18560
00:10:808 requesting URL: /bearssl.txt with data: {}
00:10:822 Request sent 14 ms
00:10:823 Free HEAP: 16944
00:10:949 Got HTTP code 200
00:10:950 
*** Timeout receiving headers

00:10:952 Client Secure started 0 ms
00:10:952 Free HEAP: 41200
00:10:953 connecting to el-sag.com
00:12:304 Free HEAP: 18560
00:12:305 Connected 1349 ms
00:12:306 Free HEAP: 18560
00:12:306 requesting URL: /bearssl.txt with data: {}
00:12:321 Request sent 14 ms
00:12:322 Free HEAP: 16944
00:12:442 Got HTTP code 200
00:12:450 Got Content-length: 21
00:12:453 Headers received 130 ms
00:12:453 Free HEAP: 18560
00:12:454 Result length: 21 | 21
00:12:455 Content received 1 ms
00:12:456 Free HEAP: 18560
00:12:462 Client stop 3 ms
00:12:463 Free HEAP: 40760
00:12:466 
*** Result: {"result":"success"}

00:12:473 Client Secure started 0 ms
00:12:478 Free HEAP: 41072
00:12:481 connecting to el-sag.com
00:13:828 Free HEAP: 18560
00:13:829 Connected 1342 ms
00:13:829 Free HEAP: 18560
00:13:830 requesting URL: /bearssl.txt with data: {}
00:13:845 Request sent 14 ms
00:13:846 Free HEAP: 16944
00:13:969 Got HTTP code 200
00:13:970 
*** Timeout receiving headers

00:13:971 Client Secure started 0 ms
00:13:972 Free HEAP: 41200
00:13:972 connecting to el-sag.com
00:15:452 Free HEAP: 18560
00:15:453 Connected 1478 ms
00:15:454 Free HEAP: 18560
00:15:454 requesting URL: /bearssl.txt with data: {}
00:15:469 Request sent 13 ms
00:15:470 Free HEAP: 16944
00:15:651 Got HTTP code 200
00:15:652 
*** Timeout receiving headers

00:15:654 Client Secure started 1 ms
00:15:654 Free HEAP: 41200
00:15:655 connecting to el-sag.com
00:17:121 Free HEAP: 18560
00:17:122 Connected 1464 ms
00:17:123 Free HEAP: 18560
00:17:123 requesting URL: /bearssl.txt with data: {}
00:17:138 Request sent 14 ms
00:17:139 Free HEAP: 16944
00:17:392 Got HTTP code 200
00:17:393 
*** Timeout receiving headers

00:17:394 Client Secure started 0 ms
00:17:395 Free HEAP: 41200
00:17:396 connecting to el-sag.com
00:18:850 Free HEAP: 18560
00:18:850 Connected 1451 ms
00:18:851 Free HEAP: 18560
00:18:852 requesting URL: /bearssl.txt with data: {}
00:18:867 Request sent 14 ms
00:18:867 Free HEAP: 16944
00:18:994 Got HTTP code 200
00:18:995 
*** Timeout receiving headers

Debug (axTLS)

SDK:2.2.1(cfd48f3)/Core:2.4.1-84-g83ab0343/lwIP:2.0.3(STABLE-2_0_3_RELEASE/glue:arduino-2.4.1-7-g2b827f8)
Connecting to Wifiscandone
.scandone
state: 0 -> 2 (b0)
state: 2 -> 3 (0)
state: 3 -> 5 (10)
add 0
aid 2
cnt 

connected with G14, channel 11
dhcp client start...
ip:192.168.3.43,mask:255.255.255.0,gw:192.168.3.200

00:00:204 Free HEAP: 45896
00:00:205 Client Secure started 0 ms
00:00:206 Free HEAP: 45896
00:00:206 connecting to el-sag.com
00:01:094 Free HEAP: 31432
00:01:095 Connected 886 ms
00:01:096 Free HEAP: 31432
00:01:098 requesting URL: /bearssl.txt with data: {}
00:01:104 Request sent 4 ms
00:01:105 Free HEAP: 29816
00:01:245 Got HTTP code 200
00:01:255 Got Content-length: 21
00:01:260 Headers received 153 ms
00:01:261 Free HEAP: 31496
00:01:266 Result length: 21 | 21
00:01:268 Content received 6 ms
00:01:269 Free HEAP: 31368
00:01:270 Client stop 1 ms
00:01:271 Free HEAP: 31368
00:01:272 
*** Result: {"result":"success"}

00:01:288 Client Secure started 0 ms
00:01:289 Free HEAP: 46080
00:01:289 connecting to el-sag.com
00:02:146 Free HEAP: 31352
00:02:147 Connected 856 ms
00:02:148 Free HEAP: 31352
00:02:150 requesting URL: /bearssl.txt with data: {}
00:02:156 Request sent 5 ms
00:02:157 Free HEAP: 29736
00:02:295 Got HTTP code 200
00:02:306 Got Content-length: 21
00:02:311 Headers received 152 ms
00:02:312 Free HEAP: 31368
00:02:314 Result length: 21 | 21
00:02:315 Content received 2 ms
00:02:317 Free HEAP: 31496
00:02:318 Client stop 0 ms
00:02:320 Free HEAP: 31496
00:02:323 
*** Result: {"result":"success"}

00:02:339 Client Secure started 0 ms
00:02:339 Free HEAP: 46080
00:02:340 connecting to el-sag.com
00:03:213 Free HEAP: 31352
00:03:214 Connected 872 ms
00:03:215 Free HEAP: 31352
00:03:217 requesting URL: /bearssl.txt with data: {}
00:03:223 Request sent 4 ms
00:03:224 Free HEAP: 29736
00:03:361 Got HTTP code 200
00:03:372 Got Content-length: 21
00:03:377 Headers received 151 ms
00:03:378 Free HEAP: 31368
00:03:380 Result length: 21 | 21
00:03:381 Content received 2 ms
00:03:383 Free HEAP: 31528
00:03:384 Client stop 0 ms
00:03:386 Free HEAP: 31528
00:03:389 
*** Result: {"result":"success"}

00:03:405 Client Secure started 0 ms
00:03:405 Free HEAP: 46112
00:03:406 connecting to el-sag.com
00:04:376 Free HEAP: 31352
00:04:378 Connected 969 ms
00:04:379 Free HEAP: 31352
00:04:380 requesting URL: /bearssl.txt with data: {}
00:04:386 Request sent 5 ms
00:04:388 Free HEAP: 29736
00:04:525 Got HTTP code 200
00:04:535 Got Content-length: 21
00:04:540 Headers received 152 ms
00:04:541 Free HEAP: 31480
00:04:546 Result length: 21 | 21
00:04:548 Content received 5 ms
00:04:549 Free HEAP: 31240
00:04:550 Client stop 0 ms
00:04:552 Free HEAP: 31240
00:04:553 
*** Result: {"result":"success"}

00:04:569 Client Secure started 0 ms
00:04:569 Free HEAP: 45952
00:04:570 connecting to el-sag.com
00:05:465 Free HEAP: 31352
00:05:466 Connected 895 ms
00:05:468 Free HEAP: 31352
00:05:469 requesting URL: /bearssl.txt with data: {}
00:05:475 Request sent 5 ms
00:05:476 Free HEAP: 29736
00:05:620 Got HTTP code 200
00:05:630 Got Content-length: 21
00:05:635 Headers received 158 ms
00:05:636 Free HEAP: 31368
00:05:638 Result length: 21 | 21
00:05:640 Content received 2 ms
00:05:641 Free HEAP: 31496
00:05:642 Client stop 0 ms
00:05:644 Free HEAP: 31496
00:05:647 
*** Result: {"result":"success"}

[earlephilhower]

Looks like a bug in client.connected() in BearSSL. If you change that while (client.connected()) to while (TOUT) it always succeeds. Probably reporting client.connected() relative to the TCP link, which may go down before the entire SSL data has been read out. Let me take a gander...

[earlephilhower]

@artua, can you give the patch I referenced below a try (#4754)? I get full success with your example code on it. It was a race condition between the SSL fragmentation, the TCP connection, and the readout from the buffer which I didn't notice before. Very simple fix.

[artua]

@earlephilhower When it will be merged to master so I can check?

[earlephilhower]

Please make a branch that has this PR in your own repo and try it out with your test...I'll be waiting on your response before it gets into master. :)

https://help.github.com/articles/checking-out-pull-requests-locally/

[artua]

@earlephilhower yes, now it's working.
But still takes 500ms more to connect, so it is unusable on battery-powered devices. :(

Update: now it gives me timeouts with another host (powered by cloudflare, so using modern ciphers).
Try https://www.artua.com/bearssl.txt

01:22:644 Client Secure started 0 ms
01:22:649 Free HEAP: 40720
01:22:652 connecting to www.artua.com
01:23:986 Free HEAP: 18464
01:23:987 Connected 1330 ms
01:23:988 Free HEAP: 18464
01:23:988 requesting URL: /bearssl.txt with data: {}
01:24:001 Request sent 12 ms
01:24:002 Free HEAP: 16848
01:24:409 Got HTTP code 200
01:24:413 Got Content-length: 21
01:24:426 Headers received 423 ms
01:24:427 Free HEAP: 18464
01:24:428 Result length: 21 | 21
01:24:428 Content received 1 ms
01:24:429 Free HEAP: 18464
01:24:432 Client stop 2 ms
01:24:434 Free HEAP: 40912
01:24:438 
*** Result: {"result":"success"}

01:24:444 Client Secure started 0 ms
01:24:449 Free HEAP: 40976
01:24:453 connecting to www.artua.com
01:25:632 Free HEAP: 18464
01:25:633 Connected 1175 ms
01:25:634 Free HEAP: 18464
01:25:635 requesting URL: /bearssl.txt with data: {}
01:25:648 Request sent 12 ms
01:25:649 Free HEAP: 16848
01:40:649 
*** Timeout receiving headers

^^^ here I set timeout to 15000ms

[earlephilhower]

Can you leave that URL accessible for a while? I'll try tonight (12hrs or so). In the meantime, can you add a call to the client.getLastSSLError() and dump that on "timeout" as well as the state of connected()/etc. The code I saw kind of mushed up socket timeout with !connected() so it's hard to say what you're seeing from the dump.

int getLastSSLError(char *dest = NULL, size_t len = 0);

Best I can about the speed is tell you to use 160MHz, not 80MHz (avail from the menus). There's no HW acceleration of any kind in the system. Even 32-bit multiply is emulated. For EC key exchange @Adam5Wu and I have seen multi-second handshakes even at 160MHz.