Files
STM32F4-Base/test/host/verify_log.py
T

449 lines
23 KiB
Python
Raw Blame History

This file contains ambiguous Unicode characters
This file contains Unicode characters that might be confused with other characters. If you think that this is intentional, you can safely ignore this warning. Use the Escape button to reveal them.
#!/usr/bin/env python3
"""verify_log.py - 对抓取的 MCU 调试日志做标记校验(纯标准库,2026-09-20 替代 verify_log.ps1)。
用于 @test 闭环:烧录后从串口助手日志提取的开机日志交给本脚本 grep 标记,
输出结构化判定(格式与旧 PowerShell 版逐字一致,下游文档/习惯不受影响)。
用法:
& '.venv\\Scripts\\python.exe' test/host/verify_log.py --log-path <file>
[--required 'marker1;marker2']
[--forbidden 'FAIL;ERROR;HardFault;assert;[ERR]']
[--require-suite-summary 'Storage Tests;GD5F2GQ5UE Tests']
[--require-selftest-pass] [--selftest-log <selftest.log 本地副本>]
[--show-tail-lines 40]
[--max-boot-count 1] [--boot-marker 'reset cause:']
[--expect-reset-cause 'software;power-on']
[--require-order 'App init OK>Network Init>net init: OK']
[--done-marker 'net init: OK'] [--max-boot-ms 8000] [--json]
退出码(与旧版一致):
0 = PASS(所有 Required 标记找到,Forbidden 零命中,汇总行要求满足)
1 = FAIL(缺 Required / 命中 Forbidden / 汇总行要求不满足)
2 = ERROR(日志文件不存在/不可读)
默认 Required 标记对应 STM32F4-Base 启动序列(见 App/app/app_main.c + App/task/net_task.c),
按测试用例覆盖,例如:
--required 'App init OK;net init: OK;PHY: 100M FULL'
--forbidden 'FAIL;ERROR;HardFault;assert;[ERR]'
语义约定(与旧 PowerShell 版对齐):
- Required:大小写敏感子串匹配(全文)
- Forbidden:大小写**不敏感**子串匹配、逐行计数(旧版 -like 语义;
如 Forbidden 'FAIL' 会命中 "write /log/run.log fail (7)" 这类行)
- 固件错误级日志前缀是 `[ERR]`(`DBG_ERROR`,形如 `[时间][ERR][TAG] 消息`),
与 `ERROR` 子串**不匹配**——默认 Forbidden 因此显式包含 `[ERR]`,驱动/模块
错误行不再漏检(2026-09-21 修复)。测试套件中**预期**出现 `[ERR]` 的用例
(如 GD5F DMA 守卫负路径、FatFs 非法名校验)须用 --forbidden 覆盖默认值。
- 读取编码:先按 UTF-8,解码失败回退系统 locale 编码(旧版 Get-Content 行为)
- 控制台输出重配置为 UTF-8(errors=replace):任何 Windows 控制台代码页
都只影响终端显示,不会导致本脚本崩溃
- 汇总行(2026-10-01 加,T-2):纯 Required 子串匹配有个盲区——套件启动横幅
命中即判 PASS,**套件是否跑到汇总行、断言数是否为 0 完全不可见**(套件中途
挂死/复位、或 Phase 宏全关时会被误判为通过)。`--require-suite-summary`
要求日志中出现 `=== <名称>: N/M PASSED (failed=0) ===` 且 **N > 0**。
- 自检记录联合判定(S7,2026-10 实机窗口):`--require-selftest-pass` 对 /log/selftest.log
的本地副本(定长 64B 记录,格式见 App/log/sys_log.h)判定。自检仅故障写盘(v1 不记
通过项):**文件缺失 / 0 字节 = 无故障 → PASS**;存在任何一条记录 = 有故障 → FAIL
(退出码 1),并逐条打印时间戳 + 描述。抓取失败(设备不可达 / FTP 错误等)由调用方
(run_boot_test.py)先打 WARN,本地文件按缺失处理 → 按上述规则不判整体 FAIL。
- 启动锚点计数(2026-10-10):`--max-boot-count N`(run_boot_test.py 默认传 1)统计
`reset cause:` 锚点出现次数——**0 次** = 采集没从复位开始(标记全中也可能只是上一轮
的残留日志);**>N 次** = 板子在采集窗口内自己复位过(IWDG 咬狗 / Fault 后
`NVIC_SystemReset` / 掉电重启),此前这类运行只要不命中 Forbidden 就判 PASS。
`--expect-reset-cause` 对第一个锚点做原因白名单(大小写不敏感子串),空 = 只报告不判。
- Forbidden 命中行(2026-10-10):命中时逐行打印**行号 + 内容**(最多 6 行,超出报剩余数)。
旧实现只说 `forbidden pattern: [ERR] (3 line(s))`,人还得自己再 grep 一遍才知道是哪几行
——而"是哪几行"恰恰是定位要的东西。
- 标记顺序(`--require-order 'a>b>c'`):按**首次出现的行序**校验启动步骤先后。标记全中
但顺序颠倒 = 某步在另一步之后补做(屏障失序、重试后补跑),旧实现完全看不见。
- 开机耗时(`--done-marker` + `--max-boot-ms`):依赖行首 `[+Nms]` 前缀(run_boot_test.py
2026-10-10 起按 daemon 毫秒时基给每行加,MCU 侧时间戳只有秒级且开机头几行根本没有)。
量"第一行 → done-marker"的真实耗时,抓"能开机但慢了几秒"(mount 重试 / PHY 重协商)。
日志里没有该前缀 → 只 WARN 跳过,不假判 FAIL。
- `--json`:同一套判定以 JSON 输出(供 CI / 上层脚本消费;退出码语义不变)。
"""
import argparse
import json
import locale
import re
import sys
from pathlib import Path
REQUIRED_DEFAULT = "App init OK;Network Init;net init: OK"
FORBIDDEN_DEFAULT = "FAIL;ERROR;HardFault;assert;[ERR]"
# Forbidden 命中时最多打印几条命中行(够定位又不刷屏;剩余条数会报出来)
HIT_LINES_MAX = 6
# 行首 `[+1234ms] `:run_boot_test.py 按 daemon 毫秒时基给每行加的相对偏移
# (MCU 侧时间戳只有秒级,且开机头几行时钟还没起 → 量不了耗时)
_TS_OFF_RE = re.compile(r"^\[\+(\d+)ms\]\s")
# 每轮启动的锚点行(App/app/app_main.c:`reset cause: <原因> (CSR=0x…)`)。
# 一次采集里出现 >1 次 = 板子在采集窗口内自己复位过(IWDG 咬狗 / Fault 后
# NVIC_SystemReset / 掉电重启),此前只有 Forbidden 命中时才被发现,
# "跑完 PASS 但中途重启过"完全不可见(2026-10-10 加)。
BOOT_MARKER_DEFAULT = "reset cause:"
# 套件汇总行:`=== Storage Tests: 3/3 PASSED (failed=0) ===`
# 名称可含空格;N/M 为十进制;failed 允许前导 0。宽松容忍前后空白与
# 日志时间戳前缀(`[2026-10-01 12:00:00.000]`)——故用 search 而非 match。
_SUMMARY_RE = re.compile(
r"===\s*(?P<name>[^:=]+?)\s*:\s*(?P<passed>\d+)\s*/\s*(?P<total>\d+)\s+"
r"PASSED\s*\(\s*failed\s*=\s*(?P<failed>\d+)\s*\)\s*==="
)
def _split_list(spec):
"""';' 分隔列表 → 去空白、去空项。"""
return [p.strip() for p in spec.split(";") if p.strip()]
def _read_lines(path):
raw = Path(path).read_bytes()
for enc in ("utf-8", locale.getpreferredencoding(False)):
try:
return raw.decode(enc).splitlines()
except UnicodeDecodeError:
continue
return raw.decode("utf-8", errors="replace").splitlines()
def _reset_cause_of(line, marker):
"""从 `reset cause: software (NVIC_SystemReset) (CSR=0x14000000)` 取原因文本。"""
i = line.find(marker)
if i < 0:
return ""
tail = line[i + len(marker):].strip()
j = tail.find(" (CSR=")
return tail[:j] if j > 0 else tail
def verify(log_path, required=REQUIRED_DEFAULT, forbidden=FORBIDDEN_DEFAULT,
show_tail=40, out=print, suite_summary="",
selftest_pass=False, selftest_log="",
boot_marker=BOOT_MARKER_DEFAULT, max_boot_count=0,
expect_reset_cause="", require_order="", done_marker="",
max_boot_ms=0, as_json=False):
"""标记校验核心(可被 run_boot_test.py 复用)。返回退出码 0/1/2。
suite_summary: ';' 分隔的套件名列表。非空时,要求日志中每个套件都出现
`=== <名称>: N/M PASSED (failed=0) ===` 且 **N > 0**。
selftest_pass: True 时对 selftest_log(/log/selftest.log 本地副本)联合判定:
文件缺失 / 0 字节 = 无故障(PASS);存在任何 64B 记录 = FAIL(S7)。
selftest_log: 自检记录文件本地路径(空串 = 按文件缺失处理)。
boot_marker / max_boot_count(2026-10-10):统计启动锚点出现次数。
max_boot_count>0 时启用:0 次 = 采集没从复位开始;>N 次 = 板子
在采集窗口内自己复位过(IWDG / Fault 后 NVIC_SystemReset)。
expect_reset_cause: ';' 分隔的原因子串白名单,只对**第一个**锚点生效(大小写不敏感)。
空 = 只报告不判定。
require_order: '>' 分隔的标记序列(2026-10-10),按**首次出现的行序**校验先后;
顺序颠倒 = 某步在另一步之后补做(屏障失序 / 重试补跑)。空 = 不查。
done_marker / max_boot_ms(2026-10-10):量"第一行 → done_marker"的毫秒耗时
(靠行首 `[+Nms]` 前缀);超过 max_boot_ms 判 FAIL。
日志无该前缀 → WARN 跳过,不假判。
as_json: True = 不打印文本判定,最后输出一个 JSON 对象(退出码不变)。
"""
res = {"log_path": str(log_path), "lines": 0, "bytes": 0, "required_missing": [],
"forbidden_hits": [], "boot": None, "suites_bad": [], "selftest": None,
"order_bad": [], "timing": None, "tail": [], "verdict": None, "exit": None}
emit = out
def finish(code):
res["exit"] = code
res["verdict"] = {0: "PASS", 1: "FAIL", 2: "ERROR"}[code]
if as_json:
emit(json.dumps(res, ensure_ascii=False, indent=2))
return code
if as_json:
out = lambda *a, **k: None # 文本判定静默,结果走 JSON
p = Path(log_path)
if not p.is_file():
out("VERIFY_ERROR: log file not found: {}".format(log_path))
return finish(2)
try:
lines = _read_lines(log_path)
except OSError:
out("VERIFY_ERROR: cannot read log file: {}".format(log_path))
return finish(2)
full = "\n".join(lines)
req_list = _split_list(required)
forb_list = _split_list(forbidden)
summary_list = _split_list(suite_summary)
out("=== Log verdict: {} ===".format(log_path))
out("Lines: {}, bytes: {}".format(len(lines), p.stat().st_size))
res["lines"] = len(lines)
res["bytes"] = p.stat().st_size
missing = []
for m in req_list:
if m in full:
out("[OK] required marker found: {}".format(m))
else:
out("[MISS] required marker NOT found: {}".format(m))
missing.append(m)
res["required_missing"] = list(missing)
hits = []
for f in forb_list:
fl = f.lower()
matched = [(i + 1, ln) for i, ln in enumerate(lines) if fl in ln.lower()]
if matched:
out("[HIT] forbidden pattern: {} ({} line(s))".format(f, len(matched)))
# 命中行必须打出来(2026-10-10):旧实现只报 "(3 line(s))",人还得自己
# 再 grep 一遍才知道是哪几行——而"哪几行"正是定位所需的那一步
for ln_no, ln in matched[:HIT_LINES_MAX]:
out(" L{}: {}".format(ln_no, ln.strip()[:200]))
if len(matched) > HIT_LINES_MAX:
out(" ... {} more".format(len(matched) - HIT_LINES_MAX))
hits.append(f)
res["forbidden_hits"].append({
"pattern": f, "count": len(matched),
"lines": [{"no": n, "text": t.strip()[:200]}
for n, t in matched[:HIT_LINES_MAX]]})
else:
out("[OK] forbidden pattern absent: {}".format(f))
# 启动锚点计数(2026-10-10):抓"跑完但中途复位过"和"采集没从复位开始"
boot_issue = False
if max_boot_count > 0:
banner_lines = [ln for ln in lines if boot_marker in ln]
n_boot = len(banner_lines)
causes = [_reset_cause_of(ln, boot_marker) for ln in banner_lines]
if n_boot == 0:
out("[FAIL] no boot banner (marker '{}'): capture did not start at a reset".format(
boot_marker))
boot_issue = True
elif n_boot > max_boot_count:
out("[FAIL] boot banner x{} > allowed {} -> board reset itself during capture".format(
n_boot, max_boot_count))
for ln in banner_lines[:6]:
out(" {}".format(ln.strip()))
boot_issue = True
else:
out("[OK] boot banner x{} (marker '{}')".format(n_boot, boot_marker))
if causes:
out("[INFO] reset cause(s): {}".format("; ".join(causes)))
exp = _split_list(expect_reset_cause)
if exp:
got = causes[0].lower()
if any(e.lower() in got for e in exp):
out("[OK] reset cause '{}' matches expected {}".format(
causes[0], expect_reset_cause))
else:
out("[FAIL] reset cause '{}' not in expected: {}".format(
causes[0], expect_reset_cause))
boot_issue = True
res["boot"] = {"marker": boot_marker, "count": n_boot, "allowed": max_boot_count,
"causes": causes, "issue": boot_issue}
# 标记顺序(2026-10-10):标记全中但**顺序颠倒** = 某步在另一步之后补做
# (屏障失序 / 失败重试补跑)。旧实现只看子串存在性,这类失序完全看不见。
order_issue = False
if require_order:
seq = [s.strip() for s in require_order.split(">") if s.strip()]
pos = []
for m in seq:
idx = next((i for i, ln in enumerate(lines) if m in ln), -1)
pos.append((m, idx))
absent = [m for m, i in pos if i < 0]
if absent:
out("[FAIL] require-order: marker(s) not found: {}".format("; ".join(absent)))
order_issue = True
else:
bad = [(pos[k][0], pos[k + 1][0]) for k in range(len(pos) - 1)
if pos[k][1] > pos[k + 1][1]]
if bad:
out("[FAIL] marker order violated (expected {})".format(require_order))
for a, b in bad:
out(" '{}' first appeared AFTER '{}'".format(a, b))
for m, i in pos:
out(" L{}: {}".format(i + 1, m))
order_issue = True
else:
out("[OK] marker order ok: {}".format(require_order))
res["order_bad"] = [m for m, i in pos if i < 0] + [
"{}>{}".format(a, b) for a, b in
[(pos[k][0], pos[k + 1][0]) for k in range(len(pos) - 1) if pos[k][1] > pos[k + 1][1]]]
# 开机耗时(2026-10-10):行首 [+Nms] = daemon 毫秒时基的相对偏移
# (MCU 侧时间戳只有秒级,且开机头几行时钟还没起,量不出耗时)。
timing = None
timing_issue = False
offs = []
for i, ln in enumerate(lines):
m = _TS_OFF_RE.match(ln)
if m:
offs.append((i, int(m.group(1))))
if offs:
timing = {"ts_lines": len(offs), "first_ms": offs[0][1], "last_ms": offs[-1][1],
"span_ms": offs[-1][1] - offs[0][1]}
out("[INFO] capture span: +{}ms .. +{}ms ({} timestamped line(s))".format(
timing["first_ms"], timing["last_ms"], timing["ts_lines"]))
if done_marker:
di = next((i for i, ln in enumerate(lines) if done_marker in ln), -1)
if di < 0:
out("[WARN] done marker '{}' not found -> boot time not measured".format(
done_marker))
else:
doff = next((off for i, off in offs if i >= di), None)
if doff is None:
out("[WARN] done marker line has no [+Nms] prefix -> not measured")
else:
boot_ms = doff - offs[0][1]
timing["boot_ms"] = boot_ms
timing["done_marker"] = done_marker
out("[INFO] boot time to '{}': {} ms".format(done_marker, boot_ms))
if max_boot_ms > 0 and boot_ms > max_boot_ms:
out("[FAIL] boot time {} ms > limit {} ms".format(boot_ms, max_boot_ms))
timing_issue = True
elif done_marker or max_boot_ms > 0:
out("[WARN] no [+Nms] line prefix in this log -> timing checks skipped "
"(run_boot_test.py adds it; --raw-log turns it off)")
res["timing"] = timing
# 套件汇总行解析(T-2):抓"没跑到汇总行 / 断言数为 0"的盲区
bad_summary = []
if summary_list:
parsed = {}
for ln in lines:
m = _SUMMARY_RE.search(ln)
if m:
parsed.setdefault(m.group("name").strip(), []).append(m)
for name in summary_list:
cands = parsed.get(name)
if not cands:
out("[MISS] suite summary NOT found: '=== {}: N/M PASSED (failed=0) ==='".format(name))
bad_summary.append(name)
continue
ok = False
for m in cands:
passed = int(m.group("passed"))
total = int(m.group("total"))
failed = int(m.group("failed"))
if failed != 0:
out("[FAIL] suite summary reports failures: {} -> {}/{} PASSED (failed={})".format(
name, passed, total, failed))
continue
if total == 0:
out("[FAIL] suite summary total is 0 (no assertion ran): '{}'".format(name))
continue
if passed != total:
out("[FAIL] suite summary inconsistent: {} -> {}/{} PASSED".format(
name, passed, total))
continue
out("[OK] suite summary ok: {} -> {}/{} PASSED".format(name, passed, total))
ok = True
if not ok:
bad_summary.append(name)
res["suites_bad"] = list(bad_summary)
# 自检记录联合判定(S7):/log/selftest.log 定长 64B 记录(格式见 App/log/sys_log.h),
# 仅故障写盘:文件缺失 / 0 字节 = 无故障 → PASS;存在任何一条记录 → FAIL
selftest_fail = False
if selftest_pass:
sp = Path(selftest_log) if selftest_log else None
if sp is None or not sp.is_file() or sp.stat().st_size == 0:
out("[OK] selftest: no fault record (file missing or empty)")
res["selftest"] = {"path": str(sp) if sp else None, "faults": 0, "records": []}
else:
raw = sp.read_bytes()
n = len(raw) // 64
if len(raw) % 64:
out("[WARN] selftest log has {} trailing incomplete bytes (ignored)".format(len(raw) % 64))
recs = []
for i in range(n):
rec = raw[i * 64:(i + 1) * 64]
ts = rec[0:19].decode("ascii", errors="replace")
desc = rec[31:59].split(b"\0", 1)[0].decode("utf-8", errors="replace")
recs.append({"no": i, "ts": ts, "desc": desc})
res["selftest"] = {"path": str(sp), "faults": n, "records": recs}
if n > 0:
selftest_fail = True
out("[FAIL] selftest: {} fault record(s) in {}".format(n, selftest_log))
for r in recs:
out(" #{}: {} {}".format(r["no"], r["ts"], r["desc"]))
else:
out("[OK] selftest: no fault record (0 complete records)")
if show_tail > 0 and lines:
res["tail"] = lines[-show_tail:]
out("")
out("=== Last {} line(s) of log ===".format(show_tail))
for ln in lines[-show_tail:]:
out(ln)
out("")
if (missing or hits or bad_summary or selftest_fail or boot_issue
or order_issue or timing_issue):
out("VERDICT: FAIL")
return finish(1)
out("VERDICT: PASS")
return finish(0)
def main(argv=None):
# 控制台输出固定 UTF-8:Windows 代码页(GBK/UTF-8 终端)均不会让本脚本崩溃
for stream in (sys.stdout, sys.stderr):
try:
stream.reconfigure(encoding="utf-8", errors="replace")
except Exception:
pass
ap = argparse.ArgumentParser(description="MCU debug log marker check (pure stdlib)")
ap.add_argument("--log-path", required=True, help="boot log file to check")
ap.add_argument("--required", default=REQUIRED_DEFAULT,
help="required markers, ';' separated (case-sensitive)")
ap.add_argument("--forbidden", default=FORBIDDEN_DEFAULT,
help="forbidden patterns, ';' separated (case-insensitive)")
ap.add_argument("--require-suite-summary", default="",
help="suite names that MUST appear as '=== <name>: N/M PASSED (failed=0) ===' "
"with N>0, ';' separated (T-2). Empty = off")
ap.add_argument("--show-tail-lines", type=int, default=40,
help="show last N log lines (0 = off)")
ap.add_argument("--require-selftest-pass", action="store_true",
help="judge /log/selftest.log local copy (S7): "
"missing/empty = PASS, any 64B record = FAIL")
ap.add_argument("--selftest-log", default="",
help="local copy path of /log/selftest.log (with --require-selftest-pass)")
ap.add_argument("--boot-marker", default=BOOT_MARKER_DEFAULT,
help="per-boot banner substring (default '{}')".format(BOOT_MARKER_DEFAULT))
ap.add_argument("--max-boot-count", type=int, default=0,
help="fail if the boot banner appears 0 times or more than N times "
"(0 = check off). run_boot_test.py passes 1 by default")
ap.add_argument("--expect-reset-cause", default="",
help="';'-separated substrings the FIRST reset cause must match "
"(case-insensitive). Empty = report only, no verdict")
ap.add_argument("--require-order", default="",
help="'>'-separated markers that must appear in that line order "
"(e.g. 'App init OK>Network Init>net init: OK'). Empty = off")
ap.add_argument("--done-marker", default="",
help="marker whose line marks boot completion, for --max-boot-ms")
ap.add_argument("--max-boot-ms", type=int, default=0,
help="fail if time from first line to --done-marker exceeds N ms "
"(needs '[+Nms]' line prefix; 0 = off)")
ap.add_argument("--json", action="store_true",
help="emit one JSON object instead of the text verdict (exit code unchanged)")
args = ap.parse_args(argv)
return verify(args.log_path, args.required, args.forbidden,
args.show_tail_lines, suite_summary=args.require_suite_summary,
selftest_pass=args.require_selftest_pass,
selftest_log=args.selftest_log,
boot_marker=args.boot_marker,
max_boot_count=args.max_boot_count,
expect_reset_cause=args.expect_reset_cause,
require_order=args.require_order,
done_marker=args.done_marker,
max_boot_ms=args.max_boot_ms,
as_json=args.json)
if __name__ == "__main__":
sys.exit(main())