fix: sync unified logging probe before file handler attach

Co-authored-by: Cursor <cursoragent@cursor.com>

scripts/jiangchang_skill_core/rpa/video_session.py

@@ -1,7 +1,4 @@
-"""RPA 运行录屏会话：ffmpeg 桌面录制 → 字幕 + 背景音乐 → 最终 MP4。
-
-Playwright 仅用于浏览器自动化，不负责录屏。
-"""
+"""RPA 运行录屏会话：ffmpeg 桌面录制 → 字幕 + 背景音乐 → 最终 MP4。"""
 
 from __future__ import annotations
 
@@ -15,7 +12,7 @@ import time
 from dataclasses import dataclass
 from datetime import datetime
 from pathlib import Path
-from typing import Any, Dict, List, Optional
+from typing import Any, Dict, IO, List, Optional
 
 from .. import config
 
@@ -222,8 +219,6 @@ class RpaVideoSession:
         self.warnings: List[str] = []
         self.output_video_path: Optional[str] = None
         self.capture_path: Optional[str] = None
-        # 已废弃：勿用于 Playwright；始终为 None。
-        self.record_video_dir: Optional[str] = None
         self.artifacts: Dict[str, Any] = {}
 
         ts = datetime.now().strftime("%Y%m%d_%H%M%S")
@@ -236,6 +231,7 @@ class RpaVideoSession:
         )
         self._subtitles_dir = os.path.join(self._artifact_root, "subtitles")
         self._logs_dir = os.path.join(self._artifact_root, "logs")
+        self._ffmpeg_record_log_path = os.path.join(self._logs_dir, "ffmpeg-record.log")
         self._capture_path = os.path.join(self._artifact_root, "capture.mp4")
         self._srt_path = os.path.join(self._subtitles_dir, f"{self._video_stem}.srt")
         self._planned_output = os.path.join(self._videos_dir, f"{self._video_stem}.mp4")
@@ -243,6 +239,7 @@ class RpaVideoSession:
         self._steps: List[_StepEntry] = []
         self._t0: Optional[float] = None
         self._ffmpeg_proc: Optional[subprocess.Popen] = None
+        self._ffmpeg_record_log_file: Optional[IO[str]] = None
 
         if self.enabled:
             os.makedirs(self._videos_dir, exist_ok=True)
@@ -250,6 +247,21 @@ class RpaVideoSession:
             os.makedirs(self._logs_dir, exist_ok=True)
             os.makedirs(self._artifact_root, exist_ok=True)
 
+    def _record_log_hint(self) -> str:
+        if self.enabled and self._ffmpeg_record_log_path:
+            return f"; record_log={self._ffmpeg_record_log_path}"
+        return ""
+
+    def _append_warning(self, code: str, detail: str = "") -> None:
+        msg = code if not detail else f"{code}: {detail}"
+        if code in (
+            "ffmpeg_record_start_failed",
+            "ffmpeg_capture_missing",
+            "ffmpeg_compose_failed",
+        ):
+            msg += self._record_log_hint()
+        self.warnings.append(msg)
+
     def step(self, text: str, *, duration: float = 4.0) -> None:
         self.add_step(text, duration=duration)
 
@@ -262,6 +274,16 @@ class RpaVideoSession:
         elapsed = time.monotonic() - self._t0
         self._steps.append(_StepEntry(start=elapsed, text=text.strip(), duration=duration))
 
+    def _close_ffmpeg_record_log(self) -> None:
+        fh = self._ffmpeg_record_log_file
+        self._ffmpeg_record_log_file = None
+        if fh is None:
+            return
+        try:
+            fh.close()
+        except Exception:
+            pass
+
     def _start_ffmpeg_capture(self) -> None:
         if not self.enabled:
             return
@@ -271,26 +293,39 @@ class RpaVideoSession:
 
         cmd = _build_desktop_record_cmd(self._capture_path)
         if cmd is None:
-            self.warnings.append(
-                "ffmpeg_record_start_failed: desktop capture only supported on Windows"
+            self._append_warning(
+                "ffmpeg_record_start_failed",
+                "desktop capture only supported on Windows",
             )
             return
 
+        stderr_target: Any = subprocess.DEVNULL
+        try:
+            os.makedirs(self._logs_dir, exist_ok=True)
+            self._ffmpeg_record_log_file = open(
+                self._ffmpeg_record_log_path, "a", encoding="utf-8"
+            )
+            stderr_target = self._ffmpeg_record_log_file
+        except Exception as exc:
+            self.warnings.append(f"ffmpeg_record_log_open_failed: {exc}")
+
         try:
             self._ffmpeg_proc = subprocess.Popen(
                 cmd,
                 stdin=subprocess.PIPE,
                 stdout=subprocess.DEVNULL,
-                stderr=subprocess.DEVNULL,
+                stderr=stderr_target,
             )
             self.capture_path = self._capture_path
         except Exception as exc:
-            self.warnings.append(f"ffmpeg_record_start_failed: {exc}")
+            self._append_warning("ffmpeg_record_start_failed", str(exc))
             self._ffmpeg_proc = None
+            self._close_ffmpeg_record_log()
 
     def _stop_ffmpeg_capture(self) -> None:
         proc = self._ffmpeg_proc
         if proc is None:
+            self._close_ffmpeg_record_log()
             return
         if proc.poll() is None:
             try:
@@ -314,8 +349,8 @@ class RpaVideoSession:
                 except Exception:
                     pass
         self._ffmpeg_proc = None
-        await_sleep = 0.3
-        time.sleep(await_sleep)
+        self._close_ffmpeg_record_log()
+        time.sleep(0.3)
 
     async def __aenter__(self) -> "RpaVideoSession":
         if self.enabled:
@@ -342,7 +377,7 @@ class RpaVideoSession:
         try:
             capture = Path(self._capture_path)
             if not capture.is_file() or capture.stat().st_size <= 0:
-                self.warnings.append("ffmpeg_capture_missing")
+                self._append_warning("ffmpeg_capture_missing")
                 self.artifacts = self.summary()
                 return
 
@@ -396,7 +431,7 @@ class RpaVideoSession:
                     ]
                 )
             if not ok:
-                self.warnings.append(f"ffmpeg_compose_failed: {err}")
+                self._append_warning("ffmpeg_compose_failed", err)
                 self.artifacts = self.summary()
                 return
 
@@ -407,10 +442,16 @@ class RpaVideoSession:
         self.artifacts = self.summary()
 
     def summary(self) -> Dict[str, Any]:
+        record_log = (
+            os.path.abspath(self._ffmpeg_record_log_path)
+            if self.enabled and self._ffmpeg_record_log_path
+            else None
+        )
         return {
             "enabled": self.enabled,
             "path": self.output_video_path,
             "capture_path": self.capture_path,
+            "record_log_path": record_log,
             "warnings": list(self.warnings),
         }
 

scripts/jiangchang_skill_core/unified_logging.py

@@ -1,5 +1,5 @@
 """
-统一文件日志：{DATA_ROOT}/{USER_ID}/logs/jiangchang.log
+统一文件日志：{JIANGCHANG_DATA_ROOT}/{JIANGCHANG_USER_ID}/logs/jiangchang.log
 按日轮转；行内带 trace_id 与 skill_slug，便于跨技能排查。
 """
 
@@ -10,31 +10,55 @@ import os
 import sys
 import uuid
 from logging.handlers import TimedRotatingFileHandler
-from typing import Optional
+from typing import Optional, Tuple
 
 from .runtime_env import get_data_root, get_user_id
 
 _skill_slug: str = ""
 _logger_name: str = ""
 
+# 避免 logging 内部错误再向 stderr 打印 "--- Logging error ---"
+logging.raiseExceptions = False
+
 
 def get_unified_logs_dir() -> str:
     path = os.path.join(get_data_root(), get_user_id(), "logs")
-    os.makedirs(path, exist_ok=True)
+    try:
+        os.makedirs(path, exist_ok=True)
+    except OSError:
+        pass
     return path
 
 
 def get_skill_log_file_path() -> str:
+    """与 setup 写入的主日志文件一致（供终端提示等）。"""
     override = (os.getenv("JIANGCHANG_LOG_FILE") or "").strip()
     if override:
         parent = os.path.dirname(os.path.abspath(override))
         if parent:
-            os.makedirs(parent, exist_ok=True)
+            try:
+                os.makedirs(parent, exist_ok=True)
+            except OSError:
+                pass
         return os.path.abspath(override)
     return os.path.join(get_unified_logs_dir(), "jiangchang.log")
 
 
+def _can_open_log_file(log_path: str) -> Tuple[bool, str]:
+    """探测日志文件是否可追加写入（真实 open，非 os.access）。"""
+    try:
+        parent = os.path.dirname(os.path.abspath(log_path))
+        if parent:
+            os.makedirs(parent, exist_ok=True)
+        with open(log_path, "a", encoding="utf-8"):
+            pass
+        return True, ""
+    except Exception as exc:
+        return False, str(exc)
+
+
 def ensure_trace_for_process() -> str:
+    """本进程调用链 ID：沿用 JIANGCHANG_TRACE_ID，否则生成并写入环境（子进程可继承）。"""
     existing = (os.getenv("JIANGCHANG_TRACE_ID") or "").strip()
     if existing:
         return existing
@@ -44,8 +68,11 @@ def ensure_trace_for_process() -> str:
 
 
 def subprocess_env_with_trace(environ: Optional[dict] = None) -> dict:
+    """subprocess.run(..., env=...) 时使用，保证带上当前 trace。"""
     ensure_trace_for_process()
-    tid = (os.getenv("JIANGCHANG_TRACE_ID") or "").strip() or ensure_trace_for_process()
+    tid = (os.getenv("JIANGCHANG_TRACE_ID") or "").strip()
+    if not tid:
+        tid = ensure_trace_for_process()
     base = os.environ if environ is None else environ
     return {**base, "JIANGCHANG_TRACE_ID": tid}
 
@@ -57,7 +84,9 @@ class _SkillContextFilter(logging.Filter):
         return True
 
 
-_FORMAT = "%(asctime)s | %(levelname)-8s | %(trace_id)s | %(skill_slug)s | %(name)s | %(message)s"
+_FORMAT = (
+    "%(asctime)s | %(levelname)-8s | %(trace_id)s | %(skill_slug)s | %(name)s | %(message)s"
+)
 _DATEFMT = "%Y-%m-%dT%H:%M:%S"
 
 
@@ -74,35 +103,72 @@ def _backup_count() -> int:
         return 30
 
 
+def _clear_logger_handlers(log: logging.Logger) -> None:
+    for h in list(log.handlers):
+        log.removeHandler(h)
+        try:
+            h.close()
+        except Exception:
+            pass
+
+
+def _attach_fallback_handler(log: logging.Logger) -> None:
+    """文件日志不可用时仅挂 NullHandler，不向 stderr 打印 logging 异常。"""
+    log.addHandler(logging.NullHandler())
+
+
 def setup_skill_logging(skill_slug: str, logger_name: str) -> None:
+    """
+    幂等：为指定 logger 挂载统一文件日志与可选 stderr。
+    须在进程早期调用（如 CLI main 在业务日志之前）。
+    文件日志不可写时降级为 NullHandler，不影响 CLI 返回码。
+    """
     global _skill_slug, _logger_name
+    logging.raiseExceptions = False
     ensure_trace_for_process()
     _skill_slug = skill_slug
     _logger_name = logger_name
 
     log = logging.getLogger(logger_name)
-    if log.handlers:
-        return
+    _clear_logger_handlers(log)
     log.setLevel(_log_level_from_env())
-    path = get_skill_log_file_path()
-    fh = TimedRotatingFileHandler(
-        path,
-        when="midnight",
-        interval=1,
-        backupCount=_backup_count(),
-        encoding="utf-8",
-        delay=True,
-    )
     fmt = logging.Formatter(_FORMAT, datefmt=_DATEFMT)
-    fh.setFormatter(fmt)
-    fh.addFilter(_SkillContextFilter())
-    log.addHandler(fh)
-    if (os.getenv("JIANGCHANG_LOG_TO_STDERR") or "").strip().lower() in ("1", "true", "yes", "on"):
-        sh = logging.StreamHandler(sys.stderr)
-        sh.setLevel(logging.WARNING)
-        sh.setFormatter(fmt)
-        sh.addFilter(_SkillContextFilter())
-        log.addHandler(sh)
+    filt = _SkillContextFilter()
+
+    log_path = get_skill_log_file_path()
+    ok, _err = _can_open_log_file(log_path)
+    if ok:
+        try:
+            fh = TimedRotatingFileHandler(
+                log_path,
+                when="midnight",
+                interval=1,
+                backupCount=_backup_count(),
+                encoding="utf-8",
+                delay=False,
+            )
+            fh.setFormatter(fmt)
+            fh.addFilter(filt)
+            log.addHandler(fh)
+        except Exception:
+            _attach_fallback_handler(log)
+    else:
+        _attach_fallback_handler(log)
+
+    if (os.getenv("JIANGCHANG_LOG_TO_STDERR") or "").strip().lower() in (
+        "1",
+        "true",
+        "yes",
+        "on",
+    ):
+        try:
+            sh = logging.StreamHandler(sys.stderr)
+            sh.setLevel(logging.WARNING)
+            sh.setFormatter(fmt)
+            sh.addFilter(filt)
+            log.addHandler(sh)
+        except Exception:
+            pass
     log.propagate = False
 
 
@@ -119,19 +185,29 @@ def attach_unified_file_handler(
     logger_name: str,
     level: int = logging.DEBUG,
 ) -> logging.Logger:
+    """
+    独立子进程内追加同一日志文件（如 login 检测子进程），格式与主进程一致。
+    """
     global _skill_slug
+    logging.raiseExceptions = False
     ensure_trace_for_process()
     _skill_slug = skill_slug
     lg = logging.getLogger(logger_name)
-    lg.handlers.clear()
+    _clear_logger_handlers(lg)
     lg.setLevel(level)
-    parent = os.path.dirname(os.path.abspath(log_path))
-    if parent:
-        os.makedirs(parent, exist_ok=True)
-    fh = logging.FileHandler(log_path, encoding="utf-8")
     fmt = logging.Formatter(_FORMAT, datefmt=_DATEFMT)
-    fh.setFormatter(fmt)
-    fh.addFilter(_SkillContextFilter())
-    lg.addHandler(fh)
+    filt = _SkillContextFilter()
+
+    ok, _err = _can_open_log_file(log_path)
+    if ok:
+        try:
+            fh = logging.FileHandler(log_path, encoding="utf-8", delay=False)
+            fh.setFormatter(fmt)
+            fh.addFilter(filt)
+            lg.addHandler(fh)
+        except Exception:
+            _attach_fallback_handler(lg)
+    else:
+        _attach_fallback_handler(lg)
     lg.propagate = False
     return lg