From b450d4c734e18c1cfe04c07da09431b57ffdc8e3 Mon Sep 17 00:00:00 2001 From: Maurice Makaay Date: Sat, 6 Nov 2021 22:52:04 +0100 Subject: [PATCH] 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 Co-authored-by: Maurice Makaay --- esphome/components/dsmr/dsmr.cpp | 104 ++++++++++++++++++------------- esphome/components/dsmr/dsmr.h | 14 ++++- 2 files changed, 71 insertions(+), 47 deletions(-) diff --git a/esphome/components/dsmr/dsmr.cpp b/esphome/components/dsmr/dsmr.cpp index b798fe5d44..031fb275f5 100644 --- a/esphome/components/dsmr/dsmr.cpp +++ b/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 (available() && count-- > 0) { + while (true) { + 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()) - return; + parse_telegram(); + 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_) { - if ((uint8_t) c == 0xdb) { - ESP_LOGV(TAG, "Start byte 0xDB found"); - header_found_ = true; + while (true) { + if (!available()) { + if (!header_found_) { + return; + } + if (!available_within_timeout_()) { + ESP_LOGW(TAG, "Timeout while reading data for encrypted telegram"); + return; } } - // Sanity check - if (!header_found_ || buffer_length >= MAX_TELEGRAM_LENGTH) { - if (buffer_length == 0) { - ESP_LOGE(TAG, "First byte of encrypted telegram should be 0xDB, aborting."); - } else { - ESP_LOGW(TAG, "Unexpected data"); + const char c = read(); + + // Find a new telegram start byte. + if (!header_found_) { + if ((uint8_t) c == 0xDB) { + ESP_LOGV(TAG, "Start byte 0xDB of encrypted telegram found"); + header_found_ = true; } - this->status_momentary_warning("unexpected_data"); - this->flush(); - while (available()) - read(); + continue; + } + + // 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 - packet_size = buffer[11] << 8 | buffer[12]; + // Complete header + data bytes + 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) { - ESP_LOGV(TAG, "Encrypted data: %d bytes", buffer_length); - + if (buffer_length == packet_size && packet_size > 0) { + ESP_LOGV(TAG, "End of encrypted telegram found"); GCM *gcmaes128{new GCM()}; 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_LOGVV(TAG, "Decrypted data %s", this->telegram_); + ESP_LOGV(TAG, "Decrypted telegram size: %d bytes", telegram_len_); + 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 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()); diff --git a/esphome/components/dsmr/dsmr.h b/esphome/components/dsmr/dsmr.h index 4f9a66b3d0..ca2c0f0877 100644 --- a/esphome/components/dsmr/dsmr.h +++ b/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 POLL_TIMEOUT = 1000; +static constexpr uint32_t READ_TIMEOUT_MS = 200; 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};