[core][scheduler] Log a new interval before taking the scheduler lock (#21721)

esphome/core/scheduler.cpp

@@ -137,6 +137,7 @@ void HOT Scheduler::set_timer_common_(Component *component, SchedulerItem::Type
     delay = 1;
   }
 
+  uint32_t offset = 0;
   // Take lock early to protect scheduler_item_pool_head_ access
   {
     LockGuard guard{this->lock_};
@@ -181,13 +182,8 @@ void HOT Scheduler::set_timer_common_(Component *component, SchedulerItem::Type
       if (type == SchedulerItem::INTERVAL) {
         item->interval = delay;
         // first execution happens immediately after a random smallish offset
-        uint32_t offset = this->calculate_interval_offset_(delay);
+        offset = this->calculate_interval_offset_(delay);
         item->set_next_execution(now_64 + offset);
-#ifdef ESPHOME_LOG_HAS_VERBOSE
-        SchedulerNameLog name_log;
-        ESP_LOGV(TAG, "Scheduler interval for %s is %" PRIu32 "ms, offset %" PRIu32 "ms",
-                 name_log.format(name_type, static_name, hash_or_id), delay, offset);
-#endif
       } else {
         item->interval = 0;
         item->set_next_execution(now_64 + delay);
@@ -213,6 +209,14 @@ void HOT Scheduler::set_timer_common_(Component *component, SchedulerItem::Type
     }
 #endif
   }
+#ifdef ESPHOME_LOG_HAS_VERBOSE
+  // Logged after releasing the lock: a logger on_message automation can call back into the scheduler.
+  if (type == SchedulerItem::INTERVAL) {
+    SchedulerNameLog name_log;
+    ESP_LOGV(TAG, "Scheduler interval for %s is %" PRIu32 "ms, offset %" PRIu32 "ms",
+             name_log.format(name_type, static_name, hash_or_id), delay, offset);
+  }
+#endif
   // A background insertion may shorten a sleep whose deadline was already computed.
   if (!is_main_loop_thread()) [[unlikely]]
     wake_scheduler_threadsafe();

tests/integration/fixtures/scheduler_verbose_log_on_message.yaml

@@ -0,0 +1,27 @@
+esphome:
+  name: sched-verbose-log
+
+host:
+api:
+logger:
+  level: VERBOSE
+  on_message:
+    # The scheduler logs each new interval at VERBOSE. This automation then
+    # calls back into the scheduler (the delay is a scheduler timeout).
+    level: VERBOSE
+    then:
+      - delay: 1ms
+
+globals:
+  - id: fire_count
+    type: int
+    initial_value: "0"
+
+interval:
+  - interval: 50ms
+    then:
+      - lambda: |-
+          id(fire_count) += 1;
+          if (id(fire_count) == 5) {
+            ESP_LOGI("test", "INTERVAL_5_FIRES_REACHED");
+          }

tests/integration/test_scheduler_verbose_log_on_message.py

@@ -0,0 +1,34 @@
+"""Test that a logger on_message automation can use the scheduler from a scheduler log.
+
+Regression test for a self-deadlock: Scheduler::set_timer_common_ logged a new
+interval at VERBOSE while holding the scheduler lock. The logger calls on_message
+listeners on the same thread, and an automation with a delay adds a scheduler
+timeout, which took the same non-recursive lock again. The first set_interval()
+in setup() hung the main loop.
+"""
+
+from __future__ import annotations
+
+import pytest
+
+from .log_utils import LineWaiter
+from .state_utils import assert_device_name
+from .types import APIClientConnectedFactory, RunCompiledFunction
+
+
+@pytest.mark.asyncio
+async def test_scheduler_verbose_log_on_message(
+    yaml_config: str,
+    run_compiled: RunCompiledFunction,
+    api_client_connected: APIClientConnectedFactory,
+) -> None:
+    """The main loop keeps running when on_message reacts to a scheduler log."""
+    waiter = LineWaiter()
+
+    async with (
+        run_compiled(yaml_config, line_callback=waiter.callback),
+        api_client_connected() as client,
+    ):
+        await assert_device_name(client, "sched-verbose-log")
+        await waiter.wait_for("Scheduler interval for", timeout=5.0)
+        await waiter.wait_for("INTERVAL_5_FIRES_REACHED", timeout=5.0)