added communication monitoring an fix for Viessmann device hanging on boot (#16)

esphome/components/optolink/binary_sensor/optolink_binary_sensor.h

@@ -9,9 +9,7 @@
 namespace esphome {
 namespace optolink {
 
-class OptolinkBinarySensor : public DatapointComponent,
+class OptolinkBinarySensor : public DatapointComponent, public esphome::binary_sensor::BinarySensor {
-                             public esphome::binary_sensor::BinarySensor,
-                             public esphome::PollingComponent {
  public:
   OptolinkBinarySensor(Optolink *optolink) : DatapointComponent(optolink) {
     set_bytes(1);

esphome/components/optolink/datapoint_component.cpp

@@ -17,6 +17,7 @@ void DatapointComponent::setup_datapoint_() {
       datapoint_ = new Datapoint<convRaw>(get_component_name().c_str(), "optolink", address_, writeable_);
       datapoint_->setLength(bytes_);
       datapoint_->setCallback([this](const IDatapoint &dp, DPValue dp_value) {
+        optolink_->notify_receive();
         uint8_t buffer[bytes_];
         dp_value.getRaw(buffer);
 #if ESPHOME_LOG_LEVEL >= ESPHOME_LOG_LEVEL_INFO
@@ -34,6 +35,7 @@ void DatapointComponent::setup_datapoint_() {
           datapoint_ = new Datapoint<conv1_1_US>(get_component_name().c_str(), "optolink", address_, writeable_);
           datapoint_->setCallback([this](const IDatapoint &dp, DPValue dp_value) {
             ESP_LOGI(TAG, "recieved data for datapoint %s: %d", dp.getName(), dp_value.getU8());
+            optolink_->notify_receive();
             datapoint_value_changed(dp_value.getU8());
             read_retries_ = 0;
           });
@@ -42,6 +44,7 @@ void DatapointComponent::setup_datapoint_() {
           datapoint_ = new Datapoint<conv2_1_US>(get_component_name().c_str(), "optolink", address_, writeable_);
           datapoint_->setCallback([this](const IDatapoint &dp, DPValue dp_value) {
             ESP_LOGI(TAG, "recieved data for datapoint %s: %d", dp.getName(), dp_value.getU16());
+            optolink_->notify_receive();
             datapoint_value_changed(dp_value.getU16());
             read_retries_ = 0;
           });
@@ -50,6 +53,7 @@ void DatapointComponent::setup_datapoint_() {
           datapoint_ = new Datapoint<conv4_1_UL>(get_component_name().c_str(), "optolink", address_, writeable_);
           datapoint_->setCallback([this](const IDatapoint &dp, DPValue dp_value) {
             ESP_LOGI(TAG, "recieved data for datapoint %s: %d", dp.getName(), dp_value.getU32());
+            optolink_->notify_receive();
             datapoint_value_changed((uint32_t) dp_value.getU32());
             read_retries_ = 0;
           });
@@ -64,6 +68,7 @@ void DatapointComponent::setup_datapoint_() {
           datapoint_ = new Datapoint<conv1_10_F>(get_component_name().c_str(), "optolink", address_, writeable_);
           datapoint_->setCallback([this](const IDatapoint &dp, DPValue dp_value) {
             ESP_LOGI(TAG, "recieved data for datapoint %s: %f", dp.getName(), dp_value.getFloat());
+            optolink_->notify_receive();
             datapoint_value_changed(dp_value.getFloat());
             read_retries_ = 0;
           });
@@ -72,6 +77,7 @@ void DatapointComponent::setup_datapoint_() {
           datapoint_ = new Datapoint<conv2_10_F>(get_component_name().c_str(), "optolink", address_, writeable_);
           datapoint_->setCallback([this](const IDatapoint &dp, DPValue dp_value) {
             ESP_LOGI(TAG, "recieved data for datapoint %s: %f", dp.getName(), dp_value.getFloat());
+            optolink_->notify_receive();
             datapoint_value_changed(dp_value.getFloat());
             read_retries_ = 0;
           });
@@ -86,6 +92,7 @@ void DatapointComponent::setup_datapoint_() {
           datapoint_ = new Datapoint<conv2_100_F>(get_component_name().c_str(), "optolink", address_, writeable_);
           datapoint_->setCallback([this](const IDatapoint &dp, DPValue dp_value) {
             ESP_LOGI(TAG, "recieved data for datapoint %s: %f", dp.getName(), dp_value.getFloat());
+            optolink_->notify_receive();
             datapoint_value_changed(dp_value.getFloat());
             read_retries_ = 0;
           });
@@ -100,6 +107,7 @@ void DatapointComponent::setup_datapoint_() {
           datapoint_ = new Datapoint<conv4_1000_F>(get_component_name().c_str(), "optolink", address_, writeable_);
           datapoint_->setCallback([this](const IDatapoint &dp, DPValue dp_value) {
             ESP_LOGI(TAG, "recieved data for datapoint %s: %f", dp.getName(), dp_value.getFloat());
+            optolink_->notify_receive();
             datapoint_value_changed(dp_value.getFloat());
             read_retries_ = 0;
           });
@@ -112,6 +120,7 @@ void DatapointComponent::setup_datapoint_() {
           datapoint_ = new Datapoint<conv4_3600_F>(get_component_name().c_str(), "optolink", address_, writeable_);
           datapoint_->setCallback([this](const IDatapoint &dp, DPValue dp_value) {
             ESP_LOGI(TAG, "recieved data for datapoint %s: %f", dp.getName(), dp_value.getFloat());
+            optolink_->notify_receive();
             datapoint_value_changed(dp_value.getFloat());
             read_retries_ = 0;
           });
@@ -128,14 +137,18 @@ void DatapointComponent::datapoint_read_request_() {
     ESP_LOGI(TAG, "read request for %s deferred due to outstanding write request", get_component_name().c_str());
     datapoint_write_request_(dp_value_outstanding_);
   } else {
-    if (read_retries_ == 0 || read_retries_ >= max_retries_until_reset_) {
+    if (!optolink_->communication_suspended()) {
-      if (optolink_->read_value(datapoint_)) {
+      if ((read_retries_ == 0 || read_retries_ >= max_retries_until_reset_) || get_update_interval() > 10000) {
-        read_retries_ = 1;
+        if (optolink_->read_value(datapoint_)) {
+          read_retries_ = 1;
+        }
+      } else {
+        read_retries_++;
+        ESP_LOGW(TAG, "%d. read request for %s rejected due to outstanding running request - increase update_interval!",
+                 read_retries_, get_component_name().c_str());
       }
     } else {
-      read_retries_++;
+      read_retries_ = 0;
-      ESP_LOGW(TAG, "%d. read request for %s rejected  due to outstanding running request - increase update_interval!",
-               read_retries_, get_component_name().c_str());
     }
   }
 }
@@ -166,9 +179,8 @@ void DatapointComponent::datapoint_value_changed(uint8_t *value, size_t length)
 
 void DatapointComponent::datapoint_write_request_(DPValue dp_value) {
   if (!writeable_) {
-    optolink_->set_state("trying to control not writable datapoint %s", get_component_name().c_str());
     ESP_LOGE(TAG, "trying to control not writable datapoint %s", get_component_name().c_str());
-  } else if (datapoint_ != nullptr) {
+  } else if (datapoint_ != nullptr && !optolink_->communication_suspended()) {
 #if ESPHOME_LOG_LEVEL >= ESPHOME_LOG_LEVEL_INFO
     char buffer[100];
     dp_value.getString(buffer, sizeof(buffer));
@@ -242,24 +254,9 @@ void DatapointComponent::write_datapoint_value_(uint8_t *value, size_t length) {
 }
 
 void DatapointComponent::unfitting_value_type_() {
-  optolink_->set_state("Unfitting byte/div_ratio combination for sensor/component %s", get_component_name().c_str());
   ESP_LOGE(TAG, "Unfitting byte/div_ratio combination for sensor/component %s", get_component_name().c_str());
 }
 
-void DatapointComponent::set_optolink_state_(const char *format, ...) {
-  va_list args;
-  va_start(args, format);
-  char buffer[128];
-  std::vsnprintf(buffer, sizeof(buffer), format, args);
-  va_end(args);
-
-  optolink_->set_state(buffer);
-}
-
-std::string DatapointComponent::get_optolink_state_() { return optolink_->get_state(); }
-
-int DatapointComponent::get_optolink_queue_size_() { return optolink_->get_queue_size(); };
-
 void conv2_100_F::encode(uint8_t *out, DPValue in) {
   int16_t tmp = floor((in.getFloat() * 100) + 0.5);
   out[1] = tmp >> 8;

esphome/components/optolink/datapoint_component.h

@@ -4,6 +4,7 @@
 
 #include "esphome/core/log.h"
 #include "esphome/core/string_ref.h"
+#include "esphome/core/component.h"
 #include "VitoWiFi.h"
 
 namespace esphome {
@@ -11,7 +12,7 @@ namespace optolink {
 
 class Optolink;
 
-class DatapointComponent {
+class DatapointComponent : public esphome::PollingComponent {
  public:
   DatapointComponent(Optolink *optolink, bool writeable = false) : dp_value_outstanding_((uint8_t) 0) {
     optolink_ = optolink;
@@ -46,13 +47,11 @@ class DatapointComponent {
   void write_datapoint_value_(uint8_t *value, size_t length);
 
   void unfitting_value_type_();
-  void set_optolink_state_(const char *format, ...);
+
-  std::string get_optolink_state_();
+  Optolink *optolink_;
-  int get_optolink_queue_size_();
 
  private:
   const size_t max_retries_until_reset_ = 10;
-  Optolink *optolink_;
   IDatapoint *datapoint_ = nullptr;
   size_t read_retries_ = 0;
   size_t div_ratio_ = 0;
@@ -62,6 +61,9 @@ class DatapointComponent {
   bool is_dp_value_writing_outstanding_ = false;
   DPValue dp_value_outstanding_;
 
+  static uint32_t last_recv;
+  static uint32_t last_send;
+
   void datapoint_write_request_(DPValue dp_value);
 };
 

esphome/components/optolink/number/optolink_number.cpp

@@ -10,7 +10,6 @@ static const char *const TAG = "optolink.number";
 
 void OptolinkNumber::control(float value) {
   if (value > traits.get_max_value() || value < traits.get_min_value()) {
-    set_optolink_state_("datapoint value of number %s not in allowed range", get_component_name().c_str());
     ESP_LOGE(TAG, "datapoint value of number %s not in allowed range", get_component_name().c_str());
   } else {
     ESP_LOGI(TAG, "control of number %s to value %f", get_component_name().c_str(), value);

esphome/components/optolink/number/optolink_number.h

@@ -9,7 +9,7 @@
 namespace esphome {
 namespace optolink {
 
-class OptolinkNumber : public DatapointComponent, public esphome::number::Number, public esphome::PollingComponent {
+class OptolinkNumber : public DatapointComponent, public esphome::number::Number {
  public:
   OptolinkNumber(Optolink *optolink) : DatapointComponent(optolink, true) {}
 

esphome/components/optolink/optolink.cpp

@@ -11,12 +11,6 @@ namespace optolink {
 
 static const char *const TAG = "optolink";
 
-void Optolink::comm_() {
-  ESP_LOGD(TAG, "enter _comm");
-  VitoWiFi.readAll();
-  ESP_LOGD(TAG, "exit _comm");
-}
-
 void Optolink::setup() {
   ESP_LOGI(TAG, "setup");
 
@@ -32,11 +26,16 @@ void Optolink::setup() {
 #endif
 }
 
-void Optolink::loop() { VitoWiFi.loop(); }
+void Optolink::loop() {
+  communication_check_();
+  if (!communication_suspended()) {
+    VitoWiFi.loop();
+  }
+}
 
 int Optolink::get_queue_size() { return VitoWiFi.queueSize(); }
 
-void Optolink::set_state(const char *format, ...) {
+void Optolink::set_state_(const char *format, ...) {
   va_list args;
   va_start(args, format);
   char buffer[128];
@@ -46,11 +45,67 @@ void Optolink::set_state(const char *format, ...) {
   state_ = buffer;
 }
 
+void Optolink::notify_receive() { timestamp_receive_ = timestamp_loop_; }
+
+void Optolink::notify_send() { timestamp_send_ = timestamp_loop_; }
+
+void Optolink::communication_check_() {
+  timestamp_loop_ = millis();
+
+  if (communication_suspended()) {
+    if (timestamp_loop_ < timestamp_disruption_ ||
+        (timestamp_loop_ - timestamp_disruption_) > COMMUNICATION_SUSPENSION_DURATION) {
+      resume_communication_();
+    } else {
+      set_state_("communication suspended");
+      // if (timestamp_loop % 10 == 0)
+      //   ESP_LOGD(TAG, "communication suspended");
+    }
+  } else if (timestamp_loop_ < timestamp_send_ || timestamp_loop_ < timestamp_receive_) {
+    ESP_LOGI(TAG, "timestamp rollover");
+    timestamp_send_ = 0;
+    timestamp_receive_ = 0;
+  } else if (timestamp_send_ > 0 && (timestamp_loop_ - timestamp_receive_) > COMMUNICATION_CHECK_WINDOW) {
+    // last response older than 10 sec - check if there was no request in same time window except last two seconds
+    if (timestamp_send_ > timestamp_loop_ - MAX_RESPONSE_DELAY) {
+      // request too fresh -> possiblly still waiting for response
+    } else if (timestamp_send_ < timestamp_receive_) {
+      // no new and fresh request since last response
+      set_state_("communication unused");
+    } else {
+      suspend_communication_();
+    }
+  } else {
+    set_state_("communication active");
+  }
+}
+
+void Optolink::suspend_communication_() {
+  set_state_("communication suspended");
+  ESP_LOGW(TAG,
+           "communication disrupted - suspending communication for 10 sec; timestamp_loop: %u, timestamp_send: %u,  "
+           "timestamp_receive: %u ",
+           timestamp_loop_, timestamp_send_, timestamp_receive_);
+  timestamp_disruption_ = timestamp_loop_;
+}
+
+void Optolink::resume_communication_() {
+  ESP_LOGI(TAG, "resuming communication");
+  timestamp_disruption_ = 0;
+  timestamp_send_ = 0;
+  timestamp_receive_ = 0;
+}
+
+bool Optolink::communication_suspended() { return (timestamp_disruption_ != 0); }
+
 bool Optolink::read_value(IDatapoint *datapoint) {
-  if (datapoint != nullptr) {
+  if (datapoint != nullptr && !communication_suspended()) {
     ESP_LOGI(TAG, "requesting value of datapoint %s", datapoint->getName());
-    if (!VitoWiFi.readDatapoint(*datapoint)) {
+    if (VitoWiFi.readDatapoint(*datapoint)) {
+      notify_send();
+    } else {
       ESP_LOGE(TAG, "read request rejected due to queue overload - queue size: %d", VitoWiFi.queueSize());
+      suspend_communication_();
       for (auto *dp : IDatapoint::getCollection()) {
         ESP_LOGD(TAG, "queued datapoint: %s", dp->getName());
       }
@@ -61,11 +116,13 @@ bool Optolink::read_value(IDatapoint *datapoint) {
 }
 
 bool Optolink::write_value(IDatapoint *datapoint, DPValue dp_value) {
-  if (datapoint != nullptr) {
+  if (datapoint != nullptr && !communication_suspended()) {
     char buffer[64];
     dp_value.getString(buffer, sizeof(buffer));
     ESP_LOGI(TAG, "sending value %s of datapoint %s", buffer, datapoint->getName());
-    if (!VitoWiFi.writeDatapoint(*datapoint, dp_value)) {
+    if (VitoWiFi.writeDatapoint(*datapoint, dp_value)) {
+      notify_send();
+    } else {
       ESP_LOGE(TAG, "write request rejected due to queue overload - queue size: %d", VitoWiFi.queueSize());
       for (auto *dp : IDatapoint::getCollection()) {
         ESP_LOGE(TAG, "queued dp: %s", dp->getName());

esphome/components/optolink/optolink.h

@@ -11,13 +11,19 @@ namespace optolink {
 
 class Optolink : public esphome::Component, public Print {
  protected:
-  std::string state_ = "OK";
+  std::string state_ = "initializing";
   std::string log_buffer_;
   bool logger_enabled_ = false;
   int rx_pin_;
   int tx_pin_;
+  uint32_t timestamp_loop_ = 0;
+  uint32_t timestamp_disruption_ = 0;
+  uint32_t timestamp_receive_ = 0;
+  uint32_t timestamp_send_ = 0;
 
-  void comm_();
+  static const uint32_t COMMUNICATION_CHECK_WINDOW = 10000;
+  static const uint32_t COMMUNICATION_SUSPENSION_DURATION = 10000;
+  static const uint32_t MAX_RESPONSE_DELAY = 2000;
 
  public:
   void setup() override;
@@ -33,10 +39,19 @@ class Optolink : public esphome::Component, public Print {
   bool write_value(IDatapoint *datapoint, DPValue dp_value);
   bool read_value(IDatapoint *datapoint);
 
-  void set_state(const char *format, ...);
   std::string get_state() { return state_; }
 
   int get_queue_size();
+  bool communication_suspended();
+  void notify_receive();
+  void notify_send();
+
+ private:
+  void set_state_(const char *format, ...);
+
+  void communication_check_();
+  void suspend_communication_();
+  void resume_communication_();
 };
 
 }  // namespace optolink

esphome/components/optolink/select/optolink_select.cpp

@@ -17,7 +17,6 @@ void OptolinkSelect::control(const std::string &value) {
       break;
     }
     if (it == mapping_->end()) {
-      set_optolink_state_("unknown value %s of select %s", value.c_str(), get_component_name().c_str());
       ESP_LOGE(TAG, "unknown value %s of select %s", value.c_str(), get_component_name().c_str());
     }
   }
@@ -26,7 +25,6 @@ void OptolinkSelect::control(const std::string &value) {
 void OptolinkSelect::datapoint_value_changed(const std::string &value) {
   auto pos = mapping_->find(value);
   if (pos == mapping_->end()) {
-    set_optolink_state_("value %s not found in select %s", value.c_str(), get_component_name().c_str());
     ESP_LOGE(TAG, "value %s not found in select %s", value.c_str(), get_component_name().c_str());
   } else {
     publish_state(pos->second);

esphome/components/optolink/select/optolink_select.h

@@ -10,7 +10,7 @@
 namespace esphome {
 namespace optolink {
 
-class OptolinkSelect : public DatapointComponent, public esphome::select::Select, public esphome::PollingComponent {
+class OptolinkSelect : public DatapointComponent, public esphome::select::Select {
  public:
   OptolinkSelect(Optolink *optolink) : DatapointComponent(optolink, true) {}
 

esphome/components/optolink/sensor/optolink_sensor.cpp

@@ -25,7 +25,7 @@ void OptolinkSensor::update() {
       datapoint_read_request_();
       break;
     case SENSOR_TYPE_QUEUE_SIZE:
-      publish_state(get_optolink_queue_size_());
+      publish_state(optolink_->get_queue_size());
       break;
   }
 }

esphome/components/optolink/sensor/optolink_sensor.h

@@ -12,7 +12,7 @@ namespace optolink {
 
 enum SensorType { SENSOR_TYPE_DATAPOINT, SENSOR_TYPE_QUEUE_SIZE };
 
-class OptolinkSensor : public DatapointComponent, public esphome::sensor::Sensor, public esphome::PollingComponent {
+class OptolinkSensor : public DatapointComponent, public esphome::sensor::Sensor {
  public:
   OptolinkSensor(Optolink *optolink) : DatapointComponent(optolink) {
     set_state_class(esphome::sensor::STATE_CLASS_MEASUREMENT);

esphome/components/optolink/switch/optolink_switch.cpp

@@ -10,7 +10,6 @@ static const char *const TAG = "optolink.switch";
 
 void OptolinkSwitch::write_state(bool value) {
   if (value != 0 && value != 1) {
-    set_optolink_state_("datapoint value of switch %s not 0 or 1", get_component_name().c_str());
     ESP_LOGE(TAG, "datapoint value of switch %s not 0 or 1", get_component_name().c_str());
   } else {
     ESP_LOGI(TAG, "control of switch %s to value %d", get_component_name().c_str(), value);

esphome/components/optolink/switch/optolink_switch.h

@@ -9,7 +9,7 @@
 namespace esphome {
 namespace optolink {
 
-class OptolinkSwitch : public DatapointComponent, public esphome::switch_::Switch, public esphome::PollingComponent {
+class OptolinkSwitch : public DatapointComponent, public esphome::switch_::Switch {
  public:
   OptolinkSwitch(Optolink *optolink) : DatapointComponent(optolink, true) {
     set_bytes(1);

esphome/components/optolink/text/optolink_text.cpp

@@ -26,8 +26,6 @@ void OptolinkText::setup() {
 };
 
 void OptolinkText::control(const std::string &value) {
-  ESP_LOGE(TAG, "control %s", value.c_str());
-
   ESP_LOGD(TAG, "update for schedule plan for component %s: %s", get_component_name().c_str(), value.c_str());
   uint8_t buffer[8];
   uint8_t *data = encode_day_schedule(value, buffer);

esphome/components/optolink/text/optolink_text.h

@@ -11,7 +11,7 @@ namespace optolink {
 
 enum TextType { TEXT_TYPE_DAY_SCHEDULE };
 
-class OptolinkText : public DatapointComponent, public esphome::text::Text, public esphome::PollingComponent {
+class OptolinkText : public DatapointComponent, public esphome::text::Text {
  public:
   OptolinkText(Optolink *optolink) : DatapointComponent(optolink) {}
 

esphome/components/optolink/text_sensor/optolink_text_sensor.cpp

@@ -37,7 +37,7 @@ void OptolinkTextSensor::setup() {
 
 void OptolinkTextSensor::update() {
   if (type_ == TEXT_SENSOR_TYPE_STATE_INFO) {
-    publish_state(get_optolink_state_());
+    publish_state(optolink_->get_state());
   } else {
     datapoint_read_request_();
   }

esphome/components/optolink/text_sensor/optolink_text_sensor.h

@@ -17,9 +17,7 @@ enum TextSensorType {
   TEXT_SENSOR_TYPE_STATE_INFO
 };
 
-class OptolinkTextSensor : public DatapointComponent,
+class OptolinkTextSensor : public DatapointComponent, public esphome::text_sensor::TextSensor {
-                           public esphome::text_sensor::TextSensor,
-                           public esphome::PollingComponent {
  public:
   OptolinkTextSensor(Optolink *optolink) : DatapointComponent(optolink) {}