Fix CRC error during DSMR chunked message reading (#2622)

* DSMR chunk size from 50 to 500

* Still a few CRC errors with 500, upping to 1024.

* Adding timers to measure how long processing DSMR takes

* Handle chunked output from smart meter.

* Cleaning up and commenting the new chunk handling code

* Remove debug code.

* Fixing clang-tidy issues.

* Implementing chunked reading support for encrypted telegrams.

* Remove redundant extra delay for encrypted reader

* Beware not to flush crypted telegram headers

* Use insane data timeout for testing

* Improve logging

* Make clang-tidy happy

Co-authored-by: Maurice Makaay <mmakaay1@xs4all.net>
Co-authored-by: Maurice Makaay <account-github@makaay.nl>

esphome/components/dsmr/dsmr.cpp

@@ -19,14 +19,30 @@ void Dsmr::loop() {
     this->receive_encrypted_();
 }
 
+bool Dsmr::available_within_timeout_() {
+  uint8_t tries = READ_TIMEOUT_MS / 5;
+  while (tries--) {
+    delay(5);
+    if (available()) {
+      return true;
+    }
+  }
+  return false;
+}
+
 void Dsmr::receive_telegram_() {
-  int count = MAX_BYTES_PER_LOOP;
+  while (true) {
-  while (available() && count-- > 0) {
+    if (!available()) {
+      if (!header_found_ || !available_within_timeout_()) {
+        return;
+      }
+    }
+
     const char c = read();
 
     // Find a new telegram header, i.e. forward slash.
     if (c == '/') {
-      ESP_LOGV(TAG, "Header found");
+      ESP_LOGV(TAG, "Header of telegram found");
       header_found_ = true;
       footer_found_ = false;
       telegram_len_ = 0;
@@ -38,7 +54,7 @@ void Dsmr::receive_telegram_() {
     if (telegram_len_ >= MAX_TELEGRAM_LENGTH) {
       header_found_ = false;
       footer_found_ = false;
-      ESP_LOGE(TAG, "Error: Message larger than buffer");
+      ESP_LOGE(TAG, "Error: telegram larger than buffer (%d bytes)", MAX_TELEGRAM_LENGTH);
       return;
     }
 
@@ -54,7 +70,7 @@ void Dsmr::receive_telegram_() {
 
     // Check for a footer, i.e. exlamation mark, followed by a hex checksum.
     if (c == '!') {
-      ESP_LOGV(TAG, "Footer found");
+      ESP_LOGV(TAG, "Footer of telegram found");
       footer_found_ = true;
       continue;
     }
@@ -62,8 +78,8 @@ void Dsmr::receive_telegram_() {
     if (footer_found_ && c == '\n') {
       header_found_ = false;
       // Parse the telegram and publish sensor values.
-      if (parse_telegram())
+      parse_telegram();
-        return;
+      return;
     }
   }
 }
@@ -72,41 +88,46 @@ void Dsmr::receive_encrypted_() {
   // Encrypted buffer
   uint8_t buffer[MAX_TELEGRAM_LENGTH];
   size_t buffer_length = 0;
-
   size_t packet_size = 0;
-  while (available()) {
-    const char c = read();
 
-    if (!header_found_) {
+  while (true) {
-      if ((uint8_t) c == 0xdb) {
+    if (!available()) {
-        ESP_LOGV(TAG, "Start byte 0xDB found");
+      if (!header_found_) {
-        header_found_ = true;
+        return;
+      }
+      if (!available_within_timeout_()) {
+        ESP_LOGW(TAG, "Timeout while reading data for encrypted telegram");
+        return;
       }
     }
 
-    // Sanity check
+    const char c = read();
-    if (!header_found_ || buffer_length >= MAX_TELEGRAM_LENGTH) {
+
-      if (buffer_length == 0) {
+    // Find a new telegram start byte.
-        ESP_LOGE(TAG, "First byte of encrypted telegram should be 0xDB, aborting.");
+    if (!header_found_) {
-      } else {
+      if ((uint8_t) c == 0xDB) {
-        ESP_LOGW(TAG, "Unexpected data");
+        ESP_LOGV(TAG, "Start byte 0xDB of encrypted telegram found");
+        header_found_ = true;
       }
-      this->status_momentary_warning("unexpected_data");
+      continue;
-      this->flush();
+    }
-      while (available())
+
-        read();
+    // Check for buffer overflow.
+    if (buffer_length >= MAX_TELEGRAM_LENGTH) {
+      header_found_ = false;
+      ESP_LOGE(TAG, "Error: encrypted telegram larger than buffer (%d bytes)", MAX_TELEGRAM_LENGTH);
       return;
     }
 
     buffer[buffer_length++] = c;
 
     if (packet_size == 0 && buffer_length > 20) {
-      // Complete header + a few bytes of data
+      // Complete header + data bytes
-      packet_size = buffer[11] << 8 | buffer[12];
+      packet_size = 13 + (buffer[11] << 8 | buffer[12]);
+      ESP_LOGV(TAG, "Encrypted telegram size: %d bytes", packet_size);
     }
-    if (buffer_length == packet_size + 13 && packet_size > 0) {
+    if (buffer_length == packet_size && packet_size > 0) {
-      ESP_LOGV(TAG, "Encrypted data: %d bytes", buffer_length);
+      ESP_LOGV(TAG, "End of encrypted telegram found");
-
       GCM<AES128> *gcmaes128{new GCM<AES128>()};
       gcmaes128->setKey(this->decryption_key_.data(), gcmaes128->keySize());
       // the iv is 8 bytes of the system title + 4 bytes frame counter
@@ -123,28 +144,21 @@ void Dsmr::receive_encrypted_() {
       delete gcmaes128;  // NOLINT(cppcoreguidelines-owning-memory)
 
       telegram_len_ = strnlen(this->telegram_, sizeof(this->telegram_));
-      ESP_LOGV(TAG, "Decrypted data length: %d", telegram_len_);
+      ESP_LOGV(TAG, "Decrypted telegram size: %d bytes", telegram_len_);
-      ESP_LOGVV(TAG, "Decrypted data %s", this->telegram_);
+      ESP_LOGVV(TAG, "Decrypted telegram: %s", this->telegram_);
+
+      header_found_ = false;
+      telegram_len_ = 0;
 
       parse_telegram();
-      telegram_len_ = 0;
       return;
     }
-
-    if (!available()) {
-      // baud rate is 115200 for encrypted data, this means a few byte should arrive every time
-      // program runs faster than buffer loading then available() might return false in the middle
-      delay(4);  // Wait for data
-    }
-  }
-  if (buffer_length > 0) {
-    ESP_LOGW(TAG, "Timeout while waiting for encrypted data or invalid data received.");
   }
 }
 
 bool Dsmr::parse_telegram() {
   MyData data;
-  ESP_LOGV(TAG, "Trying to parse");
+  ESP_LOGV(TAG, "Trying to parse telegram");
   ::dsmr::ParseResult<void> res =
       ::dsmr::P1Parser::parse(&data, telegram_, telegram_len_, false,
                               this->crc_check_);  // Parse telegram according to data definition. Ignore unknown values.
@@ -161,7 +175,7 @@ bool Dsmr::parse_telegram() {
 }
 
 void Dsmr::dump_config() {
-  ESP_LOGCONFIG(TAG, "dsmr:");
+  ESP_LOGCONFIG(TAG, "DSMR:");
 
 #define DSMR_LOG_SENSOR(s) LOG_SENSOR("  ", #s, this->s_##s##_);
   DSMR_SENSOR_LIST(DSMR_LOG_SENSOR, )
@@ -178,12 +192,12 @@ void Dsmr::set_decryption_key(const std::string &decryption_key) {
   }
 
   if (decryption_key.length() != 32) {
-    ESP_LOGE(TAG, "Error, decryption key must be 32 character long.");
+    ESP_LOGE(TAG, "Error, decryption key must be 32 character long");
     return;
   }
   this->decryption_key_.clear();
 
-  ESP_LOGI(TAG, "Decryption key is set.");
+  ESP_LOGI(TAG, "Decryption key is set");
   // Verbose level prints decryption key
   ESP_LOGV(TAG, "Using decryption key: %s", decryption_key.c_str());
 

esphome/components/dsmr/dsmr.h

@@ -17,8 +17,7 @@ namespace esphome {
 namespace dsmr {
 
 static constexpr uint32_t MAX_TELEGRAM_LENGTH = 1500;
-static constexpr uint32_t MAX_BYTES_PER_LOOP = 50;
+static constexpr uint32_t READ_TIMEOUT_MS = 200;
-static constexpr uint32_t POLL_TIMEOUT = 1000;
 
 using namespace ::dsmr::fields;
 
@@ -86,6 +85,17 @@ class Dsmr : public Component, public uart::UARTDevice {
   void receive_telegram_();
   void receive_encrypted_();
 
+  /// Wait for UART data to become available within the read timeout.
+  ///
+  /// The smart meter might provide data in chunks, causing available() to
+  /// return 0. When we're already reading a telegram, then we don't return
+  /// right away (to handle further data in an upcoming loop) but wait a
+  /// little while using this method to see if more data are incoming.
+  /// By not returning, we prevent other components from taking so much
+  /// time that the UART RX buffer overflows and bytes of the telegram get
+  /// lost in the process.
+  bool available_within_timeout_();
+
   // Telegram buffer
   char telegram_[MAX_TELEGRAM_LENGTH];
   int telegram_len_{0};