Merge branch 'log-skip-vprintf-indirection' into integration

# Conflicts:
#	esphome/components/bluetooth_proxy/bluetooth_connection.cpp

esphome/components/ble_nus/__init__.py

@@ -1,29 +1,64 @@
 import esphome.codegen as cg
 from esphome.components.logger import request_log_listener
+from esphome.components.uart import (
+    UARTComponent,
+    debug_to_code,
+    maybe_empty_debug,
+    uart_ns,
+)
 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
+from esphome.const import (
+    CONF_DEBUG,
+    CONF_ID,
+    CONF_LOGS,
+    CONF_RX_BUFFER_SIZE,
+    CONF_TX_BUFFER_SIZE,
+    CONF_TYPE,
+)
+from esphome.types import ConfigType
 
-AUTO_LOAD = ["zephyr_ble_server"]
+AUTO_LOAD = ["zephyr_ble_server", "uart"]
 CODEOWNERS = ["@tomaszduda23"]
 
 ble_nus_ns = cg.esphome_ns.namespace("ble_nus")
-BLENUS = ble_nus_ns.class_("BLENUS", cg.Component)
+BLENUS = ble_nus_ns.class_("BLENUS", cg.Component, UARTComponent)
+
+CONF_UART = "uart"
+
+
+def validate_rx_buffer(config: ConfigType) -> ConfigType:
+    config = config.copy()
+    if config[CONF_TYPE] == CONF_LOGS:
+        if CONF_RX_BUFFER_SIZE in config:
+            raise cv.Invalid("logs does not support rx_buffer_size")
+    elif CONF_RX_BUFFER_SIZE not in config:
+        config[CONF_RX_BUFFER_SIZE] = 512
+    return config
+
 
 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
+                *[CONF_LOGS, CONF_UART], lower=True
             ),
+            cv.Optional(CONF_TX_BUFFER_SIZE, default=512): cv.All(
+                cv.validate_bytes, cv.int_range(min=160, max=8192)
+            ),
+            cv.Optional(CONF_RX_BUFFER_SIZE): cv.All(
+                cv.validate_bytes, cv.int_range(min=160, max=8192)
+            ),
+            cv.Optional(CONF_DEBUG): maybe_empty_debug,
         }
     ).extend(cv.COMPONENT_SCHEMA),
     cv.only_with_framework("zephyr"),
+    validate_rx_buffer,
 )
 
 
-async def to_code(config):
+async def to_code(config: ConfigType) -> None:
     var = cg.new_Pvariable(config[CONF_ID])
     zephyr_add_prj_conf("BT_NUS", True)
     expose_log = config[CONF_TYPE] == CONF_LOGS
@@ -31,3 +66,11 @@ async def to_code(config):
     if expose_log:
         request_log_listener()  # Request a log listener slot for BLE NUS log streaming
     await cg.register_component(var, config)
+    cg.add_define("ESPHOME_BLE_NUS_TX_RING_BUFFER_SIZE", config[CONF_TX_BUFFER_SIZE])
+    if CONF_RX_BUFFER_SIZE in config:
+        cg.add_define(
+            "ESPHOME_BLE_NUS_RX_RING_BUFFER_SIZE", config[CONF_RX_BUFFER_SIZE]
+        )
+    if CONF_DEBUG in config:
+        cg.add_global(uart_ns.using)
+        await debug_to_code(config[CONF_DEBUG], var)

esphome/components/ble_nus/ble_nus.cpp

@@ -11,25 +11,111 @@
 
 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);
+RING_BUF_DECLARE(global_ble_tx_ring_buf, ESPHOME_BLE_NUS_TX_RING_BUFFER_SIZE);
+#ifdef ESPHOME_BLE_NUS_RX_RING_BUFFER_SIZE
+RING_BUF_DECLARE(global_ble_rx_ring_buf, ESPHOME_BLE_NUS_RX_RING_BUFFER_SIZE);
+#endif
 // 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) {
+void BLENUS::write_array(const uint8_t *data, size_t len) {
   if (atomic_get(&this->tx_status_) == TX_DISABLED) {
-    return 0;
+    return;
+  }
+  auto sent = ring_buf_put(&global_ble_tx_ring_buf, data, len);
+  if (sent < len) {
+    ESP_LOGE(TAG, "TX dropping %u bytes", len - sent);
+    return;
+  }
+#ifdef USE_UART_DEBUGGER
+  for (size_t i = 0; i < len; i++) {
+    this->debug_callback_.call(uart::UART_DIRECTION_TX, data[i]);
+  }
+#endif
+}
+
+bool BLENUS::peek_byte(uint8_t *data) {
+#ifdef ESPHOME_BLE_NUS_RX_RING_BUFFER_SIZE
+  if (this->has_peek_) {
+    *data = this->peek_buffer_;
+    return true;
+  }
+
+  if (this->read_byte(&this->peek_buffer_)) {
+    *data = this->peek_buffer_;
+    this->has_peek_ = true;
+    return true;
+  }
+
+  return false;
+#else
+  return false;
+#endif
+}
+
+bool BLENUS::read_array(uint8_t *data, size_t len) {
+#ifdef ESPHOME_BLE_NUS_RX_RING_BUFFER_SIZE
+  if (len == 0) {
+    return true;
+  }
+  if (this->available() < len) {
+    return false;
+  }
+
+  // First, use the peek buffer if available
+  if (this->has_peek_) {
+    data[0] = this->peek_buffer_;
+    this->has_peek_ = false;
+    data++;
+    if (--len == 0) {  // Decrement len first, then check it...
+      return true;     // No more to read
+    }
+  }
+
+  if (ring_buf_get(&global_ble_rx_ring_buf, data, len) != len) {
+    ESP_LOGE(TAG, "UART BLE unexpected size");
+    return false;
+  }
+#ifdef USE_UART_DEBUGGER
+  for (size_t i = 0; i < len; i++) {
+    this->debug_callback_.call(uart::UART_DIRECTION_RX, data[i]);
+  }
+#endif
+  return true;
+#else
+  return false;
+#endif
+}
+
+size_t BLENUS::available() {
+#ifdef ESPHOME_BLE_NUS_RX_RING_BUFFER_SIZE
+  uint32_t size = ring_buf_size_get(&global_ble_rx_ring_buf);
+  ESP_LOGVV(TAG, "UART BLE available %u", size);
+  return size + (this->has_peek_ ? 1 : 0);
+#else
+  return 0;
+#endif
+}
+
+void BLENUS::flush() {
+  constexpr uint32_t timeout_5sec = 5000;
+  uint32_t start = millis();
+  while (atomic_get(&this->tx_status_) != TX_DISABLED && !ring_buf_is_empty(&global_ble_tx_ring_buf)) {
+    if (millis() - start > timeout_5sec) {
+      ESP_LOGW(TAG, "Flush timeout");
+      return;
+    }
+    delay(1);
   }
-  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));
+    global_ble_nus->connected_ = true;
   }
 }
 
@@ -38,6 +124,7 @@ void BLENUS::disconnected(bt_conn *conn, uint8_t reason) {
     bt_conn_unref(global_ble_nus->conn_.load());
     // Connection array is global static.
     // Reference can be kept even if disconnected.
+    global_ble_nus->connected_ = false;
   }
 }
 
@@ -63,12 +150,19 @@ void BLENUS::send_enabled_callback(bt_nus_send_status status) {
       break;
   }
 }
-
 void BLENUS::rx_callback(bt_conn *conn, const uint8_t *const data, uint16_t len) {
-  ESP_LOGD(TAG, "Received %d bytes.", len);
+  ESP_LOGV(TAG, "Received %d bytes.", len);
+#ifdef ESPHOME_BLE_NUS_RX_RING_BUFFER_SIZE
+  auto recv_len = ring_buf_put(&global_ble_rx_ring_buf, data, len);
+  if (recv_len < len) {
+    ESP_LOGE(TAG, "RX dropping %u bytes", len - recv_len);
+  }
+#endif
 }
-
 void BLENUS::setup() {
+#ifdef ESPHOME_BLE_NUS_RX_RING_BUFFER_SIZE
+  this->rx_buffer_size_ = ESPHOME_BLE_NUS_RX_RING_BUFFER_SIZE;
+#endif
   bt_nus_cb callbacks = {
       .received = rx_callback,
       .sent = tx_callback,
@@ -106,16 +200,17 @@ void BLENUS::on_log(uint8_t level, const char *tag, const char *message, size_t
 #endif
 
 void BLENUS::dump_config() {
-  ESP_LOGCONFIG(TAG,
-                "ble nus:\n"
-                "  log: %s",
-                YESNO(this->expose_log_));
   uint32_t mtu = 0;
   bt_conn *conn = this->conn_.load();
-  if (conn) {
+  if (conn && this->connected_) {
     mtu = bt_nus_get_mtu(conn);
   }
-  ESP_LOGCONFIG(TAG, "  MTU: %u", mtu);
+  ESP_LOGCONFIG(TAG,
+                "ble nus:\n"
+                "  log: %s\n"
+                "  connected: %s\n"
+                "  MTU: %u",
+                YESNO(this->expose_log_), YESNO(this->connected_.load()), mtu);
 }
 
 void BLENUS::loop() {

esphome/components/ble_nus/ble_nus.h

@@ -2,6 +2,7 @@
 #ifdef USE_ZEPHYR
 #include "esphome/core/defines.h"
 #include "esphome/core/component.h"
+#include "esphome/components/uart/uart_component.h"
 #ifdef USE_LOGGER
 #include "esphome/components/logger/logger.h"
 #endif
@@ -10,7 +11,7 @@
 
 namespace esphome::ble_nus {
 
-class BLENUS : public Component {
+class BLENUS : public uart::UARTComponent, public Component {
   enum TxStatus {
     TX_DISABLED,
     TX_ENABLED,
@@ -21,7 +22,12 @@ class BLENUS : public Component {
   void setup() override;
   void dump_config() override;
   void loop() override;
-  size_t write_array(const uint8_t *data, size_t len);
+  void write_array(const uint8_t *data, size_t len) override;
+  bool peek_byte(uint8_t *data) override;
+  bool read_array(uint8_t *data, size_t len) override;
+  size_t available() override;
+  void flush() override;
+  void check_logger_conflict() override {}
   void set_expose_log(bool expose_log) { this->expose_log_ = expose_log; }
 #ifdef USE_LOGGER
   void on_log(uint8_t level, const char *tag, const char *message, size_t message_len);
@@ -37,6 +43,12 @@ class BLENUS : public Component {
   std::atomic<bt_conn *> conn_ = nullptr;
   bool expose_log_ = false;
   atomic_t tx_status_ = ATOMIC_INIT(TX_DISABLED);
+  std::atomic<bool> connected_{};
+#ifdef ESPHOME_BLE_NUS_RX_RING_BUFFER_SIZE
+  // RX buffer for peek functionality
+  uint8_t peek_buffer_{0};
+  bool has_peek_{false};
+#endif
 };
 
 }  // namespace esphome::ble_nus

esphome/components/bluetooth_proxy/bluetooth_connection.cpp

@@ -183,7 +183,10 @@ void BluetoothConnection::send_service_for_discovery_() {
   static constexpr size_t MAX_PACKET_SIZE = 1360;
 
   // Keep running total of actual message size
-  size_t current_size = resp.calculate_size();
+  size_t current_size = 0;
+  api::ProtoSize size;
+  resp.calculate_size(size);
+  current_size = size.get_size();
 
   while (this->send_service_ < this->service_count_) {
     esp_gattc_service_elem_t service_result;
@@ -299,7 +302,9 @@ void BluetoothConnection::send_service_for_discovery_() {
     }  // end if (total_char_count > 0)
 
     // Calculate the actual size of just this service
-    size_t service_size = service_resp.calculate_size() + 1;  // +1 for field tag
+    api::ProtoSize service_sizer;
+    service_resp.calculate_size(service_sizer);
+    size_t service_size = service_sizer.get_size() + 1;  // +1 for field tag
 
     // Check if adding this service would exceed the limit
     if (current_size + service_size > MAX_PACKET_SIZE) {
@@ -328,7 +333,7 @@ void BluetoothConnection::send_service_for_discovery_() {
   }
 
   // Send the message with dynamically batched services
-  api_conn->send_message(resp);
+  api_conn->send_message(resp, api::BluetoothGATTGetServicesResponse::MESSAGE_TYPE);
 }
 
 void BluetoothConnection::log_connection_error_(const char *operation, esp_gatt_status_t status) {
@@ -410,11 +415,14 @@ bool BluetoothConnection::gattc_event_handler(esp_gattc_cb_event_t event, esp_ga
         this->proxy_->send_gatt_error(this->address_, param->read.handle, param->read.status);
         break;
       }
+      auto *api_connection = this->proxy_->get_api_connection();
+      if (api_connection == nullptr)
+        break;
       api::BluetoothGATTReadResponse resp;
       resp.address = this->address_;
       resp.handle = param->read.handle;
       resp.set_data(param->read.value, param->read.value_len);
-      this->proxy_->get_api_connection()->send_message(resp);
+      api_connection->send_message(resp, api::BluetoothGATTReadResponse::MESSAGE_TYPE);
       break;
     }
     case ESP_GATTC_WRITE_CHAR_EVT:
@@ -424,10 +432,13 @@ bool BluetoothConnection::gattc_event_handler(esp_gattc_cb_event_t event, esp_ga
         this->proxy_->send_gatt_error(this->address_, param->write.handle, param->write.status);
         break;
       }
+      auto *api_connection = this->proxy_->get_api_connection();
+      if (api_connection == nullptr)
+        break;
       api::BluetoothGATTWriteResponse resp;
       resp.address = this->address_;
       resp.handle = param->write.handle;
-      this->proxy_->get_api_connection()->send_message(resp);
+      api_connection->send_message(resp, api::BluetoothGATTWriteResponse::MESSAGE_TYPE);
       break;
     }
     case ESP_GATTC_UNREG_FOR_NOTIFY_EVT: {
@@ -437,10 +448,13 @@ bool BluetoothConnection::gattc_event_handler(esp_gattc_cb_event_t event, esp_ga
         this->proxy_->send_gatt_error(this->address_, param->unreg_for_notify.handle, param->unreg_for_notify.status);
         break;
       }
+      auto *api_connection = this->proxy_->get_api_connection();
+      if (api_connection == nullptr)
+        break;
       api::BluetoothGATTNotifyResponse resp;
       resp.address = this->address_;
       resp.handle = param->unreg_for_notify.handle;
-      this->proxy_->get_api_connection()->send_message(resp);
+      api_connection->send_message(resp, api::BluetoothGATTNotifyResponse::MESSAGE_TYPE);
       break;
     }
     case ESP_GATTC_REG_FOR_NOTIFY_EVT: {
@@ -450,20 +464,26 @@ bool BluetoothConnection::gattc_event_handler(esp_gattc_cb_event_t event, esp_ga
         this->proxy_->send_gatt_error(this->address_, param->reg_for_notify.handle, param->reg_for_notify.status);
         break;
       }
+      auto *api_connection = this->proxy_->get_api_connection();
+      if (api_connection == nullptr)
+        break;
       api::BluetoothGATTNotifyResponse resp;
       resp.address = this->address_;
       resp.handle = param->reg_for_notify.handle;
-      this->proxy_->get_api_connection()->send_message(resp);
+      api_connection->send_message(resp, api::BluetoothGATTNotifyResponse::MESSAGE_TYPE);
       break;
     }
     case ESP_GATTC_NOTIFY_EVT: {
       ESP_LOGV(TAG, "[%d] [%s] ESP_GATTC_NOTIFY_EVT: handle=0x%2X", this->connection_index_, this->address_str_,
                param->notify.handle);
+      auto *api_connection = this->proxy_->get_api_connection();
+      if (api_connection == nullptr)
+        break;
       api::BluetoothGATTNotifyDataResponse resp;
       resp.address = this->address_;
       resp.handle = param->notify.handle;
       resp.set_data(param->notify.value, param->notify.value_len);
-      this->proxy_->get_api_connection()->send_message(resp);
+      api_connection->send_message(resp, api::BluetoothGATTNotifyDataResponse::MESSAGE_TYPE);
       break;
     }
     default:

esphome/components/bluetooth_proxy/bluetooth_proxy.cpp

@@ -420,6 +420,8 @@ void BluetoothProxy::send_gatt_error(uint64_t address, uint16_t handle, esp_err_
 }
 
 void BluetoothProxy::send_device_pairing(uint64_t address, bool paired, esp_err_t error) {
+  if (this->api_connection_ == nullptr)
+    return;
   api::BluetoothDevicePairingResponse call;
   call.address = address;
   call.paired = paired;
@@ -429,6 +431,8 @@ void BluetoothProxy::send_device_pairing(uint64_t address, bool paired, esp_err_
 }
 
 void BluetoothProxy::send_device_unpairing(uint64_t address, bool success, esp_err_t error) {
+  if (this->api_connection_ == nullptr)
+    return;
   api::BluetoothDeviceUnpairingResponse call;
   call.address = address;
   call.success = success;

esphome/core/defines.h

@@ -358,6 +358,8 @@
 #endif
 
 #ifdef USE_NRF52
+#define ESPHOME_BLE_NUS_TX_RING_BUFFER_SIZE 512
+#define ESPHOME_BLE_NUS_RX_RING_BUFFER_SIZE 512
 #define USE_ESPHOME_TASK_LOG_BUFFER
 #define USE_LOGGER_EARLY_MESSAGE
 #define USE_LOGGER_UART_SELECTION_USB_CDC

esphome/core/log.cpp

@@ -8,18 +8,31 @@
 
 namespace esphome {
 
+// Call log_vprintf_ directly to avoid extra indirection through esp_log_vprintf_
 void HOT esp_log_printf_(int level, const char *tag, int line, const char *format, ...) {  // NOLINT
+#ifdef USE_LOGGER
+  auto *log = logger::global_logger;
+  if (log == nullptr)
+    return;
+
   va_list arg;
   va_start(arg, format);
-  esp_log_vprintf_(level, tag, line, format, arg);
+  log->log_vprintf_(static_cast<uint8_t>(level), tag, line, format, arg);
   va_end(arg);
+#endif
 }
 #ifdef USE_STORE_LOG_STR_IN_FLASH
 void HOT esp_log_printf_(int level, const char *tag, int line, const __FlashStringHelper *format, ...) {
+#ifdef USE_LOGGER
+  auto *log = logger::global_logger;
+  if (log == nullptr)
+    return;
+
   va_list arg;
   va_start(arg, format);
-  esp_log_vprintf_(level, tag, line, format, arg);
+  log->log_vprintf_(static_cast<uint8_t>(level), tag, line, format, arg);
   va_end(arg);
+#endif
 }
 #endif
 
@@ -33,19 +46,6 @@ void HOT esp_log_vprintf_(int level, const char *tag, int line, const char *form
 #endif
 }
 
-#ifdef USE_STORE_LOG_STR_IN_FLASH
-void HOT esp_log_vprintf_(int level, const char *tag, int line, const __FlashStringHelper *format,
-                          va_list args) {  // NOLINT
-#ifdef USE_LOGGER
-  auto *log = logger::global_logger;
-  if (log == nullptr)
-    return;
-
-  log->log_vprintf_(static_cast<uint8_t>(level), tag, line, format, args);
-#endif
-}
-#endif
-
 #ifdef USE_ESP32
 int HOT esp_idf_log_vprintf_(const char *format, va_list args) {  // NOLINT
 #ifdef USE_LOGGER

esphome/core/log.h

@@ -60,9 +60,6 @@ void esp_log_printf_(int level, const char *tag, int line, const char *format, .
 void esp_log_printf_(int level, const char *tag, int line, const __FlashStringHelper *format, ...);
 #endif
 void esp_log_vprintf_(int level, const char *tag, int line, const char *format, va_list args);  // NOLINT
-#ifdef USE_STORE_LOG_STR_IN_FLASH
-void esp_log_vprintf_(int level, const char *tag, int line, const __FlashStringHelper *format, va_list args);
-#endif
 #if defined(USE_ESP32)
 int esp_idf_log_vprintf_(const char *format, va_list args);  // NOLINT
 #endif

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

@@ -0,0 +1,4 @@
+ble_nus:
+  type: uart
+  tx_buffer_size: 160
+  rx_buffer_size: 160