SSLClient terminating when flushing buffer

Question

SSLClient terminating when flushing buffer

Inkomidwastaken opened this issue 4 years ago · 7 comments

I am trying to connect my ESP32 to my MQTT Broker (mosquitto on RaspberryPi) via WiFi.
My code is based on the EthernetMQTT example, but i exchanged the ethernet client for WiFi.

The esp32 succesfully connects to the Broker and publishes a first message, but afte that I get the errormessage:

(SSLClient)(SSL_WARN)(m_run_until): Terminating because the ssl engine closed
(SSLClient)(SSL_ERROR)(flush): Could not flush write buffer!

It seems that using the flush() function is crashing the sslClient, wich is unfortunate, because as described in #9, not using the flush() function after every write to the network results in an a stack overflow.

How do I go about this error? Is it possible to get a kind of stable connection?

My full code:

/**
   A BLE client example that is rich in capabilities.
   There is a lot new capabilities implemented.
   author unknown
   updated by chegewara
*/

#include <WiFi.h>
#include <PubSubClient.h>
//SSL
#include <SSLClient.h>
#include "certificates.h" // This file must be regenerated

const char my_cert[] = "FIXME";
const char my_key[] = "FIXME";
SSLClientParameters mTLS = SSLClientParameters::fromPEM(my_cert, sizeof my_cert, my_key, sizeof my_key);

// Setup Wifi
const char* ssid = "...";
const char* password = "...";

const char* mqtt_server = "192.168.2.105";

WiFiClient espClient;
SSLClient espClientSSL(espClient, TAs, (size_t)TAs_NUM, A5);
PubSubClient client(espClientSSL);

void setup_wifi() {
  delay(10);
  // We start by connecting to a WiFi network

  WiFi.begin(ssid, password);

  while (WiFi.status() != WL_CONNECTED) {
    delay(500);
    Serial.print(".");
  }

  Serial.println("");
  Serial.println("WiFi connected");
}

void reconnect() {
  // Loop until we're reconnected
  while (!client.connected()) {
    Serial.print("Attempting MQTT connection...");
    // Attempt to connect
    if (client.connect("ESP32Client")) {
      Serial.println("connected");

      // Once connected, publish an announcement...
      client.publish("outTopic", "hello world");
      // This is a workaround to address https://github.com/OPEnSLab-OSU/SSLClient/issues
      Serial.print("calling flush() \n");
      espClientSSL.flush();
      Serial.print("flush() finished \n");

      // Subscribe
      //client.subscribe("testtopic/Win");
      // This is a workaround to address https://github.com/OPEnSLab-OSU/SSLClient/issues
      //espClientSSL.flush();

    } else {
      Serial.print("failed, rc=");
      Serial.print(client.state());
      Serial.println(" try again in 5 seconds");
      // Wait 5 seconds before retrying
      delay(5000);
    }
  }
}

void callback(char* topic, byte* payload, unsigned int length) {
  Serial.print("Message arrived [");
  Serial.print(topic);
  Serial.print("] ");
  for (int i = 0; i < length; i++) {
    Serial.print((char)payload[i]);
  }
  Serial.println();
}

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

  // Enable mutual TLS with SSLClient
  espClientSSL.setMutualAuthParams(mTLS);

  //Connecting to Wifi and MQTT Broker
  setup_wifi();
  client.setServer(mqtt_server, 8883);
  client.setCallback(callback);
}

void loop() {

  //MQTT
  if (!client.connected()) {
    reconnect();
  }
  client.loop();

  //Serial.print("Attempting MQTT hello there!");

  client.publish("testtopic/ESP", "hello there!");
  // This is a workaround to address https://github.com/OPEnSLab-OSU/SSLClient/issues
  espClientSSL.flush();

  delay(3000); // Delay a second between loops.
} // End of loop

longer serial output:

...
WiFi connected
Attempting MQTT connection...connected
calling flush() 
(SSLClient)(SSL_WARN)(m_run_until): Terminating because the ssl engine closed
(SSLClient)(SSL_ERROR)(flush): Could not flush write buffer!
flush() finished 
Attempting MQTT connection...connected
calling flush()

Serverside log:

1609262639: New connection from 192.168.2.73 on port 8883.
1609262639: New client connected from 192.168.2.73 as ESP32Client (p2, c1, k15).
1609262661: Client ESP32Client has exceeded timeout, disconnecting.
1609262662: New connection from 192.168.2.73 on port 8883.
1609262662: New client connected from 192.168.2.73 as ESP32Client (p2, c1, k15).

Answer 1 · 2020-12-29T17:55:45.000Z

Hello! This bug has been really nasty thus far and it's unfortunate that you're encountering it. Would you mind posting your device logs with the debug level set to SSLClient::SSL_DUMP?

Answer 2 · 2020-12-29T19:32:01.000Z

sure:

WiFi connected
Attempting MQTT connection...(SSLClient)(SSL_INFO)(connect): Base client connected!
(SSLClient)(SSL_INFO)(m_print_br_state): (SSLClient)(SSL_INFO)(m_print_br_state): State: 
   SENDREC
(SSLClient)(SSL_INFO)(m_print_br_state): (SSLClient)(SSL_INFO)(m_print_br_state): State: 
   RECVREC
(SSLClient)(SSL_INFO)(m_run_until): m_run changed state:
(SSLClient)(SSL_INFO)(m_print_br_state): (SSLClient)(SSL_INFO)(m_print_br_state): State: 
   RECVREC
(SSLClient)(SSL_INFO)(m_run_until): Expected bytes count: 
(SSLClient)(SSL_INFO)(m_run_until): 5
(SSLClient)(SSL_INFO)(m_print_br_state): (SSLClient)(SSL_INFO)(m_print_br_state): State: 
   SENDREC
(SSLClient)(SSL_INFO)(m_print_br_state): (SSLClient)(SSL_INFO)(m_print_br_state): State: 
   RECVREC
(SSLClient)(SSL_INFO)(m_print_br_state): (SSLClient)(SSL_INFO)(m_print_br_state): State: 
   RECVREC
   SENDAPP
(SSLClient)(SSL_INFO)(m_run_until): m_run changed state:
(SSLClient)(SSL_INFO)(m_print_br_state): (SSLClient)(SSL_INFO)(m_print_br_state): State: 
   RECVREC
   SENDAPP
(SSLClient)(SSL_INFO)(m_start_ssl): Connection successful!
��MQTT��ESP32Client(SSLClient)(SSL_INFO)(m_print_br_state): (SSLClient)(SSL_INFO)(m_print_br_state): State: 
 SENDAPP
(SSLClient)(SSL_INFO)(m_print_br_state): (SSLClient)(SSL_INFO)(m_print_br_state): State: 
   SENDREC
(SSLClient)(SSL_INFO)(m_print_br_state): (SSLClient)(SSL_INFO)(m_print_br_state): State: 
   RECVREC
   SENDAPP
(SSLClient)(SSL_INFO)(m_print_br_state): (SSLClient)(SSL_INFO)(m_print_br_state): State: 
   RECVREC
(SSLClient)(SSL_INFO)(m_print_br_state): (SSLClient)(SSL_INFO)(m_print_br_state): State: 
   RECVAPP
connected
0�outTopichello world
calling flush() 
(SSLClient)(SSL_INFO)(m_print_br_state): (SSLClient)(SSL_INFO)(m_print_br_state): State: 
   RECVREC
   SENDAPP
(SSLClient)(SSL_INFO)(m_print_br_state): (SSLClient)(SSL_INFO)(m_print_br_state): State: 
   SENDAPP
(SSLClient)(SSL_INFO)(m_run_until): m_run changed state:
(SSLClient)(SSL_INFO)(m_print_br_state): (SSLClient)(SSL_INFO)(m_print_br_state): State: 
   SENDAPP
(SSLClient)(SSL_INFO)(m_print_br_state): (SSLClient)(SSL_INFO)(m_print_br_state): State: 
   SENDREC
(SSLClient)(SSL_INFO)(m_print_br_state): (SSLClient)(SSL_INFO)(m_print_br_state): State: 
   RECVREC
   SENDAPP
(SSLClient)(SSL_INFO)(m_run_until): m_run changed state:
(SSLClient)(SSL_INFO)(m_print_br_state): (SSLClient)(SSL_INFO)(m_print_br_state): State: 
   RECVREC
   SENDAPP
(SSLClient)(SSL_INFO)(m_run_until): Expected bytes count: 
(SSLClient)(SSL_INFO)(m_run_until): 5
(SSLClient)(SSL_INFO)(m_print_br_state): (SSLClient)(SSL_INFO)(m_print_br_state): State: 
   RECVREC
(SSLClient)(SSL_INFO)(m_print_br_state): (SSLClient)(SSL_INFO)(m_print_br_state): State: 
   SENDREC
(SSLClient)(SSL_INFO)(m_print_br_state): (SSLClient)(SSL_INFO)(m_print_br_state): State: 
   Connection closed
(SSLClient)(SSL_WARN)(m_run_until): Terminating because the ssl engine closed
(SSLClient)(SSL_ERROR)(flush): Could not flush write buffer!

 flush() finished 
Attempting MQTT connection...(SSLClient)(SSL_INFO)(connect): Base client connected!
(SSLClient)(SSL_INFO)(m_get_session_index): 192.168.2.105
(SSLClient)(SSL_INFO)(getSession): Using session index: 
(SSLClient)(SSL_INFO)(getSession): 0
(SSLClient)(SSL_INFO)(m_start_ssl): Set SSL session!
(SSLClient)(SSL_INFO)(m_print_br_state): (SSLClient)(SSL_INFO)(m_print_br_state): State: 
   SENDREC
(SSLClient)(SSL_INFO)(m_print_br_state): (SSLClient)(SSL_INFO)(m_print_br_state): State: 
   RECVREC
(SSLClient)(SSL_INFO)(m_run_until): m_run changed state:
(SSLClient)(SSL_INFO)(m_print_br_state): (SSLClient)(SSL_INFO)(m_print_br_state): State: 
   RECVREC
(SSLClient)(SSL_INFO)(m_run_until): Expected bytes count: 
(SSLClient)(SSL_INFO)(m_run_until): 5
(SSLClient)(SSL_INFO)(m_print_br_state): (SSLClient)(SSL_INFO)(m_print_br_state): State: 
   SENDREC
(SSLClient)(SSL_INFO)(m_print_br_state): (SSLClient)(SSL_INFO)(m_print_br_state): State: 
   RECVREC
   SENDAPP
(SSLClient)(SSL_INFO)(m_run_until): m_run changed state:
(SSLClient)(SSL_INFO)(m_print_br_state): (SSLClient)(SSL_INFO)(m_print_br_state): State: 
   RECVREC
   SENDAPP
(SSLClient)(SSL_INFO)(m_start_ssl): Connection successful!
[...]

Answer 3 · 2021-03-19T10:54:38.000Z

I have been having the same issues here.
I'm using a TTGO T-CALL v1.4 with an ESP32 WROVER-B and using PubSubClient to connect to AWS IoT Core.

I have been very keen on closing char[] with a null terminator (which already helped a lot in sustaining the connection)
I also moved the majority of static strings / char arrays to PROGMEM.

Stack seems to overflow after about 2500 successful message transfers.

I will provide the SSL debug on my next post after I have applied some of the advices I found in another thread.

Note that I am running a slightly modified MQTT PubSubClient since the orginal one does have a (heap?) memory overflow (so this issue might as well be related to that Client!)

MQTT settings:

#define MQTT_KEEPALIVE                 30
#define MQTT_MAX_PACKET_SIZE         1024
#define MQTT_MAX_TRANSFER_SIZE        256

Publish Function

bool MQTTPublish(char *topic, char *payload, size_t payload_length)
{
  mqtt.loop();                                                         // Added 19 Mar 11:39
  bool success = ( mqtt.connected() && mqtt.publish( (const char *) topic, (const char *) payload), payload_length );   // Seems this function has errors occurring!
//  https://github.com/knolleary/pubsubclient/issues/832 implemented fix for checking memory  
  
  if ( success ) {
    mqtt.loop();
    if ( ClientSSL.available() ) ClientSSL.flush(); // Added 19 Mar 11:39
    delay(1);                                                            // Added 19 Mar 11:39
    mqtt.loop();
  
    messagesTransmitted++;    // Increase total number of messages transmitted
  }

  // We currently can't handle the errors while in transmission so our message sending will need to become a retry
  if ( ! ClientSSL.connected() )                         success = false;
  if ( ClientSSL.getWriteError() != SSLClient::SSL_OK )  success = false;
  
  SerialMon.printf("[MQTT OUT %zu bytes]", payload_length);
  return success;
}

Stacktrace

0x4008da48: xTaskIncrementTick at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/freertos/tasks.c line 2473
0x4008c5ef: xPortSysTickHandler at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/freertos/port.c line 289
0x400e9fa0: br_aes_small_encrypt at /Users/genotix/Documents/Arduino/libraries/SSLClient/src/bearssl/src/symcipher/aes_small_enc.c line 71
0x400e9fdc: br_aes_small_encrypt at /Users/genotix/Documents/Arduino/libraries/SSLClient/src/bearssl/src/symcipher/aes_small_enc.c line 94
0x400e9f1b: br_aes_small_ctr_run at /Users/genotix/Documents/Arduino/libraries/SSLClient/src/bearssl/src/symcipher/aes_small_ctr.c line 72
0x400e9a94: gen_gcm_init at /Users/genotix/Documents/Arduino/libraries/SSLClient/src/bearssl/src/ssl/ssl_rec_gcm.c line 43
0x400e9d1d: gcm_encrypt at /Users/genotix/Documents/Arduino/libraries/SSLClient/src/inner.h line 511
0x4010f686: br_ssl_engine_fail at /Users/genotix/Documents/Arduino/libraries/SSLClient/src/bearssl/src/ssl/ssl_engine.c line 291
0x400e7bdd: jump_handshake at /Users/genotix/Documents/Arduino/libraries/SSLClient/src/bearssl/src/ssl/ssl_engine.c line 1053
0x400e7f31: br_ssl_engine_sendrec_ack at /Users/genotix/Documents/Arduino/libraries/SSLClient/src/bearssl/src/ssl/ssl_engine.c line 918
0x400e0f34: ssl_pem_decode_callback(void*, void const*, size_t) at /Users/genotix/Documents/Arduino/libraries/SSLClient/src/SSLClientParameters.cpp line 16
0x400ebe05: PubSubClient::disconnect() at /Users/genotix/Documents/Arduino/libraries/pubsubclient-master/src/PubSubClient.cpp line 668
0x400ec155: PubSubClient::subscribe(char const*, unsigned char) at /Users/genotix/Documents/Arduino/libraries/pubsubclient-master/src/PubSubClient.cpp line 626
0x400ec179: PubSubClient::subscribe(char const*, unsigned char) at /Users/genotix/Documents/Arduino/libraries/pubsubclient-master/src/PubSubClient.cpp line 630
0x400d388d: mqtt_update() at /var/folders/6b/0q6s_gw93sz5c0_qjptlq4pc0000gn/T/arduino_build_452967/sketch/mqtt.h line 139
0x400d7ac7: TransmitMessage(char*, bool) at /var/folders/6b/0q6s_gw93sz5c0_qjptlq4pc0000gn/T/arduino_build_452967/sketch/queue.h line 63
0x400d7b86: processQueue(bool) at /var/folders/6b/0q6s_gw93sz5c0_qjptlq4pc0000gn/T/arduino_build_452967/sketch/queue.h line 110
0x400d8fc9: rbase64_encode(char*, char*, unsigned int) at /Users/genotix/Documents/Arduino/libraries/rBase64/src/rBase64.cpp line 46
0x400ef4f9: dtostrf at /Users/genotix/Library/Arduino15/packages/esp32/hardware/esp32/1.0.5/cores/esp32/stdlib_noniso.c line 93
0x4008c502: vPortTaskWrapper at /home/runner/work/esp32-arduino-lib-builder/esp32-arduino-lib-builder/esp-idf/components/freertos/port.c line 143

Answer 4 · 2021-03-22T03:27:14.000Z

@Inkomidwastaken and @genotix sorry for the long delay but I believe I have fixed the issue. @Inkomidwastaken huge thanks for posting your code, with your example I was finally able to track this bug down to SSLClient occasionally attempting to send zero bytes which caused BearSSL to crash the ESP32. This bug should be fixes in v1.6.11, and I've updated the examples to remove the client->flush() workaround.

@Inkomidwastaken note that you'll want to refactor your loop so that client.loop is called more frequently to prevent timeouts:

unsigned long startTime = millis();
void loop() { 
  if (!client.connected()) {
    reconnect();
  }

  if (millis() - startTime > 3000) {
    // this is called every three seconds
    Serial.print("Attempting MQTT hello there!");
    bool success = client.publish("testtopic/ESP", "hello there!");
    Serial.println(success);
    Serial.println(client.state());
    heap_caps_print_heap_info(MALLOC_CAP_DEFAULT);
  }

  // this is now called every loop() instead of once every 3 seconds
  client.loop();
}

Answer 5 · 2021-03-22T12:54:14.000Z

You're kidding!
That is great!!! Thank you both!

I will run a test as soon as you have released 1.6.11

I am currently at 6000 messages (and counting) with the flush workaround.

Answer 6 · 2021-03-22T22:04:21.000Z

Y'all, for what it's worth to you I've been running this code since yesterday, with the fix. No flushes. Yesterday it looked good. Today I removed some of my debug and have been letting it go. I'm currently at 57,313 publishes without an error. This on an esp32 sitting inside an M5Stack module. I think he's nailed it.

Answer 7 · 2021-03-23T13:01:49.000Z

Ok, final checkin on this one from me. I'm now at 215,000+ publishes without an error. Nice job!