chore: log event loop watchdog startup at info

astrbot/core/core_lifecycle.py

@@ -35,6 +35,9 @@ from astrbot.core.star.star_manager import PluginManager
 from astrbot.core.subagent_orchestrator import SubAgentOrchestrator
 from astrbot.core.umop_config_router import UmopConfigRouter
 from astrbot.core.updator import AstrBotUpdator
+from astrbot.core.utils.event_loop_diagnostics import (
+    create_event_loop_diagnostic_tasks,
+)
 from astrbot.core.utils.llm_metadata import update_llm_metadata
 from astrbot.core.utils.migra_helper import migra
 from astrbot.core.utils.temp_dir_cleaner import TempDirCleaner
@@ -296,13 +299,18 @@ class AstrBotCoreLifecycle:
                 self.temp_dir_cleaner.run(),
                 name="temp_dir_cleaner",
             )
+        diagnostic_tasks = create_event_loop_diagnostic_tasks()
 
         # 把插件中注册的所有协程函数注册到事件总线中并执行
         extra_tasks = []
         for task in self.star_context._register_tasks:
             extra_tasks.append(asyncio.create_task(task, name=task.__name__))  # type: ignore
 
-        tasks_ = [event_bus_task, *(extra_tasks if extra_tasks else [])]
+        tasks_ = [
+            event_bus_task,
+            *diagnostic_tasks,
+            *(extra_tasks if extra_tasks else []),
+        ]
         if cron_task:
             tasks_.append(cron_task)
         if temp_dir_cleaner_task:

astrbot/core/utils/event_loop_diagnostics.py

@@ -0,0 +1,216 @@
+import asyncio
+import faulthandler
+from dataclasses import dataclass
+from pathlib import Path
+from typing import TextIO
+
+from astrbot import logger
+from astrbot.core.utils.astrbot_path import get_astrbot_data_path
+
+DEFAULT_LAG_MONITOR_ENABLED = True
+DEFAULT_LAG_MONITOR_INTERVAL = 5.0
+DEFAULT_LAG_MONITOR_THRESHOLD = 15.0
+DEFAULT_WATCHDOG_ENABLED = True
+DEFAULT_WATCHDOG_INTERVAL = 5.0
+DEFAULT_WATCHDOG_TIMEOUT = 30.0
+DEFAULT_WATCHDOG_LOG_RELATIVE_PATH = Path("logs") / "event_loop_watchdog.log"
+DEFAULT_WATCHDOG_LOG_MAX_BYTES = 1024 * 1024
+
+
+@dataclass(frozen=True)
+class EventLoopDiagnosticSettings:
+    """Settings for event loop lag and blockage diagnostics.
+
+    Args:
+        lag_monitor_enabled: Whether to log event loop scheduling lag.
+        lag_monitor_interval: Seconds between lag monitor wakeups.
+        lag_monitor_threshold: Minimum lag seconds before logging a warning.
+        watchdog_enabled: Whether to arm the faulthandler watchdog.
+        watchdog_interval: Seconds between faulthandler watchdog refreshes.
+        watchdog_timeout: Seconds without event loop progress before dumping stacks.
+        watchdog_log_path: File that receives faulthandler watchdog output.
+        watchdog_log_max_bytes: Maximum watchdog log bytes before rotation.
+    """
+
+    lag_monitor_enabled: bool
+    lag_monitor_interval: float
+    lag_monitor_threshold: float
+    watchdog_enabled: bool
+    watchdog_interval: float
+    watchdog_timeout: float
+    watchdog_log_path: Path
+    watchdog_log_max_bytes: int
+
+
+def _watchdog_log_path() -> Path:
+    """Resolve the watchdog stack dump log path.
+
+    Returns:
+        Absolute path for watchdog stack dump output.
+    """
+    return Path(get_astrbot_data_path()) / DEFAULT_WATCHDOG_LOG_RELATIVE_PATH
+
+
+def load_event_loop_diagnostic_settings() -> EventLoopDiagnosticSettings:
+    """Load fixed event loop diagnostic settings.
+
+    Returns:
+        Event loop diagnostic settings.
+    """
+    return EventLoopDiagnosticSettings(
+        lag_monitor_enabled=DEFAULT_LAG_MONITOR_ENABLED,
+        lag_monitor_interval=DEFAULT_LAG_MONITOR_INTERVAL,
+        lag_monitor_threshold=DEFAULT_LAG_MONITOR_THRESHOLD,
+        watchdog_enabled=DEFAULT_WATCHDOG_ENABLED,
+        watchdog_interval=DEFAULT_WATCHDOG_INTERVAL,
+        watchdog_timeout=DEFAULT_WATCHDOG_TIMEOUT,
+        watchdog_log_path=_watchdog_log_path(),
+        watchdog_log_max_bytes=DEFAULT_WATCHDOG_LOG_MAX_BYTES,
+    )
+
+
+async def monitor_event_loop_lag(
+    *,
+    interval: float = DEFAULT_LAG_MONITOR_INTERVAL,
+    warn_after: float = DEFAULT_LAG_MONITOR_THRESHOLD,
+) -> None:
+    """Log a warning when the event loop wakes significantly later than expected.
+
+    Args:
+        interval: Seconds between monitor wakeups.
+        warn_after: Minimum lag seconds before logging a warning.
+    """
+    loop = asyncio.get_running_loop()
+    expected = loop.time() + interval
+    while True:
+        await asyncio.sleep(interval)
+        now = loop.time()
+        lag = now - expected
+        if lag > warn_after:
+            logger.warning(
+                "Event loop lag detected: %.3fs (threshold %.3fs).",
+                lag,
+                warn_after,
+            )
+        expected = now + interval
+
+
+def _rotate_watchdog_log_file(log_path: Path, max_bytes: int) -> None:
+    """Rotate the watchdog log when it reaches the configured size limit.
+
+    Args:
+        log_path: Current watchdog log path.
+        max_bytes: Maximum current log size before rotation.
+    """
+    try:
+        if not log_path.exists() or log_path.stat().st_size < max_bytes:
+            return
+        rotated_path = log_path.with_name(f"{log_path.name}.1")
+        if rotated_path.exists():
+            rotated_path.unlink()
+        log_path.replace(rotated_path)
+    except OSError as e:
+        logger.warning("Failed to rotate event loop watchdog log %s: %s", log_path, e)
+
+
+def _open_watchdog_log_file(log_path: Path, max_bytes: int) -> TextIO:
+    """Open the watchdog log file after applying size-based rotation.
+
+    Args:
+        log_path: Current watchdog log path.
+        max_bytes: Maximum current log size before rotation.
+
+    Returns:
+        Writable text file object for faulthandler output.
+    """
+    log_path.parent.mkdir(parents=True, exist_ok=True)
+    _rotate_watchdog_log_file(log_path, max_bytes)
+    return log_path.open("a", encoding="utf-8")
+
+
+async def faulthandler_event_loop_watchdog(
+    *,
+    timeout: float = DEFAULT_WATCHDOG_TIMEOUT,
+    interval: float = DEFAULT_WATCHDOG_INTERVAL,
+    dump_file: TextIO | None = None,
+    dump_path: Path | None = None,
+    max_bytes: int = DEFAULT_WATCHDOG_LOG_MAX_BYTES,
+) -> None:
+    """Dump all thread stacks if the event loop is blocked for too long.
+
+    Args:
+        timeout: Seconds without watchdog refresh before faulthandler dumps stacks.
+        interval: Seconds between watchdog refreshes while the event loop is healthy.
+        dump_file: File object that receives faulthandler output.
+        dump_path: Path that receives faulthandler output when dump_file is unset.
+        max_bytes: Maximum current log size before rotation.
+    """
+    log_path = dump_path or _watchdog_log_path()
+    try:
+        while True:
+            faulthandler.cancel_dump_traceback_later()
+            output: TextIO | None = None
+            should_close = False
+            try:
+                output = dump_file or _open_watchdog_log_file(log_path, max_bytes)
+                should_close = dump_file is None
+                faulthandler.dump_traceback_later(
+                    timeout,
+                    repeat=False,
+                    file=output,
+                )
+                await asyncio.sleep(interval)
+            except Exception as e:
+                logger.warning("Event loop faulthandler watchdog failed: %s", e)
+                await asyncio.sleep(interval)
+            finally:
+                faulthandler.cancel_dump_traceback_later()
+                if should_close and output is not None:
+                    output.close()
+    finally:
+        faulthandler.cancel_dump_traceback_later()
+
+
+def create_event_loop_diagnostic_tasks() -> list[asyncio.Task]:
+    """Create enabled event loop diagnostic tasks for the current loop.
+
+    Returns:
+        A list of created asyncio tasks.
+    """
+    settings = load_event_loop_diagnostic_settings()
+    tasks: list[asyncio.Task] = []
+
+    if settings.lag_monitor_enabled:
+        tasks.append(
+            asyncio.create_task(
+                monitor_event_loop_lag(
+                    interval=settings.lag_monitor_interval,
+                    warn_after=settings.lag_monitor_threshold,
+                ),
+                name="event_loop_lag_monitor",
+            )
+        )
+
+    if settings.watchdog_enabled:
+        logger.info(
+            "Event loop faulthandler watchdog enabled: timeout=%.3fs interval=%.3fs. "
+            "If the loop is blocked, Python thread stacks will be written to %s "
+            "(rotates at %d bytes).",
+            settings.watchdog_timeout,
+            settings.watchdog_interval,
+            settings.watchdog_log_path,
+            settings.watchdog_log_max_bytes,
+        )
+        tasks.append(
+            asyncio.create_task(
+                faulthandler_event_loop_watchdog(
+                    timeout=settings.watchdog_timeout,
+                    interval=settings.watchdog_interval,
+                    dump_path=settings.watchdog_log_path,
+                    max_bytes=settings.watchdog_log_max_bytes,
+                ),
+                name="event_loop_faulthandler_watchdog",
+            )
+        )
+
+    return tasks

tests/unit/test_event_loop_diagnostics.py

@@ -0,0 +1,134 @@
+import asyncio
+
+import pytest
+
+from astrbot.core.utils import event_loop_diagnostics as diagnostics
+
+
+def test_load_event_loop_diagnostic_settings_defaults():
+    """Default settings enable lag monitoring and stack dump watchdog."""
+    settings = diagnostics.load_event_loop_diagnostic_settings()
+
+    assert settings.lag_monitor_enabled is True
+    assert settings.lag_monitor_interval == diagnostics.DEFAULT_LAG_MONITOR_INTERVAL
+    assert settings.lag_monitor_threshold == diagnostics.DEFAULT_LAG_MONITOR_THRESHOLD
+    assert settings.watchdog_enabled is True
+    assert settings.watchdog_interval == diagnostics.DEFAULT_WATCHDOG_INTERVAL
+    assert settings.watchdog_timeout == diagnostics.DEFAULT_WATCHDOG_TIMEOUT
+    assert settings.watchdog_log_max_bytes == diagnostics.DEFAULT_WATCHDOG_LOG_MAX_BYTES
+
+
+@pytest.mark.asyncio
+async def test_create_event_loop_diagnostic_tasks_defaults():
+    """Default diagnostics should create both event loop diagnostic tasks."""
+    tasks = diagnostics.create_event_loop_diagnostic_tasks()
+
+    try:
+        assert [task.get_name() for task in tasks] == [
+            "event_loop_lag_monitor",
+            "event_loop_faulthandler_watchdog",
+        ]
+    finally:
+        for task in tasks:
+            task.cancel()
+        await asyncio.gather(*tasks, return_exceptions=True)
+
+
+@pytest.mark.asyncio
+async def test_faulthandler_watchdog_cancels_pending_dump(monkeypatch):
+    """The faulthandler watchdog should cancel its pending dump on shutdown."""
+    calls = []
+
+    class FakeFaultHandler:
+        def cancel_dump_traceback_later(self):
+            calls.append("cancel")
+
+        def dump_traceback_later(self, timeout, repeat, file):
+            calls.append(("dump", timeout, repeat, file))
+
+    fake_faulthandler = FakeFaultHandler()
+    monkeypatch.setattr(diagnostics, "faulthandler", fake_faulthandler)
+
+    task = asyncio.create_task(
+        diagnostics.faulthandler_event_loop_watchdog(timeout=10, interval=1)
+    )
+    await asyncio.sleep(0)
+    task.cancel()
+    await asyncio.gather(task, return_exceptions=True)
+
+    assert any(isinstance(call, tuple) and call[0] == "dump" for call in calls)
+    assert calls[-1] == "cancel"
+
+
+@pytest.mark.asyncio
+async def test_faulthandler_watchdog_writes_rotating_log(tmp_path, monkeypatch):
+    """The faulthandler watchdog should write to and rotate its log file."""
+    log_path = tmp_path / "logs" / "event_loop_watchdog.log"
+    log_path.parent.mkdir()
+    log_path.write_text("x" * 8, encoding="utf-8")
+    calls = []
+
+    class FakeFaultHandler:
+        def cancel_dump_traceback_later(self):
+            calls.append("cancel")
+
+        def dump_traceback_later(self, timeout, repeat, file):
+            calls.append(("dump", timeout, repeat, file.name))
+            file.write("watchdog dump\n")
+            file.flush()
+
+    fake_faulthandler = FakeFaultHandler()
+    monkeypatch.setattr(diagnostics, "faulthandler", fake_faulthandler)
+
+    task = asyncio.create_task(
+        diagnostics.faulthandler_event_loop_watchdog(
+            timeout=10,
+            interval=1,
+            dump_path=log_path,
+            max_bytes=4,
+        )
+    )
+    await asyncio.sleep(0)
+    task.cancel()
+    await asyncio.gather(task, return_exceptions=True)
+
+    assert log_path.read_text(encoding="utf-8") == "watchdog dump\n"
+    assert log_path.with_name("event_loop_watchdog.log.1").read_text(
+        encoding="utf-8"
+    ) == "x" * 8
+    assert any(isinstance(call, tuple) and call[0] == "dump" for call in calls)
+
+
+@pytest.mark.asyncio
+async def test_faulthandler_watchdog_survives_dump_failure(tmp_path, monkeypatch):
+    """The watchdog should keep running after faulthandler arm failures."""
+    log_path = tmp_path / "event_loop_watchdog.log"
+    armed_again = asyncio.Event()
+    calls = []
+
+    class FakeFaultHandler:
+        def cancel_dump_traceback_later(self):
+            calls.append("cancel")
+
+        def dump_traceback_later(self, timeout, repeat, file):
+            calls.append(("dump", timeout, repeat, file.name))
+            if len([call for call in calls if isinstance(call, tuple)]) == 1:
+                raise RuntimeError("boom")
+            armed_again.set()
+
+    fake_faulthandler = FakeFaultHandler()
+    monkeypatch.setattr(diagnostics, "faulthandler", fake_faulthandler)
+
+    task = asyncio.create_task(
+        diagnostics.faulthandler_event_loop_watchdog(
+            timeout=10,
+            interval=0.01,
+            dump_path=log_path,
+        )
+    )
+    await asyncio.wait_for(armed_again.wait(), timeout=1)
+    task.cancel()
+    await asyncio.gather(task, return_exceptions=True)
+
+    dump_calls = [call for call in calls if isinstance(call, tuple)]
+    assert len(dump_calls) >= 2