Repository navigation
Error in BearSSL when attempting to connect to secure MQTT broker #7801
Description
Basic Infos
- This issue complies with the issue POLICY doc.
- I have read the documentation at readthedocs and the issue is not addressed there.
- I have tested that the issue is present in current master branch (aka latest git).
- I have searched the issue tracker for a similar issue.
- If there is a stack dump, I have decoded it.
- I have filled out all fields below.
Platform
-
Hardware: ESP-12
-
Core Version: SDK:2.2.2-dev(38a443e)/Core:2.7.4=20704000/lwIP:STABLE-2_1_2_RELEASE/glue:1.2-30-g92add50/BearSSL:5c771be and with straight from master.
-
Development Env: Arduino IDE
-
Operating System: Ubuntu & MacOS
Settings in IDE
- Module: Nodemcu
- Flash Mode: qio
- Flash Size: 4MB
- lwip Variant: v2 Lower Memory
- Reset Method: nodemcu
- Flash Frequency: ?
- CPU Frequency: 160MHz
- Upload Using: SERIAL
- Upload Speed: 115200
Problem Description
Attempting to connect to AWS IoT. MQTT client sometime is rarely successful most of the times it errors out in BearSSL. I know the AWS IoT setup works as the credentials used on other platforms and as I said it sometimes works. Same setup used on ESP8266 with sometime success. When success works as expected. When it fails the wifi connects, the SNTP gets the time, the MQTT client gets an IP addess from AWS, then attempts to connect and fails which causes and exception. The exception is either a 28 or a 9 depending on the configuration but is always associated with the same line of code ( br_ssl_hs_client_run at src/ssl/ssl_hs_client.c line 1871).
This version uses the MQTT client but the PubSubClient has the same behavior so i don't think it has to do with these libraries.
I have built this on both my MAC Powerbook and Ubuntu 18.04 to the same effect.
I have attempted to use GDB with some success but tracing this problem usually results in a segfault on target and then GDB exits abruptly. This eliminates the ability to do a backtrace.
I have looked at the max stack usage and this doesn't look like the problem. One interesting thing is that when it fails the max has like three different levels. When successful it is always the same value.
When it fails it looks like this:
Max stack 4580, 4532, 4564, 4548 or something else.
When successful it is always:
Max stack 4596
When successful the code will print out messages sent via the AWS IOT Core test client as would be expected.
What i show is with 2.7.4 but i have pulled master and it has very similar behavior but doesn't print out the exception stack so i didn't include that.
MCVE Sketch
#include <ESP8266WiFi.h>
#include <WiFiClientSecure.h>
#include <MQTT.h>
#include <ArduinoJson.h>
#include <time.h>
#include <StackThunk.h>
#define emptyString String()
#include "secrets.h"
const int MQTT_PORT = 8883;
const char MQTT_SUB_TOPIC[] = "robo/cmds";
const char MQTT_PUB_TOPIC[] = "$aws/things/" THINGNAME "/shadow/update";
#ifdef USE_SUMMER_TIME_DST
uint8_t DST = 1;
#else
uint8_t DST = 0;
#endif
WiFiClientSecure net;
BearSSL::X509List cert(cacert);
BearSSL::X509List client_crt(client_cert);
BearSSL::PrivateKey key(privkey);
MQTTClient client;
unsigned long lastMillis = 0;
time_t now;
time_t nowish = 1510592825;
void NTPConnect(void)
{
Serial.print("Setting time using SNTP");
configTime(TIME_ZONE * 3600, DST * 3600, "pool.ntp.org", "time.nist.gov");
now = time(nullptr);
while (now < nowish)
{
delay(500);
Serial.print(".");
now = time(nullptr);
}
Serial.println("done!");
struct tm timeinfo;
gmtime_r(&now, &timeinfo);
Serial.print("Current time: ");
Serial.print(asctime(&timeinfo));
}
void messageReceived(String &topic, String &payload)
{
Serial.println("Received [" + topic + "]: " + payload);
}
void lwMQTTErr(lwmqtt_err_t reason)
{
if (reason == lwmqtt_err_t::LWMQTT_SUCCESS)
Serial.print("Success");
else if (reason == lwmqtt_err_t::LWMQTT_BUFFER_TOO_SHORT)
Serial.print("Buffer too short");
else if (reason == lwmqtt_err_t::LWMQTT_VARNUM_OVERFLOW)
Serial.print("Varnum overflow");
else if (reason == lwmqtt_err_t::LWMQTT_NETWORK_FAILED_CONNECT)
Serial.print("Network failed connect");
else if (reason == lwmqtt_err_t::LWMQTT_NETWORK_TIMEOUT)
Serial.print("Network timeout");
else if (reason == lwmqtt_err_t::LWMQTT_NETWORK_FAILED_READ)
Serial.print("Network failed read");
else if (reason == lwmqtt_err_t::LWMQTT_NETWORK_FAILED_WRITE)
Serial.print("Network failed write");
else if (reason == lwmqtt_err_t::LWMQTT_REMAINING_LENGTH_OVERFLOW)
Serial.print("Remaining length overflow");
else if (reason == lwmqtt_err_t::LWMQTT_REMAINING_LENGTH_MISMATCH)
Serial.print("Remaining length mismatch");
else if (reason == lwmqtt_err_t::LWMQTT_MISSING_OR_WRONG_PACKET)
Serial.print("Missing or wrong packet");
else if (reason == lwmqtt_err_t::LWMQTT_CONNECTION_DENIED)
Serial.print("Connection denied");
else if (reason == lwmqtt_err_t::LWMQTT_FAILED_SUBSCRIPTION)
Serial.print("Failed subscription");
else if (reason == lwmqtt_err_t::LWMQTT_SUBACK_ARRAY_OVERFLOW)
Serial.print("Suback array overflow");
else if (reason == lwmqtt_err_t::LWMQTT_PONG_TIMEOUT)
Serial.print("Pong timeout");
}
void lwMQTTErrConnection(lwmqtt_return_code_t reason)
{
if (reason == lwmqtt_return_code_t::LWMQTT_CONNECTION_ACCEPTED)
Serial.print("Connection Accepted");
else if (reason == lwmqtt_return_code_t::LWMQTT_UNACCEPTABLE_PROTOCOL)
Serial.print("Unacceptable Protocol");
else if (reason == lwmqtt_return_code_t::LWMQTT_IDENTIFIER_REJECTED)
Serial.print("Identifier Rejected");
else if (reason == lwmqtt_return_code_t::LWMQTT_SERVER_UNAVAILABLE)
Serial.print("Server Unavailable");
else if (reason == lwmqtt_return_code_t::LWMQTT_BAD_USERNAME_OR_PASSWORD)
Serial.print("Bad UserName/Password");
else if (reason == lwmqtt_return_code_t::LWMQTT_NOT_AUTHORIZED)
Serial.print("Not Authorized");
else if (reason == lwmqtt_return_code_t::LWMQTT_UNKNOWN_RETURN_CODE)
Serial.print("Unknown Return Code");
}
void connectToMqtt(bool nonBlocking = false)
{
Serial.print("MQTT connecting ");
while (!client.connected())
{
if (client.connect(THINGNAME))
{
Serial.println("connected!");
if (!client.subscribe(MQTT_SUB_TOPIC))
lwMQTTErr(client.lastError());
}
else
{
Serial.print("SSL Error Code: ");
Serial.println(net.getLastSSLError());
Serial.print("failed, reason -> ");
lwMQTTErrConnection(client.returnCode());
if (!nonBlocking)
{
Serial.println(" < try again in 5 seconds");
delay(5000);
}
else
{
Serial.println(" <");
}
}
Serial.printf("Max stack %d.", stack_thunk_get_max_usage());
if (nonBlocking)
break;
}
}
void connectToWiFi(String init_str)
{
if (init_str != emptyString)
Serial.print(init_str);
while (WiFi.status() != WL_CONNECTED)
{
Serial.print(".");
delay(1000);
}
if (init_str != emptyString)
Serial.println("ok!");
}
void checkWiFiThenMQTT(void)
{
connectToWiFi("Checking WiFi");
connectToMqtt();
}
unsigned long previousMillis = 0;
const long interval = 5000;
void checkWiFiThenMQTTNonBlocking(void)
{
connectToWiFi(emptyString);
if (millis() - previousMillis >= interval && !client.connected()) {
previousMillis = millis();
connectToMqtt(true);
}
}
void checkWiFiThenReboot(void)
{
connectToWiFi("Checking WiFi");
Serial.print("Rebooting");
ESP.restart();
}
void sendData(void)
{
DynamicJsonDocument jsonBuffer(JSON_OBJECT_SIZE(3) + 100);
JsonObject root = jsonBuffer.to<JsonObject>();
JsonObject state = root.createNestedObject("state");
JsonObject state_reported = state.createNestedObject("reported");
state_reported["value"] = random(100);
Serial.printf("Sending [%s]: ", MQTT_PUB_TOPIC);
serializeJson(root, Serial);
Serial.println();
char shadow[measureJson(root) + 1];
serializeJson(root, shadow, sizeof(shadow));
if (!client.publish(MQTT_PUB_TOPIC, shadow, false, 0))
lwMQTTErr(client.lastError());
}
void setup()
{
Serial.begin(115200);
//gdbstub_init();
delay(5000);
Serial.println();
Serial.println();
WiFi.hostname(THINGNAME);
WiFi.mode(WIFI_STA);
WiFi.begin(ssid, pass);
connectToWiFi(String("Attempting to connect to SSID: ") + String(ssid));
NTPConnect();
net.setTrustAnchors(&cert);
net.setClientRSACert(&client_crt, &key);
client.begin(MQTT_HOST, MQTT_PORT, net);
client.onMessage(messageReceived);
connectToMqtt();
}
void loop()
{
//now = time(nullptr);
if (!client.connected())
{
Serial.print("Not Connected");
checkWiFiThenMQTT();
//checkWiFiThenMQTTNonBlocking();
//checkWiFiThenReboot();
}
else
{
client.loop();
if (millis() - lastMillis > 5000)
{
lastMillis = millis();
sendData();
}
}
}
Debug Messages
SDK:2.2.2-dev(38a443e)/Core:2.7.4=20704000/lwIP:STABLE-2_1_2_RELEASE/glue:1.2-30-g92add50/BearSSL:5c771be
scandone
state: 0 -> 2 (b0)
state: 2 -> 3 (0)
state: 3 -> 0 (4)
reconnect
scandone
Attempting to connect to SSID: ARSnet...scandone
state: 0 -> 2 (b0)
.state: 2 -> 3 (0)
state: 3 -> 5 (10)
add 0
aid 15
cnt
connected with ARSnet, channel 6
dhcp client start...
ip:192.168.2.122,mask:255.255.255.0,gw:192.168.2.1
ok!
Setting time using SNTP..................pm open,type:2 0
...........done!
Current time: Thu Dec 31 00:24:09 2020
MQTT connecting BSSL:_connectSSL: start connection
BSSL:_run_until: Timeout
BSSL:_wait_for_handshake: failed
BSSL:Couldn't connect. Error = 'Unknown error code.'
SSL Error Code: 0
failed, reason -> Connection Accepted < try again in 5 seconds
Max stack 4580.Fatal exception 28(LoadProhibitedCause):
epc1=0x4022451e, epc2=0x00000000, epc3=0x00000000, excvaddr=0x0000000c, depc=0x00000000
Decoded Exception
Exception 28: LoadProhibited: A load referenced a page mapped with an attribute that does not permit loads
PC: 0x4022309a: br_ssl_hs_client_run at src/ssl/ssl_hs_client.c line 1871
EXCVADDR: 0x0000000c
Decoding stack results
0x402229e5: br_ssl_hs_client_run at src/ssl/ssl_hs_client.c line 1528
0x40221120: jump_handshake at src/ssl/ssl_engine.c line 1081
0x40221605: br_ssl_engine_recvrec_ack at src/ssl/ssl_engine.c line 1206
0x402060de: BearSSL::WiFiClientSecure::_run_until(unsigned int, bool) at /home/ccdocker/Arduino/hardware/esp8266com/esp8266/libraries/ESP8266WiFi/src/WiFiClientSecureBearSSL.cpp line 540
0x40206f08: HardwareSerial::write(unsigned char const*, unsigned int) at /home/ccdocker/Arduino/hardware/esp8266com/esp8266/cores/esp8266/HardwareSerial.h line 165
0x402072a1: Print::write(char const*) at /home/ccdocker/Arduino/hardware/esp8266com/esp8266/cores/esp8266/Print.h line 62
0x4020628d: BearSSL::WiFiClientSecure::available() at /home/ccdocker/Arduino/hardware/esp8266com/esp8266/libraries/ESP8266WiFi/src/WiFiClientSecureBearSSL.cpp line 386
0x402053aa: BearSSL::WiFiClientSecure::connected() at /home/ccdocker/Arduino/hardware/esp8266com/esp8266/libraries/ESP8266WiFi/src/WiFiClientSecureBearSSL.cpp line 260
0x40208b2d: __delay(unsigned long) at /home/ccdocker/Arduino/hardware/esp8266com/esp8266/cores/esp8266/core_esp8266_wiring.cpp line 57
0x4020a65d: MQTTClient::connected() at /home/ccdocker/Arduino/libraries/MQTT/src/MQTTClient.cpp line 398
0x40202330: connectToMqtt(bool) at /home/ccdocker/projects/2020/robot_iot_3/robot_iot_3.ino line 139
0x4020d7de: strdup at /home/earle/src/esp-quick-toolchain/repo/newlib/newlib/libc/string/strdup.c line 11
0x402024d1: setup() at /home/ccdocker/projects/2020/robot_iot_3/robot_iot_3.ino line 259
0x402085dc: loop_wrapper() at /home/ccdocker/Arduino/hardware/esp8266com/esp8266/cores/esp8266/core_esp8266_main.cpp line 194
Activity
earlephilhower commentedon Dec 31, 2020
Can you please enable full debugging in the IDE and get the logs? That often gives a better idea about handshake difficulties and such. There were also 3.0.0 changes to fix reporting of some errors that you may profit from, so consider trying the master, too.
Your crash is pretty obviously a nullptr deref inside MQTTClient (the execVADDR = 0x0000 + some offset). You would need to check the library code for that, it's not part of our stuff. Could be an OOM error on a
newor amallocnot being handled properly (you need 26KB+ free, mostly contiguous for SSL, and the JSON libraries I've seen are all monster memory hogs).schnorea commentedon Dec 31, 2020
On the logs I will give it a go and post them.
I tried 3.0.0 and the only difference was that I didn't get the exception print out so I need to find out where that get's enabled.
I also tried multiple MQTTClients had the same issue pointing to BearSSL.
I don't need JSON lib so i will remove that and try again.
Thanks for the pointers.
schnorea commentedon Dec 31, 2020
Removing JSON didn't change anything except it loads a lot quicker.
schnorea commentedon Dec 31, 2020
IDE Build Log
earlephilhower commentedon Dec 31, 2020
schnorea commentedon Dec 31, 2020
Failing output log with all debug enabled.
This log has an example of failure (the exception is decoded above).
schnorea commentedon Dec 31, 2020
Successful output log
This is an example of when it works with full debug info.
embedded in the below log is this line:
which is the result of a MQTT message sent via AWS IoT Core.
earlephilhower commentedon Dec 31, 2020
Sorry, but that doesn't look like it has BearSSL debugging enabled. The certificates sent and received (they're public certs and no private cert/key dumped so should be safe to post) as well as more handshake info is generally dumped. Make sure you're using the 2nd to last setting (longest one) as that also catches malloc fails and full logs elsewhere.
For example:
earlephilhower commentedon Dec 31, 2020
Quickly ooking at the code, it's related to the BearSSL x509 context info where the x509 cert is null. W/o code, can't really say how that could happen. If you can carve out a MCVE w/o the 3rd party libs it would be helpful. W/o it, you're going to need to be self sufficient as it's using a private client cert, to a private AWS instance, using 3rd party code which means nobody but you can repro your runs. :(
schnorea commentedon Dec 31, 2020
I'm also using the Basic SSL package (Low Memory)
schnorea commentedon Dec 31, 2020
Yeah, a hear you:(
When you say "third party libs" which ones you talking about so I am clear about what I need to do?
I'll give it a try. Thanks for the encouragement.
earlephilhower commentedon Dec 31, 2020
The JSON lib and MQTT libs aren't part of the core. Something simple and minimal that does a SSL connection attempt and gets to your failed state is what we'd need.
That said, I still think you're just out of memory and not catching it properly somewhere or in a library. It's not stack usage related, the present amount is fine for every case we know of, your reported usage is small, and when an overflow occurs it is reported as a SSL stack overflow via canaries or via massive memory corruption (not nulls).
schnorea commentedon Dec 31, 2020
I woke up with a similar thought. What if that transaction is processing things to slowly? The evidence is this:
And, if i had turned on time stamps you would see that this time out is always 15 seconds. What if sometimes that transaction takes less than 15 seconds and succeeds but most of the time it doesn't because inadequate hardware performance.
No, I like your explination better. Low memory issue draws program execution out in the sticks (exception) and it can't get back in time.
Okay the logs from above were without the JSON Lib. Next I'll try pulling the MQTT to get at the raw SSL connection.
Thanks again.
schnorea commentedon Jan 14, 2021
After a few days and a broken leg I still haven't figured this out.
I tried to decypher how to test BearSSL without the MQTT library and after looking at openssl I can't figure that out. Is there an example that anyone can point me to?
The other complication is doing it without a network connection.
earlephilhower commentedon Jan 24, 2021
Sorry to hear about the leg. I guess on the bright side, more time inside to hack?
FWIW, there was a very minor change to catch a malloc() failure while reading an EC private key. Most keys are RSA, so it may not be related at all, but see #7823. Root problem would still be OOM, and the old code would crash in the EC key reader immediately anyway.
For MQTT testing, you can set up a local mosquitto instance (that's how I debugged the client cert code while writing the BearSSL stuff) and come close to simulating AWS...while being able to see both sides of the conversation w/Wireshark and having both encryption keys.
Jason2866 commentedon Feb 9, 2021
@s-hadinger has modified/optimized bearssl (lower footprint) so it can be used with Tasmota and AWS IoT. It works stable :-)
Maybe it helps you.
s-hadinger commentedon Feb 9, 2021
Doc is here, I've been using for 18 months and it's super stable.
https://tasmota.github.io/docs/AWS-IoT/
Implementation details can be found here
https://tasmota.github.io/docs/TLS/#implementation-notes
earlephilhower commentedon Feb 9, 2021
While I have reservations about Tasmota dynamically allocating the BSSL stack(heap fragmentation could cause failure easily in my experience when trying to get a 6kb block), the other stuff looks interesting. If you or the Tasmota team would be interested in adding that option to the IDE menus (like the "minimal codes" option already) I think it would be a good addition!
s-hadinger commentedon Feb 9, 2021
I understand your reservation but ram is so precious that I need to spare it. Based on experience, tls handshakes are rare with Mqtt, while they would be common with https. This makes it sustainable on Tasmota and actually does not hurt fragmentation.
Jason2866 commentedon Feb 11, 2021
We dont use Arduino IDE, we use Platformio. I think i can speak for the whole Tasmota team we dont know how to add stuff to Arduino IDE. Sorry we cant contribute.
schnorea commentedon Feb 14, 2021
Okay this works but...
It is not stable but...
The while loop in 'connectToMqtt' will generally run until it connects.
And then I can control my robot over the internet.
I will pull the latest and see if the fixes above make it more stable.
Here are the other files.
dalbert2 commentedon Feb 10, 2023
In case it helps, I'm getting a similar crash in a RESTful client with much more memory available (typically > 28K heap free, >20K largest available block) which seems to point away from the MQTT client or low memory. However, I am using an EC certificate.
Target: ESP12E, Core:3.1.1 SDK:2.2.2-dev(38a443e) LWIP:2.1.3
Free Heap:28744 Largest:20816 Frag:24 Stack:1488
The crashes (which are intermittent), always seem to occur around the same place; see a few samples below:
Exc 9 @ 40237195: /home/earle/src/esp-quick-toolchain/arduino/tools/sdk/ssl/bearssl/src/ssl/ssl_hs_client.c:1916
Exc 0 @ 40236d44: /home/earle/src/esp-quick-toolchain/arduino/tools/sdk/ssl/bearssl/src/ssl/ssl_hs_client.c:1551
Exc 0 @ 40236ce0: /home/earle/src/esp-quick-toolchain/arduino/tools/sdk/ssl/bearssl/src/ssl/ssl_hs_client.c:1531
It looks like the exceptions are happening during the SSL connection phase. The first attempt to contact the server is an HTTPS GET request for current time (the GET time... debug output). The crash appears to happen before the http.GET() returns. Note that most of the time this code works; the exceptions are intermittent.
More of the traces: