BearSSL::WiFiClientSecure::connect() throws Exception

[braiden]

Basic Infos

• [X ] This issue complies with the issue POLICY doc.
• [ 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.
• [ X] If there is a stack dump, I have decoded it.
• [ X] I have filled out all fields below.

Platform

• Hardware: ESP8266
• Core Version: 2d9253e
• Development Env: Platformio
• Operating System: Debian Testing

Settings in IDE

• Module: Wemos D1 mini
• Flash Mode: dout
• Flash Size: 4MB
• lwip Variant: -DLWIP_OPEN_SRC -DLWIP_FEATURES=1 -DLWIP_IPV6=0
• Reset Method: nodemcu
• Flash Frequency: 80Mhz
• CPU Frequency: 80Mhz
• Upload Using: SERIAL
• Upload Speed: 1M

Problem Description

BearSSL::WiFiClientSecure::connect() throws Exception while connecting. The issue happens about 3/10. So the sketch below fails in a few seconds. Both a hostname of "mqtt.2030.ltsapis.goog" and a call to configTime() are required or the bug doesn't happen (or happens much much less often.)

Also, an exception is not always thrown, sometimes connect() completes successfully but memory elsewhere not owned by wifi client is corrupted. I could provide another sketch demonstrating this, but thought the exception more useful.

The sketch omits X509List, same issue happens with valid certs.

MCVE Sketch

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

WiFiClientSecure *client;

void setup() {
  Serial.begin(115200);

  WiFi.mode(WIFI_STA);
  WiFi.hostname("test");
  WiFi.begin("redacted", "redacted");
  while (WiFi.status() != WL_CONNECTED) delay(10);
  Serial.println("WiFi Connected");

  configTime(0, 0, "pool.ntp.org");
  while (time(nullptr) < 1514764800) delay(10);
  Serial.println("NTP Time Synced");

  client = new WiFiClientSecure();
}

void loop() {
  Serial.print(".");
  client->connect("mqtt.2030.ltsapis.goog", 443); // BAD
  // client->connect("google.com", 443); // OK
  client->stop();
  delay(100);
}

Debug Messages

WiFi Connected
NTP Time Synced
..
Exception (28):
epc1=0x4021292e epc2=0x00000000 epc3=0x00000000 excvaddr=0x00000013 depc=0x00000000

Exception Cause: 28  [LoadProhibited: A load referenced a page mapped with an attribute that does not permit loads]

0x4021292e: pbuf_free_LWIP2 at ??:?
0x4020eda0: esp2glue_lwip_init at /home/gauchard/dev/esp8266/esp8266/tools/sdk/lwip2/builder/glue-lwip/lwip-git.c:404
0x401008d5: ppEnqueueRxq at ??:?
0x40248292: ethernet_input at /home/gauchard/dev/esp8266/esp8266/tools/sdk/lwip2/builder/glue-esp/lwip-esp.c:330
0x4023def1: ppCheckTxIdle at ??:?
0x4023dfb0: ppCheckTxIdle at ??:?
0x4023d8ce: ppPeocessRxPktHdr at ??:?
0x40000f49: ?? ??:0
0x40000f49: ?? ??:0
0x40000e19: ?? ??:0
0x40001878: ?? ??:0
0x40104214: call_user_start_local at ??:?
0x4010421a: call_user_start_local at ??:?
0x4010000d: call_user_start at ??:?
0x40100484: cont_ret at /home/braiden/.platformio/packages/framework-arduinoespressif8266@src-31d658a59f41540201fc3726a1394910/cores/esp8266/cont.S:142
0x40100425: cont_continue at /home/braiden/.platformio/packages/framework-arduinoespressif8266@src-31d658a59f41540201fc3726a1394910/cores/esp8266/cont.S:51
0x40253f80: sleep_reset_analog_rtcreg_8266 at ??:?
0x40100d06: pp_post at ??:?
0x401040f0: lmacTxFrame at ??:?
0x40103313: lmacRecycleMPDU at ??:?
0x40103776: lmacRecycleMPDU at ??:?
0x4010325a: lmacProcessTxSuccess at ??:?
0x401020d7: wDev_ProcessFiq at ??:?
0x4000050c: ?? ??:0
0x40101dd4: wDev_ProcessFiq at ??:?
0x4021aaa0: sha2big_out at /home/earle/Arduino/hardware/esp8266com/esp8266/tools/sdk/ssl/bearssl/src/hash/sha2big.c:172
0x40231534: ieee80211_send_nulldata at ??:?
0x4023eb87: pp_attach at ??:?
0x4023ebd6: pp_attach at ??:?
0x4023ece2: pp_attach at ??:?
0x4023dc7f: ppTxPkt at ??:?
0x4023104b: ieee80211_send_setup at ??:?
0x40104793: wdt_feed at ??:?
0x401049ed: ets_timer_disarm at ??:?
0x4000050c: ?? ??:0
0x4020ea5d: dhcps_start at /home/gauchard/dev/esp8266/esp8266/tools/sdk/lwip2/builder/glue-esp/lwip-esp.c:384
0x40217d44: inet_chksum_pseudo at /home/gauchard/dev/esp8266/esp8266/tools/sdk/lwip2/builder/lwip2-src/src/core/inet_chksum.c:323
0x4020ecdf: lwiperr_check at /home/gauchard/dev/esp8266/esp8266/tools/sdk/lwip2/builder/glue-lwip/lwip-git.c:167
0x4020f0d0: do_memp_malloc_pool at /home/gauchard/dev/esp8266/esp8266/tools/sdk/lwip2/builder/lwip2-src/src/core/memp.c:295
0x40216600: etharp_query at /home/gauchard/dev/esp8266/esp8266/tools/sdk/lwip2/builder/lwip2-src/src/core/ipv4/etharp.c:953
0x4020ecdf: lwiperr_check at /home/gauchard/dev/esp8266/esp8266/tools/sdk/lwip2/builder/glue-lwip/lwip-git.c:167
0x40100d06: pp_post at ??:?
0x4010410b: lmacRxDone at ??:?
0x40216854: ip4addr_aton at /home/gauchard/dev/esp8266/esp8266/tools/sdk/lwip2/builder/lwip2-src/src/core/ipv4/ip4_addr.c:179
0x40101bfa: trc_NeedRTS at ??:?
0x40217268: ip4_output_if at /home/gauchard/dev/esp8266/esp8266/tools/sdk/lwip2/builder/lwip2-src/src/core/ipv4/ip4.c:792
0x4010203a: wDev_ProcessFiq at ??:?
0x40217d44: inet_chksum_pseudo at /home/gauchard/dev/esp8266/esp8266/tools/sdk/lwip2/builder/lwip2-src/src/core/inet_chksum.c:323
0x402172b0: autoip_start_probing at /home/gauchard/dev/esp8266/esp8266/tools/sdk/lwip2/builder/lwip2-src/src/core/ipv4/autoip.c:300
0x40204c91: user_init at /home/braiden/.platformio/packages/framework-arduinoespressif8266@src-31d658a59f41540201fc3726a1394910/cores/esp8266/core_esp8266_main.cpp:261
0x402172d6: autoip_start_probing at /home/gauchard/dev/esp8266/esp8266/tools/sdk/lwip2/builder/lwip2-src/src/core/ipv4/autoip.c:314
0x40217e4f: inet_chksum_pbuf at /home/gauchard/dev/esp8266/esp8266/tools/sdk/lwip2/builder/lwip2-src/src/core/inet_chksum.c:580
0x40213733: tcp_write_checks at /home/gauchard/dev/esp8266/esp8266/tools/sdk/lwip2/builder/lwip2-src/src/core/tcp_out.c:311
 (inlined by) tcp_write at /home/gauchard/dev/esp8266/esp8266/tools/sdk/lwip2/builder/lwip2-src/src/core/tcp_out.c:432
0x40213629: tcp_build_sack_option at /home/gauchard/dev/esp8266/esp8266/tools/sdk/lwip2/builder/lwip2-src/src/core/tcp_out.c:1207
 (inlined by) tcp_output_fill_options at /home/gauchard/dev/esp8266/esp8266/tools/sdk/lwip2/builder/lwip2-src/src/core/tcp_out.c:1894
0x40213f7c: tcp_route at /home/gauchard/dev/esp8266/esp8266/tools/sdk/lwip2/builder/lwip2-src/src/core/tcp_out.c:136
 (inlined by) tcp_output at /home/gauchard/dev/esp8266/esp8266/tools/sdk/lwip2/builder/lwip2-src/src/core/tcp_out.c:1290
0x4021406a: tcp_output at /home/gauchard/dev/esp8266/esp8266/tools/sdk/lwip2/builder/lwip2-src/src/core/tcp_out.c:1357
0x4020614c: _umm_free at /home/braiden/.platformio/packages/framework-arduinoespressif8266@src-31d658a59f41540201fc3726a1394910/cores/esp8266/umm_malloc/umm_malloc.cpp:1320
0x40206574: run_scheduled_functions() at /home/braiden/.platformio/packages/framework-arduinoespressif8266@src-31d658a59f41540201fc3726a1394910/cores/esp8266/PolledTimeout.h:218
 (inlined by) ?? at /home/braiden/.platformio/packages/framework-arduinoespressif8266@src-31d658a59f41540201fc3726a1394910/cores/esp8266/PolledTimeout.h:230
 (inlined by) ?? at /home/braiden/.platformio/packages/framework-arduinoespressif8266@src-31d658a59f41540201fc3726a1394910/cores/esp8266/PolledTimeout.h:161
 (inlined by) ?? at /home/braiden/.platformio/packages/framework-arduinoespressif8266@src-31d658a59f41540201fc3726a1394910/cores/esp8266/PolledTimeout.h:168
 (inlined by) run_scheduled_functions() at /home/braiden/.platformio/packages/framework-arduinoespressif8266@src-31d658a59f41540201fc3726a1394910/cores/esp8266/Schedule.cpp:119
0x40217d68: inet_cksum_pseudo_base at /home/gauchard/dev/esp8266/esp8266/tools/sdk/lwip2/builder/lwip2-src/src/core/inet_chksum.c:269
 (inlined by) inet_chksum_pseudo at /home/gauchard/dev/esp8266/esp8266/tools/sdk/lwip2/builder/lwip2-src/src/core/inet_chksum.c:326
0x4021296e: pbuf_alloc_LWIP2 at /home/gauchard/dev/esp8266/esp8266/tools/sdk/lwip2/builder/lwip2-src/src/core/pbuf.c:234
0x40204c6a: optimistic_yield at ??:?
0x40204cb5: user_init at /home/braiden/.platformio/packages/framework-arduinoespressif8266@src-31d658a59f41540201fc3726a1394910/cores/esp8266/core_esp8266_main.cpp:273
0x40203079: BearSSL::WiFiClientSecure::_run_until(unsigned int, bool) at /home/braiden/.platformio/packages/framework-arduinoespressif8266@src-31d658a59f41540201fc3726a1394910/libraries/ESP8266WiFi/src/WiFiClientSecureBearSSL.cpp:452 (discriminator 1)
0x4021d148: br_ssl_hs_client_run at /home/earle/Arduino/hardware/esp8266com/esp8266/tools/sdk/ssl/bearssl/src/ssl/ssl_hs_client.c:966
0x4021d0f0: br_ssl_hs_client_run at /home/earle/Arduino/hardware/esp8266com/esp8266/tools/sdk/ssl/bearssl/src/ssl/ssl_hs_client.c:957
0x4021cbfe: br_ssl_engine_compute_master at /home/earle/Arduino/hardware/esp8266com/esp8266/tools/sdk/ssl/bearssl/src/ssl/ssl_engine.c:1334
0x40203328: BearSSL::WiFiClientSecure::_connectSSL(char const*) at /home/braiden/.platformio/packages/framework-arduinoespressif8266@src-31d658a59f41540201fc3726a1394910/libraries/ESP8266WiFi/src/WiFiClientSecureBearSSL.cpp:931
0x40203520: BearSSL::WiFiClientSecure::_connectSSL(char const*) at /home/braiden/.platformio/packages/toolchain-xtensa/xtensa-lx106-elf/include/c++/4.8.2/bits/shared_ptr_base.h:781
 (inlined by) ?? at /home/braiden/.platformio/packages/toolchain-xtensa/xtensa-lx106-elf/include/c++/4.8.2/bits/shared_ptr.h:93
 (inlined by) BearSSL::WiFiClientSecure::_connectSSL(char const*) at /home/braiden/.platformio/packages/framework-arduinoespressif8266@src-31d658a59f41540201fc3726a1394910/libraries/ESP8266WiFi/src/WiFiClientSecureBearSSL.cpp:1011
0x40204b7c: init_done() at /home/braiden/.platformio/packages/framework-arduinoespressif8266@src-31d658a59f41540201fc3726a1394910/cores/esp8266/core_esp8266_main.cpp:181
0x4020511b: init at /home/braiden/.platformio/packages/framework-arduinoespressif8266@src-31d658a59f41540201fc3726a1394910/cores/esp8266/core_esp8266_wiring.cpp:214
0x4020215d: WiFiClient::connect(IPAddress, unsigned short) at /home/braiden/.platformio/packages/framework-arduinoespressif8266@src-31d658a59f41540201fc3726a1394910/libraries/ESP8266WiFi/src/include/ClientContext.h:142
 (inlined by) WiFiClient::connect(IPAddress, unsigned short) at /home/braiden/.platformio/packages/framework-arduinoespressif8266@src-31d658a59f41540201fc3726a1394910/libraries/ESP8266WiFi/src/WiFiClient.cpp:170
0x4020363d: thunk_br_ssl_engine_recvapp_ack at ??:?
0x40206e30: __run_user_rf_pre_init() at ??:?
0x40206e30: __run_user_rf_pre_init() at ??:?
0x4020110e: loop at /home/braiden/src/esp8266/wifibug/src/wifi.ino:29
0x40204c30: optimistic_yield at /home/braiden/.platformio/packages/framework-arduinoespressif8266@src-31d658a59f41540201fc3726a1394910/cores/esp8266/core_esp8266_main.cpp:111

[edit, updated stack with debug symbols for local files]

[braiden]

Update:

I replaced tools/sdk/lib/libbearssl.a with a version I built from https://www.bearssl.org/git/BearSSL@e4edfb84eda32c3b3aa548f975c4a13d406db989

Issue seems to be fixed. Maybe BearSSL lib needs to be updated? Or, maybe my library was compiled with different flags? I did:

make \
  CC=~/.platformio/packages/toolchain-xtensa/bin/xtensa-lx106-elf-gcc \
  LD=~/.platformio/packages/toolchain-xtensa/bin/xtensa-lx106-elf-ld \
  AR=~/.platformio/packages/toolchain-xtensa/bin/xtensa-lx106-elf-ar \
  LDDLL=~/.platformio/packages/toolchain-xtensa/bin/xtensa-lx106-elf-ld 

and copied ~/build/libbearssl.a to tools/sdk/lib/libbearssl.a.

[braiden]

Update 2:

Spoke too soon. With my version of libbearssl.a my real sketch doesn't work anymore. Aborts every time at BearSSL::WiFiClientSecure::_connectSSL(). So i'm not sure my previous comment is meaningful.

Building from the correct https://github.com/earlephilhower/bearssl-esp8266 the issue remains as originally described.

[earlephilhower]

@d-a-v, I'm seeing this crashing inside LWIP wrappers. Any ideas?

[braiden]

I've been looking a lot at exception too, and think its misleading. My theory, and some evidence below, is the exception happens because bearssl corrupts LWIP memory and causes the eventual crash. Instead I've been using a second sketch based on my comment: "sometimes connect() completes successfully but memory elsewhere not owned by wifi client is corrupted".

Seems like br_ssl_engine_recvrec_ack is writing out-of-bounds somehow. The following sketch demonstrates the issue:

The idea is head and tail are zero'd memory. Each loop, I check that that's still true, and if not, dump the contents. So eventually to program dumps non-zero content. When the corruption happens the corrupted address is mostly predictable, so I chased it further with gdb watch points to narrow down what was changing the values.

#include <ESP8266WiFi.h>
#include <WiFiClientSecure.h>
#include <time.h>
//#include <GDBStub.h>


static const int pad = 768;
char *head;
WiFiClientSecure *client;
char *tail;

void hexDump(char *addr, int size) {
  for (char *row = (char *)(uint32_t(addr) & 0xfffffff0); row < addr + size; row += 16) {
    Serial.printf("%08x: ", (uint32_t) row);
    for (char *col = row; col < row + 16; col++) {
      if ((col < addr) || (col > addr + size)) {
        Serial.print("__");
      } else {
        Serial.printf("%02x", *col);
      }
    }
    Serial.printf("\r\n");
  }
  Serial.println();
}

void setup() {
  Serial.begin(115200);
  //gdbstub_init();

  WiFi.mode(WIFI_STA);
  WiFi.hostname("...");
  WiFi.begin("braiden", "...");
  while (WiFi.status() != WL_CONNECTED) delay(10);
  Serial.println("WiFi Connected");

  tail = (char *) calloc(pad, sizeof(char));
  client = new WiFiClientSecure();
  head = (char *) calloc(pad, sizeof(char));

  client->setX509Time(1558874730);
  Serial.printf("head=%08x\r\n", head);
  Serial.printf("client=%08x\r\n", client); 
  Serial.printf("tail=%08x\r\n", tail);
  Serial.println();
}

void loop() {
  Serial.print(".");
  if (memcmp(head, tail, pad)) {
    hexDump(head, pad);
    hexDump((char *)client, sizeof(WiFiClientSecure));
    hexDump(tail, pad);
    while (true) delay(1000);
  }
  client->connect("mqtt.2030.ltsapis.goog", 443);
  delay(1000);
}

Turns out br_ssl_engine_recvrec_ack corrupts the memory

WiFiClientSecureBearSSL.cpp:

 523           Serial.printf("br_ssl_engine_recvrec_ack: %08x\r\n", *(uint16_t *)(0x3ffefe90));
 524           br_ssl_engine_recvrec_ack(_eng, rlen);
 525           Serial.printf("br_ssl_engine_recvrec_ack: %08x\r\n", *(uint16_t *)(0x3ffefe90));

Prints:

br_ssl_engine_recvrec_ack: 00000000
br_ssl_engine_recvrec_ack: 00009045

0x3ffefe90 is part of the memory allocated by tail = calloc() and never free()'d so it should not be changed by br_ssl_engine_recvrec_ack.

[d-a-v]

I tried OP sketch and it works no error if

• running @160Mhz
• and selecting basic SSL ciphers

Otherwise, I get WDT.

In that type of sketch, making a (SSL or not) connection to a server every 0.1s greatly increases the chances to be temporarily banned, making things worse to debug.

(edit: 150 successful connections, no fail, 10s between each)

[braiden]

"... and selecting basic SSL ciphers".

Does that imply -DBEARSSL_SSL_BASIC? I was also just trying that too. And it leads me to suspect the reason mqtt.googleapis.com works reliably but mqtt.2030.ltsapis.goog does not is a difference in ciphers?

mqtt.googleapis.com works regardless of DBEARSSL_SSL_BASIC.

mqtt.2030.ltsapis.goog never works with -DBEARSSL_SSL_BASIC. It throws no exception and has no negative side-effects, but the MqttClient wrapping the connection disconnects immediately. With -DBEARSSL_SSL_BASIC unset, it works completely or crashes.

Thanks both for your help!

[d-a-v]

my tests are run on mqtt.2030.ltsapis.goog like in OP.

mqtt.2030.ltsapis.goog never works with -DBEARSSL_SSL_BASIC

Have you tried at 160MHz (option in menu) ?
Are you using Arduino IDE ?

[braiden]

I'm using platformio with build_flags = -DBEARSSL_SSL_BASIC and board_build.f_cpu = 160000000L.

Running the basic connect loop sketch with -DDEBUG_ESP_SSL and without -DBEARSSL_SSL_BASIC will either print the expected BSSL:Couldn't connect. Error = 'Chain could not be linked to a trust anchor.' or crash. It will completely connect if I setup trust roots.

Adding -DBEARSSL_SSL_BASIC the sketch only prints BSSL:Couldn't connect. Error = 'Unknown error code.'. It never crashes, but it also never connects.

[braiden]

FYI, https://cloud.google.com/iot/docs/how-tos/mqtt-bridge#using_a_long-term_mqtt_domain cites TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256 as the cipher suite for this server.

That's disabled if -DBEARSSL_SSL_BASIC is set.

[earlephilhower]

Your sample code can never actually connect to anything. No trust anchor was set, and setInsecure wasn't used. Enabling debugging will give you the warning. See the BSSL_Validation example for more info.

That's a "no trust anchor" error and should not cause a crash, though.

You'll also want to be at 160mhz, too, or you'll take too long to connect and be punted off most servers.

[earlephilhower]

Seems like br_ssl_engine_recvrec_ack is writing out-of-bounds somehow. The following sketch demonstrates the issue ...

Thanks, let me look at that more closely now. That part of the code has been pretty stable for a while, but your constant failing-to-connect may be exercising it in a different way than others' code...

Might be BSSL stack overflowing, actually, given your writeup.

[earlephilhower]

Yes, it is stack overflow. Very good debugging, @braiden!
Add "#include <StackThunk.h>" to the top and change your printf to " Serial.printf("%d.", stack_thunk_get_max_usage());" and you see that it stabilizes at 5700 bytes.

I only allocate 5600 bytes, so there is your overwrite.

It's a 1-line fix in cores/esp8266/StackThunk.cpp. Change 5600 to 5750 and your crashes should disappear. I'll do a PR ASAP.