修复串口助手6处采集缺陷：wait-idle no_data与首字节门、log先过滤后截尾、HTTP独占绑定修正、超时不再误拉daemon、配置BOM容错

2026-10-10 02:33:44 +08:00
parent 29df7bf8fb
commit b37fdea21b
6 changed files with 326 additions and 62 deletions
@@ -17,9 +17,9 @@
    open / close                开（幂等）/ 关串口
    send <text> | --hex <hh>    发送 TX（进日志）；--nl 追加 CRLF
    status                      全状态（单条 JSON）
-    log --tail N --grep P       读日志（CLI 直接读文件，daemon 死了也能看历史）
+    log --tail N --grep P       读日志（先过滤后截尾；-i 忽略大小写 / --regex 正则）
    clear                       清空日志（原子截断 + 代际递增）
-    wait-idle                   等 RX 静默（@test 用；--settle-ms / --max-ms）
+    wait-idle                   等 RX 静默（@test 用；--settle-ms / --max-ms / --first-timeout-ms）
    start / stop / restart      daemon 生命周期（其余命令会自动拉起 daemon）
    selftest                    无头自检（行拆分/解码回退/截头算法，无需硬件）

@@ -29,7 +29,9 @@ import argparse
 import json
 import os
 import queue
+import re
 import signal
+import socket
 import subprocess
 import sys
 import tempfile
@@ -60,21 +62,44 @@ CAP_BYTES = 20 * 1024 * 1024      # 日志体积上限
 KEEP_BYTES = 10 * 1024 * 1024     # 超限后保留的尾部
 PARTIAL_FLUSH_S = 0.2             # 残行冲刷窗口（秒）
 REOPEN_SETTLE_S = 1.5             # 重开端口退避（CH340 释放后立即重开的 EOF 陷阱）
-DEFAULT_TIMEOUT_S = 5.0           # CLI→daemon 硬超时（秒）
+DEFAULT_TIMEOUT_S = 5.0           # CLI→daemon 硬超时（秒；wait-idle 未显式给时按 --max-ms 推导）
+DAEMON_LOG_MAX = 1024 * 1024      # daemon.log 超此体积 → 拉起新实例前只保尾部
+DAEMON_LOG_KEEP = 256 * 1024


 # ---------------------------------------------------------------- 配置 / 元数据

 def load_config():
-    cfg = {"portName": "", "baudRate": 115200, "httpPort": DEFAULT_HTTP_PORT}
+    """读唯一配置源 .opencode/serial_config.json。
+
+    编码用 utf-8-sig（与 run_boot_test.py 同口径）：纯 utf-8 遇 BOM 会让 json.load
+    抛错，旧实现再把它静默吞掉 → 端口/波特率全回退默认 → 报 "no port specified"，
+    把配置问题误导成端口问题（2026-10-09 修）。解析失败不再静默：错误文本放进
+    configError，由 status / open / ports 显式回显。
+    """
+    cfg = {"portName": "", "baudRate": 115200, "httpPort": DEFAULT_HTTP_PORT,
+           "configError": ""}
    try:
-        with open(CONFIG_FILE, "r", encoding="utf-8") as f:
+        with open(CONFIG_FILE, "r", encoding="utf-8-sig") as f:
            raw = json.load(f)
-        cfg["portName"] = str(raw.get("portName", ""))
+    except FileNotFoundError:
+        cfg["configError"] = "config file not found: %s" % CONFIG_FILE
+        return cfg
+    except OSError as e:
+        cfg["configError"] = "cannot read config %s: %s" % (CONFIG_FILE, e)
+        return cfg
+    except ValueError as e:
+        cfg["configError"] = "bad JSON in %s: %s" % (CONFIG_FILE, e)
+        return cfg
+    if not isinstance(raw, dict):
+        cfg["configError"] = "config root is not an object: %s" % CONFIG_FILE
+        return cfg
+    cfg["portName"] = str(raw.get("portName", ""))
+    try:
        cfg["baudRate"] = int(raw.get("baudRate", 115200))
        cfg["httpPort"] = int(raw.get("httpPort", DEFAULT_HTTP_PORT))
-    except (OSError, ValueError):
-        pass
+    except (TypeError, ValueError) as e:
+        cfg["configError"] = "bad baudRate/httpPort in %s: %s" % (CONFIG_FILE, e)
    return cfg


@@ -356,7 +381,10 @@ class Daemon:
        p = cmd.params
        name = p.get("port") or self.cfg.get("portName") or ""
        if not name:
-            cmd.finish({"ok": False, "error": "no port specified (and no portName in config)"})
+            err = "no port specified (and no portName in config)"
+            if self.cfg.get("configError"):
+                err += " [config: %s]" % self.cfg["configError"]
+            cmd.finish({"ok": False, "error": err})
            return
        baud = int(p.get("baud") or self.cfg.get("baudRate") or 115200)
        dtr = bool(p.get("dtr", False))
@@ -483,29 +511,49 @@ class Daemon:
        size = LOG_FILE.stat().st_size if LOG_FILE.exists() else 0
        return {"ok": True,
                "daemon": {"pid": os.getpid(), "version": VERSION,
-                           "uptime_s": int(time.time() - self.born)},
+                           "uptime_s": int(time.time() - self.born),
+                           "exclusive_bind": getattr(self.server, "exclusive_bound", False)},
                "port": port, "counters": counters, "last_rx": last,
                "log": {"path": str(LOG_FILE), "size": size, "gen": gen},
-                "state": state, "error": err}
+                "state": state, "error": err,
+                "config_error": self.cfg.get("configError") or None}

-    def wait_idle(self, settle_s, max_s):
+    def wait_idle(self, settle_s, max_s, first_timeout_s=None):
+        """等 RX 静默，返回 reason ∈ {idle, no_data, timeout}。
+
+        2026-10-09 修三处（旧实现会让 @test 在"板子全程没输出"时误判收尾）：
+          1. no_data 判据：旧实现比的是"进入函数时 daemon 累计 rx_bytes 是否为 0"。
+             daemon 常驻（本机实测 rx_bytes=1.2MB）→ 永远 >0 → 板子一个字节都不发
+             也返回 idle:true，@test 的 no_data 拦截形同虚设。现按**本次增量**判。
+          2. 首字节门：旧实现从进入即开始计静默时间，板子第一行比 settle_ms 来得
+             晚就提前收尾（"开机日志缺尾巴"的另一半成因）。现首字节到达前不启动
+             settle 计时，改由 first_timeout_s 兜底（默认 = max_s）。
+          3. 返回的 rx_bytes 改为**本次等待期间的增量**（旧实现回的是 daemon 累计
+             值，调用方打出来的 WAIT: rx_bytes=1246761 毫无意义）。
+        """
        t0 = time.time()
-        last = self.rx_bytes
-        last_change = t0
-        while time.time() - t0 < max_s:
-            time.sleep(0.1)
+        initial = self.rx_bytes
+        last = initial
+        last_change = 0.0                     # 0.0 = 本次尚未收到任何字节
+        first_deadline = t0 + (first_timeout_s if first_timeout_s is not None else max_s)
+        reason = "timeout"
+        while True:
+            now = time.time()
            if self.rx_bytes != last:
                last = self.rx_bytes
-                last_change = time.time()
-            elif time.time() - last_change >= settle_s:
+                last_change = now
+            if last_change:
+                if now - last_change >= settle_s:
+                    reason = "idle"
+                    break
+            elif now >= first_deadline:
+                reason = "no_data"
                break
-        if last == 0:
-            reason = "no_data"
-        elif time.time() - last_change >= settle_s:
-            reason = "idle"
-        else:
-            reason = "timeout"
-        return {"ok": True, "rx_bytes": last, "idle": reason == "idle",
+            if now - t0 >= max_s:
+                reason = "timeout"
+                break
+            time.sleep(0.1)
+        return {"ok": True, "rx_bytes": last - initial, "idle": reason == "idle",
                "waited_ms": int((time.time() - t0) * 1000), "reason": reason}

    # -- 生命周期 --
@@ -540,18 +588,32 @@ class _ExclusiveHTTPServer(ThreadingHTTPServer):
    socket 绑同一端口（Linux 不会），会致多 daemon 并存、请求随机分发，必须禁用。"""

    allow_reuse_address = False
+    exclusive_bound = False

    def server_bind(self):
-        import socket as _socket
        if os.name == "nt":
-            # SO_EXCLUSIVEADDRPLACE = 0x0040；部分发行版 socket 模块未导出，用数值兜底
-            excl = getattr(_socket, "SO_EXCLUSIVEADDRPLACE", 0x0040)
+            # 真名是 SO_EXCLUSIVEADDRUSE（值 -5 = ~SO_REUSEADDR）。旧代码写成
+            # "SO_EXCLUSIVEADDRPLACE" 并用数值 0x0040 兜底：属性不存在 → 取到 0x40
+            # → setsockopt 抛 WinError 10042（无效选项）→ 被 except 静默吞掉
+            # → 注释承诺的"独占绑定"从未真正生效（2026-10-09 实测复现）。
+            excl = getattr(socket, "SO_EXCLUSIVEADDRUSE", -5)
            try:
-                self.socket.setsockopt(_socket.SOL_SOCKET, excl, 1)
-            except (OSError, AttributeError):
-                pass  # 退回 allow_reuse_address=False（Windows 同样拒绝二次绑定）
+                self.socket.setsockopt(socket.SOL_SOCKET, excl, 1)
+                _ExclusiveHTTPServer.exclusive_bound = True
+            except OSError as e:
+                print("serial_tool: SO_EXCLUSIVEADDRUSE failed (%s); falling back "
+                      "to allow_reuse_address=False" % e, file=sys.stderr, flush=True)
        super().server_bind()

+    def handle_error(self, request, client_address):
+        """CLI 硬超时先退出会掐断连接 → socketserver 默认往 daemon.log 打整段
+        traceback（本机实测 16 次 ConnectionAbortedError）。客户端已断开不是
+        daemon 故障，静音处理。"""
+        exc = sys.exc_info()[1]
+        if isinstance(exc, ConnectionError):
+            return
+        super().handle_error(request, client_address)
+

 class _Handler(BaseHTTPRequestHandler):
    daemon = None  # 由 Daemon.run 注入
@@ -623,7 +685,9 @@ class _Handler(BaseHTTPRequestHandler):
            body = self._body()
            settle = max(0.5, float(body.get("settle_ms", 8000)) / 1000.0)
            mx = max(1.0, float(body.get("max_ms", 30000)) / 1000.0)
-            self._send(200, d.wait_idle(settle, mx))
+            ft = body.get("first_timeout_ms")
+            ft = None if ft is None else max(1.0, float(ft) / 1000.0)
+            self._send(200, d.wait_idle(settle, mx, ft))
        elif self.path == "/stop":
            cmd = Cmd("close")
            d.cmd_q.put(cmd)
@@ -664,8 +728,31 @@ def http_request(method, path, body=None, timeout=DEFAULT_TIMEOUT_S):
            raise ToolError("daemon HTTP %d (non-JSON body)" % e.code, 2)


+def _rotate_daemon_log():
+    """daemon.log 超 DAEMON_LOG_MAX → 原地只保尾部 DAEMON_LOG_KEEP。
+
+    不 rename（Windows 下老 daemon 可能还持有句柄，rename 会让它继续往旧 inode 写）；
+    只在拉起新实例前做，写入口径不变。旧实现无上限：daemon 反复重启 + 断连
+    traceback 会把它无限撑大。
+    """
+    try:
+        size = DAEMON_LOG.stat().st_size
+        if size <= DAEMON_LOG_MAX:
+            return
+        with open(DAEMON_LOG, "r+b") as f:
+            f.seek(size - DAEMON_LOG_KEEP)
+            tail = f.read()
+            f.seek(0)
+            os.ftruncate(f.fileno(), 0)
+            f.write(b"[daemon.log rotated: kept last %dKB]\n" % (DAEMON_LOG_KEEP // 1024))
+            f.write(tail)
+    except OSError:
+        pass
+
+
 def spawn_daemon():
    STATE_DIR.mkdir(parents=True, exist_ok=True)
+    _rotate_daemon_log()
    log_fh = open(DAEMON_LOG, "ab")
    kwargs = {}
    if os.name == "nt":
@@ -695,12 +782,33 @@ def _try_kill(pid):
        return False


+def _is_timeout_exc(exc):
+    """超时判定：urlopen 连接阶段超时会被包成 URLError(reason=socket.timeout)，
+    读响应阶段超时则直接抛 socket.timeout（3.10+ 即 TimeoutError）。"""
+    if isinstance(exc, (socket.timeout, TimeoutError)):
+        return True
+    return isinstance(getattr(exc, "reason", None), (socket.timeout, TimeoutError))
+
+
 def call_daemon(args, method, path, body=None):
-    """调 daemon；连接失败时自动拉起并重试一次。"""
+    """调 daemon；**连接被拒/不可达**时自动拉起并重试一次。
+
+    2026-10-10 修：超时不再当"daemon 不可达"。旧实现把超时和拒连塞进同一个
+    except → 任何耗时超过 --timeout 的命令（典型：wait-idle）都会误判 daemon 已死、
+    额外拉起一个 daemon（新实例绑不上 HTTP 口 → 打 "HTTP port busy" 后退出；
+    daemon.log 里 36 条 listening 大半是这么攒出来的），再把原命令撞一次超时。
+    现在超时直接快速失败并提示调大 --timeout；只有真·不可达才走自动拉起。
+    """
    timeout = getattr(args, "timeout", DEFAULT_TIMEOUT_S)
    try:
        return http_request(method, path, body, timeout)
+    except (socket.timeout, TimeoutError) as e:
+        raise ToolError("daemon did not answer within %.1fs (busy? raise --timeout): %s"
+                        % (timeout, e), 2)
    except (urllib.error.URLError, OSError) as e:
+        if _is_timeout_exc(e):
+            raise ToolError("daemon did not answer within %.1fs (busy? raise --timeout): %s"
+                            % (timeout, getattr(e, "reason", e)), 2)
        if args.command == "stop":
            killed = False
            pid = load_meta().get("pid")
@@ -725,7 +833,9 @@ def call_daemon(args, method, path, body=None):
 def cmd_ports(args):
    ports = [{"name": p.device, "description": p.description, "hwid": p.hwid}
             for p in serial.tools.list_ports.comports()]
-    return {"ok": True, "ports": ports, "configured": load_config().get("portName", "")}
+    cfg = load_config()
+    return {"ok": True, "ports": ports, "configured": cfg.get("portName", ""),
+            "config_error": cfg.get("configError") or None}


 def cmd_open(args):
@@ -761,16 +871,39 @@ def cmd_status(args):


 def cmd_log(args):
+    """读日志：**先过滤、后截尾**。
+
+    旧实现先 tail 后 grep → `log --grep "App init OK"`（--tail 默认 50）只在末 50 行
+    里找，开机标记必然查无此 marker——这就是 AGENTS.md 里"log --grep 实测不可信"的
+    根因（2026-10-09 实测复现并修复）。返回带 scanned/matched 计数，便于判定。
+    """
    gen = int(load_meta().get("gen", 0))
    if not LOG_FILE.exists():
        return {"ok": True, "gen": gen, "lines": [], "note": "log file not created yet"}
    with open(LOG_FILE, "r", encoding="utf-8", errors="replace") as f:
        lines = f.read().splitlines()
+    scanned = len(lines)
+    matched = scanned
+    if args.grep:
+        if args.regex:
+            try:
+                pat = re.compile(args.grep, re.IGNORECASE if args.ignore_case else 0)
+            except re.error as e:
+                raise ToolError("bad --grep regex %r: %s" % (args.grep, e), 3)
+            lines = [l for l in lines if pat.search(l)]
+        elif args.ignore_case:
+            low = args.grep.lower()
+            lines = [l for l in lines if low in l.lower()]
+        else:
+            lines = [l for l in lines if args.grep in l]
+        matched = len(lines)
    if args.tail:
        lines = lines[-args.tail:]
-    if args.grep:
-        lines = [l for l in lines if args.grep in l]
-    return {"ok": True, "gen": gen, "lines": lines}
+    result = {"ok": True, "gen": gen, "lines": lines,
+              "scanned": scanned, "matched": matched}
+    if args.grep and args.tail and matched > len(lines):
+        result["note"] = "grep matched %d line(s), showing last %d (tail)" % (matched, len(lines))
+    return result


 def cmd_clear(args):
@@ -778,8 +911,16 @@ def cmd_clear(args):


 def cmd_wait_idle(args):
-    return call_daemon(args, "POST", "/wait-idle",
-                       {"settle_ms": args.settle_ms, "max_ms": args.max_ms})
+    body = {"settle_ms": args.settle_ms, "max_ms": args.max_ms}
+    if args.first_timeout_ms:
+        body["first_timeout_ms"] = args.first_timeout_ms
+    if not args.timeout_explicit:
+        # wait-idle 是同步阻塞的长操作：CLI 超时按等待上限自动推导。旧实现固定 5s
+        # 硬超时会在 daemon 还在等的时候先掐断 → CLI 报 exit 2、daemon 侧
+        # ConnectionAbortedError traceback（本机 daemon.log 实测 16 次）。
+        # AGENTS.md 抓开机日志铁律②"必须带 --timeout"就是这个坑的手工补丁。
+        args.timeout = args.max_ms / 1000.0 + 5.0
+    return call_daemon(args, "POST", "/wait-idle", body)


 def cmd_start(args, force=False):
@@ -903,6 +1044,92 @@ def run_selftest():
        except OSError:
            pass

+    # T5 wait_idle：no_data 判据 / 首字节门 / 增量字节（2026-10-09 回归锁）
+    class _Cnt:
+        def __init__(self, n):
+            self.rx_bytes = n
+
+    r = Daemon.wait_idle(_Cnt(500000), 0.2, 0.6, 0.3)   # 常驻 daemon：累计值非 0
+    check("T5a 零字节判 no_data", r["reason"] == "no_data" and r["rx_bytes"] == 0
+          and not r["idle"], repr(r))
+
+    p5 = _Cnt(100)
+    threading.Thread(target=lambda: (time.sleep(0.35), setattr(p5, "rx_bytes", 200)),
+                     daemon=True).start()
+    r = Daemon.wait_idle(p5, 0.2, 2.0, 1.0)             # 第一行比 settle 晚到
+    check("T5b 首字节门（晚到的第一行仍收全）",
+          r["reason"] == "idle" and r["rx_bytes"] == 100 and r["waited_ms"] >= 500, repr(r))
+
+    p6 = _Cnt(0)
+    stop6 = threading.Event()
+
+    def _spam():
+        while not stop6.is_set():
+            p6.rx_bytes += 10
+            time.sleep(0.05)
+
+    threading.Thread(target=_spam, daemon=True).start()
+    r = Daemon.wait_idle(p6, 0.3, 0.8)
+    stop6.set()
+    check("T5c 持续吐数判 timeout + 返回增量字节",
+          r["reason"] == "timeout" and r["rx_bytes"] > 0, repr(r))
+
+    # T6 log 命令：先 grep 后 tail（旧顺序即 AGENTS.md"log --grep 不可信"的根因）
+    saved_log, saved_meta = LOG_FILE, load_meta
+    fd2, lpath2 = tempfile.mkstemp(prefix="serial_tool_selftest_log_", suffix=".log")
+    os.close(fd2)
+    try:
+        body = "[RX] 2026-10-09T00:00:00.000+08:00 App init OK\n" + "\n".join(
+            "[RX] 2026-10-09T00:00:01.000+08:00 noise %d" % i for i in range(60))
+        Path(lpath2).write_text(body, encoding="utf-8")
+        globals()["LOG_FILE"] = Path(lpath2)
+        globals()["load_meta"] = lambda: {"gen": 7}
+
+        class _G:
+            tail = 50
+            grep = "App init OK"
+            regex = False
+            ignore_case = False
+
+        r = cmd_log(_G())
+        check("T6a grep 先于 tail（末 50 行也查到开机标记）",
+              r["matched"] == 1 and len(r["lines"]) == 1 and "App init OK" in r["lines"][0],
+              "matched=%s lines=%d" % (r.get("matched"), len(r["lines"])))
+
+        class _R:
+            tail = 0
+            grep = r"App init|noise 5[0-9]"
+            regex = True
+            ignore_case = False
+
+        r = cmd_log(_R())
+        check("T6b --regex 交替匹配", r["matched"] == 11, "matched=%s" % r.get("matched"))
+
+        class _I:
+            tail = 5
+            grep = "NOISE"
+            regex = False
+            ignore_case = True
+
+        r = cmd_log(_I())
+        check("T6c -i 忽略大小写 + tail 在过滤之后",
+              r["scanned"] == 61 and r["matched"] == 60 and len(r["lines"]) == 5,
+              "scanned=%s matched=%s lines=%d" % (r.get("scanned"), r.get("matched"),
+                                                  len(r["lines"])))
+    finally:
+        globals()["LOG_FILE"], globals()["load_meta"] = saved_log, saved_meta
+        try:
+            os.remove(lpath2)
+        except OSError:
+            pass
+
+    # T7 CLI 超时/拒连区分（旧实现把超时也当"daemon 不可达"→ 误拉起新实例）
+    check("T7a 超时识别（裸抛 + URLError 包裹）",
+          _is_timeout_exc(socket.timeout("t"))
+          and _is_timeout_exc(urllib.error.URLError(socket.timeout("t"))))
+    check("T7b 拒连不当成超时（仍走自动拉起）",
+          not _is_timeout_exc(urllib.error.URLError(ConnectionRefusedError("refused"))))
+
    width = 46
    all_ok = True
    for name, ok, detail in results:
@@ -917,8 +1144,9 @@ def run_selftest():

 def build_parser():
    common = argparse.ArgumentParser(add_help=False)
-    common.add_argument("--timeout", type=float, default=DEFAULT_TIMEOUT_S,
-                        help="CLI->daemon 硬超时秒数（默认 %.0f）" % DEFAULT_TIMEOUT_S)
+    common.add_argument("--timeout", type=float, default=None,
+                        help="CLI->daemon 硬超时秒数（默认 %.0f；wait-idle 未显式给时按 --max-ms 自动推导）"
+                             % DEFAULT_TIMEOUT_S)

    parser = argparse.ArgumentParser(
        prog="serial_tool",
@@ -944,8 +1172,10 @@ def build_parser():
    sub.add_parser("status", parents=[common], help="全状态 JSON")

    p = sub.add_parser("log", parents=[common], help="读日志（直接读文件，daemon 死也能用）")
-    p.add_argument("--tail", type=int, default=50, help="取末 N 行（默认 50；0 = 全部）")
-    p.add_argument("--grep", help="仅含子串的行")
+    p.add_argument("--tail", type=int, default=50, help="过滤后取末 N 行（默认 50；0 = 全部）")
+    p.add_argument("--grep", help="只留匹配行（默认子串匹配；先过滤后 tail）")
+    p.add_argument("-i", "--ignore-case", action="store_true", help="grep 忽略大小写")
+    p.add_argument("--regex", action="store_true", help="grep 按 Python re 正则")

    sub.add_parser("clear", parents=[common], help="清空日志（代际 +1）")

@@ -953,6 +1183,8 @@ def build_parser():
    p.add_argument("--settle-ms", type=int, default=8000,
                   help="静默判据毫秒（默认 8000：boot 有 3~4s 自然静默间隙）")
    p.add_argument("--max-ms", type=int, default=30000, help="最长等待毫秒（默认 30000）")
+    p.add_argument("--first-timeout-ms", type=int, default=0,
+                   help="首字节超时毫秒（0 = 同 --max-ms）：期间零字节即判 no_data")

    sub.add_parser("start", parents=[common], help="拉起 daemon（已在跑则直接返回）")
    sub.add_parser("stop", parents=[common], help="停止 daemon（关端口后退出）")
@@ -977,6 +1209,11 @@ def main(argv=None):
        parser.print_help()
        return 3

+    # --timeout 缺省解析：显式与否要留给 cmd_wait_idle（它按 --max-ms 自动推导）
+    args.timeout_explicit = args.timeout is not None
+    if args.timeout is None:
+        args.timeout = DEFAULT_TIMEOUT_S
+
    try:
        if args.command == "selftest":
            return run_selftest()