Optimize logger callback API by including message length parameter (#9368)

Co-authored-by: Copilot <175728472+Copilot@users.noreply.github.com>

esphome/components/api/api_connection.cpp

@@ -1392,12 +1392,11 @@ void APIConnection::update_command(const UpdateCommandRequest &msg) {
 }
 #endif
 
-bool APIConnection::try_send_log_message(int level, const char *tag, const char *line) {
+bool APIConnection::try_send_log_message(int level, const char *tag, const char *line, size_t message_len) {
   if (this->flags_.log_subscription < level)
     return false;
 
   // Pre-calculate message size to avoid reallocations
-  const size_t line_length = strlen(line);
   uint32_t msg_size = 0;
 
   // Add size for level field (field ID 1, varint type)
@@ -1406,14 +1405,14 @@ bool APIConnection::try_send_log_message(int level, const char *tag, const char
 
   // Add size for string field (field ID 3, string type)
   // 1 byte for field tag + size of length varint + string length
-  msg_size += 1 + api::ProtoSize::varint(static_cast<uint32_t>(line_length)) + line_length;
+  msg_size += 1 + api::ProtoSize::varint(static_cast<uint32_t>(message_len)) + message_len;
 
   // Create a pre-sized buffer
   auto buffer = this->create_buffer(msg_size);
 
   // Encode the message (SubscribeLogsResponse)
   buffer.encode_uint32(1, static_cast<uint32_t>(level));  // LogLevel level = 1
-  buffer.encode_string(3, line, line_length);             // string message = 3
+  buffer.encode_string(3, line, message_len);             // string message = 3
 
   // SubscribeLogsResponse - 29
   return this->send_buffer(buffer, SubscribeLogsResponse::MESSAGE_TYPE);

esphome/components/api/api_connection.h

@@ -107,7 +107,7 @@ class APIConnection : public APIServerConnection {
   bool send_media_player_state(media_player::MediaPlayer *media_player);
   void media_player_command(const MediaPlayerCommandRequest &msg) override;
 #endif
-  bool try_send_log_message(int level, const char *tag, const char *line);
+  bool try_send_log_message(int level, const char *tag, const char *line, size_t message_len);
   void send_homeassistant_service_call(const HomeassistantServiceResponse &call) {
     if (!this->flags_.service_call_subscription)
       return;

esphome/components/api/api_server.cpp

@@ -104,18 +104,19 @@ void APIServer::setup() {
 
 #ifdef USE_LOGGER
   if (logger::global_logger != nullptr) {
-    logger::global_logger->add_on_log_callback([this](int level, const char *tag, const char *message) {
-      if (this->shutting_down_) {
-        // Don't try to send logs during shutdown
-        // as it could result in a recursion and
-        // we would be filling a buffer we are trying to clear
-        return;
-      }
-      for (auto &c : this->clients_) {
-        if (!c->flags_.remove)
-          c->try_send_log_message(level, tag, message);
-      }
-    });
+    logger::global_logger->add_on_log_callback(
+        [this](int level, const char *tag, const char *message, size_t message_len) {
+          if (this->shutting_down_) {
+            // Don't try to send logs during shutdown
+            // as it could result in a recursion and
+            // we would be filling a buffer we are trying to clear
+            return;
+          }
+          for (auto &c : this->clients_) {
+            if (!c->flags_.remove)
+              c->try_send_log_message(level, tag, message, message_len);
+          }
+        });
   }
 #endif
 

esphome/components/logger/logger.cpp

@@ -90,6 +90,25 @@ void HOT Logger::log_vprintf_(uint8_t level, const char *tag, int line, const ch
 #ifdef USE_STORE_LOG_STR_IN_FLASH
 // Implementation for ESP8266 with flash string support.
 // Note: USE_STORE_LOG_STR_IN_FLASH is only defined for ESP8266.
+//
+// This function handles format strings stored in flash memory (PROGMEM) to save RAM.
+// The buffer is used in a special way to avoid allocating extra memory:
+//
+// Memory layout during execution:
+// Step 1: Copy format string from flash to buffer
+//         tx_buffer_: [format_string][null][.....................]
+//         tx_buffer_at_: ------------------^
+//         msg_start: saved here -----------^
+//
+// Step 2: format_log_to_buffer_with_terminator_ reads format string from beginning
+//         and writes formatted output starting at msg_start position
+//         tx_buffer_: [format_string][null][formatted_message][null]
+//         tx_buffer_at_: -------------------------------------^
+//
+// Step 3: Output the formatted message (starting at msg_start)
+//         write_msg_ and callbacks receive: this->tx_buffer_ + msg_start
+//         which points to: [formatted_message][null]
+//
 void Logger::log_vprintf_(uint8_t level, const char *tag, int line, const __FlashStringHelper *format,
                           va_list args) {  // NOLINT
   if (level > this->level_for(tag) || global_recursion_guard_)
@@ -121,7 +140,9 @@ void Logger::log_vprintf_(uint8_t level, const char *tag, int line, const __Flas
   if (this->baud_rate_ > 0) {
     this->write_msg_(this->tx_buffer_ + msg_start);
   }
-  this->log_callback_.call(level, tag, this->tx_buffer_ + msg_start);
+  size_t msg_length =
+      this->tx_buffer_at_ - msg_start;  // Don't subtract 1 - tx_buffer_at_ is already at the null terminator position
+  this->log_callback_.call(level, tag, this->tx_buffer_ + msg_start, msg_length);
 
   global_recursion_guard_ = false;
 }
@@ -185,7 +206,8 @@ void Logger::loop() {
                                   this->tx_buffer_size_);
       this->write_footer_to_buffer_(this->tx_buffer_, &this->tx_buffer_at_, this->tx_buffer_size_);
       this->tx_buffer_[this->tx_buffer_at_] = '\0';
-      this->log_callback_.call(message->level, message->tag, this->tx_buffer_);
+      size_t msg_len = this->tx_buffer_at_;  // We already know the length from tx_buffer_at_
+      this->log_callback_.call(message->level, message->tag, this->tx_buffer_, msg_len);
       // At this point all the data we need from message has been transferred to the tx_buffer
       // so we can release the message to allow other tasks to use it as soon as possible.
       this->log_buffer_->release_message_main_loop(received_token);
@@ -214,7 +236,7 @@ void Logger::set_log_level(const std::string &tag, uint8_t log_level) { this->lo
 UARTSelection Logger::get_uart() const { return this->uart_; }
 #endif
 
-void Logger::add_on_log_callback(std::function<void(uint8_t, const char *, const char *)> &&callback) {
+void Logger::add_on_log_callback(std::function<void(uint8_t, const char *, const char *, size_t)> &&callback) {
   this->log_callback_.add(std::move(callback));
 }
 float Logger::get_setup_priority() const { return setup_priority::BUS + 500.0f; }

esphome/components/logger/logger.h

@@ -143,7 +143,7 @@ class Logger : public Component {
   inline uint8_t level_for(const char *tag);
 
   /// Register a callback that will be called for every log message sent
-  void add_on_log_callback(std::function<void(uint8_t, const char *, const char *)> &&callback);
+  void add_on_log_callback(std::function<void(uint8_t, const char *, const char *, size_t)> &&callback);
 
   // add a listener for log level changes
   void add_listener(std::function<void(uint8_t)> &&callback) { this->level_callback_.add(std::move(callback)); }
@@ -192,7 +192,7 @@ class Logger : public Component {
     if (this->baud_rate_ > 0) {
       this->write_msg_(this->tx_buffer_);  // If logging is enabled, write to console
     }
-    this->log_callback_.call(level, tag, this->tx_buffer_);
+    this->log_callback_.call(level, tag, this->tx_buffer_, this->tx_buffer_at_);
   }
 
   // Write the body of the log message to the buffer
@@ -246,7 +246,7 @@ class Logger : public Component {
 
   // Large objects (internally aligned)
   std::map<std::string, uint8_t> log_levels_{};
-  CallbackManager<void(uint8_t, const char *, const char *)> log_callback_{};
+  CallbackManager<void(uint8_t, const char *, const char *, size_t)> log_callback_{};
   CallbackManager<void(uint8_t)> level_callback_{};
 #ifdef USE_ESPHOME_TASK_LOG_BUFFER
   std::unique_ptr<logger::TaskLogBuffer> log_buffer_;  // Will be initialized with init_log_buffer
@@ -385,7 +385,7 @@ class LoggerMessageTrigger : public Trigger<uint8_t, const char *, const char *>
  public:
   explicit LoggerMessageTrigger(Logger *parent, uint8_t level) {
     this->level_ = level;
-    parent->add_on_log_callback([this](uint8_t level, const char *tag, const char *message) {
+    parent->add_on_log_callback([this](uint8_t level, const char *tag, const char *message, size_t message_len) {
       if (level <= this->level_) {
         this->trigger(level, tag, message);
       }

esphome/components/mqtt/mqtt_client.cpp

@@ -57,14 +57,15 @@ void MQTTClientComponent::setup() {
   });
 #ifdef USE_LOGGER
   if (this->is_log_message_enabled() && logger::global_logger != nullptr) {
-    logger::global_logger->add_on_log_callback([this](int level, const char *tag, const char *message) {
-      if (level <= this->log_level_ && this->is_connected()) {
-        this->publish({.topic = this->log_message_.topic,
-                       .payload = message,
-                       .qos = this->log_message_.qos,
-                       .retain = this->log_message_.retain});
-      }
-    });
+    logger::global_logger->add_on_log_callback(
+        [this](int level, const char *tag, const char *message, size_t message_len) {
+          if (level <= this->log_level_ && this->is_connected()) {
+            this->publish({.topic = this->log_message_.topic,
+                           .payload = std::string(message, message_len),
+                           .qos = this->log_message_.qos,
+                           .retain = this->log_message_.retain});
+          }
+        });
   }
 #endif
 

esphome/components/syslog/esphome_syslog.cpp

@@ -21,10 +21,12 @@ constexpr int LOG_LEVEL_TO_SYSLOG_SEVERITY[] = {
 
 void Syslog::setup() {
   logger::global_logger->add_on_log_callback(
-      [this](int level, const char *tag, const char *message) { this->log_(level, tag, message); });
+      [this](int level, const char *tag, const char *message, size_t message_len) {
+        this->log_(level, tag, message, message_len);
+      });
 }
 
-void Syslog::log_(const int level, const char *tag, const char *message) const {
+void Syslog::log_(const int level, const char *tag, const char *message, size_t message_len) const {
   if (level > this->log_level_)
     return;
   // Syslog PRI calculation: facility * 8 + severity
@@ -34,7 +36,7 @@ void Syslog::log_(const int level, const char *tag, const char *message) const {
   }
   int pri = this->facility_ * 8 + severity;
   auto timestamp = this->time_->now().strftime("%b %d %H:%M:%S");
-  unsigned len = strlen(message);
+  size_t len = message_len;
   // remove color formatting
   if (this->strip_ && message[0] == 0x1B && len > 11) {
     message += 7;

esphome/components/syslog/esphome_syslog.h

@@ -17,7 +17,7 @@ class Syslog : public Component, public Parented<udp::UDPComponent> {
 
  protected:
   int log_level_;
-  void log_(int level, const char *tag, const char *message) const;
+  void log_(int level, const char *tag, const char *message, size_t message_len) const;
   time::RealTimeClock *time_;
   bool strip_{true};
   int facility_{16};

esphome/components/web_server/web_server.cpp

@@ -287,7 +287,8 @@ void WebServer::setup() {
   if (logger::global_logger != nullptr && this->expose_log_) {
     logger::global_logger->add_on_log_callback(
         // logs are not deferred, the memory overhead would be too large
-        [this](int level, const char *tag, const char *message) {
+        [this](int level, const char *tag, const char *message, size_t message_len) {
+          (void) message_len;
           this->events_.try_send_nodefer(message, "log", millis());
         });
   }