Merge branch 'dev' into store-yaml-firmware

This commit is contained in:
J. Nick Koston
2026-07-03 19:04:12 -05:00
committed by GitHub
1326 changed files with 27006 additions and 16857 deletions
@@ -8,14 +8,23 @@ static const char *const TAG = "bulk_cleanup";
void SchedulerBulkCleanupComponent::setup() { ESP_LOGI(TAG, "Scheduler bulk cleanup test component loaded"); }
// Static name tables keep the const char* pointers valid for the lifetime of the scheduled tasks.
static const char *const BULK_TIMEOUT_NAMES[25] = {
"bulk_timeout_0", "bulk_timeout_1", "bulk_timeout_2", "bulk_timeout_3", "bulk_timeout_4",
"bulk_timeout_5", "bulk_timeout_6", "bulk_timeout_7", "bulk_timeout_8", "bulk_timeout_9",
"bulk_timeout_10", "bulk_timeout_11", "bulk_timeout_12", "bulk_timeout_13", "bulk_timeout_14",
"bulk_timeout_15", "bulk_timeout_16", "bulk_timeout_17", "bulk_timeout_18", "bulk_timeout_19",
"bulk_timeout_20", "bulk_timeout_21", "bulk_timeout_22", "bulk_timeout_23", "bulk_timeout_24"};
static const char *const POST_CLEANUP_NAMES[5] = {"post_cleanup_0", "post_cleanup_1", "post_cleanup_2",
"post_cleanup_3", "post_cleanup_4"};
void SchedulerBulkCleanupComponent::trigger_bulk_cleanup() {
ESP_LOGI(TAG, "Starting bulk cleanup test...");
// Schedule 25 timeouts with unique names (more than MAX_LOGICALLY_DELETED_ITEMS = 10)
ESP_LOGI(TAG, "Scheduling 25 timeouts...");
for (int i = 0; i < 25; i++) {
std::string name = "bulk_timeout_" + std::to_string(i);
App.scheduler.set_timeout(this, name, 2500, [i]() {
App.scheduler.set_timeout(this, BULK_TIMEOUT_NAMES[i], 2500, [i]() {
// These should never execute as we'll cancel them
ESP_LOGW(TAG, "Timeout %d executed - this should not happen!", i);
});
@@ -24,8 +33,7 @@ void SchedulerBulkCleanupComponent::trigger_bulk_cleanup() {
// Cancel all of them to mark for removal
ESP_LOGI(TAG, "Cancelling all 25 timeouts to trigger bulk cleanup...");
int cancelled_count = 0;
for (int i = 0; i < 25; i++) {
std::string name = "bulk_timeout_" + std::to_string(i);
for (const char *name : BULK_TIMEOUT_NAMES) {
if (App.scheduler.cancel_timeout(this, name)) {
cancelled_count++;
}
@@ -56,8 +64,7 @@ void SchedulerBulkCleanupComponent::trigger_bulk_cleanup() {
// Also schedule some normal timeouts to ensure scheduler keeps working after cleanup
static int post_cleanup_count = 0;
for (int i = 0; i < 5; i++) {
std::string name = "post_cleanup_" + std::to_string(i);
App.scheduler.set_timeout(this, name, 50 + i * 25, [i]() {
App.scheduler.set_timeout(this, POST_CLEANUP_NAMES[i], 50 + i * 25, [i]() {
ESP_LOGI(TAG, "Post-cleanup timeout %d executed correctly", i);
post_cleanup_count++;
if (post_cleanup_count >= 5) {
@@ -4,12 +4,18 @@
#include <vector>
#include <chrono>
#include <random>
#include <sstream>
namespace esphome::scheduler_rapid_cancellation_component {
static const char *const TAG = "scheduler_rapid_cancellation";
// Static name table keeps the const char* pointers valid for the lifetime of the scheduled tasks.
// Threads race over this fixed set of names; STATIC_STRING names match by content, so scheduling
// the same name replaces (implicitly cancels) the previous timeout, exactly as before.
static const char *const SHARED_TIMEOUT_NAMES[10] = {
"shared_timeout_0", "shared_timeout_1", "shared_timeout_2", "shared_timeout_3", "shared_timeout_4",
"shared_timeout_5", "shared_timeout_6", "shared_timeout_7", "shared_timeout_8", "shared_timeout_9"};
void SchedulerRapidCancellationComponent::setup() { ESP_LOGCONFIG(TAG, "SchedulerRapidCancellationComponent setup"); }
void SchedulerRapidCancellationComponent::run_rapid_cancellation_test() {
@@ -32,14 +38,12 @@ void SchedulerRapidCancellationComponent::run_rapid_cancellation_test() {
for (int i = 0; i < OPERATIONS_PER_THREAD; i++) {
// Use modulo to ensure multiple threads use the same names
int name_index = i % NUM_NAMES;
std::stringstream ss;
ss << "shared_timeout_" << name_index;
std::string name = ss.str();
const char *name = SHARED_TIMEOUT_NAMES[name_index];
// All threads schedule timeouts - this will implicitly cancel existing ones
this->set_timeout(name, 150, [this, name]() {
this->total_executed_.fetch_add(1);
ESP_LOGI(TAG, "Executed callback '%s'", name.c_str());
ESP_LOGI(TAG, "Executed callback '%s'", name);
});
this->total_scheduled_.fetch_add(1);
@@ -1,9 +1,9 @@
#include "simultaneous_callbacks_component.h"
#include "esphome/core/log.h"
#include <cinttypes>
#include <thread>
#include <vector>
#include <chrono>
#include <sstream>
namespace esphome::scheduler_simultaneous_callbacks_component {
@@ -41,13 +41,11 @@ void SchedulerSimultaneousCallbacksComponent::run_simultaneous_callbacks_test()
std::this_thread::sleep_until(start_time + std::chrono::microseconds(100));
for (int i = 0; i < CALLBACKS_PER_THREAD; i++) {
// Create unique name for each callback
std::stringstream ss;
ss << "thread_" << thread_id << "_cb_" << i;
std::string name = ss.str();
// Unique numeric ID for each callback (zero heap allocation, no name collisions)
uint32_t callback_id = static_cast<uint32_t>(thread_id) * CALLBACKS_PER_THREAD + i;
// Schedule callback for exactly DELAY_MS from now
this->set_timeout(name, DELAY_MS, [this, name]() {
this->set_timeout(callback_id, DELAY_MS, [this, callback_id]() {
// Increment concurrent counter atomically
int current = this->callbacks_at_once_.fetch_add(1) + 1;
@@ -57,7 +55,7 @@ void SchedulerSimultaneousCallbacksComponent::run_simultaneous_callbacks_test()
// Loop until we successfully update or someone else set a higher value
}
ESP_LOGV(TAG, "Callback executed: %s (concurrent: %d)", name.c_str(), current);
ESP_LOGV(TAG, "Callback executed: id=%" PRIu32 " (concurrent: %d)", callback_id, current);
// Simulate some minimal work
std::atomic<int> work{0};
@@ -73,7 +71,7 @@ void SchedulerSimultaneousCallbacksComponent::run_simultaneous_callbacks_test()
});
this->total_scheduled_.fetch_add(1);
ESP_LOGV(TAG, "Scheduled callback %s", name.c_str());
ESP_LOGV(TAG, "Scheduled callback id=%" PRIu32, callback_id);
}
ESP_LOGD(TAG, "Thread %d completed scheduling", thread_id);
@@ -1,21 +0,0 @@
import esphome.codegen as cg
import esphome.config_validation as cv
from esphome.const import CONF_ID
scheduler_string_lifetime_component_ns = cg.esphome_ns.namespace(
"scheduler_string_lifetime_component"
)
SchedulerStringLifetimeComponent = scheduler_string_lifetime_component_ns.class_(
"SchedulerStringLifetimeComponent", cg.Component
)
CONFIG_SCHEMA = cv.Schema(
{
cv.GenerateID(): cv.declare_id(SchedulerStringLifetimeComponent),
}
).extend(cv.COMPONENT_SCHEMA)
async def to_code(config):
var = cg.new_Pvariable(config[CONF_ID])
await cg.register_component(var, config)
@@ -1,260 +0,0 @@
#include "string_lifetime_component.h"
#include "esphome/core/log.h"
#include <memory>
#include <thread>
#include <chrono>
namespace esphome::scheduler_string_lifetime_component {
static const char *const TAG = "scheduler_string_lifetime";
void SchedulerStringLifetimeComponent::setup() { ESP_LOGCONFIG(TAG, "SchedulerStringLifetimeComponent setup"); }
void SchedulerStringLifetimeComponent::run_string_lifetime_test() {
ESP_LOGI(TAG, "Starting string lifetime tests");
this->tests_passed_ = 0;
this->tests_failed_ = 0;
// Run each test
test_temporary_string_lifetime();
test_scope_exit_string();
test_vector_reallocation();
test_string_move_semantics();
test_lambda_capture_lifetime();
}
void SchedulerStringLifetimeComponent::run_test1() {
test_temporary_string_lifetime();
// Wait for all callbacks to execute
this->set_timeout("test1_complete", 10, []() { ESP_LOGI(TAG, "Test 1 complete"); });
}
void SchedulerStringLifetimeComponent::run_test2() {
test_scope_exit_string();
// Wait for all callbacks to execute
this->set_timeout("test2_complete", 20, []() { ESP_LOGI(TAG, "Test 2 complete"); });
}
void SchedulerStringLifetimeComponent::run_test3() {
test_vector_reallocation();
// Wait for all callbacks to execute
this->set_timeout("test3_complete", 60, []() { ESP_LOGI(TAG, "Test 3 complete"); });
}
void SchedulerStringLifetimeComponent::run_test4() {
test_string_move_semantics();
// Wait for all callbacks to execute
this->set_timeout("test4_complete", 35, []() { ESP_LOGI(TAG, "Test 4 complete"); });
}
void SchedulerStringLifetimeComponent::run_test5() {
test_lambda_capture_lifetime();
// Wait for all callbacks to execute
this->set_timeout("test5_complete", 50, []() { ESP_LOGI(TAG, "Test 5 complete"); });
}
void SchedulerStringLifetimeComponent::run_final_check() {
ESP_LOGI(TAG, "Tests passed: %d", this->tests_passed_);
ESP_LOGI(TAG, "Tests failed: %d", this->tests_failed_);
if (this->tests_failed_ == 0) {
ESP_LOGI(TAG, "SUCCESS: All string lifetime tests passed!");
} else {
ESP_LOGE(TAG, "FAILURE: %d string lifetime tests failed!", this->tests_failed_);
}
ESP_LOGI(TAG, "String lifetime tests complete");
}
void SchedulerStringLifetimeComponent::test_temporary_string_lifetime() {
ESP_LOGI(TAG, "Test 1: Temporary string lifetime for timeout names");
// Test with a temporary string that goes out of scope immediately
{
std::string temp_name = "temp_callback_" + std::to_string(12345);
// Schedule with temporary string name - scheduler must copy/store this
this->set_timeout(temp_name, 1, [this]() {
ESP_LOGD(TAG, "Callback for temp string name executed");
this->tests_passed_++;
});
// String goes out of scope here, but scheduler should have made a copy
}
// Test with rvalue string as name
this->set_timeout(std::string("rvalue_test"), 2, [this]() {
ESP_LOGD(TAG, "Rvalue string name callback executed");
this->tests_passed_++;
});
// Test cancelling with reconstructed string
{
std::string cancel_name = "cancel_test_" + std::to_string(999);
this->set_timeout(cancel_name, 100, [this]() {
ESP_LOGE(TAG, "This should have been cancelled!");
this->tests_failed_++;
});
} // cancel_name goes out of scope
// Reconstruct the same string to cancel
std::string cancel_name_2 = "cancel_test_" + std::to_string(999);
bool cancelled = this->cancel_timeout(cancel_name_2);
if (cancelled) {
ESP_LOGD(TAG, "Successfully cancelled with reconstructed string");
this->tests_passed_++;
} else {
ESP_LOGE(TAG, "Failed to cancel with reconstructed string");
this->tests_failed_++;
}
}
void SchedulerStringLifetimeComponent::test_scope_exit_string() {
ESP_LOGI(TAG, "Test 2: Scope exit string names");
// Create string names in a limited scope
{
std::string scoped_name = "scoped_timeout_" + std::to_string(555);
// Schedule with scoped string name
this->set_timeout(scoped_name, 3, [this]() {
ESP_LOGD(TAG, "Scoped name callback executed");
this->tests_passed_++;
});
// scoped_name goes out of scope here
}
// Test with dynamically allocated string name
{
auto *dynamic_name = new std::string("dynamic_timeout_" + std::to_string(777));
this->set_timeout(*dynamic_name, 4, [this, dynamic_name]() {
ESP_LOGD(TAG, "Dynamic string name callback executed");
this->tests_passed_++;
delete dynamic_name; // Clean up in callback
});
// Pointer goes out of scope but string object remains until callback
}
// Test multiple timeouts with same dynamically created name
for (int i = 0; i < 3; i++) {
std::string loop_name = "loop_timeout_" + std::to_string(i);
this->set_timeout(loop_name, 5 + i * 1, [this, i]() {
ESP_LOGD(TAG, "Loop timeout %d executed", i);
this->tests_passed_++;
});
// loop_name destroyed and recreated each iteration
}
}
void SchedulerStringLifetimeComponent::test_vector_reallocation() {
ESP_LOGI(TAG, "Test 3: Vector reallocation stress on timeout names");
// Create a vector that will reallocate
std::vector<std::string> names;
names.reserve(2); // Small initial capacity to force reallocation
// Schedule callbacks with string names from vector
for (int i = 0; i < 10; i++) {
names.push_back("vector_cb_" + std::to_string(i));
// Use the string from vector as timeout name
this->set_timeout(names.back(), 8 + i * 1, [this, i]() {
ESP_LOGV(TAG, "Vector name callback %d executed", i);
this->tests_passed_++;
});
}
// Force reallocation by adding more elements
// This will move all strings to new memory locations
for (int i = 10; i < 50; i++) {
names.push_back("realloc_trigger_" + std::to_string(i));
}
// Add more timeouts after reallocation to ensure old names still work
for (int i = 50; i < 55; i++) {
names.push_back("post_realloc_" + std::to_string(i));
this->set_timeout(names.back(), 20 + (i - 50), [this]() {
ESP_LOGV(TAG, "Post-reallocation callback executed");
this->tests_passed_++;
});
}
// Clear the vector while timeouts are still pending
names.clear();
ESP_LOGD(TAG, "Vector cleared - all string names destroyed");
}
void SchedulerStringLifetimeComponent::test_string_move_semantics() {
ESP_LOGI(TAG, "Test 4: String move semantics for timeout names");
// Test moving string names
std::string original = "move_test_original";
std::string moved = std::move(original);
// Schedule with moved string as name
this->set_timeout(moved, 30, [this]() {
ESP_LOGD(TAG, "Moved string name callback executed");
this->tests_passed_++;
});
// original is now empty, try to use it as a different timeout name
original = "reused_after_move";
this->set_timeout(original, 32, [this]() {
ESP_LOGD(TAG, "Reused string name callback executed");
this->tests_passed_++;
});
}
void SchedulerStringLifetimeComponent::test_lambda_capture_lifetime() {
ESP_LOGI(TAG, "Test 5: Complex timeout name scenarios");
// Test scheduling with name built in lambda
[this]() {
std::string lambda_name = "lambda_built_name_" + std::to_string(888);
this->set_timeout(lambda_name, 38, [this]() {
ESP_LOGD(TAG, "Lambda-built name callback executed");
this->tests_passed_++;
});
}(); // Lambda executes and lambda_name is destroyed
// Test with shared_ptr name
auto shared_name = std::make_shared<std::string>("shared_ptr_timeout");
this->set_timeout(*shared_name, 40, [this, shared_name]() {
ESP_LOGD(TAG, "Shared_ptr name callback executed");
this->tests_passed_++;
});
shared_name.reset(); // Release the shared_ptr
// Test overwriting timeout with same name
std::string overwrite_name = "overwrite_test";
this->set_timeout(overwrite_name, 1000, [this]() {
ESP_LOGE(TAG, "This should have been overwritten!");
this->tests_failed_++;
});
// Overwrite with shorter timeout
this->set_timeout(overwrite_name, 42, [this]() {
ESP_LOGD(TAG, "Overwritten timeout executed");
this->tests_passed_++;
});
// Test very long string name
std::string long_name;
for (int i = 0; i < 100; i++) {
long_name += "very_long_timeout_name_segment_" + std::to_string(i) + "_";
}
this->set_timeout(long_name, 44, [this]() {
ESP_LOGD(TAG, "Very long name timeout executed");
this->tests_passed_++;
});
// Test empty string as name
this->set_timeout("", 46, [this]() {
ESP_LOGD(TAG, "Empty string name timeout executed");
this->tests_passed_++;
});
}
} // namespace esphome::scheduler_string_lifetime_component
@@ -1,35 +0,0 @@
#pragma once
#include "esphome/core/component.h"
#include <vector>
#include <string>
namespace esphome::scheduler_string_lifetime_component {
class SchedulerStringLifetimeComponent : public Component {
public:
void setup() override;
float get_setup_priority() const override { return setup_priority::LATE; }
void run_string_lifetime_test();
// Individual test methods exposed as services
void run_test1();
void run_test2();
void run_test3();
void run_test4();
void run_test5();
void run_final_check();
private:
void test_temporary_string_lifetime();
void test_scope_exit_string();
void test_vector_reallocation();
void test_string_move_semantics();
void test_lambda_capture_lifetime();
int tests_passed_{0};
int tests_failed_{0};
};
} // namespace esphome::scheduler_string_lifetime_component
@@ -1,21 +0,0 @@
import esphome.codegen as cg
import esphome.config_validation as cv
from esphome.const import CONF_ID
scheduler_string_name_stress_component_ns = cg.esphome_ns.namespace(
"scheduler_string_name_stress_component"
)
SchedulerStringNameStressComponent = scheduler_string_name_stress_component_ns.class_(
"SchedulerStringNameStressComponent", cg.Component
)
CONFIG_SCHEMA = cv.Schema(
{
cv.GenerateID(): cv.declare_id(SchedulerStringNameStressComponent),
}
).extend(cv.COMPONENT_SCHEMA)
async def to_code(config):
var = cg.new_Pvariable(config[CONF_ID])
await cg.register_component(var, config)
@@ -1,108 +0,0 @@
#include "string_name_stress_component.h"
#include "esphome/core/log.h"
#include <thread>
#include <atomic>
#include <vector>
#include <chrono>
#include <string>
#include <sstream>
namespace esphome::scheduler_string_name_stress_component {
static const char *const TAG = "scheduler_string_name_stress";
void SchedulerStringNameStressComponent::setup() { ESP_LOGCONFIG(TAG, "SchedulerStringNameStressComponent setup"); }
void SchedulerStringNameStressComponent::run_string_name_stress_test() {
// Use member variables to reset state
this->total_callbacks_ = 0;
this->executed_callbacks_ = 0;
static constexpr int NUM_THREADS = 10;
static constexpr int CALLBACKS_PER_THREAD = 100;
ESP_LOGI(TAG, "Starting string name stress test - multi-threaded set_timeout with std::string names");
ESP_LOGI(TAG, "This test specifically uses dynamic string names to test memory management");
// Track start time
auto start_time = std::chrono::steady_clock::now();
// Create threads
std::vector<std::thread> threads;
ESP_LOGI(TAG, "Creating %d threads, each will schedule %d callbacks with dynamic names", NUM_THREADS,
CALLBACKS_PER_THREAD);
threads.reserve(NUM_THREADS);
for (int i = 0; i < NUM_THREADS; i++) {
threads.emplace_back([this, i]() {
ESP_LOGV(TAG, "Thread %d starting", i);
// Each thread schedules callbacks with dynamically created string names
for (int j = 0; j < CALLBACKS_PER_THREAD; j++) {
int callback_id = this->total_callbacks_.fetch_add(1);
// Create a dynamic string name - this will test memory management
std::stringstream ss;
ss << "thread_" << i << "_callback_" << j << "_id_" << callback_id;
std::string dynamic_name = ss.str();
ESP_LOGV(TAG, "Thread %d scheduling timeout with dynamic name: %s", i, dynamic_name.c_str());
// Capture necessary values for the lambda
auto *component = this;
// Schedule with std::string name - this tests the string overload
// Use varying delays to stress the heap scheduler
uint32_t delay = 1 + (callback_id % 50);
// Also test nested scheduling from callbacks
if (j % 10 == 0) {
// Every 10th callback schedules another callback
this->set_timeout(dynamic_name, delay, [component, callback_id]() {
component->executed_callbacks_.fetch_add(1);
ESP_LOGV(TAG, "Executed string-named callback %d (nested scheduler)", callback_id);
// Schedule another timeout from within this callback with a new dynamic name
std::string nested_name = "nested_from_" + std::to_string(callback_id);
component->set_timeout(nested_name, 1, [callback_id]() {
ESP_LOGV(TAG, "Executed nested string-named callback from %d", callback_id);
});
});
} else {
// Regular callback
this->set_timeout(dynamic_name, delay, [component, callback_id]() {
component->executed_callbacks_.fetch_add(1);
ESP_LOGV(TAG, "Executed string-named callback %d", callback_id);
});
}
// Add some timing variations to increase race conditions
if (j % 5 == 0) {
std::this_thread::sleep_for(std::chrono::microseconds(100));
}
}
ESP_LOGV(TAG, "Thread %d finished scheduling", i);
});
}
// Wait for all threads to complete scheduling
for (auto &t : threads) {
t.join();
}
auto end_time = std::chrono::steady_clock::now();
auto thread_time = std::chrono::duration_cast<std::chrono::milliseconds>(end_time - start_time).count();
ESP_LOGI(TAG, "All threads finished scheduling in %lldms. Created %d callbacks with dynamic names", thread_time,
this->total_callbacks_.load());
// Give some time for callbacks to execute
ESP_LOGI(TAG, "Waiting for callbacks to execute...");
// Schedule a final callback to signal completion
this->set_timeout("test_complete", 2000, [this]() {
ESP_LOGI(TAG, "String name stress test complete. Executed %d of %d callbacks", this->executed_callbacks_.load(),
this->total_callbacks_.load());
});
}
} // namespace esphome::scheduler_string_name_stress_component
@@ -1,20 +0,0 @@
#pragma once
#include "esphome/core/component.h"
#include <atomic>
namespace esphome::scheduler_string_name_stress_component {
class SchedulerStringNameStressComponent : public Component {
public:
void setup() override;
float get_setup_priority() const override { return setup_priority::LATE; }
void run_string_name_stress_test();
private:
std::atomic<int> total_callbacks_{0};
std::atomic<int> executed_callbacks_{0};
};
} // namespace esphome::scheduler_string_name_stress_component
@@ -0,0 +1,61 @@
esphome:
name: logger-recursion-test
host:
api:
logger:
level: DEBUG
on_message:
# Fires on the main loop for every message delivered to listeners, including
# messages drained from the task log buffer (i.e. logged from a non-main thread).
# The lambda logs again on the main task. Without a recursion guard on the buffered
# drain path this re-entrant log reuses the shared tx_buffer_ and clobbers the
# buffered message that is still being delivered, corrupting its console output.
- level: VERY_VERBOSE
then:
- lambda: |-
ESP_LOGD("reentry", "REENTRANT_CLOBBER_MARKER");
button:
- platform: template
name: "Start Race Test"
id: start_test_button
on_press:
- lambda: |-
// Keep the count well under the host task-log-buffer slot count so every
// message goes through the ring buffer (buffered drain path) instead of the
// emergency console fallback. The main loop is blocked in pthread_join while
// the thread logs, so all messages are drained together once it returns.
static const int NUM_MESSAGES = 30;
struct ThreadTest {
static void *thread_func(void *arg) {
char thread_name[16];
snprintf(thread_name, sizeof(thread_name), "LogThread");
#ifdef __APPLE__
pthread_setname_np(thread_name);
#else
pthread_setname_np(pthread_self(), thread_name);
#endif
for (int i = 0; i < NUM_MESSAGES; i++) {
// Verifiable payload: data is a deterministic function of the message
// index, so a clobbered buffer shows up as a missing or mismatched line.
ESP_LOGD("thread_test", "THREADMSG%03d_DATA_%08X", i, i * 12345);
}
return nullptr;
}
};
// RACE_TEST_START / RACE_TEST_COMPLETE are logged from the main task (the
// synchronous path, which already holds the recursion guard) so the test can
// always detect completion even when the buffered path is corrupted.
ESP_LOGI("thread_test", "RACE_TEST_START: logging %d messages from a thread", NUM_MESSAGES);
pthread_t thread;
if (pthread_create(&thread, nullptr, ThreadTest::thread_func, nullptr) != 0) {
ESP_LOGE("thread_test", "RACE_TEST_ERROR: Failed to create thread");
return;
}
pthread_join(thread, nullptr);
ESP_LOGI("thread_test", "RACE_TEST_COMPLETE: thread finished, expected %d messages", NUM_MESSAGES);
@@ -109,7 +109,7 @@ select:
set_action:
- lambda: |-
ESP_LOGI("test", "Device A Mode set to %s", x.c_str());
id(mode_device_a).state = x;
id(mode_device_a).publish_state(x);
- platform: template
name: Mode
@@ -124,7 +124,7 @@ select:
set_action:
- lambda: |-
ESP_LOGI("test", "Device B Mode set to %s", x.c_str());
id(mode_device_b).state = x;
id(mode_device_b).publish_state(x);
- platform: template
name: Mode
@@ -138,7 +138,7 @@ select:
set_action:
- lambda: |-
ESP_LOGI("test", "Main Mode set to %s", x.c_str());
id(mode_main).state = x;
id(mode_main).publish_state(x);
# Button to trigger preference logging test
button:
@@ -153,9 +153,9 @@ button:
ESP_LOGI("test", "Device A Setpoint: %.1f", id(setpoint_device_a).state);
ESP_LOGI("test", "Device B Setpoint: %.1f", id(setpoint_device_b).state);
ESP_LOGI("test", "Main Setpoint: %.1f", id(setpoint_main).state);
ESP_LOGI("test", "Device A Mode: %s", id(mode_device_a).state.c_str());
ESP_LOGI("test", "Device B Mode: %s", id(mode_device_b).state.c_str());
ESP_LOGI("test", "Main Mode: %s", id(mode_main).state.c_str());
ESP_LOGI("test", "Device A Mode: %s", id(mode_device_a).current_option().c_str());
ESP_LOGI("test", "Device B Mode: %s", id(mode_device_b).current_option().c_str());
ESP_LOGI("test", "Main Mode: %s", id(mode_main).current_option().c_str());
// Log preference hashes for entities that actually store preferences
ESP_LOGI("test", "Device A Switch Pref Hash: %u", id(light_device_a).get_preference_hash());
ESP_LOGI("test", "Device B Switch Pref Hash: %u", id(light_device_b).get_preference_hash());
@@ -0,0 +1,22 @@
esphome:
name: scheduler-blocking-warning
on_boot:
then:
- script.execute: blocking_script
host:
api:
logger:
level: DEBUG
# The busy-block runs in the second delay's continuation; the warning must name the script. Two
# delays verify the source survives chained delays (the scheduler republishes it each continuation).
script:
- id: blocking_script
then:
- delay: 10ms
- delay: 10ms
- lambda: |-
const uint32_t start = millis();
while (millis() - start < 80) {
}
@@ -0,0 +1,30 @@
esphome:
name: scheduler-blocking-generic
host:
api:
logger:
level: DEBUG
globals:
- id: done
type: bool
restore_value: false
initial_value: "false"
# A delay in a plain (non-script) automation has no owning script, so the block must log the
# generic "a scheduled task" label, not a script name.
interval:
- interval: 100ms
id: gen_interval
then:
- if:
condition:
lambda: "return !id(done);"
then:
- lambda: "id(done) = true;"
- delay: 10ms
- lambda: |-
const uint32_t start = millis();
while (millis() - start < 80) {
}
@@ -0,0 +1,29 @@
esphome:
name: scheduler-delay-failed
host:
api:
logger:
level: DEBUG
globals:
- id: started
type: bool
restore_value: false
initial_value: "false"
# The interval marks itself failed, then schedules a delay. The delay must still fire: a failed
# component must not drop it, since the SELF_POINTER scheduler item has no owning component.
interval:
- interval: 100ms
id: host_interval
then:
- if:
condition:
lambda: "return !id(started);"
then:
- lambda: |-
id(started) = true;
id(host_interval)->mark_failed();
- delay: 200ms
- logger.log: "DELAY_FIRED_AFTER_FAIL"
@@ -156,9 +156,9 @@ script:
// Simulate a burst of defer operations like ratgdo does with state updates
// These should execute immediately and recycle quickly to the pool
// Phase-specific id range (0..9) so ids never collide with later phases
for (int i = 0; i < 10; i++) {
std::string defer_name = "defer_" + std::to_string(i);
App.scheduler.set_timeout(component, defer_name, 0, [i]() {
App.scheduler.set_timeout(component, static_cast<uint32_t>(i), 0, [i]() {
ESP_LOGD("test", "Defer %d executed", i);
// Force a small delay between defer executions to see recycling
if (i == 5) {
@@ -207,9 +207,9 @@ script:
// Now create 8 new timeouts - they should reuse from pool when available
int reuse_test_count = 8;
// Phase-specific id range (100..107) so ids never collide with other phases
for (int i = 0; i < reuse_test_count; i++) {
std::string name = "reuse_test_" + std::to_string(i);
App.scheduler.set_timeout(component, name, 10 + i * 5, [i]() {
App.scheduler.set_timeout(component, static_cast<uint32_t>(100 + i), 10 + i * 5, [i]() {
ESP_LOGD("test", "Reuse test %d completed", i);
});
}
@@ -229,9 +229,9 @@ script:
auto *component = id(test_sensor);
int full_reuse_count = 10;
// Phase-specific id range (200..209) so ids never collide with other phases
for (int i = 0; i < full_reuse_count; i++) {
std::string name = "full_reuse_" + std::to_string(i);
App.scheduler.set_timeout(component, name, 10 + i * 5, [i]() {
App.scheduler.set_timeout(component, static_cast<uint32_t>(200 + i), 10 + i * 5, [i]() {
ESP_LOGD("test", "Full reuse test %d completed", i);
});
}
@@ -1,48 +0,0 @@
esphome:
debug_scheduler: true # Enable scheduler leak detection
name: scheduler-string-lifetime-test
external_components:
- source:
type: local
path: EXTERNAL_COMPONENT_PATH
components: [scheduler_string_lifetime_component]
host:
logger:
level: DEBUG
scheduler_string_lifetime_component:
id: string_lifetime
api:
services:
- service: run_string_lifetime_test
then:
- lambda: |-
id(string_lifetime)->run_string_lifetime_test();
- service: run_test1
then:
- lambda: |-
id(string_lifetime)->run_test1();
- service: run_test2
then:
- lambda: |-
id(string_lifetime)->run_test2();
- service: run_test3
then:
- lambda: |-
id(string_lifetime)->run_test3();
- service: run_test4
then:
- lambda: |-
id(string_lifetime)->run_test4();
- service: run_test5
then:
- lambda: |-
id(string_lifetime)->run_test5();
- service: run_final_check
then:
- lambda: |-
id(string_lifetime)->run_final_check();
@@ -1,39 +0,0 @@
esphome:
debug_scheduler: true # Enable scheduler leak detection
name: sched-string-name-stress
external_components:
- source:
type: local
path: EXTERNAL_COMPONENT_PATH
components: [scheduler_string_name_stress_component]
host:
logger:
level: VERBOSE
scheduler_string_name_stress_component:
id: string_stress
api:
services:
- service: run_string_name_stress_test
then:
- lambda: |-
id(string_stress)->run_string_name_stress_test();
event:
- platform: template
name: "Test Complete"
id: test_complete
device_class: button
event_types:
- "test_finished"
- platform: template
name: "Test Result"
id: test_result
device_class: button
event_types:
- "passed"
- "failed"
@@ -18,9 +18,6 @@ globals:
- id: interval_counter
type: int
initial_value: '0'
- id: dynamic_counter
type: int
initial_value: '0'
- id: static_tests_done
type: bool
initial_value: 'false'
@@ -103,46 +100,43 @@ script:
- id: test_dynamic_strings
then:
- logger.log: "Testing dynamic string timeouts and intervals"
- logger.log: "Testing const char* timeouts and intervals"
- lambda: |-
auto *component2 = id(test_sensor2);
// Test 8: 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, []() {
// Test 8: const char* name with set_timeout
App.scheduler.set_timeout(component2, "dynamic_timeout", 100, []() {
ESP_LOGI("test", "Dynamic timeout fired");
id(timeout_counter) += 1;
});
// Test 9: 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());
// Test 9: const char* name with set_interval, cancelled from inside the callback
App.scheduler.set_interval(component2, "dynamic_interval", 250, []() {
ESP_LOGI("test", "Dynamic interval fired");
id(interval_counter) += 1;
if (id(interval_counter) >= 6) {
App.scheduler.cancel_interval(id(test_sensor2), interval_name);
App.scheduler.cancel_interval(id(test_sensor2), "dynamic_interval");
ESP_LOGI("test", "Cancelled dynamic interval");
}
});
// Test 10: Cancel with different string object but same content
std::string cancel_name = "cancel_test";
App.scheduler.set_timeout(component2, cancel_name, 2000, []() {
// Test 10: Cancel with a different pointer but identical content.
// STATIC_STRING names match by content, so a distinct static buffer with the
// same characters still cancels the scheduled timeout.
static const char CANCEL_NAME[] = "cancel_test";
App.scheduler.set_timeout(component2, CANCEL_NAME, 2000, []() {
ESP_LOGI("test", "This should be cancelled");
});
static const char CANCEL_NAME_2[] = "cancel_test";
App.scheduler.cancel_timeout(component2, CANCEL_NAME_2);
ESP_LOGI("test", "Cancelled timeout using different buffer with same content");
// Cancel using a different string object
std::string cancel_name_2 = "cancel_test";
App.scheduler.cancel_timeout(component2, cancel_name_2);
ESP_LOGI("test", "Cancelled timeout using different string object");
// Test 11: Dynamic string with defer (using std::string overload)
// Test 11: const char* name with defer
class TestDynamicDeferComponent : public Component {
public:
void test_dynamic_defer() {
std::string defer_name = "dynamic_defer_" + std::to_string(id(dynamic_counter)++);
this->defer(defer_name, [defer_name]() {
ESP_LOGI("test", "Dynamic defer fired: %s", defer_name.c_str());
this->defer("dynamic_defer", []() {
ESP_LOGI("test", "Dynamic defer fired");
id(timeout_counter) += 1;
});
}
@@ -0,0 +1,27 @@
esphome:
name: socket-wake-gate-tcp
on_boot:
priority: -100
then:
- lambda: |-
// Raise loop_interval_ to 2000ms. Without wake_request_set() being
// called when select() returns due to socket data, the component
// phase would be gated for up to 2000ms after a TCP request arrives.
App.set_loop_interval(2000);
# Let boot transients and API handshake settle.
- delay: 500ms
- lambda: |-
ESP_LOGI("test", "BOOT_DONE");
host:
api:
actions:
- action: ping
then:
- logger.log:
format: "PONG"
level: INFO
logger:
level: INFO
@@ -49,15 +49,16 @@ modbus_controller:
- address: 1
id: modbus_controller_ok
max_cmd_retries: 2
update_interval: 1s
# Update interval is set to never to prevent automatic polling: the test will trigger requests by pressing the "Start Scenario" button
update_interval: never
- address: 2
id: modbus_controller_slow
max_cmd_retries: 0
update_interval: 1s
update_interval: never
- address: 3
id: modbus_controller_offline
max_cmd_retries: 0
update_interval: 1s
update_interval: never
sensor:
- platform: modbus_controller
@@ -91,4 +92,11 @@ button:
name: "Start Scenario"
id: start_scenario_btn
on_press:
- lambda: "id(virtual_uart_dev).start_scenario();"
- lambda: |-
id(virtual_uart_dev).start_scenario();
id(modbus_controller_ok).set_update_interval(1000);
id(modbus_controller_ok).start_poller();
id(modbus_controller_slow).set_update_interval(1000);
id(modbus_controller_slow).start_poller();
id(modbus_controller_offline).set_update_interval(1000);
id(modbus_controller_offline).start_poller();
@@ -54,7 +54,11 @@ modbus:
sensor:
- platform: sdm_meter
address: 2
update_interval: 1s
id: sdm_meter_1
# update_interval is set to never to avoid automatic polling before the test starts the scenario.
# The test will manually start the poller after subscribing to states, to ensure no state changes are missed.
# This also allows us to assert there are no modbus errors/warnings during the initial request/response.
update_interval: never
phase_a:
voltage:
name: sdm_voltage
@@ -64,4 +68,7 @@ button:
name: "Start Scenario"
id: start_scenario_btn
on_press:
- lambda: "id(virtual_uart_dev).start_scenario();"
- lambda: |-
id(virtual_uart_dev).start_scenario();
id(sdm_meter_1).set_update_interval(1000);
id(sdm_meter_1).start_poller();
@@ -53,8 +53,8 @@ modbus:
modbus_controller:
- address: 1
modbus_id: virtual_modbus_controller
update_interval: 1s
id: modbus_controller_1
update_interval: 1s
modbus_server:
- address: 1
@@ -176,6 +176,4 @@ button:
- platform: template
name: "Start Scenario"
id: start_scenario_btn
on_press:
- lambda: "id(virtual_uart_server).start_scenario();"
- lambda: "id(virtual_uart_controller).start_scenario();"
# This test does not have anything to start (mock is autostart)
@@ -113,7 +113,4 @@ button:
- platform: template
name: "Start Scenario"
id: start_scenario_btn
on_press:
- lambda: "id(virtual_uart_server).start_scenario();"
- lambda: "id(virtual_uart_server_2).start_scenario();"
- lambda: "id(virtual_uart_controller).start_scenario();"
# This test does not have anything to start (mock is autostart)
@@ -326,6 +326,4 @@ button:
- platform: template
name: "Start Scenario"
id: start_scenario_btn
on_press:
- lambda: "id(virtual_uart_server).start_scenario();"
- lambda: "id(virtual_uart_controller).start_scenario();"
# This test does not have anything to start (mock is autostart)
@@ -53,7 +53,11 @@ modbus:
sensor:
- platform: sdm_meter
address: 2
update_interval: 1s
id: sdm_meter_1
# update_interval is set to never to avoid automatic polling before the test starts the scenario.
# The test will manually start the poller after subscribing to states, to ensure no state changes are missed.
# This also allows us to assert there are no modbus errors/warnings during the initial request/response.
update_interval: never
phase_a:
voltage:
name: sdm_voltage
@@ -63,4 +67,7 @@ button:
name: "Start Scenario"
id: start_scenario_btn
on_press:
- lambda: "id(virtual_uart_dev).start_scenario();"
- lambda: |-
id(virtual_uart_dev).start_scenario();
id(sdm_meter_1).set_update_interval(1000);
id(sdm_meter_1).start_poller();
+2 -3
View File
@@ -19,7 +19,6 @@ from aioesphomeapi import (
_LOGGER = logging.getLogger(__name__)
T = TypeVar("T", bound=EntityInfo)
S = TypeVar("S", bound=EntityState)
@@ -58,7 +57,7 @@ async def wait_for_state(
return await asyncio.wait_for(future, timeout=timeout)
def find_entity(
def find_entity[T: EntityInfo](
entities: list[EntityInfo],
object_id_substring: str,
entity_type: type[T] | None = None,
@@ -86,7 +85,7 @@ def find_entity(
return None
def require_entity(
def require_entity[T: EntityInfo](
entities: list[EntityInfo],
object_id_substring: str,
entity_type: type[T] | None = None,
@@ -0,0 +1,119 @@
"""Integration test for the recursion guard on the buffered logger drain path.
Regression test for a crash where a log message drained from the task log buffer
(i.e. logged from a non-main thread) re-entered the logger on the main task while it
was still being delivered to listeners. The buffered drain in
``Logger::process_messages_`` did not hold the main-task recursion guard that the
synchronous logging path holds, so a listener callback that logged again on the main
task (e.g. the API log-forwarding path, or a ``logger.on_message`` automation) reused
the shared ``tx_buffer_`` and clobbered the message mid-delivery. On ESP32 this showed
up as a ``StoreProhibited`` panic inside the API send path.
The fixture logs a small batch of verifiable messages from a non-main thread (kept
under the host task-log-buffer slot count so they all take the buffered drain path
rather than the emergency console fallback) while an ``on_message`` automation re-logs
``REENTRANT_CLOBBER_MARKER`` on the main task for every delivered message.
Without the guard the re-entrant marker is written into the shared ``tx_buffer_`` while
the buffered thread message is still being delivered, so the message the API receives is
contaminated (it contains the marker and an embedded newline glued onto the thread
payload). With the guard the re-entrant log is dropped during the drain, the marker
never appears, and every thread message is delivered clean.
"""
from __future__ import annotations
import asyncio
import re
from aioesphomeapi import LogLevel
import pytest
from .types import APIClientConnectedFactory, RunCompiledFunction
_ANSI = re.compile(r"\x1b\[[0-9;]*m")
# THREADMSGnnn_DATA_xxxxxxxx where data is a deterministic checksum of the index
THREAD_MSG_PATTERN = re.compile(r"THREADMSG(\d{3})_DATA_([0-9A-F]{8})")
NUM_MESSAGES = 30
@pytest.mark.asyncio
async def test_logger_buffered_recursion_guard(
yaml_config: str,
run_compiled: RunCompiledFunction,
api_client_connected: APIClientConnectedFactory,
) -> None:
"""Buffered (non-main-thread) log messages survive a re-entrant main-task log."""
api_messages: list[str] = []
all_drained = asyncio.Event()
async with (
run_compiled(yaml_config),
api_client_connected() as client,
):
device_info = await client.device_info()
assert device_info is not None
assert device_info.name == "logger-recursion-test"
# Subscribe over the API: this is the exact path that crashed in the field
# (the API log callback runs during the buffered drain). The API message field
# preserves embedded newlines, so it reliably exposes a clobbered buffer.
#
# Every buffered thread message is delivered here whether it survives intact or
# gets clobbered (a clobbered message still carries its THREADMSG payload), so
# counting THREADMSG occurrences is a deterministic "drain complete" signal: no
# arbitrary sleep, no dependence on the fix being present.
def on_log(msg) -> None:
text = msg.message.decode("utf-8", errors="replace")
api_messages.append(text)
received = sum(len(THREAD_MSG_PATTERN.findall(m)) for m in api_messages)
if received >= NUM_MESSAGES:
all_drained.set()
client.subscribe_logs(on_log, log_level=LogLevel.LOG_LEVEL_VERY_VERBOSE)
entities, _ = await client.list_entities_services()
buttons = [e for e in entities if e.name == "Start Race Test"]
assert buttons, "Could not find Start Race Test button"
client.button_command(buttons[0].key)
# Wait until every buffered thread message has been delivered over the API.
try:
await asyncio.wait_for(all_drained.wait(), timeout=30.0)
except TimeoutError:
received = sum(len(THREAD_MSG_PATTERN.findall(m)) for m in api_messages)
pytest.fail(
f"Only {received}/{NUM_MESSAGES} thread messages arrived before timeout; "
"device likely crashed or hung."
)
intact: set[int] = set()
contaminated: list[str] = []
for raw in api_messages:
text = _ANSI.sub("", raw)
if "THREADMSG" not in text:
continue
# A clean thread message is a single line carrying only its own payload. A
# clobbered buffer glues the re-entrant marker (and an embedded newline) onto it.
if "REENTRANT" in text or "\n" in text:
contaminated.append(repr(raw))
continue
match = THREAD_MSG_PATTERN.search(text)
assert match, f"Unexpected thread message format: {raw!r}"
msg_num = int(match.group(1))
expected = f"{msg_num * 12345:08X}"
if match.group(2) != expected:
contaminated.append(repr(raw))
continue
intact.add(msg_num)
assert not contaminated, (
"Buffered thread messages were clobbered by a re-entrant main-task log "
"(missing recursion guard on the buffered drain path):\n"
+ "\n".join(contaminated[:10])
)
assert len(intact) == NUM_MESSAGES, (
f"Expected {NUM_MESSAGES} intact buffered thread messages over the API, got "
f"{len(intact)}. Missing ids: {sorted(set(range(NUM_MESSAGES)) - intact)}"
)
@@ -0,0 +1,120 @@
"""Integration tests for blocking-warning source attribution.
A blocking operation that runs inside a deferred scheduler continuation (e.g. after a ``delay``
in a script) used to be reported as ``<null> took a long time for an operation (NN ms),
max is 30 ms`` because the continuation carries no component. The warning should instead name
the owning script and report the real threshold (50 ms).
"""
from __future__ import annotations
import asyncio
import re
import pytest
from .types import APIClientConnectedFactory, RunCompiledFunction
# Matches: "<source> took a long time for an operation (NN ms), max is NN ms"
WARN_PATTERN = re.compile(
r"(\S+) took a long time for an operation \((\d+) ms\), max is (\d+) ms"
)
@pytest.mark.asyncio
async def test_scheduler_blocking_warning(
yaml_config: str,
run_compiled: RunCompiledFunction,
api_client_connected: APIClientConnectedFactory,
) -> None:
"""Deferred blocking work inside a script is attributed to the script, not "<null>"."""
loop = asyncio.get_running_loop()
warning_future: asyncio.Future[str] = loop.create_future()
def check_output(line: str) -> None:
if WARN_PATTERN.search(line) and not warning_future.done():
warning_future.set_result(line)
async with (
run_compiled(yaml_config, line_callback=check_output),
api_client_connected() as client,
):
device_info = await client.device_info()
assert device_info is not None
# on_boot runs the script, which defers via delay then busy-blocks > 50 ms in the
# continuation, tripping the blocking warning.
warning_line = await asyncio.wait_for(warning_future, timeout=10.0)
# Must name the owning script, not "<null>" and not the generic fallback.
assert "<null>" not in warning_line, (
f"Warning should name the script, got: {warning_line}"
)
assert "a scheduled task" not in warning_line, (
f"Warning should name the script, got: {warning_line}"
)
match = WARN_PATTERN.search(warning_line)
assert match is not None
assert match.group(1) == "blocking_script", (
f"Warning should name 'blocking_script', got: {warning_line}"
)
# The reported threshold must be the real default (50 ms), not the stale "30 ms".
assert match.group(3) == "50", f"Expected 'max is 50 ms', got: {warning_line}"
@pytest.mark.asyncio
async def test_scheduler_blocking_warning_generic_source(
yaml_config: str,
run_compiled: RunCompiledFunction,
api_client_connected: APIClientConnectedFactory,
) -> None:
"""A delay in a plain (non-script) automation logs the generic label, not a script name."""
loop = asyncio.get_running_loop()
warning_future: asyncio.Future[str] = loop.create_future()
def check_output(line: str) -> None:
if WARN_PATTERN.search(line) and not warning_future.done():
warning_future.set_result(line)
async with (
run_compiled(yaml_config, line_callback=check_output),
api_client_connected() as client,
):
assert await client.device_info() is not None
warning_line = await asyncio.wait_for(warning_future, timeout=10.0)
assert "a scheduled task took a long time" in warning_line, (
f"Non-script deferred work should log the generic label, got: {warning_line}"
)
assert "<null>" not in warning_line
match = WARN_PATTERN.search(warning_line)
assert match is not None and match.group(3) == "50", (
f"Expected 'max is 50 ms', got: {warning_line}"
)
@pytest.mark.asyncio
async def test_scheduler_delay_runs_on_failed_component(
yaml_config: str,
run_compiled: RunCompiledFunction,
api_client_connected: APIClientConnectedFactory,
) -> None:
"""A delay must still fire even when its context component is marked failed.
Deferred (SELF_POINTER) scheduler items have no owning component, so the scheduler's
failed-component skip must not drop them.
"""
loop = asyncio.get_running_loop()
fired: asyncio.Future[bool] = loop.create_future()
def check_output(line: str) -> None:
if "DELAY_FIRED_AFTER_FAIL" in line and not fired.done():
fired.set_result(True)
async with (
run_compiled(yaml_config, line_callback=check_output),
api_client_connected() as client,
):
assert await client.device_info() is not None
# If the failed host component wrongly dropped the delay, this times out.
await asyncio.wait_for(fired, timeout=10.0)
@@ -1,169 +0,0 @@
"""String lifetime test - verify scheduler handles string destruction correctly."""
import asyncio
from pathlib import Path
import re
import pytest
from .types import APIClientConnectedFactory, RunCompiledFunction
@pytest.mark.asyncio
async def test_scheduler_string_lifetime(
yaml_config: str,
run_compiled: RunCompiledFunction,
api_client_connected: APIClientConnectedFactory,
) -> None:
"""Test that scheduler correctly handles string lifetimes when strings go out of scope."""
# Get the absolute path to the external components directory
external_components_path = str(
Path(__file__).parent / "fixtures" / "external_components"
)
# Replace the placeholder in the YAML config with the actual path
yaml_config = yaml_config.replace(
"EXTERNAL_COMPONENT_PATH", external_components_path
)
# Create events for synchronization
test1_complete = asyncio.Event()
test2_complete = asyncio.Event()
test3_complete = asyncio.Event()
test4_complete = asyncio.Event()
test5_complete = asyncio.Event()
all_tests_complete = asyncio.Event()
# Track test progress
test_stats = {
"tests_passed": 0,
"tests_failed": 0,
"errors": [],
"current_test": None,
"test_callbacks_executed": {},
}
def on_log_line(line: str) -> None:
# Track test-specific events
if "Test 1 complete" in line:
test1_complete.set()
elif "Test 2 complete" in line:
test2_complete.set()
elif "Test 3 complete" in line:
test3_complete.set()
elif "Test 4 complete" in line:
test4_complete.set()
elif "Test 5 complete" in line:
test5_complete.set()
# Track individual callback executions
callback_match = re.search(r"Callback '(.+?)' executed", line)
if callback_match:
callback_name = callback_match.group(1)
test_stats["test_callbacks_executed"][callback_name] = True
# Track test results from the C++ test output
if "Tests passed:" in line and "string_lifetime" in line:
# Extract the number from "Tests passed: 32"
match = re.search(r"Tests passed:\s*(\d+)", line)
if match:
test_stats["tests_passed"] = int(match.group(1))
elif "Tests failed:" in line and "string_lifetime" in line:
match = re.search(r"Tests failed:\s*(\d+)", line)
if match:
test_stats["tests_failed"] = int(match.group(1))
elif "ERROR" in line and "string_lifetime" in line:
test_stats["errors"].append(line)
# Check for memory corruption indicators
if any(
indicator in line.lower()
for indicator in [
"use after free",
"heap corruption",
"segfault",
"abort",
"assertion",
"sanitizer",
"bad memory",
"invalid pointer",
]
):
pytest.fail(f"Memory corruption detected: {line}")
# Check for completion
if "String lifetime tests complete" in line:
all_tests_complete.set()
async with (
run_compiled(yaml_config, line_callback=on_log_line),
api_client_connected() as client,
):
# Verify we can connect
device_info = await client.device_info()
assert device_info is not None
assert device_info.name == "scheduler-string-lifetime-test"
# List entities and services
_, services = await asyncio.wait_for(
client.list_entities_services(), timeout=5.0
)
# Find our test services
test_services = {}
for service in services:
if service.name == "run_test1":
test_services["test1"] = service
elif service.name == "run_test2":
test_services["test2"] = service
elif service.name == "run_test3":
test_services["test3"] = service
elif service.name == "run_test4":
test_services["test4"] = service
elif service.name == "run_test5":
test_services["test5"] = service
elif service.name == "run_final_check":
test_services["final"] = service
# Ensure all services are found
required_services = ["test1", "test2", "test3", "test4", "test5", "final"]
for service_name in required_services:
assert service_name in test_services, f"{service_name} service not found"
# Run tests sequentially, waiting for each to complete
try:
# Test 1
await client.execute_service(test_services["test1"], {})
await asyncio.wait_for(test1_complete.wait(), timeout=5.0)
# Test 2
await client.execute_service(test_services["test2"], {})
await asyncio.wait_for(test2_complete.wait(), timeout=5.0)
# Test 3
await client.execute_service(test_services["test3"], {})
await asyncio.wait_for(test3_complete.wait(), timeout=5.0)
# Test 4
await client.execute_service(test_services["test4"], {})
await asyncio.wait_for(test4_complete.wait(), timeout=5.0)
# Test 5
await client.execute_service(test_services["test5"], {})
await asyncio.wait_for(test5_complete.wait(), timeout=5.0)
# Final check
await client.execute_service(test_services["final"], {})
await asyncio.wait_for(all_tests_complete.wait(), timeout=5.0)
except TimeoutError:
pytest.fail(f"String lifetime test timed out. Stats: {test_stats}")
# Check for any errors
assert test_stats["tests_failed"] == 0, f"Tests failed: {test_stats['errors']}"
# Verify we had the expected number of passing tests
assert test_stats["tests_passed"] == 30, (
f"Expected exactly 30 tests to pass, but got {test_stats['tests_passed']}"
)
@@ -1,116 +0,0 @@
"""Stress test for heap scheduler with std::string names from multiple threads."""
import asyncio
from pathlib import Path
import re
from aioesphomeapi import UserService
import pytest
from .types import APIClientConnectedFactory, RunCompiledFunction
@pytest.mark.asyncio
async def test_scheduler_string_name_stress(
yaml_config: str,
run_compiled: RunCompiledFunction,
api_client_connected: APIClientConnectedFactory,
) -> None:
"""Test that set_timeout/set_interval with std::string names doesn't crash when called from multiple threads."""
# Get the absolute path to the external components directory
external_components_path = str(
Path(__file__).parent / "fixtures" / "external_components"
)
# Replace the placeholder in the YAML config with the actual path
yaml_config = yaml_config.replace(
"EXTERNAL_COMPONENT_PATH", external_components_path
)
# Create a future to signal test completion
loop = asyncio.get_running_loop()
test_complete_future: asyncio.Future[None] = loop.create_future()
# Track executed callbacks and any crashes
executed_callbacks: set[int] = set()
error_messages: list[str] = []
def on_log_line(line: str) -> None:
# Check for crash indicators
if any(
indicator in line.lower()
for indicator in [
"segfault",
"abort",
"assertion",
"heap corruption",
"use after free",
]
):
error_messages.append(line)
if not test_complete_future.done():
test_complete_future.set_exception(Exception(f"Crash detected: {line}"))
return
# Track executed callbacks
match = re.search(r"Executed string-named callback (\d+)", line)
if match:
callback_id = int(match.group(1))
executed_callbacks.add(callback_id)
# Check for completion
if (
"String name stress test complete" in line
and not test_complete_future.done()
):
test_complete_future.set_result(None)
async with (
run_compiled(yaml_config, line_callback=on_log_line),
api_client_connected() as client,
):
# Verify we can connect
device_info = await client.device_info()
assert device_info is not None
assert device_info.name == "sched-string-name-stress"
# List entities and services
_, services = await asyncio.wait_for(
client.list_entities_services(), timeout=5.0
)
# Find our test service
run_stress_test_service: UserService | None = None
for service in services:
if service.name == "run_string_name_stress_test":
run_stress_test_service = service
break
assert run_stress_test_service is not None, (
"run_string_name_stress_test service not found"
)
# Call the service to start the test
await client.execute_service(run_stress_test_service, {})
# Wait for test to complete or crash
try:
await asyncio.wait_for(test_complete_future, timeout=30.0)
except TimeoutError:
pytest.fail(
f"String name stress test timed out. Executed {len(executed_callbacks)} callbacks. "
f"This might indicate a deadlock."
)
# Verify no errors occurred (crashes already handled by exception)
assert not error_messages, f"Errors detected during test: {error_messages}"
# Verify we executed all 1000 callbacks (10 threads × 100 callbacks each)
assert len(executed_callbacks) == 1000, (
f"Expected 1000 callbacks but got {len(executed_callbacks)}"
)
# Verify each callback ID was executed exactly once
for i in range(1000):
assert i in executed_callbacks, f"Callback {i} was not executed"
@@ -99,7 +99,7 @@ async def test_scheduler_string_test(
timeout_count += 1
# Check for cancel test
elif "Cancelled timeout using different string object" in clean_line:
elif "Cancelled timeout using different buffer with same content" in clean_line:
cancel_test_done.set()
# Check for final results
@@ -0,0 +1,75 @@
"""Test that a TCP socket receive opens the component-phase gate immediately.
Regression test for the wake-request flag not being set when select() returns
due to socket data on the host platform (wake_host.cpp wakeable_delay fix).
The API server's accepted connection sockets use accept_loop_monitored(), so
they are registered with the host select() loop. A service call from the Python
client arrives on that socket. Without the fix, select() returning early did not
set g_wake_requested, so Application::loop()'s Phase B gate stayed closed until
loop_interval_ expired. With the fix, the gate opens immediately.
"""
from __future__ import annotations
import asyncio
import time
import pytest
from .types import APIClientConnectedFactory, RunCompiledFunction
@pytest.mark.asyncio
async def test_socket_wake_gate_tcp(
yaml_config: str,
run_compiled: RunCompiledFunction,
api_client_connected: APIClientConnectedFactory,
) -> None:
"""TCP socket receive must open the component-phase gate immediately,
even with loop_interval_ raised to 2000ms."""
loop = asyncio.get_running_loop()
boot_done: asyncio.Future[None] = loop.create_future()
pong: asyncio.Future[None] = loop.create_future()
def on_log_line(line: str) -> None:
if "BOOT_DONE" in line and not boot_done.done():
boot_done.set_result(None)
if "PONG" in line and not pong.done():
pong.set_result(None)
async with (
run_compiled(yaml_config, line_callback=on_log_line),
api_client_connected() as client,
):
device_info = await client.device_info()
assert device_info is not None
assert device_info.name == "socket-wake-gate-tcp"
try:
await asyncio.wait_for(boot_done, timeout=15.0)
except TimeoutError:
pytest.fail("BOOT_DONE never appeared — device did not complete boot")
_, services = await client.list_entities_services()
ping_service = next((s for s in services if s.name == "ping"), None)
assert ping_service is not None, "ping service not found"
# Execute the service and time how long until PONG appears in logs.
# The request bytes arrive on an accept_loop_monitored() TCP socket,
# which is registered with the host select() loop.
t_send = time.monotonic()
await client.execute_service(ping_service, {})
try:
await asyncio.wait_for(pong, timeout=5.0)
except TimeoutError:
pytest.fail("PONG never appeared — service did not execute")
elapsed_ms = (time.monotonic() - t_send) * 1000
# Without the fix the gate stays closed for up to loop_interval_=2000ms.
# With the fix the gate opens on the next tick; 500ms gives ample CI headroom.
assert elapsed_ms < 500, (
f"Service response took {elapsed_ms:.0f}ms with loop_interval_=2000ms — "
f"expected < 500ms; without the wake-request fix this would take up to 2000ms"
)
+10 -12
View File
@@ -127,15 +127,18 @@ async def test_uart_mock_modbus_timing(
) -> None:
"""Test modbus timing with multi-register SDM meter response."""
line_callback, error_log_lines, warning_log_lines = _make_modbus_line_callback()
tracker = SensorTracker(["sdm_voltage"])
voltage_changed = tracker.expect_any("sdm_voltage")
async with (
run_compiled(yaml_config),
run_compiled(yaml_config, line_callback=line_callback),
api_client_connected() as client,
):
await tracker.setup_and_start_scenario(client)
await tracker.await_change(voltage_changed, "sdm_voltage")
_assert_no_modbus_errors(error_log_lines, warning_log_lines)
@pytest.mark.asyncio
@@ -148,26 +151,25 @@ async def test_uart_mock_modbus_no_threshold(
Without the 50ms fallback timeout, the chunked response with a 40ms gap
between USB packets would cause a false timeout and CRC failure cascade.
Bus-level warnings (CRC failures, buffer clears) are expected during
chunked reassembly — the test only verifies the final value arrives.
Bus-level warnings (CRC/parse failures, buffer clears) are NOT expected during
chunked reassembly, if timeouts are set properly — these warnings indicate undersized timeouts.
"""
line_callback, error_log_lines, warning_log_lines = _make_modbus_line_callback()
tracker = SensorTracker(["sdm_voltage"])
voltage_changed = tracker.expect_any("sdm_voltage")
async with (
run_compiled(yaml_config),
run_compiled(yaml_config, line_callback=line_callback),
api_client_connected() as client,
):
await tracker.setup_and_start_scenario(client)
await tracker.await_change(voltage_changed, "sdm_voltage")
_assert_no_modbus_errors(error_log_lines, warning_log_lines)
@pytest.mark.asyncio
@pytest.mark.xfail(
reason="Modbus parser cannot handle server responses from other devices on the bus. Fix tracked in PR #11969.",
strict=True,
)
async def test_uart_mock_modbus_server(
yaml_config: str,
run_compiled: RunCompiledFunction,
@@ -308,10 +310,6 @@ async def test_uart_mock_modbus_server_controller_write(
@pytest.mark.asyncio
@pytest.mark.xfail(
reason="Modbus parser cannot handle server responses from other devices on the bus. Fix tracked in PR #11969.",
strict=True,
)
async def test_uart_mock_modbus_server_controller_multiple(
yaml_config: str,
run_compiled: RunCompiledFunction,