diff --git a/esphome/components/api/api_connection.cpp b/esphome/components/api/api_connection.cpp index fdcce6088c..65588ad4d8 100644 --- a/esphome/components/api/api_connection.cpp +++ b/esphome/components/api/api_connection.cpp @@ -94,6 +94,19 @@ APIConnection::~APIConnection() { #endif } +#ifdef HAS_PROTO_MESSAGE_DUMP +void APIConnection::log_batch_item_(const DeferredBatch::BatchItem &item) { + // Set log-only mode + this->log_only_mode_ = true; + + // Call the creator - it will create the message and log it via encode_message_to_buffer + item.creator(item.entity, this, std::numeric_limits::max(), true, item.message_type); + + // Clear log-only mode + this->log_only_mode_ = false; +} +#endif + void APIConnection::loop() { if (this->next_close_) { // requested a disconnect @@ -249,6 +262,14 @@ void APIConnection::on_disconnect_response(const DisconnectResponse &value) { // including header and footer overhead. Returns 0 if the message doesn't fit. uint16_t APIConnection::encode_message_to_buffer(ProtoMessage &msg, uint16_t message_type, APIConnection *conn, uint32_t remaining_size, bool is_single) { +#ifdef HAS_PROTO_MESSAGE_DUMP + // If in log-only mode, just log and return + if (conn->log_only_mode_) { + conn->log_send_message_(msg.message_name(), msg.dump()); + return 1; // Return non-zero to indicate "success" for logging + } +#endif + // Calculate size uint32_t calculated_size = 0; msg.calculate_size(calculated_size); @@ -276,11 +297,6 @@ uint16_t APIConnection::encode_message_to_buffer(ProtoMessage &msg, uint16_t mes // Encode directly into buffer msg.encode(buffer); -#ifdef HAS_PROTO_MESSAGE_DUMP - // Log the message for VV debugging - conn->log_send_message_(msg.message_name(), msg.dump()); -#endif - // Calculate actual encoded size (not including header that was already added) size_t actual_payload_size = shared_buf.size() - size_before_encode; @@ -1891,6 +1907,15 @@ void APIConnection::process_batch_() { } } +#ifdef HAS_PROTO_MESSAGE_DUMP + // Log messages after send attempt for VV debugging + // It's safe to use the buffer for logging at this point regardless of send result + for (size_t i = 0; i < items_processed; i++) { + const auto &item = this->deferred_batch_.items[i]; + this->log_batch_item_(item); + } +#endif + // Handle remaining items more efficiently if (items_processed < this->deferred_batch_.items.size()) { // Remove processed items from the beginning diff --git a/esphome/components/api/api_connection.h b/esphome/components/api/api_connection.h index e872711e95..07e87ab39f 100644 --- a/esphome/components/api/api_connection.h +++ b/esphome/components/api/api_connection.h @@ -470,6 +470,10 @@ class APIConnection : public APIServerConnection { bool sent_ping_{false}; bool service_call_subscription_{false}; bool next_close_ = false; +#ifdef HAS_PROTO_MESSAGE_DUMP + // When true, encode_message_to_buffer will only log, not encode + bool log_only_mode_{false}; +#endif uint8_t ping_retries_{0}; // 8 bytes used, no padding needed @@ -627,6 +631,10 @@ class APIConnection : public APIServerConnection { // State for batch buffer allocation bool batch_first_message_{false}; +#ifdef HAS_PROTO_MESSAGE_DUMP + void log_batch_item_(const DeferredBatch::BatchItem &item); +#endif + // Helper function to schedule a deferred message with known message type bool schedule_message_(EntityBase *entity, MessageCreator creator, uint16_t message_type) { this->deferred_batch_.add_item(entity, std::move(creator), message_type); diff --git a/esphome/core/datatypes.h b/esphome/core/datatypes.h index 5356be6b52..4929518387 100644 --- a/esphome/core/datatypes.h +++ b/esphome/core/datatypes.h @@ -11,7 +11,7 @@ namespace internal { /// Wrapper class for memory using big endian data layout, transparently converting it to native order. template class BigEndianLayout { public: - constexpr14 operator T() { return convert_big_endian(val_); } + constexpr operator T() { return convert_big_endian(val_); } private: T val_; @@ -20,7 +20,7 @@ template class BigEndianLayout { /// Wrapper class for memory using big endian data layout, transparently converting it to native order. template class LittleEndianLayout { public: - constexpr14 operator T() { return convert_little_endian(val_); } + constexpr operator T() { return convert_little_endian(val_); } private: T val_; diff --git a/esphome/core/helpers.cpp b/esphome/core/helpers.cpp index 79dbb314c8..fc91d83972 100644 --- a/esphome/core/helpers.cpp +++ b/esphome/core/helpers.cpp @@ -76,23 +76,8 @@ static const uint16_t CRC16_1021_BE_LUT_H[] = {0x0000, 0x1231, 0x2462, 0x3653, 0 0x9188, 0x83b9, 0xb5ea, 0xa7db, 0xd94c, 0xcb7d, 0xfd2e, 0xef1f}; #endif -// STL backports - -#if _GLIBCXX_RELEASE < 8 -std::string to_string(int value) { return str_snprintf("%d", 32, value); } // NOLINT -std::string to_string(long value) { return str_snprintf("%ld", 32, value); } // NOLINT -std::string to_string(long long value) { return str_snprintf("%lld", 32, value); } // NOLINT -std::string to_string(unsigned value) { return str_snprintf("%u", 32, value); } // NOLINT -std::string to_string(unsigned long value) { return str_snprintf("%lu", 32, value); } // NOLINT -std::string to_string(unsigned long long value) { return str_snprintf("%llu", 32, value); } // NOLINT -std::string to_string(float value) { return str_snprintf("%f", 32, value); } -std::string to_string(double value) { return str_snprintf("%f", 32, value); } -std::string to_string(long double value) { return str_snprintf("%Lf", 32, value); } -#endif - // Mathematics -float lerp(float completion, float start, float end) { return start + (end - start) * completion; } uint8_t crc8(const uint8_t *data, uint8_t len) { uint8_t crc = 0; diff --git a/esphome/core/helpers.h b/esphome/core/helpers.h index 8bd5b813c7..7d5366f323 100644 --- a/esphome/core/helpers.h +++ b/esphome/core/helpers.h @@ -37,89 +37,18 @@ #define ESPHOME_ALWAYS_INLINE __attribute__((always_inline)) #define PACKED __attribute__((packed)) -// Various functions can be constexpr in C++14, but not in C++11 (because their body isn't just a return statement). -// Define a substitute constexpr keyword for those functions, until we can drop C++11 support. -#if __cplusplus >= 201402L -#define constexpr14 constexpr -#else -#define constexpr14 inline // constexpr implies inline -#endif - namespace esphome { /// @name STL backports ///@{ -// Backports for various STL features we like to use. Pull in the STL implementation wherever available, to avoid -// ambiguity and to provide a uniform API. - -// std::to_string() from C++11, available from libstdc++/g++ 8 -// See https://github.com/espressif/esp-idf/issues/1445 -#if _GLIBCXX_RELEASE >= 8 +// Keep "using" even after the removal of our backports, to avoid breaking existing code. using std::to_string; -#else -std::string to_string(int value); // NOLINT -std::string to_string(long value); // NOLINT -std::string to_string(long long value); // NOLINT -std::string to_string(unsigned value); // NOLINT -std::string to_string(unsigned long value); // NOLINT -std::string to_string(unsigned long long value); // NOLINT -std::string to_string(float value); -std::string to_string(double value); -std::string to_string(long double value); -#endif - -// std::is_trivially_copyable from C++11, implemented in libstdc++/g++ 5.1 (but minor releases can't be detected) -#if _GLIBCXX_RELEASE >= 6 using std::is_trivially_copyable; -#else -// Implementing this is impossible without compiler intrinsics, so don't bother. Invalid usage will be detected on -// other variants that use a newer compiler anyway. -// NOLINTNEXTLINE(readability-identifier-naming) -template struct is_trivially_copyable : public std::integral_constant {}; -#endif - -// std::make_unique() from C++14 -#if __cpp_lib_make_unique >= 201304 using std::make_unique; -#else -template std::unique_ptr make_unique(Args &&...args) { - return std::unique_ptr(new T(std::forward(args)...)); -} -#endif - -// std::enable_if_t from C++14 -#if __cplusplus >= 201402L using std::enable_if_t; -#else -template using enable_if_t = typename std::enable_if::type; -#endif - -// std::clamp from C++17 -#if __cpp_lib_clamp >= 201603 using std::clamp; -#else -template constexpr const T &clamp(const T &v, const T &lo, const T &hi, Compare comp) { - return comp(v, lo) ? lo : comp(hi, v) ? hi : v; -} -template constexpr const T &clamp(const T &v, const T &lo, const T &hi) { - return clamp(v, lo, hi, std::less{}); -} -#endif - -// std::is_invocable from C++17 -#if __cpp_lib_is_invocable >= 201703 using std::is_invocable; -#else -// https://stackoverflow.com/a/37161919/8924614 -template struct is_invocable { // NOLINT(readability-identifier-naming) - template static auto test(U *p) -> decltype((*p)(std::declval()...), void(), std::true_type()); - template static auto test(...) -> decltype(std::false_type()); - static constexpr auto value = decltype(test(nullptr))::value; // NOLINT -}; -#endif - -// std::bit_cast from C++20 #if __cpp_lib_bit_cast >= 201806 using std::bit_cast; #else @@ -134,31 +63,29 @@ To bit_cast(const From &src) { return dst; } #endif +using std::lerp; // std::byteswap from C++23 -template constexpr14 T byteswap(T n) { +template constexpr T byteswap(T n) { T m; for (size_t i = 0; i < sizeof(T); i++) reinterpret_cast(&m)[i] = reinterpret_cast(&n)[sizeof(T) - 1 - i]; return m; } -template<> constexpr14 uint8_t byteswap(uint8_t n) { return n; } -template<> constexpr14 uint16_t byteswap(uint16_t n) { return __builtin_bswap16(n); } -template<> constexpr14 uint32_t byteswap(uint32_t n) { return __builtin_bswap32(n); } -template<> constexpr14 uint64_t byteswap(uint64_t n) { return __builtin_bswap64(n); } -template<> constexpr14 int8_t byteswap(int8_t n) { return n; } -template<> constexpr14 int16_t byteswap(int16_t n) { return __builtin_bswap16(n); } -template<> constexpr14 int32_t byteswap(int32_t n) { return __builtin_bswap32(n); } -template<> constexpr14 int64_t byteswap(int64_t n) { return __builtin_bswap64(n); } +template<> constexpr uint8_t byteswap(uint8_t n) { return n; } +template<> constexpr uint16_t byteswap(uint16_t n) { return __builtin_bswap16(n); } +template<> constexpr uint32_t byteswap(uint32_t n) { return __builtin_bswap32(n); } +template<> constexpr uint64_t byteswap(uint64_t n) { return __builtin_bswap64(n); } +template<> constexpr int8_t byteswap(int8_t n) { return n; } +template<> constexpr int16_t byteswap(int16_t n) { return __builtin_bswap16(n); } +template<> constexpr int32_t byteswap(int32_t n) { return __builtin_bswap32(n); } +template<> constexpr int64_t byteswap(int64_t n) { return __builtin_bswap64(n); } ///@} /// @name Mathematics ///@{ -/// Linearly interpolate between \p start and \p end by \p completion (between 0 and 1). -float lerp(float completion, float start, float end); - /// Remap \p value from the range (\p min, \p max) to (\p min_out, \p max_out). template T remap(U value, U min, U max, T min_out, T max_out) { return (value - min) * (max_out - min_out) / (max - min) + min_out; @@ -203,8 +130,7 @@ constexpr uint32_t encode_uint32(uint8_t byte1, uint8_t byte2, uint8_t byte3, ui } /// Encode a value from its constituent bytes (from most to least significant) in an array with length sizeof(T). -template::value, int> = 0> -constexpr14 T encode_value(const uint8_t *bytes) { +template::value, int> = 0> constexpr T encode_value(const uint8_t *bytes) { T val = 0; for (size_t i = 0; i < sizeof(T); i++) { val <<= 8; @@ -214,12 +140,12 @@ constexpr14 T encode_value(const uint8_t *bytes) { } /// Encode a value from its constituent bytes (from most to least significant) in an std::array with length sizeof(T). template::value, int> = 0> -constexpr14 T encode_value(const std::array bytes) { +constexpr T encode_value(const std::array bytes) { return encode_value(bytes.data()); } /// Decode a value into its constituent bytes (from most to least significant). template::value, int> = 0> -constexpr14 std::array decode_value(T val) { +constexpr std::array decode_value(T val) { std::array ret{}; for (size_t i = sizeof(T); i > 0; i--) { ret[i - 1] = val & 0xFF; @@ -246,7 +172,7 @@ inline uint32_t reverse_bits(uint32_t x) { } /// Convert a value between host byte order and big endian (most significant byte first) order. -template constexpr14 T convert_big_endian(T val) { +template constexpr T convert_big_endian(T val) { #if __BYTE_ORDER__ == __ORDER_LITTLE_ENDIAN__ return byteswap(val); #else @@ -255,7 +181,7 @@ template constexpr14 T convert_big_endian(T val) { } /// Convert a value between host byte order and little endian (least significant byte first) order. -template constexpr14 T convert_little_endian(T val) { +template constexpr T convert_little_endian(T val) { #if __BYTE_ORDER__ == __ORDER_LITTLE_ENDIAN__ return val; #else @@ -276,9 +202,6 @@ bool str_startswith(const std::string &str, const std::string &start); /// Check whether a string ends with a value. bool str_endswith(const std::string &str, const std::string &end); -/// Convert the value to a string (added as extra overload so that to_string() can be used on all stringifiable types). -inline std::string to_string(const std::string &val) { return val; } - /// Truncate a string to a specific length. std::string str_truncate(const std::string &str, size_t length); diff --git a/tests/integration/fixtures/api_vv_logging.yaml b/tests/integration/fixtures/api_vv_logging.yaml new file mode 100644 index 0000000000..df1edc796a --- /dev/null +++ b/tests/integration/fixtures/api_vv_logging.yaml @@ -0,0 +1,89 @@ +esphome: + name: vv-logging-test + +host: + +api: + +logger: + level: VERY_VERBOSE + # Enable VV logging for API components where the issue occurs + logs: + api.connection: VERY_VERBOSE + api.service: VERY_VERBOSE + api.proto: VERY_VERBOSE + sensor: VERY_VERBOSE + +# Create many sensors that update frequently to generate API traffic +# This will cause many messages to be batched and sent, triggering the +# code path where VV logging could cause buffer corruption +sensor: + - platform: template + name: "Test Sensor 1" + lambda: 'return millis() / 1000.0;' + update_interval: 50ms + unit_of_measurement: "s" + + - platform: template + name: "Test Sensor 2" + lambda: 'return (millis() / 1000.0) + 10;' + update_interval: 50ms + unit_of_measurement: "s" + + - platform: template + name: "Test Sensor 3" + lambda: 'return (millis() / 1000.0) + 20;' + update_interval: 50ms + unit_of_measurement: "s" + + - platform: template + name: "Test Sensor 4" + lambda: 'return (millis() / 1000.0) + 30;' + update_interval: 50ms + unit_of_measurement: "s" + + - platform: template + name: "Test Sensor 5" + lambda: 'return (millis() / 1000.0) + 40;' + update_interval: 50ms + unit_of_measurement: "s" + + - platform: template + name: "Test Sensor 6" + lambda: 'return (millis() / 1000.0) + 50;' + update_interval: 50ms + unit_of_measurement: "s" + + - platform: template + name: "Test Sensor 7" + lambda: 'return (millis() / 1000.0) + 60;' + update_interval: 50ms + unit_of_measurement: "s" + + - platform: template + name: "Test Sensor 8" + lambda: 'return (millis() / 1000.0) + 70;' + update_interval: 50ms + unit_of_measurement: "s" + + - platform: template + name: "Test Sensor 9" + lambda: 'return (millis() / 1000.0) + 80;' + update_interval: 50ms + unit_of_measurement: "s" + + - platform: template + name: "Test Sensor 10" + lambda: 'return (millis() / 1000.0) + 90;' + update_interval: 50ms + unit_of_measurement: "s" + +# Add some binary sensors too for variety +binary_sensor: + - platform: template + name: "Test Binary 1" + lambda: 'return (millis() / 1000) % 2 == 0;' + + - platform: template + name: "Test Binary 2" + lambda: 'return (millis() / 1000) % 3 == 0;' diff --git a/tests/integration/fixtures/scheduler_string_test.yaml b/tests/integration/fixtures/scheduler_string_test.yaml index ed10441ccc..1188577e15 100644 --- a/tests/integration/fixtures/scheduler_string_test.yaml +++ b/tests/integration/fixtures/scheduler_string_test.yaml @@ -67,20 +67,28 @@ script: ESP_LOGI("test", "Empty string timeout fired"); }); + // Test 5: Cancel timeout with const char* literal + App.scheduler.set_timeout(component1, "cancel_static_timeout", 5000, []() { + ESP_LOGI("test", "This static timeout should be cancelled"); + }); + // Cancel using const char* directly + App.scheduler.cancel_timeout(component1, "cancel_static_timeout"); + ESP_LOGI("test", "Cancelled static timeout using const char*"); + - id: test_dynamic_strings then: - logger.log: "Testing dynamic string timeouts and intervals" - lambda: |- auto *component2 = id(test_sensor2); - // Test 5: Dynamic string with set_timeout (std::string) + // Test 6: Dynamic string with set_timeout (std::string) std::string dynamic_name = "dynamic_timeout_" + std::to_string(id(dynamic_counter)++); App.scheduler.set_timeout(component2, dynamic_name, 100, []() { ESP_LOGI("test", "Dynamic timeout fired"); id(timeout_counter) += 1; }); - // Test 6: Dynamic string with set_interval + // Test 7: Dynamic string with set_interval std::string interval_name = "dynamic_interval_" + std::to_string(id(dynamic_counter)++); App.scheduler.set_interval(component2, interval_name, 250, [interval_name]() { ESP_LOGI("test", "Dynamic interval fired: %s", interval_name.c_str()); @@ -91,7 +99,7 @@ script: } }); - // Test 7: Cancel with different string object but same content + // Test 8: Cancel with different string object but same content std::string cancel_name = "cancel_test"; App.scheduler.set_timeout(component2, cancel_name, 2000, []() { ESP_LOGI("test", "This should be cancelled"); diff --git a/tests/integration/test_api_vv_logging.py b/tests/integration/test_api_vv_logging.py new file mode 100644 index 0000000000..19aab2001c --- /dev/null +++ b/tests/integration/test_api_vv_logging.py @@ -0,0 +1,83 @@ +"""Integration test for API with VERY_VERBOSE logging to verify no buffer corruption.""" + +from __future__ import annotations + +import asyncio +from typing import Any + +from aioesphomeapi import LogLevel +import pytest + +from .types import APIClientConnectedFactory, RunCompiledFunction + + +@pytest.mark.asyncio +async def test_api_vv_logging( + yaml_config: str, + run_compiled: RunCompiledFunction, + api_client_connected: APIClientConnectedFactory, +) -> None: + """Test that VERY_VERBOSE logging doesn't cause buffer corruption with API messages.""" + + # Track that we're receiving VV log messages and sensor updates + vv_logs_received = 0 + sensor_updates_received = 0 + errors_detected = [] + + def on_log(msg: Any) -> None: + """Capture log messages.""" + nonlocal vv_logs_received + # msg is a SubscribeLogsResponse object with 'message' attribute + # The message field is always bytes + message_text = msg.message.decode("utf-8", errors="replace") + + # Only count VV logs specifically + if "[VV]" in message_text: + vv_logs_received += 1 + + # Check for assertion or error messages + if "assert" in message_text.lower() or "error" in message_text.lower(): + errors_detected.append(message_text) + + # Write, compile and run the ESPHome device + async with run_compiled(yaml_config), api_client_connected() as client: + # Subscribe to VERY_VERBOSE logs - this enables the code path that could cause corruption + client.subscribe_logs(on_log, log_level=LogLevel.LOG_LEVEL_VERY_VERBOSE) + + # Wait for device to be ready + device_info = await client.device_info() + assert device_info is not None + assert device_info.name == "vv-logging-test" + + # Subscribe to sensor states + states = {} + + def on_state(state): + nonlocal sensor_updates_received + sensor_updates_received += 1 + states[state.key] = state + + client.subscribe_states(on_state) + + # List entities to find our test sensors + entity_info, _ = await client.list_entities_services() + + # Count sensors + sensor_count = sum(1 for e in entity_info if hasattr(e, "unit_of_measurement")) + assert sensor_count >= 10, f"Expected at least 10 sensors, got {sensor_count}" + + # Wait for sensor updates to flow with VV logging active + # The sensors update every 50ms, so we should get many updates + await asyncio.sleep(0.25) + + # Verify we received both VV logs and sensor updates + assert vv_logs_received > 0, "Expected to receive VERY_VERBOSE log messages" + assert sensor_updates_received > 10, ( + f"Expected many sensor updates, got {sensor_updates_received}" + ) + + # Check for any errors + if errors_detected: + pytest.fail(f"Errors detected during test: {errors_detected}") + + # The test passes if we didn't hit any assertions or buffer corruption diff --git a/tests/integration/test_scheduler_string_test.py b/tests/integration/test_scheduler_string_test.py index 670af6e22d..b5ca07f9db 100644 --- a/tests/integration/test_scheduler_string_test.py +++ b/tests/integration/test_scheduler_string_test.py @@ -25,6 +25,7 @@ async def test_scheduler_string_test( static_interval_fired = asyncio.Event() static_interval_cancelled = asyncio.Event() empty_string_timeout_fired = asyncio.Event() + static_timeout_cancelled = asyncio.Event() dynamic_timeout_fired = asyncio.Event() dynamic_interval_fired = asyncio.Event() cancel_test_done = asyncio.Event() @@ -67,6 +68,10 @@ async def test_scheduler_string_test( elif "Empty string timeout fired" in clean_line: empty_string_timeout_fired.set() + # Check for static timeout cancellation + elif "Cancelled static timeout using const char*" in clean_line: + static_timeout_cancelled.set() + # Check for dynamic string tests elif "Dynamic timeout fired" in clean_line: dynamic_timeout_fired.set() @@ -123,6 +128,11 @@ async def test_scheduler_string_test( f"Expected static interval to run at least 3 times, got {static_interval_count + 1}" ) + # Verify static timeout was cancelled + assert static_timeout_cancelled.is_set(), ( + "Static timeout should have been cancelled" + ) + # Wait for dynamic string tests try: await asyncio.wait_for(dynamic_timeout_fired.wait(), timeout=1.0)