feat(coding): 补齐窗口预热执行日志

Author: mudssky

.trellis/spec/infra/coding-plan-window-warmer.md

@@ -48,6 +48,11 @@
   - Warm requests use `litellm.completion(model=plan.model, messages=[...], api_base=target.base_url, api_key=api_key, timeout=..., max_tokens=..., temperature=...)`.
   - The warmer must not call local LiteLLM Proxy `/v1/chat/completions` for default GLM warmup.
   - Health checks may use direct HTTP GET because they are a readiness probe, not the warmup completion.
+- Logging contract:
+  - Watch mode logs the next scheduled event and the due event before calling the warmer.
+  - Each real warmup logs start, container check, API key source, health check, request send, retry wait, final success/failure, and millisecond durations.
+  - Logs may include target name, model, base URL, timeout, max tokens, retry counts, and API key source (`env:<name>` or `file:<path>`).
+  - Logs must not include prompt text, API key values, request headers, or full request body.
 
 ### 4. Validation & Error Matrix
 
@@ -81,6 +86,7 @@
 - Unit tests for `interval` continuous-window rollover across midnight.
 - Unit tests for multiple plans with simultaneous base time remaining independently executable.
 - Config parse tests for multiple `[[plans]]`.
+- Logging regression test asserting real warmups log lifecycle checkpoints without exposing prompt text or API key values.
 - SDK call test mocking the local wrapper around `litellm.completion`, asserting:
   - `model` keeps the configured provider-prefixed model.
   - `api_base` is the direct target URL.

ai/coding/window-warmer/README.md

@@ -93,6 +93,8 @@ pm2 start ai/coding/window-warmer/window-warmer.pm2.config.cjs
 pm2 logs coding-window-warmer
 ```
 
+执行日志会包含调度触发、容器检查、API key 来源、健康检查、请求发送、重试、成功/失败和耗时；不会输出 prompt、API key、请求头或完整请求体。
+
 重启：
 
 ```bash

ai/coding/window-warmer/tests/test_window_warmer.py

@@ -252,6 +252,71 @@ def test_dry_run_skips_readiness_checks(self) -> None:
 
         self.assertTrue(warmer.warm_plan(config, plan, dry_run=True))
 
+    def test_warm_plan_logs_execution_lifecycle_without_secret(self) -> None:
+        """真实执行应记录关键链路日志且不泄露 prompt 与 API key。
+
+        Args:
+            None.
+
+        Returns:
+            无返回值。
+        """
+        plan = warmer.parse_plan_config(
+            {
+                "name": "glm",
+                "model": "openai/GLM-5.1",
+                "prompt": "secret prompt",
+                "schedule_mode": "fixed_times",
+                "times": ["08:00"],
+            },
+            warmer.SchedulerConfig(True, 60, 120, 1, 30, False),
+        )
+        config = warmer.AppConfig(
+            target=warmer.TargetConfig(
+                name="z-ai",
+                base_url="https://open.bigmodel.cn/api/coding/paas/v4",
+                container_name=None,
+                api_key_env="Z_AI_API_KEY",
+                env_file=None,
+                health_path="/models",
+                request_timeout_seconds=30,
+            ),
+            scheduler=warmer.SchedulerConfig(True, 60, 120, 1, 30, False),
+            plans=(plan,),
+        )
+
+        def ready_with_logs(target: warmer.TargetConfig, log_fn: warmer.target.LogFn | None = None):
+            """模拟已通过前置检查并输出检查日志。
+
+            Args:
+                target: 目标服务配置。
+                log_fn: 可选日志函数。
+
+            Returns:
+                目标可用状态、诊断消息与模拟 API key。
+            """
+            self.assertEqual(target.name, "z-ai")
+            if log_fn is not None:
+                log_fn("container check skipped")
+                log_fn("api key check passed source=file:.env.local")
+                log_fn("health check passed result=target api is ready")
+            return True, "z-ai 已就绪 api_key_source=file:.env.local", "sk-secret"
+
+        with (
+            patch("window_warmer_lib.runner.ensure_target_ready", side_effect=ready_with_logs),
+            patch("window_warmer_lib.runner.send_warm_completion"),
+            patch("window_warmer_lib.runner.log") as log_mock,
+        ):
+            self.assertTrue(warmer.warm_plan(config, plan))
+
+        messages = "\n".join(call.args[0] for call in log_mock.call_args_list)
+        self.assertIn("warm started", messages)
+        self.assertIn("api key check passed source=file:.env.local", messages)
+        self.assertIn("sending warm request", messages)
+        self.assertIn("warm succeeded", messages)
+        self.assertNotIn("sk-secret", messages)
+        self.assertNotIn("secret prompt", messages)
+
     def test_read_api_key_falls_back_to_dotenv_file(self) -> None:
         """API key 应支持从配置指定的 dotenv 文件读取。
 

ai/coding/window-warmer/window_warmer_lib/runner.py

@@ -23,28 +23,50 @@ def warm_plan(config: AppConfig, plan: PlanConfig, dry_run: bool = False) -> boo
     Returns:
         预热成功时返回 True，否则返回 False。
     """
+    started_at = time.monotonic()
+    log(f"[{plan.name}] warm started target={config.target.name} model={plan.model} schedule_mode={plan.schedule_mode}")
+
     if dry_run or config.scheduler.dry_run:
-        log(f"[{plan.name}] dry-run warm target={config.target.name} model={plan.model}")
+        log(
+            f"[{plan.name}] dry-run warm target={config.target.name} model={plan.model} "
+            f"duration_ms={elapsed_ms(started_at)}"
+        )
         return True
 
-    ready, message, api_key = ensure_target_ready(config.target)
+    ready, message, api_key = ensure_target_ready(
+        config.target,
+        log_fn=lambda readiness_message: log(f"[{plan.name}] {readiness_message}"),
+    )
     if not ready:
-        log(f"[{plan.name}] skip warm: {message}")
+        log(f"[{plan.name}] skip warm: {message} duration_ms={elapsed_ms(started_at)}")
         return False
+    log(f"[{plan.name}] readiness check passed: {message}")
 
     attempts = plan.retry_count + 1
     for attempt in range(1, attempts + 1):
+        attempt_started_at = time.monotonic()
+        log(
+            f"[{plan.name}] sending warm request target={config.target.name} model={plan.model} "
+            f"base_url={config.target.base_url} attempt={attempt}/{attempts} "
+            f"timeout={config.target.request_timeout_seconds}s max_tokens={plan.max_tokens}"
+        )
         try:
             send_warm_completion(config.target, plan, api_key)
             log(
                 f"[{plan.name}] warm succeeded target={config.target.name} "
-                f"model={plan.model} attempt={attempt}/{attempts}"
+                f"model={plan.model} attempt={attempt}/{attempts} "
+                f"duration_ms={elapsed_ms(attempt_started_at)} total_duration_ms={elapsed_ms(started_at)}"
             )
             return True
         except Exception as exc:
-            log(f"[{plan.name}] warm failed attempt={attempt}/{attempts}: {exc}")
+            log(
+                f"[{plan.name}] warm failed attempt={attempt}/{attempts} "
+                f"duration_ms={elapsed_ms(attempt_started_at)} error={exc}"
+            )
             if attempt < attempts and plan.retry_delay_seconds > 0:
+                log(f"[{plan.name}] retrying warm in {plan.retry_delay_seconds}s")
                 time.sleep(plan.retry_delay_seconds)
+    log(f"[{plan.name}] warm exhausted attempts={attempts} total_duration_ms={elapsed_ms(started_at)}")
     return False
 
 
@@ -63,9 +85,11 @@ def run_once(config: AppConfig, dry_run: bool = False) -> int:
         log("没有启用的 plan。")
         return 1
 
+    log(f"run once started enabled_plans={len(enabled_plans)}")
     success = True
     for plan in enabled_plans:
         success = warm_plan(config, plan, dry_run=dry_run) and success
+    log(f"run once finished success={str(success).lower()}")
     return 0 if success else 1
 
 
@@ -120,6 +144,10 @@ def run_watch(config: AppConfig, rng: random.Random, dry_run: bool = False) -> i
             f"run_at={event.run_at.isoformat()} jitter={event.jitter_seconds}s"
         )
         sleep_until(event.run_at)
+        log(
+            f"warm due plan={event.plan.name} base_at={event.base_at.isoformat()} "
+            f"run_at={event.run_at.isoformat()} now={datetime.now().isoformat(timespec='seconds')}"
+        )
         warm_plan(config, event.plan, dry_run=dry_run)
         events[event.plan.name] = build_warm_event(event.plan, datetime.now(), rng)
 
@@ -152,6 +180,18 @@ def interruptible_sleep(seconds: float) -> None:
     time.sleep(max(0, seconds))
 
 
+def elapsed_ms(started_at: float) -> int:
+    """计算从起点到当前的毫秒耗时。
+
+    Args:
+        started_at: `time.monotonic()` 记录的起点。
+
+    Returns:
+        非负毫秒数。
+    """
+    return max(0, round((time.monotonic() - started_at) * 1000))
+
+
 def log(message: str) -> None:
     """输出带本地时间戳的日志。
 

ai/coding/window-warmer/window_warmer_lib/target.py

@@ -7,13 +7,16 @@
 import subprocess
 import urllib.error
 import urllib.request
+from collections.abc import Callable
 from pathlib import Path
 from typing import Any
 
 from dotenv import dotenv_values
 
 from .models import PlanConfig, TargetConfig
 
+LogFn = Callable[[str], None]
+
 
 def read_env_file(path: Path | None) -> dict[str, str]:
     """读取 dotenv 环境变量文件。
@@ -47,6 +50,29 @@ def read_api_key(config: TargetConfig) -> str | None:
     return read_env_file(config.env_file).get(config.api_key_env)
 
 
+def read_api_key_with_source(config: TargetConfig) -> tuple[str | None, str]:
+    """读取目标服务 API key 及其来源。
+
+    Args:
+        config: 目标服务连接配置。
+
+    Returns:
+        `(API key, 来源描述)`；未配置或未找到时 API key 为 None。
+    """
+    if config.api_key_env is None:
+        return None, "disabled"
+
+    env_value = os.getenv(config.api_key_env)
+    if env_value:
+        return env_value, f"env:{config.api_key_env}"
+
+    env_values = read_env_file(config.env_file)
+    file_value = env_values.get(config.api_key_env)
+    if file_value:
+        return file_value, f"file:{format_path(config.env_file)}"
+    return None, "missing"
+
+
 def is_container_running(container_name: str) -> tuple[bool, str]:
     """检查 Docker 容器是否处于 running 状态。
 
@@ -199,25 +225,65 @@ def call_litellm_completion(**kwargs: Any) -> None:
     completion(**kwargs)
 
 
-def ensure_target_ready(config: TargetConfig) -> tuple[bool, str, str | None]:
+def ensure_target_ready(config: TargetConfig, log_fn: LogFn | None = None) -> tuple[bool, str, str | None]:
     """确认目标前置条件与 API 均可用。
 
     Args:
         config: 目标服务连接配置。
+        log_fn: 可选日志函数，用于输出检查链路。
 
     Returns:
         `(是否可用, 诊断信息, API key)`。
     """
     if config.container_name is not None:
+        emit(log_fn, f"container check started container={config.container_name}")
         container_running, container_message = is_container_running(config.container_name)
         if not container_running:
+            emit(log_fn, f"container check failed container={config.container_name} reason={container_message}")
             return False, f"容器 {config.container_name} 未就绪: {container_message}", None
+        emit(log_fn, f"container check passed container={config.container_name}")
+    else:
+        emit(log_fn, "container check skipped")
 
-    api_key = read_api_key(config)
+    api_key, api_key_source = read_api_key_with_source(config)
     if config.api_key_env is not None and api_key is None:
+        emit(log_fn, f"api key check failed source={api_key_source} env={config.api_key_env}")
         return False, f"未找到 {config.api_key_env}", None
+    emit(log_fn, f"api key check passed source={api_key_source}")
 
+    if config.health_path is not None:
+        emit(log_fn, f"health check started url={join_url(config.base_url, config.health_path)}")
     api_ready, api_message = is_target_api_ready(config, api_key)
     if not api_ready:
+        emit(log_fn, f"health check failed reason={api_message}")
         return False, f"{config.name} API 未就绪: {api_message}", api_key
-    return True, f"{config.name} 已就绪", api_key
+    emit(log_fn, f"health check passed result={api_message}")
+    return True, f"{config.name} 已就绪 api_key_source={api_key_source}", api_key
+
+
+def emit(log_fn: LogFn | None, message: str) -> None:
+    """按需输出目标检查日志。
+
+    Args:
+        log_fn: 可选日志函数。
+        message: 日志消息。
+
+    Returns:
+        无返回值。
+    """
+    if log_fn is not None:
+        log_fn(message)
+
+
+def format_path(path: Path | None) -> str:
+    """格式化日志中的路径值。
+
+    Args:
+        path: 可选路径。
+
+    Returns:
+        适合日志展示的路径文本。
+    """
+    if path is None:
+        return "none"
+    return str(path)