Skip to content

SSLClient terminating when flushing buffer #30

Closed

Description

@Inkomidwastaken

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).

Activity

  1. prototypicalpro commented on Dec 29, 2020

    @prototypicalpro
    Member

    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?

  2. Inkomidwastaken commented on Dec 29, 2020

    @Inkomidwastaken
    Author

    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!
    [...]
    
  3. genotix commented on Mar 19, 2021

    @genotix

    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
    
  4. prototypicalpro commented on Mar 22, 2021

    @prototypicalpro
    Member

    @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();
    }
  5. genotix commented on Mar 22, 2021

    @genotix

    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.

  6. michaelhwhitten commented on Mar 22, 2021

    @michaelhwhitten

    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.

  7. michaelhwhitten commented on Mar 23, 2021

    @michaelhwhitten

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

  8. added
    bugSomething isn't working
    and removed
    questionFurther information is requested
    on Mar 25, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    bugSomething isn't working

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions