[canbus] Bus error logging, Auto-recover bus-off on ESP32 (#10953)

Co-authored-by: J. Nick Koston <nick@koston.org>
Co-authored-by: J. Nick Koston <nick@home-assistant.io>

esphome/components/canbus/__init__.py

@@ -1,14 +1,17 @@
+import logging
 import re
 from typing import Any
 
 from esphome import automation
 import esphome.codegen as cg
 import esphome.config_validation as cv
-from esphome.const import CONF_DATA, CONF_ID, CONF_TRIGGER_ID
+from esphome.const import CONF_DATA, CONF_ID, CONF_PLATFORM, CONF_TRIGGER_ID
 from esphome.core import CORE, ID
 from esphome.cpp_generator import MockObj, TemplateArgsType
 from esphome.types import ConfigType
 
+_LOGGER = logging.getLogger(__name__)
+
 CODEOWNERS = ["@mvturnho", "@danielschramm"]
 DOMAIN = "canbus"
 IS_PLATFORM_COMPONENT = True
@@ -150,9 +153,19 @@ async def setup_canbus_core_(var: MockObj, config: ConfigType) -> None:
         )
 
 
-async def register_canbus(var: MockObj, config: ConfigType) -> None:
+async def register_canbus(
+    var: MockObj, config: ConfigType, *, reports_status: bool | None = None
+) -> None:
     if not CORE.has_id(config[CONF_ID]):
         var = cg.new_Pvariable(config[CONF_ID], var)
+    if reports_status is None:
+        _LOGGER.warning(
+            "CAN bus platform '%s' does not report bus state, so bus-off recovery and "
+            "error-state logging are disabled. Platform authors should either override "
+            "get_status() and get_events() and call register_canbus(..., reports_status=True) "
+            "or pass reports_status=False if the hardware cannot report it",
+            config[CONF_PLATFORM],
+        )
     await setup_canbus_core_(var, config)
 
 

esphome/components/canbus/canbus.cpp

@@ -1,5 +1,6 @@
 #include "canbus.h"
 #include <algorithm>
+#include "esphome/core/application.h"
 #include "esphome/core/log.h"
 
 namespace esphome::canbus {
@@ -65,6 +66,12 @@ void Canbus::add_trigger(CanbusTrigger *trigger) {
 };
 
 void Canbus::loop() {
+  uint32_t now = App.get_loop_component_start_time();
+  if ((now - this->last_event_check_time_) >= EVENT_CHECK_INTERVAL_MS) {
+    this->log_events_(this->get_events(), now);
+    this->last_event_check_time_ = now;
+  }
+
   struct CanFrame can_message;
   uint32_t message_counter = 0;
   for (; message_counter < this->max_frames_per_loop_; message_counter++) {
@@ -109,4 +116,55 @@ void Canbus::loop() {
   }
 }
 
+void Canbus::log_events_(CanEventFlags events, uint32_t now) {
+  // Bus-off gets its own handling because automatic recovery can make it flap
+  if (events & CanEventFlags::CAN_EVENT_BUS_OFF) {
+    this->last_bus_off_time_ = now;
+    if (!this->bus_off_) {
+      this->bus_off_ = true;
+      this->status_set_warning(LOG_STR("Bus off"));
+    }
+  } else if (this->bus_off_) {
+    if ((now - this->last_bus_off_time_) >= EVENT_LOG_BUS_OFF_HOLDOFF_MS) {
+      // No bus-off event for the hold-off time, so ask whether it is really over
+      if (this->get_status().bus_off) {
+        this->last_bus_off_time_ = now;
+      } else {
+        this->bus_off_ = false;
+        this->status_clear_warning();
+        // Events gathered while bus-off say nothing about the recovered bus
+        this->events_to_log_ = 0;
+      }
+    }
+  } else {
+    this->events_to_log_ |= events;
+    if (this->events_to_log_ != 0 && (now - this->last_event_log_time_) >= EVENT_LOG_THROTTLE_MS) {
+      if (this->events_to_log_ & (CanEventFlags::CAN_EVENT_PASSIVE | CanEventFlags::CAN_EVENT_ACTIVE)) {
+        bool error_passive = this->events_to_log_ & CanEventFlags::CAN_EVENT_PASSIVE;
+        if (error_passive && (this->events_to_log_ & CanEventFlags::CAN_EVENT_ACTIVE)) {
+          // Both edges within one throttle window, so the counters decide the current state
+          auto status = this->get_status();
+          error_passive = status.rx_error_counter >= CAN_ERROR_PASSIVE_THRESHOLD ||
+                          status.tx_error_counter >= CAN_ERROR_PASSIVE_THRESHOLD;
+        }
+        ESP_LOGW(TAG, "entered %s", error_passive ? LOG_STR_LITERAL("error-passive") : LOG_STR_LITERAL("error-active"));
+      }
+      if (this->events_to_log_ & CanEventFlags::CAN_EVENT_RX_QUEUE_FULL) {
+        ESP_LOGD(TAG, "receive buffer overrun");
+      }
+      this->events_to_log_ = 0;
+      this->last_event_log_time_ = now;
+    }
+  }
+
+#ifdef ESPHOME_LOG_HAS_VERBOSE
+  if ((now - this->last_state_log_time_) >= STATE_LOG_INTERVAL_MS) {
+    auto status = this->get_status();
+    ESP_LOGV(TAG, "Status: bus_off %d, tx_err %d, rx_err %d", status.bus_off, status.tx_error_counter,
+             status.rx_error_counter);
+    this->last_state_log_time_ = now;
+  }
+#endif
+}
+
 }  // namespace esphome::canbus

esphome/components/canbus/canbus.h

@@ -48,6 +48,8 @@ template<typename... Ts> class CanbusSendAction;
 /* CAN payload length definitions according to ISO 11898-1 */
 static const uint8_t CAN_MAX_DATA_LENGTH = 8;
 
+static const uint8_t CAN_ERROR_PASSIVE_THRESHOLD = 128;
+
 /*
 Can Frame describes a normative CAN Frame
 The RTR = Remote Transmission Request is implemented in every CAN controller but rarely used
@@ -61,6 +63,26 @@ struct CanFrame {
   uint8_t data[CAN_MAX_DATA_LENGTH] __attribute__((aligned(8)));
 };
 
+enum CanEventFlags : uint8_t {
+  CAN_EVENT_PASSIVE = 1 << 0,
+  CAN_EVENT_ACTIVE = 1 << 1,
+  CAN_EVENT_BUS_OFF = 1 << 2,
+  CAN_EVENT_RX_QUEUE_FULL = 1 << 3,
+};
+
+static constexpr uint32_t CAN_STATUS_UNSET = UINT32_MAX;
+
+struct CanStatus {
+  bool bus_off{false};
+  uint8_t rx_error_counter{0};
+  uint8_t tx_error_counter{0};
+  uint32_t tx_failed_count{CAN_STATUS_UNSET};
+  uint32_t rx_missed_count{CAN_STATUS_UNSET};
+  uint32_t rx_overrun_count{CAN_STATUS_UNSET};
+  uint32_t arb_lost_count{CAN_STATUS_UNSET};
+  uint32_t bus_error_count{CAN_STATUS_UNSET};
+};
+
 class Canbus : public Component {
  public:
   Canbus(){};
@@ -83,6 +105,7 @@ class Canbus : public Component {
   void set_use_extended_id(bool use_extended_id) { this->use_extended_id_ = use_extended_id; }
   void set_bitrate(CanSpeed bit_rate) { this->bit_rate_ = bit_rate; }
   void set_max_frames_per_loop(uint32_t max_frames_per_loop) { this->max_frames_per_loop_ = max_frames_per_loop; }
+  virtual CanStatus get_status() { return {}; }
 
   void add_trigger(CanbusTrigger *trigger);
   /**
@@ -104,12 +127,33 @@ class Canbus : public Component {
   uint32_t max_frames_per_loop_{50};  // Keep in sync with DEFAULT_MAX_FRAMES_PER_LOOP in __init__.py
   CanSpeed bit_rate_{CAN_125KBPS};    // Keep in sync with DEFAULT_BIT_RATE in __init__.py
   bool use_extended_id_{false};
+  uint8_t events_to_log_{0};
+  bool bus_off_{false};
   CallbackManager<void(uint32_t can_id, bool extended_id, bool rtr, const std::vector<uint8_t> &data)>
       callback_manager_{};
 
+  // interval in which to check for new can bus events (bus-off, passive, active)
+  static constexpr uint32_t EVENT_CHECK_INTERVAL_MS = 100;
+  uint32_t last_event_check_time_{0};
+
+  // time to wait after logging an event before logging the next event(s)
+  static constexpr uint32_t EVENT_LOG_THROTTLE_MS = 1000;
+  uint32_t last_event_log_time_{0};
+
+  // time span without bus-off events before the bus is declared recovered
+  static constexpr uint32_t EVENT_LOG_BUS_OFF_HOLDOFF_MS = 1000;
+  uint32_t last_bus_off_time_{0};
+
+#ifdef ESPHOME_LOG_HAS_VERBOSE
+  static constexpr uint32_t STATE_LOG_INTERVAL_MS = 1000;
+  uint32_t last_state_log_time_{0};
+#endif
+
+  void log_events_(CanEventFlags events, uint32_t now);
   virtual bool setup_internal() = 0;
   virtual Error send_message(struct CanFrame *frame) = 0;
   virtual Error read_message(struct CanFrame *frame) = 0;
+  virtual CanEventFlags get_events() { return CanEventFlags{}; }
 };
 
 template<typename... Ts> class CanbusSendAction final : public Action<Ts...>, public Parented<Canbus> {

esphome/components/esp32_can/canbus.py

@@ -129,7 +129,7 @@ async def to_code(config: ConfigType) -> None:
     # Also enable esp_driver_twai for future migration to new API
     include_builtin_idf_component("esp_driver_twai")
     var = cg.new_Pvariable(config[CONF_ID])
-    await canbus.register_canbus(var, config)
+    await canbus.register_canbus(var, config, reports_status=True)
 
     cg.add(var.set_rx(config[CONF_RX_PIN]))
     cg.add(var.set_tx(config[CONF_TX_PIN]))

esphome/components/esp32_can/esp32_can.cpp

@@ -84,6 +84,8 @@ bool ESP32Can::setup_internal() {
   twai_general_config_t g_config =
       TWAI_GENERAL_CONFIG_DEFAULT((gpio_num_t) this->tx_, (gpio_num_t) this->rx_, twai_mode);
   g_config.controller_id = next_twai_ctrl_num++;
+  g_config.alerts_enabled = TWAI_ALERT_ERR_PASS | TWAI_ALERT_ERR_ACTIVE | TWAI_ALERT_BUS_OFF |
+                            TWAI_ALERT_BUS_RECOVERED | TWAI_ALERT_RX_QUEUE_FULL;
   if (this->tx_queue_len_.has_value()) {
     g_config.tx_queue_len = this->tx_queue_len_.value();
   }
@@ -116,6 +118,86 @@ bool ESP32Can::setup_internal() {
   return true;
 }
 
+canbus::CanEventFlags ESP32Can::get_events() {
+  if (this->twai_handle_ == nullptr) {
+    return {};  // not set up yet, or setup failed
+  }
+
+  uint32_t alerts;
+  esp_err_t err = twai_read_alerts_v2(this->twai_handle_, &alerts, 0);
+  if (err != ESP_OK) {
+    if (err != ESP_ERR_TIMEOUT) {
+      ESP_LOGD(TAG, "failed to get CAN events");
+    }
+    alerts = 0;
+  }
+
+  uint8_t events = 0;
+  if (alerts & TWAI_ALERT_ERR_PASS) {
+    events |= canbus::CAN_EVENT_PASSIVE;
+  }
+  if (alerts & TWAI_ALERT_ERR_ACTIVE) {
+    events |= canbus::CAN_EVENT_ACTIVE;
+  }
+  if (alerts & TWAI_ALERT_BUS_OFF) {
+    events |= canbus::CAN_EVENT_BUS_OFF;
+    // Start recovery at once, as the MCP2515 does in hardware
+    this->recovery_pending_ = true;
+  }
+  if (alerts & TWAI_ALERT_BUS_RECOVERED) {
+    // Recovery leaves the controller stopped
+    this->restart_pending_ = true;
+  }
+  if (this->recovery_pending_ || this->restart_pending_) {
+    this->handle_bus_off_recovery_();
+  }
+  if (alerts & TWAI_ALERT_RX_QUEUE_FULL) {
+    events |= canbus::CAN_EVENT_RX_QUEUE_FULL;
+  }
+  return static_cast<canbus::CanEventFlags>(events);
+}
+
+void ESP32Can::handle_bus_off_recovery_() {
+  // These only fail with an invalid handle or outside the expected state; retry on the next pass
+  if (this->recovery_pending_) {
+    if (twai_initiate_recovery_v2(this->twai_handle_) != ESP_OK) {
+      this->status_set_error(LOG_STR("Recovery after bus off failed"));
+      return;
+    }
+    this->recovery_pending_ = false;
+  }
+  if (this->restart_pending_) {
+    if (twai_start_v2(this->twai_handle_) != ESP_OK) {
+      this->status_set_error(LOG_STR("Restart after bus off failed"));
+      return;
+    }
+    this->restart_pending_ = false;
+  }
+  this->status_clear_error();
+}
+
+canbus::CanStatus ESP32Can::get_status() {
+  canbus::CanStatus status = {};
+
+  twai_status_info_t twai_status;
+
+  if (this->twai_handle_ != nullptr && twai_get_status_info_v2(this->twai_handle_, &twai_status) == ESP_OK) {
+    status.bus_off = (twai_status.state == TWAI_STATE_BUS_OFF) || (twai_status.state == TWAI_STATE_RECOVERING);
+    status.rx_error_counter = twai_status.rx_error_counter;
+    status.tx_error_counter = twai_status.tx_error_counter;
+
+    status.tx_failed_count = twai_status.tx_failed_count;
+    status.rx_missed_count = twai_status.rx_missed_count;
+    status.rx_overrun_count = twai_status.rx_overrun_count;
+    status.arb_lost_count = twai_status.arb_lost_count;
+    status.bus_error_count = twai_status.bus_error_count;
+  } else {
+    ESP_LOGD(TAG, "failed to get CAN status");
+  }
+
+  return status;
+}
+
 canbus::Error ESP32Can::send_message(struct canbus::CanFrame *frame) {
   // In listen-only mode, we cannot transmit
   if (this->mode_ == CAN_MODE_LISTEN_ONLY) {

esphome/components/esp32_can/esp32_can.h

@@ -24,16 +24,21 @@ class ESP32Can final : public canbus::Canbus {
   void set_tx_enqueue_timeout_ms(uint32_t tx_enqueue_timeout_ms) {
     this->tx_enqueue_timeout_ticks_ = pdMS_TO_TICKS(tx_enqueue_timeout_ms);
   }
+  canbus::CanStatus get_status() override;
   ESP32Can(){};
 
  protected:
   bool setup_internal() override;
+  canbus::CanEventFlags get_events() override;
   canbus::Error send_message(struct canbus::CanFrame *frame) override;
   canbus::Error read_message(struct canbus::CanFrame *frame) override;
+  void handle_bus_off_recovery_();
 
   int rx_{-1};
   int tx_{-1};
   CanMode mode_{CAN_MODE_NORMAL};
+  bool recovery_pending_{false};
+  bool restart_pending_{false};
   TickType_t tx_enqueue_timeout_ticks_{};
   optional<uint32_t> tx_queue_len_{};
   optional<uint32_t> rx_queue_len_{};

esphome/components/mcp2515/canbus.py

@@ -40,7 +40,7 @@ CONFIG_SCHEMA = canbus.CANBUS_SCHEMA.extend(
 async def to_code(config: ConfigType) -> None:
     rhs = mcp2515.new()
     var = cg.Pvariable(config[CONF_ID], rhs)
-    await canbus.register_canbus(var, config)
+    await canbus.register_canbus(var, config, reports_status=True)
     if CONF_CLOCK in config:
         canclock = CAN_CLOCK[config[CONF_CLOCK]]
         cg.add(var.set_mcp_clock(canclock))

esphome/components/mcp2515/mcp2515.cpp

@@ -43,6 +43,48 @@ bool MCP2515::setup_internal() {
   return true;
 }
 
+canbus::CanEventFlags MCP2515::get_events() {
+  uint8_t events = 0;
+  uint8_t error_flags = this->get_error_flags_();
+
+  // Error-passive is one state for RX and TX together, so only a change of the combined flag is an event
+  bool was_passive = this->last_error_flags_ & (EFLG_RXEP | EFLG_TXEP);
+  bool is_passive = error_flags & (EFLG_RXEP | EFLG_TXEP);
+  if (was_passive != is_passive) {
+    events |= is_passive ? canbus::CAN_EVENT_PASSIVE : canbus::CAN_EVENT_ACTIVE;
+  }
+  if ((this->last_error_flags_ ^ error_flags) & EFLG_TXBO) {
+    events |= canbus::CAN_EVENT_BUS_OFF;
+  }
+
+  // The receive flowchart in the datasheet says that if rollover is set (BUKT), RX1OVR flag will be set
+  // once both buffers are full. However, the RX0OVR flag is actually set instead.
+  // We can just check for both though because it doesn't break anything.
+  if (error_flags & (EFLG_RX0OVR | EFLG_RX1OVR)) {
+    events |= canbus::CAN_EVENT_RX_QUEUE_FULL;
+    this->clear_rx_n_ovr_flags_();
+  }
+
+  this->last_error_flags_ = error_flags;
+  return static_cast<canbus::CanEventFlags>(events);
+}
+
+canbus::CanStatus MCP2515::get_status() {
+  canbus::CanStatus status = {};
+
+  uint8_t error_flags = this->get_error_flags_();
+  status.bus_off = error_flags & EFLG_TXBO;
+
+  // Transmit Error Counter is followed by Receive Error Counter so we're reading both at once
+  uint8_t err_counters[2];
+  this->read_registers_(MCP_TEC, err_counters, 2);
+
+  status.rx_error_counter = err_counters[1];
+  status.tx_error_counter = err_counters[0];
+
+  return status;
+}
+
 canbus::Error MCP2515::reset_() {
   this->enable();
   this->transfer_byte(INSTRUCTION_RESET);
@@ -331,17 +373,6 @@ canbus::Error MCP2515::read_message(struct canbus::CanFrame *frame) {
     rc = canbus::ERROR_NOMSG;
   }
 
-#ifdef ESPHOME_LOG_HAS_DEBUG
-  uint8_t err = get_error_flags_();
-  // The receive flowchart in the datasheet says that if rollover is set (BUKT), RX1OVR flag will be set
-  // once both buffers are full. However, the RX0OVR flag is actually set instead.
-  // We can just check for both though because it doesn't break anything.
-  if (err & (EFLG_RX0OVR | EFLG_RX1OVR)) {
-    ESP_LOGD(TAG, "receive buffer overrun");
-    clear_rx_n_ovr_flags_();
-  }
-#endif
-
   return rc;
 }
 

esphome/components/mcp2515/mcp2515.h

@@ -58,6 +58,7 @@ class MCP2515 final : public canbus::Canbus,
   MCP2515(){};
   void set_mcp_clock(CanClock clock) { this->mcp_clock_ = clock; };
   void set_mcp_mode(const CanctrlReqopMode mode) { this->mcp_mode_ = mode; }
+  canbus::CanStatus get_status() override;
   static const struct TxBnRegs {
     REGISTER CTRL;
     REGISTER SIDH;
@@ -74,7 +75,11 @@ class MCP2515 final : public canbus::Canbus,
  protected:
   CanClock mcp_clock_{MCP_8MHZ};
   CanctrlReqopMode mcp_mode_ = CANCTRL_REQOP_NORMAL;
+
+  uint8_t last_error_flags_{0};
+
   bool setup_internal() override;
+  canbus::CanEventFlags get_events() override;
   canbus::Error set_mode_(CanctrlReqopMode mode);
 
   uint8_t read_register_(REGISTER reg);

tests/components/esp32_can/common.yaml

@@ -44,3 +44,12 @@ canbus:
                   break;
                 // to be continued...
               }
+
+interval:
+  - interval: 1s
+    then:
+      - lambda: |-
+          auto status = id(esp32_can_esp32_internal_can).get_status();
+          ESP_LOGD("canbus_status", "bus_off: %d, tx_err: %d, rx_err: %d, bus_err: %" PRIu32 ", arb_lost: %" PRIu32,
+            status.bus_off, status.tx_error_counter, status.rx_error_counter,
+            status.bus_error_count, status.arb_lost_count);

tests/components/mcp2515/common.yaml

@@ -42,6 +42,17 @@ canbus:
                 // to be continued...
               }
 
+interval:
+  - interval: 1s
+    then:
+      - lambda: |-
+          auto status = id(mcp2515_can).get_status();
+          ESP_LOGD("canbus_status", "bus_off: %d, tx_err: %d, rx_err: %d",
+            status.bus_off,
+            status.tx_error_counter,
+            status.rx_error_counter
+          );
+
 button:
   - platform: template
     name: MCP2515 Send