CI runner 修日志噪声与 -Status 假警：PS5.1 把原生 stderr 包成 ErrorRecord

双看门狗缺陷已实测收敛：管理员 -StartNow 清掉 3 个残留（孤儿看门狗 26900/19716 + 占锁 daemon 53848）→ "daemon up: pid 40360 (single instance)"，监管链恢复为 svchost(任务) → 看门狗 → daemon，看门狗日志 25 秒零增长，runner 回 online。切换瞬间新看门狗先失败 1~2 次（旧 daemon 刚死、锁未释放）后自愈，属预期。顺带查出并修掉两个由验证动作暴露的问题： 1) 日志噪声：daemon 把日志写到 stderr，PS 5.1 的 2>&1 会把每行原生 stderr 包成 ErrorRecord，Out-File 渲染出 "gitea-runner.exe : " 前缀 + 4 行 CategoryInfo 块。实测对比（用无效子命令产生真实 stderr）：& exe 2>&1 | Out-File 把 2 行真日志写成 8 行——每 4 行有 3 行是 PowerShell 噪声，而且就在文档让大家第一个打开的文件里。改为 2>&1 | ForEach-Object { "$_" } | Out-File -Encoding utf8：实测与 cmd 包装等价但不用操心 cmd 对含空格路径的引号剥离，ErrorRecord.ToString() 即原始行， $LASTEXITCODE 不受影响（看门狗靠它打印退出码）。§7.2 方式 B 的示例原本正是 "> log 2>&1"（UTF-16LE + ErrorRecord 双坑），已改；新增 §7.3 汇总这两条陷阱。 2) -Status 两处不诚实：① 非管理员读不到 SYSTEM 进程的 CommandLine（返回 null），过滤器静默匹配 0 个 → 会谎报"没有看门狗"（今天两次被这个假象误导），改为明说 "需提权"；② 重启循环判据原本靠"日志尾部 40 行里有没有 lock 字样"，而日志不轮转，修好之后旧失败仍留在尾部 → 对健康 runner 报假警。改看 daemon 进程存活时长（活过 10 秒重拉间隔就不可能在循环里）；用 CIM CreationDate，因为 Process.StartTime 对 SYSTEM 进程不可读。验证：bootstrap parse 0 错 / 纯 ASCII / -Status 与 -DryRun 均正常； check_doc_links.py --all 125 篇 0 问题；pre-commit run --all-files 17 项全 Passed。注：磁盘上的 run_runner_watchdog.ps1 仍是旧模板，噪声修复要下次管理员 -StartNow （或开机自启）时才生效，纯观感问题，不必专门再重启一次 runner。
2026-10-12 17:59:45 +08:00
parent 49f3e2dac5
commit 3557b60ceb
3 changed files with 84 additions and 15 deletions
@@ -66,6 +66,8 @@
 > 于是新看门狗每 10 秒失败一次（`runner file is already locked by another process`）——
 > **而 runner 在网页上照样显示 online**，CI 看着正常，任务其实谁也没管。
 > 现在 `-StartNow` 会先清掉这些残留进程再启动（约离线几秒），`-Status` 也会报出重复实例。
+> **2026-10-12 已实测收敛**：清掉 3 个残留后 `daemon up: pid … (single instance)`，
+> 监管链 `svchost(任务) → 看门狗 → daemon` 恢复，runner 回 online。

 ## 相关文档

@@ -79,6 +81,7 @@

 | 日期 | 变更 |
 |---|---|
+| 2026-10-12 | ✅ 双看门狗缺陷**实测收敛**（管理员 `-StartNow` 清掉 3 个残留 → 单实例、链路恢复、runner online）。另修两处：daemon 日志走 stderr 被 PS 5.1 `2>&1` 包成 ErrorRecord（2 行真日志写成 8 行，每 4 行 3 行噪声）→ 启动器改 `ForEach-Object { "$_" }`；`-Status` 诚实化（非管理员读不到 SYSTEM 进程命令行 → 明说需提权而非谎报"无看门狗"；重启循环判据改看进程存活时长，不再靠不轮转日志的尾部字符串报假警）。详见指南 §7.3 |
 | 2026-10-12 | 🔴 **修复"双看门狗抢 `.runner.lock`"缺陷**：`Unregister-ScheduledTask` 不停旧实例进程 → 孤儿看门狗养着旧 daemon 占锁，新看门狗每 10 秒失败一次，而 runner 网页照样 online、`-Status` 也说"在跑"。现 `-StartNow` 先清残留进程再启动、`-Status` 报重复实例与锁冲突。同日清理机器侧：`config.yaml` 头部错误指引（"改用 sc.exe / New-Service"）改为看门狗口径，删除已废弃的 `deploy_runner_task.ps1` 与 `run_runner.cmd`，`check_env.ps1` 提示同步改指 bootstrap |
 | 2026-10-12 | **单一口径清理**：合并稿初版对 4 处分歧"两说并存"，现统一为本机实测现状——注册口径（`gitea-runner v4.0.1` / `D:\Docker\act_runner` / `127.0.0.1:3001`，旧 `act_runner v0.2.11` + `C:\act_runner` 段删去可复制命令只留警示）、`config.yaml`（`fetch_timeout: 1m0s`、`timeout: 30m0s`）、常驻方式（只认看门狗，`deploy_runner_task.ps1` 标废弃）、验收数字（L0.5 `288/288`，历史数字标注为快照）。并补"机器侧遗留脚本勿误用"警示 |
 | 2026-10-12 | **新建本目录**：远程 CI 内容原先散在 `docs/环境与部署/`（两篇互相重叠的指南）、`docs/测试说明/测试开发标准流程.md` §9、`AGENTS.md` 提交门禁节共 4 处，约 2000 行；现合并为单一指南并把 `AGENTS.md` 压成一行指针。动因：远程 CI 只涉及本机一台 runner，与日常开发规范混在一起每次会话都被读，造成困惑 |
@@ -1079,7 +1079,7 @@ date +%s   # 对比 last_online
 | 🔴 `Start-Service gitea-runner` 报 **无法启动服务**（错误 1053） | **`daemon` 不是服务型程序**，不向 SCM 回报 `SERVICE_RUNNING` | **删除该服务，改用任务计划程序**（§3.0 / §3.5） |
 | `Register-ScheduledTask` 报 **拒绝访问** | Shell 未提权（`IsAdmin=False`） | 右键 PowerShell → **以管理员身份运行**（§3.6） |
 | 任务 `LastTaskResult` 非 0 | 启动器路径/权限问题，或任务被手工终止 | 看 `log\runner-watchdog.log` 与 `log\runner-daemon.log`；确认 `run_runner_watchdog.ps1` 存在且为纯 ASCII；`0x41301` 是"正在运行"不是错误 |
-| 🔴 **runner 网页显示 online，但 `runner-watchdog.log` 每 10 秒刷 `starting daemon` → `daemon exited, exit code 1`** | **两个看门狗抢 `.runner.lock`**：`Unregister-ScheduledTask` 不会带走旧实例启动的进程，孤儿看门狗养着的旧 daemon 仍占着锁，新看门狗起不来（daemon 日志写 `another gitea-runner process is already using ".runner"` / `runner file is already locked by another process`）。此时 online 是**旧 daemon 在硬撑**，任务实际谁也没管 | `scripts\ci_runner_bootstrap.ps1 -Status` 会报出重复实例；**管理员**跑 `-StartNow`（现已会先清残留进程再启动，runner 约离线几秒）。应急可手工：`Get-CimInstance Win32_Process -Filter "Name='powershell.exe'" \| ? CommandLine -match 'run_runner_watchdog'` 找出多个 pid，杀掉**旧的那个**，再 `taskkill /PID <旧 daemon>` 让在册看门狗接管 |
+| 🔴 **runner 网页显示 online，但 `runner-watchdog.log` 每 10 秒刷 `starting daemon` → `daemon exited, exit code 1`** | **两个看门狗抢 `.runner.lock`**：`Unregister-ScheduledTask` 不会带走旧实例启动的进程，孤儿看门狗养着的旧 daemon 仍占着锁，新看门狗起不来（daemon 日志写 `another gitea-runner process is already using ".runner"` / `runner file is already locked by another process`）。此时 online 是**旧 daemon 在硬撑**，任务实际谁也没管 | `scripts\ci_runner_bootstrap.ps1 -Status` 会报出重复实例；**管理员**跑 `-StartNow`（现已会先清残留进程再启动，runner 约离线几秒）。应急可手工：`Get-CimInstance Win32_Process -Filter "Name='powershell.exe'" \| ? CommandLine -match 'run_runner_watchdog'` 找出多个 pid，杀掉**旧的那个**，再 `taskkill /PID <旧 daemon>` 让在册看门狗接管。**✅ 2026-10-12 实测收敛**：`-StartNow` 输出 `stopping stale watchdog pid 26900 / 19716` → `stopping stale daemon pid 53848` → `daemon up: pid 40360 (single instance, holds .runner.lock)`；之后看门狗日志 25 秒零增长、runner 回 `online`。切换瞬间新看门狗可能先失败 1~2 次（旧 daemon 刚被杀、锁尚未释放），10 秒重拉后自愈，属预期 |
 | `l0-gates` 报 `Cannot find: pwsh in PATH` | `shell: pwsh` = PS7，本机只有 WinPS 5.1 | 改 `shell: powershell` |
 | 🔴 `doc-links` 钩子本地过、CI 挂 | 引用了 **gitignore 的运行时文件**（如 `.dsh/skills/serial-assistant/scripts/state/*.json`），本地存在、干净克隆里没有 | 该行加状态词「未创建/不存在」等（§4.1.2） |
 | 任务跑满 72 小时被杀 | 计划任务默认 `ExecutionTimeLimit` | 设为 `0`（不限时长），见 §3.3 警示 |
@@ -1139,7 +1139,7 @@ foreach ($f in @("check_env.ps1","run_runner_watchdog.ps1")) {

 | 日志 | 位置 |
 |---|---|
-| runner **自身** stdout/stderr | `D:\Docker\act_runner\log\runner-daemon.log`（由看门狗 `Out-File -Append -Encoding utf8` 落盘） |
+| runner **自身** stdout/stderr | `D:\Docker\act_runner\log\runner-daemon.log`（由看门狗落盘，显式 `-Encoding utf8`；**2026-10-12 之前的行**夹带 PowerShell 包装噪声，见 §7.3） |
 | **看门狗自身**动作（等 Gitea / 拉起 / 退出码 / 重拉） | `D:\Docker\act_runner\log\runner-watchdog.log`（ASCII） |
 | **每个 job** 的详细日志 | `D:\Docker\act_runner\log\job\` |
 | 🗑 历史遗留 | `log\runner-stdout.log` 是旧 `run_runner.cmd` 时代的文件，**已不再写入**；它内部混着 ASCII 与 UTF-16LE 两种编码（PS 5.1 `*>>` 默认 UTF-16LE），按 UTF-8 读会看到"每个字节后跟一个 NUL"的 `t i m e = ...` 形态，属正常现象不是新故障 |
@@ -1155,13 +1155,42 @@ log:
 ```

 ```powershell
-# 方式 B：前台运行 / 包装脚本里重定向
-.\gitea-runner.exe daemon > "D:\Docker\act_runner\log\runner.log" 2>&1
+# 方式 B：前台运行 / 包装脚本里重定向。
+# 🔴 不要写成 `.\gitea-runner.exe daemon > log 2>&1`：PS 5.1 的 `>` 就是 Out-File，
+#    默认编码 UTF-16LE，且会把原生 stderr 包成 ErrorRecord（见 §7.3）。要这样写：
+& '.\gitea-runner.exe' daemon 2>&1 | ForEach-Object { "$_" } |
+    Out-File -FilePath 'D:\Docker\act_runner\log\runner.log' -Append -Encoding utf8
 ```

 任务本身的历史记录：**任务计划程序 → 任务计划程序库 → `GiteaActionsRunner` → 历史记录**；
 或用 `Get-ScheduledTaskInfo -TaskName GiteaActionsRunner` 看 `LastTaskResult`。

+### 7.3 🔴 原生命令 stderr 的两个 PS 5.1 陷阱（本仓库实测，均已修）
+
+runner 的日志走 **stderr**，于是上面两个日志文件都栽在这两条上。两条都在
+`scripts/ci_runner_bootstrap.ps1` 生成的启动器里修掉了，改脚本时勿回退：
+
+**① 重定向的默认编码是 UTF-16LE。** `*>>` / `>` 在 PS 5.1 里就是 `Out-File`，默认
+`Unicode`(UTF-16LE)。同一文件里若还有 `Add-Content -Encoding ascii` 写的行，就会
+**一个文件两种编码**，按 UTF-8 读出来是 `t i m e = 2 0 2 6 ...`（每字节后跟 NUL）。
+→ **永远显式写 `-Encoding utf8`**（别用 ascii：job/提交文本可能含非 ASCII）。
+
+**② `2>&1` 把原生 stderr 包成 ErrorRecord。** 实测（用无效子命令产生真实 stderr）：
+
+| 写法 | 2 行真实日志写成 | 噪声 |
+|---|---|---|
+| `& $exe 2>&1 \| Out-File` | **8 行** | `gitea-runner.exe : ` 前缀 + 4 行 `CategoryInfo`/`FullyQualifiedErrorId` 块 |
+| `& $exe 2>&1 \| ForEach-Object { "$_" } \| Out-File` | **2 行** | 0 |
+| `& cmd.exe /c "… 2>&1" \| Out-File` | 2 行 | 0（等价，但要额外操心 cmd 对含空格路径的引号剥离） |
+
+即**每 4 行日志有 3 行是 PowerShell 噪声**，而且它就出现在文档让大家第一个打开的文件里。
+`ErrorRecord.ToString()` 就是原始 stderr 行，所以逐项字符串化即可去掉装饰，
+且 `$LASTEXITCODE` 不受影响（看门狗靠它打印退出码）。
+
+> 💡 顺带一条同类教训：**别用"日志尾部还有没有错误串"判断健康状态**。日志不轮转，
+> 修好之后旧失败仍留在尾部几十行内——`-Status` 曾据此对健康 runner 报假警。
+> 现在改看**进程存活时长**（活过 10 秒重拉间隔就不可能在重启循环里）。
+
 ---

 ## 8. 日常维护
@@ -1319,6 +1348,7 @@ powershell -ExecutionPolicy Bypass -File scripts\ci_runner_bootstrap.ps1 -DryRun

 | 日期 | 变更 |
 |---|---|
+| 2026-10-12 | ✅ **双看门狗缺陷实测收敛** + 修掉日志里的 PS 5.1 stderr 包装噪声与 `-Status` 假警。① 管理员 `-StartNow` 杀掉 3 个残留（孤儿看门狗 26900/19716 + 占锁 daemon 53848）→ `daemon up: pid 40360 (single instance)`，监管链 `svchost → 看门狗 → daemon`，看门狗日志 25 秒零增长、runner 回 online。② 新坑：daemon 日志写 **stderr**，PS 5.1 的 `2>&1` 把每行包成 ErrorRecord → `gitea-runner.exe : ` 前缀 + 4 行 `CategoryInfo` 块，实测 2 行真日志写成 8 行（**每 4 行有 3 行是噪声**，且就在文档让大家第一个打开的文件里）。启动器改为 `2>&1 \| ForEach-Object { "$_" } \| Out-File -Encoding utf8`（实测与 cmd 包装等价但免引号剥离坑，`$LASTEXITCODE` 不受影响）；§7.2 方式 B 的示例原本正是 `> log 2>&1`（UTF-16LE + 包装双坑），已改；新增 §7.3 汇总这两条。③ `-Status` 两处诚实化：非管理员**读不到 SYSTEM 进程命令行**（`CommandLine` 为 null → 过滤器静默匹配 0 个），改为明说"需提权"而不是谎报"没有看门狗"；重启循环判据不再靠"日志尾部有没有错误串"（文件不轮转，修好后旧失败仍在尾部 → 对健康 runner 报假警），改看 **daemon 进程存活时长**（CIM `CreationDate` 非管理员可读，`Process.StartTime` 对 SYSTEM 进程不可读） |
 | 2026-10-12 | 🔴 **实测揪出"双看门狗抢锁"缺陷并修复** + 机器侧清理。① 现象：runner 网页 online、`-Status` 说 daemon 在跑，但 `runner-watchdog.log` 每 10 秒刷 `starting daemon → daemon exited, exit code 1`，daemon 日志 `runner file is already locked by another process`。② 根因：`Unregister-ScheduledTask` **不停旧实例启动的进程**——13:22 重跑 bootstrap 时旧看门狗(12:53 起)成孤儿并继续养着旧 daemon、占住 `.runner.lock`，新看门狗永远抢不到锁，任务实际谁也没管，日志以约 20 MB/天在刷。③ 修复：`ci_runner_bootstrap.ps1` 的 `-StartNow` 现在**先停孤儿看门狗与残留 daemon 再启动**并回显单实例确认；`-Status` 新增重复实例计数与锁冲突检测。④ 机器侧清理：`config.yaml` 头部那句**错误指引**（"常驻改用 Windows sc.exe / New-Service"，正是 §3.0 证伪的路）改为看门狗口径并指向本文；删除已废弃的 `deploy_runner_task.ps1` 与 `run_runner.cmd`（§3.2），`check_env.ps1` 指向它们的提示同步改指 bootstrap。⑤ 核实：`config.yaml` 改后 YAML 可解析且**所有配置值与改前逐项一致**（只动注释）；`check_env.ps1` 带 BOM 且语法 0 错；删除前确认计划任务动作目标是 `run_runner_watchdog.ps1`，删除不影响在跑 runner |
 | 2026-10-12 | 🧹 **单一口径清理（以本机实测现状为准）**：合并稿初版对 4 处分歧采取"两说并存 + 衔接注"，本次统一。① 注册口径——`act_runner v0.2.11` + `C:\act_runner` + 公网域名 instance 一段**删除可复制命令**，只留"勿照抄"警示（核实 `C:\act_runner` 至今不存在，本机是 `gitea-runner v4.0.1` + `D:\Docker\act_runner` + `127.0.0.1:3001`）；② `config.yaml` 示例 `fetch_timeout` 由 `5m0s` 改为磁盘实际值 **`1m0s`**、`timeout` 统一 `30m0s`，并补"不得超过 RPC timeout(1m0s)"；③ 常驻口径统一为看门狗——§3.2 `deploy_runner_task.ps1` 标为**已废弃**并说明失效机理（单次 daemon = 正常退出，失败重启永不触发），§3.3 手动等价命令**重写为看门狗版任务对象**（旧版会教人手搓出坏配置），§10 TL;DR 第 4 步改指 `ci_runner_bootstrap.ps1`；④ 数字口径——L0.5 期望值更新为 **288/288**（run#8 的 39/39 与 278/278 标注为历史快照，判定只看 `fail=0` 与 A==B），钩子数按现行 18 定义 / 17 报告。另同步：健康三查与排障表改用现行日志名（`runner-daemon.log` / `runner-watchdog.log`，`runner-stdout.log` 标为遗留且说明其混编码）、BOM 示例对象换成 `check_env.ps1` 并注明看门狗是纯 ASCII 无需 BOM、配套脚本表补 `run_runner_watchdog.ps1` 并标出磁盘上仍存的废弃脚本建议删除、补 `Next Run Time` 为空属正常的说明 |
 | 2026-10-12 | **文档合并**：本次把 `CI配置指南.md` 与 `Gitea_Runner部署指南.md` 合并为本篇（`docs/CI/远程CI完整指南.md`）并迁入 `docs/CI/`，去重（runner 注册 / config.yaml / 装软件 / 排障表两篇均有）、补入 runner 看门狗与机器级变量实测教训；相对链接按新位置改写，原两篇互引改为本文内部引用 |
@@ -229,18 +229,44 @@ if ($Status) {
    # A watchdog that cannot get the lock fails every 10s while the runner still
    # reports ONLINE, so the loop is invisible from the web UI. Count watchdogs and
    # grep the daemon log for the lock error (measured 2026-10-12).
-    $wd = @(Get-CimInstance Win32_Process -Filter "Name='powershell.exe'" -ErrorAction SilentlyContinue |
-            Where-Object { $_.CommandLine -match 'run_runner_watchdog\.ps1' })
-    if ($wd.Count -gt 1) {
-        Warn ("  {0} watchdog processes (pids {1}) -- an old one survived a task re-registration" -f `
-            $wd.Count, (($wd | ForEach-Object { $_.ProcessId }) -join ','))
-        Warn '  and is racing the new one for .runner.lock; re-run elevated with -StartNow'
+    # MEASURED TRAP #3 (2026-10-12): a NON-ELEVATED session cannot read SYSTEM
+    # process command lines -- CommandLine comes back $null, so the filter below
+    # silently matches NOTHING and reporting "no watchdog" would be a lie (this
+    # bit us twice while diagnosing). Say what we cannot see instead.
+    if (-not (Test-Admin)) {
+        Info '  watchdog count skipped: needs elevation (SYSTEM command lines are hidden)'
+    } else {
+        $wd = @(Get-CimInstance Win32_Process -Filter "Name='powershell.exe'" -ErrorAction SilentlyContinue |
+                Where-Object { $_.CommandLine -match 'run_runner_watchdog\.ps1' })
+        if ($wd.Count -gt 1) {
+            Warn ("  {0} watchdog processes (pids {1}) -- an old one survived a task re-registration" -f `
+                $wd.Count, (($wd | ForEach-Object { $_.ProcessId }) -join ','))
+            Warn '  and is racing the new one for .runner.lock; re-run elevated with -StartNow'
+        } elseif ($wd.Count -eq 1) {
+            Ok ("watchdog running: pid {0}" -f $wd[0].ProcessId)
+        } else {
+            Warn 'no watchdog process found (task not running?)'
+        }
    }
-    $dlog = Join-Path $RunnerDir 'log\runner-daemon.log'
-    if (Test-Path -LiteralPath $dlog) {
-        $tail = Get-Content -LiteralPath $dlog -Tail 40 -Encoding UTF8 -ErrorAction SilentlyContinue
-        if ($tail -match 'already locked by another process') {
-            Warn '  daemon log says ".runner is already locked by another process" -- stale instance present'
+    # Restart-loop detection. Do NOT just grep the log tail: the file is never
+    # rotated, so old failures stay in the last lines forever and a HEALTHY runner
+    # keeps "reporting" a stale error (measured false positive 2026-10-12). The
+    # reliable signal is a daemon that keeps dying young -- a process alive longer
+    # than the 10s restart interval cannot be inside that loop. CIM CreationDate is
+    # readable without elevation; Process.StartTime is NOT for SYSTEM processes.
+    $dmon = Get-CimInstance Win32_Process -Filter "Name='gitea-runner.exe'" -ErrorAction SilentlyContinue |
+            Select-Object -First 1
+    $upSec = if ($dmon) { [int]((Get-Date) - $dmon.CreationDate).TotalSeconds } else { -1 }
+    if ($upSec -ge 90) {
+        Ok ("daemon up for {0} min -- no restart loop" -f [int]($upSec / 60))
+    } else {
+        $dlog = Join-Path $RunnerDir 'log\runner-daemon.log'
+        if (Test-Path -LiteralPath $dlog) {
+            $tail = Get-Content -LiteralPath $dlog -Tail 40 -Encoding UTF8 -ErrorAction SilentlyContinue
+            if ($tail -match 'already locked by another process') {
+                Warn '  daemon keeps dying young and the log shows ".runner is already locked'
+                Warn '  by another process" -- a stale instance holds the lock; re-run with -StartNow'
+            }
        }
    }

@@ -402,7 +428,17 @@ while ($true) {
    # daemon lines read back as "t i m e = 2 0 2 6 ..." (a NUL after every byte).
    # Never rely on a redirection's default encoding -- state it explicitly.
    # utf8 (not ascii) because job/commit text can legitimately be non-ASCII.
+    # MEASURED TRAP #2 (2026-10-12): the daemon writes its log to STDERR, and in
+    # PS 5.1 a native `2>&1` merge wraps every stderr line into an ErrorRecord.
+    # Out-File then renders "gitea-runner.exe : <line>" plus a 4-line CategoryInfo
+    # block -- measured: a 2-line message became 8 lines, so 3 of every 4 lines in
+    # the daemon log were PowerShell noise, in the very file the docs tell people
+    # to read first. Stringifying each pipeline item keeps the text and drops the
+    # decoration (ErrorRecord.ToString() IS the original stderr line) and leaves
+    # $LASTEXITCODE intact. Verified against a cmd.exe wrapper; same result, and
+    # this form avoids cmd's quote-stripping rules for spaced paths.
    & $runnerExe daemon --config $runnerCfg 2>&1 |
+        ForEach-Object { "$_" } |
        Out-File -FilePath $daemonLog -Append -Encoding utf8
    Log ("daemon exited, exit code {0}; restarting in 10s" -f $LASTEXITCODE)
    Start-Sleep -Seconds 10