[nrf52, ble_nus] add logging over BLE (#9846)

CODEOWNERS

@@ -70,6 +70,7 @@ esphome/components/bl0939/* @ziceva
 esphome/components/bl0940/* @dan-s-github @tobias-
 esphome/components/bl0942/* @dbuezas @dwmw2
 esphome/components/ble_client/* @buxtronix @clydebarrow
+esphome/components/ble_nus/* @tomaszduda23
 esphome/components/bluetooth_proxy/* @bdraco @jesserockz
 esphome/components/bme280_base/* @esphome/core
 esphome/components/bme280_spi/* @apbodrov

esphome/components/ble_nus/__init__.py

@@ -0,0 +1,29 @@
+import esphome.codegen as cg
+from esphome.components.zephyr import zephyr_add_prj_conf
+import esphome.config_validation as cv
+from esphome.const import CONF_ID, CONF_LOGS, CONF_TYPE
+
+AUTO_LOAD = ["zephyr_ble_server"]
+CODEOWNERS = ["@tomaszduda23"]
+
+ble_nus_ns = cg.esphome_ns.namespace("ble_nus")
+BLENUS = ble_nus_ns.class_("BLENUS", cg.Component)
+
+CONFIG_SCHEMA = cv.All(
+    cv.Schema(
+        {
+            cv.GenerateID(): cv.declare_id(BLENUS),
+            cv.Optional(CONF_TYPE, default=CONF_LOGS): cv.one_of(
+                *[CONF_LOGS], lower=True
+            ),
+        }
+    ).extend(cv.COMPONENT_SCHEMA),
+    cv.only_with_framework("zephyr"),
+)
+
+
+async def to_code(config):
+    var = cg.new_Pvariable(config[CONF_ID])
+    zephyr_add_prj_conf("BT_NUS", True)
+    cg.add(var.set_expose_log(config[CONF_TYPE] == CONF_LOGS))
+    await cg.register_component(var, config)

esphome/components/ble_nus/ble_nus.cpp

@@ -0,0 +1,157 @@
+#ifdef USE_ZEPHYR
+#include "ble_nus.h"
+#include <zephyr/kernel.h>
+#include <bluetooth/services/nus.h>
+#include "esphome/core/log.h"
+#ifdef USE_LOGGER
+#include "esphome/components/logger/logger.h"
+#include "esphome/core/application.h"
+#endif
+#include <zephyr/sys/ring_buffer.h>
+
+namespace esphome::ble_nus {
+
+constexpr size_t BLE_TX_BUF_SIZE = 2048;
+
+// NOLINTBEGIN(cppcoreguidelines-avoid-non-const-global-variables)
+BLENUS *global_ble_nus;
+RING_BUF_DECLARE(global_ble_tx_ring_buf, BLE_TX_BUF_SIZE);
+// NOLINTEND(cppcoreguidelines-avoid-non-const-global-variables)
+
+static const char *const TAG = "ble_nus";
+
+size_t BLENUS::write_array(const uint8_t *data, size_t len) {
+  if (atomic_get(&this->tx_status_) == TX_DISABLED) {
+    return 0;
+  }
+  return ring_buf_put(&global_ble_tx_ring_buf, data, len);
+}
+
+void BLENUS::connected(bt_conn *conn, uint8_t err) {
+  if (err == 0) {
+    global_ble_nus->conn_.store(bt_conn_ref(conn));
+  }
+}
+
+void BLENUS::disconnected(bt_conn *conn, uint8_t reason) {
+  if (global_ble_nus->conn_) {
+    bt_conn_unref(global_ble_nus->conn_.load());
+    // Connection array is global static.
+    // Reference can be kept even if disconnected.
+  }
+}
+
+void BLENUS::tx_callback(bt_conn *conn) {
+  atomic_cas(&global_ble_nus->tx_status_, TX_BUSY, TX_ENABLED);
+  ESP_LOGVV(TAG, "Sent operation completed");
+}
+
+void BLENUS::send_enabled_callback(bt_nus_send_status status) {
+  switch (status) {
+    case BT_NUS_SEND_STATUS_ENABLED:
+      atomic_set(&global_ble_nus->tx_status_, TX_ENABLED);
+#ifdef USE_LOGGER
+      if (global_ble_nus->expose_log_) {
+        App.schedule_dump_config();
+      }
+#endif
+      ESP_LOGD(TAG, "NUS notification has been enabled");
+      break;
+    case BT_NUS_SEND_STATUS_DISABLED:
+      atomic_set(&global_ble_nus->tx_status_, TX_DISABLED);
+      ESP_LOGD(TAG, "NUS notification has been disabled");
+      break;
+  }
+}
+
+void BLENUS::rx_callback(bt_conn *conn, const uint8_t *const data, uint16_t len) {
+  ESP_LOGD(TAG, "Received %d bytes.", len);
+}
+
+void BLENUS::setup() {
+  bt_nus_cb callbacks = {
+      .received = rx_callback,
+      .sent = tx_callback,
+      .send_enabled = send_enabled_callback,
+  };
+
+  bt_nus_init(&callbacks);
+
+  static bt_conn_cb conn_callbacks = {
+      .connected = BLENUS::connected,
+      .disconnected = BLENUS::disconnected,
+  };
+
+  bt_conn_cb_register(&conn_callbacks);
+
+  global_ble_nus = this;
+#ifdef USE_LOGGER
+  if (logger::global_logger != nullptr && this->expose_log_) {
+    logger::global_logger->add_on_log_callback(
+        [this](int level, const char *tag, const char *message, size_t message_len) {
+          this->write_array(reinterpret_cast<const uint8_t *>(message), message_len);
+          const char c = '\n';
+          this->write_array(reinterpret_cast<const uint8_t *>(&c), 1);
+        });
+  }
+
+#endif
+}
+
+void BLENUS::dump_config() {
+  ESP_LOGCONFIG(TAG, "ble nus:");
+  ESP_LOGCONFIG(TAG, "  log: %s", YESNO(this->expose_log_));
+  uint32_t mtu = 0;
+  bt_conn *conn = this->conn_.load();
+  if (conn) {
+    mtu = bt_nus_get_mtu(conn);
+  }
+  ESP_LOGCONFIG(TAG, "  MTU: %u", mtu);
+}
+
+void BLENUS::loop() {
+  if (ring_buf_is_empty(&global_ble_tx_ring_buf)) {
+    return;
+  }
+
+  if (!atomic_cas(&this->tx_status_, TX_ENABLED, TX_BUSY)) {
+    if (atomic_get(&this->tx_status_) == TX_DISABLED) {
+      ring_buf_reset(&global_ble_tx_ring_buf);
+    }
+    return;
+  }
+
+  bt_conn *conn = this->conn_.load();
+  if (conn) {
+    conn = bt_conn_ref(conn);
+  }
+
+  if (nullptr == conn) {
+    atomic_cas(&this->tx_status_, TX_BUSY, TX_ENABLED);
+    return;
+  }
+
+  uint32_t req_len = bt_nus_get_mtu(conn);
+
+  uint8_t *buf;
+  uint32_t size = ring_buf_get_claim(&global_ble_tx_ring_buf, &buf, req_len);
+
+  int err, err2;
+
+  err = bt_nus_send(conn, buf, size);
+  err2 = ring_buf_get_finish(&global_ble_tx_ring_buf, size);
+  if (err2) {
+    // It should no happen.
+    ESP_LOGE(TAG, "Size %u exceeds valid bytes in the ring buffer (%d error)", size, err2);
+  }
+  if (err == 0) {
+    ESP_LOGVV(TAG, "Sent %d bytes", size);
+  } else {
+    ESP_LOGE(TAG, "Failed to send %d bytes (%d error)", size, err);
+    atomic_cas(&this->tx_status_, TX_BUSY, TX_ENABLED);
+  }
+  bt_conn_unref(conn);
+}
+
+}  // namespace esphome::ble_nus
+#endif

esphome/components/ble_nus/ble_nus.h

@@ -0,0 +1,37 @@
+#pragma once
+#ifdef USE_ZEPHYR
+#include "esphome/core/defines.h"
+#include "esphome/core/component.h"
+#include <shell/shell_bt_nus.h>
+#include <atomic>
+
+namespace esphome::ble_nus {
+
+class BLENUS : public Component {
+  enum TxStatus {
+    TX_DISABLED,
+    TX_ENABLED,
+    TX_BUSY,
+  };
+
+ public:
+  void setup() override;
+  void dump_config() override;
+  void loop() override;
+  size_t write_array(const uint8_t *data, size_t len);
+  void set_expose_log(bool expose_log) { this->expose_log_ = expose_log; }
+
+ protected:
+  static void send_enabled_callback(bt_nus_send_status status);
+  static void tx_callback(bt_conn *conn);
+  static void rx_callback(bt_conn *conn, const uint8_t *data, uint16_t len);
+  static void connected(bt_conn *conn, uint8_t err);
+  static void disconnected(bt_conn *conn, uint8_t reason);
+
+  std::atomic<bt_conn *> conn_ = nullptr;
+  bool expose_log_ = false;
+  atomic_t tx_status_ = ATOMIC_INIT(TX_DISABLED);
+};
+
+}  // namespace esphome::ble_nus
+#endif

esphome/components/zephyr_ble_server/__init__.py

@@ -0,0 +1,34 @@
+import esphome.codegen as cg
+from esphome.components.zephyr import zephyr_add_prj_conf
+import esphome.config_validation as cv
+from esphome.const import CONF_ESPHOME, CONF_ID, CONF_NAME, Framework
+import esphome.final_validate as fv
+
+zephyr_ble_server_ns = cg.esphome_ns.namespace("zephyr_ble_server")
+BLEServer = zephyr_ble_server_ns.class_("BLEServer", cg.Component)
+
+CONFIG_SCHEMA = cv.All(
+    cv.Schema(
+        {
+            cv.GenerateID(): cv.declare_id(BLEServer),
+        }
+    ).extend(cv.COMPONENT_SCHEMA),
+    cv.only_with_framework(Framework.ZEPHYR),
+)
+
+
+def _final_validate(_):
+    full_config = fv.full_config.get()
+    zephyr_add_prj_conf("BT_DEVICE_NAME", full_config[CONF_ESPHOME][CONF_NAME])
+
+
+FINAL_VALIDATE_SCHEMA = _final_validate
+
+
+async def to_code(config):
+    var = cg.new_Pvariable(config[CONF_ID])
+    zephyr_add_prj_conf("BT", True)
+    zephyr_add_prj_conf("BT_PERIPHERAL", True)
+    zephyr_add_prj_conf("BT_RX_STACK_SIZE", 1536)
+    # zephyr_add_prj_conf("BT_LL_SW_SPLIT", True)
+    await cg.register_component(var, config)

esphome/components/zephyr_ble_server/ble_server.cpp

@@ -0,0 +1,100 @@
+#ifdef USE_ZEPHYR
+#include "ble_server.h"
+#include "esphome/core/defines.h"
+#include "esphome/core/log.h"
+#include <zephyr/bluetooth/bluetooth.h>
+#include <zephyr/bluetooth/conn.h>
+
+namespace esphome::zephyr_ble_server {
+
+static const char *const TAG = "zephyr_ble_server";
+
+static struct k_work advertise_work;  // NOLINT(cppcoreguidelines-avoid-non-const-global-variables)
+
+#define DEVICE_NAME CONFIG_BT_DEVICE_NAME
+#define DEVICE_NAME_LEN (sizeof(DEVICE_NAME) - 1)
+
+static const struct bt_data AD[] = {
+    BT_DATA_BYTES(BT_DATA_FLAGS, (BT_LE_AD_GENERAL | BT_LE_AD_NO_BREDR)),
+    BT_DATA(BT_DATA_NAME_COMPLETE, DEVICE_NAME, DEVICE_NAME_LEN),
+};
+
+static const struct bt_data SD[] = {
+#ifdef USE_OTA
+    BT_DATA_BYTES(BT_DATA_UUID128_ALL, 0x84, 0xaa, 0x60, 0x74, 0x52, 0x8a, 0x8b, 0x86, 0xd3, 0x4c, 0xb7, 0x1d, 0x1d,
+                  0xdc, 0x53, 0x8d),
+#endif
+};
+
+const struct bt_le_adv_param *const ADV_PARAM = BT_LE_ADV_CONN;
+
+static void advertise(struct k_work *work) {
+  int rc = bt_le_adv_stop();
+  if (rc) {
+    ESP_LOGE(TAG, "Advertising failed to stop (rc %d)", rc);
+  }
+
+  rc = bt_le_adv_start(ADV_PARAM, AD, ARRAY_SIZE(AD), SD, ARRAY_SIZE(SD));
+  if (rc) {
+    ESP_LOGE(TAG, "Advertising failed to start (rc %d)", rc);
+    return;
+  }
+  ESP_LOGI(TAG, "Advertising successfully started");
+}
+
+static void connected(struct bt_conn *conn, uint8_t err) {
+  if (err) {
+    ESP_LOGE(TAG, "Connection failed (err 0x%02x)", err);
+  } else {
+    ESP_LOGI(TAG, "Connected");
+  }
+}
+
+static void disconnected(struct bt_conn *conn, uint8_t reason) {
+  ESP_LOGI(TAG, "Disconnected (reason 0x%02x)", reason);
+  k_work_submit(&advertise_work);
+}
+
+static void bt_ready(int err) {
+  if (err != 0) {
+    ESP_LOGE(TAG, "Bluetooth failed to initialise: %d", err);
+  } else {
+    k_work_submit(&advertise_work);
+  }
+}
+
+BT_CONN_CB_DEFINE(conn_callbacks) = {
+    .connected = connected,
+    .disconnected = disconnected,
+};
+
+void BLEServer::setup() {
+  k_work_init(&advertise_work, advertise);
+  resume_();
+}
+
+void BLEServer::loop() {
+  if (this->suspended_) {
+    resume_();
+    this->suspended_ = false;
+  }
+}
+
+void BLEServer::resume_() {
+  int rc = bt_enable(bt_ready);
+  if (rc != 0) {
+    ESP_LOGE(TAG, "Bluetooth enable failed: %d", rc);
+    return;
+  }
+}
+
+void BLEServer::on_shutdown() {
+  struct k_work_sync sync;
+  k_work_cancel_sync(&advertise_work, &sync);
+  bt_disable();
+  this->suspended_ = true;
+}
+
+}  // namespace esphome::zephyr_ble_server
+
+#endif

esphome/components/zephyr_ble_server/ble_server.h

@@ -0,0 +1,19 @@
+#pragma once
+#ifdef USE_ZEPHYR
+#include "esphome/core/component.h"
+
+namespace esphome::zephyr_ble_server {
+
+class BLEServer : public Component {
+ public:
+  void setup() override;
+  void loop() override;
+  void on_shutdown() override;
+
+ protected:
+  void resume_();
+  bool suspended_ = false;
+};
+
+}  // namespace esphome::zephyr_ble_server
+#endif

script/helpers_zephyr.py

@@ -25,6 +25,7 @@ int main() { return 0;}
     Path(zephyr_dir / "prj.conf").write_text(
         """
 CONFIG_NEWLIB_LIBC=y
+CONFIG_BT=y
 CONFIG_ADC=y
 """,
         encoding="utf-8",

tests/components/ble_nus/test.nrf52-adafruit.yaml

@@ -0,0 +1,2 @@
+ble_nus:
+  type: logs

tests/components/ble_nus/test.nrf52-mcumgr.yaml

@@ -0,0 +1,2 @@
+ble_nus:
+  type: logs