From b1280e3cd160400a7706012a2498687bb7566461 Mon Sep 17 00:00:00 2001 From: Wanderingss <1624155937@qq.com> Date: Mon, 26 Oct 2026 23:42:34 +0800 Subject: [PATCH] =?UTF-8?q?feat(=E5=8F=B0=E6=9E=B6=E5=B7=A5=E5=85=B7):=20?= =?UTF-8?q?=E5=8E=9F=E5=AD=90=E6=80=A7=E5=A4=8D=E9=AA=8C=E8=83=BD=E5=8A=9B?= =?UTF-8?q?=E5=B9=B6=E8=BF=9B=E6=97=A2=E6=9C=89=20verify=5Flog=20=E5=B9=B6?= =?UTF-8?q?=E6=8E=A5=E8=BF=9B=20@test=E2=80=94=E2=80=94=E6=97=A7=E5=8F=A3?= =?UTF-8?q?=E5=BE=84=E5=88=A4=20PASS=20=E7=9A=84=E7=BC=BA=E9=99=B7?= =?UTF-8?q?=E6=96=B0=E5=8F=A3=E5=BE=84=E5=88=A4=20FAIL?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 关键决定是**不造第二只校验器**：卡片原建议把校验器放进 scripts/，但「标记校验」这个 能力已归 .dsh/skills/serial-boot-test/scripts/verify_log.py，再造一只就是本仓反对的 实现漂移（reset.bat 折进技能是同一类判断）。改为扩展它 + 把开关接进 run_boot_test.py ——**不接就等于吸收了没人用得到**；默认路径逐字节不变（不传开关时 exact_check 根本不进）。 新增：--exact 整行锚定（并把「含最长字面串却未整行命中」的邻居原样打出来，那就是 行级交错的特征）、--pair 跨复位配对、--allow-residual 与 --head-char 服务崩溃注入腿、 --include-comments 复现旧行为、--selftest 判别自检。钉长度改成显式 @@LEN= 逃生口， **不再是默认**。 最硬的一条实证（进文档表格，也钉成一条 selftest 用例）：同一份缺陷捕获——行首被吃、 尾巴完好的那行 NAND_FTL——旧 --required 子串口径判 **PASS（假绿）**，--exact 判 **FAIL 并打出缺行首的邻居**。口径据此改写：凡是这一行可能丢行首或被插字节的标记，一律 --exact，不许只用子串。 实测不是声称：--selftest 16/16；真日志三向（修复后 PASS / 修复前 FAIL+邻居 / 带 ASCII 溯源头不再被头里的 [ERR] 误报）；被动烟测（--flash-cmd 置空 = 不烧录、不动板上镜像、 只采 60 行空闲流量，bench 锁取了即还）证明四个开关在 @test 闭环里**真的执行了**； 空闲流量里 PROF 行长 124/78/123 交替，顺手再证一次「钉长度当默认」会天天假红。 作者自报四个自己的问题（都被自测抓到并修掉，卡里也写了）：残留行被重复计成交错邻居 （会假红）、一条断言写反、**CLI 参数忘了接进 verify()——最危险那种：功能静默空跑而 外面看着全绿**、以及误报 run_boot_test.py 变 CRLF（实为自己的检查把换行符写成了字面 量，两个文件复核均为纯 LF，别按那句去查）。 boot_log_data/README.md 里同时有两个道的内容：bench23 的台账行，与 task-25 那条道写的 「证据可达性」规则与 force-add 定案——autostash 往返后两侧都逐一确认仍在。三份 bench23 证据 txt 首次入库（可再生的采集文本；两张非再生 .bin 已随前一笔入库）。 --- .dsh/skills/serial-boot-test/SKILL.md | 4 +- .../serial-boot-test/scripts/run_boot_test.py | 21 +- .../serial-boot-test/scripts/verify_log.py | 236 +++++- .../20261026_bench23_flash_boot_log.txt | 164 +++++ .../20261026_bench23_recheck_verdicts.txt | 44 ++ ...0261026_bench23_reset_only_boots_r1_r4.txt | 676 ++++++++++++++++++ docs/测试说明/boot_log_data/README.md | 37 +- docs/测试说明/启动日志原子性复验流程.md | 107 +++ docs/测试说明/自动化测试流程.md | 2 +- 9 files changed, 1283 insertions(+), 8 deletions(-) create mode 100644 docs/测试说明/boot_log_data/20261026_bench23_flash_boot_log.txt create mode 100644 docs/测试说明/boot_log_data/20261026_bench23_recheck_verdicts.txt create mode 100644 docs/测试说明/boot_log_data/20261026_bench23_reset_only_boots_r1_r4.txt create mode 100644 docs/测试说明/启动日志原子性复验流程.md diff --git a/.dsh/skills/serial-boot-test/SKILL.md b/.dsh/skills/serial-boot-test/SKILL.md index 7913bf35..9a775cfb 100644 --- a/.dsh/skills/serial-boot-test/SKILL.md +++ b/.dsh/skills/serial-boot-test/SKILL.md @@ -14,7 +14,9 @@ whenToUse: 需要向目标板烧录或复位后，用串口日志自动判定运 | 脚本 | 作用 | |---|---| | `.dsh/skills/serial-boot-test/scripts/run_boot_test.py` | 一键闭环：open+clear → 烧录 → wait-idle → 提取 boot log → 烧录回读校验 → 标记校验。串口助手按 `$DSH_SERIAL_TOOL` > 同目录 > `../serial-assistant/scripts/serial_tool.py` 解析 | -| `.dsh/skills/serial-boot-test/scripts/verify_log.py` | 对任意日志文件做标记校验（Required/Forbidden/锚点计数/顺序/耗时），可单独用 | +| `.dsh/skills/serial-boot-test/scripts/verify_log.py` | 对任意日志文件做标记校验（Required/Forbidden/锚点计数/顺序/耗时），可单独用。`--exact` 做**整行 `^…$` 锚定**（子串口径照不出"行还在但行首被吃掉/行内被插字节"那一类损坏）、`--pair` 做跨复位配对、`--allow-residual/--head-char` 服务崩溃注入腿、`--selftest` 跑内置判别用例（**证明这套判据不是空跑**）。四个行级开关（`--exact` / `--pair` / `--allow-residual` / `--head-char`）同时接进了 `run_boot_test.py`，@test 闭环直接可用 | + +> **判据取向（重要，会复发）**：`--exact` 默认**只锚文本、不钉长度**——字节长度属于某一份构建，钉死它会在无辜改动上假红（`@@LEN=` 是显式逃生口，不是默认）。子串 `--required` 不能用于"可能丢行首/被插字节"的行。来龙去脉与固定动作见本仓 `docs/测试说明/启动日志原子性复验流程.md`。 交互式串口操作（open/send/log/wait-idle/status 等）不属于本 skill—— **用 `serial-assistant` skill**。 diff --git a/.dsh/skills/serial-boot-test/scripts/run_boot_test.py b/.dsh/skills/serial-boot-test/scripts/run_boot_test.py index f53d793e..539e32f2 100644 --- a/.dsh/skills/serial-boot-test/scripts/run_boot_test.py +++ b/.dsh/skills/serial-boot-test/scripts/run_boot_test.py @@ -392,6 +392,23 @@ def main(argv=None): ap.add_argument("--require-order", default=None, help="'>'-separated markers that must appear in that line order " "(catches out-of-order boot steps); empty = off") + ap.add_argument("--exact", action="append", default=[], + help="repeatable regex that must match a WHOLE firmware line " + "(forwarded to verify_log.py --exact). Use it instead of --required " + "for any marker whose line could lose its head or gain spliced " + "bytes -- substring matching cannot see that class of damage. " + "Suffix '@@LEN=' pins byte length: opt-in only, lengths belong " + "to one image") + ap.add_argument("--pair", action="append", nargs=2, metavar=("FIRST", "THEN"), default=[], + help="repeatable cross-reset pairing (exactly one FIRST, then exactly " + "one THEN after it), e.g. --pair MEMFAULT 'reset cause:'") + ap.add_argument("--allow-residual", type=int, default=0, + help="accept up to N stray bytes before the line head on a --exact hit " + "(crash-dump legs: 1 leftover from a reset mid-byte is known; " + "recorded, not a failure)") + ap.add_argument("--head-char", default="", + help="every --exact hit must start with this char after the optional " + "residual prefix (crash-dump legs: '[')") ap.add_argument("--done-marker", default=None, help="marker whose line marks boot completion (for --max-boot-ms); " "empty = don't measure") @@ -743,7 +760,9 @@ def main(argv=None): expect_reset_cause=args.expect_reset_cause, require_order=args.require_order, done_marker=args.done_marker, - max_boot_ms=args.max_boot_ms) + max_boot_ms=args.max_boot_ms, + exact=args.exact, pairs=args.pair, + allow_residual=args.allow_residual, head_char=args.head_char) if selftest_forced_fail and rc == 0: # 标记校验全过，但自检台账判定根本没能执行（无数据源 / 抓取失败 / 无法证明无新增） # —— 这类"判不了"必须以 FAIL 收口，否则就又回到假绿。 diff --git a/.dsh/skills/serial-boot-test/scripts/verify_log.py b/.dsh/skills/serial-boot-test/scripts/verify_log.py index c0759ad6..e2f5a02c 100644 --- a/.dsh/skills/serial-boot-test/scripts/verify_log.py +++ b/.dsh/skills/serial-boot-test/scripts/verify_log.py @@ -114,6 +114,106 @@ def _read_lines(path): return raw.decode("utf-8", errors="replace").splitlines() +# --- whole-line exact matching (2026-10-26, task-36; absorbed from bench-runner scratch) --- +# Why this exists (measured, not theoretical): -Required is a SUBSTRING check, and the +# console-interleave defect kept the substring while destroying the line, e.g. the +# headless victim line "26-10-26 08:37:07][NAND_FTL] Initializing NAND FTL..." still +# contains the marker "Initializing NAND FTL" -> the old check called that boot a PASS. +# Any marker whose line can lose its head is therefore NOT verifiable by substring alone. +# --exact anchors the WHOLE payload (^ ... $) so one spliced byte breaks the match, and it +# also reports lines containing the pattern's longest literal run that do NOT match fully: +# that is the splicing signature and it must never stay silent. Length pinning is OPT-IN +# ("@@LEN="): byte lengths belong to one image, pinning them by default gives a false +# red on innocent commits (measured uiTask stack swing 4116..4188 on ONE image). +EXACT_LEN_SEP = "@@LEN=" +_DAEMON_RX = re.compile(r"^\[RX\] \S+ (.*)$") +_RUNBT_RX = re.compile(r"^\[\+\d+ms\] (.*)$") + + +def _parse_exact(spec): + """'REGEX@@LEN=42' -> (regex, 42); no suffix -> (regex, None).""" + if EXACT_LEN_SEP in spec: + pat, _, ln = spec.rpartition(EXACT_LEN_SEP) + return pat, int(ln.strip()) + return spec, None + + +def _payload_of(line): + """Drop the collector prefix so ^...$ applies to the firmware line itself. + + Handles serial-assistant daemon lines ('[RX] ...'), run_boot_test boot logs + ('[+Nms] ...') and bare payload lines. Archived evidence files may carry a leading + '#' provenance header; those are dropped unless include_comments is set (otherwise a + header that merely MENTIONS [ERR] would trip Forbidden / pollute exact counts). + """ + for rx in (_DAEMON_RX, _RUNBT_RX): + m = rx.match(line) + if m: + return m.group(1) + return line + + +def _longest_literal(pattern): + """Longest run of non-metacharacters in a regex -> a greppable neighbour probe.""" + parts = re.split(r"\\.|\\\[|\]|\(|\)|\{|\}|\||\*|\+|\?|\^|\$|\.|\[:", pattern) + parts = [x for x in parts if x and not x.startswith("\\")] + return max(parts, key=len) if parts else "" + + +def exact_check(payloads, spec, allow_residual=0, head_char=""): + """(ok, detail, neighbours, residuals) for one --exact spec. See block note above.""" + pat, want_len = _parse_exact(spec) + rx = re.compile("^" + pat + "$") + hits, residuals, consumed = [], [], set() + for idx, pl in enumerate(payloads): + if rx.match(pl): + hits.append(pl) + consumed.add(idx) + continue + if allow_residual > 0: + for k in range(1, allow_residual + 1): + if len(pl) > k and pl[k] == "[" and rx.match(pl[k:]): + hits.append(pl[k:]) + residuals.append((k, pl[:k])) + consumed.add(idx) + break + key = _longest_literal(pat) + # a line counted (directly or after residual realignment) is never also a neighbour + neigh = [pl for i2, pl in enumerate(payloads) if key and key in pl and i2 not in consumed] + detail = "hits={} lens={} loose_neighbours={}".format( + len(hits), [len(h) for h in hits], len(neigh)) + if residuals: + detail += " residual_head_bytes={}".format([(k, repr(v)) for k, v in residuals]) + ok = len(hits) >= 1 and not neigh + if want_len is not None: + ok = ok and all(len(h) == want_len for h in hits) + detail += " want_len={}".format(want_len) + if head_char: + bad = [h for h in hits if not h.startswith(head_char)] + ok = ok and not bad + detail += " head_char={!r} bad={}".format(head_char, len(bad)) + return ok, detail, neigh[:3], residuals[:3] + + +def pair_check(payloads, first_pat, then_pat): + """Exactly one FIRST line with exactly one THEN line after it (cross-reset pairing). + + Crash-dump legs need this: the fault line must pair with the NEXT boot's reset cause, + and a second following cause would mean an unlogged or repeated reset. + """ + frx, trx = re.compile(first_pat), re.compile(then_pat) + fi = [i for i, pl in enumerate(payloads) if frx.search(pl)] + ti = [i for i, pl in enumerate(payloads) if trx.search(pl)] + if len(fi) != 1: + return False, "first matches={} (want exactly 1), then matches={}".format(len(fi), len(ti)) + after = [i for i in ti if i > fi[0]] + if len(after) != 1: + return False, "first at L{} but following THEN count={} at {} (want exactly 1)".format( + fi[0] + 1, len(after), [x + 1 for x in after]) + return True, "first L{} -> only following THEN at L{} (gap {} line(s))".format( + fi[0] + 1, after[0] + 1, after[0] - fi[0]) + + def _reset_cause_of(line, marker): """从 `reset cause: software (NVIC_SystemReset) (CSR=0x14000000)` 取原因文本。""" i = line.find(marker) @@ -129,7 +229,8 @@ def verify(log_path, required=REQUIRED_DEFAULT, forbidden=FORBIDDEN_DEFAULT, 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): + max_boot_ms=0, as_json=False, exact=None, pairs=None, + allow_residual=0, head_char="", include_comments=False): """标记校验核心（可被 run_boot_test.py 复用）。返回退出码 0/1/2。 suite_summary: ';' 分隔的套件名列表。非空时，要求日志中每个套件都出现 @@ -151,7 +252,8 @@ def verify(log_path, required=REQUIRED_DEFAULT, forbidden=FORBIDDEN_DEFAULT, """ 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} + "order_bad": [], "timing": None, "tail": [], "verdict": None, "exit": None, + "exact_bad": [], "exact_ok": [], "pair_bad": [], "pair_ok": []} emit = out def finish(code): @@ -173,6 +275,10 @@ def verify(log_path, required=REQUIRED_DEFAULT, forbidden=FORBIDDEN_DEFAULT, except OSError: out("VERIFY_ERROR: cannot read log file: {}".format(log_path)) return finish(2) + if not include_comments: + # archived evidence files carry an ASCII provenance header; a header that merely + # MENTIONS [ERR] must not trip Forbidden (tool-level false-red guard, task-36) + lines = [l for l in lines if not l.lstrip().startswith("#")] full = "\n".join(lines) req_list = _split_list(required) @@ -213,6 +319,37 @@ def verify(log_path, required=REQUIRED_DEFAULT, forbidden=FORBIDDEN_DEFAULT, else: out("[OK] forbidden pattern absent: {}".format(f)) + # ---- whole-line exact checks + cross-reset pairing (task-36) ---- + payloads = [_payload_of(l) for l in lines] + res["payload_lines"] = len(payloads) + exact_bad = [] + for spec in (exact or []): + pat, _want = _parse_exact(spec) + ok_x, detail, neigh, residuals = exact_check(payloads, spec, allow_residual, head_char) + if ok_x: + out("[OK] exact line: {} {}".format(pat[:64], detail)) + res["exact_ok"].append({"pattern": pat, "detail": detail}) + else: + out("[FAIL] exact line: {} {}".format(pat[:64], detail)) + for nb in neigh: + out(" inexact neighbour: {}".format(nb.strip()[:170])) + exact_bad.append(pat) + res["exact_bad"].append({"pattern": pat, "detail": detail, + "neighbours": [n.strip()[:170] for n in neigh]}) + for k, v in residuals: + out("[NOTE] {} residual byte(s) before the line head, realigned and NOT a " + "failure: {}".format(k, repr(v))) + pair_bad = [] + for f_pat, t_pat in (pairs or []): + ok_p, detail = pair_check(payloads, f_pat, t_pat) + if ok_p: + out("[OK] pair: {} -> {}".format(f_pat[:44], t_pat[:44])) + res["pair_ok"].append({"first": f_pat, "then": t_pat, "detail": detail}) + else: + out("[FAIL] pair: {} -> {} {}".format(f_pat[:44], t_pat[:44], detail)) + pair_bad.append({"first": f_pat, "then": t_pat, "detail": detail}) + res["pair_bad"].append(detail) + # 启动锚点计数（2026-10-10）：抓"跑完但中途复位过"和"采集没从复位开始" boot_issue = False if max_boot_count > 0: @@ -384,13 +521,75 @@ def verify(log_path, required=REQUIRED_DEFAULT, forbidden=FORBIDDEN_DEFAULT, out("") if (missing or hits or bad_summary or selftest_fail or boot_issue - or order_issue or timing_issue): + or order_issue or timing_issue or exact_bad or pair_bad): out("VERDICT: FAIL") return finish(1) out("VERDICT: PASS") return finish(0) +def selftest(out=print): + """Prove the exact/pair machinery actually discriminates (exit 0 = all behaviours ok). + + Written because a PASS that cannot fail is worthless: case 2/3 are the real captured + shapes of the 2026-10-26 console-interleave defect, and case 9 shows that the legacy + substring check calls the SAME defective line a PASS -- that is the blind spot --exact + exists to close. + """ + T = "[2026-10-26 08:00:00]" + prot_re = (r"\[\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}\]\[PROT\] uncalibrated -> protection " + r"blocked \(UA/UN/IA VALID not all set\)") + nand_re = r"\[\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}\]\[NAND_FTL\] Initializing NAND FTL\.\.\." + prot_ok = T + "[PROT] uncalibrated -> protection blocked (UA/UN/IA VALID not all set)" + prot_spliced = T + "[PROT] uncalibrated -> protection [blocked (UA/UN/IA VALI2D not all s0et)" + nand_ok = T + "[NAND_FTL] Initializing NAND FTL..." + nand_headless = "26-10-26 08:37:07][NAND_FTL] Initializing NAND FTL..." + mem_re = r"\[ERR\] MEMFAULT PC=\S+ LR=\S+ CFSR=\S+ HFSR=\S+" + mem_ok = "[ERR] MEMFAULT PC=0x08004a12 LR=0x08004a3f CFSR=0x00008200 HFSR=0x40000000" + rc_ok = T + "[APP] reset cause: software (NVIC_SystemReset) (CSR=0x14000000)" + cases = [] + + def chk(name, got, want): + cases.append((name, got == want, "got={!r} want={!r}".format(got, want))) + + chk("clean exact", exact_check([prot_ok], prot_re)[0], True) + ok_s, _d_s, neigh_s, _r_s = exact_check([prot_spliced], prot_re) + chk("spliced line rejected", ok_s, False) + chk("spliced line fails even with broken probe key", len(neigh_s), 0) + ok_n, _d_n, neigh_n, _r_n = exact_check([nand_headless], nand_re) + chk("headless line rejected", ok_n, False) + chk("headless line reported as neighbour", len(neigh_n) >= 1, True) + chk("residual 1 rejected when not allowed", exact_check(["#" + nand_ok], nand_re)[0], False) + ok_r, det_r, _n_r, res_r = exact_check(["#" + nand_ok], nand_re, allow_residual=1) + chk("residual 1 accepted when allowed", ok_r and len(res_r) == 1, True) + chk("residual 2 still rejected", exact_check(["##" + nand_ok], nand_re, allow_residual=1)[0], False) + chk("head_char enforced", exact_check([nand_ok], nand_re, 0, "[")[0], True) + chk("head_char catches wrong head", exact_check([nand_headless], r"26-10-26.*NAND_FTL.*", 0, "[")[0], False) + chk("len pin ok", exact_check([nand_ok], nand_re + EXACT_LEN_SEP + str(len(nand_ok)))[0], True) + chk("len pin mismatch fails", exact_check([nand_ok], nand_re + EXACT_LEN_SEP + "9")[0], False) + chk("pair good", pair_check([mem_ok, rc_ok], "MEMFAULT", "reset cause:")[0], True) + chk("pair two following causes fails", + pair_check([mem_ok, rc_ok, rc_ok], "MEMFAULT", "reset cause:")[0], False) + chk("pair wrong order fails", + pair_check([rc_ok, mem_ok], "MEMFAULT", "reset cause:")[0], False) + # blind spot: legacy substring would PASS on this defective line + full = "\n".join([prot_ok, nand_headless]) + legacy_present = "Initializing NAND FTL" in full # what --required sees + exact_ok_here = exact_check([prot_ok, nand_headless], nand_re)[0] + chk("blind spot proven: legacy substring PASSES where --exact FAILS", + legacy_present and not exact_ok_here, True) + + bad = 0 + for name, ok, detail in cases: + out("{} {}".format("[OK] " if ok else "[FAIL]", name)) + if not ok: + out(" {}".format(detail)) + bad += 1 + out("SELFTEST: {} case(s), {} failure(s) -> {}".format( + len(cases), bad, "PASS" if bad == 0 else "FAIL")) + return 0 if bad == 0 else 1 + + def main(argv=None): # 控制台输出固定 UTF-8：Windows 代码页（GBK/UTF-8 终端）均不会让本脚本崩溃 for stream in (sys.stdout, sys.stderr): @@ -431,10 +630,36 @@ def main(argv=None): 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("--exact", action="append", default=[], + help="repeatable regex that must match a WHOLE firmware line " + "(collector prefix stripped, anchored ^...$); a spliced byte or a " + "missing line head fails. Optional suffix '@@LEN=' pins the byte " + "length -- opt-in only, lengths belong to one image. Use --exact " + "instead of --required for any marker whose line can lose its head.") + ap.add_argument("--allow-residual", type=int, default=0, + help="accept up to N stray bytes before the line head on an --exact hit " + "(crash-dump legs: 1 shift-register leftover is known; recorded, " + "not a failure). 0 = strict (default)") + ap.add_argument("--head-char", default="", + help="every --exact hit must start with this char right after the " + "optional residual prefix (crash-dump legs: '[')") + ap.add_argument("--pair", action="append", nargs=2, metavar=("FIRST", "THEN"), default=[], + help="repeatable pair: exactly one FIRST line, and exactly one THEN line " + "after it (cross-reset pairing, e.g. 'MEMFAULT' 'reset cause:')") + ap.add_argument("--include-comments", action="store_true", + help="do NOT skip '#' lines (archived evidence files carry an ASCII " + "provenance header; skipping it is the default so a header that " + "merely mentions [ERR] cannot trip --forbidden)") + ap.add_argument("--selftest", action="store_true", + help="run the built-in discrimination cases and exit (0 = all behave " + "as specified); needs no log file and no hardware") 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) + if args.selftest: + return selftest() + 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, @@ -445,7 +670,10 @@ def main(argv=None): require_order=args.require_order, done_marker=args.done_marker, max_boot_ms=args.max_boot_ms, - as_json=args.json) + as_json=args.json, + exact=args.exact, pairs=args.pair, + allow_residual=args.allow_residual, head_char=args.head_char, + include_comments=args.include_comments) if __name__ == "__main__": diff --git a/docs/测试说明/boot_log_data/20261026_bench23_flash_boot_log.txt b/docs/测试说明/boot_log_data/20261026_bench23_flash_boot_log.txt new file mode 100644 index 00000000..5f549c12 --- /dev/null +++ b/docs/测试说明/boot_log_data/20261026_bench23_flash_boot_log.txt @@ -0,0 +1,164 @@ +# provenance (ASCII header; payload below is the verbatim boot log from run_boot_test.py) +# commit : 1d4b6a17 fix(console): whole-line exclusive during the un-registered window +# built in the READ-ONLY detached worktree D:/Code/DTU Code/_wt/bench-23-1d4b6a17 +# (main tree is at the same commit but carries ui lane task-6 uncommitted work, +# so the image was deliberately NOT built from the main tree) +# build : @build 2026-10-26 19:43, rc=0, "0 Error(s), 0 Warning(s)" +# Program Size: Code=228812 RO-data=25060 RW-data=1456 ZI-data=135976 +# image stamp : fw build: Oct 26 2026 19:43:23 suite=NONE dstr=off (product, destructive OFF) +# flash : -P 0x08000000 -Rst -Run -> Programming Complete; log captured; THEN -CmpFile +# -> READBACK: OK (no difference found) [order per the reset-semantics rule] +# this boot : the FLASH boot (task-30 also ran 4 further reset-only boots, see the other file) +# verdict : run_boot_test rc=0 PASS; verifier rc=0 PASS ([ERR]=0, both victim lines byte-exact, +# anchor x1, no Fault, comm init OK, heap identical to previous round) + +[+0ms] [----/--/-- --:--:--][APP] boot: syslog init OK +[+0ms] [----/--/-- --:--:--][APP] fw build: Oct 26 2026 19:43:23 suite=NONE dstr=off +[+10ms] [----/--/-- --:--:--][APP] reset cause: software (NVIC_SystemReset) (CSR=0x14000000) +[+21ms] PREVRUN seg=2 seq=2157782617 t=9536985 +[+21ms] TICKRUN uw=9536997 n=9536997 duw=12 +[+21ms] [----/--/-- --:--:--][RTC] sd2506_init: OK +[+32ms] [----/--/-- --:--:--][APP] SD2506 init: OK (ret=0) +[+32ms] [2026-10-26 11:45:40][CLK] sys_clock_init: RTC initial time 2026-10-26 11:45:40 +[+42ms] [2026-10-26 11:45:40][CLK] sys_clock_init: wall clock base = unix 1793015140, base_tick=139 +[+53ms] [2026-10-26 11:45:40][APP] RS485 init: OK (UART4, DE=PA15) +[+63ms] [2026-10-26 11:45:40][NAND] Resetting NAND... +[+84ms] [2026-10-26 11:45:40][NAND] Reading NAND ID... +[+84ms] [2026-10-26 11:45:40][NAND] NAND ID: MID=0xC8, DID=0x52 +[+94ms] [2026-10-26 11:45:40][NAND] Scanning bad blocks... +[+221ms] [2026-10-26 11:45:40][NAND] BBT scan: 0 bad blocks found +[+231ms] [2026-10-26 11:45:40][NAND] Enabling ECC... +[+231ms] [2026-10-26 11:45:40][NAND] Unlocking block protection... +[+242ms] [2026-10-26 11:45:40][NAND] Locating BBT pool... +[+242ms] [2026-10-26 11:45:40][NAND] Loading persisted BBT... +[+252ms] [2026-10-26 11:45:40][NAND] NAND init OK +[+252ms] [2026-10-26 11:45:40][APP] NAND init: OK +[+262ms] [2026-10-26 11:45:40][ADC] Init OK +[+262ms] [2026-10-26 11:45:40][APP] ADC init: OK +[+262ms] [2026-10-26 11:45:40][APP] ADC input layer init: OK +[+273ms] [2026-10-26 11:45:40][APP] phasor layer init: OK (inst=5) +[+273ms] [2026-10-26 11:45:40][APP] freq layer init: OK +[+283ms] [2026-10-26 11:45:40][CFG] register: section 'adc_cal' (9 keys) +[+283ms] [2026-10-26 11:45:40][CFG] register: section 'adc_cal_ofs' (8 keys) +[+294ms] [2026-10-26 11:45:40][APP] adc cal init: OK (k_q16 tpafe=10000000 stm32=52800000) +[+294ms] [2026-10-26 11:45:40][CFG] register: section 'run_par' (9 keys) +[+304ms] [2026-10-26 11:45:40][APP] run par init: OK (db9 k/b via adc_cal, evt=1<<8) +[+315ms] [2026-10-26 11:45:40][CFG] register: section 'comm' (2 keys) +[+315ms] [2026-10-26 11:45:40][APP] comm init: OK (ca=1 port=2404) +[+325ms] [2026-10-26 11:45:40][APP] protection init: OK (set=40 elm=9) +[+335ms] [2026-10-26 11:45:40][APP] SD2506 ID: 2512153425482405 +[+335ms] [2026-10-26 11:45:40][APP] SD2506 time: 2026-10-26 11:45:41 (week 1) +[+346ms] [2026-10-26 11:45:40][APP] SD2506 temp: 25 C +[+346ms] [2026-10-26 11:45:40][APP] SD2506 battery: 3.12 V +[+357ms] [2026-10-26 11:45:40][APP] App init OK +[+357ms] [2026-10-26 11:45:40][NAND_FTL] Initializing NAND FTL... +[+388ms] [2026-10-26 11:45:40][PROT] uncalibrated -> protection blocked (UA/UN/IA VALID not all set) +[+461ms] [2026-10-26 11:45:40][NAND_FTL] Map resumed: 14094/97504 sectors used +[+461ms] [2026-10-26 11:45:40][NAND_FTL] Map head=49568 tail=2486 epoch=7 +[+473ms] [2026-10-26 11:45:40][NAND_FTL] NAND FTL ready (capacity: 97504 pages = 190 MB) +[+555ms] [2026-10-26 11:45:40] [FS] FATFS mounted +[+618ms] [2026-10-26 11:45:40][SYSLOG] runlog boot entry: power on +[+618ms] [2026-10-26 11:45:40][CFG] register: section 'network' (4 keys) +[+628ms] [2026-10-26 11:45:40][CFG] register: section 'ftp' (3 keys) +[+639ms] [2026-10-26 11:45:40][CFG] load: OK (957B, heap free 16552B) +[+639ms] [2026-10-26 11:45:40][NET_CFG] load: OK ip=192.168.1.100 +[+650ms] [2026-10-26 11:45:40] [CFG] prot set loaded (/prot_set.bin) +[+712ms] [2026-10-26 11:45:40][ADC_TASK] first: UA=11430 UB=1063 UC=900 UN=11453 IA=11452 IB=1050 IC=1035 IN=919 T=1002 +[+723ms] [2026-10-26 11:45:40][ADC_TASK] phasor(first) C01-IA-F1: Re=0 Im=0 rms=0 (x0.1) +[+733ms] [2026-10-26 11:45:40][ADC_TASK] phasor(first) C02-UA-F1: Re=0 Im=0 rms=0 (x0.1) +[+733ms] [2026-10-26 11:45:40][ADC_TASK] phasor(first) C03-UN-F1: Re=0 Im=0 rms=0 (x0.1) +[+744ms] [2026-10-26 11:45:40][ADC_TASK] phasor(first) C04-IA-F2: Re=0 Im=0 rms=0 (x0.1) +[+755ms] [2026-10-26 11:45:40][ADC_TASK] phasor(first) C05-IA-F5: Re=0 Im=0 rms=0 (x0.1) +[+755ms] [2026-10-26 11:45:40][ADC_TASK] freq(first): f=0 valid=0 (x0.01) +[+766ms] [2026-10-26 11:45:40][NET_TASK] === Network Init === +[+766ms] [2026-10-26 11:45:40][PROT] protect task start: cycle=20ms elm=9 +[+776ms] [2026-10-26 11:45:40][NET] ch395f ver=0x4A fun_para=0x08 +[+776ms] [2026-10-26 11:45:40][NET_TASK] net init: OK +[+787ms] [2026-10-26 11:45:40][NET_TASK] MAC: 3C:AB:72:53:2B:12 +[+787ms] [2026-10-26 11:45:40][NET_TASK] IP_INF: IP=192.168.1.100 GW=192.168.1.1 MASK=255.255.255.0 +[+798ms] MISS start snap=0x000001E7 req=0x000001F7 t=900 +[+798ms] [2026-10-26 11:45:40][WD] [WD] armed: timeout ~2498ms (worst ~1701ms), miss_tol=800ms +[+854ms] [2026-10-26 11:45:40][UI_TASK] UI task: started, wait net ready +[+2714ms] [2026-10-26 11:45:42][NET_TASK] PHY: 100M FULL +[+2735ms] [2026-10-26 11:45:42][NET_TASK] netTask: started (single-socket mode) +[+2766ms] [2026-10-26 11:45:42] [FTP] using factory default password +[+2798ms] [2026-10-26 11:45:42][TIME_SYNC] time_sync: TCP listen on :8888 (sock=0) +[+2829ms] [2026-10-26 11:45:42][I104] i104: listening on 2404 +[+2829ms] MISS start snap=0x000001E7 req=0x000001F7 t=2937 +[+2840ms] [PROF] t=2942 uic=0 uip=0 uipn=0 uil=0 uiw=0 uis=0 uisn=0 adc=2481 adcm=2237 adcn=0 gl=0 +[+2850ms] [PROF2] t=2942 defd=130981 defs=37447 netp=2991 netn=0 adcp=8 adcq=0 gl=0 +[+2850ms] [2026-10-26 11:45:42] [FTP] waiting for connection... +[+2861ms] [2026-10-26 11:45:42][UI_TASK] UI task: net ready, init port +[+2861ms] [2026-10-26 11:45:42][UI_TASK] UI task: ui_port_init enter +[+2871ms] [2026-10-26 11:45:42][UI_PORT] theme: mono dark_bg=true applied +[+2882ms] [2026-10-26 11:45:42][UI_TASK] UI port init: OK +[+2882ms] [2026-10-26 11:45:42][UI_TASK] UI task: ui_menu_init enter +[+2892ms] [2026-10-26 11:45:42][UI_MENU] menu build start: total=15136 free=12692 big=12692 +[+2903ms] [2026-10-26 11:45:42][UI_MENU_VIEW] view init: root frame w=66 h=107 +[+2913ms] [2026-10-26 11:45:42][UI_MENU] menu build done: total=15020 free=11828 big=11816 used=3192 +[+2913ms] [2026-10-26 11:45:42][UI_TASK] UI menu init: OK +[+2924ms] [2026-10-26 11:45:42][UI_STANDBY] standby: ready (idle=60000ms) +[+2924ms] [2026-10-26 11:45:42][UI_TASK] UI standby: ready (idle=60s) +[+2975ms] [2026-10-26 11:45:42][UI_TASK] UI net sink: started (port 7003) +[+4948ms] [PROF] t=5035 uic=176 uip=21962 uipn=2840 uil=10998 uiw=12055 uis=1186 uisn=0 adc=4573 adcm=2237 adcn=0 gl=0 +[+4948ms] [PROF2] t=5035 defd=130981 defs=37447 netp=3012 netn=0 adcp=8 adcq=0 gl=0 +[+5400ms] [2026-10-26 11:45:45] [STACK] default peak_used=2172/5120 free_min=2948 (57%) +[+5411ms] [2026-10-26 11:45:45] [STACK] net peak_used=1048/3840 free_min=2792 (72%) +[+5411ms] [2026-10-26 11:45:45] [STACK] ftp peak_used=740/4096 free_min=3356 (81%) +[+5421ms] [2026-10-26 11:45:45] [STACK] ui peak_used=4188/16384 free_min=12196 (74%) +[+5431ms] [2026-10-26 11:45:45] [STACK] timesync peak_used=616/2560 free_min=1944 (75%) +[+5431ms] [2026-10-26 11:45:45] [STACK] adc peak_used=920/2560 free_min=1640 (64%) +[+5442ms] [2026-10-26 11:45:45] [STACK] iec104 peak_used=540/2560 free_min=2020 (78%) +[+5452ms] [2026-10-26 11:45:45] [STACK] protect peak_used=492/2048 free_min=1556 (75%) +[+5452ms] [2026-10-26 11:45:45] [STACK] heap free=15624 min_ever=8464 +[+6965ms] [PROF] t=7065 uic=354 uip=72975 uipn=3840 uil=10999 uiw=12055 uis=1186 uisn=0 adc=6603 adcm=2237 adcn=0 gl=0 +[+6975ms] [PROF2] t=7065 defd=130981 defs=37447 netp=3988 netn=0 adcp=8 adcq=0 gl=0 +[+8980ms] [PROF] t=9083 uic=536 uip=72975 uipn=9840 uil=10938 uiw=12055 uis=1205 uisn=0 adc=8621 adcm=2237 adcn=0 gl=0 +[+8990ms] [PROF2] t=9083 defd=130981 defs=37447 netp=3988 netn=0 adcp=8 adcq=0 gl=0 +[+10360ms] [2026-10-26 11:45:50][ADC_TASK] frames=10001 idle=0 skip=33 seq=10006 frst_err=0 ring=9968 adc1_rc=0 adc1_err=0 adc1_seq=10004 adc1_gap=35 adc1_hw=0 tgap=1 +[+10371ms] [2026-10-26 11:45:50][ADC_TASK] phasor(hb) C01-IA-F1: Re=0 Im=0 rms=0 (x0.1) +[+10381ms] [2026-10-26 11:45:50][ADC_TASK] phasor(hb) C02-UA-F1: Re=0 Im=0 rms=0 (x0.1) +[+10392ms] [2026-10-26 11:45:50][ADC_TASK] phasor(hb) C03-UN-F1: Re=0 Im=0 rms=0 (x0.1) +[+10392ms] [2026-10-26 11:45:50][ADC_TASK] phasor(hb) C04-IA-F2: Re=0 Im=0 rms=0 (x0.1) +[+10402ms] [2026-10-26 11:45:50][ADC_TASK] phasor(hb) C05-IA-F5: Re=0 Im=0 rms=0 (x0.1) +[+10413ms] [2026-10-26 11:45:50][ADC_TASK] freq(hb): f=0 valid=0 (x0.01) +[+10413ms] [2026-10-26 11:45:50][ADC_TASK] cal: ua_mv=1743 un_mv=1747 ia_mv=1747 vl=0x00 cl=0xe6 rail=0x000 edge=0x000 +[+10424ms] [2026-10-26 11:45:50][ADC_TASK] meas: seq=50 v=1 ua_mv=0 un_mv=0 ia_mv=0 f=0 fv=0 +[+10981ms] [PROF] t=11084 uic=710 uip=81571 uipn=9839 uil=11000 uiw=12055 uis=1205 uisn=0 adc=10621 adcm=2879 adcn=0 gl=0 +[+10992ms] [PROF2] t=11084 defd=130981 defs=37447 netp=5012 netn=0 adcp=8 adcq=0 gl=0 +[+11455ms] [2026-10-26 11:45:51] [STACK] default peak_used=2172/5120 free_min=2948 (57%) +[+11455ms] [2026-10-26 11:45:51] [STACK] net peak_used=1048/3840 free_min=2792 (72%) +[+11466ms] [2026-10-26 11:45:51] [STACK] ftp peak_used=740/4096 free_min=3356 (81%) +[+11476ms] [2026-10-26 11:45:51] [STACK] ui peak_used=4188/16384 free_min=12196 (74%) +[+11476ms] [2026-10-26 11:45:51] [STACK] timesync peak_used=616/2560 free_min=1944 (75%) +[+11486ms] [2026-10-26 11:45:51] [STACK] adc peak_used=1000/2560 free_min=1560 (60%) +[+11497ms] [2026-10-26 11:45:51] [STACK] iec104 peak_used=540/2560 free_min=2020 (78%) +[+11497ms] [2026-10-26 11:45:51] [STACK] protect peak_used=492/2048 free_min=1556 (75%) +[+11507ms] [2026-10-26 11:45:51] [STACK] heap free=15624 min_ever=8464 +[+13012ms] [PROF] t=13114 uic=888 uip=81571 uipn=2840 uil=10999 uiw=12055 uis=1205 uisn=0 adc=12651 adcm=2879 adcn=0 gl=0 +[+13022ms] [PROF2] t=13114 defd=130981 defs=37447 netp=5012 netn=0 adcp=8 adcq=0 gl=0 +[+15033ms] [PROF] t=15132 uic=1070 uip=81571 uipn=9839 uil=11000 uiw=12055 uis=1205 uisn=0 adc=14669 adcm=2879 adcn=0 gl=0 +[+15043ms] [PROF2] t=15132 defd=130981 defs=37447 netp=5012 netn=0 adcp=8 adcq=0 gl=0 +[+17051ms] [PROF] t=17150 uic=1252 uip=81571 uipn=9840 uil=10998 uiw=12055 uis=1205 uisn=0 adc=16687 adcm=2879 adcn=0 gl=0 +[+17051ms] [PROF2] t=17150 defd=130981 defs=37447 netp=5012 netn=0 adcp=8 adcq=0 gl=0 +[+19067ms] [PROF] t=19168 uic=1434 uip=81571 uipn=9839 uil=10895 uiw=12055 uis=1205 uisn=0 adc=18705 adcm=2879 adcn=0 gl=0 +[+19077ms] [PROF2] t=19168 defd=130981 defs=37447 netp=5012 netn=0 adcp=8 adcq=0 gl=0 +[+20363ms] [2026-10-26 11:46:00][ADC_TASK] frames=20000 idle=0 skip=93 seq=20006 frst_err=0 ring=19907 adc1_rc=0 adc1_err=0 adc1_seq=20004 adc1_gap=96 adc1_hw=0 tgap=2 +[+20373ms] [2026-10-26 11:46:00][ADC_TASK] phasor(hb) C01-IA-F1: Re=0 Im=0 rms=0 (x0.1) +[+20384ms] [2026-10-26 11:46:00][ADC_TASK] phasor(hb) C02-UA-F1: Re=0 Im=0 rms=0 (x0.1) +[+20384ms] [2026-10-26 11:46:00][ADC_TASK] phasor(hb) C03-UN-F1: Re=0 Im=0 rms=0 (x0.1) +[+20394ms] [2026-10-26 11:46:00][ADC_TASK] phasor(hb) C04-IA-F2: Re=0 Im=0 rms=0 (x0.1) +[+20405ms] [2026-10-26 11:46:00][ADC_TASK] phasor(hb) C05-IA-F5: Re=0 Im=0 rms=0 (x0.1) +[+20405ms] [2026-10-26 11:46:00][ADC_TASK] freq(hb): f=0 valid=0 (x0.01) +[+20415ms] [2026-10-26 11:46:00][ADC_TASK] cal: ua_mv=1743 un_mv=1747 ia_mv=1747 vl=0x00 cl=0xe6 rail=0x000 edge=0x000 +[+20426ms] [2026-10-26 11:46:00][ADC_TASK] meas: seq=100 v=1 ua_mv=0 un_mv=0 ia_mv=0 f=0 fv=0 +[+21085ms] [PROF] t=21185 uic=1610 uip=84102 uipn=1840 uil=10997 uiw=73991 uis=73977 uisn=0 adc=20721 adcm=2879 adcn=0 gl=0 +[+21095ms] [PROF2] t=21185 defd=130981 defs=37447 netp=5012 netn=0 adcp=8 adcq=0 gl=0 +[+23097ms] [PROF] t=23203 uic=1792 uip=84102 uipn=9848 uil=10999 uiw=73991 uis=73977 uisn=0 adc=22740 adcm=2879 adcn=0 gl=0 +[+23108ms] [PROF2] t=23203 defd=130981 defs=37447 netp=5012 netn=0 adcp=8 adcq=0 gl=0 +[+25115ms] [PROF] t=25221 uic=1974 uip=84102 uipn=9839 uil=10999 uiw=73991 uis=73977 uisn=0 adc=24757 adcm=2879 adcn=0 gl=0 +[+25125ms] [PROF2] t=25221 defd=130981 defs=37447 netp=5012 netn=0 adcp=8 adcq=0 gl=0 +[+27135ms] [PROF] t=27239 uic=2156 uip=84102 uipn=9840 uil=10998 uiw=73991 uis=73977 uisn=0 adc=26775 adcm=2879 adcn=0 gl=0 +[+27145ms] [PROF2] t=27239 defd=130981 defs=37447 netp=5012 netn=0 adcp=8 adcq=0 gl=0 +[+29153ms] [PROF] t=29257 uic=2338 uip=84102 uipn=9840 uil=10999 uiw=73991 uis=73977 uisn=0 adc=28793 adcm=2879 adcn=0 gl=0 +[+29163ms] [PROF2] t=29257 defd=130981 defs=37447 netp=5012 netn=0 adcp=8 adcq=0 gl=0 diff --git a/docs/测试说明/boot_log_data/20261026_bench23_recheck_verdicts.txt b/docs/测试说明/boot_log_data/20261026_bench23_recheck_verdicts.txt new file mode 100644 index 00000000..3f7568c7 --- /dev/null +++ b/docs/测试说明/boot_log_data/20261026_bench23_recheck_verdicts.txt @@ -0,0 +1,44 @@ +# task-30 (task-23 closure re-check) verdicts -- image 1d4b6a17, stamp Oct 26 2026 19:43:23 suite=NONE dstr=off +# criterion owner: lead; verifier: scratch/bench23_verify.py (kept OUTSIDE the repo; repo untouched) +# the verifier anchors BOTH victim lines with ^...$ full-line regexes, so any spliced byte -> FAIL +# +# boot log files (raw daemon lines, byte order preserved, nothing rewritten): +# R1 gen=264 R2 gen=265 R3 gen=266 R4 gen=267 -- all RESET ONLY via stlink_flash.py reset +# (= "-c SWD -Rst -Run", zero flash writes); serial clear before each, so gen increments prove +# each capture window starts fresh and each log is one single boot (anchor count below). +# +# per-boot results (5 boots total incl. the flash boot A): +boot lines [ERR] dropped prot_seen/exact/len nand_seen/exact/head/len anchors faults verdict +R1 166 0 0 1/[true]/91px 1/[true]/[true]/56px 1 0 PASS +R2 165 0 0 1/[true]/91px 1/[true]/[true]/56px 1 0 PASS +R3 165 0 0 1/[true]/91px 1/[true]/[true]/56px 1 0 PASS +R4 156 0 0 1/[true]/91px 1/[true]/[true]/56px 1 0 PASS +A 150 0 0 1/[true]/91px 1/[true]/[true]/56px 1 0 PASS (flash boot) +# +# line order note (recorded, not judged): in ALL 5 boots the [NAND_FTL] line comes one line BEFORE +# the [PROT] line (index 39 vs 40). In the defective image the [PROT] line came first and the +# [NAND_FTL] line had lost its head. This is consistent with the fix design: the loser of the +# whole-line claim is queued verbatim and emitted right after the winner's line. +# +# criterion 3 (no regression), same image measured 4 times: +# ui peak 4188/16384 (R1,R2,R4) and 4116/16384 (R3) -> the SAME image alone swings 72 B +# previous round (77779d49) measured 4088/16384; the +100 B step is inside that swing, +# so it is NOT attributable to 1d4b6a17. Heap is byte-identical every boot AND identical +# to the previous round: heap free=15624 min_ever=8464. +# protect 492/2048 (identical to previous round), iec104 540/2560, net 1048/3840, ftp 740/4096, +# timesync 616/2560, adc 920..1000/2560 (previous round 1000), default 2172/5120 (+12 B). +# comm init anchor present in every boot: comm init: OK (ca=1 port=2404) -- no comm [ERR]. +# prot set loaded x1, CORRUPT x0 in every boot. +# +# NON-VACUOUSNESS CONTROL (why this PASS means something): +# the very same verifier, pointed at the pre-fix capture archived as +# 20261026_prod_77779d49_boot_log_reset_only.txt, returns rc=1 / verdict FAIL with +# nand_head_ok=[false] and the neighbour line reading literally +# "26-10-26 08:37:07][NAND_FTL] Initializing NAND FTL..." <- its own "[20" head is gone +# i.e. the check demonstrably catches the original defect. +# +# final chip state (run AFTER every log capture, since -CmpFile resets the target): +cmp rc=0 +CMP: D:\Code\DTU Code\_wt\bench-23-1d4b6a17\MDK-ARM\STM32F407-Demo\STM32F407-Demo.hex vs device flash @ 0x08000000 (NOTE: connecting resets the target) +No difference found. +CMP: OK (No difference found) diff --git a/docs/测试说明/boot_log_data/20261026_bench23_reset_only_boots_r1_r4.txt b/docs/测试说明/boot_log_data/20261026_bench23_reset_only_boots_r1_r4.txt new file mode 100644 index 00000000..e2e81756 --- /dev/null +++ b/docs/测试说明/boot_log_data/20261026_bench23_reset_only_boots_r1_r4.txt @@ -0,0 +1,676 @@ +# task-30: four consecutive RESET-ONLY boots on image 1d4b6a17 (no reflash between them). +# Each block = raw serial-assistant daemon lines for one boot; "clear" ran before every reset +# (gen shown per block), byte order as received, nothing rewritten or re-flowed. +# Verdicts and the negative control live in 20261026_bench23_recheck_verdicts.txt + + +################################################################################################ +### BLOCK R1 serial gen=264 lines=166 [ERR]=0 anchors=1 verdict=PASS +################################################################################################ +[RX] 2026-10-26T19:51:20.554+08:00 [----/--/-- --:--:--][APP] boot: syslog init OK +[RX] 2026-10-26T19:51:20.571+08:00 [----/--/-- --:--:--][APP] fw build: Oct 26 2026 19:43:23 suite=NONE dstr=off +[RX] 2026-10-26T19:51:20.571+08:00 [----/--/-- --:--:--][APP] reset cause: software (NVIC_SystemReset) (CSR=0x14000000) +[RX] 2026-10-26T19:51:20.571+08:00 PREVRUN seg=2 seq=2157830406 t=305573 +[RX] 2026-10-26T19:51:20.594+08:00 TICKRUN uw=45 n=45 duw=4294661768 +[RX] 2026-10-26T19:51:20.594+08:00 [----/--/-- --:--:--][RTC] sd2506_init: OK +[RX] 2026-10-26T19:51:20.594+08:00 [----/--/-- --:--:--][APP] SD2506 init: OK (ret=0) +[RX] 2026-10-26T19:51:20.612+08:00 [2026-10-26 11:51:19][CLK] sys_clock_init: RTC initial time 2026-10-26 11:51:19 +[RX] 2026-10-26T19:51:20.612+08:00 [2026-10-26 11:51:19][CLK] sys_clock_init: wall clock base = unix 1793015479, base_tick=139 +[RX] 2026-10-26T19:51:20.612+08:00 [2026-10-26 11:51:19][APP] RS485 init: OK (UART4, DE=PA15) +[RX] 2026-10-26T19:51:20.627+08:00 [2026-10-26 11:51:19][NAND] Resetting NAND... +[RX] 2026-10-26T19:51:20.643+08:00 [2026-10-26 11:51:19][NAND] Reading NAND ID... +[RX] 2026-10-26T19:51:20.643+08:00 [2026-10-26 11:51:19][NAND] NAND ID: MID=0xC8, DID=0x52 +[RX] 2026-10-26T19:51:20.658+08:00 [2026-10-26 11:51:19][NAND] Scanning bad blocks... +[RX] 2026-10-26T19:51:20.788+08:00 [2026-10-26 11:51:19][NAND] BBT scan: 0 bad blocks found +[RX] 2026-10-26T19:51:20.788+08:00 [2026-10-26 11:51:19][NAND] Enabling ECC... +[RX] 2026-10-26T19:51:20.799+08:00 [2026-10-26 11:51:19][NAND] Unlocking block protection... +[RX] 2026-10-26T19:51:20.799+08:00 [2026-10-26 11:51:19][NAND] Locating BBT pool... +[RX] 2026-10-26T19:51:20.799+08:00 [2026-10-26 11:51:19][NAND] Loading persisted BBT... +[RX] 2026-10-26T19:51:20.810+08:00 [2026-10-26 11:51:19][NAND] NAND init OK +[RX] 2026-10-26T19:51:20.810+08:00 [2026-10-26 11:51:19][APP] NAND init: OK +[RX] 2026-10-26T19:51:20.820+08:00 [2026-10-26 11:51:19][ADC] Init OK +[RX] 2026-10-26T19:51:20.820+08:00 [2026-10-26 11:51:19][APP] ADC init: OK +[RX] 2026-10-26T19:51:20.831+08:00 [2026-10-26 11:51:19][APP] ADC input layer init: OK +[RX] 2026-10-26T19:51:20.831+08:00 [2026-10-26 11:51:19][APP] phasor layer init: OK (inst=5) +[RX] 2026-10-26T19:51:20.831+08:00 [2026-10-26 11:51:19][APP] freq layer init: OK +[RX] 2026-10-26T19:51:20.842+08:00 [2026-10-26 11:51:19][CFG] register: section 'adc_cal' (9 keys) +[RX] 2026-10-26T19:51:20.842+08:00 [2026-10-26 11:51:19][CFG] register: section 'adc_cal_ofs' (8 keys) +[RX] 2026-10-26T19:51:20.852+08:00 [2026-10-26 11:51:19][APP] adc cal init: OK (k_q16 tpafe=10000000 stm32=52800000) +[RX] 2026-10-26T19:51:20.863+08:00 [2026-10-26 11:51:19][CFG] register: section 'run_par' (9 keys) +[RX] 2026-10-26T19:51:20.863+08:00 [2026-10-26 11:51:19][APP] run par init: OK (db9 k/b via adc_cal, evt=1<<8) +[RX] 2026-10-26T19:51:20.873+08:00 [2026-10-26 11:51:19][CFG] register: section 'comm' (2 keys) +[RX] 2026-10-26T19:51:20.884+08:00 [2026-10-26 11:51:19][APP] comm init: OK (ca=1 port=2404) +[RX] 2026-10-26T19:51:20.884+08:00 [2026-10-26 11:51:19][APP] protection init: OK (set=40 elm=9) +[RX] 2026-10-26T19:51:20.894+08:00 [2026-10-26 11:51:19][APP] SD2506 ID: 2512153425482405 +[RX] 2026-10-26T19:51:20.894+08:00 [2026-10-26 11:51:19][APP] SD2506 time: 2026-10-26 11:51:19 (week 1) +[RX] 2026-10-26T19:51:20.905+08:00 [2026-10-26 11:51:19][APP] SD2506 temp: 24 C +[RX] 2026-10-26T19:51:20.905+08:00 [2026-10-26 11:51:19][APP] SD2506 battery: 3.12 V +[RX] 2026-10-26T19:51:20.915+08:00 [2026-10-26 11:51:19][APP] App init OK +[RX] 2026-10-26T19:51:20.915+08:00 [2026-10-26 11:51:19][NAND_FTL] Initializing NAND FTL... +[RX] 2026-10-26T19:51:20.947+08:00 [2026-10-26 11:51:19][PROT] uncalibrated -> protection blocked (UA/UN/IA VALID not all set) +[RX] 2026-10-26T19:51:21.019+08:00 [2026-10-26 11:51:19][NAND_FTL] Map resumed: 14094/97504 sectors used +[RX] 2026-10-26T19:51:21.019+08:00 [2026-10-26 11:51:19][NAND_FTL] Map head=49696 tail=2603 epoch=7 +[RX] 2026-10-26T19:51:21.030+08:00 [2026-10-26 11:51:19][NAND_FTL] NAND FTL ready (capacity: 97504 pages = 190 MB) +[RX] 2026-10-26T19:51:21.217+08:00 [2026-10-26 11:51:19] [FS] FATFS mounted +[RX] 2026-10-26T19:51:21.363+08:00 [2026-10-26 11:51:19][SYSLOG] cap full, recreate /log/run.log +[RX] 2026-10-26T19:51:21.498+08:00 [2026-10-26 11:51:19][SYSLOG] runlog boot entry: reboot +[RX] 2026-10-26T19:51:21.498+08:00 [2026-10-26 11:51:19][CFG] register: section 'network' (4 keys) +[RX] 2026-10-26T19:51:21.508+08:00 [2026-10-26 11:51:19][CFG] register: section 'ftp' (3 keys) +[RX] 2026-10-26T19:51:21.519+08:00 [2026-10-26 11:51:19][CFG] load: OK (957B, heap free 16552B) +[RX] 2026-10-26T19:51:21.519+08:00 [2026-10-26 11:51:19][NET_CFG] load: OK ip=192.168.1.100 +[RX] 2026-10-26T19:51:21.529+08:00 [2026-10-26 11:51:19] [CFG] prot set loaded (/prot_set.bin) +[RX] 2026-10-26T19:51:21.550+08:00 [2026-10-26 11:51:19][ADC_TASK] first: UA=11428 UB=1067 UC=923 UN=11454 IA=11452 IB=980 IC=1000 IN=971 T=943 +[RX] 2026-10-26T19:51:21.560+08:00 [2026-10-26 11:51:19][ADC_TASK] phasor(first) C01-IA-F1: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:51:21.571+08:00 [2026-10-26 11:51:19][ADC_TASK] phasor(first) C02-UA-F1: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:51:21.571+08:00 [2026-10-26 11:51:19][ADC_TASK] phasor(first) C03-UN-F1: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:51:21.581+08:00 [2026-10-26 11:51:19][ADC_TASK] phasor(first) C04-IA-F2: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:51:21.592+08:00 [2026-10-26 11:51:19][ADC_TASK] phasor(first) C05-IA-F5: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:51:21.602+08:00 [2026-10-26 11:51:19][ADC_TASK] freq(first): f=0 valid=0 (x0.01) +[RX] 2026-10-26T19:51:21.602+08:00 [2026-10-26 11:51:19][PROT] protect task start: cycle=20ms elm=9 +[RX] 2026-10-26T19:51:21.612+08:00 [2026-10-26 11:51:19][NET_TASK] === Network Init === +[RX] 2026-10-26T19:51:21.612+08:00 [2026-10-26 11:51:19][NET] ch395f ver=0x4A fun_para=0x08 +[RX] 2026-10-26T19:51:21.612+08:00 MISS start snap=0x000001E7 req=0x000001F7 t=1162 +[RX] 2026-10-26T19:51:21.623+08:00 [2026-10-26 11:51:19][WD] [WD] armed: timeout ~2498ms (worst ~1701ms), miss_tol=800ms +[RX] 2026-10-26T19:51:21.676+08:00 [2026-10-26 11:51:20][NET_TASK] net init: OK +[RX] 2026-10-26T19:51:21.676+08:00 [2026-10-26 11:51:20][NET_TASK] MAC: 3C:AB:72:53:2B:12 +[RX] 2026-10-26T19:51:21.687+08:00 [2026-10-26 11:51:20][NET_TASK] IP_INF: IP=192.168.1.100 GW=192.168.1.1 MASK=255.255.255.0 +[RX] 2026-10-26T19:51:21.697+08:00 [2026-10-26 11:51:20][UI_TASK] UI task: started, wait net ready +[RX] 2026-10-26T19:51:22.597+08:00 [2026-10-26 11:51:20][NET_TASK] PHY: 100M FULL +[RX] 2026-10-26T19:51:22.613+08:00 [2026-10-26 11:51:20][NET_TASK] netTask: started (single-socket mode) +[RX] 2026-10-26T19:51:22.666+08:00 [2026-10-26 11:51:20] [FTP] using factory default password +[RX] 2026-10-26T19:51:22.687+08:00 [2026-10-26 11:51:21][TIME_SYNC] time_sync: TCP listen on :8888 (sock=0) +[RX] 2026-10-26T19:51:22.719+08:00 [2026-10-26 11:51:21][I104] i104: listening on 2404 +[RX] 2026-10-26T19:51:22.719+08:00 MISS start snap=0x000001E7 req=0x000001F7 t=2261 +[RX] 2026-10-26T19:51:22.719+08:00 [PROF] t=2266 uic=0 uip=0 uipn=0 uil=0 uiw=0 uis=0 uisn=0 adc=1805 adcm=2219 adcn=0 gl=0 +[RX] 2026-10-26T19:51:22.735+08:00 [PROF2] t=2266 defd=130909 defs=46587 netp=2990 netn=0 adcp=12 adcq=0 gl=0 +[RX] 2026-10-26T19:51:22.735+08:00 [2026-10-26 11:51:21] [FTP] waiting for connection... +[RX] 2026-10-26T19:51:22.754+08:00 [2026-10-26 11:51:21][UI_TASK] UI task: net ready, init port +[RX] 2026-10-26T19:51:22.754+08:00 [2026-10-26 11:51:21][UI_TASK] UI task: ui_port_init enter +[RX] 2026-10-26T19:51:22.754+08:00 [2026-10-26 11:51:21][UI_PORT] theme: mono dark_bg=true applied +[RX] 2026-10-26T19:51:22.767+08:00 [2026-10-26 11:51:21][UI_TASK] UI port init: OK +[RX] 2026-10-26T19:51:22.767+08:00 [2026-10-26 11:51:21][UI_TASK] UI task: ui_menu_init enter +[RX] 2026-10-26T19:51:22.778+08:00 [2026-10-26 11:51:21][UI_MENU] menu build start: total=15136 free=12692 big=12692 +[RX] 2026-10-26T19:51:22.778+08:00 [2026-10-26 11:51:21][UI_MENU_VIEW] view init: root frame w=66 h=107 +[RX] 2026-10-26T19:51:22.793+08:00 [2026-10-26 11:51:21][UI_MENU] menu build done: total=15020 free=11828 big=11816 used=3192 +[RX] 2026-10-26T19:51:22.793+08:00 [2026-10-26 11:51:21][UI_TASK] UI menu init: OK +[RX] 2026-10-26T19:51:22.811+08:00 [2026-10-26 11:51:21][UI_STANDBY] standby: ready (idle=60000ms) +[RX] 2026-10-26T19:51:22.811+08:00 [2026-10-26 11:51:21][UI_TASK] UI standby: ready (idle=60s) +[RX] 2026-10-26T19:51:22.862+08:00 [2026-10-26 11:51:21][UI_TASK] UI net sink: started (port 7003) +[RX] 2026-10-26T19:51:25.470+08:00 [PROF] t=5008 uic=235 uip=22024 uipn=3823 uil=11015 uiw=12115 uis=1264 uisn=0 adc=4546 adcm=2219 adcn=0 gl=0 +[RX] 2026-10-26T19:51:25.470+08:00 [PROF2] t=5008 defd=130909 defs=46587 netp=3012 netn=0 adcp=12 adcq=0 gl=0 +[RX] 2026-10-26T19:51:25.930+08:00 [2026-10-26 11:51:24] [STACK] default peak_used=2232/5120 free_min=2888 (56%) +[RX] 2026-10-26T19:51:25.945+08:00 [2026-10-26 11:51:24] [STACK] net peak_used=1116/3840 free_min=2724 (70%) +[RX] 2026-10-26T19:51:25.945+08:00 [2026-10-26 11:51:24] [STACK] ftp peak_used=740/4096 free_min=3356 (81%) +[RX] 2026-10-26T19:51:25.957+08:00 [2026-10-26 11:51:24] [STACK] ui peak_used=4188/16384 free_min=12196 (74%) +[RX] 2026-10-26T19:51:25.957+08:00 [2026-10-26 11:51:24] [STACK] timesync peak_used=616/2560 free_min=1944 (75%) +[RX] 2026-10-26T19:51:25.969+08:00 [2026-10-26 11:51:24] [STACK] adc peak_used=896/2560 free_min=1664 (65%) +[RX] 2026-10-26T19:51:25.979+08:00 [2026-10-26 11:51:24] [STACK] iec104 peak_used=540/2560 free_min=2020 (78%) +[RX] 2026-10-26T19:51:25.979+08:00 [2026-10-26 11:51:24] [STACK] protect peak_used=492/2048 free_min=1556 (75%) +[RX] 2026-10-26T19:51:25.990+08:00 [2026-10-26 11:51:24] [STACK] heap free=15624 min_ever=8464 +[RX] 2026-10-26T19:51:27.497+08:00 [PROF] t=7038 uic=413 uip=73656 uipn=3839 uil=11000 uiw=12115 uis=1287 uisn=0 adc=6576 adcm=2219 adcn=0 gl=0 +[RX] 2026-10-26T19:51:27.507+08:00 [PROF2] t=7038 defd=130909 defs=46587 netp=3984 netn=0 adcp=12 adcq=0 gl=0 +[RX] 2026-10-26T19:51:29.515+08:00 [PROF] t=9056 uic=595 uip=73656 uipn=9839 uil=11000 uiw=12115 uis=1287 uisn=0 adc=8594 adcm=2219 adcn=0 gl=0 +[RX] 2026-10-26T19:51:29.526+08:00 [PROF2] t=9056 defd=130909 defs=46587 netp=3984 netn=0 adcp=12 adcq=0 gl=0 +[RX] 2026-10-26T19:51:30.923+08:00 [2026-10-26 11:51:29][ADC_TASK] frames=10001 idle=0 skip=56 seq=10006 frst_err=0 ring=9945 adc1_rc=0 adc1_err=0 adc1_seq=10004 adc1_gap=58 adc1_hw=0 tgap=1 +[RX] 2026-10-26T19:51:30.933+08:00 [2026-10-26 11:51:29][ADC_TASK] phasor(hb) C01-IA-F1: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:51:30.944+08:00 [2026-10-26 11:51:29][ADC_TASK] phasor(hb) C02-UA-F1: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:51:30.944+08:00 [2026-10-26 11:51:29][ADC_TASK] phasor(hb) C03-UN-F1: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:51:30.954+08:00 [2026-10-26 11:51:29][ADC_TASK] phasor(hb) C04-IA-F2: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:51:30.964+08:00 [2026-10-26 11:51:29][ADC_TASK] phasor(hb) C05-IA-F5: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:51:30.964+08:00 [2026-10-26 11:51:29][ADC_TASK] freq(hb): f=0 valid=0 (x0.01) +[RX] 2026-10-26T19:51:30.975+08:00 [2026-10-26 11:51:29][ADC_TASK] cal: ua_mv=1743 un_mv=1747 ia_mv=1747 vl=0x00 cl=0xe6 rail=0x000 edge=0x000 +[RX] 2026-10-26T19:51:30.985+08:00 [2026-10-26 11:51:29][ADC_TASK] meas: seq=50 v=1 ua_mv=0 un_mv=0 ia_mv=0 f=0 fv=0 +[RX] 2026-10-26T19:51:31.537+08:00 [PROF] t=11084 uic=772 uip=75582 uipn=10736 uil=11045 uiw=12115 uis=1287 uisn=0 adc=10621 adcm=2879 adcn=0 gl=0 +[RX] 2026-10-26T19:51:31.548+08:00 [PROF2] t=11084 defd=130909 defs=46587 netp=6006 netn=0 adcp=12 adcq=0 gl=0 +[RX] 2026-10-26T19:51:32.009+08:00 [2026-10-26 11:51:30] [STACK] default peak_used=2232/5120 free_min=2888 (56%) +[RX] 2026-10-26T19:51:32.019+08:00 [2026-10-26 11:51:30] [STACK] net peak_used=1116/3840 free_min=2724 (70%) +[RX] 2026-10-26T19:51:32.019+08:00 [2026-10-26 11:51:30] [STACK] ftp peak_used=740/4096 free_min=3356 (81%) +[RX] 2026-10-26T19:51:32.030+08:00 [2026-10-26 11:51:30] [STACK] ui peak_used=4188/16384 free_min=12196 (74%) +[RX] 2026-10-26T19:51:32.040+08:00 [2026-10-26 11:51:30] [STACK] timesync peak_used=616/2560 free_min=1944 (75%) +[RX] 2026-10-26T19:51:32.040+08:00 [2026-10-26 11:51:30] [STACK] adc peak_used=1000/2560 free_min=1560 (60%) +[RX] 2026-10-26T19:51:32.051+08:00 [2026-10-26 11:51:30] [STACK] iec104 peak_used=540/2560 free_min=2020 (78%) +[RX] 2026-10-26T19:51:32.062+08:00 [2026-10-26 11:51:30] [STACK] protect peak_used=492/2048 free_min=1556 (75%) +[RX] 2026-10-26T19:51:32.062+08:00 [2026-10-26 11:51:30] [STACK] heap free=15624 min_ever=8464 +[RX] 2026-10-26T19:51:33.573+08:00 [PROF] t=13115 uic=950 uip=75582 uipn=3848 uil=10998 uiw=12115 uis=1287 uisn=0 adc=12653 adcm=2879 adcn=0 gl=0 +[RX] 2026-10-26T19:51:33.584+08:00 [PROF2] t=13115 defd=130909 defs=46587 netp=6006 netn=0 adcp=12 adcq=0 gl=0 +[RX] 2026-10-26T19:51:35.596+08:00 [PROF] t=15133 uic=1132 uip=75582 uipn=9840 uil=10999 uiw=12115 uis=1287 uisn=0 adc=14670 adcm=2879 adcn=0 gl=0 +[RX] 2026-10-26T19:51:35.596+08:00 [PROF2] t=15133 defd=130909 defs=46587 netp=6006 netn=0 adcp=12 adcq=0 gl=0 +[RX] 2026-10-26T19:51:37.608+08:00 [PROF] t=17151 uic=1314 uip=75582 uipn=9839 uil=10999 uiw=12115 uis=1287 uisn=0 adc=16688 adcm=2879 adcn=0 gl=0 +[RX] 2026-10-26T19:51:37.618+08:00 [PROF2] t=17151 defd=130909 defs=46587 netp=6006 netn=0 adcp=12 adcq=0 gl=0 +[RX] 2026-10-26T19:51:39.623+08:00 [PROF] t=19169 uic=1496 uip=75582 uipn=9840 uil=10999 uiw=12115 uis=1287 uisn=0 adc=18706 adcm=2879 adcn=0 gl=0 +[RX] 2026-10-26T19:51:39.634+08:00 [PROF2] t=19169 defd=130909 defs=46587 netp=6006 netn=0 adcp=12 adcq=0 gl=0 +[RX] 2026-10-26T19:51:40.918+08:00 [2026-10-26 11:51:39][ADC_TASK] frames=20000 idle=0 skip=66 seq=20006 frst_err=0 ring=19934 adc1_rc=0 adc1_err=0 adc1_seq=20004 adc1_gap=69 adc1_hw=0 tgap=2 +[RX] 2026-10-26T19:51:40.929+08:00 [2026-10-26 11:51:39][ADC_TASK] phasor(hb) C01-IA-F1: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:51:40.939+08:00 [2026-10-26 11:51:39][ADC_TASK] phasor(hb) C02-UA-F1: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:51:40.950+08:00 [2026-10-26 11:51:39][ADC_TASK] phasor(hb) C03-UN-F1: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:51:40.950+08:00 [2026-10-26 11:51:39][ADC_TASK] phasor(hb) C04-IA-F2: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:51:40.960+08:00 [2026-10-26 11:51:39][ADC_TASK] phasor(hb) C05-IA-F5: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:51:40.971+08:00 [2026-10-26 11:51:39][ADC_TASK] freq(hb): f=0 valid=0 (x0.01) +[RX] 2026-10-26T19:51:40.971+08:00 [2026-10-26 11:51:39][ADC_TASK] cal: ua_mv=1743 un_mv=1747 ia_mv=1747 vl=0x00 cl=0xe6 rail=0x000 edge=0x000 +[RX] 2026-10-26T19:51:40.981+08:00 [2026-10-26 11:51:39][ADC_TASK] meas: seq=100 v=1 ua_mv=0 un_mv=0 ia_mv=0 f=0 fv=0 +[RX] 2026-10-26T19:51:41.641+08:00 [PROF] t=21185 uic=1672 uip=83995 uipn=839 uil=11000 uiw=12115 uis=1287 uisn=829 adc=20721 adcm=2903 adcn=0 gl=0 +[RX] 2026-10-26T19:51:41.651+08:00 [PROF2] t=21185 defd=130909 defs=46587 netp=6006 netn=0 adcp=12 adcq=0 gl=0 +[RX] 2026-10-26T19:51:43.664+08:00 [PROF] t=23203 uic=1853 uip=83995 uipn=9840 uil=10993 uiw=18646 uis=18635 uisn=0 adc=22739 adcm=2903 adcn=0 gl=0 +[RX] 2026-10-26T19:51:43.664+08:00 [PROF2] t=23203 defd=130909 defs=46587 netp=6006 netn=0 adcp=12 adcq=0 gl=0 +[RX] 2026-10-26T19:51:45.682+08:00 [PROF] t=25221 uic=2035 uip=83995 uipn=9840 uil=10999 uiw=18646 uis=18635 uisn=0 adc=24757 adcm=2903 adcn=0 gl=0 +[RX] 2026-10-26T19:51:45.682+08:00 [PROF2] t=25221 defd=130909 defs=46587 netp=6006 netn=0 adcp=12 adcq=0 gl=0 +[RX] 2026-10-26T19:51:47.693+08:00 [PROF] t=27239 uic=2217 uip=83995 uipn=9736 uil=11103 uiw=18646 uis=18635 uisn=0 adc=26775 adcm=2903 adcn=0 gl=0 +[RX] 2026-10-26T19:51:47.704+08:00 [PROF2] t=27239 defd=130909 defs=46587 netp=6006 netn=0 adcp=12 adcq=0 gl=0 +[RX] 2026-10-26T19:51:49.715+08:00 [PROF] t=29257 uic=2399 uip=83995 uipn=9840 uil=10998 uiw=18646 uis=18635 uisn=0 adc=28793 adcm=2903 adcn=0 gl=0 +[RX] 2026-10-26T19:51:49.726+08:00 [PROF2] t=29257 defd=130909 defs=46587 netp=6006 netn=0 adcp=12 adcq=0 gl=0 +[RX] 2026-10-26T19:51:50.917+08:00 [2026-10-26 11:51:49][ADC_TASK] frames=29999 idle=0 skip=75 seq=30006 frst_err=0 ring=29924 adc1_rc=0 adc1_err=0 adc1_seq=30004 adc1_gap=79 adc1_hw=0 tgap=3 +[RX] 2026-10-26T19:51:50.928+08:00 [2026-10-26 11:51:49][ADC_TASK] phasor(hb) C01-IA-F1: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:51:50.938+08:00 [2026-10-26 11:51:49][ADC_TASK] phasor(hb) C02-UA-F1: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:51:50.948+08:00 [2026-10-26 11:51:49][ADC_TASK] phasor(hb) C03-UN-F1: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:51:50.959+08:00 [2026-10-26 11:51:49][ADC_TASK] phasor(hb) C04-IA-F2: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:51:50.959+08:00 [2026-10-26 11:51:49][ADC_TASK] phasor(hb) C05-IA-F5: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:51:50.969+08:00 [2026-10-26 11:51:49][ADC_TASK] freq(hb): f=0 valid=0 (x0.01) +[RX] 2026-10-26T19:51:50.969+08:00 [2026-10-26 11:51:49][ADC_TASK] cal: ua_mv=1743 un_mv=1747 ia_mv=1747 vl=0x00 cl=0xe6 rail=0x000 edge=0x000 +[RX] 2026-10-26T19:51:50.980+08:00 [2026-10-26 11:51:49][ADC_TASK] meas: seq=150 v=1 ua_mv=0 un_mv=0 ia_mv=0 f=0 fv=0 +[RX] 2026-10-26T19:51:51.745+08:00 [PROF] t=31285 uic=2576 uip=84090 uipn=1841 uil=10997 uiw=18646 uis=18635 uisn=0 adc=30820 adcm=2904 adcn=0 gl=0 +[RX] 2026-10-26T19:51:51.745+08:00 [PROF2] t=31285 defd=130909 defs=46587 netp=6006 netn=0 adcp=12 adcq=0 gl=0 +[RX] 2026-10-26T19:51:53.760+08:00 [PROF] t=33303 uic=2758 uip=84090 uipn=9840 uil=10999 uiw=18646 uis=18635 uisn=0 adc=32838 adcm=2904 adcn=0 gl=0 +[RX] 2026-10-26T19:51:53.770+08:00 [PROF2] t=33303 defd=130909 defs=46587 netp=6006 netn=0 adcp=12 adcq=0 gl=0 +[RX] 2026-10-26T19:51:55.780+08:00 [PROF] t=35321 uic=2940 uip=84090 uipn=9839 uil=10999 uiw=18646 uis=18635 uisn=0 adc=34856 adcm=2904 adcn=0 gl=0 +[RX] 2026-10-26T19:51:55.791+08:00 [PROF2] t=35321 defd=130909 defs=46587 netp=6006 netn=0 adcp=12 adcq=0 gl=0 + + +################################################################################################ +### BLOCK R2 serial gen=265 lines=165 [ERR]=0 anchors=1 verdict=PASS +################################################################################################ +[RX] 2026-10-26T19:51:56.924+08:00 [----/--/-- --:--:--][APP] boot: syslog init OK +[RX] 2026-10-26T19:51:56.924+08:00 [----/--/-- --:--:--][APP] fw build: Oct 26 2026 19:43:23 suite=NONE dstr=off +[RX] 2026-10-26T19:51:56.924+08:00 [----/--/-- --:--:--][APP] reset cause: software (NVIC_SystemReset) (CSR=0x14000000) +[RX] 2026-10-26T19:51:56.939+08:00 PREVRUN seg=2 seq=2157835431 t=35939 +[RX] 2026-10-26T19:51:56.939+08:00 TICKRUN uw=8 n=8 duw=4294931365 +[RX] 2026-10-26T19:51:56.939+08:00 [----/--/-- --:--:--][RTC] sd2506_init: OK +[RX] 2026-10-26T19:51:56.939+08:00 [----/--/-- --:--:--][APP] SD2506 init: OK (ret=0) +[RX] 2026-10-26T19:51:56.957+08:00 [2026-10-26 11:51:56][CLK] sys_clock_init: RTC initial time 2026-10-26 11:51:56 +[RX] 2026-10-26T19:51:56.957+08:00 [2026-10-26 11:51:56][CLK] sys_clock_init: wall clock base = unix 1793015516, base_tick=138 +[RX] 2026-10-26T19:51:56.971+08:00 [2026-10-26 11:51:56][APP] RS485 init: OK (UART4, DE=PA15) +[RX] 2026-10-26T19:51:56.985+08:00 [2026-10-26 11:51:56][NAND] Resetting NAND... +[RX] 2026-10-26T19:51:57.006+08:00 [2026-10-26 11:51:56][NAND] Reading NAND ID... +[RX] 2026-10-26T19:51:57.006+08:00 [2026-10-26 11:51:56][NAND] NAND ID: MID=0xC8, DID=0x52 +[RX] 2026-10-26T19:51:57.006+08:00 [2026-10-26 11:51:56][NAND] Scanning bad blocks... +[RX] 2026-10-26T19:51:57.140+08:00 [2026-10-26 11:51:56][NAND] BBT scan: 0 bad blocks found +[RX] 2026-10-26T19:51:57.140+08:00 [2026-10-26 11:51:56][NAND] Enabling ECC... +[RX] 2026-10-26T19:51:57.152+08:00 [2026-10-26 11:51:56][NAND] Unlocking block protection... +[RX] 2026-10-26T19:51:57.152+08:00 [2026-10-26 11:51:56][NAND] Locating BBT pool... +[RX] 2026-10-26T19:51:57.162+08:00 [2026-10-26 11:51:56][NAND] Loading persisted BBT... +[RX] 2026-10-26T19:51:57.162+08:00 [2026-10-26 11:51:56][NAND] NAND init OK +[RX] 2026-10-26T19:51:57.174+08:00 [2026-10-26 11:51:56][APP] NAND init: OK +[RX] 2026-10-26T19:51:57.174+08:00 [2026-10-26 11:51:56][ADC] Init OK +[RX] 2026-10-26T19:51:57.174+08:00 [2026-10-26 11:51:56][APP] ADC init: OK +[RX] 2026-10-26T19:51:57.184+08:00 [2026-10-26 11:51:56][APP] ADC input layer init: OK +[RX] 2026-10-26T19:51:57.184+08:00 [2026-10-26 11:51:56][APP] phasor layer init: OK (inst=5) +[RX] 2026-10-26T19:51:57.195+08:00 [2026-10-26 11:51:56][APP] freq layer init: OK +[RX] 2026-10-26T19:51:57.195+08:00 [2026-10-26 11:51:56][CFG] register: section 'adc_cal' (9 keys) +[RX] 2026-10-26T19:51:57.206+08:00 [2026-10-26 11:51:56][CFG] register: section 'adc_cal_ofs' (8 keys) +[RX] 2026-10-26T19:51:57.206+08:00 [2026-10-26 11:51:56][APP] adc cal init: OK (k_q16 tpafe=10000000 stm32=52800000) +[RX] 2026-10-26T19:51:57.216+08:00 [2026-10-26 11:51:56][CFG] register: section 'run_par' (9 keys) +[RX] 2026-10-26T19:51:57.216+08:00 [2026-10-26 11:51:56][APP] run par init: OK (db9 k/b via adc_cal, evt=1<<8) +[RX] 2026-10-26T19:51:57.227+08:00 [2026-10-26 11:51:56][CFG] register: section 'comm' (2 keys) +[RX] 2026-10-26T19:51:57.237+08:00 [2026-10-26 11:51:56][APP] comm init: OK (ca=1 port=2404) +[RX] 2026-10-26T19:51:57.237+08:00 [2026-10-26 11:51:56][APP] protection init: OK (set=40 elm=9) +[RX] 2026-10-26T19:51:57.248+08:00 [2026-10-26 11:51:56][APP] SD2506 ID: 2512153425482405 +[RX] 2026-10-26T19:51:57.248+08:00 [2026-10-26 11:51:56][APP] SD2506 time: 2026-10-26 11:51:56 (week 1) +[RX] 2026-10-26T19:51:57.258+08:00 [2026-10-26 11:51:56][APP] SD2506 temp: 24 C +[RX] 2026-10-26T19:51:57.258+08:00 [2026-10-26 11:51:56][APP] SD2506 battery: 3.12 V +[RX] 2026-10-26T19:51:57.269+08:00 [2026-10-26 11:51:56][APP] App init OK +[RX] 2026-10-26T19:51:57.269+08:00 [2026-10-26 11:51:56][NAND_FTL] Initializing NAND FTL... +[RX] 2026-10-26T19:51:57.301+08:00 [2026-10-26 11:51:56][PROT] uncalibrated -> protection blocked (UA/UN/IA VALID not all set) +[RX] 2026-10-26T19:51:57.374+08:00 [2026-10-26 11:51:56][NAND_FTL] Map resumed: 14094/97504 sectors used +[RX] 2026-10-26T19:51:57.374+08:00 [2026-10-26 11:51:56][NAND_FTL] Map head=49776 tail=2901 epoch=7 +[RX] 2026-10-26T19:51:57.384+08:00 [2026-10-26 11:51:56][NAND_FTL] NAND FTL ready (capacity: 97504 pages = 190 MB) +[RX] 2026-10-26T19:51:57.623+08:00 [2026-10-26 11:51:56] [FS] FATFS mounted +[RX] 2026-10-26T19:51:57.686+08:00 [2026-10-26 11:51:56][SYSLOG] runlog boot entry: reboot +[RX] 2026-10-26T19:51:57.686+08:00 [2026-10-26 11:51:56][CFG] register: section 'network' (4 keys) +[RX] 2026-10-26T19:51:57.696+08:00 [2026-10-26 11:51:56][CFG] register: section 'ftp' (3 keys) +[RX] 2026-10-26T19:51:57.707+08:00 [2026-10-26 11:51:56][CFG] load: OK (957B, heap free 16552B) +[RX] 2026-10-26T19:51:57.707+08:00 [2026-10-26 11:51:56][NET_CFG] load: OK ip=192.168.1.100 +[RX] 2026-10-26T19:51:57.717+08:00 [2026-10-26 11:51:56] [CFG] prot set loaded (/prot_set.bin) +[RX] 2026-10-26T19:51:57.738+08:00 [2026-10-26 11:51:56][ADC_TASK] first: UA=11429 UB=1078 UC=954 UN=11453 IA=11449 IB=1034 IC=1019 IN=975 T=1005 +[RX] 2026-10-26T19:51:57.748+08:00 [2026-10-26 11:51:56][ADC_TASK] phasor(first) C01-IA-F1: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:51:57.759+08:00 [2026-10-26 11:51:56][ADC_TASK] phasor(first) C02-UA-F1: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:51:57.759+08:00 [2026-10-26 11:51:56][ADC_TASK] phasor(first) C03-UN-F1: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:51:57.769+08:00 [2026-10-26 11:51:56][ADC_TASK] phasor(first) C04-IA-F2: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:51:57.780+08:00 [2026-10-26 11:51:56][ADC_TASK] phasor(first) C05-IA-F5: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:51:57.790+08:00 [2026-10-26 11:51:56][ADC_TASK] freq(first): f=0 valid=0 (x0.01) +[RX] 2026-10-26T19:51:57.790+08:00 [2026-10-26 11:51:56][PROT] protect task start: cycle=20ms elm=9 +[RX] 2026-10-26T19:51:57.801+08:00 [2026-10-26 11:51:56][NET_TASK] === Network Init === +[RX] 2026-10-26T19:51:57.801+08:00 [2026-10-26 11:51:56][NET] ch395f ver=0x4A fun_para=0x08 +[RX] 2026-10-26T19:51:57.801+08:00 MISS start snap=0x000001E7 req=0x000001F7 t=994 +[RX] 2026-10-26T19:51:57.811+08:00 [2026-10-26 11:51:56][WD] [WD] armed: timeout ~2498ms (worst ~1701ms), miss_tol=800ms +[RX] 2026-10-26T19:51:57.853+08:00 [2026-10-26 11:51:56][NET_TASK] net init: OK +[RX] 2026-10-26T19:51:57.864+08:00 [2026-10-26 11:51:56][NET_TASK] MAC: 3C:AB:72:53:2B:12 +[RX] 2026-10-26T19:51:57.864+08:00 [2026-10-26 11:51:56][NET_TASK] IP_INF: IP=192.168.1.100 GW=192.168.1.1 MASK=255.255.255.0 +[RX] 2026-10-26T19:51:57.874+08:00 [2026-10-26 11:51:56][UI_TASK] UI task: started, wait net ready +[RX] 2026-10-26T19:51:59.825+08:00 [2026-10-26 11:51:58][NET_TASK] PHY: 100M FULL +[RX] 2026-10-26T19:51:59.846+08:00 [2026-10-26 11:51:58][NET_TASK] netTask: started (single-socket mode) +[RX] 2026-10-26T19:51:59.877+08:00 [2026-10-26 11:51:58] [FTP] using factory default password +[RX] 2026-10-26T19:51:59.909+08:00 [2026-10-26 11:51:58][TIME_SYNC] time_sync: TCP listen on :8888 (sock=0) +[RX] 2026-10-26T19:51:59.940+08:00 [2026-10-26 11:51:58] [FTP] waiting for connection... +[RX] 2026-10-26T19:51:59.950+08:00 [2026-10-26 11:51:58][I104] i104: listening on 2404 +[RX] 2026-10-26T19:51:59.950+08:00 [2026-10-26 11:51:59][UI_TASK] UI task: net ready, init port +[RX] 2026-10-26T19:51:59.961+08:00 [2026-10-26 11:51:59][UI_TASK] UI task: ui_port_init enter +[RX] 2026-10-26T19:51:59.961+08:00 [2026-10-26 11:51:59][UI_PORT] theme: mono dark_bg=true applied +[RX] 2026-10-26T19:51:59.971+08:00 [2026-10-26 11:51:59][UI_TASK] UI port init: OK +[RX] 2026-10-26T19:51:59.971+08:00 [2026-10-26 11:51:59][UI_TASK] UI task: ui_menu_init enter +[RX] 2026-10-26T19:51:59.982+08:00 [2026-10-26 11:51:59][UI_MENU] menu build start: total=15136 free=12692 big=12692 +[RX] 2026-10-26T19:51:59.992+08:00 [2026-10-26 11:51:59][UI_MENU_VIEW] view init: root frame w=66 h=107 +[RX] 2026-10-26T19:52:00.002+08:00 [2026-10-26 11:51:59][UI_MENU] menu build done: total=15020 free=11828 big=11816 used=3192 +[RX] 2026-10-26T19:52:00.002+08:00 [2026-10-26 11:51:59][UI_TASK] UI menu init: OK +[RX] 2026-10-26T19:52:00.013+08:00 [2026-10-26 11:51:59][UI_STANDBY] standby: ready (idle=60000ms) +[RX] 2026-10-26T19:52:00.013+08:00 [2026-10-26 11:51:59][UI_TASK] UI standby: ready (idle=60s) +[RX] 2026-10-26T19:52:00.065+08:00 [2026-10-26 11:51:59][UI_TASK] UI net sink: started (port 7003) +[RX] 2026-10-26T19:52:00.075+08:00 MISS start snap=0x000001E7 req=0x000001F7 t=3261 +[RX] 2026-10-26T19:52:00.075+08:00 [PROF] t=3265 uic=0 uip=0 uipn=0 uil=0 uiw=0 uis=0 uisn=0 adc=2805 adcm=2241 adcn=0 gl=0 +[RX] 2026-10-26T19:52:00.086+08:00 [PROF2] t=3265 defd=131065 defs=37714 netp=3987 netn=1622 adcp=9 adcq=0 gl=0 +[RX] 2026-10-26T19:52:01.844+08:00 [PROF] t=5030 uic=157 uip=22447 uipn=10841 uil=10998 uiw=12538 uis=1283 uisn=0 adc=4569 adcm=2241 adcn=0 gl=0 +[RX] 2026-10-26T19:52:01.858+08:00 [PROF2] t=5030 defd=131065 defs=37714 netp=3987 netn=0 adcp=9 adcq=0 gl=0 +[RX] 2026-10-26T19:52:02.317+08:00 [2026-10-26 11:52:01] [STACK] default peak_used=2172/5120 free_min=2948 (57%) +[RX] 2026-10-26T19:52:02.317+08:00 [2026-10-26 11:52:01] [STACK] net peak_used=1116/3840 free_min=2724 (70%) +[RX] 2026-10-26T19:52:02.327+08:00 [2026-10-26 11:52:01] [STACK] ftp peak_used=740/4096 free_min=3356 (81%) +[RX] 2026-10-26T19:52:02.338+08:00 [2026-10-26 11:52:01] [STACK] ui peak_used=4188/16384 free_min=12196 (74%) +[RX] 2026-10-26T19:52:02.338+08:00 [2026-10-26 11:52:01] [STACK] timesync peak_used=616/2560 free_min=1944 (75%) +[RX] 2026-10-26T19:52:02.348+08:00 [2026-10-26 11:52:01] [STACK] adc peak_used=944/2560 free_min=1616 (63%) +[RX] 2026-10-26T19:52:02.348+08:00 [2026-10-26 11:52:01] [STACK] iec104 peak_used=540/2560 free_min=2020 (78%) +[RX] 2026-10-26T19:52:02.358+08:00 [2026-10-26 11:52:01] [STACK] protect peak_used=492/2048 free_min=1556 (75%) +[RX] 2026-10-26T19:52:02.369+08:00 [2026-10-26 11:52:01] [STACK] heap free=15624 min_ever=8464 +[RX] 2026-10-26T19:52:03.872+08:00 [PROF] t=7060 uic=335 uip=73755 uipn=4206 uil=10998 uiw=12538 uis=1305 uisn=0 adc=6600 adcm=2241 adcn=0 gl=0 +[RX] 2026-10-26T19:52:03.882+08:00 [PROF2] t=7060 defd=131065 defs=37714 netp=3987 netn=0 adcp=9 adcq=0 gl=0 +[RX] 2026-10-26T19:52:05.892+08:00 [PROF] t=9078 uic=517 uip=73755 uipn=9840 uil=10999 uiw=12538 uis=1341 uisn=0 adc=8617 adcm=2241 adcn=0 gl=0 +[RX] 2026-10-26T19:52:05.902+08:00 [PROF2] t=9078 defd=131065 defs=37714 netp=3987 netn=0 adcp=9 adcq=0 gl=0 +[RX] 2026-10-26T19:52:07.279+08:00 [2026-10-26 11:52:06][ADC_TASK] frames=10001 idle=0 skip=59 seq=10006 frst_err=0 ring=9942 adc1_rc=0 adc1_err=0 adc1_seq=10004 adc1_gap=61 adc1_hw=0 tgap=1 +[RX] 2026-10-26T19:52:07.289+08:00 [2026-10-26 11:52:06][ADC_TASK] phasor(hb) C01-IA-F1: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:52:07.300+08:00 [2026-10-26 11:52:06][ADC_TASK] phasor(hb) C02-UA-F1: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:52:07.300+08:00 [2026-10-26 11:52:06][ADC_TASK] phasor(hb) C03-UN-F1: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:52:07.310+08:00 [2026-10-26 11:52:06][ADC_TASK] phasor(hb) C04-IA-F2: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:52:07.310+08:00 [2026-10-26 11:52:06][ADC_TASK] phasor(hb) C05-IA-F5: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:52:07.320+08:00 [2026-10-26 11:52:06][ADC_TASK] freq(hb): f=0 valid=0 (x0.01) +[RX] 2026-10-26T19:52:07.331+08:00 [2026-10-26 11:52:06][ADC_TASK] cal: ua_mv=1743 un_mv=1747 ia_mv=1747 vl=0x00 cl=0xe6 rail=0x000 edge=0x000 +[RX] 2026-10-26T19:52:07.342+08:00 [2026-10-26 11:52:06][ADC_TASK] meas: seq=50 v=1 ua_mv=0 un_mv=0 ia_mv=0 f=0 fv=0 +[RX] 2026-10-26T19:52:07.899+08:00 [PROF] t=11083 uic=692 uip=74504 uipn=10741 uil=11045 uiw=12538 uis=1341 uisn=0 adc=10621 adcm=2787 adcn=0 gl=0 +[RX] 2026-10-26T19:52:07.909+08:00 [PROF2] t=11083 defd=131065 defs=37714 netp=5988 netn=0 adcp=9 adcq=0 gl=0 +[RX] 2026-10-26T19:52:08.369+08:00 [2026-10-26 11:52:07] [STACK] default peak_used=2172/5120 free_min=2948 (57%) +[RX] 2026-10-26T19:52:08.369+08:00 [2026-10-26 11:52:07] [STACK] net peak_used=1116/3840 free_min=2724 (70%) +[RX] 2026-10-26T19:52:08.380+08:00 [2026-10-26 11:52:07] [STACK] ftp peak_used=740/4096 free_min=3356 (81%) +[RX] 2026-10-26T19:52:08.390+08:00 [2026-10-26 11:52:07] [STACK] ui peak_used=4188/16384 free_min=12196 (74%) +[RX] 2026-10-26T19:52:08.390+08:00 [2026-10-26 11:52:07] [STACK] timesync peak_used=616/2560 free_min=1944 (75%) +[RX] 2026-10-26T19:52:08.401+08:00 [2026-10-26 11:52:07] [STACK] adc peak_used=1000/2560 free_min=1560 (60%) +[RX] 2026-10-26T19:52:08.411+08:00 [2026-10-26 11:52:07] [STACK] iec104 peak_used=540/2560 free_min=2020 (78%) +[RX] 2026-10-26T19:52:08.411+08:00 [2026-10-26 11:52:07] [STACK] protect peak_used=492/2048 free_min=1556 (75%) +[RX] 2026-10-26T19:52:08.422+08:00 [2026-10-26 11:52:07] [STACK] heap free=15624 min_ever=8464 +[RX] 2026-10-26T19:52:09.924+08:00 [PROF] t=13113 uic=870 uip=74504 uipn=2840 uil=10997 uiw=12538 uis=1341 uisn=0 adc=12651 adcm=2787 adcn=0 gl=0 +[RX] 2026-10-26T19:52:09.935+08:00 [PROF2] t=13113 defd=131065 defs=37714 netp=5988 netn=0 adcp=9 adcq=0 gl=0 +[RX] 2026-10-26T19:52:11.942+08:00 [PROF] t=15131 uic=1052 uip=74504 uipn=9840 uil=10999 uiw=12538 uis=1341 uisn=0 adc=14669 adcm=2787 adcn=0 gl=0 +[RX] 2026-10-26T19:52:11.953+08:00 [PROF2] t=15131 defd=131065 defs=37714 netp=5988 netn=0 adcp=9 adcq=0 gl=0 +[RX] 2026-10-26T19:52:13.967+08:00 [PROF] t=17149 uic=1234 uip=74504 uipn=9839 uil=11000 uiw=12538 uis=1341 uisn=0 adc=16687 adcm=2787 adcn=0 gl=0 +[RX] 2026-10-26T19:52:13.967+08:00 [PROF2] t=17149 defd=131065 defs=37714 netp=5988 netn=0 adcp=9 adcq=0 gl=0 +[RX] 2026-10-26T19:52:15.983+08:00 [PROF] t=19167 uic=1416 uip=74504 uipn=9840 uil=10984 uiw=12538 uis=1341 uisn=0 adc=18705 adcm=2787 adcn=0 gl=0 +[RX] 2026-10-26T19:52:15.993+08:00 [PROF2] t=19167 defd=131065 defs=37714 netp=5988 netn=0 adcp=9 adcq=0 gl=0 +[RX] 2026-10-26T19:52:17.276+08:00 [2026-10-26 11:52:16][ADC_TASK] frames=20000 idle=0 skip=64 seq=20006 frst_err=0 ring=19936 adc1_rc=0 adc1_err=0 adc1_seq=20004 adc1_gap=67 adc1_hw=0 tgap=2 +[RX] 2026-10-26T19:52:17.286+08:00 [2026-10-26 11:52:16][ADC_TASK] phasor(hb) C01-IA-F1: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:52:17.297+08:00 [2026-10-26 11:52:16][ADC_TASK] phasor(hb) C02-UA-F1: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:52:17.297+08:00 [2026-10-26 11:52:16][ADC_TASK] phasor(hb) C03-UN-F1: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:52:17.307+08:00 [2026-10-26 11:52:16][ADC_TASK] phasor(hb) C04-IA-F2: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:52:17.317+08:00 [2026-10-26 11:52:16][ADC_TASK] phasor(hb) C05-IA-F5: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:52:17.328+08:00 [2026-10-26 11:52:16][ADC_TASK] freq(hb): f=0 valid=0 (x0.01) +[RX] 2026-10-26T19:52:17.328+08:00 [2026-10-26 11:52:16][ADC_TASK] cal: ua_mv=1743 un_mv=1747 ia_mv=1747 vl=0x00 cl=0xe6 rail=0x000 edge=0x000 +[RX] 2026-10-26T19:52:17.338+08:00 [2026-10-26 11:52:16][ADC_TASK] meas: seq=100 v=1 ua_mv=0 un_mv=0 ia_mv=0 f=0 fv=0 +[RX] 2026-10-26T19:52:17.993+08:00 [PROF] t=21184 uic=1592 uip=83999 uipn=1839 uil=10999 uiw=73968 uis=73954 uisn=0 adc=20721 adcm=2898 adcn=0 gl=0 +[RX] 2026-10-26T19:52:18.003+08:00 [PROF2] t=21184 defd=131065 defs=37714 netp=5988 netn=0 adcp=9 adcq=0 gl=0 +[RX] 2026-10-26T19:52:20.012+08:00 [PROF] t=23202 uic=1774 uip=83999 uipn=9840 uil=10998 uiw=73968 uis=73954 uisn=0 adc=22739 adcm=2898 adcn=0 gl=0 +[RX] 2026-10-26T19:52:20.023+08:00 [PROF2] t=23202 defd=131065 defs=37714 netp=5988 netn=0 adcp=9 adcq=0 gl=0 +[RX] 2026-10-26T19:52:22.037+08:00 [PROF] t=25220 uic=1956 uip=83999 uipn=9840 uil=10999 uiw=73968 uis=73954 uisn=0 adc=24757 adcm=2898 adcn=0 gl=0 +[RX] 2026-10-26T19:52:22.037+08:00 [PROF2] t=25220 defd=131065 defs=37714 netp=5988 netn=0 adcp=9 adcq=0 gl=0 +[RX] 2026-10-26T19:52:24.051+08:00 [PROF] t=27238 uic=2138 uip=83999 uipn=9839 uil=10999 uiw=73968 uis=73954 uisn=0 adc=26775 adcm=2898 adcn=0 gl=0 +[RX] 2026-10-26T19:52:24.061+08:00 [PROF2] t=27238 defd=131065 defs=37714 netp=5988 netn=0 adcp=9 adcq=0 gl=0 +[RX] 2026-10-26T19:52:26.067+08:00 [PROF] t=29256 uic=2320 uip=83999 uipn=9840 uil=10999 uiw=73968 uis=73954 uisn=0 adc=28793 adcm=2898 adcn=0 gl=0 +[RX] 2026-10-26T19:52:26.078+08:00 [PROF2] t=29256 defd=131065 defs=37714 netp=5988 netn=0 adcp=9 adcq=0 gl=0 +[RX] 2026-10-26T19:52:27.277+08:00 [2026-10-26 11:52:26][ADC_TASK] frames=29999 idle=0 skip=68 seq=30006 frst_err=0 ring=29931 adc1_rc=0 adc1_err=0 adc1_seq=30004 adc1_gap=72 adc1_hw=0 tgap=3 +[RX] 2026-10-26T19:52:27.288+08:00 [2026-10-26 11:52:26][ADC_TASK] phasor(hb) C01-IA-F1: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:52:27.298+08:00 [2026-10-26 11:52:26][ADC_TASK] phasor(hb) C02-UA-F1: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:52:27.298+08:00 [2026-10-26 11:52:26][ADC_TASK] phasor(hb) C03-UN-F1: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:52:27.308+08:00 [2026-10-26 11:52:26][ADC_TASK] phasor(hb) C04-IA-F2: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:52:27.319+08:00 [2026-10-26 11:52:26][ADC_TASK] phasor(hb) C05-IA-F5: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:52:27.319+08:00 [2026-10-26 11:52:26][ADC_TASK] freq(hb): f=0 valid=0 (x0.01) +[RX] 2026-10-26T19:52:27.329+08:00 [2026-10-26 11:52:26][ADC_TASK] cal: ua_mv=1743 un_mv=1747 ia_mv=1747 vl=0x00 cl=0xe6 rail=0x000 edge=0x000 +[RX] 2026-10-26T19:52:27.339+08:00 [2026-10-26 11:52:26][ADC_TASK] meas: seq=150 v=1 ua_mv=0 un_mv=0 ia_mv=0 f=0 fv=0 +[RX] 2026-10-26T19:52:28.092+08:00 [PROF] t=31283 uic=2497 uip=83999 uipn=840 uil=10998 uiw=73968 uis=73954 uisn=827 adc=30819 adcm=2902 adcn=0 gl=0 +[RX] 2026-10-26T19:52:28.103+08:00 [PROF2] t=31283 defd=131065 defs=37714 netp=5988 netn=0 adcp=9 adcq=0 gl=0 +[RX] 2026-10-26T19:52:30.113+08:00 [PROF] t=33301 uic=2678 uip=83999 uipn=9840 uil=10998 uiw=73968 uis=73954 uisn=0 adc=32837 adcm=2902 adcn=0 gl=0 +[RX] 2026-10-26T19:52:30.124+08:00 [PROF2] t=33301 defd=131065 defs=37714 netp=5988 netn=0 adcp=9 adcq=0 gl=0 +[RX] 2026-10-26T19:52:32.133+08:00 [PROF] t=35319 uic=2860 uip=83999 uipn=9839 uil=11000 uiw=73968 uis=73954 uisn=0 adc=34855 adcm=2902 adcn=0 gl=0 +[RX] 2026-10-26T19:52:32.143+08:00 [PROF2] t=35319 defd=131065 defs=37714 netp=5988 netn=0 adcp=9 adcq=0 gl=0 + + +################################################################################################ +### BLOCK R3 serial gen=266 lines=165 [ERR]=0 anchors=1 verdict=PASS +################################################################################################ +[RX] 2026-10-26T19:52:33.227+08:00 [----/--/-- --:--:--][APP] boot: syslog init OK +[RX] 2026-10-26T19:52:33.227+08:00 [----/--/-- --:--:--][APP] fw build: Oct 26 2026 19:43:23 suite=NONE dstr=off +[RX] 2026-10-26T19:52:33.242+08:00 [----/--/-- --:--:--][APP] reset cause: software (NVIC_SystemReset) (CSR=0x14000000) +[RX] 2026-10-26T19:52:33.242+08:00 PREVRUN seg=2 seq=2157840491 t=35937 +[RX] 2026-10-26T19:52:33.254+08:00 TICKRUN uw=7 n=7 duw=4294931366 +[RX] 2026-10-26T19:52:33.254+08:00 [----/--/-- --:--:--][RTC] sd2506_init: OK +[RX] 2026-10-26T19:52:33.254+08:00 [----/--/-- --:--:--][APP] SD2506 init: OK (ret=0) +[RX] 2026-10-26T19:52:33.265+08:00 [2026-10-26 11:52:32][CLK] sys_clock_init: RTC initial time 2026-10-26 11:52:32 +[RX] 2026-10-26T19:52:33.280+08:00 [2026-10-26 11:52:32][CLK] sys_clock_init: wall clock base = unix 1793015552, base_tick=138 +[RX] 2026-10-26T19:52:33.280+08:00 [2026-10-26 11:52:32][APP] RS485 init: OK (UART4, DE=PA15) +[RX] 2026-10-26T19:52:33.295+08:00 [2026-10-26 11:52:32][NAND] Resetting NAND... +[RX] 2026-10-26T19:52:33.308+08:00 [2026-10-26 11:52:32][NAND] Reading NAND ID... +[RX] 2026-10-26T19:52:33.322+08:00 [2026-10-26 11:52:32][NAND] NAND ID: MID=0xC8, DID=0x52 +[RX] 2026-10-26T19:52:33.322+08:00 [2026-10-26 11:52:32][NAND] Scanning bad blocks... +[RX] 2026-10-26T19:52:33.461+08:00 [2026-10-26 11:52:32][NAND] BBT scan: 0 bad blocks found +[RX] 2026-10-26T19:52:33.461+08:00 [2026-10-26 11:52:32][NAND] Enabling ECC... +[RX] 2026-10-26T19:52:33.475+08:00 [2026-10-26 11:52:32][NAND] Unlocking block protection... +[RX] 2026-10-26T19:52:33.475+08:00 [2026-10-26 11:52:32][NAND] Locating BBT pool... +[RX] 2026-10-26T19:52:33.475+08:00 [2026-10-26 11:52:32][NAND] Loading persisted BBT... +[RX] 2026-10-26T19:52:33.487+08:00 [2026-10-26 11:52:32][NAND] NAND init OK +[RX] 2026-10-26T19:52:33.487+08:00 [2026-10-26 11:52:32][APP] NAND init: OK +[RX] 2026-10-26T19:52:33.487+08:00 [2026-10-26 11:52:32][ADC] Init OK +[RX] 2026-10-26T19:52:33.487+08:00 [2026-10-26 11:52:32][APP] ADC init: OK +[RX] 2026-10-26T19:52:33.498+08:00 [2026-10-26 11:52:32][APP] ADC input layer init: OK +[RX] 2026-10-26T19:52:33.498+08:00 [2026-10-26 11:52:32][APP] phasor layer init: OK (inst=5) +[RX] 2026-10-26T19:52:33.511+08:00 [2026-10-26 11:52:32][APP] freq layer init: OK +[RX] 2026-10-26T19:52:33.511+08:00 [2026-10-26 11:52:32][CFG] register: section 'adc_cal' (9 keys) +[RX] 2026-10-26T19:52:33.521+08:00 [2026-10-26 11:52:32][CFG] register: section 'adc_cal_ofs' (8 keys) +[RX] 2026-10-26T19:52:33.521+08:00 [2026-10-26 11:52:32][APP] adc cal init: OK (k_q16 tpafe=10000000 stm32=52800000) +[RX] 2026-10-26T19:52:33.532+08:00 [2026-10-26 11:52:32][CFG] register: section 'run_par' (9 keys) +[RX] 2026-10-26T19:52:33.532+08:00 [2026-10-26 11:52:32][APP] run par init: OK (db9 k/b via adc_cal, evt=1<<8) +[RX] 2026-10-26T19:52:33.544+08:00 [2026-10-26 11:52:32][CFG] register: section 'comm' (2 keys) +[RX] 2026-10-26T19:52:33.554+08:00 [2026-10-26 11:52:32][APP] comm init: OK (ca=1 port=2404) +[RX] 2026-10-26T19:52:33.554+08:00 [2026-10-26 11:52:32][APP] protection init: OK (set=40 elm=9) +[RX] 2026-10-26T19:52:33.565+08:00 [2026-10-26 11:52:32][APP] SD2506 ID: 2512153425482405 +[RX] 2026-10-26T19:52:33.565+08:00 [2026-10-26 11:52:32][APP] SD2506 time: 2026-10-26 11:52:32 (week 1) +[RX] 2026-10-26T19:52:33.576+08:00 [2026-10-26 11:52:32][APP] SD2506 temp: 25 C +[RX] 2026-10-26T19:52:33.576+08:00 [2026-10-26 11:52:32][APP] SD2506 battery: 3.12 V +[RX] 2026-10-26T19:52:33.586+08:00 [2026-10-26 11:52:32][APP] App init OK +[RX] 2026-10-26T19:52:33.586+08:00 [2026-10-26 11:52:32][NAND_FTL] Initializing NAND FTL... +[RX] 2026-10-26T19:52:33.618+08:00 [2026-10-26 11:52:32][PROT] uncalibrated -> protection blocked (UA/UN/IA VALID not all set) +[RX] 2026-10-26T19:52:33.691+08:00 [2026-10-26 11:52:32][NAND_FTL] Map resumed: 14094/97504 sectors used +[RX] 2026-10-26T19:52:33.691+08:00 [2026-10-26 11:52:32][NAND_FTL] Map head=49840 tail=3132 epoch=7 +[RX] 2026-10-26T19:52:33.701+08:00 [2026-10-26 11:52:32][NAND_FTL] NAND FTL ready (capacity: 97504 pages = 190 MB) +[RX] 2026-10-26T19:52:33.785+08:00 [2026-10-26 11:52:32] [FS] FATFS mounted +[RX] 2026-10-26T19:52:33.837+08:00 [2026-10-26 11:52:32][SYSLOG] runlog boot entry: reboot +[RX] 2026-10-26T19:52:33.847+08:00 [2026-10-26 11:52:32][CFG] register: section 'network' (4 keys) +[RX] 2026-10-26T19:52:33.847+08:00 [2026-10-26 11:52:32][CFG] register: section 'ftp' (3 keys) +[RX] 2026-10-26T19:52:33.858+08:00 [2026-10-26 11:52:32][CFG] load: OK (957B, heap free 16552B) +[RX] 2026-10-26T19:52:33.869+08:00 [2026-10-26 11:52:32][NET_CFG] load: OK ip=192.168.1.100 +[RX] 2026-10-26T19:52:33.879+08:00 [2026-10-26 11:52:32] [CFG] prot set loaded (/prot_set.bin) +[RX] 2026-10-26T19:52:33.900+08:00 [2026-10-26 11:52:32][ADC_TASK] first: UA=11430 UB=1057 UC=942 UN=11454 IA=11451 IB=1010 IC=1002 IN=982 T=970 +[RX] 2026-10-26T19:52:33.900+08:00 [2026-10-26 11:52:32][ADC_TASK] phasor(first) C01-IA-F1: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:52:33.910+08:00 [2026-10-26 11:52:32][ADC_TASK] phasor(first) C02-UA-F1: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:52:33.920+08:00 [2026-10-26 11:52:32][ADC_TASK] phasor(first) C03-UN-F1: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:52:33.931+08:00 [2026-10-26 11:52:32][ADC_TASK] phasor(first) C04-IA-F2: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:52:33.931+08:00 [2026-10-26 11:52:32][ADC_TASK] phasor(first) C05-IA-F5: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:52:33.941+08:00 [2026-10-26 11:52:32][ADC_TASK] freq(first): f=0 valid=0 (x0.01) +[RX] 2026-10-26T19:52:33.941+08:00 [2026-10-26 11:52:32][PROT] protect task start: cycle=20ms elm=9 +[RX] 2026-10-26T19:52:33.952+08:00 [2026-10-26 11:52:32][NET_TASK] === Network Init === +[RX] 2026-10-26T19:52:33.952+08:00 [2026-10-26 11:52:32][NET] ch395f ver=0x4A fun_para=0x08 +[RX] 2026-10-26T19:52:33.962+08:00 MISS start snap=0x000001E7 req=0x000001F7 t=833 +[RX] 2026-10-26T19:52:33.962+08:00 [2026-10-26 11:52:32][WD] [WD] armed: timeout ~2498ms (worst ~1701ms), miss_tol=800ms +[RX] 2026-10-26T19:52:34.014+08:00 [2026-10-26 11:52:32][NET_TASK] net init: OK +[RX] 2026-10-26T19:52:34.014+08:00 [2026-10-26 11:52:32][NET_TASK] MAC: 3C:AB:72:53:2B:12 +[RX] 2026-10-26T19:52:34.024+08:00 [2026-10-26 11:52:32][NET_TASK] IP_INF: IP=192.168.1.100 GW=192.168.1.1 MASK=255.255.255.0 +[RX] 2026-10-26T19:52:34.035+08:00 [2026-10-26 11:52:32][UI_TASK] UI task: started, wait net ready +[RX] 2026-10-26T19:52:35.986+08:00 [2026-10-26 11:52:34][NET_TASK] PHY: 100M FULL +[RX] 2026-10-26T19:52:35.997+08:00 [2026-10-26 11:52:34][NET_TASK] netTask: started (single-socket mode) +[RX] 2026-10-26T19:52:36.028+08:00 [2026-10-26 11:52:34] [FTP] using factory default password +[RX] 2026-10-26T19:52:36.060+08:00 [2026-10-26 11:52:34][TIME_SYNC] time_sync: TCP listen on :8888 (sock=0) +[RX] 2026-10-26T19:52:36.101+08:00 [2026-10-26 11:52:34][I104] i104: listening on 2404 +[RX] 2026-10-26T19:52:36.101+08:00 [2026-10-26 11:52:34] [FTP] waiting for connection... +[RX] 2026-10-26T19:52:36.112+08:00 [2026-10-26 11:52:34][UI_TASK] UI task: net ready, init port +[RX] 2026-10-26T19:52:36.112+08:00 [2026-10-26 11:52:34][UI_TASK] UI task: ui_port_init enter +[RX] 2026-10-26T19:52:36.122+08:00 [2026-10-26 11:52:34][UI_PORT] theme: mono dark_bg=true applied +[RX] 2026-10-26T19:52:36.132+08:00 [2026-10-26 11:52:34][UI_TASK] UI port init: OK +[RX] 2026-10-26T19:52:36.132+08:00 [2026-10-26 11:52:34][UI_TASK] UI task: ui_menu_init enter +[RX] 2026-10-26T19:52:36.132+08:00 [2026-10-26 11:52:34][UI_MENU] menu build start: total=15136 free=12692 big=12692 +[RX] 2026-10-26T19:52:36.143+08:00 [2026-10-26 11:52:34][UI_MENU_VIEW] view init: root frame w=66 h=107 +[RX] 2026-10-26T19:52:36.153+08:00 [2026-10-26 11:52:34][UI_MENU] menu build done: total=15020 free=11828 big=11816 used=3192 +[RX] 2026-10-26T19:52:36.164+08:00 [2026-10-26 11:52:34][UI_TASK] UI menu init: OK +[RX] 2026-10-26T19:52:36.164+08:00 [2026-10-26 11:52:34][UI_STANDBY] standby: ready (idle=60000ms) +[RX] 2026-10-26T19:52:36.174+08:00 [2026-10-26 11:52:34][UI_TASK] UI standby: ready (idle=60s) +[RX] 2026-10-26T19:52:36.226+08:00 [2026-10-26 11:52:34][UI_TASK] UI net sink: started (port 7003) +[RX] 2026-10-26T19:52:36.226+08:00 MISS start snap=0x000001E7 req=0x000001F7 t=3101 +[RX] 2026-10-26T19:52:36.237+08:00 [PROF] t=3105 uic=0 uip=0 uipn=0 uil=0 uiw=0 uis=0 uisn=0 adc=2645 adcm=2228 adcn=0 gl=0 +[RX] 2026-10-26T19:52:36.237+08:00 [PROF2] t=3105 defd=130912 defs=38741 netp=3013 netn=1597 adcp=9 adcq=0 gl=0 +[RX] 2026-10-26T19:52:38.147+08:00 [PROF] t=5020 uic=171 uip=22422 uipn=6840 uil=10998 uiw=12513 uis=1283 uisn=0 adc=4559 adcm=2228 adcn=0 gl=0 +[RX] 2026-10-26T19:52:38.161+08:00 [PROF2] t=5020 defd=130912 defs=38741 netp=3013 netn=0 adcp=9 adcq=0 gl=0 +[RX] 2026-10-26T19:52:38.619+08:00 [2026-10-26 11:52:37] [STACK] default peak_used=2172/5120 free_min=2948 (57%) +[RX] 2026-10-26T19:52:38.619+08:00 [2026-10-26 11:52:37] [STACK] net peak_used=1116/3840 free_min=2724 (70%) +[RX] 2026-10-26T19:52:38.629+08:00 [2026-10-26 11:52:37] [STACK] ftp peak_used=740/4096 free_min=3356 (81%) +[RX] 2026-10-26T19:52:38.639+08:00 [2026-10-26 11:52:37] [STACK] ui peak_used=4116/16384 free_min=12268 (74%) +[RX] 2026-10-26T19:52:38.650+08:00 [2026-10-26 11:52:37] [STACK] timesync peak_used=616/2560 free_min=1944 (75%) +[RX] 2026-10-26T19:52:38.650+08:00 [2026-10-26 11:52:37] [STACK] adc peak_used=920/2560 free_min=1640 (64%) +[RX] 2026-10-26T19:52:38.660+08:00 [2026-10-26 11:52:37] [STACK] iec104 peak_used=540/2560 free_min=2020 (78%) +[RX] 2026-10-26T19:52:38.670+08:00 [2026-10-26 11:52:37] [STACK] protect peak_used=492/2048 free_min=1556 (75%) +[RX] 2026-10-26T19:52:38.670+08:00 [2026-10-26 11:52:37] [STACK] heap free=15624 min_ever=8464 +[RX] 2026-10-26T19:52:40.184+08:00 [PROF] t=7050 uic=349 uip=73568 uipn=2840 uil=10998 uiw=12513 uis=1283 uisn=0 adc=6589 adcm=2228 adcn=0 gl=0 +[RX] 2026-10-26T19:52:40.184+08:00 [PROF2] t=7050 defd=130912 defs=38741 netp=3985 netn=0 adcp=9 adcq=0 gl=0 +[RX] 2026-10-26T19:52:42.195+08:00 [PROF] t=9068 uic=531 uip=73568 uipn=9840 uil=10997 uiw=12513 uis=1283 uisn=0 adc=8607 adcm=2228 adcn=0 gl=0 +[RX] 2026-10-26T19:52:42.205+08:00 [PROF2] t=9068 defd=130912 defs=38741 netp=3985 netn=0 adcp=9 adcq=0 gl=0 +[RX] 2026-10-26T19:52:43.593+08:00 [2026-10-26 11:52:42][ADC_TASK] frames=10001 idle=0 skip=48 seq=10006 frst_err=0 ring=9953 adc1_rc=0 adc1_err=0 adc1_seq=10004 adc1_gap=50 adc1_hw=0 tgap=1 +[RX] 2026-10-26T19:52:43.604+08:00 [2026-10-26 11:52:42][ADC_TASK] phasor(hb) C01-IA-F1: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:52:43.614+08:00 [2026-10-26 11:52:42][ADC_TASK] phasor(hb) C02-UA-F1: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:52:43.614+08:00 [2026-10-26 11:52:42][ADC_TASK] phasor(hb) C03-UN-F1: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:52:43.624+08:00 [2026-10-26 11:52:42][ADC_TASK] phasor(hb) C04-IA-F2: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:52:43.635+08:00 [2026-10-26 11:52:42][ADC_TASK] phasor(hb) C05-IA-F5: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:52:43.635+08:00 [2026-10-26 11:52:42][ADC_TASK] freq(hb): f=0 valid=0 (x0.01) +[RX] 2026-10-26T19:52:43.645+08:00 [2026-10-26 11:52:42][ADC_TASK] cal: ua_mv=1743 un_mv=1747 ia_mv=1747 vl=0x00 cl=0xe6 rail=0x000 edge=0x000 +[RX] 2026-10-26T19:52:43.656+08:00 [2026-10-26 11:52:42][ADC_TASK] meas: seq=50 v=1 ua_mv=0 un_mv=0 ia_mv=0 f=0 fv=0 +[RX] 2026-10-26T19:52:44.217+08:00 [PROF] t=11083 uic=707 uip=82999 uipn=839 uil=10995 uiw=73643 uis=73629 uisn=825 adc=10621 adcm=2876 adcn=0 gl=0 +[RX] 2026-10-26T19:52:44.217+08:00 [PROF2] t=11083 defd=130912 defs=38741 netp=6005 netn=0 adcp=9 adcq=0 gl=0 +[RX] 2026-10-26T19:52:44.682+08:00 [2026-10-26 11:52:43] [STACK] default peak_used=2172/5120 free_min=2948 (57%) +[RX] 2026-10-26T19:52:44.682+08:00 [2026-10-26 11:52:43] [STACK] net peak_used=1116/3840 free_min=2724 (70%) +[RX] 2026-10-26T19:52:44.693+08:00 [2026-10-26 11:52:43] [STACK] ftp peak_used=740/4096 free_min=3356 (81%) +[RX] 2026-10-26T19:52:44.704+08:00 [2026-10-26 11:52:43] [STACK] ui peak_used=4116/16384 free_min=12268 (74%) +[RX] 2026-10-26T19:52:44.704+08:00 [2026-10-26 11:52:43] [STACK] timesync peak_used=616/2560 free_min=1944 (75%) +[RX] 2026-10-26T19:52:44.714+08:00 [2026-10-26 11:52:43] [STACK] adc peak_used=1000/2560 free_min=1560 (60%) +[RX] 2026-10-26T19:52:44.724+08:00 [2026-10-26 11:52:43] [STACK] iec104 peak_used=540/2560 free_min=2020 (78%) +[RX] 2026-10-26T19:52:44.724+08:00 [2026-10-26 11:52:43] [STACK] protect peak_used=492/2048 free_min=1556 (75%) +[RX] 2026-10-26T19:52:44.735+08:00 [2026-10-26 11:52:43] [STACK] heap free=15624 min_ever=8464 +[RX] 2026-10-26T19:52:46.240+08:00 [PROF] t=13113 uic=884 uip=82999 uipn=3207 uil=10999 uiw=73643 uis=73629 uisn=0 adc=12652 adcm=2876 adcn=0 gl=0 +[RX] 2026-10-26T19:52:46.250+08:00 [PROF2] t=13113 defd=130912 defs=38741 netp=6005 netn=0 adcp=9 adcq=0 gl=0 +[RX] 2026-10-26T19:52:48.262+08:00 [PROF] t=15131 uic=1066 uip=82999 uipn=9839 uil=11000 uiw=73643 uis=73629 uisn=0 adc=14669 adcm=2876 adcn=0 gl=0 +[RX] 2026-10-26T19:52:48.273+08:00 [PROF2] t=15131 defd=130912 defs=38741 netp=6005 netn=0 adcp=9 adcq=0 gl=0 +[RX] 2026-10-26T19:52:50.280+08:00 [PROF] t=17149 uic=1248 uip=82999 uipn=9840 uil=10994 uiw=73643 uis=73629 uisn=0 adc=16687 adcm=2876 adcn=0 gl=0 +[RX] 2026-10-26T19:52:50.290+08:00 [PROF2] t=17149 defd=130912 defs=38741 netp=6005 netn=0 adcp=9 adcq=0 gl=0 +[RX] 2026-10-26T19:52:52.301+08:00 [PROF] t=19167 uic=1430 uip=82999 uipn=9839 uil=10999 uiw=73643 uis=73629 uisn=0 adc=18705 adcm=2876 adcn=0 gl=0 +[RX] 2026-10-26T19:52:52.301+08:00 [PROF2] t=19167 defd=130912 defs=38741 netp=6005 netn=0 adcp=9 adcq=0 gl=0 +[RX] 2026-10-26T19:52:53.588+08:00 [2026-10-26 11:52:52][ADC_TASK] frames=20000 idle=0 skip=57 seq=20006 frst_err=0 ring=19943 adc1_rc=0 adc1_err=0 adc1_seq=20004 adc1_gap=60 adc1_hw=0 tgap=2 +[RX] 2026-10-26T19:52:53.599+08:00 [2026-10-26 11:52:52][ADC_TASK] phasor(hb) C01-IA-F1: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:52:53.609+08:00 [2026-10-26 11:52:52][ADC_TASK] phasor(hb) C02-UA-F1: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:52:53.620+08:00 [2026-10-26 11:52:52][ADC_TASK] phasor(hb) C03-UN-F1: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:52:53.631+08:00 [2026-10-26 11:52:52][ADC_TASK] phasor(hb) C04-IA-F2: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:52:53.631+08:00 [2026-10-26 11:52:52][ADC_TASK] phasor(hb) C05-IA-F5: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:52:53.641+08:00 [2026-10-26 11:52:52][ADC_TASK] freq(hb): f=0 valid=0 (x0.01) +[RX] 2026-10-26T19:52:53.641+08:00 [2026-10-26 11:52:52][ADC_TASK] cal: ua_mv=1743 un_mv=1747 ia_mv=1747 vl=0x00 cl=0xe6 rail=0x000 edge=0x000 +[RX] 2026-10-26T19:52:53.652+08:00 [2026-10-26 11:52:52][ADC_TASK] meas: seq=100 v=1 ua_mv=0 un_mv=0 ia_mv=0 f=0 fv=0 +[RX] 2026-10-26T19:52:54.311+08:00 [PROF] t=21184 uic=1606 uip=84014 uipn=1840 uil=10998 uiw=73947 uis=73933 uisn=0 adc=20721 adcm=2897 adcn=0 gl=0 +[RX] 2026-10-26T19:52:54.322+08:00 [PROF2] t=21184 defd=130912 defs=38741 netp=6005 netn=0 adcp=9 adcq=0 gl=0 +[RX] 2026-10-26T19:52:56.332+08:00 [PROF] t=23202 uic=1788 uip=84014 uipn=9840 uil=10997 uiw=73947 uis=73933 uisn=0 adc=22739 adcm=2897 adcn=0 gl=0 +[RX] 2026-10-26T19:52:56.342+08:00 [PROF2] t=23202 defd=130912 defs=38741 netp=6005 netn=0 adcp=9 adcq=0 gl=0 +[RX] 2026-10-26T19:52:58.353+08:00 [PROF] t=25220 uic=1970 uip=84014 uipn=9839 uil=10999 uiw=73947 uis=73933 uisn=0 adc=24757 adcm=2897 adcn=0 gl=0 +[RX] 2026-10-26T19:52:58.353+08:00 [PROF2] t=25220 defd=130912 defs=38741 netp=6005 netn=0 adcp=9 adcq=0 gl=0 +[RX] 2026-10-26T19:53:00.366+08:00 [PROF] t=27238 uic=2152 uip=84014 uipn=9840 uil=10998 uiw=73947 uis=73933 uisn=0 adc=26775 adcm=2897 adcn=0 gl=0 +[RX] 2026-10-26T19:53:00.376+08:00 [PROF2] t=27238 defd=130912 defs=38741 netp=6005 netn=0 adcp=9 adcq=0 gl=0 +[RX] 2026-10-26T19:53:02.381+08:00 [PROF] t=29256 uic=2334 uip=84014 uipn=9840 uil=10999 uiw=73947 uis=73933 uisn=0 adc=28793 adcm=2897 adcn=0 gl=0 +[RX] 2026-10-26T19:53:02.391+08:00 [PROF2] t=29256 defd=130912 defs=38741 netp=6005 netn=0 adcp=9 adcq=0 gl=0 +[RX] 2026-10-26T19:53:03.591+08:00 [2026-10-26 11:53:02][ADC_TASK] frames=29999 idle=0 skip=67 seq=30006 frst_err=0 ring=29932 adc1_rc=0 adc1_err=0 adc1_seq=30004 adc1_gap=71 adc1_hw=0 tgap=3 +[RX] 2026-10-26T19:53:03.602+08:00 [2026-10-26 11:53:02][ADC_TASK] phasor(hb) C01-IA-F1: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:53:03.612+08:00 [2026-10-26 11:53:02][ADC_TASK] phasor(hb) C02-UA-F1: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:53:03.612+08:00 [2026-10-26 11:53:02][ADC_TASK] phasor(hb) C03-UN-F1: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:53:03.623+08:00 [2026-10-26 11:53:02][ADC_TASK] phasor(hb) C04-IA-F2: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:53:03.633+08:00 [2026-10-26 11:53:02][ADC_TASK] phasor(hb) C05-IA-F5: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:53:03.643+08:00 [2026-10-26 11:53:02][ADC_TASK] freq(hb): f=0 valid=0 (x0.01) +[RX] 2026-10-26T19:53:03.643+08:00 [2026-10-26 11:53:02][ADC_TASK] cal: ua_mv=1743 un_mv=1747 ia_mv=1747 vl=0x00 cl=0xe6 rail=0x000 edge=0x000 +[RX] 2026-10-26T19:53:03.654+08:00 [2026-10-26 11:53:02][ADC_TASK] meas: seq=150 v=1 ua_mv=0 un_mv=0 ia_mv=0 f=0 fv=0 +[RX] 2026-10-26T19:53:04.410+08:00 [PROF] t=31284 uic=2511 uip=84067 uipn=1841 uil=10998 uiw=73947 uis=73933 uisn=0 adc=30820 adcm=2897 adcn=0 gl=0 +[RX] 2026-10-26T19:53:04.421+08:00 [PROF2] t=31284 defd=130912 defs=38741 netp=6005 netn=0 adcp=9 adcq=0 gl=0 +[RX] 2026-10-26T19:53:06.426+08:00 [PROF] t=33302 uic=2693 uip=84067 uipn=9840 uil=10999 uiw=73947 uis=73933 uisn=0 adc=32838 adcm=2897 adcn=0 gl=0 +[RX] 2026-10-26T19:53:06.436+08:00 [PROF2] t=33302 defd=130912 defs=38741 netp=6005 netn=0 adcp=9 adcq=0 gl=0 +[RX] 2026-10-26T19:53:08.451+08:00 [PROF] t=35320 uic=2875 uip=84067 uipn=9839 uil=10999 uiw=73947 uis=73933 uisn=0 adc=34856 adcm=2897 adcn=0 gl=0 +[RX] 2026-10-26T19:53:08.461+08:00 [PROF2] t=35320 defd=130912 defs=38741 netp=6005 netn=0 adcp=9 adcq=0 gl=0 + + +################################################################################################ +### BLOCK R4 serial gen=267 lines=156 [ERR]=0 anchors=1 verdict=PASS +################################################################################################ +[RX] 2026-10-26T19:53:09.349+08:00 [----/--/-- --:--:--][APP] boot: syslog init OK +[RX] 2026-10-26T19:53:09.349+08:00 [----/--/-- --:--:--][APP] fw build: Oct 26 2026 19:43:23 suite=NONE dstr=off +[RX] 2026-10-26T19:53:09.371+08:00 [----/--/-- --:--:--][APP] reset cause: software (NVIC_SystemReset) (CSR=0x14000000) +[RX] 2026-10-26T19:53:09.371+08:00 PREVRUN seg=2 seq=2157845544 t=35737 +[RX] 2026-10-26T19:53:09.371+08:00 TICKRUN uw=21 n=21 duw=4294931580 +[RX] 2026-10-26T19:53:09.390+08:00 [----/--/-- --:--:--][RTC] sd2506_init: OK +[RX] 2026-10-26T19:53:09.390+08:00 [----/--/-- --:--:--][APP] SD2506 init: OK (ret=0) +[RX] 2026-10-26T19:53:09.390+08:00 [2026-10-26 11:53:08][CLK] sys_clock_init: RTC initial time 2026-10-26 11:53:08 +[RX] 2026-10-26T19:53:09.390+08:00 [2026-10-26 11:53:08][CLK] sys_clock_init: wall clock base = unix 1793015588, base_tick=139 +[RX] 2026-10-26T19:53:09.407+08:00 [2026-10-26 11:53:08][APP] RS485 init: OK (UART4, DE=PA15) +[RX] 2026-10-26T19:53:09.440+08:00 [2026-10-26 11:53:08][NAND] Resetting NAND... +[RX] 2026-10-26T19:53:09.440+08:00 [2026-10-26 11:53:08][NAND] Reading NAND ID... +[RX] 2026-10-26T19:53:09.440+08:00 [2026-10-26 11:53:08][NAND] NAND ID: MID=0xC8, DID=0x52 +[RX] 2026-10-26T19:53:09.440+08:00 [2026-10-26 11:53:08][NAND] Scanning bad blocks... +[RX] 2026-10-26T19:53:09.575+08:00 [2026-10-26 11:53:08][NAND] BBT scan: 0 bad blocks found +[RX] 2026-10-26T19:53:09.588+08:00 [2026-10-26 11:53:08][NAND] Enabling ECC... +[RX] 2026-10-26T19:53:09.588+08:00 [2026-10-26 11:53:08][NAND] Unlocking block protection... +[RX] 2026-10-26T19:53:09.588+08:00 [2026-10-26 11:53:08][NAND] Locating BBT pool... +[RX] 2026-10-26T19:53:09.599+08:00 [2026-10-26 11:53:08][NAND] Loading persisted BBT... +[RX] 2026-10-26T19:53:09.599+08:00 [2026-10-26 11:53:08][NAND] NAND init OK +[RX] 2026-10-26T19:53:09.610+08:00 [2026-10-26 11:53:08][APP] NAND init: OK +[RX] 2026-10-26T19:53:09.610+08:00 [2026-10-26 11:53:08][ADC] Init OK +[RX] 2026-10-26T19:53:09.610+08:00 [2026-10-26 11:53:08][APP] ADC init: OK +[RX] 2026-10-26T19:53:09.623+08:00 [2026-10-26 11:53:08][APP] ADC input layer init: OK +[RX] 2026-10-26T19:53:09.623+08:00 [2026-10-26 11:53:08][APP] phasor layer init: OK (inst=5) +[RX] 2026-10-26T19:53:09.623+08:00 [2026-10-26 11:53:08][APP] freq layer init: OK +[RX] 2026-10-26T19:53:09.634+08:00 [2026-10-26 11:53:08][CFG] register: section 'adc_cal' (9 keys) +[RX] 2026-10-26T19:53:09.634+08:00 [2026-10-26 11:53:08][CFG] register: section 'adc_cal_ofs' (8 keys) +[RX] 2026-10-26T19:53:09.646+08:00 [2026-10-26 11:53:08][APP] adc cal init: OK (k_q16 tpafe=10000000 stm32=52800000) +[RX] 2026-10-26T19:53:09.646+08:00 [2026-10-26 11:53:08][CFG] register: section 'run_par' (9 keys) +[RX] 2026-10-26T19:53:09.656+08:00 [2026-10-26 11:53:08][APP] run par init: OK (db9 k/b via adc_cal, evt=1<<8) +[RX] 2026-10-26T19:53:09.667+08:00 [2026-10-26 11:53:08][CFG] register: section 'comm' (2 keys) +[RX] 2026-10-26T19:53:09.667+08:00 [2026-10-26 11:53:08][APP] comm init: OK (ca=1 port=2404) +[RX] 2026-10-26T19:53:09.677+08:00 [2026-10-26 11:53:08][APP] protection init: OK (set=40 elm=9) +[RX] 2026-10-26T19:53:09.688+08:00 [2026-10-26 11:53:08][APP] SD2506 ID: 2512153425482405 +[RX] 2026-10-26T19:53:09.688+08:00 [2026-10-26 11:53:08][APP] SD2506 time: 2026-10-26 11:53:08 (week 1) +[RX] 2026-10-26T19:53:09.699+08:00 [2026-10-26 11:53:08][APP] SD2506 temp: 25 C +[RX] 2026-10-26T19:53:09.699+08:00 [2026-10-26 11:53:08][APP] SD2506 battery: 3.12 V +[RX] 2026-10-26T19:53:09.709+08:00 [2026-10-26 11:53:08][APP] App init OK +[RX] 2026-10-26T19:53:09.709+08:00 [2026-10-26 11:53:08][NAND_FTL] Initializing NAND FTL... +[RX] 2026-10-26T19:53:09.730+08:00 [2026-10-26 11:53:08][PROT] uncalibrated -> protection blocked (UA/UN/IA VALID not all set) +[RX] 2026-10-26T19:53:09.804+08:00 [2026-10-26 11:53:08][NAND_FTL] Map resumed: 14094/97504 sectors used +[RX] 2026-10-26T19:53:09.815+08:00 [2026-10-26 11:53:08][NAND_FTL] Map head=49904 tail=3194 epoch=7 +[RX] 2026-10-26T19:53:09.825+08:00 [2026-10-26 11:53:08][NAND_FTL] NAND FTL ready (capacity: 97504 pages = 190 MB) +[RX] 2026-10-26T19:53:09.908+08:00 [2026-10-26 11:53:08] [FS] FATFS mounted +[RX] 2026-10-26T19:53:09.959+08:00 [2026-10-26 11:53:08][SYSLOG] runlog boot entry: reboot +[RX] 2026-10-26T19:53:09.959+08:00 [2026-10-26 11:53:08][CFG] register: section 'network' (4 keys) +[RX] 2026-10-26T19:53:09.969+08:00 [2026-10-26 11:53:08][CFG] register: section 'ftp' (3 keys) +[RX] 2026-10-26T19:53:09.980+08:00 [2026-10-26 11:53:08][CFG] load: OK (957B, heap free 16552B) +[RX] 2026-10-26T19:53:09.980+08:00 [2026-10-26 11:53:08][NET_CFG] load: OK ip=192.168.1.100 +[RX] 2026-10-26T19:53:09.990+08:00 [2026-10-26 11:53:08] [CFG] prot set loaded (/prot_set.bin) +[RX] 2026-10-26T19:53:10.011+08:00 [2026-10-26 11:53:08][ADC_TASK] first: UA=11428 UB=1057 UC=925 UN=11453 IA=11451 IB=1036 IC=1023 IN=942 T=997 +[RX] 2026-10-26T19:53:10.021+08:00 [2026-10-26 11:53:08][ADC_TASK] phasor(first) C01-IA-F1: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:53:10.031+08:00 [2026-10-26 11:53:08][ADC_TASK] phasor(first) C02-UA-F1: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:53:10.042+08:00 [2026-10-26 11:53:08][ADC_TASK] phasor(first) C03-UN-F1: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:53:10.042+08:00 [2026-10-26 11:53:08][ADC_TASK] phasor(first) C04-IA-F2: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:53:10.052+08:00 [2026-10-26 11:53:08][ADC_TASK] phasor(first) C05-IA-F5: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:53:10.063+08:00 [2026-10-26 11:53:08][ADC_TASK] freq(first): f=0 valid=0 (x0.01) +[RX] 2026-10-26T19:53:10.063+08:00 [2026-10-26 11:53:08][PROT] protect task start: cycle=20ms elm=9 +[RX] 2026-10-26T19:53:10.073+08:00 [2026-10-26 11:53:08][NET_TASK] === Network Init === +[RX] 2026-10-26T19:53:10.073+08:00 [2026-10-26 11:53:08][NET] ch395f ver=0x4A fun_para=0x08 +[RX] 2026-10-26T19:53:10.083+08:00 MISS start snap=0x000001E7 req=0x000001F7 t=833 +[RX] 2026-10-26T19:53:10.083+08:00 [2026-10-26 11:53:08][WD] [WD] armed: timeout ~2498ms (worst ~1701ms), miss_tol=800ms +[RX] 2026-10-26T19:53:10.094+08:00 [2026-10-26 11:53:08][NET_TASK] net init: OK +[RX] 2026-10-26T19:53:10.135+08:00 [2026-10-26 11:53:08][NET_TASK] MAC: 3C:AB:72:53:2B:12 +[RX] 2026-10-26T19:53:10.135+08:00 [2026-10-26 11:53:08][NET_TASK] IP_INF: IP=192.168.1.100 GW=192.168.1.1 MASK=255.255.255.0 +[RX] 2026-10-26T19:53:10.146+08:00 [2026-10-26 11:53:08][UI_TASK] UI task: started, wait net ready +[RX] 2026-10-26T19:53:12.085+08:00 [2026-10-26 11:53:10][NET_TASK] PHY: 100M FULL +[RX] 2026-10-26T19:53:12.106+08:00 [2026-10-26 11:53:10][NET_TASK] netTask: started (single-socket mode) +[RX] 2026-10-26T19:53:12.138+08:00 [2026-10-26 11:53:10] [FTP] using factory default password +[RX] 2026-10-26T19:53:12.169+08:00 [2026-10-26 11:53:10][TIME_SYNC] time_sync: TCP listen on :8888 (sock=0) +[RX] 2026-10-26T19:53:12.200+08:00 [2026-10-26 11:53:10][I104] i104: listening on 2404 +[RX] 2026-10-26T19:53:12.210+08:00 [2026-10-26 11:53:10] [FTP] waiting for connection... +[RX] 2026-10-26T19:53:12.210+08:00 [2026-10-26 11:53:10][UI_TASK] UI task: net ready, init port +[RX] 2026-10-26T19:53:12.221+08:00 [2026-10-26 11:53:10][UI_TASK] UI task: ui_port_init enter +[RX] 2026-10-26T19:53:12.231+08:00 [2026-10-26 11:53:10][UI_PORT] theme: mono dark_bg=true applied +[RX] 2026-10-26T19:53:12.231+08:00 [2026-10-26 11:53:10][UI_TASK] UI port init: OK +[RX] 2026-10-26T19:53:12.241+08:00 [2026-10-26 11:53:10][UI_TASK] UI task: ui_menu_init enter +[RX] 2026-10-26T19:53:12.241+08:00 [2026-10-26 11:53:10][UI_MENU] menu build start: total=15136 free=12692 big=12692 +[RX] 2026-10-26T19:53:12.252+08:00 [2026-10-26 11:53:10][UI_MENU_VIEW] view init: root frame w=66 h=107 +[RX] 2026-10-26T19:53:12.262+08:00 [2026-10-26 11:53:10][UI_MENU] menu build done: total=15020 free=11828 big=11816 used=3192 +[RX] 2026-10-26T19:53:12.272+08:00 [2026-10-26 11:53:10][UI_TASK] UI menu init: OK +[RX] 2026-10-26T19:53:12.272+08:00 [2026-10-26 11:53:10][UI_STANDBY] standby: ready (idle=60000ms) +[RX] 2026-10-26T19:53:12.283+08:00 [2026-10-26 11:53:10][UI_TASK] UI standby: ready (idle=60s) +[RX] 2026-10-26T19:53:12.325+08:00 [2026-10-26 11:53:10][UI_TASK] UI net sink: started (port 7003) +[RX] 2026-10-26T19:53:12.335+08:00 MISS start snap=0x000001E7 req=0x000001F7 t=3088 +[RX] 2026-10-26T19:53:12.335+08:00 [PROF] t=3092 uic=0 uip=0 uipn=0 uil=0 uiw=0 uis=0 uisn=0 adc=2630 adcm=2159 adcn=0 gl=0 +[RX] 2026-10-26T19:53:12.346+08:00 [PROF2] t=3092 defd=131098 defs=36361 netp=2018 netn=757 adcp=10 adcq=0 gl=0 +[RX] 2026-10-26T19:53:14.251+08:00 [PROF] t=5006 uic=171 uip=22229 uipn=6839 uil=10999 uiw=12322 uis=1286 uisn=0 adc=4544 adcm=2159 adcn=0 gl=0 +[RX] 2026-10-26T19:53:14.261+08:00 [PROF2] t=5006 defd=131098 defs=36361 netp=2984 netn=0 adcp=10 adcq=0 gl=0 +[RX] 2026-10-26T19:53:14.732+08:00 [2026-10-26 11:53:13] [STACK] default peak_used=2160/5120 free_min=2960 (57%) +[RX] 2026-10-26T19:53:14.732+08:00 [2026-10-26 11:53:13] [STACK] net peak_used=1116/3840 free_min=2724 (70%) +[RX] 2026-10-26T19:53:14.732+08:00 [2026-10-26 11:53:13] [STACK] ftp peak_used=740/4096 free_min=3356 (81%) +[RX] 2026-10-26T19:53:14.752+08:00 [2026-10-26 11:53:13] [STACK] ui peak_used=4188/16384 free_min=12196 (74%) +[RX] 2026-10-26T19:53:14.752+08:00 [2026-10-26 11:53:13] [STACK] timesync peak_used=616/2560 free_min=1944 (75%) +[RX] 2026-10-26T19:53:14.752+08:00 [2026-10-26 11:53:13] [STACK] adc peak_used=1000/2560 free_min=1560 (60%) +[RX] 2026-10-26T19:53:14.772+08:00 [2026-10-26 11:53:13] [STACK] iec104 peak_used=540/2560 free_min=2020 (78%) +[RX] 2026-10-26T19:53:14.772+08:00 [2026-10-26 11:53:13] [STACK] protect peak_used=492/2048 free_min=1556 (75%) +[RX] 2026-10-26T19:53:14.783+08:00 [2026-10-26 11:53:13] [STACK] heap free=15624 min_ever=8464 +[RX] 2026-10-26T19:53:16.281+08:00 [PROF] t=7036 uic=349 uip=73749 uipn=2838 uil=10999 uiw=12322 uis=1286 uisn=0 adc=6574 adcm=2159 adcn=0 gl=0 +[RX] 2026-10-26T19:53:16.292+08:00 [PROF2] t=7036 defd=131098 defs=36361 netp=2984 netn=0 adcp=10 adcq=0 gl=0 +[RX] 2026-10-26T19:53:18.302+08:00 [PROF] t=9054 uic=531 uip=73749 uipn=9839 uil=10998 uiw=12322 uis=1286 uisn=0 adc=8592 adcm=2159 adcn=0 gl=0 +[RX] 2026-10-26T19:53:18.313+08:00 [PROF2] t=9054 defd=131098 defs=36361 netp=2984 netn=0 adcp=10 adcq=0 gl=0 +[RX] 2026-10-26T19:53:19.716+08:00 [2026-10-26 11:53:18][ADC_TASK] frames=10001 idle=0 skip=0 seq=10006 frst_err=0 ring=10001 adc1_rc=0 adc1_err=0 adc1_seq=10004 adc1_gap=3 adc1_hw=0 tgap=1 +[RX] 2026-10-26T19:53:19.727+08:00 [2026-10-26 11:53:18][ADC_TASK] phasor(hb) C01-IA-F1: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:53:19.737+08:00 [2026-10-26 11:53:18][ADC_TASK] phasor(hb) C02-UA-F1: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:53:19.737+08:00 [2026-10-26 11:53:18][ADC_TASK] phasor(hb) C03-UN-F1: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:53:19.748+08:00 [2026-10-26 11:53:18][ADC_TASK] phasor(hb) C04-IA-F2: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:53:19.748+08:00 [2026-10-26 11:53:18][ADC_TASK] phasor(hb) C05-IA-F5: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:53:19.758+08:00 [2026-10-26 11:53:18][ADC_TASK] freq(hb): f=0 valid=0 (x0.01) +[RX] 2026-10-26T19:53:19.769+08:00 [2026-10-26 11:53:18][ADC_TASK] cal: ua_mv=1743 un_mv=1747 ia_mv=1747 vl=0x00 cl=0xe6 rail=0x000 edge=0x000 +[RX] 2026-10-26T19:53:19.779+08:00 [2026-10-26 11:53:18][ADC_TASK] meas: seq=50 v=1 ua_mv=0 un_mv=0 ia_mv=0 f=0 fv=0 +[RX] 2026-10-26T19:53:20.336+08:00 [PROF] t=11084 uic=708 uip=77540 uipn=10838 uil=10941 uiw=12322 uis=1286 uisn=0 adc=10621 adcm=2855 adcn=0 gl=0 +[RX] 2026-10-26T19:53:20.347+08:00 [PROF2] t=11084 defd=131098 defs=36361 netp=4018 netn=0 adcp=10 adcq=0 gl=0 +[RX] 2026-10-26T19:53:22.356+08:00 [PROF] t=13102 uic=890 uip=77540 uipn=9839 uil=10998 uiw=12322 uis=1286 uisn=0 adc=12639 adcm=2855 adcn=0 gl=0 +[RX] 2026-10-26T19:53:22.356+08:00 [PROF2] t=13102 defd=131098 defs=36361 netp=4018 netn=0 adcp=10 adcq=0 gl=0 +[RX] 2026-10-26T19:53:24.374+08:00 [PROF] t=15120 uic=1072 uip=77540 uipn=9838 uil=11000 uiw=12322 uis=1286 uisn=0 adc=14657 adcm=2855 adcn=0 gl=0 +[RX] 2026-10-26T19:53:24.374+08:00 [PROF2] t=15120 defd=131098 defs=36361 netp=4018 netn=0 adcp=10 adcq=0 gl=0 +[RX] 2026-10-26T19:53:26.382+08:00 [PROF] t=17138 uic=1254 uip=77540 uipn=9839 uil=10998 uiw=12322 uis=1286 uisn=0 adc=16675 adcm=2855 adcn=0 gl=0 +[RX] 2026-10-26T19:53:26.392+08:00 [PROF2] t=17138 defd=131098 defs=36361 netp=4018 netn=0 adcp=10 adcq=0 gl=0 +[RX] 2026-10-26T19:53:28.402+08:00 [PROF] t=19156 uic=1436 uip=77540 uipn=9838 uil=11000 uiw=12322 uis=1286 uisn=0 adc=18693 adcm=2855 adcn=0 gl=0 +[RX] 2026-10-26T19:53:28.412+08:00 [PROF2] t=19156 defd=131098 defs=36361 netp=4018 netn=0 adcp=10 adcq=0 gl=0 +[RX] 2026-10-26T19:53:29.711+08:00 [2026-10-26 11:53:28][ADC_TASK] frames=20000 idle=0 skip=0 seq=20006 frst_err=0 ring=20000 adc1_rc=0 adc1_err=0 adc1_seq=20004 adc1_gap=4 adc1_hw=0 tgap=2 +[RX] 2026-10-26T19:53:29.721+08:00 [2026-10-26 11:53:28][ADC_TASK] phasor(hb) C01-IA-F1: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:53:29.731+08:00 [2026-10-26 11:53:28][ADC_TASK] phasor(hb) C02-UA-F1: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:53:29.741+08:00 [2026-10-26 11:53:28][ADC_TASK] phasor(hb) C03-UN-F1: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:53:29.741+08:00 [2026-10-26 11:53:28][ADC_TASK] phasor(hb) C04-IA-F2: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:53:29.752+08:00 [2026-10-26 11:53:28][ADC_TASK] phasor(hb) C05-IA-F5: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:53:29.762+08:00 [2026-10-26 11:53:28][ADC_TASK] freq(hb): f=0 valid=0 (x0.01) +[RX] 2026-10-26T19:53:29.762+08:00 [2026-10-26 11:53:28][ADC_TASK] cal: ua_mv=1743 un_mv=1747 ia_mv=1747 vl=0x00 cl=0xe6 rail=0x000 edge=0x000 +[RX] 2026-10-26T19:53:29.772+08:00 [2026-10-26 11:53:28][ADC_TASK] meas: seq=100 v=1 ua_mv=0 un_mv=0 ia_mv=0 f=0 fv=0 +[RX] 2026-10-26T19:53:30.431+08:00 [PROF] t=21184 uic=1614 uip=77540 uipn=838 uil=10999 uiw=12322 uis=1286 uisn=577 adc=20720 adcm=2864 adcn=0 gl=0 +[RX] 2026-10-26T19:53:30.442+08:00 [PROF2] t=21184 defd=131098 defs=36361 netp=4018 netn=0 adcp=10 adcq=0 gl=0 +[RX] 2026-10-26T19:53:32.453+08:00 [PROF] t=23202 uic=1795 uip=77540 uipn=9838 uil=11000 uiw=18740 uis=18478 uisn=0 adc=22738 adcm=2864 adcn=0 gl=0 +[RX] 2026-10-26T19:53:32.463+08:00 [PROF2] t=23202 defd=131098 defs=36361 netp=4018 netn=0 adcp=10 adcq=0 gl=0 +[RX] 2026-10-26T19:53:34.466+08:00 [PROF] t=25220 uic=1977 uip=77540 uipn=9839 uil=10998 uiw=18740 uis=18478 uisn=0 adc=24756 adcm=2864 adcn=0 gl=0 +[RX] 2026-10-26T19:53:34.477+08:00 [PROF2] t=25220 defd=131098 defs=36361 netp=4018 netn=0 adcp=10 adcq=0 gl=0 +[RX] 2026-10-26T19:53:36.486+08:00 [PROF] t=27238 uic=2159 uip=77540 uipn=9839 uil=11000 uiw=18740 uis=18478 uisn=0 adc=26774 adcm=2864 adcn=0 gl=0 +[RX] 2026-10-26T19:53:36.497+08:00 [PROF2] t=27238 defd=131098 defs=36361 netp=4018 netn=0 adcp=10 adcq=0 gl=0 +[RX] 2026-10-26T19:53:38.506+08:00 [PROF] t=29256 uic=2341 uip=77540 uipn=9839 uil=10998 uiw=18740 uis=18478 uisn=0 adc=28792 adcm=2864 adcn=0 gl=0 +[RX] 2026-10-26T19:53:38.516+08:00 [PROF2] t=29256 defd=131098 defs=36361 netp=4018 netn=0 adcp=10 adcq=0 gl=0 +[RX] 2026-10-26T19:53:39.709+08:00 [2026-10-26 11:53:38][ADC_TASK] frames=29999 idle=0 skip=0 seq=30006 frst_err=0 ring=29999 adc1_rc=0 adc1_err=0 adc1_seq=30004 adc1_gap=5 adc1_hw=0 tgap=3 +[RX] 2026-10-26T19:53:39.719+08:00 [2026-10-26 11:53:38][ADC_TASK] phasor(hb) C01-IA-F1: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:53:39.730+08:00 [2026-10-26 11:53:38][ADC_TASK] phasor(hb) C02-UA-F1: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:53:39.740+08:00 [2026-10-26 11:53:38][ADC_TASK] phasor(hb) C03-UN-F1: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:53:39.751+08:00 [2026-10-26 11:53:38][ADC_TASK] phasor(hb) C04-IA-F2: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:53:39.751+08:00 [2026-10-26 11:53:38][ADC_TASK] phasor(hb) C05-IA-F5: Re=0 Im=0 rms=0 (x0.1) +[RX] 2026-10-26T19:53:39.762+08:00 [2026-10-26 11:53:38][ADC_TASK] freq(hb): f=0 valid=0 (x0.01) +[RX] 2026-10-26T19:53:39.762+08:00 [2026-10-26 11:53:38][ADC_TASK] cal: ua_mv=1743 un_mv=1747 ia_mv=1747 vl=0x00 cl=0xe6 rail=0x000 edge=0x000 +[RX] 2026-10-26T19:53:39.772+08:00 [2026-10-26 11:53:38][ADC_TASK] meas: seq=150 v=1 ua_mv=0 un_mv=0 ia_mv=0 f=0 fv=0 +[RX] 2026-10-26T19:53:40.535+08:00 [PROF] t=31284 uic=2518 uip=82999 uipn=2838 uil=10999 uiw=73648 uis=73638 uisn=0 adc=30819 adcm=2871 adcn=0 gl=0 +[RX] 2026-10-26T19:53:40.545+08:00 [PROF2] t=31284 defd=131098 defs=36361 netp=4018 netn=0 adcp=10 adcq=0 gl=0 +[RX] 2026-10-26T19:53:42.551+08:00 [PROF] t=33302 uic=2700 uip=82999 uipn=9839 uil=10998 uiw=73648 uis=73638 uisn=0 adc=32837 adcm=2871 adcn=0 gl=0 +[RX] 2026-10-26T19:53:42.561+08:00 [PROF2] t=33302 defd=131098 defs=36361 netp=4018 netn=0 adcp=10 adcq=0 gl=0 +[RX] 2026-10-26T19:53:44.569+08:00 [PROF] t=35320 uic=2882 uip=82999 uipn=9839 uil=11000 uiw=73648 uis=73638 uisn=0 adc=34855 adcm=2871 adcn=0 gl=0 +[RX] 2026-10-26T19:53:44.579+08:00 [PROF2] t=35320 defd=131098 defs=36361 netp=4018 netn=0 adcp=10 adcq=0 gl=0 diff --git a/docs/测试说明/boot_log_data/README.md b/docs/测试说明/boot_log_data/README.md index 1bac4f0b..44b6113b 100644 --- a/docs/测试说明/boot_log_data/README.md +++ b/docs/测试说明/boot_log_data/README.md @@ -21,7 +21,41 @@ | 随文件登记 | 在下方 §3 清单登记日期、构建、负载、关键 `[STACK]` 水位（如 defaultTask 峰值） | | 入库门槛 | **只存有对照价值的快照**——常规 `@test` 通过日志不必入库 | | 故障注入日志 | 含**刻意产生**的 `[ERR]` 行（如兜底门闭锁）的日志用自定义标记集采集：`--required` 加闭锁/复归两行、`--forbidden` 去掉 `[ERR]` 保留 `FAIL;ERROR;HardFault`。此类日志的 PASS 只代表注入行为符合预期，不代表标记集等价于日常门禁 | +| 证据可达性 | 台账**只准引用已入库的文件**。被忽略规则挡住的产物（如全局 `*.bin`）要么显式 force-add 入库，要么把行内引用改写成「本机产物（不入库）」——**两者都不做 = 让台账行指着仓库里不存在的证据**，按图索骥的人只能拿到 File Not Found | +### 2.1 一处已知断链的处置记录（2026-10-26 核查） + +清单里 2026-10-12 B9 那一行引用的 `20261012_B9_soe_pre.bin` 与 `20261012_B9_soe_after_post.bin` +**从未入库**：`.gitignore` 第 115 行的全局 `*.bin` 规则挡的，`git ls-files` 查无此文件，但文件确实在本机台架目录里。 +核查过全目录 37 个被引用的证据名，**只有这两个是真断链**——其余查不到的名字要么是模板占位（如 +`boot_log_.txt`），要么是设备侧路径（`/log/soe.log`、`/prot_set.bin`），本就不是仓库文件。 + +**选定处置：入库（对这两个具名文件 force-add），不改成「可再生成的派生物」。** 理由是后者在这里前提不成立： + +- 这两个 `.bin` 是当次 FTP 下载的 `/log/soe.log` **原始 64 B 记录帧**，而该文件是 512 条环形累计历史—— + 当时那 56 条早被后续台架长跑覆盖，**不可复现、不可重生成**。把它写成「可由脚本重新生成」= 新造一条无法 + 核实的断言，比现在这条断链更糟（这正是本卡要修的毛病，不能拿一个新毛病换一个旧毛病）。 +- 体积可忽略：两个文件合计 **6,528 B**（2,944 + 3,584，64 B/条的裸记录），比同目录**已入库**的两份解码 + 文本 `20261012_B9_soe_decode_pre.txt` / `20261012_B9_soe_decode_post.txt`（7,861 + 9,521 B）还小；对登记簿 + 「仓库体积膨胀观察」那条（.git 约 233 MB）没有可测影响。 +- 不放宽任何规则：全局 `*.bin` 与 `simulator/tests/ref/*.bin` 的显式反选（`.gitignore` 第 130 行）**都不动**， + 只对这两个具名文件各 `git add -f` 一次。入库理由要与黄金参考区分开：那边入库是因为它是**判据本体** + （不入库则新克隆上这条门禁直接不存在），这边入库是因为它是**不可复现的原始证据**——理由不同， + 但都落在「被引用的文件必须在库里」这一条上，不构成把全局规则打开的口实。 + +落库动作由提交车道执行（本卡不碰 git）： + +```powershell +git add -f docs/测试说明/boot_log_data/20261012_B9_soe_pre.bin +git add -f docs/测试说明/boot_log_data/20261012_B9_soe_after_post.bin +``` + +> ⚠ 同目录另有 **3 个同状态的本机 `.bin`** 目前**没有**被任何台账行引用，故本卡不代其决定，只登记防复发： +> `20261026_prod_77779d49_ui_set_badge_uncal.bin`、`20261026_task24_boardnav_standby_unknown.bin`、 +> `20261026_task24_boardnav_view_set.bin`（各 3200 B = 160×160 单色帧）。**谁先把它们写进台账，谁就得先按 +> §2「证据可达性」二选一处置掉**——否则本节这条断链会以同样形态重长一遍。 + +--- ## 3. 清单 | 日期 | 构建 / 负载 | 关键 `[STACK]` 水位 | 文件 | @@ -40,7 +74,8 @@ | 2026-10-25 | 同固件 / **f3rounds 轮② e02_probe 单独 30 min**（50 个探针掉线窗） | **v1.1 判据 FAIL（如实申报，零放水）**：stall=8 = 3 事件（20:06:05/20:16:54/20:20:30，miss=998-1000/1187-1189/1249-1250），mask=0x1E7 纯 UI 单串×7 + 0x167 UI+I104×1，h= 环全部 ≥8 连窗真申报；**饿死型**（每样本点 uisn=0、mg=217/262、拖点不在推流段而在 feed/port 墙钟）=「reconcile 突发饿死 uiTask」登记行与 E-27/E-28 批 3 的直接立项证据；全窗无 IWDG 复位 | `f3rounds_r2_probe_30min.log.gz` | | 2026-10-21 | `prod` + **兜底新鲜度门停 TIM3 注入探针**（`task/adc-health-design-doc`，探针已撤）/ 开机 + 45 s | `protect` **620/2048（69%）**、`adc` 与 heap 水位同前；`[ERR][PROT] … blocked (hf=0x00000100)` +5462ms、`recovered` +5757ms、`health:` 0 次、`reset cause:` ×1 | `20261021_probe_stale_gate_boot_log.txt` | | 2026-10-26 | `prod`（**像来自仓外只读 detached worktree `_wt/bench-21-77779d49` @ 77779d49**；主树当时另有在飞文档改动，这份像**不含**主树未提交内容——别拿本行结论去对主树源码）/ 开机 + 30 s 空载，**@test PASS** | `protect` **492/2048（75%）**、`iec104` 540/2560（78%）、`adc` 1000/2560（60%）、`ui` 4088/16384（75%）、`default` 2160/5120（57%）、heap free=15624 **min_ever=8464**；`protection init: OK (set=40 elm=9)`、锚点 `reset cause:` ×1、**[ERR]=0 / Fault=0**、`net init: OK` **+762 ms**、身份戳 `Oct 26 2026 16:27:01 suite=NONE dstr=off` 从 hex 抠出并与线上相符、`-CmpFile` 回读 No difference found（**排在采日志之后**）；⚠ **启动日志行内字节交错缺陷**：protectTask `[PROT]` 与 `[NAND_FTL]` 两个写者并发，3 次启动命中 2 次，hexdump 实证「某行内多出的字节恰等于下一行被吃掉的行首」（串口 framing 错不可能让行变长）→ 已立项派 App/log 属主 | `20261026_prod_77779d49_boot_log.txt` / `20261026_prod_77779d49_boot_log_reset_only.txt` / `20261026_prod_console_interleave_evidence.txt` | -| 2026-10-26 | 同镜像 / **整定页两条实机判据**（主站 `test/host/iec104_master.py` 以库形式复用，驱动脚本留在仓外 `_wt/.state/bench21_104.py`，**未改仓库**；复位只用 `-Rst -Run`，**全程不重烧**） | **C_RD 27/27 可寻址项全中出厂值**（清单取自 `git show 77779d49:App/algo/prot_set.[ch]` 而非工作树；**13 个 comm_addr=0 本地项结构性不可寻址 → 明确不参与本判据**，另以 0x8854/0x8855/0x8862 三个未映射地址实证「不应答」）；⚠ **未标定闭锁态下 C_SE 仍允许写**（闭锁 ≠ 禁写）：0x8858=7.5 / 0x885D=1234 / 0x8820=11000 三项 sel+exe 均 actcon 且 C_RD 同值 → 仅复位后仍为 7.5/1234/11000，启动日志 `[CFG] prot set loaded (/prot_set.bin)`、CORRUPT=0、version change=0、YX31=OFF（**校验和通过**）；越界写 0x8858=500(>100)、0x8821=0.5(<1) 均回 **actcon+PN** 且原值一字未变；还原默认值 → 再复位 → 27/27 回默认（双向持久化，台架留在出厂态）。屏检：整定页（123 修改密码）标题右侧**「未标定」徽标在位**（Glyph 精确命中 x=105/117/129；同页用查看密码进去无徽标 = 设计如此），**LOCK 未见且可证未闭锁**（ENTER 被消费进入数值编辑，而闭锁时 ENTER 一律不消费），全程零提交；强制真 LOCK 需篡改 `/prot_set.bin`，台架禁做 | `20261026_prod_77779d49_iec104_setpoint_leg.txt` / `20261026_prod_77779d49_ui_set_badge_uncal.png`（同名 `.bin` = 原始 3200 B 帧、可 `board_ui_nav.py --classify` 复判，但被 `.gitignore` 的 `*.bin` 全局规则挡住，**入库需 `git add -f`**；顺带一条既存事实：本目录上方 B9 那两行引用的 `20261012_B9_soe*.bin` 同样从未入库，`git ls-files` 查不到）/ `20261026_prod_77779d49_ui_set_view_readonly.png` / `20261026_prod_77779d49_ui_set_edit_enter_accepted.png` / `20261026_prod_77779d49_ui_nav_trace.json` | +| 2026-10-26 | 同镜像 / **整定页两条实机判据**（主站 `test/host/iec104_master.py` 以库形式复用，驱动脚本留在仓外 `_wt/scratch/bench21_104.py`（原写 `_wt/.state/`，但那是 task-worktree 的**台账目录**，放脚手架会把 `list` 撞崩，已挪出），**未改仓库**；复位只用 `-Rst -Run`，**全程不重烧**） | **C_RD 27/27 可寻址项全中出厂值**（清单取自 `git show 77779d49:App/algo/prot_set.[ch]` 而非工作树；**13 个 comm_addr=0 本地项结构性不可寻址 → 明确不参与本判据**，另以 0x8854/0x8855/0x8862 三个未映射地址实证「不应答」）；⚠ **未标定闭锁态下 C_SE 仍允许写**（闭锁 ≠ 禁写）：0x8858=7.5 / 0x885D=1234 / 0x8820=11000 三项 sel+exe 均 actcon 且 C_RD 同值 → 仅复位后仍为 7.5/1234/11000，启动日志 `[CFG] prot set loaded (/prot_set.bin)`、CORRUPT=0、version change=0、YX31=OFF（**校验和通过**）；越界写 0x8858=500(>100)、0x8821=0.5(<1) 均回 **actcon+PN** 且原值一字未变；还原默认值 → 再复位 → 27/27 回默认（双向持久化，台架留在出厂态）。屏检：整定页（123 修改密码）标题右侧**「未标定」徽标在位**（Glyph 精确命中 x=105/117/129；同页用查看密码进去无徽标 = 设计如此），**LOCK 未见且可证未闭锁**（ENTER 被消费进入数值编辑，而闭锁时 ENTER 一律不消费），全程零提交；强制真 LOCK 需篡改 `/prot_set.bin`，台架禁做 | `20261026_prod_77779d49_iec104_setpoint_leg.txt` / `20261026_prod_77779d49_ui_set_badge_uncal.png`（同名 `.bin` = 原始 3200 B 帧、可 `board_ui_nav.py --classify` 复判，但被 `.gitignore` 的 `*.bin` 全局规则挡住，**入库需 `git add -f`**；顺带一条既存事实：本目录上方 B9 那两行引用的 `20261012_B9_soe*.bin` 同样从未入库，`git ls-files` 查不到）/ `20261026_prod_77779d49_ui_set_view_readonly.png` / `20261026_prod_77779d49_ui_set_edit_enter_accepted.png` / `20261026_prod_77779d49_ui_nav_trace.json` | +| 2026-10-26 | `prod`（**像 = `1d4b6a17` 控制台整行独占修复**；仓外只读 detached worktree `_wt/bench-23-1d4b6a17` 出像，主树同 HEAD 但压着 UI 道 task-6 未提交半成品 → **像不含它**）/ **task-23 收口复验：1 次烧录启动 + 连续 4 次「仅复位不重烧」** | **5/5 启动 [ERR]=0、CONSOLE dropped=0**（让路没被计成 [ERR]，与设计一致）；两条旧受害行**逐字节完整**：`[PROT]` 未标定行恒 91 px、`[NAND_FTL] Initializing…` 恒 56 px 且行首 `[ts]` 齐（旧缺陷正是吃它行首）；锚点 `reset cause:` ×1、无 Fault、`comm init: OK (ca=1 port=2404)` 每次都在、`prot set loaded` ×1 且 CORRUPT ×0；heap **free=15624 min_ever=8464 与上一轮逐字节相同**、protect 492/2048 相同；ui 峰值 **4116~4188/16384** —— **同一份像自己就摆 72 B**，故相对上一轮 4088 的 +100 B **不可归因于本修复**（顺带记账：`[STACK]` 峰值有 ±100 B 噪声，拿它当门禁得先定容差）；行序一处变化：`[NAND_FTL]` 现排在 `[PROT]` 前一行 = 抢不到独占者整行入环延后发，与修法吻合；**反证非空跑**：同一校验器打旧缺陷那份 → rc=1 FAIL、`nand_head_ok=false`（那行真读作 `26-10-26 …`）；`-CmpFile` 排在全批日志之后、No difference found | `20261026_bench23_flash_boot_log.txt` / `20261026_bench23_reset_only_boots_r1_r4.txt`（4 次仅复位原始字节，按 gen 264~267 分块）/ `20261026_bench23_recheck_verdicts.txt`（逐启动判据 + 反证 + 栈口径 + 最终回读） | > f3rounds 两只是**判读证据存档**（非 `[STACK]` 水位快照）：源为 serial-assistant live 日志的 > 字节偏移切片（不 clear、行边界对齐），gz 前置 ASCII 头行携带偏移窗、负载定义与 v1.1 判据 diff --git a/docs/测试说明/启动日志原子性复验流程.md b/docs/测试说明/启动日志原子性复验流程.md new file mode 100644 index 00000000..ef02504f --- /dev/null +++ b/docs/测试说明/启动日志原子性复验流程.md @@ -0,0 +1,107 @@ +# 启动日志原子性复验流程（台架） + +> **这篇是什么**：验证"控制台整行独占 / 崩溃遗言原子性"这类**行级完整性**判据的固定动作与口径。 +> 它补的是 `../子系统设计/控制台单写者日志设计说明.md` 的**验收侧**：那边讲怎么修，这边讲怎么证明修好了、 +> 以及**为什么"标记全中"不等于"日志没坏"**。 +> 来源：2026-10-26 台架实测（缺陷立项 task-23、收口复验 task-30、工具与流程吸收 task-36）。 + +## 1. 为什么子串标记照不出交错 + +`.dsh/skills/serial-boot-test/scripts/verify_log.py` 的 `--required` 是**大小写敏感子串**匹配。 +交错缺陷的真实产物是这样的两行（原始捕获，未改写）： + +```text +[PROT] uncalibrated -> protection [blocked (UA/UN/IA VALI2D not all s0et) +26-10-26 08:37:07][NAND_FTL] Initializing NAND FTL... +``` + +第二行**仍然包含**标记串 `Initializing NAND FTL` —— 于是旧口径把这份启动判成 PASS。 +实测对照（同一份文件、同一台机器）： + +| 口径 | 命令要点 | 对缺陷捕获的判定 | +|---|---|---| +| 旧（子串） | `--required 'Initializing NAND FTL;uncalibrated -> protection'` | **PASS（假绿）** | +| 新（整行） | `--exact '\[...\]\[NAND_FTL\] Initializing NAND FTL\.\.\.'` | **FAIL**，并把缺行首的邻居原样打出来 | + +**结论**：任何"这一行可能丢行首 / 可能被插字节"的标记，必须用 `--exact` 整行锚定， +不得只用 `--required`。 + +## 2. 校验器口径（`verify_log.py`） + +| 开关 | 语义 | 为什么这样默认 | +|---|---|---| +| `--exact 'REGEX'` | 剥掉采集器前缀（`[RX] ` / `[+Nms]`）后**整行** `^REGEX$` 必须命中；同时报告"含该式最长字面串但未整行命中"的邻居行 = 交错特征 | 单点插字节即失配；邻居不得静默 | +| `…@@LEN=` 后缀 | **显式**钉该行字节长度 | 长度属于**某一份像**的属性；默认不钉，否则无辜改动就假红（实测同一份像 uiTask 峰值自己摆 72 B） | +| `--allow-residual N` | 允许行首前 N 个杂散字节（复位打断移位寄存器的已知残留），**记录但不判失败** | 崩溃注入腿允许 ≤1 残留；写成失败就会把已知现象当回归 | +| `--head-char C` | 命中行（去残留后）必须以 C 开头，如 `[` | 崩溃日志的行首形态本身就是判据 | +| `--pair FIRST THEN` | 恰好一条 FIRST，且其后**只有一条** THEN（跨复位配对） | 崩溃遗言必须与下一次启动的 `reset cause:` 成对；出现两条 = 有未记录/重复复位 | +| `--include-comments` | 不跳过 `#` 行 | 默认**跳过**：归档证据文件带 ASCII 溯源头，头里提到 `[ERR]` 不该触发 Forbidden（工具级假红防线） | +| `--selftest` | 跑内置 16 条判别用例后退出，无需日志与硬件 | "不可能失败的 PASS 就是空跑"——用例里含交错、缺行首、残留 1/2、配对错序，以及**"旧子串口径在同一条缺陷行上判 PASS"** 这一条盲区证明 | + +用法示例（一次仅复位启动的原子性判定）。四个行级开关**也已接进 `run_boot_test.py`**， +所以 @test 闭环里直接加 `--exact ... --pair ... --allow-residual 1 --head-char '['` 即可，无需单独跑本脚本： + +```powershell +& '.venv\Scripts\python.exe' .dsh\skills\serial-boot-test\scripts\verify_log.py ` + --log-path ` + --required 'App init OK;net init: OK' ` + --exact '\[\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}\]\[PROT\] uncalibrated -> protection blocked \(UA/UN/IA VALID not all set\)' ` + --exact '\[\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}\]\[NAND_FTL\] Initializing NAND FTL\.\.\.' ` + --max-boot-count 1 --show-tail-lines 0 +``` + +## 3. 固定动作（顺序即判据，别调） + +1. **环境**：继承完整环境，只补 `DTU_KEIL_UV4` / `DTU_STLINK_CLI`，并把 `TEMP`/`TMP` 指到真实目录。 + ⚠ 根因记账：本机注册表 **User 级 `TMP` 是未展开的字面量 `%USERPROFILE%\AppData\Local\Temp`** —— + 残缺环境里 UV4 会在仓库根建出字面量目录 `%SystemDrive%/`，而 `task_worktree.py` 会因找不到 + `git` 让 `keil_build.py` 报**假的"build 锁被占用"（rc=4）**。看到 rc=4 先 `lock status` 再判断，别默认是并发。 +2. **出像**：像必须来自**已提交 commit + 干净工作树**。主树脏（别人在飞）时走仓外只读 detached worktree： + `git worktree add --detach <_wt>/bench-- ` + `mklink /J \.venv
\.venv`； + 建树后 `git -C status --short` 必须为空，全程只读、不 commit、不跑生成器。 +3. **@build**：0 错误 0 警告；随后**从 .hex 二进制里抠身份戳**（不是从 build_log 里读），与之后线上读到的 + `fw build:` 逐字对上——这是"烧进去的就是这份像"的唯一硬证据。 +4. **烧录启动**：`@test` 已保证 flash(`-Rst -Run`) → 采日志 → 回读(`-CmpFile`) 的次序（`-CmpFile` 会复位目标， + 必须排最后）。 +5. **N 次仅复位对照**（N≥3）：每次 `clear`（记下 gen，证明窗口不重叠）→ `stlink_flash.py reset`（`-c SWD -Rst -Run`， + **零重烧**）→ `wait-idle` → 取日志逐块存档。"保存的值重启后还在"用重烧去验是**无意义**的。 +6. **逐块校验**：`--exact` 锚定受害行 + `--max-boot-count 1` + Forbidden 默认含 `[ERR]`； + 崩溃注入腿才加 `--pair\ --allow-residual 1\ --head-char '['`。 +7. **非空跑对照**：每换一版校验器，至少跑一次 `--selftest`，并把**缺陷发生时的原始捕获**再判一遍——必须 FAIL。 +8. **收尾**：最后一次硬件动作是 `cmp`（排在全批日志之后）；台账与证据按 `boot_log_data/README.md` 的口径归档。 + +## 4. 两条容易踩的纪律 + +1. **故意复位的腿不得并入"连续仅复位不重烧"的计数**。崩溃注入腿（MemManage/栈溢出钩子）本身就要复位设备， + 并进常规序列会被下一个人数锚点数判成异常。它必须单独跑、单独进台账、标题写明"本腿含故意复位"。 +2. **崩溃腿的判据是原子性，不是 `[ERR]` 为零**。内核故障钩子的输出**本身就以 `[ERR]` 开头** + （`[ERR] MEMFAULT …` / `[ERR] STACK OVERFLOW task=…`），在同一条路径上要求 `[ERR]=0` 等于要求它别工作； + 而**产品构建的正常启动根本不走 IPSR 路径**（多段裸发只在 `Src/freertos.c` 的两个内核钩子里）， + 所以"跑 5 次正常启动、[ERR] 零命中"**证不到 IPSR**——那是定义上的必然，是空跑。 + IPSR 主张交给主机侧套件（假 USART + IPSR + 临界区深度水位）；要硬件证据就得由代码道**提交触发器**， + 判据写"崩溃遗言一整行、恰好一次、`dropped=0`"，并按 `boot_log_data/README.md` §2「故障注入日志」 + 运行时放宽 `@test`（`--forbidden` 去掉 `[ERR]`、`--max-boot-count 2`）——**不改仓库配置**。 + +## 5. 栈与堆的比对口径 + +同一份像连跑 4 次仅复位启动，uiTask 峰值实测 4116~4188 B（**自身摆动 72 B**），heap 计数逐字节稳定。 +因此：**不要**用"栈水位不劣于上一轮"这种单次比较当判据。要么取 ≥3 次的最大值对最大值， +要么把 `scripts/stack_report.py` 的静态最坏链当硬线、运行时峰值只作趋势（定稿见 task-32）。 + +## 6. 锁与脚手架 + +- bench 锁是**会话级**，必须手工 acquire/release，且**用同一个名字**释放。 +- 非登记任务名（如临时验收窗）走 `lock release bench --task `（**不带** `--bench-pass`）即可释放； + `--bench-pass` 会先读 `_wt/.state/.json` 台账，没有就报"任务不存在"，`--force` 也救不了。 + 为记一个 PASS 去**造假台账**会白占 3 棵并发工作树名额——PASS 写进任务卡描述即可。 +- ⚠ **脚手架 `*.json` 一律不得放 `_wt/.state/`**：那是 task-worktree 的**台账目录**，脚本把每个 `*.json` + 当台账读，实测 `task_worktree.py list` 直接崩在 `KeyError: 'id'`。放 `_wt/scratch/`。 + +## 7. 关联 + +- 修法与设计口径：`../子系统设计/控制台单写者日志设计说明.md`（O1 两实例与字节账、§4.4.1 崩溃路径验证设计） +- 闭环与标记口径：`./自动化测试流程.md` +- 证据归档与命名：`./boot_log_data/README.md` +- 复位语义与回读次序：`./ST-LINK_CLI_复位使用说明.md` +- 烧录 / 采集 / 校验脚本：`../../.dsh/skills/serial-boot-test/SKILL.md`、`../../.dsh/skills/stlink-flash/SKILL.md`、 + `../../.dsh/skills/serial-assistant/SKILL.md` diff --git a/docs/测试说明/自动化测试流程.md b/docs/测试说明/自动化测试流程.md index 2c9e8abc..f7a51a94 100644 --- a/docs/测试说明/自动化测试流程.md +++ b/docs/测试说明/自动化测试流程.md @@ -26,7 +26,7 @@ | `.dsh/skills/serial-boot-test/scripts/run_boot_test.py` | `.dsh/skills/serial-boot-test/scripts/run_boot_test.py` | **一键闭环**：open + clear → 烧录 → 固件身份戳（从 hex 抠 `fw build:`）→ wait-idle（静默 8s/超时 30s/首字节 12s）→ 提取 `[RX]`（每行加 `[+Nms]` 时基）→ 回读校验（`stlink_flash.py cmp`）→ verify；`--keep-out` 清旧产物；退出码 0=PASS/1=FAIL/2=采集·烧录·回读错误/3=用法错误 | | `.dsh/skills/stlink-flash/scripts/stlink_flash.py` | `stlink-flash` skill | ST-LINK CLI 封装：`flash [hex]`（烧 + `-Rst -Run`）/ **`cmp [hex]`（回读比对，2026-10-10 加）**/ `reset`（只复位）/ `hard`（nRST 脉冲，CLI 拒 `RM=` 自动降级）/ `halt`/`run`/`list`；原 `MDK-ARM/reset.bat` 已于 2026-10-10 删除并全并入本 skill | | `.dsh/skills/serial-assistant/scripts/serial_tool.py` | `.dsh/skills/serial-assistant/` | Python 串口助手（常驻 daemon + 薄 CLI）：ports/open/send/status/log/clear/wait-idle/selftest；全量日志 `state/serial.log`（20MB 自动截头） | -| `.dsh/skills/serial-boot-test/scripts/verify_log.py` | `.dsh/skills/serial-boot-test/scripts/verify_log.py` | 对日志做标记校验：Required/Forbidden（**命中逐行打印行号+内容**）、启动锚点计数 `--max-boot-count`、原因白名单 `--expect-reset-cause`、标记顺序 `--require-order`、开机耗时 `--done-marker`/`--max-boot-ms`、`--json` 结构化输出；退出码 0/1/2 | +| `.dsh/skills/serial-boot-test/scripts/verify_log.py` | `.dsh/skills/serial-boot-test/scripts/verify_log.py` | 对日志做标记校验：Required/Forbidden（**命中逐行打印行号+内容**）、启动锚点计数 `--max-boot-count`、原因白名单 `--expect-reset-cause`、标记顺序 `--require-order`、开机耗时 `--done-marker`/`--max-boot-ms`、`--json` 结构化输出、**整行锚定 `--exact` / 跨复位配对 `--pair` / 崩溃腿 `--allow-residual`+`--head-char` / 判别自检 `--selftest`**；退出码 0/1/2。子串 Required 照不出"行首被吃掉"那一类行级损坏 → 行级完整性一律用 `--exact`，口径与固定动作见 `启动日志原子性复验流程.md` | ## 判定标准